merge bitcoin#18638: Use mockable time for ping/pong, add tests

src/net.cpp

@@ -807,15 +807,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 (Dash users should be well used to small numbers with many decimal places by now :)
-    stats.dPingTime = (((double)nPingUsecTime) / 1e6);
-    stats.dMinPing  = (((double)nMinPingUsecTime) / 1e6);
-    stats.dPingWait = (((double)nPingUsecWait) / 1e6);
+    stats.m_ping_usec = nPingUsecTime;
+    stats.m_min_ping_usec  = nMinPingUsecTime;
+    stats.m_ping_wait_usec = count_microseconds(ping_wait);
 
     // Leave string empty if addrLocal invalid (not filled in yet)
     CService addrLocalUnlocked = GetAddrLocal();
@@ -833,9 +833,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) {
 
@@ -1501,9 +1501,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)

src/net.h

@@ -966,9 +966,9 @@ class CNode
     std::atomic<int64_t> timeLastMempoolReq;
     // Ping time measurement:
     // The pong reply we're expecting, or 0 if no pong expected.
-    std::atomic<uint64_t> nPingNonceSent;
-    // Time (in usec) the last ping was sent, or 0 if no ping was ever sent.
-    std::atomic<int64_t> nPingUsecStart;
+    std::atomic<uint64_t> nPingNonceSent{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;
     // Best measured round-trip time.

src/net_processing.cpp

@@ -2089,7 +2089,7 @@ std::string RejectCodeToString(const unsigned char code)
     return "";
 }
 
-bool static ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStream& vRecv, int64_t nTimeReceived, const CChainParams& chainparams, CConnman* connman, const std::atomic<bool>& interruptMsgProc, bool enable_bip61)
+bool static ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStream& vRecv, const std::chrono::microseconds time_received, const CChainParams& chainparams, CConnman* connman, const std::atomic<bool>& interruptMsgProc, bool enable_bip61)
 {
     LogPrint(BCLog::NET, "received: %s (%u bytes) peer=%d\n", SanitizeString(strCommand), vRecv.size(), pfrom->GetId());
     statsClient.inc("message.received." + SanitizeString(strCommand), 1.0f);
@@ -3188,7 +3188,7 @@ bool static ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStr
         } // cs_main
 
         if (fProcessBLOCKTXN)
-            return ProcessMessage(pfrom, NetMsgType::BLOCKTXN, blockTxnMsg, nTimeReceived, chainparams, connman, interruptMsgProc, enable_bip61);
+            return ProcessMessage(pfrom, NetMsgType::BLOCKTXN, blockTxnMsg, time_received, chainparams, connman, interruptMsgProc, enable_bip61);
 
         if (fRevertToHeaderProcessing) {
             // Headers received from HB compact block peers are permitted to be
@@ -3448,7 +3448,7 @@ bool static ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStr
     }
 
     if (strCommand == 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;
@@ -3462,11 +3462,11 @@ bool static ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStr
                 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";
@@ -3761,7 +3761,7 @@ bool PeerLogicValidation::ProcessMessages(CNode* pfrom, std::atomic<bool>& inter
     bool fRet = false;
     try
     {
-        fRet = ProcessMessage(pfrom, strCommand, vRecv, msg.nTime, chainparams, connman, interruptMsgProc, m_enable_bip61);
+        fRet = ProcessMessage(pfrom, strCommand, vRecv, std::chrono::seconds{msg.nTime}, chainparams, connman, interruptMsgProc, m_enable_bip61);
         if (interruptMsgProc)
             return false;
         if (!pfrom->vRecvGetData.empty())
@@ -3978,7 +3978,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;
         }
@@ -3988,7 +3988,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>();
             pto->nPingNonceSent = nonce;
             connman->PushMessage(pto, msgMaker.Make(NetMsgType::PING, nonce));
         }

src/netbase.cpp

@@ -609,7 +609,7 @@ bool IsProxy(const CNetAddr &addr) {
     return false;
 }
 
-bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int port, const SOCKET& hSocket, int nTimeout, bool *outProxyConnectionFailed)
+bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int port, const Sock& sock, int nTimeout, bool *outProxyConnectionFailed)
 {
     // first connect to proxy server
     if (!ConnectSocketDirectly(proxy.proxy, hSocket, nTimeout, true)) {

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

test/functional/feature_bip68_sequence.py

@@ -21,7 +21,13 @@
 class BIP68Test(BitcoinTestFramework):
     def set_test_params(self):
         self.num_nodes = 2
-        self.extra_args = [[], ["-acceptnonstdtxn=0"]]
+        self.extra_args = [
+            [
+                "-acceptnonstdtxn=1",
+                "-peertimeout=9999",  # bump because mocktime might cause a disconnect otherwise
+            ],
+            ["-acceptnonstdtxn=0"],
+        ]
 
     def run_test(self):
         self.relayfee = self.nodes[0].getnetworkinfo()["relayfee"]

test/functional/feature_maxuploadtarget.py

@@ -35,7 +35,11 @@ class MaxUploadTest(BitcoinTestFramework):
     def set_test_params(self):
         self.setup_clean_chain = True
         self.num_nodes = 1
-        self.extra_args = [["-maxuploadtarget=200", "-blockmaxsize=999000", "-maxtipage="+str(2*60*60*24*7)]]
+        self.extra_args = [[
+            "-maxuploadtarget=800",
+            "-acceptnonstdtxn=1",
+            "-peertimeout=9999",  # bump because mocktime might cause a disconnect otherwise
+        ]]
 
         # Cache for utxos, as the listunspent may take a long time later in the test
         self.utxo_cache = []

test/functional/p2p_ping.py

@@ -0,0 +1,123 @@
+#!/usr/bin/env python3
+# Copyright (c) 2020 The Bitcoin Core developers
+# Distributed under the MIT software license, see the accompanying
+# file COPYING or http://www.opensource.org/licenses/mit-license.php.
+"""Test ping message
+"""
+
+import time
+
+from test_framework.messages import (
+    msg_pong,
+)
+from test_framework.mininode import (
+    P2PInterface,
+    wait_until,
+)
+from test_framework.test_framework import BitcoinTestFramework
+from test_framework.util import assert_equal
+
+PING_INTERVAL = 2 * 60
+
+
+class msg_pong_corrupt(msg_pong):
+    def serialize(self):
+        return b""
+
+
+class NodePongAdd1(P2PInterface):
+    def on_ping(self, message):
+        self.send_message(msg_pong(message.nonce + 1))
+
+
+class NodeNoPong(P2PInterface):
+    def on_ping(self, message):
+        pass
+
+
+class PingPongTest(BitcoinTestFramework):
+    def set_test_params(self):
+        self.setup_clean_chain = True
+        self.num_nodes = 1
+        self.extra_args = [['-peertimeout=3']]
+
+    def check_peer_info(self, *, pingtime, minping, pingwait):
+        stats = self.nodes[0].getpeerinfo()[0]
+        assert_equal(stats.pop('pingtime', None), pingtime)
+        assert_equal(stats.pop('minping', None), minping)
+        assert_equal(stats.pop('pingwait', None), pingwait)
+
+    def mock_forward(self, delta):
+        self.mock_time += delta
+        self.nodes[0].setmocktime(self.mock_time)
+
+    def run_test(self):
+        self.mock_time = int(time.time())
+        self.mock_forward(0)
+
+        self.log.info('Check that ping is sent after connection is established')
+        no_pong_node = self.nodes[0].add_p2p_connection(NodeNoPong())
+        self.mock_forward(3)
+        assert no_pong_node.last_message.pop('ping').nonce != 0
+        self.check_peer_info(pingtime=None, minping=None, pingwait=3)
+
+        self.log.info('Reply without nonce cancels ping')
+        with self.nodes[0].assert_debug_log(['pong peer=0: Short payload']):
+            no_pong_node.send_and_ping(msg_pong_corrupt())
+        self.check_peer_info(pingtime=None, minping=None, pingwait=None)
+
+        self.log.info('Reply without ping')
+        with self.nodes[0].assert_debug_log([
+                'pong peer=0: Unsolicited pong without ping, 0 expected, 0 received, 8 bytes',
+        ]):
+            no_pong_node.send_and_ping(msg_pong())
+        self.check_peer_info(pingtime=None, minping=None, pingwait=None)
+
+        self.log.info('Reply with wrong nonce does not cancel ping')
+        assert 'ping' not in no_pong_node.last_message
+        with self.nodes[0].assert_debug_log(['pong peer=0: Nonce mismatch']):
+            # mock time PING_INTERVAL ahead to trigger node into sending a ping
+            self.mock_forward(PING_INTERVAL + 1)
+            wait_until(lambda: 'ping' in no_pong_node.last_message)
+            self.mock_forward(9)
+            # Send the wrong pong
+            no_pong_node.send_and_ping(msg_pong(no_pong_node.last_message.pop('ping').nonce - 1))
+        self.check_peer_info(pingtime=None, minping=None, pingwait=9)
+
+        self.log.info('Reply with zero nonce does cancel ping')
+        with self.nodes[0].assert_debug_log(['pong peer=0: Nonce zero']):
+            no_pong_node.send_and_ping(msg_pong(0))
+        self.check_peer_info(pingtime=None, minping=None, pingwait=None)
+
+        self.log.info('Check that ping is properly reported on RPC')
+        assert 'ping' not in no_pong_node.last_message
+        # mock time PING_INTERVAL ahead to trigger node into sending a ping
+        self.mock_forward(PING_INTERVAL + 1)
+        wait_until(lambda: 'ping' in no_pong_node.last_message)
+        ping_delay = 29
+        self.mock_forward(ping_delay)
+        wait_until(lambda: 'ping' in no_pong_node.last_message)
+        no_pong_node.send_and_ping(msg_pong(no_pong_node.last_message.pop('ping').nonce))
+        self.check_peer_info(pingtime=ping_delay, minping=ping_delay, pingwait=None)
+
+        self.log.info('Check that minping is decreased after a fast roundtrip')
+        # mock time PING_INTERVAL ahead to trigger node into sending a ping
+        self.mock_forward(PING_INTERVAL + 1)
+        wait_until(lambda: 'ping' in no_pong_node.last_message)
+        ping_delay = 9
+        self.mock_forward(ping_delay)
+        wait_until(lambda: 'ping' in no_pong_node.last_message)
+        no_pong_node.send_and_ping(msg_pong(no_pong_node.last_message.pop('ping').nonce))
+        self.check_peer_info(pingtime=ping_delay, minping=ping_delay, pingwait=None)
+
+        self.log.info('Check that peer is disconnected after ping timeout')
+        assert 'ping' not in no_pong_node.last_message
+        self.nodes[0].ping()
+        wait_until(lambda: 'ping' in no_pong_node.last_message)
+        with self.nodes[0].assert_debug_log(['ping timeout: 1201.000000s']):
+            self.mock_forward(20 * 60 + 1)
+            time.sleep(4)  # peertimeout + 1
+
+
+if __name__ == '__main__':
+    PingPongTest().main()

test/functional/test_runner.py

@@ -192,6 +192,7 @@
     'p2p_unrequested_blocks.py',
     'feature_asmap.py',
     'feature_includeconf.py',
+    'p2p_ping.py',
     'feature_logging.py',
     'p2p_node_network_limited.py',
     'feature_blocksdir.py',