test: increase rpc_timeout for fundrawtx test_transaction_too_large #21410

pull jonatack wants to merge 1 commits into bitcoin:master from jonatack:give-test_transaction_too_large-more-time changing 1 files +8 −6
  1. jonatack commented at 9:04 PM on March 10, 2021: member

    to hopefully fix timeouts from a new test added in 48a0319bab 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)
    
  2. fanquake added the label Tests on Mar 10, 2021
  3. jonatack commented at 10:52 PM on March 10, 2021: member

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

  4. DrahtBot commented at 4:21 AM on March 11, 2021: member

    <!--e57a25ab6845829454e8d69fc972939a-->

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

    <!--174a7506f384e20aa4161008e828411d-->

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #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.

  5. jonatack commented at 3:27 PM on March 12, 2021: member

    Encountering this timeout daily. Latest one, locally:

    <details><summary>test output</summary><p>

    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
    

    </p></details>

  6. MarcoFalke commented at 3:33 PM on March 12, 2021: member

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

  7. jonatack commented at 4:03 PM on March 12, 2021: member

    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)
    
  8. MarcoFalke commented at 5:06 PM on March 12, 2021: member

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

  9. MarcoFalke commented at 5:08 PM on March 12, 2021: member

    in the combined log it looks like a deadlock/hang

  10. brunoerg commented at 1:07 AM on March 13, 2021: member

    Concept ACK

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

  11. jonatack force-pushed on Mar 15, 2021
  12. jonatack commented at 2:51 PM on March 15, 2021: member

    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.

  13. jonatack commented at 5:15 PM on March 15, 2021: member
  14. test: give fundraw more time for test_transaction_too_large d09120b7d1
  15. jonatack force-pushed on Mar 16, 2021
  16. jonatack commented at 4:21 PM on March 16, 2021: member

    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.

  17. MarcoFalke commented at 4:52 PM on March 16, 2021: member

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

  18. jonatack commented at 5:15 PM on March 16, 2021: member

    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.

  19. MarcoFalke merged this on Mar 16, 2021
  20. MarcoFalke closed this on Mar 16, 2021

  21. MarcoFalke commented at 6:27 PM on March 16, 2021: member

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

  22. jonatack deleted the branch on Mar 16, 2021
  23. jonatack commented at 7:13 PM on March 16, 2021: member

    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.

  24. jonatack commented at 7:14 PM on March 16, 2021: member

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

  25. MarcoFalke commented at 8:33 AM on April 26, 2021: member

    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.

  26. DrahtBot locked this on Aug 18, 2022

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-04-13 18:14 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me