From fa3365430c5fb57d7c0b5f2bce9fbbe290be93c3 Mon Sep 17 00:00:00 2001 From: MarcoFalke Date: Tue, 14 Apr 2020 13:24:18 -0400 Subject: net: Use mockable time for ping/pong, add tests --- src/net.cpp | 21 ++--- src/net.h | 16 ++-- src/net_processing.cpp | 22 ++--- src/test/fuzz/p2p_transport_deserializer.cpp | 2 +- src/test/fuzz/process_message.cpp | 4 +- test/functional/feature_bip68_sequence.py | 5 +- test/functional/feature_maxuploadtarget.py | 6 +- test/functional/p2p_ping.py | 123 +++++++++++++++++++++++++++ test/functional/test_runner.py | 1 + 9 files changed, 166 insertions(+), 34 deletions(-) create mode 100755 test/functional/p2p_ping.py diff --git a/src/net.cpp b/src/net.cpp index 371fbeed59..d66570e6a0 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -563,15 +563,15 @@ void CNode::copyStats(CNodeStats &stats, const std::vector &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() - m_ping_start.load(); } // Raw ping time is in microseconds, but show it to user as whole seconds (Bitcoin users should be well used to small numbers with many decimal 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(); @@ -582,9 +582,9 @@ void CNode::copyStats(CNodeStats &stats, const std::vector &m_asmap) bool CNode::ReceiveMsgBytes(const char *pch, unsigned int 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 @@ -596,7 +596,7 @@ bool CNode::ReceiveMsgBytes(const char *pch, unsigned int nBytes, bool& complete if (m_deserializer->Complete()) { // decompose a transport agnostic CNetMessage from the deserializer - CNetMessage msg = m_deserializer->GetMessage(Params().MessageStart(), nTimeMicros); + CNetMessage msg = m_deserializer->GetMessage(Params().MessageStart(), time); //store received bytes per message command //to prevent a memory DOS, only allow valid commands @@ -699,7 +699,8 @@ const uint256& V1TransportDeserializer::GetMessageHash() const return data_hash; } -CNetMessage V1TransportDeserializer::GetMessage(const CMessageHeader::MessageStartChars& message_start, int64_t time) { +CNetMessage V1TransportDeserializer::GetMessage(const CMessageHeader::MessageStartChars& message_start, const std::chrono::microseconds time) +{ // decompose a single CNetMessage from the TransportDeserializer CNetMessage msg(std::move(vRecv)); @@ -1154,9 +1155,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()) { - LogPrintf("ping timeout: %fs\n", 0.000001 * (GetTimeMicros() - pnode->nPingUsecStart)); + LogPrintf("ping timeout: %fs\n", 0.000001 * count_microseconds(GetTime() - pnode->m_ping_start.load())); pnode->fDisconnect = true; } else if (!pnode->fSuccessfullyConnected) diff --git a/src/net.h b/src/net.h index b461470f1f..63603d881f 100644 --- a/src/net.h +++ b/src/net.h @@ -612,13 +612,13 @@ public: */ class CNetMessage { public: - CDataStream m_recv; // received message data - int64_t m_time = 0; // time (in microseconds) of message receipt. + CDataStream m_recv; //!< received message data + std::chrono::microseconds m_time{0}; //!< time of message receipt bool m_valid_netmagic = false; bool m_valid_header = false; bool m_valid_checksum = false; - uint32_t m_message_size = 0; // size of the payload - uint32_t m_raw_message_size = 0; // used wire size of the message (including header/checksum) + uint32_t m_message_size{0}; //!< size of the payload + uint32_t m_raw_message_size{0}; //!< used wire size of the message (including header/checksum) std::string m_command; CNetMessage(CDataStream&& recv_in) : m_recv(std::move(recv_in)) {} @@ -642,7 +642,7 @@ public: // read and deserialize data virtual int Read(const char *data, unsigned int bytes) = 0; // decomposes a message from the context - virtual CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, int64_t time) = 0; + virtual CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, std::chrono::microseconds time) = 0; virtual ~TransportDeserializer() {} }; @@ -695,7 +695,7 @@ public: if (ret < 0) Reset(); return ret; } - CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, int64_t time) override; + CNetMessage GetMessage(const CMessageHeader::MessageStartChars& message_start, std::chrono::microseconds time) override; }; /** The TransportSerializer prepares messages for the network transport @@ -845,8 +845,8 @@ public: // 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_processing.cpp b/src/net_processing.cpp index d7fbf6941d..f7e2ed3f96 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -66,8 +66,8 @@ static constexpr int STALE_RELAY_AGE_LIMIT = 30 * 24 * 60 * 60; /// Age after which a block is considered historical for purposes of rate /// 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). */ -static const int PING_INTERVAL = 2 * 60; +/** Time between pings automatically sent out for latency probing and keepalive */ +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 */ @@ -2208,7 +2208,7 @@ void ProcessMessage( CNode& pfrom, const std::string& msg_type, CDataStream& vRecv, - int64_t nTimeReceived, + const std::chrono::microseconds time_received, const CChainParams& chainparams, ChainstateManager& chainman, CTxMemPool& mempool, @@ -3111,7 +3111,7 @@ void ProcessMessage( } // cs_main if (fProcessBLOCKTXN) - return ProcessMessage(pfrom, NetMsgType::BLOCKTXN, blockTxnMsg, nTimeReceived, chainparams, chainman, mempool, connman, banman, interruptMsgProc); + return ProcessMessage(pfrom, NetMsgType::BLOCKTXN, blockTxnMsg, time_received, chainparams, chainman, mempool, connman, banman, interruptMsgProc); if (fRevertToHeaderProcessing) { // Headers received from HB compact block peers are permitted to be @@ -3386,7 +3386,7 @@ void ProcessMessage( } 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; @@ -3400,11 +3400,11 @@ void ProcessMessage( 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"; @@ -3860,7 +3860,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()) { // Ping automatically sent as a latency probe & keepalive. pingSend = true; } @@ -3870,7 +3870,7 @@ bool PeerLogicValidation::SendMessages(CNode* pto) GetRandBytes((unsigned char*)&nonce, sizeof(nonce)); } pto->fPingQueued = false; - pto->nPingUsecStart = GetTimeMicros(); + pto->m_ping_start = GetTime(); if (pto->nVersion > BIP0031_VERSION) { pto->nPingNonceSent = nonce; 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 index 57393fed45..6fba2bfaba 100644 --- a/src/test/fuzz/p2p_transport_deserializer.cpp +++ b/src/test/fuzz/p2p_transport_deserializer.cpp @@ -30,7 +30,7 @@ void test_one_input(const std::vector& buffer) 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(Params().MessageStart(), 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 index 2fa751b987..fa8d67059c 100644 --- a/src/test/fuzz/process_message.cpp +++ b/src/test/fuzz/process_message.cpp @@ -34,7 +34,7 @@ void ProcessMessage( CNode& pfrom, const std::string& msg_type, CDataStream& vRecv, - int64_t nTimeReceived, + const std::chrono::microseconds time_received, const CChainParams& chainparams, ChainstateManager& chainman, CTxMemPool& mempool, @@ -87,7 +87,7 @@ void test_one_input(const std::vector& buffer) connman.AddTestNode(p2p_node); g_setup->m_node.peer_logic->InitializeNode(&p2p_node); try { - ProcessMessage(p2p_node, random_message_type, random_bytes_data_stream, GetTimeMillis(), + ProcessMessage(p2p_node, random_message_type, random_bytes_data_stream, GetTime(), Params(), *g_setup->m_node.chainman, *g_setup->m_node.mempool, g_setup->m_node.connman.get(), g_setup->m_node.banman.get(), std::atomic{false}); 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 7eabf86cad..ffcc65d5bb 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 79a172706c..f94c7e35a4 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', -- cgit v1.2.3