bryancall commented on code in PR #13873:
URL: https://github.com/apache/trafficserver/pull/13873#discussion_r4342849652
##########
tests/uranium_tests/h2/h2active_timeout.py:
##########
@@ -54,16 +54,28 @@ def get_socket(port: int) -> socket.socket:
return tls_socket
-def makerequest(port: int, path: str, delay: int) -> None:
- """Establish an HTTP/2 connection and send a request.
+def makerequest(port: int, path: str, active_timeout: int, max_wait: int) ->
None:
+ """Send a request, then wait for ATS to close the connection on its active
timeout.
+
+ ATS enforces the active timeout from its InactivityCop, which looks at a
+ connection only once a second, so the close lands up to a second after the
+ timeout expires, and later still on a loaded machine. Rather than guess
when
+ that is, wait for the close itself and check that it came no sooner than
the
+ timeout and within max_wait seconds.
:param port: The port to connect to.
:param path: The path to request.
- :param delay: The delay to wait between sending requests in a stream.
+ :param active_timeout: The proxy.config.http2.active_timeout_in ATS uses,
in seconds.
+ :param max_wait: The number of seconds to wait for ATS to close the
connection.
"""
tls_socket = get_socket(port)
+ # ATS starts the active timeout when it reads the connection preface, which
+ # happens after this point, so it cannot close the connection any sooner
+ # than active_timeout seconds from now.
+ start = time.monotonic()
+
h2_connection = h2.connection.H2Connection()
h2_connection.initiate_connection()
tls_socket.sendall(h2_connection.data_to_send())
Review Comment:
ATS starts the active timeout when it reads the connection preface, in
`state_read_connection_preface`
([Http2CommonSession.cc:223](https://github.com/apache/trafficserver/blob/32209e8858/src/proxy/http2/Http2CommonSession.cc#L223)).
That read can only happen after the client sends the preface, so with the
clock started first, a close that is on time can never look early. Starting it
after `sendall` returns would flip that: ATS can read the preface before the
client takes its timestamp, and a close right at the deadline would then fail.
The slack this leaves is the time the preface takes to cross a local socket,
and the closes I measured landed 0.55 to 0.90 seconds past the timeout, so I've
left it as is.
##########
tests/uranium_tests/h2/h2active_timeout.py:
##########
@@ -54,16 +54,28 @@ def get_socket(port: int) -> socket.socket:
return tls_socket
-def makerequest(port: int, path: str, delay: int) -> None:
- """Establish an HTTP/2 connection and send a request.
+def makerequest(port: int, path: str, active_timeout: int, max_wait: int) ->
None:
+ """Send a request, then wait for ATS to close the connection on its active
timeout.
+
+ ATS enforces the active timeout from its InactivityCop, which looks at a
+ connection only once a second, so the close lands up to a second after the
+ timeout expires, and later still on a loaded machine. Rather than guess
when
+ that is, wait for the close itself and check that it came no sooner than
the
+ timeout and within max_wait seconds.
:param port: The port to connect to.
:param path: The path to request.
- :param delay: The delay to wait between sending requests in a stream.
+ :param active_timeout: The proxy.config.http2.active_timeout_in ATS uses,
in seconds.
+ :param max_wait: The number of seconds to wait for ATS to close the
connection.
"""
tls_socket = get_socket(port)
+ # ATS starts the active timeout when it reads the connection preface, which
+ # happens after this point, so it cannot close the connection any sooner
+ # than active_timeout seconds from now.
+ start = time.monotonic()
+
h2_connection = h2.connection.H2Connection()
h2_connection.initiate_connection()
tls_socket.sendall(h2_connection.data_to_send())
Review Comment:
ATS starts the active timeout when it reads the connection preface, in
`state_read_connection_preface`
([Http2CommonSession.cc:223](https://github.com/apache/trafficserver/blob/32209e8858/src/proxy/http2/Http2CommonSession.cc#L223)).
That read can only happen after the client sends the preface, so with the
clock started first, a close that is on time can never look early. Starting it
after `sendall` returns would flip that: ATS can read the preface before the
client takes its timestamp, and a close right at the deadline would then fail.
The slack this leaves is the time the preface takes to cross a local socket,
and the closes I measured landed 0.55 to 0.90 seconds past the timeout, so I've
left it as is.
##########
tests/uranium_tests/h2/h2active_timeout.py:
##########
@@ -78,65 +90,46 @@ def makerequest(port: int, path: str, delay: int) -> None:
h2_connection.send_headers(1, headers, end_stream=True)
tls_socket.sendall(h2_connection.data_to_send())
- # delay, triggering ATS timeout.
- time.sleep(delay)
-
- # The following should fail due to the timeout.
+ # Read the response, then keep reading until ATS closes the connection.
+ closed = False
try:
- # Send a second request.
- h2_connection.send_headers(3, headers, end_stream=True)
- tls_socket.sendall(h2_connection.data_to_send())
-
- response_stream_ended = False
- body = b''
- while not response_stream_ended:
- # read raw data from the socket
- data = tls_socket.recv(65536 * 1024)
+ while True:
+ remaining = start + max_wait - time.monotonic()
+ if remaining <= 0:
+ break
+ tls_socket.settimeout(remaining)
+ data = tls_socket.recv(65536)
if not data:
+ closed = True
break
-
- # feed raw data into h2, and process resulting events
- events = h2_connection.receive_data(data)
- for event in events:
- if isinstance(event, h2.events.ResponseReceived):
- # response headers received
- print("Response received:")
- for header in event.headers:
- print(f' {header[0].decode()}: {header[1].decode()}')
+ for event in h2_connection.receive_data(data):
if isinstance(event, h2.events.DataReceived):
- # update flow control so the server doesn't starve us
h2_connection.acknowledge_received_data(event.flow_controlled_length,
event.stream_id)
- # more response body data received
- body += event.data
- if isinstance(event, h2.events.StreamEnded):
- # response body completed, let's exit the loop
- response_stream_ended = True
- break
- # send any pending data to the server
tls_socket.sendall(h2_connection.data_to_send())
Review Comment:
The only writes in this loop are the acknowledgements and flow control
updates h2 queues in reply to what it read, a few dozen bytes at a time. A send
waits only when the socket's send buffer is full, which those won't do on a
local connection, and the loop never sets a timeout once the deadline has
passed. If ATS has closed the connection, `sendall` raises `ConnectionError` or
`ssl.SSLError`, which the loop already counts as a close. I've left it as is.
##########
tests/uranium_tests/h2/h2active_timeout.py:
##########
@@ -78,65 +90,46 @@ def makerequest(port: int, path: str, delay: int) -> None:
h2_connection.send_headers(1, headers, end_stream=True)
tls_socket.sendall(h2_connection.data_to_send())
- # delay, triggering ATS timeout.
- time.sleep(delay)
-
- # The following should fail due to the timeout.
+ # Read the response, then keep reading until ATS closes the connection.
+ closed = False
try:
- # Send a second request.
- h2_connection.send_headers(3, headers, end_stream=True)
- tls_socket.sendall(h2_connection.data_to_send())
-
- response_stream_ended = False
- body = b''
- while not response_stream_ended:
- # read raw data from the socket
- data = tls_socket.recv(65536 * 1024)
+ while True:
+ remaining = start + max_wait - time.monotonic()
+ if remaining <= 0:
+ break
Review Comment:
`max_wait` is the deadline, so a close that hasn't arrived by then is late.
With `MAX_WAIT = ACTIVE_TIMEOUT + 5` in `test_http2.py`, a close at the
boundary is five seconds past the timeout, and failing it is the right answer.
A final read would only move the edge by however long that read waits, so I've
left it as is.
##########
tests/uranium_tests/h2/h2active_timeout.py:
##########
@@ -78,65 +90,46 @@ def makerequest(port: int, path: str, delay: int) -> None:
h2_connection.send_headers(1, headers, end_stream=True)
tls_socket.sendall(h2_connection.data_to_send())
- # delay, triggering ATS timeout.
- time.sleep(delay)
-
- # The following should fail due to the timeout.
+ # Read the response, then keep reading until ATS closes the connection.
+ closed = False
try:
- # Send a second request.
- h2_connection.send_headers(3, headers, end_stream=True)
- tls_socket.sendall(h2_connection.data_to_send())
-
- response_stream_ended = False
- body = b''
- while not response_stream_ended:
- # read raw data from the socket
- data = tls_socket.recv(65536 * 1024)
+ while True:
+ remaining = start + max_wait - time.monotonic()
+ if remaining <= 0:
+ break
+ tls_socket.settimeout(remaining)
+ data = tls_socket.recv(65536)
if not data:
+ closed = True
break
-
- # feed raw data into h2, and process resulting events
- events = h2_connection.receive_data(data)
- for event in events:
- if isinstance(event, h2.events.ResponseReceived):
- # response headers received
- print("Response received:")
- for header in event.headers:
- print(f' {header[0].decode()}: {header[1].decode()}')
+ for event in h2_connection.receive_data(data):
if isinstance(event, h2.events.DataReceived):
- # update flow control so the server doesn't starve us
h2_connection.acknowledge_received_data(event.flow_controlled_length,
event.stream_id)
- # more response body data received
- body += event.data
- if isinstance(event, h2.events.StreamEnded):
- # response body completed, let's exit the loop
- response_stream_ended = True
- break
- # send any pending data to the server
tls_socket.sendall(h2_connection.data_to_send())
-
- print(f"Response fully received: {len(body)} bytes")
-
- body_str = body.decode('utf-8')
-
- # tell the server we are closing the h2 connection
- h2_connection.close_connection()
- tls_socket.sendall(h2_connection.data_to_send())
-
- # close the socket
- tls_socket.close()
- except Exception:
+ except socket.timeout:
+ pass
+ except (ConnectionError, ssl.SSLError):
+ closed = True
+ elapsed = time.monotonic() - start
+ tls_socket.close()
Review Comment:
This is the same point as the [earlier thread on this
line](https://github.com/apache/trafficserver/pull/13873#discussion_r4340375531).
h2active_timeout.py runs as its own short-lived process, so an unexpected
exception exits non-zero with a traceback and the OS closes the socket. The
test then fails on its return code assert with that traceback in the output.
##########
tests/uranium_tests/h2/h2active_timeout.py:
##########
@@ -78,65 +90,46 @@ def makerequest(port: int, path: str, delay: int) -> None:
h2_connection.send_headers(1, headers, end_stream=True)
tls_socket.sendall(h2_connection.data_to_send())
- # delay, triggering ATS timeout.
- time.sleep(delay)
-
- # The following should fail due to the timeout.
+ # Read the response, then keep reading until ATS closes the connection.
+ closed = False
try:
- # Send a second request.
- h2_connection.send_headers(3, headers, end_stream=True)
- tls_socket.sendall(h2_connection.data_to_send())
-
- response_stream_ended = False
- body = b''
- while not response_stream_ended:
- # read raw data from the socket
- data = tls_socket.recv(65536 * 1024)
+ while True:
+ remaining = start + max_wait - time.monotonic()
+ if remaining <= 0:
+ break
+ tls_socket.settimeout(remaining)
+ data = tls_socket.recv(65536)
if not data:
+ closed = True
break
-
- # feed raw data into h2, and process resulting events
- events = h2_connection.receive_data(data)
- for event in events:
- if isinstance(event, h2.events.ResponseReceived):
- # response headers received
- print("Response received:")
- for header in event.headers:
- print(f' {header[0].decode()}: {header[1].decode()}')
+ for event in h2_connection.receive_data(data):
if isinstance(event, h2.events.DataReceived):
- # update flow control so the server doesn't starve us
h2_connection.acknowledge_received_data(event.flow_controlled_length,
event.stream_id)
- # more response body data received
- body += event.data
- if isinstance(event, h2.events.StreamEnded):
- # response body completed, let's exit the loop
- response_stream_ended = True
- break
- # send any pending data to the server
tls_socket.sendall(h2_connection.data_to_send())
-
- print(f"Response fully received: {len(body)} bytes")
-
- body_str = body.decode('utf-8')
-
- # tell the server we are closing the h2 connection
- h2_connection.close_connection()
- tls_socket.sendall(h2_connection.data_to_send())
-
- # close the socket
- tls_socket.close()
- except Exception:
+ except socket.timeout:
+ pass
+ except (ConnectionError, ssl.SSLError):
+ closed = True
+ elapsed = time.monotonic() - start
+ tls_socket.close()
+
+ if not closed:
+ print(f"Connection still open after {max_wait} seconds")
+ elif elapsed < active_timeout:
+ print(f"Connection closed after {elapsed:.1f} seconds, before the
{active_timeout} second active timeout")
+ else:
print("CONNECTION_TIMEOUT")
Review Comment:
This is the same point as the [earlier thread on this
line](https://github.com/apache/trafficserver/pull/13873#discussion_r4340376003).
`test_http2.py` asserts that `CONNECTION_TIMEOUT` is in the output, and pytest
prints that output when the assert fails, so a failure already shows which case
it hit.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
