net: Log accepted connection after m_nodes.push_back; Fix intermittent test issue

maflcko commented at 5:40 pm on July 23, 2024: member

Fix the two issues reported in https://github.com/bitcoin/bitcoin/pull/30468/files#r1688444784:

Delay a debug log line for consistency.
Fix an intermittent test issue.

They are completely separate fixes, but both net related.

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.

55555574d1

DrahtBot commented at 5:40 pm on July 23, 2024: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage

For detailed information about the code coverage, see the test coverage report.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	stratospher, 0xB10C

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#29641 (scripted-diff: Use LogInfo/LogDebug over LogPrintf/LogPrint by maflcko)
#25832 (tracing: network connection tracepoints by 0xB10C)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

DrahtBot added the label P2P on Jul 23, 2024

maflcko commented at 5:44 pm on July 23, 2024: member

Can be tested by adding a sleep before the LOCK:

0diff --git a/src/net.cpp b/src/net.cpp
1index ad43b316b3..a60aa5f31c 100644
2--- a/src/net.cpp
3+++ b/src/net.cpp
4@@ -1813,2 +1813,3 @@ void CConnman::CreateNodeFromAcceptedSocket(std::unique_ptr<Sock>&& sock,
5     {
6+        UninterruptibleSleep(100ms);
7         LOCK(m_nodes_mutex);

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 <lambda>
                                       self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)
                                                               ~~~~~~~~~~~~~~~~~~~^^^^
                                   IndexError: list index out of range

fa3ea3b83c

maflcko force-pushed on Jul 23, 2024

stratospher commented at 1:35 pm on July 24, 2024: contributor

tested ACK fa3ea3b.

maflcko added this to the milestone 28.0 on Jul 24, 2024

0xB10C commented at 1:27 pm on August 5, 2024: contributor

Code Review ACK fa3ea3b83c6a4c9726a17f2a48bbdb77f944bf6c

Both changes look reasonable to me.

fanquake merged this on Aug 5, 2024

fanquake closed this on Aug 5, 2024

maflcko deleted the branch on Aug 5, 2024

bitcoin locked this on Aug 5, 2025

net: Log accepted connection after m_nodes.push_back; Fix intermittent test issue #30512

Code Coverage

Reviews

Conflicts