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

1. 
   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.

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.

   55555574d1
3. 
   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.

4. DrahtBot added the label P2P on Jul 23, 2024
5. 
   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);
   

6. 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
7. maflcko force-pushed on Jul 23, 2024
8. 
   stratospher commented at 1:35 pm on July 24, 2024: contributor

   tested ACK fa3ea3b.
9. maflcko added this to the milestone 28.0 on Jul 24, 2024
10. 
    0xB10C commented at 1:27 pm on August 5, 2024: contributor

    Code Review ACK fa3ea3b83c6a4c9726a17f2a48bbdb77f944bf6c

    Both changes look reasonable to me.

11. fanquake merged this on Aug 5, 2024
12. fanquake closed this on Aug 5, 2024

    ---

13. maflcko deleted the branch on Aug 5, 2024

Contributors
maflcko DrahtBot stratospher 0xB10C

Labels
P2P

Milestone
28.0