test: fix debug log assertion in p2p_i2p_ports test #30345

pull ceffikhan wants to merge 2 commits into bitcoin:master from ceffikhan:master changing 1 files +1 −1
  1. ceffikhan commented at 0:37 am on June 27, 2024: none

    This PR addresses an p2p_i2p_ports.py test in the Bitcoin Core test framework where the expected debug log message was incorrect, causing the test to fail intermittently.

    Changes:

    • Corrected the expected debug log message in test/functional/p2p_i2p_ports.py to properly match the error message generated.

    Steps Taken to Fix:

    -Updated the expected debug log message in the method.

    Closes #30030

  2. DrahtBot commented at 0:37 am on June 27, 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
    Concept ACK brunoerg

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

  3. DrahtBot added the label Tests on Jun 27, 2024
  4. Fix debug log assertion in p2p_i2p_ports.py test 
    This commit addresses the expected debug log message in the p2p_i2p_ports.py test to ensure proper error message is checked. This fixes the issue where the test was failing due to an incorrect expected message.

Changes:
- Corrected the expected debug log message to match the actual error generated by the I2P connection attempt.
    1aca3d1e85
  5. ceffikhan force-pushed on Jun 27, 2024
  6. brunoerg commented at 12:38 pm on June 27, 2024: contributor
    Concept ACK
  7. ceffikhan commented at 8:18 pm on June 30, 2024: none

    Hi @pinheadmz ,

    Could you please review this pull request when you have a moment? Your feedback would be greatly appreciated!

    Thank you!

  8. brunoerg commented at 2:15 pm on July 1, 2024: contributor

    I’m not 100% convinced of the change in this PR, I mean, just removing the second part of the expected log.

    The log (from #30030) says:

     0 test  2024-04-28T17:46:07.437000Z TestFramework (INFO): Ensure we try to connect if port=0 and get an error due to missing I2P proxy 
 1 node0 2024-04-28T17:46:07.437631Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 2 node0 2024-04-28T17:46:07.437669Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__ 
 3 node0 2024-04-28T17:46:07.437708Z [httpworker.0] [net.cpp:410] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs 
 4 node0 2024-04-28T17:46:07.437733Z [httpworker.0] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session ef0bda29ed with 127.0.0.1:60000 
 5 node0 2024-04-28T17:46:07.437887Z [httpworker.0] [i2p.cpp:289] [Log] [i2p] Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Missing RESULT= in the reply to "HELLO VERSION MIN=3.1 MAX=3.1": "HELLO VERSION MIN=3.1 MAX=3.1" 
 6 node0 2024-04-28T17:46:08.362998Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session d00fa05b26 with 127.0.0.1:60000 
 7 node0 2024-04-28T17:46:08.363157Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
 8 node0 2024-04-28T17:46:08.363230Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 9 node0 2024-04-28T17:46:10.363358Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session e6c846052b with 127.0.0.1:60000 
10 node0 2024-04-28T17:46:10.363457Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
11 node0 2024-04-28T17:46:10.363506Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
12 node0 2024-04-28T17:46:13.363629Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 52392d7213 with 127.0.0.1:60000 
13 node0 2024-04-28T17:46:13.363758Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
14 node0 2024-04-28T17:46:13.363815Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
15 node0 2024-04-28T17:46:17.363936Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 7b4ca1e901 with 127.0.0.1:60000 
16 node0 2024-04-28T17:46:17.364079Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
17 node0 2024-04-28T17:46:17.364140Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
18 node0 2024-04-28T17:46:22.364266Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 71fd5d01e7 with 127.0.0.1:60000 
19 node0 2024-04-28T17:46:22.364418Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
20 node0 2024-04-28T17:46:22.364476Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
21 node0 2024-04-28T17:46:28.364604Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 456c2be19d with 127.0.0.1:60000 
22 node0 2024-04-28T17:46:28.364747Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
23 node0 2024-04-28T17:46:28.364801Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
24 node0 2024-04-28T17:46:35.364979Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session fe9c34d0c4 with 127.0.0.1:60000 
25 node0 2024-04-28T17:46:35.365142Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
26 node0 2024-04-28T17:46:35.365204Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
27 node0 2024-04-28T17:46:43.365375Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 259947762e with 127.0.0.1:60000 
28 node0 2024-04-28T17:46:43.365547Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
29 node0 2024-04-28T17:46:43.365610Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
30 node0 2024-04-28T17:46:52.351012Z [scheduler] [net.cpp:2345] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers 
31 node0 2024-04-28T17:46:52.365791Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 9382e16d70 with 127.0.0.1:60000 
32 node0 2024-04-28T17:46:52.365952Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
33 node0 2024-04-28T17:46:52.366015Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
34 node0 2024-04-28T17:47:02.366195Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 6e43de2025 with 127.0.0.1:60000 
35 node0 2024-04-28T17:47:02.366391Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
36 node0 2024-04-28T17:47:02.366454Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
37 node0 2024-04-28T17:47:13.366620Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 84a7e1afb0 with 127.0.0.1:60000 
38 node0 2024-04-28T17:47:13.366787Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
39 node0 2024-04-28T17:47:13.366860Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
40 node0 2024-04-28T17:47:25.367036Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session ba0e7156d5 with 127.0.0.1:60000 
41 node0 2024-04-28T17:47:25.367240Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111) 
42 node0 2024-04-28T17:47:25.367302Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
43 test  2024-04-28T17:47:27.449000Z TestFramework (ERROR): Assertion failed 
44                                   Traceback (most recent call last):
45                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
46                                       self.run_test()
47                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_i2p_ports.py", line 30, in run_test
48                                       with node.assert_debug_log(expected_msgs=[f"Error connecting to {addr}: Cannot connect to {PROXY}"]):
49                                     File "/usr/lib/python3.10/contextlib.py", line 142, in __exit__
50                                       next(self.gen)
51                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 490, in assert_debug_log
52                                       self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
53                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
54                                       raise AssertionError(self._node_msg(msg))
55                                   AssertionError: [node 0] Expected messages "['Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Cannot connect to 127.0.0.1:60000']" does not partially match log:

    So, we’re basically expecting Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Cannot connect to 127.0.0.1:60000 since we expect it cannot connect to the proxy. However, what we get is:

    0Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Missing RESULT= in the reply to "HELLO VERSION MIN=3.1 MAX=3.1": "HELLO VERSION MIN=3.1 MAX=3.1"
  9. vasild commented at 3:43 pm on July 1, 2024: contributor

    I’m not 100% convinced of the change in this PR

    Right. This looks quite bizarre to me. Session::Hello() creates the socket and it shouldn’t be able to proceed since it shouldn’t be able connect to 127.0.0.1:60000. However, from the log message Missing RESULT= it seems it managed to call SendRequestAndGetReply(*sock, "HELLO VERSION MIN=3.1 MAX=3.1");, write to that socket, got a reply and is upset because the reply is missing RESULT=, and the reply is the same as the request :raised_eyebrow:

  10. pinheadmz commented at 5:02 pm on July 1, 2024: member
    @vasild is it possible that in the intermittent case, some other test running in parallel has a process that is listening on port 60000? So we connect OK but fail the i2p handshake?
  11. brunoerg commented at 5:16 pm on July 1, 2024: contributor

    @vasild is it possible that in the intermittent case, some other test running in parallel has a process that is listening on port 60000? So we connect OK but fail the i2p handshake?

    Yes, it’s possible. I just started a server with python3 -m http.server 60000 and ran the test (from master branch), I got:

    0AssertionError: [node 0] Expected messages "['Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Cannot connect to 127.0.0.1:60000']" does not partially match log:
1
2 - 2024-07-01T17:14:12.228574Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:64704
3 - 2024-07-01T17:14:12.228609Z [httpworker.3] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__
4 - 2024-07-01T17:14:12.228629Z [httpworker.3] [net.cpp:407] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs
5 - 2024-07-01T17:14:12.228644Z [httpworker.3] [i2p.cpp:417] [CreateIfNotCreatedAlready] [i2p] Creating persistent SAM session 660c4438c4 with 127.0.0.1:60000
6 - 2024-07-01T17:14:12.230004Z [httpworker.3] [i2p.cpp:274] [Connect] [i2p] Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Missing RESULT= in the reply to "HELLO VERSION MIN=3.1 MAX=3.1": "<!DOCTYPE HTML>"
7 - 2024-07-01T17:14:13.158547Z [i2paccept] [i2p.cpp:417] [CreateIfNotCreatedAlready] [i2p] Creating persistent SAM session 5e7b16c5b0 with 127.0.0.1:60000
8 - 2024-07-01T17:14:13.159729Z [i2paccept] [i2p.cpp:151] [Listen] [i2p:error] Couldn't listen: Missing RESULT= in the reply to "HELLO VERSION MIN=3.1 MAX=3.1": "<!DOCTYPE HTML>"
  12. Merge branch 'bitcoin:master' into master ed2662e5cb
  13. ceffikhan commented at 8:10 pm on July 1, 2024: none
    closing PR for now
  14. ceffikhan closed this on Jul 1, 2024
  15. vasild commented at 11:53 am on July 2, 2024: contributor

    Ok, in the case with python3 -m http.server 60000 the reply is <!DOCTYPE HTML>. In the CI the reply is HELLO VERSION MIN=3.1 MAX=3.1, same as the request. So some “echo tcp server” is running on port 60000!?

    I wonder what is a sure way to find an address and port that will fail the connection quickly? Maybe pick one of the “reserved” ports from https://en.wikipedia.org/wiki/List_of_TCP_and_UDP_port_numbers, e.g. 127.0.0.1:250? Or use the P2P port of node0 (p2p_port(0)), bitcoind is listening on it, but at least trying to speak I2P SAM to it will fail in a deterministic way?

  16. brunoerg commented at 12:28 pm on July 3, 2024: contributor

    Ok, in the case with python3 -m http.server 60000 the reply is . In the CI the reply is HELLO VERSION MIN=3.1 MAX=3.1, same as the request.

    Yes, just did that to exemplify.

    I wonder what is a sure way to find an address and port that will fail the connection quickly? Maybe pick one of the “reserved” ports from https://en.wikipedia.org/wiki/List_of_TCP_and_UDP_port_numbers, e.g. 127.0.0.1:250? Or use the P2P port of node0 (p2p_port(0)), bitcoind is listening on it, but at least trying to speak I2P SAM to it will fail in a deterministic way

    Perhaps we could get a random available port for that?

  17. vasild commented at 9:14 am on July 24, 2024: contributor

    Perhaps we could get a random available port for that?

    How?


ceffikhan DrahtBot brunoerg vasild pinheadmz

Labels
Tests

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