qa: timeout in StopHTTPServer() #31894
Description
Ran into a CI timeout in feature_assumeutxo.py on Windows: https://github.com/hodlinator/bitcoin/actions/runs/13371466603/job/37340702068#step:12:123
In the combined log we see the following, "Restarting node to stop at height" is referring to node 1):
test ...T14:10:53.420000Z TestFramework (INFO): Restarting node to stop at height 359
test ...T14:10:53.420000Z TestFramework.node1 (DEBUG): Stopping node
node1 ...T14:10:53.420155Z (mocktime...) [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56740
node1 ...T14:10:53.420240Z (mocktime...) [httpworker.8] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=gettxout user=__cookie__
node1 ...T14:10:53.421024Z (mocktime...) [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56740
node1 ...T14:10:53.421114Z (mocktime...) [httpworker.11] [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:241] [parse] [rpc] ThreadRPCServer method=stop user=__cookie__
node1 ...T14:10:53.421203Z (mocktime...) [init] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:508] [InterruptHTTPServer] [http] Interrupting HTTP server
node1 ...T14:10:53.421251Z (mocktime...) [init] [D:\a\bitcoin\bitcoin\src\httprpc.cpp:382] [InterruptHTTPRPC] [rpc] Interrupting HTTP RPC server
node1 ...T14:10:53.421280Z (mocktime...) [init] [D:\a\bitcoin\bitcoin\src\rpc\server.cpp:291] [operator ()] [rpc] Interrupting RPC
node1 ...T14:10:53.421320Z (mocktime...) [init] [D:\a\bitcoin\bitcoin\src\init.cpp:287] [Shutdown] Shutdown: In progress...
node1 ...T14:10:53.421345Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\httprpc.cpp:387] [StopHTTPRPC] [rpc] Stopping HTTP RPC server
node1 ...T14:10:53.422054Z (mocktime...) [addcon] [D:\a\bitcoin\bitcoin\src\util\thread.cpp:22] [TraceThread] addcon thread exit
node1 ...T14:10:53.422540Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:770] [UnregisterHTTPHandler] [http] Unregistering HTTP handler for / (exactmatch 1)
node1 ...T14:10:53.422641Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:770] [UnregisterHTTPHandler] [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
node1 ...T14:10:53.422674Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\rpc\server.cpp:303] [operator ()] [rpc] Stopping RPC
node1 ...T14:10:53.422847Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\rpc\server.cpp:306] [operator ()] [rpc] RPC stopped.
node1 ...T14:10:53.422879Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:520] [StopHTTPServer] [http] Stopping HTTP server
node1 ...T14:10:53.422945Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:522] [StopHTTPServer] [http] Waiting for HTTP worker threads to exit
node1 ...T14:10:53.423118Z (mocktime...) [shutoff] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:536] [StopHTTPServer] [http] Waiting for 1 connections to stop HTTP server
node1 ...T14:10:53.423164Z (mocktime...) [http] [D:\a\bitcoin\bitcoin\src\httpserver.cpp:355] [ThreadHTTP] [http] Exited http event loop
node1 ...T14:10:53.440186Z (mocktime...) [net] [D:\a\bitcoin\bitcoin\src\util\thread.cpp:22] [TraceThread] net thread exit
node1 ...T14:10:53.652881Z (mocktime...) [msghand] [D:\a\bitcoin\bitcoin\src\util\thread.cpp:22] [TraceThread] msghand thread exit
...
node1 ...T14:11:32.925206Z (mocktime...) [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2428] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers
...
node1 ...T14:25:47.935847Z (mocktime...) [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2391] [DumpAddresses] [net] Flushed 0 addresses to peers.dat 1ms
...
node1 ...T14:40:47.947785Z (mocktime...) [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2391] [DumpAddresses] [net] Flushed 0 addresses to peers.dat 1ms
...
test ...T14:50:53.446000Z TestFramework (ERROR): JSONRPC error
Traceback (most recent call last):
File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\authproxy.py", line 164, in _get_response
http_response = self.__conn.getresponse()
...
File "C:\hostedtoolcache\windows\Python\3.13.2\x64\Lib\socket.py", line 719, in readinto
return self._sock.recv_into(b)
~~~~~~~~~~~~~~~~~~~~^^^
TimeoutError: timed out
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\test_framework.py", line 135, in main
self.run_test()
~~~~~~~~~~~~~^^
File "D:\a\bitcoin\bitcoin\build\test\functional\feature_assumeutxo.py", line 587, in run_test
self.restart_node(1, extra_args=[
~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^
f"-stopatheight={PAUSE_HEIGHT}", *self.extra_args[1]])
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
...
File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\test_node.py", line 395, in stop_node
self.stop(wait=wait)
~~~~~~~~~^^^^^^^^^^^
...
File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\authproxy.py", line 106, in _request
return self._get_response()
~~~~~~~~~~~~~~~~~~^^
File "D:\a\bitcoin\bitcoin\build\test\functional\test_framework\authproxy.py", line 166, in _get_response
raise JSONRPCException({
...
test_framework.authproxy.JSONRPCException: 'stop' RPC took longer than 2400.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)
Note how it takes:
- ~40 seconds to go from receiving stop-RPC to "enabling extra block-relay-only peers"
- Additional 14 minutes to reach "Flushed 0 addresses to peers.dat"
- Additional 15 minutes for the second one
- Additional 10 minutes until we reach the JSONRPC error/timeout.
It would be good to have log output describing what the node is doing, it obviously started shutting down, and is maybe still flushing some state to disk?
Also, I wonder if bitcoind might have terminated the TCP/HTTP connection before responding to the stop-RPC (maybe gettxout-RPC being called right before it is a factor)?
Included in the log, but seems unrelated as it's another node:
node0 stderr Error: A fatal internal error occurred, see debug.log for details: Assumeutxo data not found for the given blockhash '7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a7a'.