Rare sendheaders.py failure #8096

From here: #8090 (comment)

More specifically, we have one travis failure (https://travis-ci.org/bitcoin/bitcoin/jobs/132557240) in sendheaders.py that looks like this:

sendheaders.py:
Initializing test directory /tmp/test8bijuqpx
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
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:11072
MiniNode: Connecting to Bitcoin Node IP # 127.0.0.1:11072
Part 1: headers don't start before sendheaders message...
Part 1: success!
Part 2: announce blocks with headers after sendheaders message...
Part 2: success!
Part 3: headers announcements can stop after large reorg, and resume after headers/inv from peer...
Unexpected exception caught during testing: ConnectionResetError(104, 'Connection reset by peer')
Stopping nodes
WARN: Unable to stop node: CannotSendRequest('Request-sent',)
Cleaning up
Failed
stderr:
 bitcoind: main.cpp:2807: void PruneBlockIndexCandidates(): Assertion `!setBlockIndexCandidates.empty()' failed.
  File "/home/travis/build/bitcoin/bitcoin/bitcoin-x86_64-unknown-linux-gnu/qa/rpc-tests/test_framework/test_framework.py", line 142, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/bitcoin-x86_64-unknown-linux-gnu/qa/rpc-tests/sendheaders.py", line 372, in run_test
    new_block_hashes = self.mine_reorg(length=7)
  File "/home/travis/build/bitcoin/bitcoin/bitcoin-x86_64-unknown-linux-gnu/qa/rpc-tests/sendheaders.py", line 241, in mine_reorg
    all_hashes = self.nodes[1].generate(length+1) # Must be longer than the orig chain
  File "/home/travis/build/bitcoin/bitcoin/bitcoin-x86_64-unknown-linux-gnu/qa/rpc-tests/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/home/travis/build/bitcoin/bitcoin/bitcoin-x86_64-unknown-linux-gnu/qa/rpc-tests/test_framework/authproxy.py", line 137, in __call__
    response = self._request('POST', self.__url.path, postdata)
  File "/home/travis/build/bitcoin/bitcoin/bitcoin-x86_64-unknown-linux-gnu/qa/rpc-tests/test_framework/authproxy.py", line 119, in _request
    return self._get_response()
  File "/home/travis/build/bitcoin/bitcoin/bitcoin-x86_64-unknown-linux-gnu/qa/rpc-tests/test_framework/authproxy.py", line 152, in _get_response
    http_response = self.__conn.getresponse()
  File "/usr/lib/python3.4/http/client.py", line 1147, in getresponse
    response.begin()
  File "/usr/lib/python3.4/http/client.py", line 351, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.4/http/client.py", line 313, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.4/socket.py", line 371, in readinto
    return self._sock.recv_into(b)
Pass: False, Duration: 16 s

At the moment I have no idea what could cause this; my first guess is something funny with invalidateblock that hopefully would never occur in the wild, but this needs to be tracked down. So far I've been unable to reproduce.

Thanks for reporting, I was not able to reproduce either.

I'm also not able to reproduce this, but can reproduce this very often (0.1 probability):

Initializing test directory /var/folders/65/fn0h49r55k7779vg1b_h461r0000gn/T/testeqexi0jw
Unexpected exception caught during testing: timeout('timed out',)
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/test_framework.py", line 140, in main
    self.setup_network()
  File "./sendheaders.py", line 218, in setup_network
    self.nodes = start_nodes(self.num_nodes, self.options.tmpdir, [["-debug", "-logtimemicros=1"]]*2)
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/util.py", line 323, in start_nodes
    rpcs.append(start_node(i, dirname, extra_args[i], rpchost, binary=binary[i]))
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/util.py", line 304, in start_node
    wait_for_bitcoind_start(bitcoind_processes[i], url, i)
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/util.py", line 177, in wait_for_bitcoind_start
    blocks = rpc.getblockcount()
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/authproxy.py", line 137, in __call__
    response = self._request('POST', self.__url.path, postdata)
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/authproxy.py", line 118, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/http/client.py", line 1083, in request
    self._send_request(method, url, body, headers)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/http/client.py", line 1128, in _send_request
    self.endheaders(body)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/http/client.py", line 1079, in endheaders
    self._send_output(message_body)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/http/client.py", line 911, in _send_output
    self.send(msg)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/http/client.py", line 854, in send
    self.connect()
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/http/client.py", line 826, in connect
    (self.host,self.port), self.timeout, self.source_address)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/socket.py", line 711, in create_connection
    raise err
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/socket.py", line 702, in create_connection
    sock.connect(sa)
Stopping nodes
Traceback (most recent call last):
  File "./sendheaders.py", line 518, in <module>
    SendHeadersTest().main()
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/test_framework.py", line 164, in main
    wait_bitcoinds()
  File "/private/tmp/bitcoin-master/qa/rpc-tests/test_framework/util.py", line 355, in wait_bitcoinds
    bitcoind.wait(timeout=BITCOIND_PROC_WAIT_TIMEOUT)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/subprocess.py", line 1643, in wait
    raise TimeoutExpired(self.args, timeout)
subprocess.TimeoutExpired: Command '['bitcoind', '-datadir=/var/folders/65/fn0h49r55k7779vg1b_h461r0000gn/T/testeqexi0jw/node1', '-server', '-keypool=1', '-discover=0', '-rest', '-mocktime=0', '-debug', '-logtimemicros=1']' timed out after 60 seconds

Was triggered in travis in #9246 (which has no code changes). Fails at a different stage than the ones above so may be a different issue.

sendheaders.py:
Initializing test directory /tmp/testmyq6oa3l/319
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC successfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC successfully started
MiniNode: Connecting to Bitcoin Node IP # 127.0.0.1:13552
MiniNode: Connecting to Bitcoin Node IP # 127.0.0.1:13552
Part 1: headers don't start before sendheaders message...
Assertion failed: False != True
Stopping nodes
Not cleaning up dir /tmp/testmyq6oa3l/319
Failed

stderr:
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 145, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/../qa/rpc-tests/sendheaders.py", line 291, in run_test
    assert_equal(inv_node.check_last_announcement(inv=[tip]), True)
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/util.py", line 529, in assert_equal
    raise AssertionError("%s != %s"%(str(thing1),str(thing2)))
Pass: False, Duration: 4 s

@laanwj, is there a link to the failing travis run? The only run I see related to #9246 in the last 14 days at https://travis-ci.org/bitcoin/bitcoin/pull_requests seems to have finished successfully.

I just tried running sendheaders.py myself in a loop on travis. It ran 328 times with no failures before timing out: https://travis-ci.org/ryanofsky/bitcoin/builds/180127519

The travis link was invalidated when I restarted the build.

No follow ups in a year. Closing.