test: bump mocktime only after node has received and sent bytes

stratospher commented at 10:45 am on July 17, 2024: contributor

Fixes an intermittent failure for p2p_v2_misbehaving.py reported in #30420 (review).

A different error message "socket no message in first %i seconds" will be displayed if m_last_send=0 or if m_last_recv is 0. Fix this by:

mocktime bump is done after all the bytes are received. (m_last_recv is not 0 now)
wait until bytes are sent by TestNode/bitcoind (m_last_send is not 0 now)

See https://cirrus-ci.com/task/5359619151757312?logs=ci#L3935 for an example failure (I wasn’t able to reproduce the intermittent failure locally but I think the fix is logical)

DrahtBot commented at 10:45 am on July 17, 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	maflcko

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

DrahtBot added the label Tests on Jul 17, 2024

in test/functional/p2p_v2_misbehaving.py:153 in e6f4614ea5 outdated

146@@ -147,9 +147,10 @@ def test_earlykeyresponse(self):
147         peer1.v2_state.can_data_be_received = True
148         self.wait_until(lambda: peer1.v2_state.ellswift_ours)
149         peer1.send_raw_message(peer1.v2_state.ellswift_ours[4:] + peer1.v2_state.sent_garbage)
150-        node0.bumpmocktime(3)
151         # Ensure that the bytes sent after 4 bytes network magic are actually received.
152         self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)
153+        self.wait_until(lambda: node0.getpeerinfo()[-1]["bytessent"] > 0)
154+        node0.bumpmocktime(3)

maflcko commented at 11:43 am on July 17, 2024:

This will be racy, no?

The peer timeout is 3, which is also the bump, so the peer may be disconnected at any time, leading to a test failure if it is disconnected at the wrong time.

Something like this should fail the test, no?

0        node0.bumpmocktime(3); time.sleep(1);

stratospher commented at 12:17 pm on July 17, 2024:

I couldn’t reproduce it locally.

since peer timeout is 3, InactivityCheck()(and hence disconnection) will happen when our time is > 3. so disconnection will only happen during the next bumpmocktime(1) I think.

(Also see #30420 (review))

maflcko commented at 12:23 pm on July 17, 2024:

Ah, I see the check is <, not <=.

However, what is the purpose of two immediately following bumpmocktime on the same node? Wouldn’t it be easier to just combine them into one (and use the sum of their arguments)?

stratospher commented at 12:28 pm on July 17, 2024:

true, done.

maflcko commented at 12:24 pm on July 17, 2024: member

review ACK e6f4614ea57dbd3d8690fdbed55ecf2612619070

Looks good, feel free to ignore the nit.

stratospher force-pushed on Jul 17, 2024

test: bump mocktime after node has received and sent bytes

a different error message "socket no message in first %i seconds"
will be displayed if m_last_send=0 or if m_last_recv is 0. make
the test robust by ensuring that they will not be 0 before
bumping mocktime.

c322bddd08

stratospher force-pushed on Jul 17, 2024

maflcko commented at 12:32 pm on July 17, 2024: member

reACK c322bddd08ed1f1f7f0c39768b659dd62d5e2dd5

fanquake merged this on Jul 17, 2024

fanquake closed this on Jul 17, 2024

stratospher deleted the branch on Jul 17, 2024

in test/functional/p2p_v2_misbehaving.py:151 in c322bddd08

146@@ -147,11 +147,11 @@ def test_earlykeyresponse(self):
147         peer1.v2_state.can_data_be_received = True
148         self.wait_until(lambda: peer1.v2_state.ellswift_ours)
149         peer1.send_raw_message(peer1.v2_state.ellswift_ours[4:] + peer1.v2_state.sent_garbage)
150-        node0.bumpmocktime(3)
151         # Ensure that the bytes sent after 4 bytes network magic are actually received.
152         self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)

maflcko commented at 5:25 pm on July 23, 2024:

This can fail intermittently:

 0 node0 2024-07-22T16:31:54.104994Z [httpworker.0] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ 
 1 test  2024-07-22T16:31:54.291000Z TestFramework (INFO): Sending first 4 bytes of ellswift which match network magic 
 2 test  2024-07-22T16:31:54.292000Z TestFramework (INFO): If a response is received, assertion failure would happen in our custom data_received() function 
 3 test  2024-07-22T16:31:54.292000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:12644 
 4 test  2024-07-22T16:31:54.293000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:12644 
 5 test  2024-07-22T16:31:54.588000Z TestFramework.p2p (DEBUG): sending 4050 bytes of garbage data 
 6 test  2024-07-22T16:31:54.588000Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is 
 7 test  2024-07-22T16:31:54.588000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure 
 8 node0 2024-07-22T16:31:55.523868Z (mocktime: 2024-07-22T16:31:54Z) [net] [net.cpp:3764] [CNode] [net] Added connection peer=0 
 9 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 
10 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 
11 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__ 
12 test  2024-07-22T16:31:55.818000Z TestFramework (ERROR): Unexpected exception caught during testing 
13                                   Traceback (most recent call last):
14                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
15                                       self.run_test()
16                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 133, in run_test
17                                       self.test_earlykeyresponse()
18                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 151, in test_earlykeyresponse
19                                       self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)
20                                     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
21                                       return wait_until_helper_internal(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor)
22                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
23                                     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
24                                       if predicate():
25                                          ^^^^^^^^^^^
26                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 151, in <lambda>
27                                       self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)
28                                                               ~~~~~~~~~~~~~~~~~~~^^^^
29                                   IndexError: list index out of range

The code in net.cpp:

0    LogPrint(BCLog::NET, "connection from %s accepted\n", addr.ToStringAddrPort());
1
2    {
3        LOCK(m_nodes_mutex);
4        m_nodes.push_back(pnode);
5    }

So I presume the log was premature and should have done after m_nodes.push_back(pnode);. Otherwise, getpeerinfo/GetNodeStats may be empty.

My recommendation would be to call wait_for_new_peer, or otherwise sync here, before indexing into an array of possibly empty size.

maflcko commented at 5:41 pm on July 23, 2024:

Fixed in https://github.com/bitcoin/bitcoin/pull/30512

bitcoin locked this on Jul 23, 2025

test: bump mocktime only after node has received and sent bytes #30468

Code Coverage

Reviews