merge bitcoin#19499: Make timeout mockable and type safe, speed up test

src/net.cpp

@@ -660,8 +660,8 @@ void CNode::copyStats(CNodeStats &stats, const std::vector<bool> &m_asmap)
     } else {
         stats.fRelayTxes = false;
     }
-    X(nLastSend);
-    X(nLastRecv);
+    X(m_last_send);
+    X(m_last_recv);
     X(nLastTXTime);
     X(nLastBlockTime);
     X(nTimeConnected);
@@ -710,7 +710,7 @@ bool CNode::ReceiveMsgBytes(Span<const uint8_t> msg_bytes, bool& complete)
     // TODO: use mocktime here after bitcoin#19499 is backported
     const auto time = std::chrono::microseconds(GetTimeMicros());
     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
@@ -881,7 +881,7 @@ size_t CConnman::SocketSendData(CNode& node)
             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;
@@ -1524,31 +1524,33 @@ void CConnman::CalculateNumConnectionsChangedStats()
     statsClient.gauge("peers.torConnections", torNodes, 1.0f);
 }
 
-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;
     }
 

src/net.h

@@ -63,7 +63,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};
 /** Time to wait since nTimeConnected before disconnecting a probe node. **/
 static const int PROBE_WAIT_INTERVAL = 5;
 /** Minimum time between warnings printed to log. */
@@ -275,8 +275,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;
@@ -459,8 +459,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};
@@ -926,7 +926,7 @@ friend class CNode;
         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;
@@ -1235,7 +1235,7 @@ friend class CNode;
     void SetAsmap(std::vector<bool> asmap) { addrman.m_asmap = std::move(asmap); }
 
     /** 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 {
@@ -1351,7 +1351,7 @@ friend class CNode;
     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).

src/net_processing.cpp

@@ -5063,9 +5063,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);

src/qt/guiutil.cpp

@@ -23,6 +23,7 @@
 #include <script/script.h>
 #include <script/standard.h>
 #include <util/system.h>
+#include <util/time.h>
 
 #include <cmath>
 
@@ -1673,8 +1674,9 @@ QString ConnectionTypeToQString(ConnectionType conn_type)
     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;

src/qt/guiutil.h

@@ -401,7 +401,7 @@ namespace GUIUtil
     QString ConnectionTypeToQString(ConnectionType conn_type);
 
     /** 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);

src/qt/rpcconsole.cpp

@@ -1152,7 +1152,7 @@ void RPCConsole::on_sldGraphRange_valueChanged(int value)
 void RPCConsole::setTrafficGraphRange(TrafficGraphData::GraphRange range)
 {
     ui->trafficGraph->setGraphRangeMins(range);
-    ui->lblGraphRange->setText(GUIUtil::formatDurationStr(TrafficGraphData::RangeMinutes[range] * 60));
+    ui->lblGraphRange->setText(GUIUtil::formatDurationStr(std::chrono::minutes{TrafficGraphData::RangeMinutes[range]}));
 }
 
 void RPCConsole::peerLayoutAboutToChange()
@@ -1237,12 +1237,12 @@ void RPCConsole::updateDetailWidget()
     ui->peerHeading->setText(peerAddrDetails);
     ui->peerServices->setText(GUIUtil::formatServicesStr(stats->nodeStats.nServices));
     ui->peerRelayTxes->setText(stats->nodeStats.fRelayTxes ? "Yes" : "No");
-    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));

src/qt/rpcconsole.h

@@ -193,8 +193,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:

src/rpc/net.cpp

@@ -220,8 +220,8 @@ static RPCHelpMan getpeerinfo()
         }
         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);

src/test/denialofservice_tests.cpp

@@ -66,7 +66,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.scheduler,
                                        *m_node.chainman, *m_node.mempool, *m_node.mn_metaman, *m_node.mn_sync,
                                        *m_node.govman, *m_node.sporkman, /* mn_activeman = */ nullptr, m_node.dmnman,

src/test/util/net.h

@@ -16,7 +16,7 @@
 struct ConnmanTestMsg : public CConnman {
     using CConnman::CConnman;
 
-    void SetPeerConnectTimeout(int64_t timeout)
+    void SetPeerConnectTimeout(std::chrono::seconds timeout)
     {
         m_peer_connect_timeout = timeout;
     }

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 dashd 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
@@ -60,7 +66,7 @@ def run_test(self):
         no_verack_node.send_message(msg_ping())
         no_version_node.send_message(msg_ping())
 
-        sleep(1)
+        self.mock_forward(1)
 
         assert "version" in no_verack_node.last_message
 
@@ -78,10 +84,10 @@ def run_test(self):
         ]
 
         with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):
-            sleep(3 + 1) # Sleep one second more than peertimeout
-            assert not no_verack_node.is_connected
-            assert not no_version_node.is_connected
-            assert not no_send_node.is_connected
+            self.mock_forward(3)
+            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__':

test/functional/test_framework/util.py

@@ -375,10 +375,10 @@ def write_config(config_path, *, n, chain, extra_config=""):
         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 overriden 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")