[qa] Tests occasionally raise http.client.RemoteDisconnected or BadStatusLine #11777

issue MarcoFalke openend this issue on November 27, 2017
  1. MarcoFalke commented at 9:20 pm on November 27, 2017: member

    Unrelated to any specific test, randomly a BadStatusLine might raise when reading the response.

    This only happens on travis, so assigning low priority.

    Recent examples:

  2. MarcoFalke added the label Priority Low on Nov 27, 2017
  3. MarcoFalke added the label Tests on Nov 27, 2017
  4. MarcoFalke removed the label Priority Low on Nov 28, 2017
  5. ryanofsky commented at 4:10 pm on January 11, 2018: member

    Saw this with importprunedfunds in https://travis-ci.org/bitcoin/bitcoin/jobs/327693845. Here’s the stack trace in case it it might help people find this issue:

     0stderr:
 1Traceback (most recent call last):
 2  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 107, in _request
 3    return self._get_response()
 4  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 153, in _get_response
 5    http_response = self.__conn.getresponse()
 6  File "/usr/lib/python3.4/http/client.py", line 1208, in getresponse
 7    response.begin()
 8  File "/usr/lib/python3.4/http/client.py", line 380, in begin
 9    version, status, reason = self._read_status()
10  File "/usr/lib/python3.4/http/client.py", line 350, in _read_status
11    raise BadStatusLine(line)
12http.client.BadStatusLine: ''
13During handling of the above exception, another exception occurred:
14Traceback (most recent call last):
15  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/importprunedfunds.py", line 114, in <module>
16    ImportPrunedFundsTest().main()
17  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 141, in main
18    self.stop_nodes()
19  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 258, in stop_nodes
20    node.stop_node()
21  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_node.py", line 124, in stop_node
22    self.stop()
23  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/coverage.py", line 47, in __call__
24    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
25  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 136, in __call__
26    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
27  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 111, in _request
28    self.__conn.request(method, path, postdata, headers)
29  File "/usr/lib/python3.4/http/client.py", line 1125, in request
30    self._send_request(method, url, body, headers)
31  File "/usr/lib/python3.4/http/client.py", line 1163, in _send_request
32    self.endheaders(body)
33  File "/usr/lib/python3.4/http/client.py", line 1121, in endheaders
34    self._send_output(message_body)
35  File "/usr/lib/python3.4/http/client.py", line 951, in _send_output
36    self.send(msg)
37  File "/usr/lib/python3.4/http/client.py", line 886, in send
38    self.connect()
39  File "/usr/lib/python3.4/http/client.py", line 863, in connect
40    self.timeout, self.source_address)
41  File "/usr/lib/python3.4/socket.py", line 512, in create_connection
42    raise err
43  File "/usr/lib/python3.4/socket.py", line 503, in create_connection
44    sock.connect(sa)
45ConnectionRefusedError: [Errno 111] Connection refused
  6. achow101 commented at 0:45 am on January 12, 2018: member
    I’m also seeing this on my BIP 174 test here: https://travis-ci.org/bitcoin/bitcoin/jobs/327867319. It appears to be happening consistently though, so I’m not sure if that’s a test problem or a Travis problem.
  7. TheBlueMatt commented at 4:12 pm on January 14, 2018: member

    This is a bug in the python-bitcoinrpc library - I get it all the time locally, something to do with the underlying HTTP request getting closed and not automatically reopened. In my own scripts I generally wrap every call and retry if it falls.

    On January 12, 2018 12:45:15 AM UTC, Andrew Chow notifications@github.com wrote:

    I’m also seeing this on my BIP 174 test here: https://travis-ci.org/bitcoin/bitcoin/jobs/327867319. It appears to be happening consistently though, so I’m not sure if that’s a test problem or a Travis problem.

    – You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/bitcoin/bitcoin/issues/11777#issuecomment-357109147

  8. jnewbery commented at 3:59 pm on January 15, 2018: member

    @achow101 - I think your error is different. bitcoind is OOM’ing: https://travis-ci.org/bitcoin/bitcoin/jobs/327867319#L6571

    All the other examples are when the stop RPC is called. authproxy.py has handling for if the RPC call raises a http.client.BadStatusLine because the connection was closed:

    https://github.com/bitcoin/bitcoin/blob/44080a90a29292df96e92f22242785c5040000a1/test/functional/test_framework/authproxy.py#L109

    It tries to reconnect and send the RPC again. I guess if the stop RPC is successful but causes the connection to be closed before the response is received, then authproxy won’t be able to reconnect and we’ll get the subsequent ConnectionRefusedError.

    Shutdown processing was changed here: #11006. I wonder if that’s made this worse. I guess we see it on travis because it’s a timing thing. @TheBlueMatt - you’re able to reproduce this locally. Can you check whether reverting #11006 improves this for you?

    We could fix this by special casing calls to stop, and wrapping them in a try-except (which would check that the process had indeed stopped and then continue).

  9. MarcoFalke commented at 9:43 pm on January 15, 2018: member

    We could fix this by special casing calls to stop, and wrapping them in a try-except (which would check that the process had indeed stopped and then continue).

    Imo, we should properly send the response before cutting the connection and going silent.

  10. TheBlueMatt commented at 11:38 pm on January 15, 2018: member

    Err, no, I’ve never seen the issue when running our test suite, only when using python-bitcoinrpc locally against a local bitcoind for other stuff.

    On January 15, 2018 3:59:49 PM UTC, John Newbery notifications@github.com wrote:

    @achow101 - I think your error is different. bitcoind is OOM’ing: https://travis-ci.org/bitcoin/bitcoin/jobs/327867319#L6571

    All the other examples are when the stop RPC is called. authproxy.py has handling for if the RPC call raises a http.client.BadStatusLine because the connection was closed:

    https://github.com/bitcoin/bitcoin/blob/44080a90a29292df96e92f22242785c5040000a1/test/functional/test_framework/authproxy.py#L109

    It tries to reconnect and send the RPC again. I guess if the stop RPC is successful but causes the connection to be closed before the response is received, then authproxy won’t be able to reconnect and we’ll get the subsequent ConnectionRefusedError.

    Shutdown processing was changed here: https://github.com/bitcoin/bitcoin/pull/11006. I wonder if that’s made this worse. I guess we see it on travis because it’s a timing thing.

    @TheBlueMatt - you’re able to reproduce this locally. Can you check whether reverting #11006 improves this for you?

    We could fix this by special casing calls to stop, and wrapping them in a try-except (which would check that the process had indeed stopped and then continue).

    – You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/bitcoin/bitcoin/issues/11777#issuecomment-357722916

  11. MarcoFalke commented at 1:21 am on January 16, 2018: member

    @TheBlueMatt I assume you are using python-bitcoinrpc:1.0 and python:3.4, which will incorrectly throw BadStatusLine due to a bug in python (c.f. https://bugs.python.org/issue3566).

    In case my assumption is wrong, do you see this exception also for rpcs other than stop?

  12. MarcoFalke commented at 4:29 pm on January 16, 2018: member

    So I tried running with the depends build (i.e. libevent 2.1.8-stable) and python:3.4.3 from trusty. So all of that should be identical to what travis is running, but I couldn’t reproduce the issue.

    Since we print the consolidated logs on failure on travis, someone should copy-paste them here before wiping the travis log. I suspect they might help debug further.

  13. jnewbery commented at 2:49 pm on May 21, 2018: member

    @MarcoFalke , here’s the log from https://travis-ci.org/bitcoin/bitcoin/jobs/379941758, failing in mempool_persist.py:

     0test  2018-05-16T22:34:40.352000Z TestFramework (DEBUG): Stop-start node0 with -persistmempool=0. Verify that it doesn't load its mempool.dat file. 
 1 test  2018-05-16T22:34:40.352000Z TestFramework.node0 (DEBUG): Stopping node 
 2 node0 2018-05-16T22:34:40.352576Z Received a POST request for / from 127.0.0.1:32826 
 3 node0 2018-05-16T22:34:40.352707Z ThreadRPCServer method=stop user=__cookie__ 
 4 node0 2018-05-16T22:34:40.352776Z Interrupting HTTP server 
 5 node0 2018-05-16T22:34:40.352818Z Interrupting HTTP RPC server 
 6 node0 2018-05-16T22:34:40.352828Z Interrupting RPC 
 7 node0 2018-05-16T22:34:40.352845Z Shutdown: In progress... 
 8 node0 2018-05-16T22:34:40.352861Z opencon thread exit 
 9 node0 2018-05-16T22:34:40.352867Z Stopping HTTP RPC server 
10 node0 2018-05-16T22:34:40.352880Z Unregistering HTTP handler for / (exactmatch 1) 
11 node0 2018-05-16T22:34:40.352894Z addcon thread exit 
12 node0 2018-05-16T22:34:40.352903Z Unregistering HTTP handler for /wallet/ (exactmatch 0) 
13 node0 2018-05-16T22:34:40.352917Z Stopping RPC 
14 test  2018-05-16T22:34:40.353000Z TestFramework (ERROR): Unexpected exception caught during testing
15Traceback (most recent call last):
16  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 107, in _request
17    return self._get_response()
18  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 153, in _get_response
19    http_response = self.__conn.getresponse()
20  File "/usr/lib/python3.4/http/client.py", line 1208, in getresponse
21    response.begin()
22  File "/usr/lib/python3.4/http/client.py", line 380, in begin
23    version, status, reason = self._read_status()
24  File "/usr/lib/python3.4/http/client.py", line 350, in _read_status
25    raise BadStatusLine(line)
26http.client.BadStatusLine: ''
27During handling of the above exception, another exception occurred:
28Traceback (most recent call last):
29  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 152, in main
30    self.run_test()
31  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/mempool_persist.py", line 85, in run_test
32    self.stop_nodes()
33  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 301, in stop_nodes
34    node.stop_node()
35  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_node.py", line 196, in stop_node
36    self.stop()
37  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/coverage.py", line 47, in __call__
38    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
39  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 136, in __call__
40    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
41  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 111, in _request
42    self.__conn.request(method, path, postdata, headers)
43  File "/usr/lib/python3.4/http/client.py", line 1125, in request
44    self._send_request(method, url, body, headers)
45  File "/usr/lib/python3.4/http/client.py", line 1163, in _send_request
46    self.endheaders(body)
47  File "/usr/lib/python3.4/http/client.py", line 1121, in endheaders
48    self._send_output(message_body)
49  File "/usr/lib/python3.4/http/client.py", line 951, in _send_output
50    self.send(msg)
51  File "/usr/lib/python3.4/http/client.py", line 886, in send
52    self.connect()
53  File "/usr/lib/python3.4/http/client.py", line 863, in connect
54    self.timeout, self.source_address)
55  File "/usr/lib/python3.4/socket.py", line 512, in create_connection
56    raise err
57  File "/usr/lib/python3.4/socket.py", line 503, in create_connection
58    sock.connect(sa)
59ConnectionRefusedError: [Errno 111] Connection refused 
60 node0 2018-05-16T22:34:40.353006Z RPC stopped. 
61 node0 2018-05-16T22:34:40.353022Z Stopping HTTP server 
62 node0 2018-05-16T22:34:40.353078Z Waiting for HTTP worker threads to exit 
63 node0 2018-05-16T22:34:40.353136Z msghand thread exit 
64 node0 2018-05-16T22:34:40.353169Z Waiting for HTTP event thread to exit 
65 node0 2018-05-16T22:34:40.353213Z Exited http event loop 
66 node0 2018-05-16T22:34:40.353323Z Stopped HTTP server 
67 node0 2018-05-16T22:34:40.353351Z BerkeleyEnvironment::Flush: Flush(false) 
68 node0 2018-05-16T22:34:40.353368Z BerkeleyEnvironment::Flush: Flushing wallet.dat (refcount = 0)... 
69 node0 2018-05-16T22:34:40.353469Z BerkeleyEnvironment::Flush: wallet.dat checkpoint 
70 node0 2018-05-16T22:34:40.353714Z net thread exit 
71 node0 2018-05-16T22:34:40.354198Z BerkeleyEnvironment::Flush: wallet.dat detach 
72 node0 2018-05-16T22:34:40.355314Z BerkeleyEnvironment::Flush: wallet.dat closed 
73 node0 2018-05-16T22:34:40.355334Z BerkeleyEnvironment::Flush: Flush(false) took               2ms 
74 node0 2018-05-16T22:34:40.358379Z Flushed 0 addresses to peers.dat  3ms 
75 node0 2018-05-16T22:34:40.358545Z scheduler thread interrupt 
76 node0 2018-05-16T22:34:40.361186Z Dumped mempool: 1.8e-05s to copy, 0.002403s to dump 
77 node0 2018-05-16T22:34:40.361215Z Recorded 5 unconfirmed txs from mempool in 1.5e-05s 
78 test  2018-05-16T22:34:40.362000Z TestFramework (INFO): Stopping nodes 
79 test  2018-05-16T22:34:40.362000Z TestFramework.node0 (DEBUG): Stopping node 
80 test  2018-05-16T22:34:40.363000Z TestFramework.node0 (ERROR): Unable to stop node.
81Traceback (most recent call last):
82  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_node.py", line 196, in stop_node
83    self.stop()
84  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/coverage.py", line 47, in __call__
85    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
86  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 136, in __call__
87    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
88  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/authproxy.py", line 106, in _request
89    self.__conn.request(method, path, postdata, headers)
90  File "/usr/lib/python3.4/http/client.py", line 1125, in request
91    self._send_request(method, url, body, headers)
92  File "/usr/lib/python3.4/http/client.py", line 1153, in _send_request
93    self.putrequest(method, url, **skips)
94  File "/usr/lib/python3.4/http/client.py", line 993, in putrequest
95    raise CannotSendRequest(self.__state)
96http.client.CannotSendRequest: Request-sent 
97 test  2018-05-16T22:34:40.363000Z TestFramework.node1 (DEBUG): Stopping node 
98 test  2018-05-16T22:34:40.364000Z TestFramework.node2 (DEBUG): Stopping node
  14. MarcoFalke commented at 3:08 pm on May 21, 2018: member
    @jnewbery I’d suggest to revisit this issue report after #13215, which runs the functional tests through docker exec on a bionic container. Bionic uses python3.6 and tests still failing with this error would rule out a bug that is only present in python3.4
  15. MarcoFalke commented at 5:55 pm on June 3, 2018: member
    I believe the exception on python 3.6 is http.client.RemoteDisconnected: Remote end closed connection without response. So this is likely not an issue with travis or python 3.4.
  16. MarcoFalke renamed this:
    [qa] Tests on travis occasionally raise http.client.BadStatusLine: ''
    [qa] Tests occasionally raise http.client.RemoteDisconnected or BadStatusLine
    on Jun 3, 2018
  17. laanwj commented at 1:59 pm on June 4, 2018: member
    I think this is caused by a race during shutdown of the http server, causing it to not succesfully return the JSON response to stop to the caller. See also #13211, which more reliably reproduces the issue.
  18. ken2812221 commented at 2:35 pm on June 4, 2018: contributor
    @laanwj So the expected action is waiting for RPC client to get response from RPC server? Even if the client does tend to not get any response. I think the server should close ASAP even when the client does not want to get response.
  19. MarcoFalke commented at 3:45 pm on June 4, 2018: member

    RPC client to get response from RPC server

    Yes, all responses should be sent out unless you sent the corresponding request after the stop

  20. jnewbery commented at 3:59 pm on June 4, 2018: member

    Do people consider it a bug that bitcoind won’t always respond to a stop call (and presumably an encryptwallet call) before shutting down?

    If so, we should fix that bug in bitcoind. If not, we can fix the test failures by adding special casing for calls to stop and encryptwallet so that the test framework handles not receiving a response.

  21. laanwj commented at 5:40 pm on June 4, 2018: member

    Do people consider it a bug that bitcoind won’t always respond to a stop call (and presumably an encryptwallet call) before shutting down?

    It was always considered a bug, at least. So not regarding it as a bug is a change of behavior. I’m also not sure how bitcoin-cli copes with this.

  22. MarcoFalke commented at 6:11 pm on June 4, 2018: member
    If this is not a bug, the documentation on help stop should clearly state that the remote might disconnect without sending a reply.
  23. laanwj closed this on Dec 6, 2018
  24. laanwj referenced this in commit a88bd3186d on Dec 6, 2018
  25. codablock referenced this in commit 835636d9b0 on Oct 14, 2019
  26. codablock referenced this in commit fefe07003b on Oct 14, 2019
  27. barrystyle referenced this in commit 32ea3cc4ef on Jan 22, 2020
  28. TheArbitrator referenced this in commit 7df7b4f53c on Jun 23, 2021
  29. TheArbitrator referenced this in commit 47b8deeda8 on Jun 25, 2021
  30. Munkybooty referenced this in commit aa25265942 on Aug 2, 2021
  31. Munkybooty referenced this in commit 2e1fb3f3e8 on Aug 3, 2021
  32. Munkybooty referenced this in commit 21d93c1aea on Aug 5, 2021
  33. Munkybooty referenced this in commit 36b2f4e0f0 on Aug 5, 2021
  34. Munkybooty referenced this in commit 6db39063f8 on Aug 8, 2021
  35. Munkybooty referenced this in commit 9740c21531 on Aug 11, 2021
  36. Munkybooty referenced this in commit 09963a6af0 on Aug 11, 2021
  37. DrahtBot locked this on Sep 8, 2021


MarcoFalke ryanofsky achow101 TheBlueMatt jnewbery laanwj ken2812221

Labels
Tests

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-12-22 15:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me