From 0b3b3b61f98cca4f422b62dd923882811348aa2b Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 19 Jun 2023 10:52:54 -0500 Subject: [PATCH] GH-1315 Completely remove problematic tstamp type. --- .../include/eosio/net_plugin/protocol.hpp | 11 +-- plugins/net_plugin/net_plugin.cpp | 86 ++++++++++++------- 2 files changed, 58 insertions(+), 39 deletions(-) diff --git a/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp b/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp index 2e7245c180..5ca2ba1456 100644 --- a/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp +++ b/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp @@ -7,9 +7,6 @@ namespace eosio { using namespace chain; using namespace fc; - static_assert(sizeof(std::chrono::system_clock::duration::rep) >= 8, "system_clock is expected to be at least 64 bits"); - typedef std::chrono::system_clock::duration::rep tstamp; - struct chain_size_message { uint32_t last_irreversible_block_num = 0; block_id_type last_irreversible_block_id; @@ -83,10 +80,10 @@ namespace eosio { }; struct time_message { - tstamp org{0}; //!< origin timestamp - tstamp rec{0}; //!< receive timestamp - tstamp xmt{0}; //!< transmit timestamp - mutable tstamp dst{0}; //!< destination timestamp + int64_t org{0}; //!< origin timestamp, in nanoseconds + int64_t rec{0}; //!< receive timestamp, in nanoseconds + int64_t xmt{0}; //!< transmit timestamp, in nanoseconds + mutable int64_t dst{0}; //!< destination timestamp, in nanoseconds }; enum id_list_modes { diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 8d0a17454c..0a29e161ae 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -51,6 +51,9 @@ namespace eosio { using connection_ptr = std::shared_ptr; using connection_wptr = std::weak_ptr; + static constexpr int64_t block_interval_ns = + std::chrono::duration_cast(std::chrono::milliseconds(config::block_interval_ms)).count(); + const fc::string logger_name("net_plugin_impl"); fc::logger logger; std::string peer_log_format; @@ -121,9 +124,6 @@ namespace eosio { in_sync }; - static constexpr int64_t block_interval_ns = - std::chrono::duration_cast(std::chrono::milliseconds(config::block_interval_ms)).count(); - mutable std::mutex sync_mtx; uint32_t sync_known_lib_num{0}; uint32_t sync_last_requested_num{0}; @@ -681,10 +681,10 @@ namespace eosio { * @{ */ // Members set from network data - tstamp org{0}; //!< originate timestamp - tstamp rec{0}; //!< receive timestamp - tstamp dst{0}; //!< destination timestamp - tstamp xmt{0}; //!< transmit timestamp + std::chrono::nanoseconds org{0}; //!< origin timestamp. Time at the client when the request departed for the server. + // std::chrono::nanoseconds (not used) rec{0}; //!< receive timestamp. Time at the server when the request arrived from the client. + std::chrono::nanoseconds xmt{0}; //!< transmit timestamp, Time at the server when the response left for the client. + // std::chrono::nanoseconds (not used) dst{0}; //!< destination timestamp, Time at the client when the reply arrived from the server. /** @} */ // timestamp for the lastest message std::chrono::system_clock::time_point latest_msg_time{std::chrono::system_clock::time_point::min()}; @@ -1192,20 +1192,27 @@ namespace eosio { // called from connection strand void connection::send_time() { - time_message xpkt; - xpkt.org = rec; - xpkt.rec = dst; - xpkt.xmt = get_time().count(); - org = xpkt.xmt; - enqueue(xpkt); + if (org == std::chrono::nanoseconds{0}) { // do not send if there is already a time loop in progress + org = get_time(); + // xpkt.org == 0 means we are initiating a ping. Actual origin time is in xpkt.xmt. + time_message xpkt{ + .org = 0, + .rec = 0, + .xmt = org.count(), + .dst = 0 }; + peer_dlog(this, "send init time_message: ${t}", ("t", xpkt)); + enqueue(xpkt); + } } // called from connection strand void connection::send_time(const time_message& msg) { - time_message xpkt; - xpkt.org = msg.xmt; - xpkt.rec = msg.dst; - xpkt.xmt = get_time().count(); + time_message xpkt{ + .org = msg.xmt, + .rec = msg.dst, + .xmt = get_time().count(), + .dst = 0 }; + peer_dlog( this, "send time_message: ${t}, org: ${o}", ("t", xpkt)("o", org.count()) ); enqueue(xpkt); } @@ -3005,38 +3012,53 @@ namespace eosio { close( retry ); // reconnect if wrong_version } + // some clients before leap 5.0 provided microsecond epoch instead of nanosecond epoch + std::chrono::nanoseconds normalize_epoch_to_ns(int64_t x) { + // 1686211688888 milliseconds - 2023-06-08T08:08:08.888, 5yrs from EOS genesis 2018-06-08T08:08:08.888 + // 1686211688888000 microseconds + // 1686211688888000000 nanoseconds + if (x >= 1686211688888000000) // nanoseconds + return std::chrono::nanoseconds{x}; + if (x >= 1686211688888000) // microseconds + return std::chrono::nanoseconds{x*1000}; + if (x >= 1686211688888) // milliseconds + return std::chrono::nanoseconds{x*1000*1000}; + if (x >= 1686211688) // seconds + return std::chrono::nanoseconds{x*1000*1000*1000}; + return std::chrono::nanoseconds{0}; // unknown or is zero + } + void connection::handle_message( const time_message& msg ) { - peer_ilog( this, "received time_message" ); + peer_dlog( this, "received time_message: ${t}, org: ${o}", ("t", msg)("o", org.count()) ); - /* We've already lost however many microseconds it took to dispatch - * the message, but it can't be helped. - */ + // We've already lost however many microseconds it took to dispatch the message, but it can't be helped. msg.dst = get_time().count(); // If the transmit timestamp is zero, the peer is horribly broken. if(msg.xmt == 0) return; /* invalid timestamp */ - if(msg.xmt == xmt) + auto msg_xmt = normalize_epoch_to_ns(msg.xmt); + if(msg_xmt == xmt) return; /* duplicate packet */ - xmt = msg.xmt; - rec = msg.rec; - dst = msg.dst; + xmt = msg_xmt; if( msg.org == 0 ) { send_time( msg ); return; // We don't have enough data to perform the calculation yet. } - double offset = (double(rec - org) + double(msg.xmt - dst)) / 2; - double NsecPerUsec{1000}; + if (org != std::chrono::nanoseconds{0}) { + auto rec = normalize_epoch_to_ns(msg.rec); + int64_t offset = (double((rec - org).count()) + double(msg_xmt.count() - msg.dst)) / 2.0; - if( logger.is_enabled( fc::log_level::all ) ) - logger.log( FC_LOG_MESSAGE( all, "Clock offset is ${o}ns (${us}us)", - ("o", offset)( "us", offset / NsecPerUsec ) ) ); - org = 0; - rec = 0; + if (std::abs(offset) > block_interval_ns) { + peer_wlog(this, "Clock offset is ${of}us, calculation: (rec ${r} - org ${o} + xmt ${x} - dst ${d})/2", + ("of", offset / 1000)("r", rec.count())("o", org.count())("x", msg_xmt.count())("d", msg.dst)); + } + } + org = std::chrono::nanoseconds{0}; std::unique_lock g_conn( conn_mtx ); if( last_handshake_recv.generation == 0 ) {