Merge bitcoin/bitcoin#19499: p2p: Make timeout mockable and type safe, speed up test

MarcoFalke · MarcoFalke · commit 9f7661c0c4cb · 2021-12-10T10:02:12.000+01:00
fadc0c8 p2p: Make timeout mockable and type safe, speed up test (MarcoFalke) fa6d5a2 scripted-diff: Rename m_last_send and m_last_recv (MarcoFalke) Pull request description: Use type-safe time for better code readability/maintainability and mockable time for better testability. This speeds up the p2p_timeout test. This is also a bugfix for intermittent test issues like: https://cirrus-ci.com/task/4769904156999680?command=ci#L2836 Fixes #20654 ACKs for top commit: laanwj: Code review ACK fadc0c8 naumenkogs: ACK fadc0c8 Tree-SHA512: 28c6544c97f188c8a0fbc80411c74ab74ffd055885322c325aa3d1c404b29c3fd70a737e86083eecae58ef394db1cb56bc122d06cff63742aa89a8e868730c64
diff --git a/src/net.cpp b/src/net.cpp
@@ -586,8 +586,8 @@ void CNode::CopyStats(CNodeStats& stats)
     } else {
         stats.fRelayTxes = false;
     }
-    X(nLastSend);
-    X(nLastRecv);
+    X(m_last_send);
+    X(m_last_recv);
     X(nLastTXTime);
     X(nLastBlockTime);
     X(nTimeConnected);
@@ -634,7 +634,7 @@ bool CNode::ReceiveMsgBytes(Span<const uint8_t> msg_bytes, bool& complete)
     complete = false;
     const auto time = GetTime<std::chrono::microseconds>();
     LOCK(cs_vRecv);
-    nLastRecv = std::chrono::duration_cast<std::chrono::seconds>(time).count();
+    m_last_recv = std::chrono::duration_cast<std::chrono::seconds>(time);
     nRecvBytes += msg_bytes.size();
     while (msg_bytes.size() > 0) {
         // absorb network data
@@ -805,7 +805,7 @@ size_t CConnman::SocketSendData(CNode& node) const
             nBytes = send(node.hSocket, reinterpret_cast<const char*>(data.data()) + node.nSendOffset, data.size() - node.nSendOffset, MSG_NOSIGNAL | MSG_DONTWAIT);
         }
         if (nBytes > 0) {
-            node.nLastSend = GetTimeSeconds();
+            node.m_last_send = GetTime<std::chrono::seconds>();
             node.nSendBytes += nBytes;
             node.nSendOffset += nBytes;
             nSentSize += nBytes;
@@ -1318,31 +1318,33 @@ void CConnman::NotifyNumConnectionsChanged()
     }
 }
 
-bool CConnman::ShouldRunInactivityChecks(const CNode& node, int64_t now) const
+bool CConnman::ShouldRunInactivityChecks(const CNode& node, std::chrono::seconds now) const
 {
-    return node.nTimeConnected + m_peer_connect_timeout < now;
+    return std::chrono::seconds{node.nTimeConnected} + m_peer_connect_timeout < now;
 }
 
 bool CConnman::InactivityCheck(const CNode& node) const
 {
-    // Use non-mockable system time (otherwise these timers will pop when we
-    // use setmocktime in the tests).
-    int64_t now = GetTimeSeconds();
+    // Tests that see disconnects after using mocktime can start nodes with a
+    // large timeout. For example, -peertimeout=999999999.
+    const auto now{GetTime<std::chrono::seconds>()};
+    const auto last_send{node.m_last_send.load()};
+    const auto last_recv{node.m_last_recv.load()};
 
     if (!ShouldRunInactivityChecks(node, now)) return false;
 
-    if (node.nLastRecv == 0 || node.nLastSend == 0) {
-        LogPrint(BCLog::NET, "socket no message in first %i seconds, %d %d peer=%d\n", m_peer_connect_timeout, node.nLastRecv != 0, node.nLastSend != 0, node.GetId());
+    if (last_recv.count() == 0 || last_send.count() == 0) {
+        LogPrint(BCLog::NET, "socket no message in first %i seconds, %d %d peer=%d\n", count_seconds(m_peer_connect_timeout), last_recv.count() != 0, last_send.count() != 0, node.GetId());
         return true;
     }
 
-    if (now > node.nLastSend + TIMEOUT_INTERVAL) {
-        LogPrint(BCLog::NET, "socket sending timeout: %is peer=%d\n", now - node.nLastSend, node.GetId());
+    if (now > last_send + TIMEOUT_INTERVAL) {
+        LogPrint(BCLog::NET, "socket sending timeout: %is peer=%d\n", count_seconds(now - last_send), node.GetId());
         return true;
     }
 
-    if (now > node.nLastRecv + TIMEOUT_INTERVAL) {
-        LogPrint(BCLog::NET, "socket receive timeout: %is peer=%d\n", now - node.nLastRecv, node.GetId());
+    if (now > last_recv + TIMEOUT_INTERVAL) {
+        LogPrint(BCLog::NET, "socket receive timeout: %is peer=%d\n", count_seconds(now - last_recv), node.GetId());
         return true;
     }
 
diff --git a/src/net.h b/src/net.h
@@ -48,7 +48,7 @@ static const bool DEFAULT_WHITELISTRELAY = true;
 static const bool DEFAULT_WHITELISTFORCERELAY = false;
 
 /** Time after which to disconnect, after waiting for a ping response (or inactivity). */
-static const int TIMEOUT_INTERVAL = 20 * 60;
+static constexpr std::chrono::minutes TIMEOUT_INTERVAL{20};
 /** Run the feeler connection loop once every 2 minutes. **/
 static constexpr auto FEELER_INTERVAL = 2min;
 /** Run the extra block-relay-only connection loop once every 5 minutes. **/
@@ -241,8 +241,8 @@ class CNodeStats
     NodeId nodeid;
     ServiceFlags nServices;
     bool fRelayTxes;
-    int64_t nLastSend;
-    int64_t nLastRecv;
+    std::chrono::seconds m_last_send;
+    std::chrono::seconds m_last_recv;
     int64_t nLastTXTime;
     int64_t nLastBlockTime;
     int64_t nTimeConnected;
@@ -420,8 +420,8 @@ class CNode
 
     uint64_t nRecvBytes GUARDED_BY(cs_vRecv){0};
 
-    std::atomic<int64_t> nLastSend{0};
-    std::atomic<int64_t> nLastRecv{0};
+    std::atomic<std::chrono::seconds> m_last_send{0s};
+    std::atomic<std::chrono::seconds> m_last_recv{0s};
     //! Unix epoch time at peer connection, in seconds.
     const int64_t nTimeConnected;
     std::atomic<int64_t> nTimeOffset{0};
@@ -784,7 +784,7 @@ class CConnman
         m_msgproc = connOptions.m_msgproc;
         nSendBufferMaxSize = connOptions.nSendBufferMaxSize;
         nReceiveFloodSize = connOptions.nReceiveFloodSize;
-        m_peer_connect_timeout = connOptions.m_peer_connect_timeout;
+        m_peer_connect_timeout = std::chrono::seconds{connOptions.m_peer_connect_timeout};
         {
             LOCK(cs_totalBytesSent);
             nMaxOutboundLimit = connOptions.nMaxOutboundLimit;
@@ -942,7 +942,7 @@ class CConnman
     std::chrono::microseconds PoissonNextSendInbound(std::chrono::microseconds now, std::chrono::seconds average_interval);
 
     /** Return true if we should disconnect the peer for failing an inactivity check. */
-    bool ShouldRunInactivityChecks(const CNode& node, int64_t secs_now) const;
+    bool ShouldRunInactivityChecks(const CNode& node, std::chrono::seconds now) const;
 
 private:
     struct ListenSocket {
@@ -1084,7 +1084,7 @@ class CConnman
     uint64_t nMaxOutboundLimit GUARDED_BY(cs_totalBytesSent);
 
     // P2P timeout in seconds
-    int64_t m_peer_connect_timeout;
+    std::chrono::seconds m_peer_connect_timeout;
 
     // Whitelisted ranges. Any node connecting from these is automatically
     // whitelisted (as well as those connecting to whitelisted binds).
diff --git a/src/net_processing.cpp b/src/net_processing.cpp
@@ -4357,9 +4357,10 @@ void PeerManagerImpl::CheckForStaleTipAndEvictPeers()
 
 void PeerManagerImpl::MaybeSendPing(CNode& node_to, Peer& peer, std::chrono::microseconds now)
 {
-    if (m_connman.ShouldRunInactivityChecks(node_to, std::chrono::duration_cast<std::chrono::seconds>(now).count()) &&
+    if (m_connman.ShouldRunInactivityChecks(node_to, std::chrono::duration_cast<std::chrono::seconds>(now)) &&
         peer.m_ping_nonce_sent &&
-        now > peer.m_ping_start.load() + std::chrono::seconds{TIMEOUT_INTERVAL}) {
+        now > peer.m_ping_start.load() + TIMEOUT_INTERVAL)
+    {
         // The ping timeout is using mocktime. To disable the check during
         // testing, increase -peertimeout.
         LogPrint(BCLog::NET, "ping timeout: %fs peer=%d\n", 0.000001 * count_microseconds(now - peer.m_ping_start.load()), peer.m_id);
diff --git a/src/qt/guiutil.cpp b/src/qt/guiutil.cpp
@@ -20,6 +20,7 @@
 #include <script/script.h>
 #include <script/standard.h>
 #include <util/system.h>
+#include <util/time.h>
 
 #ifdef WIN32
 #ifndef NOMINMAX
@@ -705,8 +706,9 @@ QString ConnectionTypeToQString(ConnectionType conn_type, bool prepend_direction
     assert(false);
 }
 
-QString formatDurationStr(int secs)
+QString formatDurationStr(std::chrono::seconds dur)
 {
+    const auto secs = count_seconds(dur);
     QStringList strList;
     int days = secs / 86400;
     int hours = (secs % 86400) / 3600;
diff --git a/src/qt/guiutil.h b/src/qt/guiutil.h
@@ -221,7 +221,7 @@ namespace GUIUtil
     QString ConnectionTypeToQString(ConnectionType conn_type, bool prepend_direction);
 
     /** Convert seconds into a QString with days, hours, mins, secs */
-    QString formatDurationStr(int secs);
+    QString formatDurationStr(std::chrono::seconds dur);
 
     /** Format CNodeStats.nServices bitmask into a user-readable string */
     QString formatServicesStr(quint64 mask);
diff --git a/src/qt/rpcconsole.cpp b/src/qt/rpcconsole.cpp
@@ -1141,7 +1141,7 @@ void RPCConsole::on_sldGraphRange_valueChanged(int value)
 void RPCConsole::setTrafficGraphRange(int mins)
 {
     ui->trafficGraph->setGraphRangeMins(mins);
-    ui->lblGraphRange->setText(GUIUtil::formatDurationStr(mins * 60));
+    ui->lblGraphRange->setText(GUIUtil::formatDurationStr(std::chrono::minutes{mins}));
 }
 
 void RPCConsole::updateTrafficStats(quint64 totalBytesIn, quint64 totalBytesOut)
@@ -1172,12 +1172,12 @@ void RPCConsole::updateDetailWidget()
     if (stats->nodeStats.m_bip152_highbandwidth_from) bip152_hb_settings += (bip152_hb_settings.isEmpty() ? ts.from : QLatin1Char('/') + ts.from);
     if (bip152_hb_settings.isEmpty()) bip152_hb_settings = ts.no;
     ui->peerHighBandwidth->setText(bip152_hb_settings);
-    const int64_t time_now{GetTimeSeconds()};
-    ui->peerConnTime->setText(GUIUtil::formatDurationStr(time_now - stats->nodeStats.nTimeConnected));
-    ui->peerLastBlock->setText(TimeDurationField(time_now, stats->nodeStats.nLastBlockTime));
-    ui->peerLastTx->setText(TimeDurationField(time_now, stats->nodeStats.nLastTXTime));
-    ui->peerLastSend->setText(TimeDurationField(time_now, stats->nodeStats.nLastSend));
-    ui->peerLastRecv->setText(TimeDurationField(time_now, stats->nodeStats.nLastRecv));
+    const auto time_now{GetTime<std::chrono::seconds>()};
+    ui->peerConnTime->setText(GUIUtil::formatDurationStr(time_now - std::chrono::seconds{stats->nodeStats.nTimeConnected}));
+    ui->peerLastBlock->setText(TimeDurationField(time_now, std::chrono::seconds{stats->nodeStats.nLastBlockTime}));
+    ui->peerLastTx->setText(TimeDurationField(time_now, std::chrono::seconds{stats->nodeStats.nLastTXTime}));
+    ui->peerLastSend->setText(TimeDurationField(time_now, stats->nodeStats.m_last_send));
+    ui->peerLastRecv->setText(TimeDurationField(time_now, stats->nodeStats.m_last_recv));
     ui->peerBytesSent->setText(GUIUtil::formatBytes(stats->nodeStats.nSendBytes));
     ui->peerBytesRecv->setText(GUIUtil::formatBytes(stats->nodeStats.nRecvBytes));
     ui->peerPingTime->setText(GUIUtil::formatPingTime(stats->nodeStats.m_last_ping_time));
diff --git a/src/qt/rpcconsole.h b/src/qt/rpcconsole.h
@@ -175,8 +175,9 @@ public Q_SLOTS:
     void updateNetworkState();
 
     /** Helper for the output of a time duration field. Inputs are UNIX epoch times. */
-    QString TimeDurationField(uint64_t time_now, uint64_t time_at_event) const {
-        return time_at_event ? GUIUtil::formatDurationStr(time_now - time_at_event) : tr("Never");
+    QString TimeDurationField(std::chrono::seconds time_now, std::chrono::seconds time_at_event) const
+    {
+        return time_at_event.count() ? GUIUtil::formatDurationStr(time_now - time_at_event) : tr("Never");
     }
 
 private Q_SLOTS:
diff --git a/src/rpc/net.cpp b/src/rpc/net.cpp
@@ -196,8 +196,8 @@ static RPCHelpMan getpeerinfo()
         obj.pushKV("services", strprintf("%016x", stats.nServices));
         obj.pushKV("servicesnames", GetServicesNames(stats.nServices));
         obj.pushKV("relaytxes", stats.fRelayTxes);
-        obj.pushKV("lastsend", stats.nLastSend);
-        obj.pushKV("lastrecv", stats.nLastRecv);
+        obj.pushKV("lastsend", count_seconds(stats.m_last_send));
+        obj.pushKV("lastrecv", count_seconds(stats.m_last_recv));
         obj.pushKV("last_transaction", stats.nLastTXTime);
         obj.pushKV("last_block", stats.nLastBlockTime);
         obj.pushKV("bytessent", stats.nSendBytes);
diff --git a/src/test/denialofservice_tests.cpp b/src/test/denialofservice_tests.cpp
@@ -53,7 +53,7 @@ BOOST_AUTO_TEST_CASE(outbound_slow_chain_eviction)
     const CChainParams& chainparams = Params();
     auto connman = std::make_unique<CConnman>(0x1337, 0x1337, *m_node.addrman);
     // Disable inactivity checks for this test to avoid interference
-    static_cast<ConnmanTestMsg*>(connman.get())->SetPeerConnectTimeout(99999);
+    static_cast<ConnmanTestMsg*>(connman.get())->SetPeerConnectTimeout(99999s);
     auto peerLogic = PeerManager::make(chainparams, *connman, *m_node.addrman, nullptr,
                                        *m_node.chainman, *m_node.mempool, false);
 
diff --git a/src/test/util/net.h b/src/test/util/net.h
@@ -18,7 +18,7 @@
 struct ConnmanTestMsg : public CConnman {
     using CConnman::CConnman;
 
-    void SetPeerConnectTimeout(int64_t timeout)
+    void SetPeerConnectTimeout(std::chrono::seconds timeout)
     {
         m_peer_connect_timeout = timeout;
     }
diff --git a/test/functional/p2p_timeouts.py b/test/functional/p2p_timeouts.py
@@ -4,13 +4,12 @@
 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
 """Test various net timeouts.
 
-- Create three bitcoind nodes:
+- Create three peers:
 
     no_verack_node - we never send a verack in response to their version
     no_version_node - we never send a version (only a ping)
     no_send_node - we never send any P2P message.
 
-- Start all three nodes
 - Wait 1 second
 - Assert that we're connected
 - Send a ping to no_verack_node and no_version_node
@@ -21,12 +20,12 @@
 - Assert that we're no longer connected (timeout to receive version/verack is 3 seconds)
 """
 
-from time import sleep
-
 from test_framework.messages import msg_ping
 from test_framework.p2p import P2PInterface
 from test_framework.test_framework import BitcoinTestFramework
 
+import time
+
 
 class TestP2PConn(P2PInterface):
     def on_version(self, message):
@@ -41,7 +40,14 @@ def set_test_params(self):
         # set timeout to receive version/verack to 3 seconds
         self.extra_args = [["-peertimeout=3"]]
 
+    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)
+
         # Setup the p2p connections
         no_verack_node = self.nodes[0].add_p2p_connection(TestP2PConn(), wait_for_verack=False)
         no_version_node = self.nodes[0].add_p2p_connection(TestP2PConn(), send_version=False, wait_for_verack=False)
@@ -51,7 +57,7 @@ def run_test(self):
         # verack, since we never sent one
         no_verack_node.wait_for_verack()
 
-        sleep(1)
+        self.mock_forward(1)
 
         assert no_verack_node.is_connected
         assert no_version_node.is_connected
@@ -62,7 +68,7 @@ def run_test(self):
         with self.nodes[0].assert_debug_log(['non-version message before version handshake. Message "ping" from peer=1']):
             no_version_node.send_message(msg_ping())
 
-        sleep(1)
+        self.mock_forward(1)
 
         assert "version" in no_verack_node.last_message
 
@@ -80,14 +86,10 @@ def run_test(self):
         ]
 
         with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):
-            sleep(3)
-            # By now, we waited a total of 5 seconds. Off-by-two for two
-            # reasons:
-            #  * The internal precision is one second
-            #  * Account for network delay
-            assert not no_verack_node.is_connected
-            assert not no_version_node.is_connected
-            assert not no_send_node.is_connected
+            self.mock_forward(2)
+            no_verack_node.wait_for_disconnect(timeout=1)
+            no_version_node.wait_for_disconnect(timeout=1)
+            no_send_node.wait_for_disconnect(timeout=1)
 
 
 if __name__ == '__main__':
diff --git a/test/functional/test_framework/util.py b/test/functional/test_framework/util.py
@@ -379,10 +379,10 @@ def write_config(config_path, *, n, chain, extra_config="", disable_autoconnect=
         f.write("fixedseeds=0\n")
         f.write("listenonion=0\n")
         # Increase peertimeout to avoid disconnects while using mocktime.
-        # peertimeout is measured in wall clock time, so setting it to the
-        # duration of the longest test is sufficient. It can be overridden in
-        # tests.
-        f.write("peertimeout=999999\n")
+        # peertimeout is measured in mock time, so setting it large enough to
+        # cover any duration in mock time is sufficient. It can be overridden
+        # in tests.
+        f.write("peertimeout=999999999\n")
         f.write("printtoconsole=0\n")
         f.write("upnp=0\n")
         f.write("natpmp=0\n")

Original file line number	Diff line number	Diff line change
`@@ -18,7 +18,7 @@`
`18`	`18`	`struct ConnmanTestMsg : public CConnman {`
`19`	`19`	`using CConnman::CConnman;`
`20`	`20`
`21`		`- void SetPeerConnectTimeout(int64_t timeout)`
	`21`	`+ void SetPeerConnectTimeout(std::chrono::seconds timeout)`
`22`	`22`	`{`
`23`	`23`	`m_peer_connect_timeout = timeout;`
`24`	`24`	`}`