qa: failure in p2p_segwit #11696

Saw this the first time and keeping track of it by filing an issue.

File "p2p-segwit.py", line 1006, in test_block_relay
    assert_equal(wit_block.serialize(True), hex_str_to_bytes(rpc_block))

Commit: 927a1d7d088e52aa079682e1d4f514222c0a2069 Job: https://travis-ci.org/bitcoin/bitcoin/jobs/302552842

The byte strings copied from the log:

AssertionError: not(
b'\x04\x00\x00\x00\xfb\xc8t_\xec\xa0\xd3\x17}X\x8c$\xe1\x857\t\x14\xbd\xe0\x97B\xed\xb9R\xb5\x9f\xfb\xd5n\xbc\x1c!\xe9\x80\xa1M7\xd7\xba!\xd5\x03\x9bd\xa9s\xb3\xb9\xf1\xd2b\x8d\xa1\xf4\xa81\xa6cP\xb5\x02:\xc9\x94\xf4t\x0cZ\xff\xff\x7f \x00\x00\x00\x00\x01\x01\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\xff\xff\xff\x03\x02\xc3\x01\xff\xff\xff\xff\x02@\xbe@%\x00\x00\x00\x00\x01Q\x00\x00\x00\x00\x00\x00\x00\x00&j$\xaa!\xa9\xed\xe2\xf6\x1c?q\xd1\xde\xfd?\xa9\x99\xdf\xa3iSu\\i\x06\x89y\x99b\xb4\x8b\xeb\xd86\x97N\x8c\xf9\x00\x00\x00\x00' == 
b'\x04\x00\x00\x00\xfb\xc8t_\xec\xa0\xd3\x17}X\x8c$\xe1\x857\t\x14\xbd\xe0\x97B\xed\xb9R\xb5\x9f\xfb\xd5n\xbc\x1c!\xe9\x80\xa1M7\xd7\xba!\xd5\x03\x9bd\xa9s\xb3\xb9\xf1\xd2b\x8d\xa1\xf4\xa81\xa6cP\xb5\x02:\xc9\x94\xf4t\x0cZ\xff\xff\x7f \x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\xff\xff\xff\x03\x02\xc3\x01\xff\xff\xff\xff\x02@\xbe@%\x00\x00\x00\x00\x01Q\x00\x00\x00\x00\x00\x00\x00\x00&j$\xaa!\xa9\xed\xe2\xf6\x1c?q\xd1\xde\xfd?\xa9\x99\xdf\xa3iSu\\i\x06\x89y\x99b\xb4\x8b\xeb\xd86\x97N\x8c\xf9\x01 \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')

Locally:

p2p_segwit.py failed, Duration: 18 s

stdout:
2018-05-13T15:07:59.097000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_test_runner_20180513_110737/p2p_segwit_245
2018-05-13T15:07:59.989000Z TestFramework (INFO): Starting tests before segwit lock in:
2018-05-13T15:07:59.989000Z TestFramework (INFO): Verifying NODE_WITNESS service bit
2018-05-13T15:07:59.989000Z TestFramework (INFO): Testing non-witness transaction
2018-05-13T15:08:01.065000Z TestFramework (INFO): Testing behavior of unnecessary witnesses
2018-05-13T15:08:01.240000Z TestFramework (INFO): Testing that v0 witness program outputs aren't spendable before activation
2018-05-13T15:08:01.309000Z TestFramework (INFO): Testing block relay
2018-05-13T15:08:02.933000Z TestFramework (INFO): Testing getblocktemplate setting of segwit versionbit (before lockin)
2018-05-13T15:08:04.164000Z TestFramework (INFO): Testing behavior post lockin, pre-activation
2018-05-13T15:08:05.402000Z TestFramework (INFO): Testing behavior of unnecessary witnesses
2018-05-13T15:08:05.522000Z TestFramework (INFO): Testing relay of witness transactions
2018-05-13T15:08:07.602000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: (['        test_function = lambda: self.last_message.get("getdata")\n'], 367)
2018-05-13T15:08:07.776000Z TestFramework (INFO): Testing block relay
2018-05-13T15:08:09.198000Z TestFramework (INFO): Testing standardness of v0 outputs (before activation)
2018-05-13T15:08:09.452000Z TestFramework (INFO): Testing behavior after segwit activation
2018-05-13T15:08:11.435000Z TestFramework (INFO): Testing P2SH witness transactions
2018-05-13T15:08:11.742000Z TestFramework (INFO): Testing witness commitments
2018-05-13T15:08:12.041000Z TestFramework (INFO): Testing witness block malleability
2018-05-13T15:08:12.544000Z TestFramework (INFO): Testing witness block size limit
2018-05-13T15:08:14.882000Z TestFramework (INFO): Testing extra witness data in tx
2018-05-13T15:08:14.966000Z TestFramework (INFO): Testing maximum witness push size
2018-05-13T15:08:15.076000Z TestFramework (INFO): Testing maximum witness program length
2018-05-13T15:08:15.187000Z TestFramework (INFO): Testing witness input length
2018-05-13T15:08:15.489000Z TestFramework (INFO): Testing block relay
2018-05-13T15:08:15.911000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/bitcoin/test/functional/test_framework/test_framework.py", line 152, in main
    self.run_test()
  File "/bitcoin/test/functional/p2p_segwit.py", line 2029, in run_test
    self.test_block_relay(segwit_activated=True)
  File "/bitcoin/test/functional/p2p_segwit.py", line 1047, in test_block_relay
    assert_equal(wit_block.serialize(True), hex_str_to_bytes(rpc_block))
  File "/bitcoin/test/functional/test_framework/util.py", line 39, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(b'\x04\x00\x00\x00$\n\xbc\x19\xf6\xaf\x00\xf4\x9a\xdf\x1eT\x9b\r{)}u\x8bq1Y\xcf\x16\xbf\xf2Y\x16\x82|\x84u\xe9\x80\xa1M7\xd7\xba!\xd5\x03\x9bd\xa9s\xb3\xb9\xf1\xd2b\x8d\xa1\xf4\xa81\xa6cP\xb5\x02:\xc9\x94\x1bU\xf8Z\xff\xff\x7f \x00\x00\x00\x00\x01\x01\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\xff\xff\xff\x03\x02\xc3\x01\xff\xff\xff\xff\x02@\xbe@%\x00\x00\x00\x00\x01Q\x00\x00\x00\x00\x00\x00\x00\x00&j$\xaa!\xa9\xed\xe2\xf6\x1c?q\xd1\xde\xfd?\xa9\x99\xdf\xa3iSu\\i\x06\x89y\x99b\xb4\x8b\xeb\xd86\x97N\x8c\xf9\x00\x00\x00\x00' == b'\x04\x00\x00\x00$\n\xbc\x19\xf6\xaf\x00\xf4\x9a\xdf\x1eT\x9b\r{)}u\x8bq1Y\xcf\x16\xbf\xf2Y\x16\x82|\x84u\xe9\x80\xa1M7\xd7\xba!\xd5\x03\x9bd\xa9s\xb3\xb9\xf1\xd2b\x8d\xa1\xf4\xa81\xa6cP\xb5\x02:\xc9\x94\x1bU\xf8Z\xff\xff\x7f \x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\xff\xff\xff\x03\x02\xc3\x01\xff\xff\xff\xff\x02@\xbe@%\x00\x00\x00\x00\x01Q\x00\x00\x00\x00\x00\x00\x00\x00&j$\xaa!\xa9\xed\xe2\xf6\x1c?q\xd1\xde\xfd?\xa9\x99\xdf\xa3iSu\\i\x06\x89y\x99b\xb4\x8b\xeb\xd86\x97N\x8c\xf9\x01 \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')
2018-05-13T15:08:15.912000Z TestFramework (INFO): Stopping nodes
2018-05-13T15:08:16.169000Z TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_test_runner_20180513_110737/p2p_segwit_245
2018-05-13T15:08:16.169000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/bitcoin_test_runner_20180513_110737/p2p_segwit_245/test_framework.log

I plan to tidy up p2p_segwit.py and feature_segwit.py after #12360 has been merged.

#13467 may make p2p_segwit.py failures easier to debug.

Another one:

https://ci.appveyor.com/project/DrahtBot/bitcoin/builds/31079510#L4118

                                   File "C:\projects\bitcoin/test/functional/p2p_segwit.py", line 422, in test_block_relay
                                       assert_equal(wit_block.serialize(), hex_str_to_bytes(rpc_block))
                                     File "C:\projects\bitcoin\test\functional\test_framework\util.py", line 46, in assert_equal
                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
                                   AssertionError: not(b"\x04\x00\x00\x00\xeb\x97\xc4\xa9\x0f2FS\xef\xde5\xe8N\x83u/\xaa?\xec\x88\xb9\xf2\x0eh\xea\x9bu\xb6\xa7dHx\xfe\xae\xb1K\xa5,\x94\x96:\xdcP b\xc1\xd4N\xfe\xe8a\xd8\x14\x10\x89\xd1'\xc4\x10?\xb8\xf3\xa1\xb1\xfd\xedV^\xff\xff\x7f \x00\x00\x00\x00\x01\x01\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\xff\xff\xff\x03\x02\x8b\x00\xff\xff\xff\xff\x02\x00\xf2\x05*\x01\x00\x00\x00\x01Q\x00\x00\x00\x00\x00\x00\x00\x00&j$\xaa!\xa9\xed\xe2\xf6\x1c?q\xd1\xde\xfd?\xa9\x99\xdf\xa3iSu\\i\x06\x89y\x99b\xb4\x8b\xeb\xd86\x97N\x8c\xf9\x00\x00\x00\x00" == b"\x04\x00\x00\x00\xeb\x97\xc4\xa9\x0f2FS\xef\xde5\xe8N\x83u/\xaa?\xec\x88\xb9\xf2\x0eh\xea\x9bu\xb6\xa7dHx\xfe\xae\xb1K\xa5,\x94\x96:\xdcP b\xc1\xd4N\xfe\xe8a\xd8\x14\x10\x89\xd1'\xc4\x10?\xb8\xf3\xa1\xb1\xfd\xedV^\xff\xff\x7f \x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\xff\xff\xff\x03\x02\x8b\x00\xff\xff\xff\xff\x02\x00\xf2\x05*\x01\x00\x00\x00\x01Q\x00\x00\x00\x00\x00\x00\x00\x00&j$\xaa!\xa9\xed\xe2\xf6\x1c?q\xd1\xde\xfd?\xa9\x99\xdf\xa3iSu\\i\x06\x89y\x99b\xb4\x8b\xeb\xd86\x97N\x8c\xf9\x01 \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00")

I think I figured it out. Looks like a bug in the test.

https://github.com/bitcoin/bitcoin/blob/324a6dfeafcbee8d92231d23f15064edf12715b4/test/functional/p2p_segwit.py#L419-L424

Here, we're requesting the non-witness version of a block by sending a getdata message, and then the witness version of that block. However, the way we request a block over the p2p connection is not robust to their being a witness-stripped version of the block in the receive buffer already:

https://github.com/bitcoin/bitcoin/blob/324a6dfeafcbee8d92231d23f15064edf12715b4/test/functional/test_framework/mininode.py#L371-L376

This function wait_for_block() is used by the p2p_segwit test, and all it does to determine whether the new block has come in is check whether the last thing in the buffer has the right block hash -- but this will be the case as soon as the function is invoked, because we don't clear the witness-stripped version of the block out of the buffer. Thus if the block takes any amount of time to arrive it's possible this function could return too early and we'll end up storing the witness-stripped block as the witness-version of the block, causing test failure -- I think.

Just looked this over with @marcofalke offline -- my explanation above is wrong, because we do clear the last block message in a helper function (request_block) that is invoking wait_for_block:

https://github.com/bitcoin/bitcoin/blob/1615043935ef9c185eb1dc5d2365d0460424bc7b/test/functional/p2p_segwit.py#L178-L183

However, there is a race condition due to an extra getdata request that happens in the mininode thread, because we don't hold the mininode lock in request_block. Getting rid of the extra getdata request in mininode should just fix this:

https://github.com/bitcoin/bitcoin/blob/1615043935ef9c185eb1dc5d2365d0460424bc7b/test/functional/test_framework/mininode.py#L335-L341