qa: Always refresh cache to be out of ibd #15419

maflcko · 2019-02-15T14:42:36Z

When starting a test, we are always in IBD because the timestamps on cached blocks are in the past. Usually, we solve that by generating a block at the beginning of the test.

That is clumsy and might even lead to other problems such as #15360 and #14446 (comment)

So fix that by getting rid of mocktime and always refreshing the last block of the cache when starting the test framework.

Should fix #14446

DrahtBot · 2019-02-15T15:46:34Z

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

#12134 (Build previous releases and run functional tests by Sjors)

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.

promag

nit, update copyright year.

promag

LGTM, some questions though, as I think you could take the opportunity to simplify a bit.

promag · 2019-02-18T18:51:44Z

test/functional/test_framework/test_framework.py

Could remove this right?

test/functional/test_framework/test_framework.py

promag · 2019-02-18T19:20:38Z

test/functional/test_framework/test_framework.py

Maybe something more straightforward?

def gen_blocks(peer, blocks): node = self.nodes[peer] address = node.get_deterministic_priv_key().address return node.generatetoaddress(blocks, address) gen_blocks(0, 25) gen_blocks(1, 25) gen_blocks(2, 25) gen_blocks(3, 24)

No, that would generate 99 blocks, we need 199.

Not sure if this looks simpler:

gen_blocks(0, 25) gen_blocks(1, 25) gen_blocks(2, 25) gen_blocks(3, 25) gen_blocks(0, 25) gen_blocks(1, 25) gen_blocks(2, 25) gen_blocks(3, 24)

Oh right, I was doing for 99 🤦‍♂️

In that case

gen_blocks(0, 50) gen_blocks(1, 50) gen_blocks(2, 50) gen_blocks(3, 49)

Or is there a reason against?

See the comment two lines up:

# Create a 199-block-long chain; each of the 4 first nodes # gets 25 mature blocks and 25 immature.

promag · 2019-02-18T19:24:23Z

test/functional/test_framework/test_framework.py

Is this really necessary?

No, but nice to see that the cache really is 199 blocks high

jnewbery · 2019-02-18T23:39:21Z

Concept ACK. Please remove unrelated code style fixes from your commits.

I think 'rot' is the wrong terminology, and the comment here: faeb65a#diff-64721c5ee64d44f7114d6d0d2226db4dR495 isn't clear.

sipa · 2019-02-19T00:58:27Z

By rotten, you mean dirty? :)

maflcko · 2019-02-19T13:55:27Z

rotten as in from yesterday or from last week. If the cache was edible, it would be rotten, no?

jnewbery · 2019-02-19T14:11:53Z

rotten as in from yesterday or from last week. If the cache was edible, it would be rotten, no?

There's nothing wrong with the block, it's just old. I think this would be much clearer to people reading the tests if you removed the rotten terminology and just said that the latest block needs to be within the last 24 hours for the nodes to consider themselves sync'ed to the tip, possibly with reference to IsInitialBlockDownload() and

bitcoin/src/validation.h

Line 113 in 904308d

static const int64_t DEFAULT_MAX_TIP_AGE = 24 * 60 * 60;

.

Sjors · 2019-02-19T14:32:16Z

the latest block needs to be within the last 24 hours for the nodes to consider themselves sync'ed to the tip

That's definitely useful to remind the reader of (including yours truly).

maflcko · 2019-02-19T15:28:03Z

Ok, going to fixup that comment as per @jnewbery's suggestion

jnewbery · 2019-02-19T16:44:15Z

stale is still wrong:

in caching terminology, stale is commonly understood as meaning that a piece of data in a cache is no longer valid because the underlying value for that data has been updated.
In Bitcoin terminology, a stale block is one which is valid, but not part of the main chain as its on a fork which has less work than the main chain.

Neither of those is the case here. The old block is not stale, it's just old.

I suggest not creating new (confusing) terminology here and just describe what's actually being implemented.

Sjors

The following tests failed on macOS 10.14.3 on the first run. logs:

mining_basic.py                       | ✖ Failed  | 15 s
p2p_invalid_messages.py               | ✖ Failed  | 8 s
tool_wallet.py                        | ✖ Failed  | 2 s
wallet_txn_clone.py                   | ✖ Failed  | 11 s
wallet_txn_clone.py --mineblock       | ✖ Failed  | 9 s
wallet_txn_clone.py --segwit          | ✖ Failed  | 11 s

Some of that seems to be usage of modern Python, which might be unrelated.

@jnewbery agreed. The problem seems to be that cache is not properly invalidated. Our test suite cache items should probably have an expiration timestamp, but that's perhaps a bit overkill to engineer.

Sjors · 2019-02-19T16:46:37Z

test/functional/test_framework/test_framework.py

This needs more explanation, since iiuc it's very relevant to the bug you're trying to squash. What cache is going stale and what is the consequence of that? And in what we should one see IsInitialBlockDownload? What about the cache causes nodes to think they're in or out of IBD? The absolute age of the block in the cache?

It's explained a bit in the next commit, but that's in a very different place.

There are other conditions that keep our node in IBD, but the one we care about here is the tip age (difference between now and the time the miner claimed to have mined the block)

jnewbery · 2019-02-19T17:03:16Z

Can you remove unrelated style changes?

I don't care much about additional new lines between classes (https://github.com/bitcoin/bitcoin/pull/15419/files#diff-a12894108450a68b27252d39d7b6e704R44) or terminating lists with commas (https://github.com/bitcoin/bitcoin/pull/15419/files#diff-86294e5ae5283eebdd9f98d79007a0e1R93).

If you think that should be the project code style, the right thing to do would be update the developer notes and add linters.

maflcko · 2019-02-19T19:28:28Z

@jnewbery We agreed to not add any style-related linters to this project several times already. Personally I format all changed code according to https://github.com/bitcoin/bitcoin/blob/master/doc/productivity.md#writing-code, so that review can focus on the actual changes and is not wasted on counting how many spaces or newlines are between non-whitepace characters.

jnewbery · 2019-02-19T19:38:14Z

so that review can focus on the actual changes and is not wasted on counting how many spaces or newlines are between non-whitepace characters.

My suggestion is to not change code style in PRs which are supposed to be changing behaviour. Here for example: https://github.com/bitcoin/bitcoin/pull/15419/files#diff-64721c5ee64d44f7114d6d0d2226db4dR36 you add a newline that has nothing to do with the changes in this PR.

If you want review to focus on the actual changes, just remove unnecessary noise.

maflcko · 2019-02-19T22:15:00Z

I fixed up the comment and removed a newline that the formatter added. I missed the newline you pointed in the previous comment. Though, I am going to leave this as is for now unless there are actual concerns about the code.

Sjors · 2019-02-20T09:26:06Z

Python syntax issue are fixed in #15439. Also ignore the tool_wallet.py failure, since I forgot to build that target.

utACK fa25210

jnewbery

Looks good. A few suggestions inline.

I still don't like the fact that this PR adds random newlines to various files but if you insist, then I don't care enough to block merging.

jnewbery · 2019-02-21T14:55:21Z

test/functional/test_framework/test_framework.py

+        if not self.setup_clean_chain:
+            for n in self.nodes:
+                assert_equal(n.getblockchaininfo()["blocks"], 199)
+            self.log.debug('Generate a block with current time to finalize the cache and assert we are out of IBD')


I don't think "finalize the cache" would mean anything to people without more context. I'd suggest changing this to:

# To ensure that all nodes are out of IBD, the most recent block must # be within the last 24 hours (see IsInitialBlockDownload()). Generate it here. self.log.debug('Generate a block with current time')

jnewbery · 2019-02-21T15:03:32Z

test/functional/test_framework/test_framework.py

+            block = self.nodes[0].getblock(blockhash=block_hash, verbosity=0)
+            for n in self.nodes:
+                n.submitblock(block)
+                chain_info = n.getblockchaininfo()


There's no race here since submitblock() will only return after ActivateBestChain(), but if we ever make ProcessNewBlock() multithreaded, then there could be a race if submitblock() returns before the best chain has been activated.

I don't think you need to do anything here, but you could add a comment or a wait_until() if you wanted to make this clear to readers.

jnewbery · 2019-02-21T15:08:01Z

test/functional/test_framework/test_framework.py

-            self.mocktime = 1388534400 + (201 * 10 * 60)
-
-            # Create a 200-block-long chain; each of the 4 first nodes
+            # Create a 199-block-long chain; each of the 4 first nodes


A couple of suggestions that could make this more efficient/clear:

you could generate all blocks on node0, generating to the other nodes' addresses in turn. This would avoid the sync_blocks() calls.

do any of the tests rely on the immature blocks becoming mature during the test? I'd hope not. If they don't, you could generate those immature blocks to a dummy address, and change this to:

self.nodes[0].generatetoaddress(25, <node0_address>) self.nodes[0].generatetoaddress(25, <node1_address>) self.nodes[0].generatetoaddress(25, <node2_address>) self.nodes[0].generatetoaddress(25, <node3_address>) self.nodes[0].generatetoaddress(99, <dummy_address>)

or:

for i in range(4): self.nodes[0].generatetoaddress(25, self.nodes[i].get_deterministic_priv_key().address()) self.nodes[0].generatetoaddress(99, <dummy_address>)

Done, I measured that it wouldn't make it faster, but at least the code is shorter

jnewbery · 2019-02-21T15:11:47Z

test/functional/wallet_txn_doublespend.py

+        # If the nodes are not all out of IBD, that can interfere with
+        # blockchain sync later in the test when nodes are connected, due to
+        # timing issues.
+        for n in self.nodes:


Suggestion: combine this with the for loop below.

fa2cdc9 test: Simplify create_cache (MarcoFalke) fa25210 qa: Fix wallet_txn_doublespend issue (MarcoFalke) 1111aec qa: Always refresh stale cache to be out of ibd (MarcoFalke) fab0d85 qa: Remove mocktime unless required (MarcoFalke) Pull request description: When starting a test, we are always in IBD because the timestamps on cached blocks are in the past. Usually, we solve that by generating a block at the beginning of the test. That is clumsy and might even lead to other problems such as bitcoin#15360 and bitcoin#14446 (comment) So fix that by getting rid of mocktime and always refreshing the last block of the cache when starting the test framework. Should fix bitcoin#14446 Tree-SHA512: 6af09800f9c86131349a103af617a54551f5f3f3260d38e14e3f30fdd3d91a0feb0100c56cbb12eae4aeac5571ae4b530b16345cbb831d2670237b53351a22c1

jnewbery · 2019-02-25T19:43:58Z

utACK fa2cdc9

Summary: * qa: Remove mocktime unless required * qa: Always refresh stale cache to be out of ibd * qa: Fix wallet_txn_doublespend issue * test: Simplify create_cache This is a backport of Core [[bitcoin/bitcoin#15419 | PR15419]] Test Plan: ninja all check-all Reviewers: #bitcoin_abc, jasonbcox Reviewed By: #bitcoin_abc, jasonbcox Differential Revision: https://reviews.bitcoinabc.org/D5984

fa2cdc9 test: Simplify create_cache (MarcoFalke) fa25210 qa: Fix wallet_txn_doublespend issue (MarcoFalke) 1111aec qa: Always refresh stale cache to be out of ibd (MarcoFalke) fab0d85 qa: Remove mocktime unless required (MarcoFalke) Pull request description: When starting a test, we are always in IBD because the timestamps on cached blocks are in the past. Usually, we solve that by generating a block at the beginning of the test. That is clumsy and might even lead to other problems such as bitcoin#15360 and bitcoin#14446 (comment) So fix that by getting rid of mocktime and always refreshing the last block of the cache when starting the test framework. Should fix bitcoin#14446 Tree-SHA512: 6af09800f9c86131349a103af617a54551f5f3f3260d38e14e3f30fdd3d91a0feb0100c56cbb12eae4aeac5571ae4b530b16345cbb831d2670237b53351a22c1

maflcko added the Tests label Feb 15, 2019

ken2812221 mentioned this pull request Feb 15, 2019

tests: Some issue about running functional tests on Windows #14446

Closed

5 tasks

maflcko force-pushed the Mf1902-mocktime branch 2 times, most recently from faba821 to fa05eef Compare February 15, 2019 14:58

promag reviewed Feb 18, 2019

View reviewed changes

maflcko force-pushed the Mf1902-mocktime branch 3 times, most recently from fa9fda9 to fa5bc93 Compare February 18, 2019 21:04

maflcko changed the title ~~qa: Always refresh rotten cache to be out of ibd~~ qa: Always refresh stale cache to be out of ibd Feb 19, 2019

qa: Remove mocktime unless required

fab0d85

maflcko force-pushed the Mf1902-mocktime branch 2 times, most recently from fa0c88c to faff8d6 Compare February 19, 2019 15:50

maflcko changed the title ~~qa: Always refresh stale cache to be out of ibd~~ qa: Always refresh cache to be out of ibd Feb 19, 2019

Sjors reviewed Feb 19, 2019

View reviewed changes

MarcoFalke added 2 commits February 19, 2019 14:22

qa: Always refresh stale cache to be out of ibd

1111aec

qa: Fix wallet_txn_doublespend issue

fa25210

maflcko force-pushed the Mf1902-mocktime branch from faff8d6 to fa25210 Compare February 19, 2019 19:22

jnewbery reviewed Feb 21, 2019

View reviewed changes

maflcko force-pushed the Mf1902-mocktime branch 3 times, most recently from fa68960 to 2550188 Compare February 25, 2019 16:17

test: Simplify create_cache

fa2cdc9

maflcko force-pushed the Mf1902-mocktime branch from 2550188 to fa2cdc9 Compare February 25, 2019 16:18

maflcko merged commit fa2cdc9 into bitcoin:master Feb 25, 2019

maflcko deleted the Mf1902-mocktime branch February 25, 2019 16:46

jnewbery mentioned this pull request Feb 26, 2019

test: Add .style.yapf #15479

Merged

dsaveliev mentioned this pull request Mar 6, 2019

Eliminate the IBD state in 'wallet_txn_doublespend.py' test dtr-org/unit-e#742

Merged

bitcoin locked as resolved and limited conversation to collaborators Dec 16, 2021

qa: Always refresh cache to be out of ibd #15419

qa: Always refresh cache to be out of ibd #15419

Uh oh!

Conversation

maflcko commented Feb 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Feb 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

promag left a comment

Choose a reason for hiding this comment

Uh oh!

promag left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jnewbery commented Feb 18, 2019

Uh oh!

sipa commented Feb 19, 2019

Uh oh!

maflcko commented Feb 19, 2019

Uh oh!

jnewbery commented Feb 19, 2019

Uh oh!

Sjors commented Feb 19, 2019

Uh oh!

maflcko commented Feb 19, 2019

Uh oh!

jnewbery commented Feb 19, 2019

Uh oh!

Sjors left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jnewbery commented Feb 19, 2019

Uh oh!

maflcko commented Feb 19, 2019

Uh oh!

jnewbery commented Feb 19, 2019

Uh oh!

maflcko commented Feb 19, 2019

Uh oh!

Sjors commented Feb 20, 2019

Uh oh!

jnewbery left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jnewbery Feb 21, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

maflcko commented Feb 15, 2019 •

edited

Loading

DrahtBot commented Feb 15, 2019 •

edited

Loading

jnewbery Feb 21, 2019 •

edited

Loading