test: feature_pruning fails with AssertionError (intermittent) #16537

Current master.

Excerpt:

 node0 2019-08-02T18:17:40.159357Z [http] Received a POST request for / from 127.0.0.1:41390 
 node0 2019-08-02T18:17:40.206391Z [httpworker.3] ThreadRPCServer method=submitblock user=__cookie__ 
 node0 2019-08-02T18:17:40.365855Z [httpworker.3] PeerLogicValidation::NewPoWValidBlock sending header-and-ids 6db3371c4f0ad084a24c512bb7a3c0de35280a5feb1037b6ba4ceae5bf579114 to peer=27 
 node0 2019-08-02T18:17:40.367280Z [httpworker.3] sending cmpctblock (950159 bytes) peer=27 
 node0 2019-08-02T18:17:40.381896Z [httpworker.3] PeerLogicValidation::NewPoWValidBlock sending header-and-ids 6db3371c4f0ad084a24c512bb7a3c0de35280a5feb1037b6ba4ceae5bf579114 to peer=28 
 node0 2019-08-02T18:17:40.383189Z [httpworker.3] sending cmpctblock (950159 bytes) peer=28 
 node0 2019-08-02T18:17:40.406853Z [httpworker.3]   - Load block from disk: 0.00ms [0.05s] 
 node0 2019-08-02T18:17:40.407052Z [httpworker.3]     - Sanity checks: 0.01ms [0.03s (0.01ms/blk)] 
 node0 2019-08-02T18:17:40.407149Z [httpworker.3]     - Fork checks: 0.11ms [0.19s (0.09ms/blk)] 
 node1 2019-08-02T18:17:40.417969Z [msghand] received: cmpctblock (950159 bytes) peer=14 
 node1 2019-08-02T18:17:40.437712Z [msghand] Initialized PartiallyDownloadedBlock for block 6db3371c4f0ad084a24c512bb7a3c0de35280a5feb1037b6ba4ceae5bf579114 using a cmpctblock of size 950159 
 node1 2019-08-02T18:17:40.437830Z [msghand] received: blocktxn (33 bytes) peer=14 
 node0 2019-08-02T18:17:40.461279Z [httpworker.3]       - Connect 1 transactions: 54.05ms (54.045ms/tx, 0.000ms/txin) [71.60s (35.98ms/blk)] 
 node0 2019-08-02T18:17:40.461408Z [httpworker.3]     - Verify 0 txins: 54.25ms (0.000ms/txin) [71.94s (36.15ms/blk)] 
 node0 2019-08-02T18:17:40.461652Z [httpworker.3]     - Index writing: 0.25ms [0.50s (0.25ms/blk)] 
 node0 2019-08-02T18:17:40.461701Z [httpworker.3]     - Callbacks: 0.05ms [0.10s (0.05ms/blk)] 
 node0 2019-08-02T18:17:40.461781Z [httpworker.3]   - Connect total: 54.98ms [73.14s (36.75ms/blk)] 
 node0 2019-08-02T18:17:40.461831Z [httpworker.3]   - Flush: 0.04ms [0.11s (0.06ms/blk)] 
 node0 2019-08-02T18:17:40.461903Z [httpworker.3]   - Writing chainstate: 0.08ms [0.16s (0.08ms/blk)] 
 node0 2019-08-02T18:17:40.463359Z [httpworker.3] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
 node0 2019-08-02T18:17:40.463950Z [httpworker.3] UpdateTip: new best=6db3371c4f0ad084a24c512bb7a3c0de35280a5feb1037b6ba4ceae5bf579114 height=1552 version=0x20000000 log2_work=11.600842 tx=1553 date='2019-08-02T18:19:52Z' progress=1.000000 cache=0.1MiB(650txo) 
 node0 2019-08-02T18:17:40.464006Z [httpworker.3]   - Connect postprocess: 2.10ms [3.91s (1.96ms/blk)] 
 node0 2019-08-02T18:17:40.464046Z [httpworker.3] - Connect block: 57.22ms [77.36s (38.88ms/blk)] 
 node0 2019-08-02T18:17:40.464129Z [httpworker.3] Checking mempool with 0 transactions and 0 inputs 
 test  2019-08-02T18:17:40.472000Z TestFramework (INFO): Usage should be below target: 560 
 node1 2019-08-02T18:17:40.486452Z [msghand] Successfully reconstructed block 6db3371c4f0ad084a24c512bb7a3c0de35280a5feb1037b6ba4ceae5bf579114 with 1 txn prefilled, 0 txn from mempool (incl at least 0 from extra pool) and 0 txn requested 
 node1 2019-08-02T18:17:40.492254Z [msghand] PeerLogicValidation::NewPoWValidBlock sending header-and-ids 6db3371c4f0ad084a24c512bb7a3c0de35280a5feb1037b6ba4ceae5bf579114 to peer=15 
 node1 2019-08-02T18:17:40.493497Z [msghand] sending cmpctblock (950159 bytes) peer=15 
 node1 2019-08-02T18:17:40.516284Z [msghand]   - Load block from disk: 0.01ms [0.01s] 
 node1 2019-08-02T18:17:40.516417Z [msghand]     - Sanity checks: 0.01ms [0.02s (0.01ms/blk)] 
 node1 2019-08-02T18:17:40.516502Z [msghand]     - Fork checks: 0.09ms [0.25s (0.11ms/blk)] 
 node1 2019-08-02T18:17:40.568948Z [msghand]       - Connect 1 transactions: 52.38ms (52.379ms/tx, 0.000ms/txin) [69.38s (29.65ms/blk)] 
 node1 2019-08-02T18:17:40.569060Z [msghand]     - Verify 0 txins: 52.55ms (0.000ms/txin) [69.83s (29.84ms/blk)] 
 node1 2019-08-02T18:17:40.569290Z [msghand]     - Index writing: 0.23ms [0.44s (0.19ms/blk)] 
 node1 2019-08-02T18:17:40.569332Z [msghand]     - Callbacks: 0.05ms [0.12s (0.05ms/blk)] 
 node1 2019-08-02T18:17:40.569409Z [msghand]   - Connect total: 53.17ms [70.93s (30.31ms/blk)] 
 node1 2019-08-02T18:17:40.569454Z [msghand]   - Flush: 0.04ms [0.10s (0.04ms/blk)] 
 node1 2019-08-02T18:17:40.569527Z [msghand]   - Writing chainstate: 0.07ms [0.14s (0.06ms/blk)] 
 node1 2019-08-02T18:17:40.570938Z [msghand] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
 node1 2019-08-02T18:17:40.571506Z [msghand] UpdateTip: new best=6db3371c4f0ad084a24c512bb7a3c0de35280a5feb1037b6ba4ceae5bf579114 height=1552 version=0x20000000 log2_work=11.600842 tx=1553 date='2019-08-02T18:19:52Z' progress=1.000000 cache=0.1MiB(650txo) 
 node1 2019-08-02T18:17:40.571560Z [msghand]   - Connect postprocess: 2.03ms [3.66s (1.57ms/blk)] 
 node1 2019-08-02T18:17:40.571599Z [msghand] - Connect block: 55.33ms [74.84s (31.98ms/blk)] 
 node1 2019-08-02T18:17:40.571675Z [msghand] Checking mempool with 0 transactions and 0 inputs 
 test  2019-08-02T18:17:43.227000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/root/workspace/bitcoin-core/test/functional/test_framework/test_framework.py", line 193, in main
                                       self.run_test()
                                     File "/root/workspace/bitcoin-core/test/functional/feature_pruning.py", line 396, in run_test
                                       self.reorg_test()  # (1033, )
                                     File "/root/workspace/bitcoin-core/test/functional/feature_pruning.py", line 210, in reorg_test
                                       assert_greater_than(550, usage)
                                     File "/root/workspace/bitcoin-core/test/functional/test_framework/util.py", line 44, in assert_greater_than
                                       raise AssertionError("%s <= %s" % (str(thing1), str(thing2)))
                                   AssertionError: 550 <= 560.1718864440918
 node2 2019-08-02T18:17:44.476610Z [msghand] Prune: UnlinkPrunedFiles deleted blk/rev (00004) 
 node2 2019-08-02T18:17:44.476787Z [msghand] Writing final batch of 0.00 MiB 
 node2 2019-08-02T18:17:44.477697Z [msghand] Committed 0 changed transaction outputs (out of 0) to coin database... 
 node2 2019-08-02T18:17:44.484856Z [msghand]   - Load block from disk: 0.01ms [0.04s] 
 node2 2019-08-02T18:17:44.485366Z [msghand]     - Sanity checks: 0.11ms [0.02s (0.01ms/blk)] 
 node2 2019-08-02T18:17:44.485479Z [msghand]     - Fork checks: 0.14ms [0.18s (0.10ms/blk)] 
 test  2019-08-02T18:17:44.522000Z TestFramework (DEBUG): Closing down network thread 
 node2 2019-08-02T18:17:44.544340Z [msghand]       - Connect 1 transactions: 58.78ms (58.779ms/tx, 0.000ms/txin) [70.18s (38.69ms/blk)] 
 node2 2019-08-02T18:17:44.544504Z [msghand]     - Verify 0 txins: 59.02ms (0.000ms/txin) [70.48s (38.86ms/blk)] 
 node2 2019-08-02T18:17:44.544743Z [msghand]     - Index writing: 0.24ms [0.45s (0.25ms/blk)] 
 node2 2019-08-02T18:17:44.544786Z [msghand]     - Callbacks: 0.05ms [0.09s (0.05ms/blk)] 
 node2 2019-08-02T18:17:44.544871Z [msghand]   - Connect total: 60.10ms [71.70s (39.52ms/blk)] 
 node2 2019-08-02T18:17:44.544915Z [msghand]   - Flush: 0.05ms [0.09s (0.05ms/blk)] 
 node2 2019-08-02T18:17:44.544985Z [msghand]   - Writing chainstate: 0.07ms [0.14s (0.08ms/blk)] 
 node2 2019-08-02T18:17:44.546402Z [msghand] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
 node2 2019-08-02T18:17:44.546973Z [msghand] UpdateTip: new best=3fa2e1b6704dc4c0ea7238313abe4242915ce18351455222a8510ad0fbefd19f height=1526 version=0x20000000 log2_work=11.576484 tx=1527 date='2019-08-02T18:19:26Z' progress=1.000000 cache=0.0MiB(0txo) 
 node2 2019-08-02T18:17:44.547032Z [msghand]   - Connect postprocess: 2.04ms [3.64s (2.01ms/blk)] 
 node2 2019-08-02T18:17:44.547072Z [msghand] - Connect block: 62.27ms [75.61s (41.68ms/blk)] 
 node2 2019-08-02T18:17:44.547154Z [msghand] Checking mempool with 0 transactions and 0 inputs 
 node2 2019-08-02T18:17:44.554409Z [msghand] received: cmpctblock (950159 bytes) peer=14 
 node2 2019-08-02T18:17:44.575317Z [msghand] sending ping (8 bytes) peer=14 
 node1 2019-08-02T18:17:44.575900Z [msghand] received: ping (8 bytes) peer=15 
 node2 2019-08-02T18:17:44.576024Z [msghand] received: cmpctblock (950159 bytes) peer=13 
 node1 2019-08-02T18:17:44.576117Z [msghand] sending pong (8 bytes) peer=15 
 test  2019-08-02T18:17:44.587000Z TestFramework (INFO): Stopping nodes 

Cannot confirm this issue on master (3a3d8b83571205b8329d4ee25537e3cc4397c3b8):

$ test/functional/feature_pruning.py 
2019-08-03T07:50:27.804000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_ga_fzjjn
2019-08-03T07:50:28.757000Z TestFramework (INFO): Warning! This test requires 4GB of disk space
2019-08-03T07:50:28.757000Z TestFramework (INFO): Mining a big blockchain of 995 blocks
2019-08-03T07:51:28.022000Z TestFramework (INFO): Check that we haven't started pruning yet because we're below PruneAfterHeight
2019-08-03T07:51:28.022000Z TestFramework (INFO): Success
2019-08-03T07:51:28.023000Z TestFramework (INFO): Though we're already using more than 550MiB, current usage: 592
2019-08-03T07:51:28.023000Z TestFramework (INFO): Mining 25 more blocks should cause the first block file to be pruned
2019-08-03T07:51:29.723000Z TestFramework (INFO): Success
2019-08-03T07:51:29.723000Z TestFramework (INFO): Usage should be below target: 480
2019-08-03T07:51:29.723000Z TestFramework (INFO): Check that we'll exceed disk space target if we have a very high stale block rate
2019-08-03T07:51:29.723000Z TestFramework (INFO): Mine 24 (stale) blocks on Node 1, followed by 25 (main chain) block reorg from Node 0, for 12 rounds
2019-08-03T07:52:08.381000Z TestFramework (INFO): Usage can be over target because of high stale rate: 512
2019-08-03T07:52:08.383000Z TestFramework (INFO): Check that we can survive a 288 block reorg still
2019-08-03T07:52:08.384000Z TestFramework (INFO): Current block height: 1320
2019-08-03T07:52:08.385000Z TestFramework (INFO): Invalidating block 1afeae767903575f2f4cfc3000e39d536493af4ea4ece9be5d439877e363e3f8 at height 1033
2019-08-03T07:52:09.223000Z TestFramework (INFO): New best height: 1032
2019-08-03T07:52:09.329000Z TestFramework (INFO): Generating new longer chain of 300 more blocks
2019-08-03T07:52:09.919000Z TestFramework (INFO): Reconnect nodes
2019-08-03T07:52:12.832000Z TestFramework (INFO): Verify height on node 2: 1332
2019-08-03T07:52:12.832000Z TestFramework (INFO): Usage possibly still high because of stale blocks in block files: 512
2019-08-03T07:52:12.832000Z TestFramework (INFO): Mine 220 more large blocks so we have requisite history
2019-08-03T07:52:27.698000Z TestFramework (INFO): Usage should be below target: 448
2019-08-03T07:52:27.698000Z TestFramework (INFO): Test that we can rerequest a block we previously pruned if needed for a reorg
2019-08-03T07:52:31.398000Z TestFramework (INFO): Will need to redownload block 1033
2019-08-03T07:52:32.023000Z TestFramework (INFO): Rewind node 0 to prev main chain to mine longer chain to trigger redownload. Blocks needed: 233
2019-08-03T07:52:36.547000Z TestFramework (INFO): Verify node 2 reorged back to the main chain, some blocks of which it had to redownload
2019-08-03T07:52:45.665000Z TestFramework (INFO): Test manual pruning with block indices
2019-08-03T07:52:48.359000Z TestFramework (INFO): Success
2019-08-03T07:52:48.359000Z TestFramework (INFO): Test manual pruning with timestamps
2019-08-03T07:52:50.599000Z TestFramework (INFO): Success
2019-08-03T07:52:50.599000Z TestFramework (INFO): Test wallet re-scan
2019-08-03T07:52:50.599000Z TestFramework (INFO): Stop and start pruning node to trigger wallet rescan
2019-08-03T07:52:51.511000Z TestFramework (INFO): Success
2019-08-03T07:52:51.511000Z TestFramework (INFO): Syncing node 5 to test wallet
2019-08-03T07:53:17.623000Z TestFramework (INFO): Success
2019-08-03T07:53:17.623000Z TestFramework (INFO): Done
2019-08-03T07:53:17.674000Z TestFramework (INFO): Stopping nodes
2019-08-03T07:53:17.940000Z TestFramework (INFO): Cleaning up /tmp/bitcoin_func_test_ga_fzjjn on exit
2019-08-03T07:53:17.940000Z TestFramework (INFO): Tests successful

@MarcoFalke Could you provide steps to reliably reproduce this issue?

It is a race, so not reproducible unless you modify the source code to add sleeps.