(Luke) was unsure if the code sufficiently avoided caching a time-too-new rejection, so wrote this test to check it. It looks like despite only exempting BLOCK_MUTATED, it is still okay because header failures never cache block invalidity. This test will help ensure that if this ever changes, BLOCK_TIME_FUTURE gets excluded at the same time.
This PR re-opens #17872 which went stale and addresses the nits raised by reviewers there.
Two concept ACKs, but this needs review comments addressing, added "waiting for author" #17872 (comment)
Concept ACK, cool you picked this up.
nit: I think the title should be test: or qa: ie lower case rather than upper case
test, qa or ci for changes to the unit tests, QA tests or CI code test, https://github.com/bitcoin/bitcoin/blob/master/CONTRIBUTING.md#creating-the-pull-request
142 | + t = int(time.time()) 143 | + node.setmocktime(t) 144 | + block = create_block(tip, create_coinbase(height), t + 7201) 145 | + block.hashMerkleRoot = block.calc_merkle_root() 146 | + block.solve() 147 | + # NOTE: Need force_send because the block will get rejected without a getdata otherwise
This is a comment, there's no need to say "NOTE"
# Need force_send because the block will get rejected without a getdata otherwise
Removed!
Hm, I don't think it's been removed?
146 | + block.solve() 147 | + # NOTE: Need force_send because the block will get rejected without a getdata otherwise 148 | + node.p2ps[0].send_blocks_and_test([block], node, force_send=True, success=False, reject_reason='time-too-new') 149 | + 150 | + node.setmocktime(t + 1) 151 | + node.p2ps[0].send_blocks_and_test([block], node, success=True, timeout=5)
I'd prefer referencing the p2p object directly instead of through the node's p2p list, similar to the code above. If a subtest is added that connects/disconnects peers, this index could no longer refer to the peer you want.
peer.send_blocks_and_test([block], node, force_send=True, success=False, reject_reason='time-too-new')
node.setmocktime(t + 1)
peer.send_blocks_and_test([block], node, success=True, timeout=5)
Thanks, I agree this is both clearer and better.
135 | @@ -133,5 +136,19 @@ def run_test(self): 136 | self.log.info("Test inflation by duplicating input") 137 | peer.send_blocks_and_test([block4], node, success=False, reject_reason='bad-txns-inputs-duplicate') 138 | 139 | + 140 | + self.log.info("Test accepting identical block after rejecting it due to a future timestamp.") 141 | + 142 | + t = int(time.time()) 143 | + node.setmocktime(t) 144 | + block = create_block(tip, create_coinbase(height), t + 7201)
This is 1 second away from the cutoff right? Perhaps a slightly larger buffer would be better because the functional tests usually run multithreaded.
Another small suggestion, using 2 * 60 * 60 or MAX_FUTURE_BLOCK_TIME instead of a magic number might be a bit more clear
I went for MAX_FUTURE_BLOCK_TIME in the end and added a new t_premature = 60, so that we have a 60 second buffer to avoid any potential issues.
Concept ACK, thanks for picking this up! :)
A few (very small) suggestions for your consideration
138 | @@ -133,5 +139,19 @@ def run_test(self): 139 | self.log.info("Test inflation by duplicating input") 140 | peer.send_blocks_and_test([block4], node, success=False, reject_reason='bad-txns-inputs-duplicate') 141 | 142 | + self.log.info("Test accepting identical block after rejecting it due to a future timestamp.") 143 | + t = int(time.time()) 144 | + # Make block timestamp validity 60 seconds premature to avoid test-timing issues
why? I changed to 1 and nothing happened
I also had no difficulty/local failures with t=1, but there was a raised concern that multi-threaded tests could jeopardise this here. It doesn't seem like something that threat timing issues could throw off to me as time is advanced before validity is re-checked, but I am not 100% on that.
I am going to reset this to 1 along with the timeout change suggested as a means to restart appveyor which failed.
Edit: @MarcoFalke can you confirm that node time cannot advance automatically once setmocktime rpc has been called? If so then I will be convinced that multi-threading these tests will not cause any issues with t=1
Edit: @MarcoFalke can you confirm that node time cannot advance automatically once setmocktime rpc has been called? If so then I will be convinced that multi-threading these tests will not cause any issues with t=1
The wall clock time for the node still advances, but the mocktime is pinned once setmocktime is set to a non-zero value.
Thanks, unnecessary constant now removed in 754e802
148 | + block.hashMerkleRoot = block.calc_merkle_root() 149 | + block.solve() 150 | + # Need force_send because the block will get rejected without a getdata otherwise 151 | + peer.send_blocks_and_test([block], node, force_send=True, success=False, reject_reason='time-too-new') 152 | + node.setmocktime(t + t_premature) 153 | + peer.send_blocks_and_test([block], node, success=True, timeout=5)
peer.send_blocks_and_test([block], node, success=True)
No need to lower this. User can adjust via --timeout-factor=0.1
Thanks. Will update this with or without the time premature (=1) suggestion.
Removed in 754e802
ACK
left some ideas to adjust magic values
(Luke) was unsure if the code sufficiently avoided caching a
time-too-new rejection, so wrote this test to check it. It looks like
despite only exempting BLOCK_MUTATED, it is still okay because header
failures never cache block invalidity. This test will help ensure that
if this ever changes, BLOCK_TIME_FUTURE gets excluded at the same time.
Co-authored-by: Will Clark <will8clark@gmail.com>
Pushed to address nits and restart appveyor (which failed during fastly outage).
t_premature and reverted to simple + 1 seconds past MAX_FUTURE_BLOCK_TIMEtimeout from send_blocks_and_test as suggested here$ git range-diff HEAD~1..7879b46 HEAD~1..754e802
1: 7879b4679 ! 1: 754e80227 test: check rejected future block later accepted
@@ test/functional/p2p_invalid_block.py: class InvalidBlockRequestTest(BitcoinTestF
+ self.log.info("Test accepting identical block after rejecting it due to a future timestamp.")
+ t = int(time.time())
-+ # Make block timestamp validity 60 seconds premature to avoid test-timing issues
-+ t_premature = 60
+ node.setmocktime(t)
-+ block = create_block(tip, create_coinbase(height), t + MAX_FUTURE_BLOCK_TIME + t_premature)
++ # Set block time +1 second past max future validity
++ block = create_block(tip, create_coinbase(height), t + MAX_FUTURE_BLOCK_TIME + 1)
+ block.hashMerkleRoot = block.calc_merkle_root()
+ block.solve()
+ # Need force_send because the block will get rejected without a getdata otherwise
+ peer.send_blocks_and_test([block], node, force_send=True, success=False, reject_reason='time-too-new')
-+ node.setmocktime(t + t_premature)
-+ peer.send_blocks_and_test([block], node, success=True, timeout=5)
++ node.setmocktime(t + 1)
++ peer.send_blocks_and_test([block], node, success=True)
+
+
if __name__ == '__main__':
review ACK 754e802274e9373ad7e1dccb710acf74ded6e7fb
This PR may be causing heisenbug CI failures (example). I can reproduce the failure on my laptop after several attempts:
2021-07-06T22:15:40.550000Z TestFramework (INFO): Create a new block with an anyone-can-spend coinbase
2021-07-06T22:15:40.653000Z TestFramework (INFO): Mature the block.
2021-07-06T22:15:40.991000Z TestFramework (INFO): Test merkle root malleability.
2021-07-06T22:15:41.096000Z TestFramework (INFO): Test duplicate input block.
2021-07-06T22:15:41.200000Z TestFramework (INFO): Test very broken block.
2021-07-06T22:15:41.304000Z TestFramework (INFO): Test accepting original block after rejecting its mutated version.
2021-07-06T22:15:41.357000Z TestFramework (INFO): Test inflation by duplicating input
2021-07-06T22:15:41.460000Z TestFramework (INFO): Test accepting identical block after rejecting it due to a future timestamp.
2021-07-06T22:15:43.489000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
File "/g/bitcoin/test/functional/test_framework/test_framework.py", line 128, in main
self.run_test()
File "test/functional/p2p_invalid_block.py", line 150, in run_test
peer.send_blocks_and_test([block], node, force_send=True, success=False, reject_reason='time-too-new')
File "/g/bitcoin/test/functional/test_framework/p2p.py", line 730, in send_blocks_and_test
assert node.getbestblockhash() != blocks[-1].hash
File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
next(self.gen)
File "/g/bitcoin/test/functional/test_framework/test_node.py", line 400, in assert_debug_log
self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
File "/g/bitcoin/test/functional/test_framework/test_node.py", line 166, in _raise_assertion_error
raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['time-too-new']" does not partially match log:
Are you sure this is failing on master?
Debug log rotation must be disabled for the tests to work properly, as some are reading within the file by offset.
Are you sure this is failing on master?
Debug log rotation must be disabled for the tests to work properly, as some are reading within the file by offset.
AAACK! You're right, sorry about that! I didn't imagine the log file would get large enough to rotate, but I forgot that tests run with -debug (all logs enabled).