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:

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

    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:

     02024-07-10T10:56:33.201000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure
 12024-07-10T10:56:38.167000Z TestFramework.p2p (WARNING): Connection lost to 127.0.0.1:15258 due to [Errno 32] Broken pipe
 22024-07-10T10:56:40.217000Z TestFramework (ERROR): Assertion failed
 3Traceback (most recent call last):
 4  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
 5    self.run_test()
 6  File "/Users/FJ/projects/clones/bitcoin/test/functional/p2p_v2_misbehaving.py", line 132, in run_test
 7    self.test_earlykeyresponse()
 8  File "/Users/FJ/projects/clones/bitcoin/test/functional/p2p_v2_misbehaving.py", line 148, in test_earlykeyresponse
 9    with node0.assert_debug_log(['V2 handshake timeout peer=0']):
10  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__
11    next(self.gen)
12  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_node.py", line 491, in assert_debug_log
13    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
14  File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
15    raise AssertionError(self._node_msg(msg))
16AssertionError: [node 0] Expected messages "['V2 handshake timeout peer=0']" does not partially match log:
17
18 -

    and

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

     0$ test/functional/p2p_v2_misbehaving.py 
 12024-07-15T13:53:35.169000Z TestFramework (INFO): PRNG seed is: 5439305671400460804
 22024-07-15T13:53:35.169000Z TestFramework (INFO): Initializing test directory /var/folders/23/1bj9v8kx4pjdz4nm49dhx2440000gn/T/bitcoin_func_test_72i8znef
 32024-07-15T13:53:35.444000Z TestFramework (INFO): Sending ellswift bytes in parts to ensure that response from responder is received only when
 42024-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")
 52024-07-15T13:53:35.444000Z TestFramework (INFO): Sending first 4 bytes of ellswift which match network magic
 62024-07-15T13:53:35.444000Z TestFramework (INFO): If a response is received, assertion failure would happen in our custom data_received() function
 72024-07-15T13:53:35.495000Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is
 82024-07-15T13:53:35.495000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure
 92024-07-15T13:53:37.518000Z TestFramework (ERROR): Assertion failed
10Traceback (most recent call last):
11  File "/Users/stratospher/code/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
12    self.run_test()
13  File "/Users/stratospher/code/bitcoin/test/functional/p2p_v2_misbehaving.py", line 133, in run_test
14    self.test_earlykeyresponse()
15  File "/Users/stratospher/code/bitcoin/test/functional/p2p_v2_misbehaving.py", line 156, in test_earlykeyresponse
16    with node0.assert_debug_log(['V2 handshake timeout peer=0']):
17  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__
18    next(self.gen)
19  File "/Users/stratospher/code/bitcoin/test/functional/test_framework/test_node.py", line 491, in assert_debug_log
20    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
21  File "/Users/stratospher/code/bitcoin/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
22    raise AssertionError(self._node_msg(msg))
23AssertionError: [node 0] Expected messages "['V2 handshake timeout peer=0']" does not partially match log:
24
25 - 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
26 - 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__
27 - 2024-07-15T13:53:35.496676Z (mocktime: 2024-07-15T13:53:39Z) [net] [net.cpp:1972] [InactivityCheck] [net] ####### 1. INSIDE InactivityCheck()
28 - 2024-07-15T13:53:35.496691Z (mocktime: 2024-07-15T13:53:39Z) [net] [net.cpp:1973] [InactivityCheck] [net] ####### last_send = 0
29 - 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
30 - 2024-07-15T13:53:35.496722Z (mocktime: 2024-07-15T13:53:39Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0
31 - 2024-07-15T13:53:35.496775Z (mocktime: 2024-07-15T13:53:39Z) [net] [net_processing.cpp:1771] [FinalizeNode] [net] Cleared nodestate for peer=0
32
33
342024-07-15T13:53:37.578000Z TestFramework (INFO): Stopping nodes
352024-07-15T13:53:37.745000Z TestFramework (WARNING): Not cleaning up dir /var/folders/23/1bj9v8kx4pjdz4nm49dhx2440000gn/T/bitcoin_func_test_72i8znef
362024-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
372024-07-15T13:53:37.745000Z TestFramework (ERROR): 
382024-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
392024-07-15T13:53:37.746000Z TestFramework (ERROR): 
402024-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.
412024-07-15T13:53:37.746000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
422024-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:

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

    with

    0import 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

     0 test  2024-07-17T05:25:54.632000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:15680 
 1 node0 2024-07-17T05:25:54.634738Z (mocktime: 2024-07-17T05:25:54Z) [net] [net.cpp:3764] [CNode] [net] Added connection peer=0 
 2 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 
 3 test  2024-07-17T05:25:54.637000Z TestFramework.p2p (DEBUG): sending 3973 bytes of garbage data 
 4 test  2024-07-17T05:25:54.682000Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is 
 5 test  2024-07-17T05:25:54.682000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure 
 6 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 
 7 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__ 
 8 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 
 9 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__ 
10 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 
11 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) 
12 test  2024-07-17T05:25:54.688000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:15680 
13 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 
14 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__ 
15 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 
16 node0 2024-07-17T05:25:54.688378Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0 
17 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 
18 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 
19 test  2024-07-17T05:27:14.735000Z TestFramework (ERROR): Assertion failed 
20                                   Traceback (most recent call last):
21                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
22                                       self.run_test()
23                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 133, in run_test
24                                       self.test_earlykeyresponse()
25                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 153, in test_earlykeyresponse
26                                       with node0.assert_debug_log(['V2 handshake timeout peer=0']):
27                                     File "/usr/lib/python3.12/contextlib.py", line 144, in __exit__
28                                       next(self.gen)
29                                     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
30                                       self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
31                                     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
32                                       raise AssertionError(self._node_msg(msg))
33                                   AssertionError: [node 0] Expected messages "['V2 handshake timeout peer=0']" does not partially match log:
34                                    - 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
35                                    - 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__
36                                    - 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
37                                    - 2024-07-17T05:25:54.688378Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0
38                                    - 2024-07-17T05:25:54.688685Z (mocktime: 2024-07-17T05:25:58Z) [net] [net_processing.cpp:1771] [FinalizeNode] [net] Cleared nodestate for peer=0
39                                    - 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():

    0[net] [net.cpp:1968] [ShouldRunInactivityChecks] [net] Inactivity check does not run because 1721209275 + 3 >= 1721209275
1TestFramework.node0 (DEBUG): Bump mocktime by 3 seconds
2[net] [net.cpp:1968] [ShouldRunInactivityChecks] [net] Inactivity check does not run because 1721209275 + 3 >= 1721209278
3TestFramework.node0 (DEBUG): Bump mocktime by 1 seconds 
4[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


stratospher DrahtBot fjahr tdb3 maflcko kevkevinpal mzumsande


fjahr

Labels
Tests

Milestone
28.0

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: 2024-11-21 12:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me