test: generate fewer blocks in feature_nulldummy to fix timeouts, speed up #21373

pull jonatack wants to merge 2 commits into bitcoin:master from jonatack:fix_feature_nulldummy_test_timeout changing 1 files +16 −14
  1. jonatack commented at 3:46 PM on March 5, 2021: member

    The resolved timeout issue seen in the CI can be reproduced locally by running test/functional/feature_nulldummy.py --valgrind --loglevel=debug

    Speeds up the normal test runtime for me from 3.8 to 2.2 seconds (debug build). Thanks to Marco Falke for the approach suggestion.

  2. jonatack commented at 3:49 PM on March 5, 2021: member

    <details><summary>before (on master)</summary><p>

    $ test/functional/feature_nulldummy.py --valgrind -l debug
2021-03-05T15:19:52.679000Z TestFramework (DEBUG): PRNG seed is: 7345676661789155999
2021-03-05T15:19:52.679000Z TestFramework (DEBUG): Setting up network thread
2021-03-05T15:19:52.680000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_0_okgkoj
2021-03-05T15:19:52.684000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
2021-03-05T15:19:52.688000Z TestFramework.node1 (DEBUG): bitcoind started, waiting for RPC to come up
2021-03-05T15:20:12.471000Z TestFramework.node0 (DEBUG): RPC successfully started
2021-03-05T15:20:12.823000Z TestFramework.node1 (DEBUG): RPC successfully started
2021-03-05T15:20:20.161000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2021-03-05T15:20:21.485000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2021-03-05T15:20:51.514000Z 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/feature_nulldummy.py", line 71, in run_test
    self.nodes[0].generate(427)  # Block 429
  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-05T15:20:51.519000Z TestFramework (DEBUG): Closing down network thread
2021-03-05T15:20:51.570000Z TestFramework (INFO): Stopping nodes
2021-03-05T15:20:51.570000Z TestFramework.node0 (DEBUG): Stopping node
2021-03-05T15:20:51.571000Z 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-05T15:20:51.572000Z TestFramework.node1 (DEBUG): Stopping node
2021-03-05T15:21:51.829000Z 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
'''
Traceback (most recent call last):
  File "/home/jon/projects/bitcoin/bitcoin/test/functional/feature_nulldummy.py", line 134, in <module>
    NULLDUMMYTest().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
[node 1] Cleaning up leftover process
[node 0] Cleaning up leftover process

    </p></details>

    <details><summary>after (with this patch)</summary><p>

    $ test/functional/feature_nulldummy.py --valgrind -l debug
2021-03-05T15:40:11.700000Z TestFramework (DEBUG): PRNG seed is: 1307129330788481038
2021-03-05T15:40:11.700000Z TestFramework (DEBUG): Setting up network thread
2021-03-05T15:40:11.700000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_qdtmppe1
2021-03-05T15:40:11.704000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
2021-03-05T15:40:11.708000Z TestFramework.node1 (DEBUG): bitcoind started, waiting for RPC to come up
2021-03-05T15:40:32.086000Z TestFramework.node0 (DEBUG): RPC successfully started
2021-03-05T15:40:32.454000Z TestFramework.node1 (DEBUG): RPC successfully started
2021-03-05T15:40:40.177000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2021-03-05T15:40:41.407000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2021-03-05T15:42:09.617000Z TestFramework (INFO): Test 1: NULLDUMMY compliant base transactions should be accepted to mempool and mined before activation [430]
2021-03-05T15:42:13.159000Z TestFramework (INFO): Test 2: Non-NULLDUMMY base multisig transaction should not be accepted to mempool before activation
2021-03-05T15:42:13.563000Z TestFramework (INFO): Test 3: Non-NULLDUMMY base transactions should be accepted in a block before activation [431]
2021-03-05T15:42:14.022000Z TestFramework (INFO): Test 4: Non-NULLDUMMY base multisig transaction is invalid after activation
2021-03-05T15:42:14.593000Z TestFramework (INFO): Test 5: Non-NULLDUMMY P2WSH multisig transaction invalid after activation
2021-03-05T15:42:15.205000Z TestFramework (INFO): Test 6: NULLDUMMY compliant base/witness transactions should be accepted to mempool and in block after activation [432]
2021-03-05T15:42:15.798000Z TestFramework (DEBUG): Closing down network thread
2021-03-05T15:42:15.849000Z TestFramework (INFO): Stopping nodes
2021-03-05T15:42:15.849000Z TestFramework.node0 (DEBUG): Stopping node
2021-03-05T15:42:15.895000Z TestFramework.node1 (DEBUG): Stopping node
2021-03-05T15:42:18.436000Z TestFramework.node0 (DEBUG): Node stopped
2021-03-05T15:42:19.288000Z TestFramework.node1 (DEBUG): Node stopped
2021-03-05T15:42:19.288000Z TestFramework (INFO): Cleaning up /tmp/bitcoin_func_test_qdtmppe1 on exit
2021-03-05T15:42:19.288000Z TestFramework (INFO): Tests successful

    </p></details>

  3. in test/functional/feature_nulldummy.py:46 in 82659d44ac outdated 
      45 | @@ -46,6 +46,7 @@ def set_test_params(self):
  46 |              '-segwitheight=432',
    MarcoFalke commented at 4:06 PM on March 5, 2021:

    An alternative would be to subtract 300 from this constant (and all dependent constants)?

    jonatack commented at 4:34 PM on March 5, 2021:

    Great idea--bigger diff, but resolves the issue (locally for me, at least) and speeds up the test from 4 to 2.5 seconds

    jonatack commented at 4:53 PM on March 5, 2021:

    It looks like we can reduce the blocks from 432 to 104

  4. MarcoFalke commented at 4:06 PM on March 5, 2021: member

    Seems fine, but is there a reason to mine so many blocks in the first place?

  5. jonatack force-pushed on Mar 5, 2021
  6. jonatack renamed this:
    test: extend rpc timeout in feature_nulldummy to fix CI timeouts
    test, refactor: generate fewer blocks in feature_nulldummy to fix timeouts, speed up
    on Mar 5, 2021
  7. in test/functional/feature_nulldummy.py:24 in 31b1d26779 outdated 
      19 | @@ -20,6 +20,7 @@
  20 |  from test_framework.test_framework import BitcoinTestFramework
  21 |  from test_framework.util import assert_equal, assert_raises_rpc_error
  22 |  
  23 | +HEIGHT = 127
  24 |  NULLDUMMY_ERROR = "non-mandatory-script-verify-flag (Dummy CHECKMULTISIG argument must be zero)"
    jonatack commented at 4:40 PM on March 5, 2021:

    note to self, if need to retouch:

    -        if (len(newscript) == 0):
+        if len(newscript) == 0:
  8. jonatack force-pushed on Mar 5, 2021
  9. DrahtBot added the label Tests on Mar 5, 2021
  10. ghost commented at 1:59 AM on March 6, 2021: none

    tACK 006c512501cdb6581fcc2db99912d0f96bdb6b8f

    I've always had problems with this one running with test_runner.py. Works now for me, and running individually also seeing a decrease from 1.147s to 0.899s

  11. in test/functional/feature_nulldummy.py:23 in 006c512501 outdated 
      19 | @@ -20,13 +20,14 @@
  20 |  from test_framework.test_framework import BitcoinTestFramework
  21 |  from test_framework.util import assert_equal, assert_raises_rpc_error
  22 |  
  23 | +HEIGHT = 99
    MarcoFalke commented at 7:33 AM on March 6, 2021:

    it would be good to self-documenting name, as it is not clear which block height this refers to

    jonatack commented at 11:44 AM on March 6, 2021:

    done

  12. jonatack force-pushed on Mar 6, 2021
  13. jonatack commented at 11:47 AM on March 6, 2021: member

    Thanks @AnthonyRonning and @MarcoFalke. Separated the refactoring change from the behavior change, renamed the new constant to COINBASE_MATURITY, and proposed the higher timeout again for insurance.

  14. ghost commented at 4:13 AM on March 9, 2021: none

    tACK 248f56bf8118e4aeea80628856d40ff39bcce5ca

    Ran git rebase -i HEAD~3:

    pick f986ff532 test, refactor: abstract the feature_nulldummy blockheight values
x make -j "$(($(nproc)+1))" check && test/functional/feature_nulldummy.py
pick 1c8fe7ebc test: use 327 fewer blocks in feature_nulldummy
x make -j "$(($(nproc)+1))" check && test/functional/test_runner.py -j 60 && test/functional/feature_nulldummy.py
pick 248f56bf8 test: set a higher rpc_timeout in feature_nulldummy
x make -j "$(($(nproc)+1))" check && test/functional/test_runner.py -j 60 && test/functional/feature_nulldummy.py

    Skipped full tests on first commit since that was just a refactor and always failed for me. Everything succeeded here 👌

  15. in test/functional/feature_nulldummy.py:12 in f986ff5324 outdated 
      11 | +Generate COINBASE_MATURITY (CB) more blocks to ensure the coinbases are mature.
  12 | +[Policy/Consensus] Check that NULLDUMMY compliant transactions are accepted in block CB + 1.
  13 |  [Policy] Check that non-NULLDUMMY transactions are rejected before activation.
  14 | -[Consensus] Check that the new NULLDUMMY rules are not enforced on the 431st block.
  15 | -[Policy/Consensus] Check that the new NULLDUMMY rules are enforced on the 432nd block.
  16 | +[Consensus] Check that the new NULLDUMMY rules are not enforced on block CB + 2.
    MarcoFalke commented at 6:50 AM on March 9, 2021:

    I don't understand this CB is 427. CB+2 is 429. The previous comment said 431

    jonatack commented at 9:42 PM on March 10, 2021:

    Fixed the off-by-two error (thanks!)

  16. in test/functional/feature_nulldummy.py:50 in 248f56bf81 outdated 
      46 | @@ -47,6 +47,7 @@ def set_test_params(self):
  47 |              f'-segwitheight={COINBASE_MATURITY + 5}',
  48 |              '-addresstype=legacy',
  49 |          ]] * 2
  50 | +        self.rpc_timeout = 480
    MarcoFalke commented at 6:51 AM on March 9, 2021:

    why is this needed? A common thing in our tests is to generate 100 blocks. If this times out, the default should be bumped instead of the overwrite for each test.

    jonatack commented at 9:46 PM on March 10, 2021:

    Several other tests are doing self.rpc_timeout = 480; including wallet_groups that generates a similar number of blocks. We can start by trying without it though.

  17. test, refactor: abstract the feature_nulldummy blockheight values
    Refactoring only, no change in test behavior.
    68c280f197
  18. test: use 327 fewer blocks in feature_nulldummy
    by generating 100 blocks for coinbase maturity instead of 427.

This speeds up the test and should help avoid timeout errors.
    ccd976dd3d
  19. jonatack force-pushed on Mar 10, 2021
  20. jonatack commented at 9:50 PM on March 10, 2021: member

    Updated per @MarcoFalke's feedback (thanks!)

  21. ghost commented at 5:03 AM on March 11, 2021: none

    reACK ccd976dd3dbb8f991dc1203ada2043f1736be5a4 - ran a few times with the rest of the tests and still passing for me with just the fewer block change.

  22. practicalswift commented at 5:25 PM on March 20, 2021: contributor

    @MarcoFalke

    Seems fine, but is there a reason to mine so many blocks in the first place?

    This test was introduced in 482f852da65457eb2fbea6b259e7568133fb81c4 (PR #8636): @jl2012, thanks for adding this test five years ago - do you happen to remember the rationale (if any) for choosing 429 instead of say 100? :)

    Context: we're considering applying some "number go down" technology here to avoid timeouts, but we wanted to double check that we're not missing any good arguments for going with a larger number :)

  23. in test/functional/feature_nulldummy.py:9 in ccd976dd3d 
       5 | @@ -6,11 +6,11 @@
   6 |  
   7 |  Connect to a single node.
   8 |  Generate 2 blocks (save the coinbases for later).
   9 | -Generate 427 more blocks.
  10 | -[Policy/Consensus] Check that NULLDUMMY compliant transactions are accepted in the 430th block.
  11 | +Generate COINBASE_MATURITY (CB) more blocks to ensure the coinbases are mature.
    kiminuo commented at 6:45 AM on April 1, 2021:

    nit: Would it be easier to read to pre-pend asterisks in this documentation like this:

    * Connect to a single node.
* Generate 2 blocks (save the coinbases for later).
* Generate COINBASE_MATURITY (CB) more blocks to ensure the coinbases are mature.
* [Policy/Consensus] Check that NULLDUMMY compliant transactions are accepted in block CB + 3.
* [Policy] Check that non-NULLDUMMY transactions are rejected before activation.
* [Consensus] Check that the new NULLDUMMY rules are not enforced on block CB + 4.
* [Policy/Consensus] Check that the new NULLDUMMY rules are enforced on block CB + 5.

    Feel free to ignore.

  24. in test/functional/feature_nulldummy.py:23 in ccd976dd3d 
      19 | @@ -20,13 +20,14 @@
  20 |  from test_framework.test_framework import BitcoinTestFramework
  21 |  from test_framework.util import assert_equal, assert_raises_rpc_error
  22 |  
  23 | +COINBASE_MATURITY = 100
    kiminuo commented at 6:57 AM on April 1, 2021:

    I can see there are actually many generate(100) occurrences in test files. Would it make sense to add this to test_framework\messages.py (or in a different file with constants)? Something similar was done with MAX_MONEY in https://github.com/bitcoin/bitcoin/commit/faae5a9a356d821f0cbdea32030b0ce356351a1d.

    jonatack commented at 2:20 PM on April 1, 2021:

    I can see there are actually many generate(100) occurrences in test files. Would it make sense to add this to test_framework\messages.py (or in a different file with constants)? Something similar was done with MAX_MONEY in faae5a9.

    Sure, possibly an idea for another PR.

    $ git grep "generate(100)" test/functional/ | wc -l
18
$ git grep "generate(101)" test/functional/ | wc -l
21
  25. kiminuo commented at 7:03 AM on April 1, 2021: contributor

    The change looks good to me as intended.

    I'm not sure about the rationale for choosing 429 originally.

  26. MarcoFalke commented at 11:13 AM on April 1, 2021: member

    The height (429) was picked because vbparams didn't exist back then to "bury" changes on regtest

  27. MarcoFalke commented at 11:16 AM on April 1, 2021: member

    review ACK ccd976dd3dbb8f991dc1203ada2043f1736be5a4 🏝

    <details><summary>Show signature and timestamp</summary>

    Signature:

    -----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

review ACK ccd976dd3dbb8f991dc1203ada2043f1736be5a4 🏝
-----BEGIN PGP SIGNATURE-----

iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
pUjpbgv8DLEtCXLnczNCA0mfbZq2UaJaw9CKqgqlnW8lM1QFl9LmluhQJO7UDp9C
VGSwwYxzs0mBZprJxmGrmSjhGEyFKPtPrQtY3Ao0VWV1zEn2MKRvb6idFvIzDYMy
20LsKKW85tYH85SBWHcepoaKAcT3dvRa6HflNP0BJknABoFL+sJ66jiOaQvKd0Y1
gtRAUDCBtljgVePEj8k+En/StSF7qVuQTh2rfgo4oJncFkC/e6bCStYJGDkwuUPI
+EhvCmlB9UenOkP3B8mg6DwQtBSgCZW0PX025HoDMWsVhF95786siSaObMmAohU0
lzYAj6WmPbk46CB9qF5tsQ43qJ6HZ/GKN+XXuYDMkOaQkkalbaNrxpVs3GPnwKYa
BabZr4XyaEw1UEk9ByRT6AS7j4gve2cXZDvKDvqfqT82yDVXzGSWRKkNo5vp1lmv
jwukngXTz6jktow+7kZsRWjoDEUZMgQ3GrqT+sV/TP9ObcWMBUYdBNiNoGwAO03c
7As9rGvA
=lT3a
-----END PGP SIGNATURE-----

    Timestamp of file with hash 1e52f2914ddf1ac446dbe929e1f14d25816ad8148aa6c8c16d9aea45757f457b -

    </details>

  28. MarcoFalke renamed this:
    test, refactor: generate fewer blocks in feature_nulldummy to fix timeouts, speed up
    test: generate fewer blocks in feature_nulldummy to fix timeouts, speed up
    on Apr 1, 2021
  29. MarcoFalke commented at 11:17 AM on April 1, 2021: member

    (Removed "refactor" from title because this is not a pure refactor)

  30. MarcoFalke merged this on Apr 1, 2021
  31. MarcoFalke closed this on Apr 1, 2021
  32. jonatack deleted the branch on Apr 1, 2021
  33. jonatack commented at 2:21 PM on April 1, 2021: member

    The height (429) was picked because vbparams didn't exist back then to "bury" changes on regtest

    TIL, thanks!

  34. sidhujag referenced this in commit 99060db681 on Apr 1, 2021
  35. MarcoFalke referenced this in commit c5ee0cc11a on May 31, 2021
  36. DrahtBot locked this on Aug 16, 2022
Contributors
jonatackMarcoFalkeghostpracticalswiftkiminuo
Labels
Tests
Linked (view graph)
#21989 test: Use COINBASE_MATURITY in functional tests
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-14 21:14 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me