Intermittent issue in p2p_timeouts (assert no_verack_node.is_connected) #22207

issue MarcoFalke opened this issue on June 10, 2021
  1. MarcoFalke commented at 8:34 AM on June 10, 2021: member

    https://cirrus-ci.com/task/6617076623212544?logs=ci#L3649

     test  2021-06-09T13:37:11.354000Z TestFramework.node0 (DEBUG): RPC successfully started 
 node0 2021-06-09T13:37:11.356474Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:39406 
 node0 2021-06-09T13:37:11.356988Z [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2021-06-09T13:37:11.358928Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:39406 
 node0 2021-06-09T13:37:11.359314Z [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getrawmempool user=__cookie__ 
 node0 2021-06-09T13:37:11.446381Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:39406 
 node0 2021-06-09T13:37:11.446834Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 test  2021-06-09T13:37:11.448000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16292 
 test  2021-06-09T13:37:11.449000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16292 
 test  2021-06-09T13:37:11.449000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_version(nVersion=70016 nServices=9 nTime=Wed Jun  9 13:37:11 2021 addrTo=CAddress(nServices=1 net=IPv4 addr=127.0.0.1 port=16292) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xAFA4AA882257FE68 strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
 node0 2021-06-09T13:37:11.455960Z [net] [net.cpp:2939] [CNode] Added connection peer=0 
 node0 2021-06-09T13:37:11.456699Z [net] [net.cpp:1156] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:52494 accepted 
 node0 2021-06-09T13:37:11.457672Z [msghand] [net_processing.cpp:2404] [ProcessMessage] received: version (111 bytes) peer=0 
 node0 2021-06-09T13:37:11.457906Z [msghand] [net.cpp:2959] [PushMessage] sending version (114 bytes) peer=0 
 node0 2021-06-09T13:37:11.464976Z [msghand] [net_processing.cpp:1028] [PushNodeVersion] send version message: version 70016, blocks=0, us=[::]:0, txrelay=1, peer=0 
 test  2021-06-09T13:37:11.465000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_version(nVersion=70016 nServices=1033 nTime=Wed Jun  9 13:37:11 2021 addrTo=CAddress(nServices=0 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xDE169B86B1760571 strSubVer=/Satoshi:21.99.0(testnode0)/ nStartingHeight=0 relay=1) 
 test  2021-06-09T13:37:11.465000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_wtxidrelay() 
 test  2021-06-09T13:37:11.465000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_sendaddrv2() 
 test  2021-06-09T13:37:11.465000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_verack() 
 node0 2021-06-09T13:37:11.465115Z [msghand] [net.cpp:2959] [PushMessage] sending wtxidrelay (0 bytes) peer=0 
 node0 2021-06-09T13:37:11.465339Z [msghand] [net.cpp:2959] [PushMessage] sending sendaddrv2 (0 bytes) peer=0 
 node0 2021-06-09T13:37:11.465555Z [msghand] [net.cpp:2959] [PushMessage] sending verack (0 bytes) peer=0 
 node0 2021-06-09T13:37:11.465916Z [msghand] [net_processing.cpp:2587] [ProcessMessage] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=127.0.0.1:16292, txrelay=1, peer=0 
 node0 2021-06-09T13:37:11.466126Z [msghand] [timedata.cpp:54] [AddTimeData] added time data, samples 2, offset +0 (+0 minutes) 
 test  2021-06-09T13:37:11.500000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16292 
 test  2021-06-09T13:37:11.501000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16292 
 node0 2021-06-09T13:37:11.505210Z [net] [net.cpp:2939] [CNode] Added connection peer=1 
 node0 2021-06-09T13:37:11.505817Z [net] [net.cpp:1156] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:52496 accepted 
 test  2021-06-09T13:37:11.550000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16292 
 test  2021-06-09T13:37:11.551000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16292 
 node0 2021-06-09T13:37:11.557591Z [net] [net.cpp:2939] [CNode] Added connection peer=2 
 node0 2021-06-09T13:37:11.558325Z [net] [net.cpp:1156] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:52498 accepted 
 test  2021-06-09T13:37:12.602000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_ping(nonce=00000000) 
 node0 2021-06-09T13:37:13.049094Z [msghand] [net_processing.cpp:2404] [ProcessMessage] received: ping (8 bytes) peer=0 
 node0 2021-06-09T13:37:13.049733Z [msghand] [net_processing.cpp:2723] [ProcessMessage] Unsupported message "ping" prior to verack from peer=0 
 test  2021-06-09T13:37:13.749000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_ping(nonce=00000000) 
 node0 2021-06-09T13:37:13.750513Z [msghand] [net_processing.cpp:2404] [ProcessMessage] received: ping (8 bytes) peer=1 
 node0 2021-06-09T13:37:14.229133Z [msghand] [net_processing.cpp:2609] [ProcessMessage] non-version message before version handshake. Message "ping" from peer=1 
 node0 2021-06-09T13:37:15.006421Z [net] [net.cpp:1282] [InactivityCheck] version handshake timeout peer=0 
 node0 2021-06-09T13:37:15.035286Z [net] [net.cpp:1267] [InactivityCheck] socket no message in first 3 seconds, 1 0 peer=1 
 node0 2021-06-09T13:37:15.035389Z [net] [net.cpp:1267] [InactivityCheck] socket no message in first 3 seconds, 0 0 peer=2 
 node0 2021-06-09T13:37:15.035497Z [net] [net.cpp:503] [CloseSocketDisconnect] disconnecting peer=0 
 node0 2021-06-09T13:37:15.035666Z [net] [net.cpp:503] [CloseSocketDisconnect] disconnecting peer=1 
 node0 2021-06-09T13:37:15.035743Z [net] [net.cpp:503] [CloseSocketDisconnect] disconnecting peer=2 
 node0 2021-06-09T13:37:15.035962Z [net] [net_processing.cpp:1163] [FinalizeNode] Cleared nodestate for peer=0 
 node0 2021-06-09T13:37:15.036824Z [net] [net_processing.cpp:1163] [FinalizeNode] Cleared nodestate for peer=1 
 node0 2021-06-09T13:37:15.037532Z [net] [net_processing.cpp:1163] [FinalizeNode] Cleared nodestate for peer=2 
 test  2021-06-09T13:37:15.038000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16292 
 test  2021-06-09T13:37:15.038000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16292 
 test  2021-06-09T13:37:15.038000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16292 
 test  2021-06-09T13:37:15.449000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 128, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_timeouts.py", line 69, in run_test
                                       assert no_verack_node.is_connected
                                   AssertionError
  2. MarcoFalke added the label Bug on Jun 10, 2021
  3. MarcoFalke added the label Tests on Jun 10, 2021
  4. MarcoFalke commented at 8:36 AM on June 10, 2021: member

    Same for "assert not no_send_node.is_connected"

    https://cirrus-ci.com/task/6704741871779840?logs=ci#L4948

     test  2021-06-09T12:58:21.777000Z TestFramework.node0 (DEBUG): RPC successfully started 
 node0 2021-06-09T12:58:21.777643Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:35098 
 node0 2021-06-09T12:58:21.778003Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2021-06-09T12:58:21.779088Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:35098 
 node0 2021-06-09T12:58:21.779482Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getrawmempool user=__cookie__ 
 node0 2021-06-09T12:58:21.781209Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:35098 
 node0 2021-06-09T12:58:21.781437Z [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 test  2021-06-09T12:58:21.782000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16292 
 test  2021-06-09T12:58:21.783000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16292 
 test  2021-06-09T12:58:21.783000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_version(nVersion=70016 nServices=9 nTime=Wed Jun  9 12:58:21 2021 addrTo=CAddress(nServices=1 net=IPv4 addr=127.0.0.1 port=16292) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xCFDD36C5DA45117D strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
 node0 2021-06-09T12:58:21.784249Z [net] [net.cpp:2939] [CNode] Added connection peer=0 
 node0 2021-06-09T12:58:21.784788Z [net] [net.cpp:1156] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:57286 accepted 
 node0 2021-06-09T12:58:21.785443Z [msghand] [net_processing.cpp:2404] [ProcessMessage] received: version (111 bytes) peer=0 
 node0 2021-06-09T12:58:21.785635Z [msghand] [net.cpp:2959] [PushMessage] sending version (114 bytes) peer=0 
 node0 2021-06-09T12:58:21.785852Z [msghand] [net_processing.cpp:1028] [PushNodeVersion] send version message: version 70016, blocks=0, us=[::]:0, txrelay=1, peer=0 
 node0 2021-06-09T12:58:21.785927Z [msghand] [net.cpp:2959] [PushMessage] sending wtxidrelay (0 bytes) peer=0 
 test  2021-06-09T12:58:21.786000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_version(nVersion=70016 nServices=1033 nTime=Wed Jun  9 12:58:21 2021 addrTo=CAddress(nServices=0 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xC48314D82C542356 strSubVer=/Satoshi:21.99.0(testnode0)/ nStartingHeight=0 relay=1) 
 test  2021-06-09T12:58:21.786000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_wtxidrelay() 
 test  2021-06-09T12:58:21.786000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_sendaddrv2() 
 test  2021-06-09T12:58:21.786000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16292: msg_verack() 
 node0 2021-06-09T12:58:21.786042Z [msghand] [net.cpp:2959] [PushMessage] sending sendaddrv2 (0 bytes) peer=0 
 node0 2021-06-09T12:58:21.786200Z [msghand] [net.cpp:2959] [PushMessage] sending verack (0 bytes) peer=0 
 node0 2021-06-09T12:58:21.786376Z [msghand] [net_processing.cpp:2587] [ProcessMessage] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=127.0.0.1:16292, txrelay=1, peer=0 
 node0 2021-06-09T12:58:21.786499Z [msghand] [timedata.cpp:54] [AddTimeData] added time data, samples 2, offset +0 (+0 minutes) 
 test  2021-06-09T12:58:21.832000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16292 
 test  2021-06-09T12:58:21.833000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16292 
 node0 2021-06-09T12:58:21.834639Z [net] [net.cpp:2939] [CNode] Added connection peer=1 
 node0 2021-06-09T12:58:21.835034Z [net] [net.cpp:1156] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:57288 accepted 
 test  2021-06-09T12:58:21.883000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16292 
 test  2021-06-09T12:58:21.884000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16292 
 node0 2021-06-09T12:58:21.885080Z [net] [net.cpp:2939] [CNode] Added connection peer=2 
 node0 2021-06-09T12:58:21.885488Z [net] [net.cpp:1156] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:57290 accepted 
 test  2021-06-09T12:58:22.934000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_ping(nonce=00000000) 
 node0 2021-06-09T12:58:22.935861Z [msghand] [net_processing.cpp:2404] [ProcessMessage] received: ping (8 bytes) peer=0 
 node0 2021-06-09T12:58:22.935934Z [msghand] [net_processing.cpp:2723] [ProcessMessage] Unsupported message "ping" prior to verack from peer=0 
 test  2021-06-09T12:58:22.986000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_ping(nonce=00000000) 
 node0 2021-06-09T12:58:22.987098Z [msghand] [net_processing.cpp:2404] [ProcessMessage] received: ping (8 bytes) peer=1 
 node0 2021-06-09T12:58:22.987183Z [msghand] [net_processing.cpp:2609] [ProcessMessage] non-version message before version handshake. Message "ping" from peer=1 
 test  2021-06-09T12:58:24.038000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_ping(nonce=00000000) 
 node0 2021-06-09T12:58:25.004243Z [net] [net.cpp:1282] [InactivityCheck] version handshake timeout peer=0 
 node0 2021-06-09T12:58:25.004348Z [net] [net.cpp:1267] [InactivityCheck] socket no message in first 3 seconds, 1 0 peer=1 
 node0 2021-06-09T12:58:25.004396Z [net] [net.cpp:1267] [InactivityCheck] socket no message in first 3 seconds, 0 0 peer=2 
 node0 2021-06-09T12:58:25.004474Z [net] [net.cpp:503] [CloseSocketDisconnect] disconnecting peer=0 
 node0 2021-06-09T12:58:25.004592Z [net] [net.cpp:503] [CloseSocketDisconnect] disconnecting peer=1 
 node0 2021-06-09T12:58:25.004652Z [net] [net.cpp:503] [CloseSocketDisconnect] disconnecting peer=2 
 node0 2021-06-09T12:58:25.004812Z [net] [net_processing.cpp:1163] [FinalizeNode] Cleared nodestate for peer=0 
 node0 2021-06-09T12:58:25.005043Z [net] [net_processing.cpp:1163] [FinalizeNode] Cleared nodestate for peer=1 
 node0 2021-06-09T12:58:25.005257Z [net] [net_processing.cpp:1163] [FinalizeNode] Cleared nodestate for peer=2 
 test  2021-06-09T12:58:25.373000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16292: msg_ping(nonce=00000000) 
 test  2021-06-09T12:58:25.004000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16292 
 test  2021-06-09T12:58:25.374000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16292 
 test  2021-06-09T12:58:25.374000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16292 
 node0 2021-06-09T12:59:20.933471Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33065 bytes of dynamic environment data into RNG 
 test  2021-06-09T12:59:45.415000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 128, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_timeouts.py", line 90, in run_test
                                       assert not no_send_node.is_connected
                                     File "/usr/lib/python3.9/contextlib.py", line 124, in __exit__
                                       next(self.gen)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 400, 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 "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 166, in _raise_assertion_error
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 0] Expected messages "['version handshake timeout peer=0', 'socket no message in first 3 seconds, 1 0 peer=1', 'socket no message in first 3 seconds, 0 0 peer=2']" does not partially match log:
                                    - 2021-06-09T12:59:20.933471Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33065 bytes of dynamic environment data into RNG
  5. fanquake commented at 4:11 AM on November 17, 2021: member

    Still seeing this as of https://github.com/bitcoin/bitcoin/commit/b869a784ef2b259f14545bf6bd314fb58c36514b:

    https://cirrus-ci.com/task/4921538127331328

     test  2021-11-17T03:31:13.902000Z TestFramework.node0 (DEBUG): RPC successfully started 
 test  2021-11-17T03:31:13.902000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16460 
 test  2021-11-17T03:31:13.902000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16460 
 test  2021-11-17T03:31:13.902000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16460: msg_version(nVersion=70016 nServices=9 nTime=Wed Nov 17 03:31:13 2021 addrTo=CAddress(nServices=1 net=IPv4 addr=127.0.0.1 port=16460) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xDBD107C56604F8B3 strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
 test  2021-11-17T03:31:13.902000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16460: msg_version(nVersion=70016 nServices=1033 nTime=Wed Nov 17 03:31:13 2021 addrTo=CAddress(nServices=0 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x807EA4D1413A94C9 strSubVer=/Satoshi:22.99.0(testnode0)/ nStartingHeight=0 relay=1) 
 test  2021-11-17T03:31:13.902000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16460: msg_wtxidrelay() 
 test  2021-11-17T03:31:13.902000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16460: msg_sendaddrv2() 
 test  2021-11-17T03:31:13.902000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:16460: msg_verack() 
 node0 2021-11-17T03:31:13.903986Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\httpserver.cpp:238] [http_request_cb] Received a POST request for / from 127.0.0.1:63350 
 node0 2021-11-17T03:31:13.904245Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\rpc\request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-11-17T03:31:13.905690Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\httpserver.cpp:238] [http_request_cb] Received a POST request for / from 127.0.0.1:63351 
 node0 2021-11-17T03:31:13.905919Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\rpc\request.cpp:174] [parse] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
 node0 2021-11-17T03:31:13.907534Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\httpserver.cpp:238] [http_request_cb] Received a POST request for / from 127.0.0.1:63352 
 node0 2021-11-17T03:31:13.907738Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\rpc\request.cpp:174] [parse] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2021-11-17T03:31:13.908818Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\httpserver.cpp:238] [http_request_cb] Received a POST request for / from 127.0.0.1:63353 
 node0 2021-11-17T03:31:13.909031Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\rpc\request.cpp:174] [parse] ThreadRPCServer method=getrawmempool user=__cookie__ 
 node0 2021-11-17T03:31:13.910440Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\httpserver.cpp:238] [http_request_cb] Received a POST request for / from 127.0.0.1:63354 
 node0 2021-11-17T03:31:13.910672Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\rpc\request.cpp:174] [parse] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 node0 2021-11-17T03:31:13.912785Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:3005] [CNode] Added connection peer=0 
 node0 2021-11-17T03:31:13.912959Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:1210] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:63355 accepted 
 node0 2021-11-17T03:31:13.914597Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:2489] [ProcessMessage] received: version (111 bytes) peer=0 
 node0 2021-11-17T03:31:13.914761Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:3025] [PushMessage] sending version (114 bytes) peer=0 
 node0 2021-11-17T03:31:13.914920Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:1115] [PushNodeVersion] send version message: version 70016, blocks=0, txrelay=1, peer=0 
 node0 2021-11-17T03:31:13.914981Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:3025] [PushMessage] sending wtxidrelay (0 bytes) peer=0 
 node0 2021-11-17T03:31:13.915068Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:3025] [PushMessage] sending sendaddrv2 (0 bytes) peer=0 
 node0 2021-11-17T03:31:13.915150Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:3025] [PushMessage] sending verack (0 bytes) peer=0 
 node0 2021-11-17T03:31:13.915275Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:2682] [ProcessMessage] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=127.0.0.1:16460, txrelay=1, peer=0 
 node0 2021-11-17T03:31:13.915345Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\timedata.cpp:55] [AddTimeData] added time data, samples 2, offset +0 (+0 minutes) 
 test  2021-11-17T03:31:13.964000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16460 
 test  2021-11-17T03:31:13.964000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16460 
 node0 2021-11-17T03:31:13.966538Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:3005] [CNode] Added connection peer=1 
 node0 2021-11-17T03:31:13.966697Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:1210] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:63356 accepted 
 test  2021-11-17T03:31:14.292000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:16460 
 test  2021-11-17T03:31:14.292000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:16460 
 node0 2021-11-17T03:31:14.296053Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:3005] [CNode] Added connection peer=2 
 node0 2021-11-17T03:31:14.296226Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:1210] [CreateNodeFromAcceptedSocket] connection from 127.0.0.1:63358 accepted 
 test  2021-11-17T03:31:15.769000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16460: msg_ping(nonce=00000000) 
 node0 2021-11-17T03:31:15.781119Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:2489] [ProcessMessage] received: ping (8 bytes) peer=0 
 node0 2021-11-17T03:31:15.781222Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:2814] [ProcessMessage] Unsupported message "ping" prior to verack from peer=0 
 test  2021-11-17T03:31:15.972000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:16460: msg_ping(nonce=00000000) 
 node0 2021-11-17T03:31:15.977839Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:2489] [ProcessMessage] received: ping (8 bytes) peer=1 
 node0 2021-11-17T03:31:15.977927Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:2704] [ProcessMessage] non-version message before version handshake. Message "ping" from peer=1 
 test  2021-11-17T03:31:17.026000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16460 
 test  2021-11-17T03:31:17.026000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:16460 
 node0 2021-11-17T03:31:17.026742Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:1349] [InactivityCheck] version handshake timeout peer=0 
 node0 2021-11-17T03:31:17.026836Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:1334] [InactivityCheck] socket no message in first 3 seconds, 1 0 peer=1 
 node0 2021-11-17T03:31:17.026878Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:522] [CloseSocketDisconnect] disconnecting peer=0 
 node0 2021-11-17T03:31:17.026982Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net.cpp:522] [CloseSocketDisconnect] disconnecting peer=1 
 node0 2021-11-17T03:31:17.027105Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:1249] [FinalizeNode] Cleared nodestate for peer=0 
 node0 2021-11-17T03:31:17.027297Z [C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\src\net_processing.cpp:1249] [FinalizeNode] Cleared nodestate for peer=1 
 test  2021-11-17T03:31:17.089000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 132, in main
                                       self.run_test()
                                     File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\p2p_timeouts.py", line 69, in run_test
                                       assert no_verack_node.is_connected
                                   AssertionError
 test  2021-11-17T03:31:17.089000Z TestFramework (DEBUG): Closing down network thread 
 test  2021-11-17T03:31:17.089000Z TestFramework (INFO): Stopping nodes 
 test  2021-11-17T03:31:17.089000Z TestFramework.node0 (DEBUG): Stopping node
  6. MarcoFalke commented at 7:37 AM on November 17, 2021: member

    #20654

  7. MarcoFalke closed this on Nov 17, 2021
  8. DrahtBot locked this on Nov 17, 2022
Contributors
MarcoFalkefanquake
Labels
BugTests
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-04-17 06:14 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me