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

4 files changed, 133 insertions, 2 deletions

diff --git a/test/functional/feature_bip68_sequence.py b/test/functional/feature_bip68_sequence.py
index 549e8b2029..19cdc10935 100755
--- a/test/functional/feature_bip68_sequence.py
+++ b/test/functional/feature_bip68_sequence.py
@@ -30,7 +30,10 @@ class BIP68Test(BitcoinTestFramework):
     def set_test_params(self):
         self.num_nodes = 2
         self.extra_args = [
-            ["-acceptnonstdtxn=1"],
+            [
+                "-acceptnonstdtxn=1",
+                "-peertimeout=9999",  # bump because mocktime might cause a disconnect otherwise
+            ],
             ["-acceptnonstdtxn=0"],
         ]
 
diff --git a/test/functional/feature_maxuploadtarget.py b/test/functional/feature_maxuploadtarget.py
index 5056b807cb..5538d6d3b4 100755
--- a/test/functional/feature_maxuploadtarget.py
+++ b/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=800", "-acceptnonstdtxn=1"]]
+        self.extra_args = [[
+            "-maxuploadtarget=800",
+            "-acceptnonstdtxn=1",
+            "-peertimeout=9999",  # bump because mocktime might cause a disconnect otherwise
+        ]]
         self.supports_cli = False
 
         # Cache for utxos, as the listunspent may take a long time later in the test
diff --git a/test/functional/p2p_ping.py b/test/functional/p2p_ping.py
new file mode 100755
index 0000000000..e00af88cc4
--- /dev/null
+++ b/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()
diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py
index 6deba9a9ec..867a9909a8 100755
--- a/test/functional/test_runner.py
+++ b/test/functional/test_runner.py
@@ -236,6 +236,7 @@ BASE_SCRIPTS = [
     'mempool_compatibility.py',
     'rpc_deriveaddresses.py',
     'rpc_deriveaddresses.py --usecli',
+    'p2p_ping.py',
     'rpc_scantxoutset.py',
     'feature_logging.py',
     'p2p_node_network_limited.py',