Flaky `wallet_transactiontime_rescan.py --legacy-wallet` functional test #28221

Failed in CI on unrelated PR #28216.

 test  2023-08-04T17:39:25.417000Z TestFramework (ERROR): Called Process failed with 'error: timeout on transient error: Could not connect to the server 127.0.0.1:20800 (error code 0 - "timeout reached") 
                                   Make sure the bitcoind server is running and that you are connecting to the correct RPC port.
                                   '
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/wallet_transactiontime_rescan.py", line 209, in run_test
                                       minernode.cli("-rpcwallet=encrypted_wallet").walletpassphrase("passphrase", 1)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 714, in __call__
                                       return self.cli.send_cli(self.command, *args, **kwargs)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 779, in send_cli
                                       raise subprocess.CalledProcessError(returncode, self.binary, output=cli_stderr)
                                   subprocess.CalledProcessError: Command '/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/src/bitcoin-cli' returned non-zero exit status 1.
 test  2023-08-04T17:39:25.614000Z TestFramework (DEBUG): Closing down network thread 
 test  2023-08-04T17:39:25.665000Z TestFramework (INFO): Stopping nodes 
 test  2023-08-04T17:39:25.665000Z TestFramework.node0 (DEBUG): Stopping node 
 test  2023-08-04T17:39:25.665000Z TestFramework.node0 (ERROR): Unable to stop node. 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 346, in stop_node
                                       self.stop(wait=wait)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/coverage.py", line 50, in __call__
                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 127, in __call__
                                       response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 105, in _request
                                       self.__conn.request(method, path, postdata, headers)
                                     File "/usr/lib64/python3.9/http/client.py", line 1285, in request
                                       self._send_request(method, url, body, headers, encode_chunked)
                                     File "/usr/lib64/python3.9/http/client.py", line 1296, in _send_request
                                       self.putrequest(method, url, **skips)
                                     File "/usr/lib64/python3.9/http/client.py", line 1122, in putrequest
                                       raise CannotSendRequest(self.__state)
                                   http.client.CannotSendRequest: Request-sent
 test  2023-08-04T17:39:25.666000Z TestFramework.node1 (DEBUG): Stopping node 

CI run: https://github.com/bitcoin/bitcoin/pull/28216/checks?check_run_id=15628645597 (https://cirrus-ci.com/task/5356802372534272?logs=ci#L2440).

Looks like it did got dispatched to thread 2, but thread 0 was blocking for 24 minutes:

 test  2023-08-04T17:19:25.474000Z TestFramework.bitcoincli (DEBUG): Running bitcoin-cli ['-rpcwallet=encrypted_wallet', 'walletpassphrase', 'passphrase', '1'] 
 node0 2023-08-04T17:19:25.478233Z (mocktime: 2023-09-03T17:11:37Z) [http] [httpserver.cpp:254] [http_request_cb] [http] Received a POST request for /wallet/encrypted_wallet from 127.0.0.1:56776 
 node0 2023-08-04T17:19:25.478352Z (mocktime: 2023-09-03T17:11:37Z) [httpworker.2] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=walletpassphrase user=__cookie__ 
...
 node0 2023-08-04T17:23:35.739266Z (mocktime: 2023-09-03T17:11:37Z) [httpworker.0] [wallet/scriptpubkeyman.h:254] [WalletLogPrintf] [encrypted_wallet] keypool added 400 keys (0 internal), size=800 (400 internal) 
...
 node0 2023-08-04T17:26:24.111206Z (mocktime: 2023-09-03T17:11:37Z) [scheduler] [net.cpp:1522] [DumpAddresses] [net] Flushed 0 addresses to peers.dat  7744ms 
...
 node0 2023-08-04T17:43:54.247168Z (mocktime: 2023-09-03T17:11:37Z) [httpworker.0] [wallet/wallet.h:895] [WalletLogPrintf] [encrypted_wallet] Rescan completed in         1468844ms 

Probably an upstream GCE outage?

This is continuing to happen, i.e https://github.com/bitcoin/bitcoin/actions/runs/6082441277/job/16500239670.

Sorry, can be ignored, that's actually a different test but still windows native CI continuing to fail randomly.

Probably an upstream GCE outage?

Closing for now. Let us know if this is still an issue.

The wallet_transactiontime_rescan.py test (and only it) frequently fails on my local machine due to timeout, whenever I run the tests with multiple threads, e.g.

test/functional/test_runner.py -j "$(($(nproc)-1))"

leads to

286/286 - wallet_transactiontime_rescan.py --legacy-wallet failed, Duration: 187 s

stdout:
2023-12-15T16:00:06.770000Z TestFramework (INFO): PRNG seed is: 5568797213703148493
2023-12-15T16:00:06.771000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20231215_105714/wallet_transactiontime_rescan_162
2023-12-15T16:00:11.028000Z TestFramework (INFO): Prepare nodes and wallet
2023-12-15T16:00:13.449000Z TestFramework (INFO): Start transactions
2023-12-15T16:00:14.806000Z TestFramework (INFO): Send 10 btc to user
2023-12-15T16:00:15.346000Z TestFramework (INFO): Send 5 btc to user
2023-12-15T16:00:17.051000Z TestFramework (INFO): Send 1 btc to user
2023-12-15T16:00:18.693000Z TestFramework (INFO): Check user's final balance and transaction count
2023-12-15T16:00:18.695000Z TestFramework (INFO): Check transaction times
2023-12-15T16:00:18.696000Z TestFramework (INFO): Restore user wallet on another node without rescan
2023-12-15T16:00:19.221000Z TestFramework (INFO): Rescan last history part
2023-12-15T16:00:19.232000Z TestFramework (INFO): Rescan all history
2023-12-15T16:00:19.269000Z TestFramework (INFO): Check user's final balance and transaction count after restoration
2023-12-15T16:00:19.271000Z TestFramework (INFO): Check transaction times after restoration
2023-12-15T16:00:19.273000Z TestFramework (INFO): Test handling of invalid parameters for rescanblockchain
2023-12-15T16:00:19.275000Z TestFramework (INFO): Test `rescanblockchain` fails when wallet is encrypted and locked
2023-12-15T16:00:21.468000Z TestFramework (INFO): Test rescanning an encrypted wallet
2023-12-15T16:02:13.710000Z TestFramework (ERROR): JSONRPC error
Traceback (most recent call last):
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/authproxy.py", line 151, in _get_response
    http_response = self.__conn.getresponse()
                    ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/http/client.py", line 1378, in getresponse
    response.begin()
  File "/usr/lib/python3.11/http/client.py", line 318, in begin
    version, status, reason = self._read_status()
                              ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/http/client.py", line 279, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/socket.py", line 706, 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 "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/test_framework.py", line 131, in main
    self.run_test()
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/build/../test/functional/wallet_transactiontime_rescan.py", line 221, in run_test
    assert_equal(rescanning.result(), {"start_height": 0, "stop_height": 803})
                 ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/concurrent/futures/_base.py", line 449, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "/usr/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/coverage.py", line 50, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/authproxy.py", line 127, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/authproxy.py", line 106, in _request
    return self._get_response()
           ^^^^^^^^^^^^^^^^^^^^
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/authproxy.py", line 153, in _get_response
    raise JSONRPCException({
test_framework.authproxy.JSONRPCException: 'rescanblockchain' RPC took longer than 30.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)
2023-12-15T16:02:13.765000Z TestFramework (INFO): Stopping nodes
2023-12-15T16:02:13.765000Z TestFramework.node0 (ERROR): Unable to stop node.
Traceback (most recent call last):
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/test_node.py", line 369, in stop_node
    self.stop(wait=wait)
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/coverage.py", line 50, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/authproxy.py", line 127, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/authproxy.py", line 105, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/usr/lib/python3.11/http/client.py", line 1286, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/lib/python3.11/http/client.py", line 1297, in _send_request
    self.putrequest(method, url, **skips)
  File "/usr/lib/python3.11/http/client.py", line 1123, in putrequest
    raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2023-12-15T16:03:13.795000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        wait_until_helper_internal(lambda: self.is_node_stopped(expected_ret_code=expected_ret_code, **kwargs), timeout=timeout, timeout_factor=self.timeout_factor)
'''
[node 2] Cleaning up leftover process
[node 1] Cleaning up leftover process
[node 0] Cleaning up leftover process


stderr:
Traceback (most recent call last):
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/build/../test/functional/wallet_transactiontime_rescan.py", line 226, in <module>
    TransactionTimeRescanTest().main()
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/test_framework.py", line 154, in main
    exit_code = self.shutdown()
                ^^^^^^^^^^^^^^^
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/test_framework.py", line 313, in shutdown
    self.stop_nodes()
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/test_framework.py", line 578, in stop_nodes
    node.wait_until_stopped()
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/test_node.py", line 417, in wait_until_stopped
    wait_until_helper_internal(lambda: self.is_node_stopped(expected_ret_code=expected_ret_code, **kwargs), timeout=timeout, timeout_factor=self.timeout_factor)
  File "/home/murch/Workspace/2023-11-no-changeless-sffo/test/functional/test_framework/util.py", line 276, in wait_until_helper_internal
    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
AssertionError: Predicate ''''
        wait_until_helper_internal(lambda: self.is_node_stopped(expected_ret_code=expected_ret_code, **kwargs), timeout=timeout, timeout_factor=self.timeout_factor)
''' not true after 60 seconds

The same error occurs on the latest master branch.

On either the test passes when I call it separately:

➜  build git:(master) ✗ ./test/functional/test_runner.py wallet_transactiontime_rescan
Temporary test directory at /tmp/test_runner_₿_🏃_20231215_131217
Running Unit Tests for Test Framework Modules
.....................
----------------------------------------------------------------------
Ran 21 tests in 87.217s

OK
Remaining jobs: [wallet_transactiontime_rescan.py --descriptors, wallet_transactiontime_rescan.py --legacy-wallet]
1/2 - wallet_transactiontime_rescan.py --descriptors passed, Duration: 20 s
Remaining jobs: [wallet_transactiontime_rescan.py --legacy-wallet]
2/2 - wallet_transactiontime_rescan.py --legacy-wallet passed, Duration: 51 s

TEST                                             | STATUS    | DURATION

wallet_transactiontime_rescan.py --descriptors   | ✓ Passed  | 20 s
wallet_transactiontime_rescan.py --legacy-wallet | ✓ Passed  | 51 s

ALL                                              | ✓ Passed  | 71 s (accumulated) 
Runtime: 51 s

Could bump the timeout inside this test to fix it?

Well, if it’s just me that is affected that might be resolved by getting a faster computer.

This test is also failing for me on Mac M1 also whenever I run with --jobs greater than 1.

Will look into it.