test: Avoid intermittent test failure in feature_csv_activation.py #22907

pull MarcoFalke wants to merge 2 commits into bitcoin:master from MarcoFalke:2109-testFix changing 1 files +7 −3
  1. MarcoFalke commented at 8:27 AM on September 7, 2021: member

    Otherwise there will be disconnects if the test runs longer than the default peertimeout (60s):

     node0 2021-09-05T20:28:30.973116Z (mocktime: 2021-09-01T07:17:29Z) [net] [net.cpp:1323] [InactivityCheck] socket receive timeout: 393061s peer=0

    Fix that by skipping InactivityCheck via a large -peertimeout.

  2. fanquake added the label Tests on Sep 7, 2021
  3. MarcoFalke commented at 8:29 AM on September 7, 2021: member

    Larger excerpt:

     node0 2021-09-06T11:11:53.793409Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=setmocktime user=__cookie__ 
 test  2021-09-06T11:11:53.795000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress` 
 node0 2021-09-06T11:11:53.799988Z (mocktime: 2021-09-01T22:00:50Z) [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:49394 
 node0 2021-09-06T11:11:53.801303Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=generatetoaddress user=__cookie__ 
 node0 2021-09-06T11:11:53.911667Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:4051 started 
 node0 2021-09-06T11:11:53.912438Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:4051 completed (0μs) 
 node0 2021-09-06T11:11:55.128848Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [miner.cpp:169] [CreateNewBlock] CreateNewBlock(): block weight: 56680 txs: 83 fees: 4183200 sigops 732 
 node0 2021-09-06T11:11:55.179940Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1730] [ConnectBlock]     - Sanity checks: 0.86ms [0.09s (0.17ms/blk)] 
 node0 2021-09-06T11:11:55.197474Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1832] [ConnectBlock]     - Fork checks: 17.45ms [1.40s (2.74ms/blk)] 
 node0 2021-09-06T11:11:55.328906Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1917] [ConnectBlock]       - Connect 84 transactions: 118.15ms (1.407ms/tx, 1.423ms/txin) [1.37s (2.68ms/blk)] 
 node0 2021-09-06T11:11:55.345305Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1930] [ConnectBlock]     - Verify 83 txins: 147.47ms (1.777ms/txin) [2.36s (4.62ms/blk)] 
 node0 2021-09-06T11:11:55.348207Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [miner.cpp:184] [CreateNewBlock] CreateNewBlock() packages: 68.80ms (83 packages, 0 updated descendants), validity: 1429.11ms (total 1497.91ms) 
 node0 2021-09-06T11:11:55.493700Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validationinterface.cpp:254] [NewPoWValidBlock] NewPoWValidBlock: block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 
 node0 2021-09-06T11:11:55.495315Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:4051 started 
 node0 2021-09-06T11:11:55.496232Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:4051 completed (0μs) 
 node0 2021-09-06T11:11:55.552255Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:2340] [ConnectTip]   - Load block from disk: 0.00ms [0.20s] 
 node0 2021-09-06T11:11:55.553433Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1730] [ConnectBlock]     - Sanity checks: 0.10ms [0.09s (0.17ms/blk)] 
 node0 2021-09-06T11:11:55.586610Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1832] [ConnectBlock]     - Fork checks: 4.11ms [1.41s (2.74ms/blk)] 
 node0 2021-09-06T11:11:55.647495Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1917] [ConnectBlock]       - Connect 84 transactions: 89.83ms (1.069ms/tx, 1.082ms/txin) [1.46s (2.85ms/blk)] 
 node0 2021-09-06T11:11:55.664682Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:4051 started 
 node0 2021-09-06T11:11:55.665448Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:4051 completed (0μs) 
 node0 2021-09-06T11:11:55.666318Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1930] [ConnectBlock]     - Verify 83 txins: 108.76ms (1.310ms/txin) [2.47s (4.82ms/blk)] 
 node0 2021-09-06T11:11:55.784786Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1949] [ConnectBlock]     - Index writing: 103.39ms [1.40s (2.73ms/blk)] 
 node0 2021-09-06T11:11:55.785627Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:1952] [ConnectBlock]     - Callbacks: 15.93ms [0.98s (1.92ms/blk)] 
 node0 2021-09-06T11:11:55.786721Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validationinterface.cpp:249] [BlockChecked] BlockChecked: block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 state=Valid 
 node0 2021-09-06T11:11:55.810724Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:2352] [ConnectTip]   - Connect total: 235.36ms [8.78s (17.12ms/blk)] 
 node0 2021-09-06T11:11:55.839529Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:2357] [ConnectTip]   - Flush: 51.83ms [0.85s (1.65ms/blk)] 
 node0 2021-09-06T11:11:55.840360Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:2363] [ConnectTip]   - Writing chainstate: 0.93ms [1.16s (2.27ms/blk)] 
 node0 2021-09-06T11:11:55.882162Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [policy/fees.cpp:647] [processBlock] Blockpolicy estimates updated by 0 of 83 block txs, since last block 0 of 83 tracked, mempool map size 0, max target 0 from current 
 node0 2021-09-06T11:11:56.039127Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:2202] [UpdateTip] UpdateTip: new best=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 height=428 version=0x30000000 log2_work=9.744834 tx=512 date='2021-09-01T22:00:50Z' progress=1.000000 cache=0.1MiB(511txo) 
 node0 2021-09-06T11:11:56.040097Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:2374] [ConnectTip]   - Connect postprocess: 199.74ms [4.76s (9.27ms/blk)] 
 node0 2021-09-06T11:11:56.040851Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validation.cpp:2375] [ConnectTip] - Connect block: 487.85ms [15.75s (30.70ms/blk)] 
 node0 2021-09-06T11:11:56.041519Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [txmempool.cpp:691] [check] Checking mempool with 0 transactions and 0 inputs 
 node0 2021-09-06T11:11:56.042578Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validationinterface.cpp:226] [BlockConnected] Enqueuing BlockConnected: block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 block height=428 
 node0 2021-09-06T11:11:56.043515Z (mocktime: 2021-09-01T22:00:50Z) [scheduler] [validationinterface.cpp:226] [operator()] BlockConnected: block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 block height=428 
 node0 2021-09-06T11:11:56.047038Z (mocktime: 2021-09-01T22:00:50Z) [scheduler] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:1476 started 
 node0 2021-09-06T11:11:56.047838Z (mocktime: 2021-09-01T22:00:50Z) [scheduler] [logging/timer.h:50] [Log] LockContention: cs_main, net_processing.cpp:1476 completed (0μs) 
 node0 2021-09-06T11:11:56.054767Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.0] [validationinterface.cpp:199] [UpdatedBlockTip] Enqueuing UpdatedBlockTip: new block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 fork block hash=0e8be20a4000dc1717ef6fe1b87f98e08926c25c3edac26b0935be2d2fabf023 (in IBD=false) 
 node0 2021-09-06T11:11:56.056503Z (mocktime: 2021-09-01T22:00:50Z) [scheduler] [validationinterface.cpp:199] [operator()] UpdatedBlockTip: new block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 fork block hash=0e8be20a4000dc1717ef6fe1b87f98e08926c25c3edac26b0935be2d2fabf023 (in IBD=false) 
 node0 2021-09-06T11:11:56.057367Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [net_processing.cpp:4689] [SendMessages] SendMessages: sending inv peer=0 hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 
 test  2021-09-06T11:11:56.058000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:13208: msg_inv(inv=[CInv(type=Block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1)]) 
 node0 2021-09-06T11:11:56.058036Z (mocktime: 2021-09-01T22:00:50Z) [msghand] [net.cpp:2995] [PushMessage] sending inv (37 bytes) peer=0 
 test  2021-09-06T11:11:56.059000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:13208: msg_getdata(inv=[CInv(type=Block hash=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1)]) 
 node0 2021-09-06T11:11:56.062802Z (mocktime: 2021-09-01T22:00:50Z) [net] [net.cpp:1323] [InactivityCheck] socket receive timeout: 393066s peer=0 
 node0 2021-09-06T11:11:56.065873Z (mocktime: 2021-09-01T22:00:50Z) [net] [net.cpp:502] [CloseSocketDisconnect] disconnecting peer=0 
 test  2021-09-06T11:11:56.067000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:13208 
 node0 2021-09-06T11:11:56.109531Z (mocktime: 2021-09-01T22:00:50Z) [net] [net_processing.cpp:1242] [FinalizeNode] Cleared nodestate for peer=0 
 node0 2021-09-06T11:11:56.119620Z (mocktime: 2021-09-01T22:00:50Z) [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:49394 
 node0 2021-09-06T11:11:56.120864Z (mocktime: 2021-09-01T22:00:50Z) [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=setmocktime user=__cookie__ 
 node0 2021-09-06T11:11:56.124127Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:49394 
 node0 2021-09-06T11:11:56.126977Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblock user=__cookie__ 
 test  2021-09-06T11:11:56.219000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:13208: msg_headers(headers=[CBlockHeader(nVersion=4 hashPrevBlock=412e8eaf5a5577dcc70c94e3d19b1eb9c785e517d283f98d4f63f87bd976b4e1 hashMerkleRoot=2876ae3bf2a221c9bc59a8eafb631b987f05ebd66f875b427d2bddce057e745a nTime=Wed Sep  1 22:10:50 2021 nBits=207fffff nNonce=00000002), CBlockHeader(nVersion=4 hashPrevBlock=3ae7e509bf90f34476e7b29d38f595f5a03d4279da5dd69c6acfef942eb0ef71 hashMerkleRoot=e876fe31e8a68676a8d0c178e05beae5572e716fd1eb594834eee06cae51dd13 nTime=Wed Sep  1 22:20:50 2021 nBits=207fffff nNo... (msg truncated) 
 test  2021-09-06T11:11:56.219000Z TestFramework (ERROR): Unexpected exception caught during testing 
                                   Traceback (most recent call last):
                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
                                       self.run_test()
                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_csv_activation.py", line 247, in run_test
                                       self.send_blocks(test_blocks)
                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_csv_activation.py", line 183, in send_blocks
                                       self.helper_peer.send_blocks_and_test(blocks, self.nodes[0], success=success, reject_reason=reject_reason)
                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 716, in send_blocks_and_test
                                       self.send_message(msg_headers([CBlockHeader(block) for block in blocks]))
                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 264, in send_message
                                       return self.send_raw_message(tmsg)
                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 268, in send_raw_message
                                       raise IOError('Not connected')
                                   OSError: Not connected
 test  2021-09-06T11:11:56.221000Z TestFramework (DEBUG): Closing down network thread 
 test  2021-09-06T11:11:56.271000Z TestFramework (INFO): Stopping nodes 
 test  2021-09-06T11:11:56.272000Z TestFramework.node0 (DEBUG): Stopping node
  4. DrahtBot commented at 7:59 PM on September 7, 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:

    • #22818 (test: Activate all regtest softforks at height 1, unless overridden by MarcoFalke)

    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. fanquake deleted a comment on Sep 7, 2021
  6. practicalswift commented at 7:56 AM on September 8, 2021: contributor

    Concept ACK

  7. laanwj commented at 11:55 AM on September 9, 2021: member

    It would make sense to separate the styling changes from the behavior change into separate commits.

    Concept ACK

  8. test: Avoid intermittent test failure in feature_csv_activation.py faed284eab
  9. test: pep-8 whitespace fa676dbac8
  10. MarcoFalke commented at 11:59 AM on September 9, 2021: member

    Makes sense. Done.

  11. MarcoFalke force-pushed on Sep 9, 2021
  12. ShubhamPalriwala commented at 3:17 PM on September 9, 2021: contributor

    tAck fa676dbac87919061de9f82bce65e373e8d85bd1 peertimeout will fix the test failure for now as it overrides the default timeout of 60 seconds

    Tested on Ubuntu 21.02

  13. nina1234 approved
  14. in test/functional/feature_csv_activation.py:97 in fa676dbac8 
      93 | @@ -92,6 +94,7 @@ def set_test_params(self):
  94 |          self.num_nodes = 1
  95 |          self.setup_clean_chain = True
  96 |          self.extra_args = [[
  97 | +            '-peertimeout=999999',  # bump because mocktime might cause a disconnect otherwise
    fanquake commented at 6:11 AM on September 10, 2021:

    I take it this needs to be an even larger timeout than we currently use in a few other places, i.e: "-peertimeout=9999", # bump because mocktime might cause a disconnect otherwise? Otherwise would be good to settle on the same LARGE number everywhere.

    MarcoFalke commented at 8:01 AM on September 10, 2021:

    It only needs to be 1 second longer than the whole duration of the test. If the test takes 100 seconds, it needs to be 101. So 9999 seems enough for our purposes here.

    MarcoFalke commented at 8:19 AM on September 10, 2021:

    Maybe peertimeout should be set to ~infinity by default in our functional tests, unless opted out?

  15. fanquake approved
  16. fanquake commented at 6:11 AM on September 10, 2021: member

    ACK fa676dbac87919061de9f82bce65e373e8d85bd1

  17. MarcoFalke merged this on Sep 10, 2021
  18. MarcoFalke closed this on Sep 10, 2021
  19. MarcoFalke deleted the branch on Sep 10, 2021
  20. sidhujag referenced this in commit dfa5aab5fb on Sep 11, 2021
  21. DrahtBot locked this on Oct 30, 2022
Contributors
MarcoFalkeDrahtBotpracticalswiftlaanwjShubhamPalriwalanina1234fanquake
Labels
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-17 06:14 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me