-
Notifications
You must be signed in to change notification settings - Fork 39.2k
tests: Expand HTTP coverage to assert libevent behavior #32408
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -8,6 +8,7 @@ | |
| from test_framework.util import assert_equal, str_to_b64str | ||
|
|
||
| import http.client | ||
| import time | ||
| import urllib.parse | ||
|
|
||
| class HTTPBasicsTest (BitcoinTestFramework): | ||
|
|
@@ -105,5 +106,136 @@ def run_test(self): | |
| assert_equal(out1.status, http.client.BAD_REQUEST) | ||
|
|
||
|
|
||
| self.log.info("Check pipelining") | ||
| # Requests are responded to in order they were received | ||
| # See https://www.rfc-editor.org/rfc/rfc7230#section-6.3.2 | ||
| tip_height = self.nodes[2].getblockcount() | ||
|
|
||
| req = "POST / HTTP/1.1\r\n" | ||
| req += f'Authorization: Basic {str_to_b64str(authpair)}\r\n' | ||
|
|
||
| # First request will take a long time to process | ||
| body1 = f'{{"method": "waitforblockheight", "params": [{tip_height + 1}]}}' | ||
| req1 = req | ||
| req1 += f'Content-Length: {len(body1)}\r\n\r\n' | ||
| req1 += body1 | ||
|
|
||
| # Second request will process very fast | ||
| body2 = '{"method": "getblockcount"}' | ||
| req2 = req | ||
| req2 += f'Content-Length: {len(body2)}\r\n\r\n' | ||
| req2 += body2 | ||
| # Get the underlying socket from HTTP connection so we can send something unusual | ||
| conn = http.client.HTTPConnection(urlNode2.hostname, urlNode2.port) | ||
| conn.connect() | ||
| sock = conn.sock | ||
| sock.settimeout(5) | ||
| # Send two requests in a row. The first will block the second indefinitely | ||
| sock.sendall(req1.encode("utf-8")) | ||
| sock.sendall(req2.encode("utf-8")) | ||
| try: | ||
| # The server should not respond to the fast, second request | ||
| # until the (very) slow first request has been handled: | ||
| res = sock.recv(1024) | ||
| assert False | ||
| except TimeoutError: | ||
| pass | ||
|
|
||
| # Use a separate http connection to generate a block | ||
| self.generate(self.nodes[2], 1, sync_fun=self.no_op) | ||
|
|
||
| # Wait for two responses to be received | ||
| res = b"" | ||
| while res.count(b"result") != 2: | ||
| res += sock.recv(1024) | ||
|
Comment on lines
+149
to
+150
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. nit: I haven't looked at the actual data but this seems a bit fragile, if the second "result" is at the very end of res, the test would continue here but then fail below. Not sure how real that threat is but it could also be easily mitigated by doing one more
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I don't think that's possible, the two RPCs are |
||
|
|
||
| # waitforblockheight was responded to first, and then getblockcount | ||
| # which includes the block added after the request was made | ||
| chunks = res.split(b'"result":') | ||
| assert chunks[1].startswith(b'{"hash":') | ||
| assert chunks[2].startswith(bytes(f'{tip_height + 1}', 'utf8')) | ||
|
|
||
|
|
||
| self.log.info("Check HTTP request encoded with chunked transfer") | ||
| headers_chunked = headers.copy() | ||
| headers_chunked.update({"Transfer-encoding": "chunked"}) | ||
| body_chunked = [ | ||
| b'{"method": "submitblock", "params": ["', | ||
| b'0' * 1000000, | ||
| b'1' * 1000000, | ||
| b'2' * 1000000, | ||
| b'3' * 1000000, | ||
| b'"]}' | ||
| ] | ||
| conn = http.client.HTTPConnection(urlNode2.hostname, urlNode2.port) | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. nit: Could use a helper function to get rid of some duplication here (and even beyond the changes here across the whole test file).
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Good call thanks. I will do this if I retouch this PR, otherwise will add to #32061 on rebase |
||
| conn.connect() | ||
| conn.request( | ||
| method='POST', | ||
| url='/', | ||
| body=iter(body_chunked), | ||
| headers=headers_chunked, | ||
| encode_chunked=True) | ||
| out1 = conn.getresponse().read() | ||
| assert_equal(out1, b'{"result":"high-hash","error":null}\n') | ||
|
|
||
|
|
||
| self.log.info("Check -rpcservertimeout") | ||
| # The test framework typically reuses a single persistent HTTP connection | ||
| # for all RPCs to a TestNode. Because we are setting -rpcservertimeout | ||
| # so low on this one node, its connection will quickly timeout and get dropped by | ||
| # the server. Negating this setting will force the AuthServiceProxy | ||
| # for this node to create a fresh new HTTP connection for every command | ||
| # called for the remainder of this test. | ||
| self.nodes[2].reuse_http_connections = False | ||
|
|
||
| self.restart_node(2, extra_args=["-rpcservertimeout=2"]) | ||
| # This is the amount of time the server will wait for a client to | ||
| # send a complete request. Test it by sending an incomplete but | ||
| # so-far otherwise well-formed HTTP request, and never finishing it. | ||
|
|
||
| # Copied from http_incomplete_test_() in regress_http.c in libevent. | ||
| # A complete request would have an additional "\r\n" at the end. | ||
| http_request = "GET /test1 HTTP/1.1\r\nHost: somehost\r\n" | ||
|
|
||
| # Get the underlying socket from HTTP connection so we can send something unusual | ||
| conn = http.client.HTTPConnection(urlNode2.hostname, urlNode2.port) | ||
| conn.connect() | ||
| sock = conn.sock | ||
| sock.sendall(http_request.encode("utf-8")) | ||
| # Wait for response, but expect a timeout disconnection after 1 second | ||
| start = time.time() | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
Note: it was just working on some executions
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I noticed in the libevent's test they don't actually check that server waited at all, just that the connection closed within a few seconds of the configured time out. So I went that route, but also added a tiny minimum check just to make sure the server isn't closing immediately. And this gives us better test reliability. So the new test is:
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. If the timeout is set to 2 wouldn't make more sense to test between 2 and 4 seconds? Can it be less than 2 seconds?
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. It can be, and that was why the 1 second timeout check kept failing. I tried a few implementations of the test and it's just impossible to reliably start the test timer in sync with the HTTP server. So sometimes it starts late and you end up with The point of the test is to ensure that the server disconnects idle clients, I think it does that even though the exact time is a little fudged.
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Did you try to start the timer before connecting? Like this: # Get the underlying socket from HTTP connection so we can send something unusual
conn = http.client.HTTPConnection(urlNode2.hostname, urlNode2.port)
+ start = time.time()
conn.connect()
sock = conn.sock
sock.sendall(http_request.encode("utf-8"))
# Wait for response, but expect a timeout disconnection after 1 second
- start = time.time()
res = sock.recv(1024)
stop = time.time()
# Server disconnected with EOFIt must make it such that the timer in the test is then always >= than the server timeout of 2 seconds, no?
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. That should work but the reason I didn't leave like that is I don't feel like its effectively testing the right thing. We could start the timer at the top of the file and it would always pass, but it wouldn't necessarily catch any regressions. The server timeout should re-start every time it receives a packet from the client, and it's very hard to start the test timer at the right moment. Another approach I tried was actually setting libevent debug logs and trying to track down messages like these: Interestingly, the original version of this test always passes after switching to Sockman
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. All that being said, if you want me to use the patch you wrote that's fine by me too ;-)
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I don't see this discussion as a blocker. I just want to get to the bottom of it. Checked the source code of
Time between B and C will (must!) always be less than the time between A and D. If it is not, then I would like to know why. Maybe we are doing something completely wrong. My worry is that CI machines are sometimes veeery slow and any "reasonable" time we set turns out to be surprise and results in intermittent test failures. Now, if doing the above can result in the time between A and D being less than 2 sec (= server timeout, B to C) and we don't know why is that and we set to check only for >1 sec instead, then, because we do not know the cause, how can we be sure that the test timer (A to D) will not be sometimes e.g. 0.99 sec causing the test to fail?
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The server timer should start after receiving the last packet from the client, because its an idle timer not a session timer. So its more correct to have:
I tried to to nail this in ce9847e but that also failed. And then, if we start the timer too early, we will always get a duration > 1 no matter what the server actually does... maybe its the initial TCP connection attempt that takes 1 second and then the server doesn't connect, or responds immediately, etc. There also could be something with libevent itself making this act funny? I haven't had any intermittency with the original test in #32061 -- so maybe as part of that PR we can tighten up the test ;-)
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Ok, it could be that libevent behaves in an unexpected way. In #32061 we could tighten up the test to:
|
||
| res = sock.recv(1024) | ||
| stop = time.time() | ||
| # Server disconnected with EOF | ||
| assert_equal(res, b"") | ||
| # Server disconnected within an acceptable range of time: | ||
| # not immediately, and not too far over the configured duration. | ||
| # This allows for some jitter in the test between client and server. | ||
| duration = stop - start | ||
| assert duration <= 4, f"Server disconnected too slow: {duration} > 4" | ||
| assert duration >= 1, f"Server disconnected too fast: {duration} < 1" | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. That should be 2, I guess since the timeout is set to 2. E.g. disconnecting after 1.5 seconds is unexpected and should be treated as an error. diff --git i/test/functional/interface_http.py w/test/functional/interface_http.py
index 4f10b55afd..9c345c30b9 100755
--- i/test/functional/interface_http.py
+++ w/test/functional/interface_http.py
@@ -185,13 +185,14 @@ class HTTPBasicsTest (BitcoinTestFramework):
# so low on this one node, its connection will quickly timeout and get dropped by
# the server. Negating this setting will force the AuthServiceProxy
# for this node to create a fresh new HTTP connection for every command
# called for the remainder of this test.
self.nodes[2].reuse_http_connections = False
- self.restart_node(2, extra_args=["-rpcservertimeout=2"])
+ rpcservertimeout = 2
+ self.restart_node(2, extra_args=[f"-rpcservertimeout={rpcservertimeout}"])
# This is the amount of time the server will wait for a client to
# send a complete request. Test it by sending an incomplete but
# so-far otherwise well-formed HTTP request, and never finishing it.
# Copied from http_incomplete_test_() in regress_http.c in libevent.
# A complete request would have an additional "\r\n" at the end.
@@ -199,24 +200,24 @@ class HTTPBasicsTest (BitcoinTestFramework):
# Get the underlying socket from HTTP connection so we can send something unusual
conn = http.client.HTTPConnection(urlNode2.hostname, urlNode2.port)
conn.connect()
sock = conn.sock
sock.sendall(http_request.encode("utf-8"))
- # Wait for response, but expect a timeout disconnection after 1 second
+ # Wait for response, but expect a timeout disconnection after `rpcservertimeout` seconds
start = time.time()
res = sock.recv(1024)
stop = time.time()
# Server disconnected with EOF
assert res == b""
# Server disconnected within an acceptable range of time:
# not immediately, and not too far over the configured duration.
# This allows for some jitter in the test between client and server.
duration = stop - start
assert duration <= 4, f"Server disconnected too slow: {duration} > 4"
- assert duration >= 1, f"Server disconnected too fast: {duration} < 1"
+ assert duration >= rpcservertimeout, f"Server disconnected too fast: {duration} < {rpcservertimeout}"
# The connection is definitely closed.
try:
conn.request('GET', '/')
conn.getresponse()
# macos/linux windows
except (ConnectionResetError, ConnectionAbortedError):
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The problem with this is the test becomes flakey because the timer may not start in sync with the server, so it may record less time than the server actually waited: #32408 (comment) note also that libevent doesn't even try to test the lower bound: #32408 (comment)
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. continued the discussion in #32408 (comment) |
||
|
|
||
| # The connection is definitely closed. | ||
| got_expected_error = False | ||
| try: | ||
| conn.request('GET', '/') | ||
| conn.getresponse() | ||
| # macos/linux windows | ||
| except (ConnectionResetError, ConnectionAbortedError): | ||
| got_expected_error = True | ||
| assert got_expected_error | ||
|
|
||
| # Sanity check | ||
| http_request = "GET /test2 HTTP/1.1\r\nHost: somehost\r\n\r\n" | ||
| conn = http.client.HTTPConnection(urlNode2.hostname, urlNode2.port) | ||
| conn.connect() | ||
| sock = conn.sock | ||
| sock.sendall(http_request.encode("utf-8")) | ||
| res = sock.recv(1024) | ||
| assert res.startswith(b"HTTP/1.1 404 Not Found") | ||
| # still open | ||
| conn.request('GET', '/') | ||
| conn.getresponse() | ||
|
|
||
| if __name__ == '__main__': | ||
| HTTPBasicsTest(__file__).main() | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm not sure about this but shouldn't this be
socket.timeout? As we're usingsock.recvand notgetresponse()?There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Great catch! I found this:
Since Python 3.10 is minimum version required in dependencies.md (and the test passes!) I think it's ok to leave as-is