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:
Steps Taken to Fix:
-Updated the expected debug log message in the method.
Closes #30030
<!--e57a25ab6845829454e8d69fc972939a-->
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
<!--006a51241073e994b41acfe9ec718e94-->
For detailed information about the code coverage, see the test coverage report.
<!--021abf342d371248e50ceaed478a90ca-->
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.
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.
Concept ACK
Hi @pinheadmz ,
Could you please review this pull request when you have a moment? Your feedback would be greatly appreciated!
Thank you!
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:
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
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
node0 2024-04-28T17:46:07.437669Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__
node0 2024-04-28T17:46:07.437708Z [httpworker.0] [net.cpp:410] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs
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
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"
node0 2024-04-28T17:46:08.362998Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session d00fa05b26 with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:08.363230Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:10.363358Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session e6c846052b with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:10.363506Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:13.363629Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 52392d7213 with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:13.363815Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:17.363936Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 7b4ca1e901 with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:17.364140Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:22.364266Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 71fd5d01e7 with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:22.364476Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:28.364604Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 456c2be19d with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:28.364801Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:35.364979Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session fe9c34d0c4 with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:35.365204Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:43.365375Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 259947762e with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:43.365610Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:46:52.351012Z [scheduler] [net.cpp:2345] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers
node0 2024-04-28T17:46:52.365791Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 9382e16d70 with 127.0.0.1:60000
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)
node0 2024-04-28T17:46:52.366015Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:47:02.366195Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 6e43de2025 with 127.0.0.1:60000
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)
node0 2024-04-28T17:47:02.366454Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:47:13.366620Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 84a7e1afb0 with 127.0.0.1:60000
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)
node0 2024-04-28T17:47:13.366860Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
node0 2024-04-28T17:47:25.367036Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session ba0e7156d5 with 127.0.0.1:60000
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)
node0 2024-04-28T17:47:25.367302Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
test 2024-04-28T17:47:27.449000Z TestFramework (ERROR): Assertion failed
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_i2p_ports.py", line 30, in run_test
with node.assert_debug_log(expected_msgs=[f"Error connecting to {addr}: Cannot connect to {PROXY}"]):
File "/usr/lib/python3.10/contextlib.py", line 142, in __exit__
next(self.gen)
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
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-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
raise AssertionError(self._node_msg(msg))
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:
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"
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:
@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:
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:
- 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
- 2024-07-01T17:14:12.228609Z [httpworker.3] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__
- 2024-07-01T17:14:12.228629Z [httpworker.3] [net.cpp:407] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs
- 2024-07-01T17:14:12.228644Z [httpworker.3] [i2p.cpp:417] [CreateIfNotCreatedAlready] [i2p] Creating persistent SAM session 660c4438c4 with 127.0.0.1:60000
- 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>"
- 2024-07-01T17:14:13.158547Z [i2paccept] [i2p.cpp:417] [CreateIfNotCreatedAlready] [i2p] Creating persistent SAM session 5e7b16c5b0 with 127.0.0.1:60000
- 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>"
closing PR for now
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?
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.
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?
Perhaps we could get a random available port for that?
How?