test: increase rpc_timeout for fundrawtx test_transaction_too_large #21410

jonatack · 2021-03-10T21:04:09Z

to hopefully fix timeouts from a new test added in 48a0319 of #20536 merged March 8, 2021

seen locally when running via the test runner

File "/home/jon/projects/bitcoin/bitcoin/test/functional/rpc_fundrawtransaction.py", line 927, in test_transaction_too_large
raise JSONRPCException({
    test_framework.authproxy.JSONRPCException: 'generatetoaddress' RPC took longer than 30.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)

and in the CI like https://bitcoinbuilds.org/index.php?ansilog=28537952-2c92-46f2-9871-8918e5ba2738.log#l2398

File "/home/ubuntu/src/test/functional/rpc_fundrawtransaction.py", line 927, in test_transaction_too_large
test_framework.authproxy.JSONRPCException: 'generatetoaddress' RPC took longer than 240.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)

jonatack · 2021-03-10T22:52:38Z

This patch is green on https://bitcoinbuilds.org/?build=8266

DrahtBot · 2021-03-11T04:21:44Z

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

rpc: include_unsafe option for fundrawtransaction #21359 (rpc: include_unsafe option for fundrawtransaction by t-bast)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

jonatack · 2021-03-12T15:27:24Z

Encountering this timeout daily. Latest one, locally:

test output

2021-03-12T15:18:47.578000Z TestFramework (INFO): Test fundrawtx where BnB solution would result in a too large transaction, but Knapsack would not
2021-03-12T15:21:05.453000Z TestFramework (ERROR): JSONRPC error
Traceback (most recent call last):
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/authproxy.py", line 168, in _get_response
    http_response = self.__conn.getresponse()
  File "/usr/lib/python3.9/http/client.py", line 1347, in getresponse
    response.begin()
  File "/usr/lib/python3.9/http/client.py", line 307, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.9/http/client.py", line 268, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.9/socket.py", line 704, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 128, in main
    self.run_test()
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/rpc_fundrawtransaction.py", line 97, in run_test
    self.test_transaction_too_large()
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/rpc_fundrawtransaction.py", line 927, in test_transaction_too_large
    self.nodes[0].generate(10)
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/test_node.py", line 302, in generate
    return self.generatetoaddress(nblocks=nblocks, address=self.get_deterministic_priv_key().address, maxtries=maxtries)
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/coverage.py", line 47, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/authproxy.py", line 144, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/authproxy.py", line 108, in _request
    return self._get_response()
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/authproxy.py", line 170, in _get_response
    raise JSONRPCException({
test_framework.authproxy.JSONRPCException: 'generatetoaddress' RPC took longer than 30.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)
2021-03-12T15:21:05.510000Z TestFramework (INFO): Stopping nodes
2021-03-12T15:21:05.510000Z TestFramework.node0 (ERROR): Unable to stop node.
Traceback (most recent call last):
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/test_node.py", line 323, in stop_node
    self.stop(wait=wait)
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/coverage.py", line 47, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/authproxy.py", line 144, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/authproxy.py", line 107, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/usr/lib/python3.9/http/client.py", line 1255, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/lib/python3.9/http/client.py", line 1266, in _send_request
    self.putrequest(method, url, **skips)
  File "/usr/lib/python3.9/http/client.py", line 1092, in putrequest
    raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2021-03-12T15:22:05.561000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
    def is_node_stopped(self):
        """Checks whether the node has stopped.

        Returns True if the node has stopped. False otherwise.
        This method is responsible for freeing resources (self.process)."""
        if not self.running:
            return True
        return_code = self.process.poll()
        if return_code is None:
            return False

        # process has stopped. Assert that it didn't return an error code.
        assert return_code == 0, self._node_msg(
            "Node returned non-zero exit code (%d) when stopping" % return_code)
        self.running = False
        self.process = None
        self.rpc_connected = False
        self.rpc = None
        self.log.debug("Node stopped")
        return True
'''
[node 3] Cleaning up leftover process
[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/jon/projects/bitcoin/bitcoin/test/functional/rpc_fundrawtransaction.py", line 931, in <module>
    RawTransactionsTest().main()
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 151, in main
    exit_code = self.shutdown()
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 294, in shutdown
    self.stop_nodes()
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 545, in stop_nodes
    node.wait_until_stopped()
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/test_node.py", line 369, in wait_until_stopped
    wait_until_helper(self.is_node_stopped, timeout=timeout, timeout_factor=self.timeout_factor)
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/test_framework/util.py", line 261, in wait_until_helper
    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
AssertionError: Predicate ''''
    def is_node_stopped(self):
        """Checks whether the node has stopped.

        Returns True if the node has stopped. False otherwise.
        This method is responsible for freeing resources (self.process)."""
        if not self.running:
            return True
        return_code = self.process.poll()
        if return_code is None:
            return False

        # process has stopped. Assert that it didn't return an error code.
        assert return_code == 0, self._node_msg(
            "Node returned non-zero exit code (%d) when stopping" % return_code)
        self.running = False
        self.process = None
        self.rpc_connected = False
        self.rpc = None
        self.log.debug("Node stopped")
        return True
''' not true after 60.0 seconds

maflcko · 2021-03-12T15:33:58Z

Does the timeout happen even if just one block is created per call to generate?

jonatack · 2021-03-12T16:03:09Z

Does the timeout happen even if just one block is created per call to generate?

For me, yes, that doesn't resolve it.

-        self.nodes[0].generate(10)
+        self.nodes[0].generate(1)

maflcko · 2021-03-12T17:06:57Z

It seems excessive to take 30 seconds (or 240 seconds) for a single block to be generated. The bottleneck should be benchmarked

maflcko · 2021-03-12T17:08:20Z

in the combined log it looks like a deadlock/hang

brunoerg · 2021-03-13T01:07:13Z

Concept ACK

I am getting the same errors when running via test runner.

jonatack · 2021-03-15T14:51:31Z

Did more testing and bumping the timeout from the default 60 to only 120 (instead of 480) appears to be enough to resolve the issue for me locally. If the CI is green, we could start with that. Tested at each point with both 1 and 10 blocks generated and didn't see a difference in timeout behavior. Edit: even a value of 90 resolves the issue for me locally.

jonatack · 2021-03-15T17:15:02Z

Green on https://bitcoinbuilds.org/index.php?build=8392

jonatack · 2021-03-16T16:21:54Z

This was pretty much the only green CI on bitcoinbuilds of the past day out of a few dozen cases. Re-pushed to try lowering the timeout from 120 seconds to only 90, which seems to be sufficient to fix the issue for me locally.

maflcko · 2021-03-16T16:52:08Z

bitcoinbuilds currently fails with ./build-aux/ylwrap: line 176: yacc: command not found, which is a build failure

jonatack · 2021-03-16T17:15:21Z

Would really like to see this solved, as I'm hitting this issue every day since #20536 was merged on March 8, 2021. I'll open an issue.

maflcko · 2021-03-16T18:27:06Z

Ok, merging. Though I think this should be investigated. Generating a block shouldn't take several minutes

jonatack · 2021-03-16T19:13:10Z

Thanks. What is weird: https://bitcoinbuilds.org/index.php?build=8465 is (thankfully) green for the last push, which is the first passing CI there since the previous push.

jonatack · 2021-03-16T19:14:17Z

Maybe @jonasschnelli updated something...we'll see with the next CI runs.

maflcko · 2021-04-26T08:33:07Z

I tried reproducing this locally and on HDD I got 2.137453 seconds. On randisk I got 0.152617 to generate the block.

It would be good to have steps to reproduce or otherwise investigate this. The patch here is only meant as a temporary workaround.

fanquake added the Tests label Mar 10, 2021

DrahtBot mentioned this pull request Mar 11, 2021

rpc: include_unsafe option for fundrawtransaction #21359

Merged

jonatack force-pushed the give-test_transaction_too_large-more-time branch from f946eb1 to 12a675c Compare March 15, 2021 14:50

test: give fundraw more time for test_transaction_too_large

d09120b

jonatack force-pushed the give-test_transaction_too_large-more-time branch from 12a675c to d09120b Compare March 16, 2021 16:19

jonatack mentioned this pull request Mar 16, 2021

Timeouts in a test case in rpc_fundrawtransaction #21452

Closed

maflcko merged commit 5ef1603 into bitcoin:master Mar 16, 2021

jonatack deleted the give-test_transaction_too_large-more-time branch March 16, 2021 18:28

givanse mentioned this pull request Feb 20, 2022

createmultisig --descriptors & wallet_keypool --descriptors tests failing #20183

Closed

bitcoin locked as resolved and limited conversation to collaborators Aug 18, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: increase rpc_timeout for fundrawtx test_transaction_too_large #21410

test: increase rpc_timeout for fundrawtx test_transaction_too_large #21410

jonatack commented Mar 10, 2021 •

edited

Loading

jonatack commented Mar 10, 2021 •

edited

Loading

DrahtBot commented Mar 11, 2021

jonatack commented Mar 12, 2021

maflcko commented Mar 12, 2021

jonatack commented Mar 12, 2021

maflcko commented Mar 12, 2021

maflcko commented Mar 12, 2021

brunoerg commented Mar 13, 2021

jonatack commented Mar 15, 2021 •

edited

Loading

jonatack commented Mar 15, 2021

jonatack commented Mar 16, 2021

maflcko commented Mar 16, 2021

jonatack commented Mar 16, 2021

maflcko commented Mar 16, 2021

jonatack commented Mar 16, 2021

jonatack commented Mar 16, 2021

maflcko commented Apr 26, 2021

test: increase rpc_timeout for fundrawtx test_transaction_too_large #21410

test: increase rpc_timeout for fundrawtx test_transaction_too_large #21410

Conversation

jonatack commented Mar 10, 2021 • edited Loading

jonatack commented Mar 10, 2021 • edited Loading

DrahtBot commented Mar 11, 2021

Conflicts

jonatack commented Mar 12, 2021

maflcko commented Mar 12, 2021

jonatack commented Mar 12, 2021

maflcko commented Mar 12, 2021

maflcko commented Mar 12, 2021

brunoerg commented Mar 13, 2021

jonatack commented Mar 15, 2021 • edited Loading

jonatack commented Mar 15, 2021

jonatack commented Mar 16, 2021

maflcko commented Mar 16, 2021

jonatack commented Mar 16, 2021

maflcko commented Mar 16, 2021

jonatack commented Mar 16, 2021

jonatack commented Mar 16, 2021

maflcko commented Apr 26, 2021

jonatack commented Mar 10, 2021 •

edited

Loading

jonatack commented Mar 10, 2021 •

edited

Loading

jonatack commented Mar 15, 2021 •

edited

Loading