fix abc-parkedchain timeouts
ClosedPublic
Actions

Authored by markblundeberg on Feb 14 2019, 04:14.

Details

Reviewers

deadalnix
jasonbcox

Group Reviewers

Restricted Project

Commits

rSTAGING011e6fe43a59: fix abc-parkedchain timeouts
rABC011e6fe43a59: fix abc-parkedchain timeouts

Summary

Lately on the Diff Testing we have seen random failures in this test.
By looking at logs we can see the following race condition was happening:

Node0 generates some new blocks.
Node1 requests & receives headers.
Node0 runs invalidateblock on some blocks.
Node1 requests the blocks corresponding to the full header list.
Node0 ignores requests of invalid blocks, per BlockRequestAllowed.
Node0 re-validates those blocks and continues on.
Test proceeds up to wait_for_tip(). However, Node1 is still waiting for blocks that will never come. Timeout after 60 seconds.

This should break the race by requiring node1 to be synced before any rewind commands are done.

(thanks to @florian for noticing this in the logs)

Test Plan

very hard to test this rare failure; I can't seem to reproduce it locally.

Diff Detail

Repository

rABC Bitcoin ABC

Lint

Lint Not Applicable

Unit

Tests Not Applicable

Event Timeline

markblundeberg created this revision.Feb 14 2019, 04:14

Herald added a reviewer: Restricted Project. · View Herald TranscriptFeb 14 2019, 04:14

Herald added a reviewer: deadalnix. · View Herald Transcript

Herald added a subscriber: schancel. · View Herald Transcript

Build Bitcoin-ABC / Diffs / Bitcoin-ABC Diff Testing started.

Example: https://build.bitcoinabc.org/viewLog.html?buildId=11443&buildTypeId=BitcoinABC_BitcoinAbcStaging&tab=artifacts

Check out the debug logs.

node0 generates 3d4e9cb5afdebb672a5c3e7fd21b1a6b04fec955d8bc43e0ea04d6d4d5950dc1 at height 230 -- note the test starts with both nodes at height 200.
node1 requests headers; it gets 3d4e9cb5afdebb672a5c3e7fd21b1a6b04fec955d8bc43e0ea04d6d4d5950dc1 in header list
node0 invalidates 3d4e9cb5afdebb672a5c3e7fd21b1a6b04fec955d8bc43e0ea04d6d4d5950dc1
node1 requests 3d4e9cb5afdebb672a5c3e7fd21b1a6b04fec955d8bc43e0ea04d6d4d5950dc1
node0 log entry: ignoring request from peer=0 for old block that isn't in the main chain
node0 re-validates 3d4e9cb5afdebb672a5c3e7fd21b1a6b04fec955d8bc43e0ea04d6d4d5950dc1
... test appears to continue until the test times out because we are waiting for node1 to reach the tip of a chain that includes 3d4e9cb5afdebb672a5c3e7fd21b1a6b04fec955d8bc43e0ea04d6d4d5950dc1

(block 1b703817f5809bf806aa67bd23c1a950d5c6be2c4df7fbc04f454f7fc1964329 is also never received, so there are two 'old block' messages)

In this case the race timing seems to be exacerbated by the fact that node1 spins up later than node0, so it has to get 30 blocks all at once. This increases the duration between the time when node1 requests headers to when it requests the block.

markblundeberg edited the summary of this revision. (Show Details)Feb 14 2019, 04:25

Harbormaster completed remote builds in B4984: Diff 7335.Feb 14 2019, 04:28

Build Bitcoin-ABC / Diffs / Bitcoin-ABC Diff Testing passed.

jasonbcox requested changes to this revision.Feb 14 2019, 04:59

jasonbcox added a subscriber: jasonbcox.

jasonbcox added inline comments.

test/functional/abc-parkedchain.py
149 ↗	(On Diff #7335)	Similar to this line, you should just use wait_for_tip instead of sync_blocks. I almost did something similar in the past: https://reviews.bitcoinabc.org/D2189?id=6335#inline-12547 Just move the definition of wait_for_tip to the top of the file.