diff --git a/src/net.h b/src/net.h --- a/src/net.h +++ b/src/net.h @@ -684,17 +684,17 @@ */ class CNetMessage { public: - // received message data + //! received message data CDataStream m_recv; - // time (in microseconds) of message receipt. - int64_t m_time = 0; + //! time of message receipt + std::chrono::microseconds m_time{0}; bool m_valid_netmagic = false; bool m_valid_header = false; bool m_valid_checksum = false; - // size of the payload - uint32_t m_message_size = 0; - // used wire size of the message (including header/checksum) - uint32_t m_raw_message_size = 0; + //! size of the payload + uint32_t m_message_size{0}; + //! used wire size of the message (including header/checksum) + uint32_t m_raw_message_size{0}; std::string m_command; CNetMessage(CDataStream &&recv_in) : m_recv(std::move(recv_in)) {} @@ -717,7 +717,8 @@ virtual int Read(const Config &config, const char *data, uint32_t bytes) = 0; // decomposes a message from the context - virtual CNetMessage GetMessage(const Config &config, int64_t time) = 0; + virtual CNetMessage GetMessage(const Config &config, + std::chrono::microseconds time) = 0; virtual ~TransportDeserializer() {} }; @@ -782,7 +783,8 @@ return ret; } - CNetMessage GetMessage(const Config &config, int64_t time) override; + CNetMessage GetMessage(const Config &config, + std::chrono::microseconds time) override; }; /** @@ -1007,8 +1009,9 @@ // Ping time measurement: // The pong reply we're expecting, or 0 if no pong expected. std::atomic nPingNonceSent{0}; - // Time (in usec) the last ping was sent, or 0 if no ping was ever sent. - std::atomic nPingUsecStart{0}; + /** When the last ping was sent, or 0 if no ping was ever sent */ + std::atomic m_ping_start{ + std::chrono::microseconds{0}}; // Last measured round-trip time. std::atomic nPingUsecTime{0}; // Best measured round-trip time. diff --git a/src/net.cpp b/src/net.cpp --- a/src/net.cpp +++ b/src/net.cpp @@ -586,9 +586,9 @@ // responsive, 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() - m_ping_start.load(); } // Raw ping time is in microseconds, but show it to user as whole seconds @@ -596,7 +596,7 @@ // 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(); @@ -607,9 +607,9 @@ bool CNode::ReceiveMsgBytes(const Config &config, const char *pch, uint32_t nBytes, bool &complete) { complete = false; - int64_t nTimeMicros = GetTimeMicros(); + const auto time = GetTime(); LOCK(cs_vRecv); - nLastRecv = nTimeMicros / 1000000; + nLastRecv = std::chrono::duration_cast(time).count(); nRecvBytes += nBytes; while (nBytes > 0) { // Absorb network data. @@ -624,7 +624,7 @@ if (m_deserializer->Complete()) { // decompose a transport agnostic CNetMessage from the deserializer - CNetMessage msg = m_deserializer->GetMessage(config, nTimeMicros); + CNetMessage msg = m_deserializer->GetMessage(config, time); // Store received bytes per message command to prevent a memory DOS, // only allow valid commands. @@ -731,8 +731,9 @@ return data_hash; } -CNetMessage V1TransportDeserializer::GetMessage(const Config &config, - int64_t time) { +CNetMessage +V1TransportDeserializer::GetMessage(const Config &config, + const std::chrono::microseconds time) { // decompose a single CNetMessage from the TransportDeserializer CNetMessage msg(std::move(vRecv)); @@ -1286,10 +1287,13 @@ nTime - pnode->nLastRecv); pnode->fDisconnect = true; } else if (pnode->nPingNonceSent && - pnode->nPingUsecStart + TIMEOUT_INTERVAL * 1000000 < - GetTimeMicros()) { + pnode->m_ping_start.load() + + std::chrono::seconds{TIMEOUT_INTERVAL} < + GetTime()) { LogPrintf("ping timeout: %fs\n", - 0.000001 * (GetTimeMicros() - pnode->nPingUsecStart)); + 0.000001 * count_microseconds( + GetTime() - + pnode->m_ping_start.load())); pnode->fDisconnect = true; } else if (!pnode->fSuccessfullyConnected) { LogPrint(BCLog::NET, "version handshake timeout from %d\n", diff --git a/src/net_processing.h b/src/net_processing.h --- a/src/net_processing.h +++ b/src/net_processing.h @@ -117,7 +117,7 @@ /** Process a single message from a peer. Public for fuzz testing */ void ProcessMessage(const Config &config, CNode &pfrom, const std::string &msg_type, CDataStream &vRecv, - int64_t nTimeReceived, + const std::chrono::microseconds time_received, const std::atomic &interruptMsgProc); /** diff --git a/src/net_processing.cpp b/src/net_processing.cpp --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -86,10 +86,9 @@ /// 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). + * Time between pings automatically sent out for latency probing and keepalive. */ -static const int PING_INTERVAL = 2 * 60; +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 */ @@ -2645,7 +2644,8 @@ void PeerManager::ProcessMessage(const Config &config, CNode &pfrom, const std::string &msg_type, - CDataStream &vRecv, int64_t nTimeReceived, + CDataStream &vRecv, + const std::chrono::microseconds time_received, const std::atomic &interruptMsgProc) { LogPrint(BCLog::NET, "received: %s (%u bytes) peer=%d\n", SanitizeString(msg_type), vRecv.size(), pfrom.GetId()); @@ -3689,7 +3689,7 @@ if (fProcessBLOCKTXN) { return ProcessMessage(config, pfrom, NetMsgType::BLOCKTXN, - blockTxnMsg, nTimeReceived, interruptMsgProc); + blockTxnMsg, time_received, interruptMsgProc); } if (fRevertToHeaderProcessing) { @@ -4210,7 +4210,7 @@ } 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; @@ -4226,12 +4226,13 @@ // 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"; @@ -4794,8 +4795,8 @@ // 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()) { // Ping automatically sent as a latency probe & keepalive. pingSend = true; } @@ -4805,7 +4806,7 @@ GetRandBytes((uint8_t *)&nonce, sizeof(nonce)); } pto->fPingQueued = false; - pto->nPingUsecStart = GetTimeMicros(); + pto->m_ping_start = GetTime(); if (pto->nVersion > BIP0031_VERSION) { pto->nPingNonceSent = nonce; m_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 --- a/src/test/fuzz/p2p_transport_deserializer.cpp +++ b/src/test/fuzz/p2p_transport_deserializer.cpp @@ -32,7 +32,8 @@ pch += handled; n_bytes -= handled; if (deserializer.Complete()) { - const int64_t m_time = std::numeric_limits::max(); + const std::chrono::microseconds m_time{ + std::numeric_limits::max()}; const CNetMessage msg = deserializer.GetMessage(config, 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 --- a/src/test/fuzz/process_message.cpp +++ b/src/test/fuzz/process_message.cpp @@ -87,7 +87,7 @@ try { g_setup->m_node.peerman->ProcessMessage( config, p2p_node, random_message_type, random_bytes_data_stream, - GetTimeMillis(), std::atomic{false}); + GetTime(), std::atomic{false}); } catch (const std::ios_base::failure &) { } SyncWithValidationInterfaceQueue(); diff --git a/src/util/time.h b/src/util/time.h --- a/src/util/time.h +++ b/src/util/time.h @@ -18,10 +18,16 @@ * 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 diff --git a/test/functional/feature_bip68_sequence.py b/test/functional/feature_bip68_sequence.py --- a/test/functional/feature_bip68_sequence.py +++ b/test/functional/feature_bip68_sequence.py @@ -45,8 +45,19 @@ class BIP68Test(BitcoinTestFramework): def set_test_params(self): self.num_nodes = 2 - self.extra_args = [["-noparkdeepreorg", "-maxreorgdepth=-1", "-acceptnonstdtxn=1"], - ["-acceptnonstdtxn=0", "-maxreorgdepth=-1"]] + self.extra_args = [ + [ + "-noparkdeepreorg", + "-maxreorgdepth=-1", + "-acceptnonstdtxn=1", + # bump because mocktime might cause a disconnect otherwise + "-peertimeout=9999", + ], + [ + "-acceptnonstdtxn=0", + "-maxreorgdepth=-1" + ] + ] def skip_test_if_missing_module(self): self.skip_if_no_wallet() diff --git a/test/functional/feature_maxuploadtarget.py b/test/functional/feature_maxuploadtarget.py --- a/test/functional/feature_maxuploadtarget.py +++ b/test/functional/feature_maxuploadtarget.py @@ -40,7 +40,12 @@ self.setup_clean_chain = True self.num_nodes = 1 # Start a node with maxuploadtarget of 200 MB (/24h) - self.extra_args = [["-maxuploadtarget=200", "-acceptnonstdtxn=1"]] + self.extra_args = [[ + "-maxuploadtarget=200", + "-acceptnonstdtxn=1", + # bump because mocktime might cause a disconnect otherwise + "-peertimeout=9999", + ]] self.supports_cli = False # Cache for utxos, as the listunspent may take a long time later in the diff --git a/test/functional/p2p_ping.py b/test/functional/p2p_ping.py new file mode 100755 --- /dev/null +++ b/test/functional/p2p_ping.py @@ -0,0 +1,134 @@ +#!/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) + # peertimeout + 1 + time.sleep(4) + + +if __name__ == '__main__': + PingPongTest().main()