Intermittent failure in p2p_sendheaders.py #12453

2018-02-16 16:58:36.053000 TestFramework (INFO): Part 3: headers announcements can stop after large reorg, and resume after headers/inv from peer...
2018-02-16 16:58:36.383000 TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 125, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/p2p_sendheaders.py", line 252, in run_test
    self.test_nonnull_locators(test_node, inv_node)
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/p2p_sendheaders.py", line 387, in test_nonnull_locators
    test_node.check_last_announcement(headers=new_block_hashes)
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/p2p_sendheaders.py", line 196, in check_last_announcement
    assert_equal(compare_headers, headers)
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/util.py", line 38, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not([21996415391081472062925727093529950876648340163913973761807899188192373614365, 41087947805771153884720332894251939979522257909888350875092853482798204675635] == [16237156767898240983525953690400156058678883005511936018860737579404778220035, 52699452485172000627859704077175013870302840830899826234420564427296397739460, 8519428926351639140311625787007920542736574897071276305831407777234052406367, 57324758378539415772482471735703168948565957536613087108978545814103544260628, 17741061529019103742087627933030541919852753851779831896193550282518560975078, 31950561969150049741325853992819463170317169225272047858397904578844384461849, 21996415391081472062925727093529950876648340163913973761807899188192373614365, 41087947805771153884720332894251939979522257909888350875092853482798204675635])
2018-02-16 16:58:36.384000 TestFramework (INFO): Stopping nodes

Full log: https://travis-ci.org/bitcoin/bitcoin/jobs/342424828

@jnewbery The test uses some for loops, which make it extremely hard to deduce where the test failed.

I'd suggest adding log statements within the for loops to have "hard sync points" in the combined debug log. Alternatively the for loop (https://github.com/bitcoin/bitcoin/blob/cead84b72d27517338ac3c49eaaed4db07352f41/test/functional/p2p_sendheaders.py#L382) could be split up into two function calls, passing j as the argument.

Yes, logging could be improved here (simplest would be to just add log statements into the for loops). More radically, the test could be refactored to make each of the different test parts a separate method, and have logging each time those methods are entered.

In this case, it's not too difficult to track down which iteration we're in, by looking back to the previous log message ("Part 3: headers announcements can stop after large reorg, and resume after headers/inv from peer...") and then following the test logic downwards. I can see that we're in the first iteration of the for loop, and we're failing because check_last_announcement() on line 387 expects all 8 of the new headers to be announced in a single headers message. In the logs, I see that the node is actually announcing the headers in one headers message with 6 headers, and a second headers message with 2 headers:

node0 2018-02-16 16:58:36.332323 SendMessages: 6 headers, range (23e5e7b1881996f8d6314f6e686bea8a2f370a79ec2b7bee950b18d88aa32a03, 46a36091bd29305f54fed32c0ef0a58e220efe4d875ec41180d42c149c328419), to peer=3 
...
 node0 2018-02-16 16:58:36.334079 SendMessages: 2 headers, range (30a187a89de33c170b4c2c30f315c72d20f81061d2aeb022b63f08c02383a71d, 5ad6f44f33f1527d9ec7d711209698135aadff73e786052175f9460b73b56633), to peer=3

I think it's perfectly legal for the node to send the new headers across multiple P2P messages, so we need to update check_last_announcement() to be tolerant of this. I expect we only hit this on travis due to timing windows.

Only thing left to do is:

I think it's perfectly legal for the node to send the new headers across multiple P2P messages, so we need to update check_last_announcement() to be tolerant of this. I expect we only hit this on travis due to timing windows.

I think logging could still be improved as well. #12849 doesn't seem like much of an improvement.

@jnewbery This can be closed, right?

The intermittent failures are fixed and the debug log statements were added