Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
132 changes: 132 additions & 0 deletions test/functional/interface_http.py
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down Expand Up @@ -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:

Copy link
Copy Markdown
Member

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 using sock.recv and not getresponse()?

Copy link
Copy Markdown
Member Author

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:

exception socket.timeout
A deprecated alias of TimeoutError.
Changed in version 3.10: This class was made an alias of TimeoutError.

Since Python 3.10 is minimum version required in dependencies.md (and the test passes!) I think it's ok to leave as-is

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

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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 recv I guess.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think that's possible, the two RPCs are getblockcount and waitforblockheight, those two responses together including their HTTP overhead only total about 500 bytes so I don't think recv(1024) would truncate anything. If the server is extremely slow the client may even have to call recv() twice in the while loop, reading only about 250 bytes each time.


# 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)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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).

def _get_http_connection(self, url_node):
    conn = http.client.HTTPConnection(url_node.hostname, url_node.port) 
    conn.connect()
    sock = conn.sock
    return conn, sock

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The 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()

@polespinasa polespinasa May 7, 2025

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you move the start = time.time() before sending the test passes correctly.

CI was failing locally on my laptop. After changing this it does work.

Note: it was just working on some executions

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The 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: -rpcservertimeout=2, we send a request, we time how long it takes to close, and that duration is expected to be between 1 and 4 seconds.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The 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?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The 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 duration < expected.

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.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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 EOF

It must make it such that the timer in the test is then always >= than the server timeout of 2 seconds, no?

@pinheadmz pinheadmz May 21, 2025

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The 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:

event_add: event: 0x10a004210 (fd 20), EV_READ   EV_TIMEOUT call 0x1053cf1bc 
event_add: event 0x10a004210, timeout in 1 seconds 0 useconds, call 0x1053cf1bc 

Interestingly, the original version of this test always passes after switching to Sockman

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The 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 ;-)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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 http.client.HTTPConnection() - it does not open any connections, just sets some internal member variables of the HTTPConnection class. So, starting the timer before or after http.client.HTTPConnection() shouldn't make a difference.

conn.connect() is what makes the connection. And the timer should be started before it. Why would not the followng test the right thing?

  • start timer in the test (A)
  • connect, server timer starts here (B)
  • send
  • try to recv, connection will be closed by the server due to server timeout (C)
  • stop the timer (D)

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?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The 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:

send, server timer starts immediately after (B)

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 ;-)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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:

  • connect
  • start timer in the test (A)
  • send, server timer starts after last packet received from the client (B)
  • try to recv, connection will be closed by the server due to server timeout (C)
  • stop the timer in the test (D)

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"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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):

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The 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)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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()
5 changes: 5 additions & 0 deletions test/functional/test_framework/authproxy.py
Original file line number Diff line number Diff line change
Expand Up @@ -75,6 +75,7 @@ def __init__(self, service_url, service_name=None, timeout=HTTP_TIMEOUT, connect
self.__service_url = service_url
self._service_name = service_name
self.ensure_ascii = ensure_ascii # can be toggled on the fly by tests
self.reuse_http_connections = True
self.__url = urllib.parse.urlparse(service_url)
user = None if self.__url.username is None else self.__url.username.encode('utf8')
passwd = None if self.__url.password is None else self.__url.password.encode('utf8')
Expand All @@ -92,6 +93,8 @@ def __getattr__(self, name):
raise AttributeError
if self._service_name is not None:
name = "%s.%s" % (self._service_name, name)
if not self.reuse_http_connections:
self._set_conn()
return AuthServiceProxy(self.__service_url, name, connection=self.__conn)

def _request(self, method, path, postdata):
Expand All @@ -102,6 +105,8 @@ def _request(self, method, path, postdata):
'User-Agent': USER_AGENT,
'Authorization': self.__auth_header,
'Content-type': 'application/json'}
if not self.reuse_http_connections:
self._set_conn()
self.__conn.request(method, path, postdata, headers)
return self._get_response()

Expand Down
2 changes: 2 additions & 0 deletions test/functional/test_framework/test_node.py
Original file line number Diff line number Diff line change
Expand Up @@ -156,6 +156,7 @@ def __init__(self, i, datadir_path, *, chain, rpchost, timewait, timeout_factor,
self.process = None
self.rpc_connected = False
self.rpc = None
self.reuse_http_connections = True # Must be set before calling get_rpc_proxy() i.e. before restarting node
self.url = None
self.log = logging.getLogger('TestFramework.node%d' % i)
# Cache perf subprocesses here by their data output filename.
Expand Down Expand Up @@ -280,6 +281,7 @@ def wait_for_rpc_connection(self, *, wait_for_import=True):
timeout=self.rpc_timeout // 2, # Shorter timeout to allow for one retry in case of ETIMEDOUT
coveragedir=self.coverage_dir,
)
rpc.auth_service_proxy_instance.reuse_http_connections = self.reuse_http_connections
rpc.getblockcount()
# If the call to getblockcount() succeeds then the RPC connection is up
if self.version_is_at_least(190000) and wait_for_import:
Expand Down