Intermittent issue in p2p_i2p_ports.py AssertionError: [node 0] Expected messages “[‘Error connecting to […].b32.i2p:0: Cannot connect to 127.0.0.1:60000’]” does not partially match log: #30030

issue maflcko openend this issue on May 3, 2024

maflcko commented at 9:53 am on May 3, 2024: member

https://cirrus-ci.com/task/4526270581571584?logs=ci#L3634

  0 test  2024-04-28T17:46:07.431000Z TestFramework.node0 (DEBUG): RPC successfully started 
  1 test  2024-04-28T17:46:07.431000Z TestFramework (DEBUG): Generate a block with current time 
  2 test  2024-04-28T17:46:07.431000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress` 
  3 node0 2024-04-28T17:46:07.431322Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
  4 node0 2024-04-28T17:46:07.431380Z [httpworker.1] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
  5 node0 2024-04-28T17:46:07.431901Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
  6 node0 2024-04-28T17:46:07.431963Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__ 
  7 node0 2024-04-28T17:46:07.432032Z [httpworker.0] [node/miner.cpp:163] [CreateNewBlock] CreateNewBlock(): block weight: 904 txs: 0 fees: 0 sigops 400 
  8 node0 2024-04-28T17:46:07.432073Z [httpworker.0] [validation.cpp:2337] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
  9 node0 2024-04-28T17:46:07.432094Z [httpworker.0] [validation.cpp:2439] [ConnectBlock] [bench]     - Fork checks: 0.02ms [0.00s (0.02ms/blk)] 
 10 node0 2024-04-28T17:46:07.432108Z [httpworker.0] [validation.cpp:2531] [ConnectBlock] [bench]       - Connect 1 transactions: 0.01ms (0.011ms/tx, 0.000ms/txin) [0.00s (0.01ms/blk)] 
 11 node0 2024-04-28T17:46:07.432123Z [httpworker.0] [validation.cpp:2549] [ConnectBlock] [bench]     - Verify 0 txins: 0.03ms (0.000ms/txin) [0.00s (0.03ms/blk)] 
 12 node0 2024-04-28T17:46:07.432133Z [httpworker.0] [node/miner.cpp:182] [CreateNewBlock] [bench] CreateNewBlock() packages: 0.01ms (0 packages, 0 updated descendants), validity: 0.11ms (total 0.12ms) 
 13 node0 2024-04-28T17:46:07.432148Z [httpworker.0] [validation.cpp:4209] [AcceptBlockHeader] [validation] Saw new header hash=3d85c0577c39dd26e5317925700277c541e6f13a6c7a53df98364cdb2180c6f5 height=200 
 14 node0 2024-04-28T17:46:07.432383Z [httpworker.0] [validation.cpp:3007] [ConnectTip] [bench]   - Using cached block 
 15 node0 2024-04-28T17:46:07.432396Z [httpworker.0] [validation.cpp:3017] [ConnectTip] [bench]   - Load block from disk: 0.01ms 
 16 node0 2024-04-28T17:46:07.432424Z [httpworker.0] [validation.cpp:2337] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
 17 node0 2024-04-28T17:46:07.432441Z [httpworker.0] [validation.cpp:2439] [ConnectBlock] [bench]     - Fork checks: 0.02ms [0.00s (0.02ms/blk)] 
 18 node0 2024-04-28T17:46:07.432456Z [httpworker.0] [validation.cpp:2531] [ConnectBlock] [bench]       - Connect 1 transactions: 0.01ms (0.013ms/tx, 0.000ms/txin) [0.00s (0.01ms/blk)] 
 19 node0 2024-04-28T17:46:07.432468Z [httpworker.0] [validation.cpp:2549] [ConnectBlock] [bench]     - Verify 0 txins: 0.03ms (0.000ms/txin) [0.00s (0.03ms/blk)] 
 20 node0 2024-04-28T17:46:07.432517Z [httpworker.0] [validation.cpp:2563] [ConnectBlock] [bench]     - Write undo data: 0.05ms [0.00s (0.02ms/blk)] 
 21 node0 2024-04-28T17:46:07.432529Z [httpworker.0] [validation.cpp:2578] [ConnectBlock] [bench]     - Index writing: 0.01ms [0.00s (0.01ms/blk)] 
 22 node0 2024-04-28T17:46:07.432541Z [httpworker.0] [validationinterface.cpp:245] [BlockChecked] [validation] BlockChecked: block hash=3d85c0577c39dd26e5317925700277c541e6f13a6c7a53df98364cdb2180c6f5 state=Valid 
 23 node0 2024-04-28T17:46:07.432555Z [httpworker.0] [validation.cpp:3036] [ConnectTip] [bench]   - Connect total: 0.16ms [0.00s (0.08ms/blk)] 
 24 node0 2024-04-28T17:46:07.432575Z [httpworker.0] [validation.cpp:3045] [ConnectTip] [bench]   - Flush: 0.02ms [0.00s (0.01ms/blk)] 
 25 node0 2024-04-28T17:46:07.432588Z [httpworker.0] [validation.cpp:3055] [ConnectTip] [bench]   - Writing chainstate: 0.01ms [0.00s (0.01ms/blk)] 
 26 node0 2024-04-28T17:46:07.432604Z [httpworker.0] [validationinterface.cpp:222] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=200 txs removed=0 
 27 node0 2024-04-28T17:46:07.432637Z [httpworker.0] [validation.cpp:1848] [IsInitialBlockDownload] Leaving InitialBlockDownload (latching to false) 
 28 node0 2024-04-28T17:46:07.432664Z [scheduler] [validationinterface.cpp:222] [operator()] [validation] MempoolTransactionsRemovedForBlock: block height=200 txs removed=0 
 29 node0 2024-04-28T17:46:07.432764Z [scheduler] [policy/fees.cpp:708] [processBlock] [estimatefee] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
 30 node0 2024-04-28T17:46:07.432790Z [httpworker.0] [validation.cpp:2814] [UpdateTipLog] UpdateTip: new best=3d85c0577c39dd26e5317925700277c541e6f13a6c7a53df98364cdb2180c6f5 height=200 version=0x30000000 log2_work=8.651052 tx=201 date='2024-04-28T17:46:07Z' progress=1.000000 cache=0.3MiB(1txo) 
 31 node0 2024-04-28T17:46:07.432802Z [httpworker.0] [validation.cpp:3071] [ConnectTip] [bench]   - Connect postprocess: 0.21ms [0.00s (0.11ms/blk)] 
 32 node0 2024-04-28T17:46:07.432821Z [httpworker.0] [validation.cpp:3075] [ConnectTip] [bench] - Connect block: 0.42ms [0.00s (0.21ms/blk)] 
 33 node0 2024-04-28T17:46:07.432833Z [httpworker.0] [txmempool.cpp:663] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
 34 node0 2024-04-28T17:46:07.432850Z [httpworker.0] [validationinterface.cpp:212] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=3d85c0577c39dd26e5317925700277c541e6f13a6c7a53df98364cdb2180c6f5 block height=200 
 35 node0 2024-04-28T17:46:07.432862Z [httpworker.0] [validationinterface.cpp:183] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=3d85c0577c39dd26e5317925700277c541e6f13a6c7a53df98364cdb2180c6f5 fork block hash=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c (in IBD=false) 
 36 node0 2024-04-28T17:46:07.433048Z [scheduler] [validationinterface.cpp:212] [operator()] [validation] BlockConnected: block hash=3d85c0577c39dd26e5317925700277c541e6f13a6c7a53df98364cdb2180c6f5 block height=200 
 37 node0 2024-04-28T17:46:07.433075Z [scheduler] [validationinterface.cpp:183] [operator()] [validation] UpdatedBlockTip: new block hash=3d85c0577c39dd26e5317925700277c541e6f13a6c7a53df98364cdb2180c6f5 fork block hash=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c (in IBD=false) 
 38 node0 2024-04-28T17:46:07.433547Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 39 node0 2024-04-28T17:46:07.433614Z [httpworker.3] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
 40 node0 2024-04-28T17:46:07.434149Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 41 node0 2024-04-28T17:46:07.434213Z [httpworker.2] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=submitblock user=__cookie__ 
 42 node0 2024-04-28T17:46:07.434652Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 43 node0 2024-04-28T17:46:07.434704Z [httpworker.1] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
 44 node0 2024-04-28T17:46:07.435105Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 45 node0 2024-04-28T17:46:07.435140Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 46 node0 2024-04-28T17:46:07.435480Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 47 node0 2024-04-28T17:46:07.435529Z [httpworker.3] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 48 node0 2024-04-28T17:46:07.435898Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 49 node0 2024-04-28T17:46:07.435951Z [httpworker.2] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 50 test  2024-04-28T17:46:07.436000Z TestFramework (INFO): Ensure we don't try to connect if port!=0 
 51 node0 2024-04-28T17:46:07.436599Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:37638 
 52 node0 2024-04-28T17:46:07.436652Z [httpworker.1] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__ 
 53 node0 2024-04-28T17:46:07.436691Z [httpworker.1] [net.cpp:410] [ConnectNode] [net] trying v1 connection zsxwyo6qcn3chqzwxnseusqgsnuw3maqnztkiypyfxtya4snkoka.b32.i2p:8333 lastseen=0.0hrs 
 54 node0 2024-04-28T17:46:07.436711Z [httpworker.1] [i2p.cpp:289] [Log] [i2p] Error connecting to zsxwyo6qcn3chqzwxnseusqgsnuw3maqnztkiypyfxtya4snkoka.b32.i2p:8333, connection refused due to arbitrary port 8333 
 55 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 
 56 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 
 57 node0 2024-04-28T17:46:07.437669Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__ 
 58 node0 2024-04-28T17:46:07.437708Z [httpworker.0] [net.cpp:410] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs 
 59 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 
 60 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" 
 61 node0 2024-04-28T17:46:08.362998Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session d00fa05b26 with 127.0.0.1:60000 
 62 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) 
 63 node0 2024-04-28T17:46:08.363230Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 64 node0 2024-04-28T17:46:10.363358Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session e6c846052b with 127.0.0.1:60000 
 65 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) 
 66 node0 2024-04-28T17:46:10.363506Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 67 node0 2024-04-28T17:46:13.363629Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 52392d7213 with 127.0.0.1:60000 
 68 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) 
 69 node0 2024-04-28T17:46:13.363815Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 70 node0 2024-04-28T17:46:17.363936Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 7b4ca1e901 with 127.0.0.1:60000 
 71 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) 
 72 node0 2024-04-28T17:46:17.364140Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 73 node0 2024-04-28T17:46:22.364266Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 71fd5d01e7 with 127.0.0.1:60000 
 74 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) 
 75 node0 2024-04-28T17:46:22.364476Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 76 node0 2024-04-28T17:46:28.364604Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 456c2be19d with 127.0.0.1:60000 
 77 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) 
 78 node0 2024-04-28T17:46:28.364801Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 79 node0 2024-04-28T17:46:35.364979Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session fe9c34d0c4 with 127.0.0.1:60000 
 80 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) 
 81 node0 2024-04-28T17:46:35.365204Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 82 node0 2024-04-28T17:46:43.365375Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 259947762e with 127.0.0.1:60000 
 83 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) 
 84 node0 2024-04-28T17:46:43.365610Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 85 node0 2024-04-28T17:46:52.351012Z [scheduler] [net.cpp:2345] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers 
 86 node0 2024-04-28T17:46:52.365791Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 9382e16d70 with 127.0.0.1:60000 
 87 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) 
 88 node0 2024-04-28T17:46:52.366015Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 89 node0 2024-04-28T17:47:02.366195Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 6e43de2025 with 127.0.0.1:60000 
 90 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) 
 91 node0 2024-04-28T17:47:02.366454Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 92 node0 2024-04-28T17:47:13.366620Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 84a7e1afb0 with 127.0.0.1:60000 
 93 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) 
 94 node0 2024-04-28T17:47:13.366860Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 95 node0 2024-04-28T17:47:25.367036Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session ba0e7156d5 with 127.0.0.1:60000 
 96 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) 
 97 node0 2024-04-28T17:47:25.367302Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000 
 98 test  2024-04-28T17:47:27.449000Z TestFramework (ERROR): Assertion failed 
 99                                   Traceback (most recent call last):
100                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
101                                       self.run_test()
102                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_i2p_ports.py", line 30, in run_test
103                                       with node.assert_debug_log(expected_msgs=[f"Error connecting to {addr}: Cannot connect to {PROXY}"]):
104                                     File "/usr/lib/python3.10/contextlib.py", line 142, in __exit__
105                                       next(self.gen)
106                                     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
107                                       self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
108                                     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
109                                       raise AssertionError(self._node_msg(msg))
110                                   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:
111                                    - 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
112                                    - 2024-04-28T17:46:07.437669Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__
113                                    - 2024-04-28T17:46:07.437708Z [httpworker.0] [net.cpp:410] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs
114                                    - 2024-04-28T17:46:07.437733Z [httpworker.0] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session ef0bda29ed with 127.0.0.1:60000
115                                    - 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"
116                                    - 2024-04-28T17:46:08.362998Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session d00fa05b26 with 127.0.0.1:60000
117                                    - 2024-04-28T17:46:08.363157Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
118                                    - 2024-04-28T17:46:08.363230Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
119                                    - 2024-04-28T17:46:10.363358Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session e6c846052b with 127.0.0.1:60000
120                                    - 2024-04-28T17:46:10.363457Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
121                                    - 2024-04-28T17:46:10.363506Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
122                                    - 2024-04-28T17:46:13.363629Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 52392d7213 with 127.0.0.1:60000
123                                    - 2024-04-28T17:46:13.363758Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
124                                    - 2024-04-28T17:46:13.363815Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
125                                    - 2024-04-28T17:46:17.363936Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 7b4ca1e901 with 127.0.0.1:60000
126                                    - 2024-04-28T17:46:17.364079Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
127                                    - 2024-04-28T17:46:17.364140Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
128                                    - 2024-04-28T17:46:22.364266Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 71fd5d01e7 with 127.0.0.1:60000
129                                    - 2024-04-28T17:46:22.364418Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
130                                    - 2024-04-28T17:46:22.364476Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
131                                    - 2024-04-28T17:46:28.364604Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 456c2be19d with 127.0.0.1:60000
132                                    - 2024-04-28T17:46:28.364747Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
133                                    - 2024-04-28T17:46:28.364801Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
134                                    - 2024-04-28T17:46:35.364979Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session fe9c34d0c4 with 127.0.0.1:60000
135                                    - 2024-04-28T17:46:35.365142Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
136                                    - 2024-04-28T17:46:35.365204Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
137                                    - 2024-04-28T17:46:43.365375Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 259947762e with 127.0.0.1:60000
138                                    - 2024-04-28T17:46:43.365547Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
139                                    - 2024-04-28T17:46:43.365610Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
140                                    - 2024-04-28T17:46:52.351012Z [scheduler] [net.cpp:2345] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers
141                                    - 2024-04-28T17:46:52.365791Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 9382e16d70 with 127.0.0.1:60000
142                                    - 2024-04-28T17:46:52.365952Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
143                                    - 2024-04-28T17:46:52.366015Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
144                                    - 2024-04-28T17:47:02.366195Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 6e43de2025 with 127.0.0.1:60000
145                                    - 2024-04-28T17:47:02.366391Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
146                                    - 2024-04-28T17:47:02.366454Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
147                                    - 2024-04-28T17:47:13.366620Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session 84a7e1afb0 with 127.0.0.1:60000
148                                    - 2024-04-28T17:47:13.366787Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
149                                    - 2024-04-28T17:47:13.366860Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000
150                                    - 2024-04-28T17:47:25.367036Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Creating persistent SAM session ba0e7156d5 with 127.0.0.1:60000
151                                    - 2024-04-28T17:47:25.367240Z [i2paccept] [netbase.cpp:549] [LogConnectFailure] connect() to 127.0.0.1:60000 failed after wait: Connection refused (111)
152                                    - 2024-04-28T17:47:25.367302Z [i2paccept] [i2p.cpp:289] [Log] [i2p] Error listening: Cannot connect to 127.0.0.1:60000

maflcko added the label Tests on May 3, 2024
maflcko added the label CI failed on May 3, 2024
ceffikhan referenced this in commit 65ed73b996 on Jun 26, 2024
ceffikhan referenced this in commit 3c3eaa9f9f on Jun 27, 2024
brunoerg commented at 8:57 pm on July 1, 2024: contributor

See #30345 (comment)

It seems there is something listening at port 60000 in parallel.
maflcko commented at 6:41 am on July 2, 2024: member

The test is run inside a docker,

https://github.com/bitcoin/bitcoin/blob/ca76d180d2a30d063154be8101bce64e308866ac/ci/test/02_run_container.sh#L50-L59

, so I think it needs to be something inside the docker container. Also, I am not aware of a process inside the CI env that would echo back what it got.
fanquake commented at 5:42 pm on July 11, 2024: member

https://cirrus-ci.com/task/5777533663182848?logs=ci#L9969
maflcko commented at 11:08 am on July 12, 2024: member

, so I think it needs to be something inside the docker container. Also, I am not aware of a process inside the CI env that would echo back what it got.

Also interesting that no one reproduced this locally yet
maflcko commented at 2:57 pm on September 18, 2024: member

https://github.com/bitcoin/bitcoin/actions/runs/10923053194/job/30318787539?pr=30849#step:6:2225
maflcko commented at 11:43 am on November 18, 2024: member

https://cirrus-ci.com/task/5063913392308224?logs=ci#L6167
fanquake commented at 11:23 am on November 19, 2024: member

https://github.com/bitcoin/bitcoin/pull/31279/checks#step:6:7681

maflcko commented at 10:14 am on December 16, 2024: member

Now also on Windows:

https://github.com/bitcoin/bitcoin/actions/runs/12318851093/job/34384513871#step:12:338

 0 node0 2024-12-13T16:36:24.993446Z [httpworker.0] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
 1 test  2024-12-13T16:36:24.994000Z TestFramework (INFO): Ensure we don't try to connect if port!=0 
 2 test  2024-12-13T16:36:24.994000Z TestFramework (INFO): Ensure we try to connect if port=0 and get an error due to missing I2P proxy 
 3 node0 2024-12-13T16:36:24.994136Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523 
 4 node0 2024-12-13T16:36:24.994215Z [httpworker.3] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=submitblock user=__cookie__ 
 5 node0 2024-12-13T16:36:24.994729Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523 
 6 node0 2024-12-13T16:36:24.994801Z [httpworker.2] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
 7 node0 2024-12-13T16:36:24.995270Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523 
 8 node0 2024-12-13T16:36:24.995345Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 9 node0 2024-12-13T16:36:24.995818Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523 
10 node0 2024-12-13T16:36:24.995900Z [httpworker.0] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
11 node0 2024-12-13T16:36:24.996400Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523 
12 node0 2024-12-13T16:36:24.996474Z [httpworker.3] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
13 node0 2024-12-13T16:36:24.997283Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523 
14 node0 2024-12-13T16:36:24.997356Z [httpworker.2] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__ 
15 node0 2024-12-13T16:36:24.997434Z [httpworker.2] [D:\a\bitcoin\bitcoin\src\net.cpp:414] [ConnectNode] [net] trying v1 connection zsxwyo6qcn3chqzwxnseusqgsnuw3maqnztkiypyfxtya4snkoka.b32.i2p:8333 lastseen=0.0hrs 
16 node0 2024-12-13T16:36:24.997467Z [httpworker.2] [D:\a\bitcoin\bitcoin\src\i2p.cpp:226] [Connect] [i2p] Error connecting to zsxwyo6qcn3chqzwxnseusqgsnuw3maqnztkiypyfxtya4snkoka.b32.i2p:8333, connection refused due to arbitrary port 8333 
17 node0 2024-12-13T16:36:24.998687Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523 
18 node0 2024-12-13T16:36:24.998774Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__ 
19 node0 2024-12-13T16:36:24.998828Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\net.cpp:414] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs 
20 node0 2024-12-13T16:37:09.896819Z [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2372] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers 
21 node0 2024-12-13T16:39:24.891666Z [i2paccept] [D:\a\bitcoin\bitcoin\src\i2p.cpp:151] [Listen] [i2p:error] Couldn't listen: Receive timeout (received 0 bytes without terminator before that) 
22 node0 2024-12-13T16:39:24.891768Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\i2p.cpp:417] [CreateIfNotCreatedAlready] [i2p] Creating persistent SAM session 61f5bdf8c4 with 127.0.0.1:60000 
23 test  2024-12-13T16:42:24.895000Z TestFramework (ERROR): Assertion failed 
24                                   Traceback (most recent call last):
25                                     File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\test_framework.py", line 135, in main
26                                       self.run_test()
27                                     File "D:\a\bitcoin\bitcoin\build\test\functional\p2p_i2p_ports.py", line 30, in run_test
28                                       with node.assert_debug_log(expected_msgs=[f"Error connecting to {addr}: Cannot connect to {PROXY}"]):
29                                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
30                                     File "C:\hostedtoolcache\windows\Python\3.12.8\x64\Lib\contextlib.py", line 144, in __exit__
31                                       next(self.gen)
32                                     File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\test_node.py", line 520, in assert_debug_log
33                                       self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
34                                     File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\test_node.py", line 198, in _raise_assertion_error
35                                       raise AssertionError(self._node_msg(msg))
36                                   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:
37                                    - 2024-12-13T16:36:24.998687Z [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54523
38                                    - 2024-12-13T16:36:24.998774Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__
39                                    - 2024-12-13T16:36:24.998828Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\net.cpp:414] [ConnectNode] [net] trying v1 connection h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0 lastseen=0.0hrs
40                                    - 2024-12-13T16:37:09.896819Z [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2372] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers
41                                    - 2024-12-13T16:39:24.891666Z [i2paccept] [D:\a\bitcoin\bitcoin\src\i2p.cpp:151] [Listen] [i2p:error] Couldn't listen: Receive timeout (received 0 bytes without terminator before that)
42                                    - 2024-12-13T16:39:24.891768Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\i2p.cpp:417] [CreateIfNotCreatedAlready] [i2p] Creating persistent SAM session 61f5bdf8c4 with 127.0.0.1:60000
43                                    - 2024-12-13T16:42:24.895618Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\i2p.cpp:274] [Connect] [i2p] Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Receive timeout (received 0 bytes without terminator before that)
44 node0 2024-12-13T16:42:24.895618Z [httpworker.1] [D:\a\bitcoin\bitcoin\src\i2p.cpp:274] [Connect] [i2p] Error connecting to h3r6bkn46qxftwja53pxiykntegfyfjqtnzbm6iv6r5mungmqgmq.b32.i2p:0: Receive timeout (received 0 bytes without terminator before that) 
45 test  2024-12-13T16:42:24.926000Z TestFramework (DEBUG): Closing down network thread 
46 test  2024-12-13T16:42:24.981000Z TestFramework (INFO): Stopping nodes 
47 test  2024-12-13T16:42:24.981000Z TestFramework.node0 (DEBUG): Stopping node

Contributors
maflcko brunoerg fanquake

Labels
Tests CI failed