p2p-compactblocks.py fails randomly #8842

It seems p2p-compactblocks.py fails randomly

From: https://travis-ci.org/bitcoin/bitcoin/jobs/163788152 from #8841 The PR is trivial and totally unrelated to compact block

p2p-compactblocks.py:
Initializing test directory /tmp/test3yd_2q3h/2
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
MiniNode: Connecting to Bitcoin Node IP # 127.0.0.1:11016
Testing SENDCMPCT p2p message... 
Testing compactblock headers and shortIDs are correct...
Assertion failed: 
Stopping nodes
Not cleaning up dir /tmp/test3yd_2q3h/2
Failed
stderr:
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 151, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/../qa/rpc-tests/p2p-compactblocks.py", line 614, in run_test
    self.test_compactblock_construction()
  File "/home/travis/build/bitcoin/bitcoin/build/../qa/rpc-tests/p2p-compactblocks.py", line 264, in test_compactblock_construction
    assert(self.test_node.last_cmpctblock is not None)
Pass: False, Duration: 7 s

Thanks for the issue! I saw this failure earlier at least twice (only on travis, though)

Oops, I'll take a look...

Going to reopen this based on https://travis-ci.org/bitcoin/bitcoin/jobs/164463351

Ugh, I will take another look, thanks for noticing.

Ok I think I see what I did wrong in #8854 -- syncing with a ping doesn't ensure that all block announcements have made it to us, just that any that have been announced have been processed.

I'm working on a new fix (my idea is to replace that sync_with_ping() with logic to wait until the tip has been announced), but I'm having trouble reproducing the problem.

Please let me know if this is still an issue.

@sdaftuar - p2p-compactblocks just failed in a travis build for me: https://travis-ci.org/bitcoin/bitcoin/builds/170131004 . The next build (which was just a squash of the same commits) succeeded: https://travis-ci.org/bitcoin/bitcoin/builds/170143716 , so it appears there's still an intermittent problem with the compact blocks testcase. Sadly there doesn't appear to be much logging in travis and I can't reproduce this locally.

Those travis builds were from a PR from this branch: https://github.com/HackerResidency/bitcoin/blob/add-p2sh-segwit-options-to-bitcoin-tx/qa/rpc-tests/p2p-compactblocks.py , which includes #8882 .

Looked into the failure, but so far couldn't find a problem in the test setup that would cause it.

The failure happened in line 138 of the sync_blocks util function when the two test nodes failed to sync after 60 seconds. The place where the failing sync_blocks was called was line 809 of run_test after segwit was activated on node 1. Node 1 should have added more blocks than node 0 at that point, so some kind of failure must have happened to cause node 0 not to receive (or accept) the new blocks from node 1, and the sync_block function to time out.

Since I don't have any good theories on what would cause node 0 not to sync with node 1, I'm currently running the test in a loop to try to reproduce the problem.

I added some debug prints and made the following change to avoid a different (unrelated) intermittent test failure:

--- a/qa/rpc-tests/p2p-compactblocks.py
+++ b/qa/rpc-tests/p2p-compactblocks.py
@@ -300,8 +300,8 @@ class CompactBlocksTest(BitcoinTestFramework):
             assert(segwit_tx_generated) # check that our test is not broken

         # Wait until we've seen the block announcement for the resulting tip
-        tip = int(self.nodes[0].getbestblockhash(), 16)
-        assert(self.test_node.wait_for_block_announcement(tip))
+        tip = int(node.getbestblockhash(), 16)
+        assert(test_node.wait_for_block_announcement(tip))

         # Now mine a block, and look at the resulting compact block.
         test_node.clear_block_announcement()

Update: running the test overnight on my workstation showed the sync_blocks call returning true after 3 loop iterations in 1060 out of 1089 runs, and returning true after 2 loop iterations in the other 29 runs. It never got anywhere close to the 60 iterations that would have been required to cause the timeout.

This issue should be closed now that #9058 is merged.

Yes, let's be optimistic and close it :)