[qa] Create cached blocks with current timestamps

sdaftuar commented at 11:29 pm on February 6, 2019: member

There doesn’t seem to be any benefit to creating the cached data directories with old timestamps, but it does seem to interfere with tests because nodes using the cached chain were starting off in IBD, which interferes with chain sync.

This PR changes the cache to use current timestamps. One test seemed to be relying on the blocks in the cache being old, so I modified it to explicitly create old blocks.

Changing the cache to use recent timestamps – and thus have nodes be out of IBD on startup – fixes a bug in the wallet_txn_doublespend.py test, noted in #14446. Block sync to a node in IBD might fail because we are willing to wait a long time for our headers-sync peer to respond before we send getheaders messages to other peers. In wallet_txn_doublespend.py, the test tries to workaround this issue by mining a block after connection, which happens to trigger the IBD-node to send a getheaders after receiving the block INV. However, there is a race, where node connection and initial handshake could take longer than the call to generate the block, resulting in no block announcement going to the IBD peer, causing test failure.

[qa] Create cached blocks with current timestamps 120f9357ed

fanquake added the label Tests on Feb 6, 2019

fanquake requested review from MarcoFalke on Feb 8, 2019

in test/functional/wallet_txn_doublespend.py:43 in 120f9357ed

38+        # All nodes should be out of IBD.
39+        # If the nodes are not all out of IBD, that can interfere with
40+        # blockchain sync later in the test when nodes are connected, due to
41+        # timing issues.
42+        for n in self.nodes:
43+            assert n.getblockchaininfo()["initialblockdownload"] == False

MarcoFalke commented at 5:14 pm on February 8, 2019:

This assertion would fail when the tests are called “manually”, since the cache is not reset when calling tests individually (not through) the test_runner script.

 0$ ./test/functional/wallet_txn_doublespend.py 
 12019-02-08T17:09:47.027000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_62_g4dwe
 22019-02-08T17:09:48.015000Z TestFramework (INFO): Stopping nodes
 32019-02-08T17:09:48.275000Z TestFramework (INFO): Cleaning up /tmp/bitcoin_func_test_62_g4dwe on exit
 42019-02-08T17:09:48.275000Z TestFramework (INFO): Tests successful
 5
 6[... time travel to +1 day]
 7
 8$ ./test/functional/wallet_txn_doublespend.py 
 92019-02-09T17:10:07.360000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_jck9m01h
102019-02-09T17:10:08.138000Z TestFramework (ERROR): Assertion failed
11Traceback (most recent call last):
12  File "/home/marco/workspace/bitcoin/test/functional/test_framework/test_framework.py", line 176, in main
13    self.run_test()
14  File "./test/functional/wallet_txn_doublespend.py", line 43, in run_test
15    assert n.getblockchaininfo()["initialblockdownload"] == False
16AssertionError

MarcoFalke commented at 5:38 pm on February 8, 2019:

Couldn’t this be moved to setup_nodes under a condition of if not self.setup_clean_chain. This way there’d be a nice assumption that all nodes in tests could send and receive txs right away initially.

If the assertion failed, you could put a comment like # Cache might be outdated, please run test through the test_runner script

sdaftuar commented at 7:49 pm on February 8, 2019:

Ah, I misunderstood how the cache worked (I thought it only persisted between calls to tests in the same test_runner run, and otherwise was being cleared between tests).

in test/functional/test_framework/test_framework.py:481 in 120f9357ed

476@@ -477,10 +477,8 @@ def _initialize_chain(self):
477             for node in self.nodes:
478                 node.wait_for_rpc_connection()
479 
480-            # For backward compatibility of the python scripts with previous
481-            # versions of the cache, set mocktime to Jan 1,
482-            # 2014 + (201 * 10 * 60)"""
483-            self.mocktime = 1388534400 + (201 * 10 * 60)
484+            # Create the blocks, spaced 10 minutes apart, starting now
485+            self.mocktime = int(time.time())

MarcoFalke commented at 5:41 pm on February 8, 2019:

Seems arbitrary to still use mocktime, but only change the magic value. Also, wouldn’t mining blocks with timestamps in the future lead to block sync issues? IIRC a node woulnd’t even attempt to download a block when the header has a future timestamp?

I’d prefer to remove mocktime altogether and only use it in tests that require it for some reason (see the test below you modified for example)

Just my opinion, no need to fix in this pull request.

MarcoFalke commented at 5:41 pm on February 8, 2019: member

Concept ACK

sdaftuar commented at 7:51 pm on February 8, 2019: member

I’m not sure what the best fix here is, closing.

sdaftuar closed this on Feb 8, 2019

MarcoFalke commented at 7:57 pm on February 8, 2019: member

:(

Was good to see someone working on this, finally.

MarcoFalke referenced this in commit 8f470ecc53 on Feb 25, 2019

Munkybooty referenced this in commit e928494a49 on Sep 8, 2021

dzutto referenced this in commit 6f296bdb78 on Oct 15, 2021

DrahtBot locked this on Dec 16, 2021

[qa] Create cached blocks with current timestamps #15360