Merge #18638: net: Use mockable time for ping/pong, add tests

fa3365430c5fb57d7c0b5f2bce9fbbe290be93c3 net: Use mockable time for ping/pong, add tests (MarcoFalke)
faab4aaf2fa1153c6d76efc8113fa01b06943ece util: Add count_microseconds helper (MarcoFalke)

Pull request description:

  Switch `CNode::m_ping_start` and `CNetMessage::m_time` to mockable time, so that tests can be added.

  Mockable time is also type-safe, since it uses `std::chrono`

ACKs for top commit:
  jonatack:
    Code review re-ACK fa33654 re-read code, verified rebase per `git range-diff 4b5c919 fa94d6f fa33654`, previous tested ACKs still valid
  troygiorshev:
    ACK fa3365430c5fb57d7c0b5f2bce9fbbe290be93c3

Tree-SHA512: 7d632bd6019ce7c882029e71b667a61517e783af82755a85dd979ef09380934e172dec8b8f91d57b200a30a6e096aeaf01f19fee7f3aed0e0e871c72eb44d70e

6 files changed, 40 insertions, 34 deletions

diff --git a/src/net.cpp b/src/net.cpp
index 05ee26f8a5..969a89997c 100644
--- a/src/net.cpp
+++ b/src/net.cpp
@@ -564,15 +564,15 @@ void CNode::copyStats(CNodeStats &stats, const std::vector<bool> &m_asmap)
     // since pingtime does not update until the ping is complete, which might take a while.
     // So, if a ping is taking an unusually long time in flight,
     // the caller can immediately detect that this is happening.
-    int64_t nPingUsecWait = 0;
-    if ((0 != nPingNonceSent) && (0 != nPingUsecStart)) {
-        nPingUsecWait = GetTimeMicros() - nPingUsecStart;
+    std::chrono::microseconds ping_wait{0};
+    if ((0 != nPingNonceSent) && (0 != m_ping_start.load().count())) {
+        ping_wait = GetTime<std::chrono::microseconds>() - m_ping_start.load();
     }
 
     // Raw ping time is in microseconds, but show it to user as whole seconds (Bitcoin users should be well used to small numbers with many decimal places by now :)
     stats.m_ping_usec = nPingUsecTime;
     stats.m_min_ping_usec  = nMinPingUsecTime;
-    stats.m_ping_wait_usec = nPingUsecWait;
+    stats.m_ping_wait_usec = count_microseconds(ping_wait);
 
     // Leave string empty if addrLocal invalid (not filled in yet)
     CService addrLocalUnlocked = GetAddrLocal();
@@ -583,9 +583,9 @@ void CNode::copyStats(CNodeStats &stats, const std::vector<bool> &m_asmap)
 bool CNode::ReceiveMsgBytes(const char *pch, unsigned int nBytes, bool& complete)
 {
     complete = false;
-    int64_t nTimeMicros = GetTimeMicros();
+    const auto time = GetTime<std::chrono::microseconds>();
     LOCK(cs_vRecv);
-    nLastRecv = nTimeMicros / 1000000;
+    nLastRecv = std::chrono::duration_cast<std::chrono::seconds>(time).count();
     nRecvBytes += nBytes;
     while (nBytes > 0) {
         // absorb network data
@@ -597,7 +597,7 @@ bool CNode::ReceiveMsgBytes(const char *pch, unsigned int nBytes, bool& complete
 
         if (m_deserializer->Complete()) {
             // decompose a transport agnostic CNetMessage from the deserializer
-            CNetMessage msg = m_deserializer->GetMessage(Params().MessageStart(), nTimeMicros);
+            CNetMessage msg = m_deserializer->GetMessage(Params().MessageStart(), time);
 
             //store received bytes per message command
             //to prevent a memory DOS, only allow valid commands
@@ -700,7 +700,8 @@ const uint256& V1TransportDeserializer::GetMessageHash() const
     return data_hash;
 }
 
-CNetMessage V1TransportDeserializer::GetMessage(const CMessageHeader::MessageStartChars& message_start, int64_t time) {
+CNetMessage V1TransportDeserializer::GetMessage(const CMessageHeader::MessageStartChars& message_start, const std::chrono::microseconds time)
+{
     // decompose a single CNetMessage from the TransportDeserializer
     CNetMessage msg(std::move(vRecv));
 
@@ -1159,9 +1160,9 @@ void CConnman::InactivityCheck(CNode *pnode)
             LogPrintf("socket receive timeout: %is\n", nTime - pnode->nLastRecv);
             pnode->fDisconnect = true;
         }
-        else if (pnode->nPingNonceSent && pnode->nPingUsecStart + TIMEOUT_INTERVAL * 1000000 < GetTimeMicros())
+        else if (pnode->nPingNonceSent && pnode->m_ping_start.load() + std::chrono::seconds{TIMEOUT_INTERVAL} < GetTime<std::chrono::microseconds>())
         {
-            LogPrintf("ping timeout: %fs\n", 0.000001 * (GetTimeMicros() - pnode->nPingUsecStart));
+            LogPrintf("ping timeout: %fs\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - pnode->m_ping_start.load()));
             pnode->fDisconnect = true;
         }
         else if (!pnode->fSuccessfullyConnected)
diff --git a/src/net.h b/src/net.h
index b6c70ec068..efa3ca9f70 100644
--- a/src/net.h
+++ b/src/net.h
@@ -612,13 +612,13 @@ public:
  */
 class CNetMessage {
 public:
-    CDataStream m_recv;                  // received message data
-    int64_t m_time = 0;                  // time (in microseconds) of message receipt.
+    CDataStream m_recv;                  //!< received message data
+    std::chrono::microseconds m_time{0}; //!< time of message receipt
     bool m_valid_netmagic = false;
     bool m_valid_header = false;
     bool m_valid_checksum = false;
-    uint32_t m_message_size = 0;         // size of the payload
-    uint32_t m_raw_message_size = 0;     // used wire size of the message (including header/checksum)
+    uint32_t m_message_size{0};     //!< size of the payload
+    uint32_t m_raw_message_size{0}; //!< used wire size of the message (including header/checksum)
     std::string m_command;
 
     CNetMessage(CDataStream&& recv_in) : m_recv(std::move(recv_in)) {}
@@ -642,7 +642,7 @@ public:
     // read and deserialize data
     virtual int Read(const char *data, unsigned int bytes) = 0;
     // decomposes a message from the context
-    virtual CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, int64_t time) = 0;
+    virtual CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, std::chrono::microseconds time) = 0;
     virtual ~TransportDeserializer() {}
 };
 
@@ -695,7 +695,7 @@ public:
         if (ret < 0) Reset();
         return ret;
     }
-    CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, int64_t time) override;
+    CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, std::chrono::microseconds time) override;
 };
 
 /** The TransportSerializer prepares messages for the network transport
@@ -845,8 +845,8 @@ public:
     // Ping time measurement:
     // The pong reply we're expecting, or 0 if no pong expected.
     std::atomic<uint64_t> nPingNonceSent{0};
-    // Time (in usec) the last ping was sent, or 0 if no ping was ever sent.
-    std::atomic<int64_t> nPingUsecStart{0};
+    /** When the last ping was sent, or 0 if no ping was ever sent */
+    std::atomic<std::chrono::microseconds> m_ping_start{std::chrono::microseconds{0}};
     // Last measured round-trip time.
     std::atomic<int64_t> nPingUsecTime{0};
     // Best measured round-trip time.
diff --git a/src/net_processing.cpp b/src/net_processing.cpp
index 7f89443243..210d8ee375 100644
--- a/src/net_processing.cpp
+++ b/src/net_processing.cpp
@@ -63,8 +63,8 @@ static constexpr int STALE_RELAY_AGE_LIMIT = 30 * 24 * 60 * 60;
 /// Age after which a block is considered historical for purposes of rate
 /// limiting block relay. Set to one week, denominated in seconds.
 static constexpr int HISTORICAL_BLOCK_AGE = 7 * 24 * 60 * 60;
-/** Time between pings automatically sent out for latency probing and keepalive (in seconds). */
-static const int PING_INTERVAL = 2 * 60;
+/** Time between pings automatically sent out for latency probing and keepalive */
+static constexpr std::chrono::minutes PING_INTERVAL{2};
 /** The maximum number of entries in a locator */
 static const unsigned int MAX_LOCATOR_SZ = 101;
 /** The maximum number of entries in an 'inv' protocol message */
@@ -2206,7 +2206,7 @@ void ProcessMessage(
     CNode& pfrom,
     const std::string& msg_type,
     CDataStream& vRecv,
-    int64_t nTimeReceived,
+    const std::chrono::microseconds time_received,
     const CChainParams& chainparams,
     ChainstateManager& chainman,
     CTxMemPool& mempool,
@@ -3110,7 +3110,7 @@ void ProcessMessage(
         } // cs_main
 
         if (fProcessBLOCKTXN)
-            return ProcessMessage(pfrom, NetMsgType::BLOCKTXN, blockTxnMsg, nTimeReceived, chainparams, chainman, mempool, connman, banman, interruptMsgProc);
+            return ProcessMessage(pfrom, NetMsgType::BLOCKTXN, blockTxnMsg, time_received, chainparams, chainman, mempool, connman, banman, interruptMsgProc);
 
         if (fRevertToHeaderProcessing) {
             // Headers received from HB compact block peers are permitted to be
@@ -3385,7 +3385,7 @@ void ProcessMessage(
     }
 
     if (msg_type == NetMsgType::PONG) {
-        int64_t pingUsecEnd = nTimeReceived;
+        const auto ping_end = time_received;
         uint64_t nonce = 0;
         size_t nAvail = vRecv.in_avail();
         bool bPingFinished = false;
@@ -3399,11 +3399,11 @@ void ProcessMessage(
                 if (nonce == pfrom.nPingNonceSent) {
                     // Matching pong received, this ping is no longer outstanding
                     bPingFinished = true;
-                    int64_t pingUsecTime = pingUsecEnd - pfrom.nPingUsecStart;
-                    if (pingUsecTime > 0) {
+                    const auto ping_time = ping_end - pfrom.m_ping_start.load();
+                    if (ping_time.count() > 0) {
                         // Successful ping time measurement, replace previous
-                        pfrom.nPingUsecTime = pingUsecTime;
-                        pfrom.nMinPingUsecTime = std::min(pfrom.nMinPingUsecTime.load(), pingUsecTime);
+                        pfrom.nPingUsecTime = count_microseconds(ping_time);
+                        pfrom.nMinPingUsecTime = std::min(pfrom.nMinPingUsecTime.load(), count_microseconds(ping_time));
                     } else {
                         // This should never happen
                         sProblem = "Timing mishap";
@@ -3860,7 +3860,7 @@ bool PeerLogicValidation::SendMessages(CNode* pto)
             // RPC ping request by user
             pingSend = true;
         }
-        if (pto->nPingNonceSent == 0 && pto->nPingUsecStart + PING_INTERVAL * 1000000 < GetTimeMicros()) {
+        if (pto->nPingNonceSent == 0 && pto->m_ping_start.load() + PING_INTERVAL < GetTime<std::chrono::microseconds>()) {
             // Ping automatically sent as a latency probe & keepalive.
             pingSend = true;
         }
@@ -3870,7 +3870,7 @@ bool PeerLogicValidation::SendMessages(CNode* pto)
                 GetRandBytes((unsigned char*)&nonce, sizeof(nonce));
             }
             pto->fPingQueued = false;
-            pto->nPingUsecStart = GetTimeMicros();
+            pto->m_ping_start = GetTime<std::chrono::microseconds>();
             if (pto->nVersion > BIP0031_VERSION) {
                 pto->nPingNonceSent = nonce;
                 connman->PushMessage(pto, msgMaker.Make(NetMsgType::PING, nonce));
diff --git a/src/test/fuzz/p2p_transport_deserializer.cpp b/src/test/fuzz/p2p_transport_deserializer.cpp
index 57393fed45..6fba2bfaba 100644
--- a/src/test/fuzz/p2p_transport_deserializer.cpp
+++ b/src/test/fuzz/p2p_transport_deserializer.cpp
@@ -30,7 +30,7 @@ void test_one_input(const std::vector<uint8_t>& buffer)
         pch += handled;
         n_bytes -= handled;
         if (deserializer.Complete()) {
-            const int64_t m_time = std::numeric_limits<int64_t>::max();
+            const std::chrono::microseconds m_time{std::numeric_limits<int64_t>::max()};
             const CNetMessage msg = deserializer.GetMessage(Params().MessageStart(), m_time);
             assert(msg.m_command.size() <= CMessageHeader::COMMAND_SIZE);
             assert(msg.m_raw_message_size <= buffer.size());
diff --git a/src/test/fuzz/process_message.cpp b/src/test/fuzz/process_message.cpp
index 2fa751b987..fa8d67059c 100644
--- a/src/test/fuzz/process_message.cpp
+++ b/src/test/fuzz/process_message.cpp
@@ -34,7 +34,7 @@ void ProcessMessage(
     CNode& pfrom,
     const std::string& msg_type,
     CDataStream& vRecv,
-    int64_t nTimeReceived,
+    const std::chrono::microseconds time_received,
     const CChainParams& chainparams,
     ChainstateManager& chainman,
     CTxMemPool& mempool,
@@ -87,7 +87,7 @@ void test_one_input(const std::vector<uint8_t>& buffer)
     connman.AddTestNode(p2p_node);
     g_setup->m_node.peer_logic->InitializeNode(&p2p_node);
     try {
-        ProcessMessage(p2p_node, random_message_type, random_bytes_data_stream, GetTimeMillis(),
+        ProcessMessage(p2p_node, random_message_type, random_bytes_data_stream, GetTime<std::chrono::microseconds>(),
             Params(), *g_setup->m_node.chainman, *g_setup->m_node.mempool,
             g_setup->m_node.connman.get(), g_setup->m_node.banman.get(),
             std::atomic<bool>{false});
diff --git a/src/util/time.h b/src/util/time.h
index b00c25f67c..af934e423b 100644
--- a/src/util/time.h
+++ b/src/util/time.h
@@ -15,10 +15,15 @@ void UninterruptibleSleep(const std::chrono::microseconds& n);
 /**
  * Helper to count the seconds of a duration.
  *
- * All durations should be using std::chrono and calling this should generally be avoided in code. Though, it is still
- * preferred to an inline t.count() to protect against a reliance on the exact type of t.
+ * All durations should be using std::chrono and calling this should generally
+ * be avoided in code. Though, it is still preferred to an inline t.count() to
+ * protect against a reliance on the exact type of t.
+ *
+ * This helper is used to convert durations before passing them over an
+ * interface that doesn't support std::chrono (e.g. RPC, debug log, or the GUI)
  */
 inline int64_t count_seconds(std::chrono::seconds t) { return t.count(); }
+inline int64_t count_microseconds(std::chrono::microseconds t) { return t.count(); }
 
 /**
  * DEPRECATED