Seen in: https://github.com/bitcoin/bitcoin/actions/runs/13236532677/job/36942441812?pr=30975 (#30975)
0test 2025-02-10T09:21:22.592000Z TestFramework (INFO): Test that preferred peers are always selected over non-preferred when ready
1 test 2025-02-10T09:21:22.592000Z TestFramework.node0 (DEBUG): Stopping node
2 node0 2025-02-10T09:21:22.593102Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:57336
3 node0 2025-02-10T09:21:22.593212Z [httpworker.6] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=stop user=__cookie__
4 node0 2025-02-10T09:21:22.593261Z [init] [httpserver.cpp:508] [InterruptHTTPServer] [http] Interrupting HTTP server
5 node0 2025-02-10T09:21:22.593478Z [init] [httprpc.cpp:382] [InterruptHTTPRPC] [rpc] Interrupting HTTP RPC server
6 node0 2025-02-10T09:21:22.593490Z [init] [rpc/server.cpp:291] [operator()] [rpc] Interrupting RPC
7 node0 2025-02-10T09:21:22.593517Z [init] [init.cpp:286] [Shutdown] Shutdown: In progress...
8 node0 2025-02-10T09:21:22.593529Z [shutoff] [httprpc.cpp:387] [StopHTTPRPC] [rpc] Stopping HTTP RPC server
9 node0 2025-02-10T09:21:22.593536Z [shutoff] [httpserver.cpp:770] [UnregisterHTTPHandler] [http] Unregistering HTTP handler for / (exactmatch 1)
10 node0 2025-02-10T09:21:22.593545Z [shutoff] [httpserver.cpp:770] [UnregisterHTTPHandler] [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
11 node0 2025-02-10T09:21:22.593553Z [shutoff] [rpc/server.cpp:303] [operator()] [rpc] Stopping RPC
12 node0 2025-02-10T09:21:22.593636Z [shutoff] [rpc/server.cpp:306] [operator()] [rpc] RPC stopped.
13 node0 2025-02-10T09:21:22.593646Z [shutoff] [httpserver.cpp:520] [StopHTTPServer] [http] Stopping HTTP server
14 node0 2025-02-10T09:21:22.593653Z [shutoff] [httpserver.cpp:522] [StopHTTPServer] [http] Waiting for HTTP worker threads to exit
15 node0 2025-02-10T09:21:22.593976Z [addcon] [util/thread.cpp:22] [TraceThread] addcon thread exit
16 node0 2025-02-10T09:21:22.594367Z [shutoff] [httpserver.cpp:550] [StopHTTPServer] [http] Waiting for HTTP event thread to exit
17 node0 2025-02-10T09:21:22.594396Z [http] [httpserver.cpp:355] [ThreadHTTP] [http] Exited http event loop
18 node0 2025-02-10T09:21:22.594482Z [shutoff] [httpserver.cpp:556] [StopHTTPServer] [http] Stopped HTTP server
19 node0 2025-02-10T09:21:22.643280Z [net] [util/thread.cpp:22] [TraceThread] net thread exit
20 node0 2025-02-10T09:21:22.643367Z [msghand] [util/thread.cpp:22] [TraceThread] msghand thread exit
21 test 2025-02-10T09:21:22.644000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:14456
22 test 2025-02-10T09:21:22.644000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:14456
23 test 2025-02-10T09:21:22.644000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:14456
24 node0 2025-02-10T09:21:22.644215Z [shutoff] [net.cpp:2391] [DumpAddresses] [net] Flushed 0 addresses to peers.dat 0ms
25 node0 2025-02-10T09:21:22.644227Z [shutoff] [net.cpp:3477] [StopNodes] [net] Stopping node, disconnecting peer=1
26 node0 2025-02-10T09:21:22.644234Z [shutoff] [net.cpp:565] [CloseSocketDisconnect] [net] Resetting socket for peer=1
27 test 2025-02-10T09:21:24.705000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:49138: msg_pong(nonce=3365597ad9b5dc7f)
28 test 2025-02-10T09:21:24.705000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:49138: msg_getheaders(locator=CBlockLocator(vHave=[25904390216175313194312162455780078753009692101200952252992871177711616225820, 10439194800033568075353954394040901046437382900627609508673849620975391395575, 40446225147528968444488730747006358517695899943732003474923480031726915305221, 32881632053604177249247854545860335098773301364214891775874295669143030708145, 8274383136340278425284592751131987282275833971901249227378370713913292132329, 91375339536865810244115815573593171857986770160039248524702050... (msg truncated)
29 test 2025-02-10T09:21:24.705000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:49138: msg_feefilter(feerate=000003e8)
30 node0 2025-02-10T09:21:24.705018Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net_processing.cpp:3380] [ProcessMessage] [net] received: verack (0 bytes) peer=11
31 node0 2025-02-10T09:21:24.705027Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net_processing.cpp:3625] [ProcessMessage] New outbound-full-relay v1 peer connected: version: 70016, blocks=-1, peer=11
32 node0 2025-02-10T09:21:24.705036Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net.cpp:3875] [PushMessage] [net] sending sendcmpct (9 bytes) peer=11
33 node0 2025-02-10T09:21:24.705062Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net.cpp:3875] [PushMessage] [net] sending ping (8 bytes) peer=11
34 node0 2025-02-10T09:21:24.705100Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net.cpp:3875] [PushMessage] [net] sending getheaders (645 bytes) peer=11
35 node0 2025-02-10T09:21:24.705124Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net_processing.cpp:5508] [SendMessages] [net] initial getheaders (199) to peer=11 (startheight:-1)
36 node0 2025-02-10T09:21:24.705144Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net.cpp:3875] [PushMessage] [net] sending feefilter (8 bytes) peer=11
37 node0 2025-02-10T09:21:24.705878Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net_processing.cpp:3380] [ProcessMessage] [net] received: pong (8 bytes) peer=11
38 test 2025-02-10T09:21:24.753000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:49138: msg_ping(nonce=00000000)
39 test 2025-02-10T09:21:24.754000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:49138: msg_ping(nonce=00000001)
40 test 2025-02-10T09:21:24.754000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:49138: msg_pong(nonce=00000000)
41 test 2025-02-10T09:21:24.754000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:49138: msg_pong(nonce=00000001)
42 node0 2025-02-10T09:21:24.754344Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net_processing.cpp:3380] [ProcessMessage] [net] received: ping (8 bytes) peer=11
43 node0 2025-02-10T09:21:24.754365Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net.cpp:3875] [PushMessage] [net] sending pong (8 bytes) peer=11
44 node0 2025-02-10T09:21:24.754415Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net_processing.cpp:3380] [ProcessMessage] [net] received: ping (8 bytes) peer=11
45 node0 2025-02-10T09:21:24.754438Z (mocktime: 2025-02-10T09:21:24Z) [msghand] [net.cpp:3875] [PushMessage] [net] sending pong (8 bytes) peer=11
46 test 2025-02-10T09:21:24.804000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:49138: msg_inv(inv=[CInv(type=WTX hash=00000000000000000000000000000000000000000000000000000000ff00ff00)])
47 node0 2025-02-10T09:21:24.805809Z (mocktime: 2025-02-10T09:21:24Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:57432
48 node0 2025-02-10T09:21:24.805870Z (mocktime: 2025-02-10T09:21:24Z) [httpworker.1] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
49 test 2025-02-10T09:21:24.809000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:14456: msg_getdata(inv=[CInv(type=WTX hash=00000000000000000000000000000000000000000000000000000000ff00ff00)])
50 node0 2025-02-10T09:21:24.809051Z (mocktime: 2025-02-10T09:21:24Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:57432
51 node0 2025-02-10T09:21:24.809106Z (mocktime: 2025-02-10T09:21:24Z) [httpworker.0] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__
52 node0 2025-02-10T09:21:24.809392Z (mocktime: 2025-02-10T09:22:22Z) [msghand] [node/txdownloadman_impl.cpp:277] [GetRequestsToSend] [net] timeout of inflight wtx 00000000000000000000000000000000000000000000000000000000ff00ff00 from peer=0
53 node0 2025-02-10T09:21:24.809423Z (mocktime: 2025-02-10T09:22:22Z) [msghand] [node/txdownloadman_impl.cpp:282] [GetRequestsToSend] [net] Requesting wtx 00000000000000000000000000000000000000000000000000000000ff00ff00 peer=10
54 node0 2025-02-10T09:21:24.809433Z (mocktime: 2025-02-10T09:22:22Z) [msghand] [net.cpp:3875] [PushMessage] [net] sending getdata (37 bytes) peer=10
55 node0 2025-02-10T09:21:24.809628Z (mocktime: 2025-02-10T09:22:22Z) [msghand] [net_processing.cpp:3380] [ProcessMessage] [net] received: inv (37 bytes) peer=11
56 node0 2025-02-10T09:21:24.809657Z (mocktime: 2025-02-10T09:22:22Z) [msghand] [net_processing.cpp:3943] [ProcessMessage] [net] got inv: wtx 00000000000000000000000000000000000000000000000000000000ff00ff00 new peer=11
57 test 2025-02-10T09:21:34.852000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
58 def test_function():
59 if check_connected:
60 assert self.is_connected
61 return test_function_in()
62 '''
63 test 2025-02-10T09:21:34.852000Z TestFramework (ERROR): Assertion failed
64 Traceback (most recent call last):
65 File "/home/runner/work/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 135, in main
66 self.run_test()
67 File "/home/runner/work/bitcoin/bitcoin/build/test/functional/p2p_tx_download.py", line 385, in run_test
68 self.test_preferred_tiebreaker_inv()
69 File "/home/runner/work/bitcoin/bitcoin/build/test/functional/p2p_tx_download.py", line 283, in test_preferred_tiebreaker_inv
70 pref_peer.wait_until(lambda: pref_peer.tx_getdata_count >= 1, timeout=10)
71 File "/home/runner/work/bitcoin/bitcoin/test/functional/test_framework/p2p.py", line 594, in wait_until
72 wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
73 File "/home/runner/work/bitcoin/bitcoin/test/functional/test_framework/util.py", line 317, in wait_until_helper_internal
74 raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
75 AssertionError: Predicate ''''
76 def test_function():
77 if check_connected:
78 assert self.is_connected
79 return test_function_in()
80 ''' not true after 10 seconds
81 test 2025-02-10T09:21:34.854000Z TestFramework (DEBUG): Closing down network thread
