intermittent timeout in wallet_signer.py : 'createwallet' RPC took longer than 1200.000000 seconds

maflcko commented at 7:52 am on July 2, 2025: member

in the multiprocess, i686, DEBUG task in self.nodes[1].createwallet(wallet_name='hww_disconnect', disable_private_keys=True, external_signer=True),

https://cirrus-ci.com/task/5704849158832128?logs=ci#L2967:

 0 node1 2025-06-26T14:05:40.072184Z [msghand] [net_processing.cpp:3452] [ProcessMessage] [net] received: pong (8 bytes) peer=0 
 1 test  2025-06-26T14:05:43.222938Z TestFramework (ERROR): JSONRPC error 
 2                                   Traceback (most recent call last):
 3                                     File "/ci_container_base/test/functional/test_framework/authproxy.py", line 174, in _get_response
 4                                       http_response = self.__conn.getresponse()
 5                                                       ^^^^^^^^^^^^^^^^^^^^^^^^^
 6                                     File "/usr/lib/python3.12/http/client.py", line 1428, in getresponse
 7                                       response.begin()
 8                                     File "/usr/lib/python3.12/http/client.py", line 331, in begin
 9                                       version, status, reason = self._read_status()
10                                                                 ^^^^^^^^^^^^^^^^^^^
11                                     File "/usr/lib/python3.12/http/client.py", line 292, in _read_status
12                                       line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
13                                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
14                                     File "/usr/lib/python3.12/socket.py", line 707, in readinto
15                                       return self._sock.recv_into(b)
16                                              ^^^^^^^^^^^^^^^^^^^^^^^
17                                   TimeoutError: timed out
18                                   During handling of the above exception, another exception occurred:
19                                   Traceback (most recent call last):
20                                     File "/ci_container_base/test/functional/test_framework/test_framework.py", line 190, in main
21                                       self.run_test()
22                                     File "/ci_container_base/ci/scratch/build-i686-pc-linux-gnu/test/functional/wallet_signer.py", line 59, in run_test
23                                       self.test_disconnected_signer()
24                                     File "/ci_container_base/ci/scratch/build-i686-pc-linux-gnu/test/functional/wallet_signer.py", line 246, in test_disconnected_signer
25                                       self.nodes[1].createwallet(wallet_name='hww_disconnect', disable_private_keys=True, external_signer=True)
26                                     File "/ci_container_base/test/functional/test_framework/coverage.py", line 50, in __call__
27                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
28                                                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
29                                     File "/ci_container_base/test/functional/test_framework/authproxy.py", line 137, in __call__
30                                       response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
31                                                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
32                                     File "/ci_container_base/test/functional/test_framework/authproxy.py", line 111, in _request
33                                       return self._get_response()
34                                              ^^^^^^^^^^^^^^^^^^^^
35                                     File "/ci_container_base/test/functional/test_framework/authproxy.py", line 176, in _get_response
36                                       raise JSONRPCException({
37                                   test_framework.authproxy.JSONRPCException: 'createwallet' RPC took longer than 1200.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)
38 test  2025-06-26T14:05:43.230396Z TestFramework (DEBUG): Closing down network thread

maflcko added the label CI failed on Jul 2, 2025

maflcko added the label Tests on Jul 2, 2025

tnndbtc commented at 3:51 pm on July 3, 2025: none

@maflcko Is there a way to retrieve debug.log (in /ci_container_base/ci/scratch/test_runner/test_runner_₿_🏃_20250626_133646/) while the test fails so it may provide more clues on why RPC took longer?

maflcko commented at 4:22 pm on July 3, 2025: member

You can just follow the links to “Open full logs” to get to https://api.cirrus-ci.com/v1/task/5704849158832128/logs/ci.log, but I don’t think there are any details in the log that give more hints, on a quick skim.

bitcoin deleted a comment on Jul 3, 2025

Sjors commented at 7:51 am on July 7, 2025: member

Assuming this is specific to external wallets, and not an unrelated bug in the test itself, the most interesting code is:

0void CWallet::SetupDescriptorScriptPubKeyMans()
1{
2...
3        UniValue signer_res = signer->GetDescriptors(account);

Beyond that wallet creation is more or less the same between regular and external signer wallets.

0UniValue ExternalSigner::GetDescriptors(const int account)
1{
2    return RunCommandParseJSON(m_command + " --fingerprint " + m_fingerprint + NetworkArg() + " getdescriptors --account " + strprintf("%d", account));
3}

In the functional test this results in a call to mocks/signer.py that’s handled by def getdescriptors(args).

Note that test_disconnected_signer is not the first call to mocks/signer.py in the functional test. It would be useful to know if it always times out at this specific line or also elsewhere in the test.

This test was recently added in #32682, but the createwallet part of the new test is not unique.

maflcko commented at 8:30 am on July 7, 2025: member

I’d say it would be useful if the mocks scripts had more debug logging enabled; maybe some command tracing when entering the script and when exiting it?

intermittent timeout in wallet_signer.py : ‘createwallet’ RPC took longer than 1200.000000 seconds #32855