test: Fix intermittent failure in p2p_v2_misbehaving.py #30420

pull stratospher wants to merge 1 commits into bitcoin:master from stratospher:fix-race-earlykey changing 1 files +16 −4
  1. stratospher commented at 10:02 AM on July 10, 2024: contributor

    Fixes #30419.

    Make sure that ellswift computation is complete in the NetworkThread in test/functional/p2p_v2_misbehaving.py before sending the ellswift in the MainThread.

    One way to reproduce this failure on master would be:

    diff --git a/test/functional/test_framework/v2_p2p.py b/test/functional/test_framework/v2_p2p.py
index 87600c36de..ea0615ef3b 100644
--- a/test/functional/test_framework/v2_p2p.py
+++ b/test/functional/test_framework/v2_p2p.py
@@ -111,6 +111,7 @@ class EncryptedP2PState:
 
     def generate_keypair_and_garbage(self, garbage_len=None):
         """Generates ellswift keypair and 4095 bytes garbage at max"""
+        import time; time.sleep(3)
         self.privkey_ours, self.ellswift_ours = ellswift_create()
         if garbage_len is None:
             garbage_len = random.randrange(MAX_GARBAGE_LEN + 1)
  2. DrahtBot commented at 10:02 AM on July 10, 2024: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->

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

    <!--006a51241073e994b41acfe9ec718e94-->

    Code Coverage

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

    <!--021abf342d371248e50ceaed478a90ca-->

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK mzumsande, tdb3, maflcko
    Stale ACK fjahr, kevkevinpal

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

    <!--174a7506f384e20aa4161008e828411d-->

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #28521 (net: additional disconnect logging by Sjors)

    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.

  3. DrahtBot added the label Tests on Jul 10, 2024
  4. maflcko added this to the milestone 28.0 on Jul 10, 2024
  5. fjahr commented at 11:05 AM on July 10, 2024: contributor

    Concept ACK

    I could verify that the issue I see with sleep(3) is fixed with the change here. However, when I increase the number from 3 to 5 or 10 I still see other errors, so there may be more potential for race conditions here.

    The two failures I saw:

    2024-07-10T10:56:33.201000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure
2024-07-10T10:56:38.167000Z TestFramework.p2p (WARNING): Connection lost to 127.0.0.1:15258 due to [Errno 32] Broken pipe
2024-07-10T10:56:40.217000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
    self.run_test()
  File "/Users/FJ/projects/clones/bitcoin/test/functional/p2p_v2_misbehaving.py", line 132, in run_test
    self.test_earlykeyresponse()
  File "/Users/FJ/projects/clones/bitcoin/test/functional/p2p_v2_misbehaving.py", line 148, in test_earlykeyresponse
    with node0.assert_debug_log(['V2 handshake timeout peer=0']):
  File "/opt/homebrew/Cellar/python@3.12/3.12.3/Frameworks/Python.framework/Versions/3.12/lib/python3.12/contextlib.py", line 144, in __exit__
    next(self.gen)
  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_node.py", line 491, in assert_debug_log
    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['V2 handshake timeout peer=0']" does not partially match log:

 -

    and

    2024-07-10T10:57:20.854000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure
2024-07-10T10:57:25.817000Z TestFramework.p2p (WARNING): Connection lost to 127.0.0.1:15834 due to [Errno 54] Connection reset by peer
2024-07-10T10:57:25.825000Z TestFramework (ERROR): Unexpected exception caught during testing
Traceback (most recent call last):
  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
    self.run_test()
  File "/Users/FJ/projects/clones/bitcoin/test/functional/p2p_v2_misbehaving.py", line 132, in run_test
    self.test_earlykeyresponse()
  File "/Users/FJ/projects/clones/bitcoin/test/functional/p2p_v2_misbehaving.py", line 147, in test_earlykeyresponse
    peer1.send_raw_message(peer1.v2_state.ellswift_ours[4:] + peer1.v2_state.sent_garbage)
  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/p2p.py", line 387, in send_raw_message
    raise IOError('Not connected')
OSError: Not connected

    It seems like at least it might be a good idea to make the explicit timeouts in the test a bit less aggressive, i.e. change timeout=5 to timeout=10 or so in the two places.

  6. tdb3 approved
  7. tdb3 commented at 12:13 PM on July 10, 2024: contributor

    ACK 9cb68fa7dcd286629d727abce3282ce8a33d8acc

    Tested with the sleep() statement added into generate_keypair_and_garbage() in master and the PR branch. Failure only occurred on master (as expected).

  8. DrahtBot requested review from fjahr on Jul 10, 2024
  9. stratospher force-pushed on Jul 10, 2024
  10. stratospher commented at 2:00 PM on July 10, 2024: contributor

    I could verify that the issue I see with sleep(3) is fixed with the change here. However, when I increase the number from 3 to 5 or 10 I still see other errors, so there may be more potential for race conditions here. @fjahr good find! both the errors which you shared are because of disconnections due to InactivityCheck triggers from setting peertimeout=3 in the test. I've increased it to peertimeout=5 for more leeway.

    It seems like at least it might be a good idea to make the explicit timeouts in the test a bit less aggressive, i.e. change timeout=5 to timeout=10 or so in the two places.

    I've taken your suggestion and made it to timeout=10.

  11. in test/functional/p2p_v2_misbehaving.py:129 in 53f4329387 outdated 
     125 | @@ -126,7 +126,7 @@ def data_received(self, t):
 126 |  class EncryptedP2PMisbehaving(BitcoinTestFramework):
 127 |      def set_test_params(self):
 128 |          self.num_nodes = 1
 129 | -        self.extra_args = [["-v2transport=1", "-peertimeout=3"]]
 130 | +        self.extra_args = [["-v2transport=1", "-peertimeout=5"]]
    maflcko commented at 2:07 PM on July 10, 2024:

    This means the test is idle for this time in wall clock time. You can use mocktime to fix this and also avoid intermittent issues on slow hardware. See for example test/functional/p2p_timeouts.py

    stratospher commented at 5:36 PM on July 11, 2024:

    good idea, will push an update soon.

    stratospher commented at 12:44 PM on July 15, 2024:

    Done.

  12. fjahr commented at 2:09 PM on July 10, 2024: contributor

    tACK 53f43293875de086cd0bd424fd582bc232bec3a3

  13. DrahtBot requested review from tdb3 on Jul 10, 2024
  14. in test/functional/p2p_v2_misbehaving.py:170 in 53f4329387 outdated 
     166 | @@ -166,7 +167,7 @@ def test_v2disconnection(self):
 167 |                  node0.add_p2p_connection(MisbehavingV2Peer(test_type), wait_for_verack=True, send_version=True, supports_v2_p2p=True)
 168 |                  self.log.info(f"No disconnection for {test_type.name}")
 169 |              else:
 170 | -                with node0.assert_debug_log(expected_debug_message[test_type.value], timeout=5):
 171 | +                with node0.assert_debug_log(expected_debug_message[test_type.value], timeout=10):
    maflcko commented at 2:09 PM on July 10, 2024:

    Why is it required to set a timeout here at all? The log message should happen before the disconnect, which is waited on, no?

    maflcko commented at 2:56 PM on July 10, 2024:

    Ok, I see, the peer.wait_for_disconnect() immediately returns, as there is no connection yet, and doesn't do anything.

    maflcko commented at 3:01 PM on July 10, 2024:

    My recommendation would be to remove peer.wait_for_disconnect(), since it doesn't do anything, and instead add an assert after the assert_debug_log scope to check the peer is disconnected.

    maflcko commented at 6:15 AM on July 11, 2024:

    A more involved alternative would be to add a passing connection after the misbehaving one, then wait for the disconnect of the misbehaving one after the passing one is fully connected. This should allow to avoid using the debug log polling to sync on and proceed with the test.

    stratospher commented at 12:45 PM on July 15, 2024:

    Ok, I see, the peer.wait_for_disconnect() immediately returns, as there is no connection yet, and doesn't do anything.

    I meant it as a check so that we know if self._transport got reset to None at some point of time. (self._transport is set in connection_made() when the connection is opened irrespective of whether p2p connection remains connected or disconnected)

    Why is it required to set a timeout here at all? The log message should happen before the disconnect, which is waited on, no?

    Hmm yes, makes sense that we don't need a timeout.

    A more involved alternative would be to add a passing connection after the misbehaving one, then wait for the disconnect of the misbehaving one after the passing one is fully connected. This should allow to avoid using the debug log polling to sync on and proceed with the test.

    I've used this idea!

  15. maflcko commented at 2:09 PM on July 10, 2024: member

    left two nits

  16. kevkevinpal commented at 2:59 PM on July 10, 2024: contributor

    ACK 53f4329

    I tried increasing the time out to 6 seconds and that is when I started getting the error OSError: Not connected

  17. tdb3 approved
  18. tdb3 commented at 12:06 AM on July 11, 2024: contributor

    re ACK 53f43293875de086cd0bd424fd582bc232bec3a3 Repeated test in #30420#pullrequestreview-2168907582 Would also re-review if maflcko's suggestions were implemented.

  19. stratospher force-pushed on Jul 15, 2024
  20. in test/functional/p2p_v2_misbehaving.py:132 in d4209fc79d outdated 
     128 | @@ -128,6 +129,10 @@ def set_test_params(self):
 129 |          self.num_nodes = 1
 130 |          self.extra_args = [["-v2transport=1", "-peertimeout=3"]]
 131 |  
 132 | +    def mock_forward(self, delta):
    maflcko commented at 12:51 PM on July 15, 2024:

    Nit: You can use the existing bumpmocktime helper?

    stratospher commented at 1:29 PM on July 15, 2024:

    done.

  21. in test/functional/p2p_v2_misbehaving.py:157 in d4209fc79d outdated 
     152 |          peer1.v2_state.can_data_be_received = True
 153 | +        self.wait_until(lambda: peer1.v2_state.ellswift_ours)
 154 |          peer1.send_raw_message(peer1.v2_state.ellswift_ours[4:] + peer1.v2_state.sent_garbage)
 155 | +        self.mock_forward(3)
 156 | +        # `InactivityCheck()` displays a different net log message compared to the one specified below if `sendSet` isn't populated.
 157 | +        #  Make a passing connection so that there's time to populate `sendSet` for consistent logging.
    maflcko commented at 12:56 PM on July 15, 2024:

    Can you explain what this means? sendSet is a boolean, so what does "populated" mean? Also, when removing peer2 the test works fine, no? What would the "wrong" error message be?

    stratospher commented at 1:36 PM on July 15, 2024:

    if the test is run in a loop, sometimes "socket no message in first %I seconds" is displayed and sometimes "V2 handshake timeout" is displayed.

    if sendSet is not set, "socket no message in first %i seconds" is displayed since that check is above the check for the handshake timeout in InactivityCheck().

    I've changed the sendSet vocabulary from populated -> set. open to better wordings.

    maflcko commented at 1:49 PM on July 15, 2024:

    if the test is run in a loop, sometimes "socket no message in first %I seconds" is displayed and sometimes "V2 handshake timeout" is displayed.

    I couldn't reproduce this locally. Also, it seems odd that one member field of a peer affects the field of another peer.

    stratospher commented at 1:56 PM on July 15, 2024:

    here's a failure I get when removing peer2:

    $ test/functional/p2p_v2_misbehaving.py 
2024-07-15T13:53:35.169000Z TestFramework (INFO): PRNG seed is: 5439305671400460804
2024-07-15T13:53:35.169000Z TestFramework (INFO): Initializing test directory /var/folders/23/1bj9v8kx4pjdz4nm49dhx2440000gn/T/bitcoin_func_test_72i8znef
2024-07-15T13:53:35.444000Z TestFramework (INFO): Sending ellswift bytes in parts to ensure that response from responder is received only when
2024-07-15T13:53:35.444000Z TestFramework (INFO): ellswift bytes have a mismatch from the 16 bytes(network magic followed by "version\x00\x00\x00\x00\x00")
2024-07-15T13:53:35.444000Z TestFramework (INFO): Sending first 4 bytes of ellswift which match network magic
2024-07-15T13:53:35.444000Z TestFramework (INFO): If a response is received, assertion failure would happen in our custom data_received() function
2024-07-15T13:53:35.495000Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is
2024-07-15T13:53:35.495000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure
2024-07-15T13:53:37.518000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/Users/stratospher/code/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
    self.run_test()
  File "/Users/stratospher/code/bitcoin/test/functional/p2p_v2_misbehaving.py", line 133, in run_test
    self.test_earlykeyresponse()
  File "/Users/stratospher/code/bitcoin/test/functional/p2p_v2_misbehaving.py", line 156, in test_earlykeyresponse
    with node0.assert_debug_log(['V2 handshake timeout peer=0']):
  File "/opt/homebrew/Cellar/python@3.12/3.12.4/Frameworks/Python.framework/Versions/3.12/lib/python3.12/contextlib.py", line 144, in __exit__
    next(self.gen)
  File "/Users/stratospher/code/bitcoin/test/functional/test_framework/test_node.py", line 491, in assert_debug_log
    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
  File "/Users/stratospher/code/bitcoin/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['V2 handshake timeout peer=0']" does not partially match log:

 - 2024-07-15T13:53:35.496313Z (mocktime: 2024-07-15T13:53:38Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59333
 - 2024-07-15T13:53:35.496378Z (mocktime: 2024-07-15T13:53:38Z) [httpworker.0] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__
 - 2024-07-15T13:53:35.496676Z (mocktime: 2024-07-15T13:53:39Z) [net] [net.cpp:1972] [InactivityCheck] [net] ####### 1. INSIDE InactivityCheck()
 - 2024-07-15T13:53:35.496691Z (mocktime: 2024-07-15T13:53:39Z) [net] [net.cpp:1973] [InactivityCheck] [net] ####### last_send = 0
 - 2024-07-15T13:53:35.496705Z (mocktime: 2024-07-15T13:53:39Z) [net] [net.cpp:1975] [InactivityCheck] [net] socket no message in first 3 seconds, 1 0 peer=0
 - 2024-07-15T13:53:35.496722Z (mocktime: 2024-07-15T13:53:39Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0
 - 2024-07-15T13:53:35.496775Z (mocktime: 2024-07-15T13:53:39Z) [net] [net_processing.cpp:1771] [FinalizeNode] [net] Cleared nodestate for peer=0


2024-07-15T13:53:37.578000Z TestFramework (INFO): Stopping nodes
2024-07-15T13:53:37.745000Z TestFramework (WARNING): Not cleaning up dir /var/folders/23/1bj9v8kx4pjdz4nm49dhx2440000gn/T/bitcoin_func_test_72i8znef
2024-07-15T13:53:37.745000Z TestFramework (ERROR): Test failed. Test logging available at /var/folders/23/1bj9v8kx4pjdz4nm49dhx2440000gn/T/bitcoin_func_test_72i8znef/test_framework.log
2024-07-15T13:53:37.745000Z TestFramework (ERROR): 
2024-07-15T13:53:37.746000Z TestFramework (ERROR): Hint: Call /Users/stratospher/code/bitcoin/test/functional/combine_logs.py '/var/folders/23/1bj9v8kx4pjdz4nm49dhx2440000gn/T/bitcoin_func_test_72i8znef' to consolidate all logs
2024-07-15T13:53:37.746000Z TestFramework (ERROR): 
2024-07-15T13:53:37.746000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2024-07-15T13:53:37.746000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2024-07-15T13:53:37.746000Z TestFramework (ERROR):
    stratospher commented at 2:02 PM on July 15, 2024:

    Also, it seems odd that one member field of a peer affects the field of another peer.

    no, it doesn't! I just want some way to wait some time so that sendSet for the same peer can get set. it will eventually get set but not immediately.

    we could replace:

    peer2 = node0.add_p2p_connection(P2PInterface())
assert peer2.is_connected

    with

    import time; time.sleep(3)

    and it would do!

    maflcko commented at 2:11 PM on July 15, 2024:

    Ok, I see. Would an alternative be to wait until the RPC's peer info bytessent or bytesrecv increased after the send_raw_message?

    Alternatively, I presume the reason that sendSet is set is because send_raw_message is executed. So the comment could simply say the this is to ensure the message sent is actually received.

    Anything is fine tough. I see now why it is needed.

    stratospher commented at 3:23 PM on July 15, 2024:

    yeah, much simpler. done.

  22. stratospher force-pushed on Jul 15, 2024
  23. maflcko commented at 2:14 PM on July 15, 2024: member

    ACK 5a6bb243adb705ac876ef1efd58a4768fa4ed033

  24. DrahtBot requested review from tdb3 on Jul 15, 2024
  25. test: Fix intermittent failure in p2p_v2_misbehaving.py
    The ellswift bytes are computed in the NetworkThread and sent in
the MainThread. Add a `wait_until()` to make sure that ellswift
computation is completed in NetworkThread before sending it in
the MainThread. Also wait until bytes sent are actually received
and use mocktime for more robust disconnection checking.
    c6d43367a1
  26. stratospher force-pushed on Jul 15, 2024
  27. mzumsande commented at 5:39 PM on July 15, 2024: contributor

    Code Review ACK c6d43367a1ec47c004991143f031417c4e4b8095

  28. DrahtBot requested review from maflcko on Jul 15, 2024
  29. tdb3 approved
  30. tdb3 commented at 10:29 PM on July 15, 2024: contributor

    cr and t ACK c6d43367a1ec47c004991143f031417c4e4b8095 Repeated test in #30420#pullrequestreview-2168907582

  31. maflcko commented at 6:30 AM on July 16, 2024: member

    ACK c6d43367a1ec47c004991143f031417c4e4b8095

  32. fanquake merged this on Jul 16, 2024
  33. fanquake closed this on Jul 16, 2024
  34. in test/functional/p2p_v2_misbehaving.py:152 in c6d43367a1 
     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 6:09 AM on July 17, 2024:

    3 is the peer timeout, so you'll have to change it to bump 2 here. Otherwise, the test will fail:

    https://cirrus-ci.com/task/5359619151757312?logs=ci#L3935

     test  2024-07-17T05:25:54.632000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:15680 
 node0 2024-07-17T05:25:54.634738Z (mocktime: 2024-07-17T05:25:54Z) [net] [net.cpp:3764] [CNode] [net] Added connection peer=0 
 node0 2024-07-17T05:25:54.634776Z (mocktime: 2024-07-17T05:25:54Z) [net] [net.cpp:1814] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:35786 accepted 
 test  2024-07-17T05:25:54.637000Z TestFramework.p2p (DEBUG): sending 3973 bytes of garbage data 
 test  2024-07-17T05:25:54.682000Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is 
 test  2024-07-17T05:25:54.682000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure 
 node0 2024-07-17T05:25:54.683023Z (mocktime: 2024-07-17T05:25:54Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276 
 node0 2024-07-17T05:25:54.686396Z (mocktime: 2024-07-17T05:25:54Z) [httpworker.0] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ 
 node0 2024-07-17T05:25:54.686869Z (mocktime: 2024-07-17T05:25:57Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276 
 node0 2024-07-17T05:25:54.686921Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.2] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__ 
 node0 2024-07-17T05:25:54.687051Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.2] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_vRecv, net.cpp:630 started 
 node0 2024-07-17T05:25:54.687435Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.2] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_vRecv, net.cpp:630 completed (370μs) 
 test  2024-07-17T05:25:54.688000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:15680 
 node0 2024-07-17T05:25:54.688100Z (mocktime: 2024-07-17T05:25:57Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276 
 node0 2024-07-17T05:25:54.688149Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.3] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ 
 node0 2024-07-17T05:25:54.688344Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:1971] [InactivityCheck] [net] socket no message in first 3 seconds, 1 0 peer=0 
 node0 2024-07-17T05:25:54.688378Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0 
 node0 2024-07-17T05:25:54.688685Z (mocktime: 2024-07-17T05:25:58Z) [net] [net_processing.cpp:1771] [FinalizeNode] [net] Cleared nodestate for peer=0 
 node0 2024-07-17T05:26:39.522126Z (mocktime: 2024-07-17T05:25:58Z) [scheduler] [net.cpp:2369] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers 
 test  2024-07-17T05:27:14.735000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-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-i686-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-i686-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 153, in test_earlykeyresponse
                                       with node0.assert_debug_log(['V2 handshake timeout peer=0']):
                                     File "/usr/lib/python3.12/contextlib.py", line 144, in __exit__
                                       next(self.gen)
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 506, in assert_debug_log
                                       self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 192, in _raise_assertion_error
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 0] Expected messages "['V2 handshake timeout peer=0']" does not partially match log:
                                    - 2024-07-17T05:25:54.688100Z (mocktime: 2024-07-17T05:25:57Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276
                                    - 2024-07-17T05:25:54.688149Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.3] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__
                                    - 2024-07-17T05:25:54.688344Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:1971] [InactivityCheck] [net] socket no message in first 3 seconds, 1 0 peer=0
                                    - 2024-07-17T05:25:54.688378Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0
                                    - 2024-07-17T05:25:54.688685Z (mocktime: 2024-07-17T05:25:58Z) [net] [net_processing.cpp:1771] [FinalizeNode] [net] Cleared nodestate for peer=0
                                    - 2024-07-17T05:26:39.522126Z (mocktime: 2024-07-17T05:25:58Z) [scheduler] [net.cpp:2369] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers
    maflcko commented at 6:11 AM on July 17, 2024:

    Also, you'll have to move it up by one line. Otherwise it is racy, because sometimes it will be bumped when the message was sent, and sometimes before the raw message was sent.

    stratospher commented at 9:54 AM on July 17, 2024:

    3 is the peer timeout, so you'll have to change it to bump 2 here. Otherwise, the test will fail:

    I didn't follow. The inactivity check trigger runs only when we bump by > 3 and not when the bump = 3 right. I tried logging return node.m_connected + m_peer_connect_timeout < now; condition in ShouldRunInactivityChecks():

    [net] [net.cpp:1968] [ShouldRunInactivityChecks] [net] Inactivity check does not run because 1721209275 + 3 >= 1721209275
TestFramework.node0 (DEBUG): Bump mocktime by 3 seconds
[net] [net.cpp:1968] [ShouldRunInactivityChecks] [net] Inactivity check does not run because 1721209275 + 3 >= 1721209278
TestFramework.node0 (DEBUG): Bump mocktime by 1 seconds 
[net] [net.cpp:1968] [ShouldRunInactivityChecks] [net] Inactivity check runs because 1721209275 + 3 < 1721209279

    Also, you'll have to move it up by one line.

    right, makes sense.

    stratospher commented at 10:46 AM on July 17, 2024:

    done in https://github.com/bitcoin/bitcoin/pull/30468

  35. stratospher deleted the branch on Jul 17, 2024
  36. fanquake referenced this in commit 5f5862f382 on Jul 17, 2024
  37. bitcoin locked this on Jul 18, 2025
Contributors
stratospherDrahtBotfjahrtdb3maflckokevkevinpalmzumsande


fjahr

Labels
Tests

Milestone
28.0

Linked (view graph)
#30419 ci: failure in `p2p_v2_misbehaving.py`#30468 test: bump mocktime only after node has received and sent bytes
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-05-02 03:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me