From 55555574d105f6c529c5c966c3c971c9db5ab786 Mon Sep 17 00:00:00 2001 From: MarcoFalke <*~=`'#}+{/-|&$^_@721217.xyz> Date: Tue, 23 Jul 2024 19:37:26 +0200 Subject: [PATCH 1/2] net: Log accepted connection after m_nodes.push_back Otherwise, the debug log could read confusingly, when the getpeerinfo() RPC (calling GetNodeStats) happens after the "accepted connection" log line, but returns an empty list. For example, the following timeline in the debug log could correspond to a getpeerinfo reply that is empty: [net] [net.cpp:3764] [CNode] Added connection peer=0 [net] [net.cpp:1814] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:45154 accepted [http] [httpserver.cpp:305] [http_request_cb] Received a POST request for / from 127.0.0.1:33320 [httpworker.1] [rpc/request.cpp:232] [parse] ThreadRPCServer method=getpeerinfo user=__cookie__ Fix it by moving the log line. --- src/net.cpp | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/net.cpp b/src/net.cpp index 3d3f9f4ba7d..ad43b316b32 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -1810,13 +1810,11 @@ void CConnman::CreateNodeFromAcceptedSocket(std::unique_ptr&& sock, }); pnode->AddRef(); m_msgproc->InitializeNode(*pnode, nLocalServices); - - LogPrint(BCLog::NET, "connection from %s accepted\n", addr.ToStringAddrPort()); - { LOCK(m_nodes_mutex); m_nodes.push_back(pnode); } + LogDebug(BCLog::NET, "connection from %s accepted\n", addr.ToStringAddrPort()); // We received a new connection, harvest entropy from the time (and our peer count) RandAddEvent((uint32_t)id); From fa3ea3b83c6a4c9726a17f2a48bbdb77f944bf6c Mon Sep 17 00:00:00 2001 From: MarcoFalke <*~=`'#}+{/-|&$^_@721217.xyz> Date: Tue, 23 Jul 2024 19:41:15 +0200 Subject: [PATCH 2/2] test: Fix intermittent issue in p2p_v2_misbehaving.py Without the fix, the test could fail intermittently. For example: node0 2024-07-22T16:31:54.104994Z [httpworker.0] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ test 2024-07-22T16:31:54.291000Z TestFramework (INFO): Sending first 4 bytes of ellswift which match network magic test 2024-07-22T16:31:54.292000Z TestFramework (INFO): If a response is received, assertion failure would happen in our custom data_received() function test 2024-07-22T16:31:54.292000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:12644 test 2024-07-22T16:31:54.293000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:12644 test 2024-07-22T16:31:54.588000Z TestFramework.p2p (DEBUG): sending 4050 bytes of garbage data test 2024-07-22T16:31:54.588000Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is test 2024-07-22T16:31:54.588000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure node0 2024-07-22T16:31:55.523868Z (mocktime: 2024-07-22T16:31:54Z) [net] [net.cpp:3764] [CNode] [net] Added connection peer=0 node0 2024-07-22T16:31:55.625145Z (mocktime: 2024-07-22T16:31:54Z) [net] [net.cpp:1814] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:45154 accepted node0 2024-07-22T16:31:55.625769Z (mocktime: 2024-07-22T16:31:54Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33320 node0 2024-07-22T16:31:55.626543Z (mocktime: 2024-07-22T16:31:54Z) [httpworker.1] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__ test 2024-07-22T16:31:55.818000Z TestFramework (ERROR): Unexpected exception caught during testing Traceback (most recent call last): File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main self.run_test() File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 133, in run_test self.test_earlykeyresponse() File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 151, in test_earlykeyresponse self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4) File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 791, in wait_until return wait_until_helper_internal(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 289, in wait_until_helper_internal if predicate(): ^^^^^^^^^^^ File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 151, in self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4) ~~~~~~~~~~~~~~~~~~~^^^^ IndexError: list index out of range --- test/functional/p2p_v2_misbehaving.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/functional/p2p_v2_misbehaving.py b/test/functional/p2p_v2_misbehaving.py index 2bc7b43e1f3..0af96a4f8c9 100755 --- a/test/functional/p2p_v2_misbehaving.py +++ b/test/functional/p2p_v2_misbehaving.py @@ -140,7 +140,8 @@ class EncryptedP2PMisbehaving(BitcoinTestFramework): node0.setmocktime(int(time.time())) self.log.info('Sending first 4 bytes of ellswift which match network magic') self.log.info('If a response is received, assertion failure would happen in our custom data_received() function') - peer1 = node0.add_p2p_connection(MisbehavingV2Peer(TestType.EARLY_KEY_RESPONSE), wait_for_verack=False, send_version=False, supports_v2_p2p=True, wait_for_v2_handshake=False) + with node0.wait_for_new_peer(): + peer1 = node0.add_p2p_connection(MisbehavingV2Peer(TestType.EARLY_KEY_RESPONSE), wait_for_verack=False, send_version=False, supports_v2_p2p=True, wait_for_v2_handshake=False) peer1.send_raw_message(MAGIC_BYTES['regtest']) self.log.info('Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is') self.log.info('expected now, our custom data_received() function wouldn\'t result in assertion failure')