Seemingly fix walletbackup.py failure #8051

sipa commented at 2:52 AM on May 13, 2016: member

Looks like it fixes #8045.

I cannot explain the failure (it happens 100% reproducibly for me, with a clean cache and no other bitcoind running, even when running outside of rpc-tests.py):

$ ./walletbackup.py 
INFO: Initializing test directory /tmp/testnfwna8uq
INFO: Generating initial blockchain
INFO: Creating transactions
INFO: Backing up
INFO: More transactions
INFO: Restoring using wallet.dat
INFO: Re-starting nodes
INFO: Restoring using dumped wallet
Unexpected exception caught during testing: BrokenPipeError(32, 'Broken pipe')
  File "/home/pw/git/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 138, in main
    self.run_test()
  File "./walletbackup.py", line 193, in run_test
    sync_blocks(self.nodes)
  File "/home/pw/git/bitcoin/qa/rpc-tests/test_framework/util.py", line 127, in sync_blocks
    counts = [ x.getblockcount() for x in rpc_connections ]
  File "/home/pw/git/bitcoin/qa/rpc-tests/test_framework/util.py", line 127, in <listcomp>
    counts = [ x.getblockcount() for x in rpc_connections ]
  File "/home/pw/git/bitcoin/qa/rpc-tests/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/home/pw/git/bitcoin/qa/rpc-tests/test_framework/authproxy.py", line 137, in __call__
    response = self._request('POST', self.__url.path, postdata)
  File "/home/pw/git/bitcoin/qa/rpc-tests/test_framework/authproxy.py", line 118, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/usr/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/usr/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python3.5/http/client.py", line 936, in _send_output
    self.send(message_body)
  File "/usr/lib/python3.5/http/client.py", line 908, in send
    self.sock.sendall(data)
Stopping nodes
WARN: Unable to stop node: CannotSendRequest('Request-sent',)

I also can't explain why Travis doesn't have this problem. I certainly can't explain why this patch fixes it or even remotely has anything to do with the observed problem, but it fixes it 100% reproducibly.

sipa renamed this:
~~Fix walletbackup.py failure~~
Seemingly fix walletbackup.py failure
on May 13, 2016

sipa commented at 3:28 AM on May 13, 2016: member

Sense, this makes none: replacing the sync_blocks call with a sleep does not fix it (even when the sleep is longer than how long the sync takes).

jonasschnelli added the label Tests on May 13, 2016

MarcoFalke commented at 12:13 PM on May 13, 2016: member

Note that #8045 fails due to Error: Unable to bind to 0.0.0.0:11280 on this computer. Bitcoin Core is probably already running. in the network setup phase. Your exception seems unrelated to #8045 .

kazcw referenced this in commit 3b5310c122 on May 13, 2016

kazcw referenced this in commit 53bcca971b on May 13, 2016

pstratem commented at 11:40 PM on May 14, 2016: contributor

@MarcoFalke I think the unable to bind is just because i failed to kill the bitcoind from a previous test

sipa force-pushed on May 15, 2016

sipa commented at 1:58 AM on May 15, 2016: member

Switched to @sdaftuar's solution

MarcoFalke added the label RPC/REST/ZMQ on May 15, 2016

MarcoFalke removed the label RPC/REST/ZMQ on May 15, 2016

in qa/rpc-tests/walletbackup.py:None in e7a7f8f9b1 outdated

  47 | @@ -48,8 +48,9 @@ def setup_chain(self):
  48 |      # This mirrors how the network was setup in the bash test
  49 |      def setup_network(self, split=False):
  50 |          # nodes 1, 2,3 are spenders, let's give them a keypool=100
  51 | -        extra_args = [["-keypool=100"], ["-keypool=100"], ["-keypool=100"], []]
  52 | -        self.nodes = start_nodes(4, self.options.tmpdir, extra_args)
  53 | +        extra_args = [["-keypool=100", "-rpcservertimeout=90"], ["-keypool=100"], ["-keypool=100"], []]

MarcoFalke commented at 8:12 AM on May 15, 2016:

-rpcservertimeout=90 is now set twice

sipa commented at 3:19 AM on May 17, 2016:

Fixed.

sipa force-pushed on May 17, 2016

laanwj commented at 9:15 AM on May 18, 2016: member

I don't understand why a server timeout appears to solve this.

What the server timeout does (or is supposed to do, at least) is time out client sessions that are not making a request. They are in the state either before sending a request (or between request or keep-alive), or pausing too long during sending a request (slowloris).

The server should never time out while it is processing a request, no matter how long it takes. If that does happen, that is really really bad. This logic is unfortunately implemented in libevent so not easily accessible to us either.

What is your version of libevent?

laanwj commented at 9:20 AM on May 18, 2016: member

What might happen is that the client hasn't sent a request for a while to the server and thus the server closes the keepalive connection. Python's http doesn't detect this properly and raises an error. I vaguely remember issues with this before. E.g. see #6695, espeically ddf98d1d84343f2db0502a85628ef80f2ec57dbd.

Python's httplib does not graciously handle disconnections from the http server, resulting in BadStatusLine errors.
See https://bugs.python.org/issue3566 "httplib persistent connections violate MUST in RFC2616 sec 8.1.4."

However according to this is supposed to be fixed in Python 3.5. But it looks like you're using that. I'm not sure how well we cope with Python 3.5's solution though. Reverting commit ddf98d1d84343f2db0502a85628ef80f2ec57dbd then testing with Python 3.5 should be interesting.

laanwj commented at 9:32 AM on May 18, 2016: member

Ahh so now we get a BrokenPipeError(32, 'Broken pipe') (or CannotSendRequest ? ). I think that's the new Python 3.5 behavior.

I think we should catch that and repeat the request with a new connection if we do, analogous to the except httplib.BadStatusLine as e: handling in https://github.com/bitcoin/bitcoin/commit/ddf98d1d84343f2db0502a85628ef80f2ec57dbd.

arowser commented at 8:43 AM on May 25, 2016: contributor

Can one of the admins verify this patch?

Fix walletbackup.py failure in Python 3.5+ 4cad179b87

sipa force-pushed on Jun 2, 2016

sipa commented at 4:36 PM on June 2, 2016: member

@laanwj Thanks, that fixes it.

Rebased and updated to retry on BrokenPipeError as well as BadStatusLine.

MarcoFalke commented at 4:58 PM on June 2, 2016: member

Also, would be interesting to know why on some systems importwallet takes such a long time.

MarcoFalke commented at 5:09 PM on June 2, 2016: member

To be more clear: If there is an issue with importwallet taking a long time, it may be worth looking into that as well. (importwallet on a small regcoin-wallet should take less than a second)

If the goal of this pull is to instead fix a bug in authproxy.py, the commit subject line and pull subject line should be updated accordingly. E.g. "Also retry on BrokenPipeError" or "repeat request with new connection on BrokenPipeError".

sipa commented at 5:14 PM on June 2, 2016: member

Reopening as a new PR in that case.

sipa closed this on Jun 2, 2016

MarcoFalke locked this on Sep 8, 2021