Skip to content

Conversation

@maflcko
Copy link
Member

@maflcko maflcko commented Sep 7, 2021

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.

@fanquake fanquake added the Tests label Sep 7, 2021
@maflcko
Copy link
Member Author

maflcko commented Sep 7, 2021

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 

@DrahtBot
Copy link
Contributor

DrahtBot commented Sep 7, 2021

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

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.

@practicalswift
Copy link
Contributor

Concept ACK

@laanwj
Copy link
Member

laanwj commented Sep 9, 2021

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

Concept ACK

@maflcko
Copy link
Member Author

maflcko commented Sep 9, 2021

Makes sense. Done.

Copy link
Contributor

@ShubhamPalriwala ShubhamPalriwala left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Tested on Ubuntu 21.02

Copy link
Member

@fanquake fanquake left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK fa676db

self.num_nodes = 1
self.setup_clean_chain = True
self.extra_args = [[
'-peertimeout=999999', # bump because mocktime might cause a disconnect otherwise
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@maflcko maflcko merged commit 6088115 into bitcoin:master Sep 10, 2021
@maflcko maflcko deleted the 2109-testFix branch September 10, 2021 08:18
sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Sep 11, 2021
…_csv_activation.py

fa676db test: pep-8 whitespace (MarcoFalke)
faed284 test: Avoid intermittent test failure in feature_csv_activation.py (MarcoFalke)

Pull request description:

  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`.

ACKs for top commit:
  fanquake:
    ACK fa676db

Tree-SHA512: 061c0585a805aa2f8e55c4beedd4b8498a2951f33d60aa3632dda0a284db3a627d14a23dbd57e8a66c69a1612f39418e3a755c8ca97f6ae1105c0d70f0d1a801
@bitcoin bitcoin locked and limited conversation to collaborators Oct 30, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

7 participants