From 9061197836f192a636021c60f5ff2098ba211991 Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Mon, 3 Aug 2026 13:57:18 +0900 Subject: [PATCH 1/5] Add HTTP/1.1 content delay for server chaos testing Add a delay key inside a content node which pauses between writing a message's headers and writing its body. This lets a replay file simulate an origin that starts a response and then stalls, which exercises proxy timeout and partial-response handling that no existing replay construct could reach. The delay is inserted in Session::write(HttpHeader) immediately before the write_body call, so it covers HTTP/1.1 both in the clear and over TLS. HTTP/2 is unaffected because H2Session overrides that method; those messages already express the same behavior with a delay on their DATA frame, so combining a content delay with a frames node is rejected with a diagnostic pointing at the DATA frame alternative. A shutdown during the delay abandons the body write, matching how the existing transaction delay behaves. A peer which departs during the delay is the expected outcome when the delay is used to trigger a proxy timeout, so the resulting body write failure is reported through the errata and annotated with the delay as its likely cause, without affecting the process exit code. The AuTest duration verifier only matched the plural form of the client timing line, so its regex now also accepts the singular form which a single transaction replay emits. --- README.md | 42 ++++++ schema/replay_schema.json | 8 ++ src/core/YamlParser.cc | 42 ++++++ src/core/http.cc | 26 ++++ src/core/http.h | 8 ++ tests/unit_tests/test_YamlParser.cc | 52 ++++++++ tests/unit_tests/test_http.cc | 130 +++++++++++++++++++ tests/uranium_tests/delay/content-delay.yaml | 51 ++++++++ tests/uranium_tests/delay/test_delay.py | 45 +++++++ tests/uranium_tests/delay/verify_duration.py | 4 +- 10 files changed, 407 insertions(+), 1 deletion(-) create mode 100644 tests/uranium_tests/delay/content-delay.yaml diff --git a/README.md b/README.md index 40eaa53d..8359637e 100644 --- a/README.md +++ b/README.md @@ -27,6 +27,7 @@ Table of Contents * [Protocol Specification](#protocol-specification) * [PROXY protocol support](#proxy-protocol-support) * [Session and Transaction Delay Specification](#session-and-transaction-delay-specification) + * [Content Delay Specification](#content-delay-specification) * [Keep Connection Open](#keep-connection-open) * [Traffic Verification Specification](#traffic-verification-specification) * [Request Presence Verification](#request-presence-verification) @@ -971,6 +972,47 @@ networks anything more precise than a millisecond will not generally be useful. See also [--rate <requests/second>](#--rate-requestssecond) below for rate specification of transactions. +### Content Delay Specification + +The `delay` node described above is applied before a message is sent. To pause +in the middle of a message instead, a `delay` node can be placed inside a +`content` node. The message headers are written, the delay is inserted, and +only then is the body written. This is useful for exercising how a proxy +handles an origin which starts a response and then stalls, such as verifying +that the proxy's timeouts fire at the point they should. + +```YAML + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Content-Length, '3432' ] + content: + size: 3432 + delay: 5s +``` + +The value uses the same unit-suffixed duration format described in [Session and +Transaction Delay Specification](#session-and-transaction-delay-specification). + +Be aware of the following characteristics of a `content` `delay` node: + +* This is an HTTP/1.x feature. HTTP/2 messages express the same behavior with a + `delay` on their `DATA` frame (see [HEADERS and DATA + frame](#headers-and-data-frame)), so specifying a `content` `delay` in a + message which also has a `frames` node is rejected as a replay file error. + HTTP/3 has no equivalent. +* A `content` `delay` composes with a transaction `delay`. A transaction which + specifies both waits before its headers and again before its body. +* The delay is inserted whenever a body write follows the headers, including + when that body is empty. It is not inserted for a request carrying `Expect: + 100-continue`, since no body is written at that point. +* If the peer closes the connection during the delay, which is the expected + outcome when the delay is being used to trigger a proxy timeout, the + subsequent body write fails and is reported. This does not by itself cause + the Verifier server to exit with a non-zero status. + ### Keep Connection Open In certain special situations, a user might need to keep the connection open diff --git a/schema/replay_schema.json b/schema/replay_schema.json index 7d5715f4..ce5ac31c 100644 --- a/schema/replay_schema.json +++ b/schema/replay_schema.json @@ -96,6 +96,10 @@ "data": { "description": "Content data.", "type": "string" + }, + "delay": { + "description": "Time to wait after writing the headers and before writing the body, such as '5s', '250ms', or '17000us'. HTTP/1.x only.", + "type": "string" } } }, @@ -111,6 +115,10 @@ "size": { "description": "Size of the payload in bytes.", "type": "number" + }, + "delay": { + "description": "Time to wait after writing the headers and before writing the body, such as '5s', '250ms', or '17000us'. HTTP/1.x only.", + "type": "string" } } } diff --git a/src/core/YamlParser.cc b/src/core/YamlParser.cc index c7a9ef2d..d39f6798 100644 --- a/src/core/YamlParser.cc +++ b/src/core/YamlParser.cc @@ -1091,10 +1091,52 @@ YamlParser::populate_http_message(YAML::Node const &node, HttpHeader &message) } } + // A "delay" in a "content" node is honored by the HTTP/1.x write path only. + // A message with an explicit frame sequence is HTTP/2, which expresses the + // same behavior with a delay on its DATA frame. Such a delay would otherwise + // be silently ignored, so reject it wherever it appears in these messages. + bool const has_frame_sequence = static_cast(node[YAML_FRAMES_KEY]); + auto note_delay_conflicts_with_frames = [&errata](YAML::Node const &delay_node) { + errata.note( + S_ERROR, + R"("{}" in a "{}" node at {} cannot be combined with a "{}" node.)" + R"( Specify the delay on the "{}" frame instead.)", + YAML_TIME_DELAY_KEY, + YAML_CONTENT_KEY, + delay_node.Mark(), + YAML_FRAMES_KEY, + H2_FRAME_DATA); + }; + if (has_frame_sequence) { + if (auto const content_node{node[YAML_CONTENT_KEY]}; + content_node && content_node.IsMap() && content_node[YAML_TIME_DELAY_KEY]) + { + note_delay_conflicts_with_frames(content_node[YAML_TIME_DELAY_KEY]); + } + } + for (size_t i = 0; i < data_frames.size(); ++i) { // Do this after parsing fields so it can override transfer encoding. if (auto content_node{data_frames.at(i)[YAML_CONTENT_KEY]}; content_node) { if (content_node.IsMap()) { + if (auto delay_node{content_node[YAML_TIME_DELAY_KEY]}; delay_node) { + if (has_frame_sequence) { + note_delay_conflicts_with_frames(delay_node); + } else if (!delay_node.IsScalar()) { + errata.note( + S_ERROR, + R"("{}" in a "{}" node at {} must be a scalar.)", + YAML_TIME_DELAY_KEY, + YAML_CONTENT_KEY, + delay_node.Mark()); + } else { + auto &&[content_delay, delay_errata] = interpret_delay_string(delay_node.Scalar()); + errata.note(std::move(delay_errata)); + if (errata.is_ok()) { + message._content_delay = content_delay; + } + } + } if (auto xf_node{content_node[YAML_CONTENT_TRANSFER_KEY]}; xf_node) { TextView xf{xf_node.Scalar()}; if (0 == strcasecmp("chunked"_tv, xf)) { diff --git a/src/core/http.cc b/src/core/http.cc index 906c66a1..44a715b6 100644 --- a/src/core/http.cc +++ b/src/core/http.cc @@ -1372,9 +1372,35 @@ Session::write(HttpHeader const &hdr) if (header_bytes_written == static_cast(w.size())) { zret.result() = header_bytes_written; if (!hdr.is_request_with_expect_100_continue()) { + if (hdr._content_delay > 0us) { + zret.note( + S_DIAG, + "Delaying the body for key {} per the content delay specification: {}.", + hdr.get_key(), + duration_cast(hdr._content_delay)); + if (!interruptible_sleep_for(hdr._content_delay)) { + zret.note( + S_DIAG, + "Shutdown was requested during the content delay for key {}. " + "The body will not be written.", + hdr.get_key()); + return zret; + } + } auto &&[body_bytes_written, body_write_errata] = write_body(hdr); + auto const body_write_failed = !body_write_errata.is_ok(); zret.note(std::move(body_write_errata)); zret.result() += body_bytes_written; + if (body_write_failed && hdr._content_delay > 0us) { + // A peer which timed out during the delay is the expected outcome for + // some replay files, so make the connection between the two explicit. + zret.note( + S_DIAG, + "The body write for key {} failed after a content delay of {}. " + "The peer likely closed the connection during the delay.", + hdr.get_key(), + duration_cast(hdr._content_delay)); + } } } else { zret.note( diff --git a/src/core/http.h b/src/core/http.h index f3c66679..406e7c91 100644 --- a/src/core/http.h +++ b/src/core/http.h @@ -645,6 +645,14 @@ class HttpHeader bool _content_length_p = false; size_t _content_length = 0; + /** How long to wait after writing the headers before writing the body. + * + * This is honored by the HTTP/1.x write path only. HTTP/2 messages express + * the same behavior via a per-frame @c delay on a @c DATA frame, and HTTP/3 + * has no support for it. + */ + std::chrono::microseconds _content_delay{0}; + /// The parsed headers contain "Connection: close" header. bool _contains_connection_close = false; diff --git a/tests/unit_tests/test_YamlParser.cc b/tests/unit_tests/test_YamlParser.cc index 46f0ff0b..9556b285 100644 --- a/tests/unit_tests/test_YamlParser.cc +++ b/tests/unit_tests/test_YamlParser.cc @@ -393,6 +393,58 @@ TEST_CASE("Verify server-response validation for on_connect", "[on_connect]") } } +TEST_CASE("Verify content delay parsing", "[content_delay]") +{ + LocalizerPhaseGuard localizer_phase; + + SECTION("A content delay is parsed") + { + auto const node = YAML::Load(R"( +status: 200 +content: + size: 10 + delay: 700ms +)"); + HttpHeader response{true}; + response.set_is_response(); + CHECK(YamlParser::populate_http_message(node, response).is_ok()); + CHECK(response._content_delay == 700ms); + } + + SECTION("A malformed content delay fails parsing") + { + auto const node = YAML::Load(R"( +status: 200 +content: + size: 10 + delay: 5parsecs +)"); + HttpHeader response{true}; + response.set_is_response(); + CHECK_FALSE(YamlParser::populate_http_message(node, response).is_ok()); + CHECK(response._content_delay == 0us); + } + + SECTION("A content delay alongside a DATA frame is rejected") + { + auto const node = YAML::Load(R"( +status: 200 +content: + size: 10 + delay: 5s +frames: + - HEADERS: + - DATA: + content: + size: 10 +)"); + HttpHeader response{true}; + response.set_is_response(); + CHECK_FALSE(YamlParser::populate_http_message(node, response).is_ok()); + CHECK(response._content_delay == 0us); + } +} + TEST_CASE("Verify proxy-request expectations parse correctly", "[yaml]") { LocalizerPhaseGuard localizer_phase; diff --git a/tests/unit_tests/test_http.cc b/tests/unit_tests/test_http.cc index 73aaabc6..39427c78 100644 --- a/tests/unit_tests/test_http.cc +++ b/tests/unit_tests/test_http.cc @@ -8,6 +8,14 @@ #include "catch.hpp" #include "core/http.h" +#include +#include +#include +#include +#include + +using namespace std::literals; + struct ParseUrlTestCase { std::string const description; @@ -372,3 +380,125 @@ TEST_CASE( CHECK_FALSE(errata.is_ok()); } + +namespace +{ +/// The generated body size used by the content delay tests. +constexpr size_t CONTENT_DELAY_BODY_SIZE = 16; + +/// The content delay used by the content delay tests. This is long enough to +/// be distinguishable from scheduling jitter but short enough to keep the unit +/// tests fast. +constexpr auto CONTENT_DELAY_DURATION = std::chrono::milliseconds{300}; + +/// The observed arrival times of the two halves of an HTTP/1 response. +struct ResponseArrival +{ + /// How long after the write began the end of the headers was observed. + std::chrono::steady_clock::duration headers; + /// How long after the write began the last body byte was observed. + std::chrono::steady_clock::duration body; +}; + +/** Build a minimal HTTP/1 response with a generated body. + * + * @param[in] content_delay The delay to apply between the headers and the body. + * @return A response ready to be handed to @c Session::write. + */ +HttpHeader +make_content_delay_response(std::chrono::microseconds content_delay) +{ + HttpHeader response; + response.set_is_http1(); + response.set_is_response(); + response.set_key("content-delay-key"); + response._http_version = "1.1"; + response._status = 200; + response._reason = "OK"; + response._content_length = CONTENT_DELAY_BODY_SIZE; + response._content_length_p = true; + response._content_delay = content_delay; + response._fields_rules->add_field("Content-Length", "16"); + return response; +} + +/** Write a response to one end of a socket pair and time its arrival. + * + * The response is written from a separate thread so the reader can observe + * when the headers arrive relative to the body. + * + * @param[in] content_delay The content delay to apply to the response. + * @return When the headers and the body were observed by the peer. + */ +ResponseArrival +time_response_arrival(std::chrono::microseconds content_delay) +{ + int fd_pair[2]; + REQUIRE(::socketpair(AF_UNIX, SOCK_STREAM, 0, fd_pair) == 0); + + Session session; + REQUIRE(session.set_fd(fd_pair[0]).is_ok()); + + auto const response = make_content_delay_response(content_delay); + auto const start_time = std::chrono::steady_clock::now(); + + swoc::Rv write_result{0}; + std::thread writer{[&session, &response, &write_result]() { + write_result = session.write(response); + }}; + + std::string received; + ResponseArrival arrival{}; + constexpr swoc::TextView HEADER_TERMINATOR = "\r\n\r\n"; + size_t expected_total = 0; + while (true) { + char buffer[256]; + auto const n = ::read(fd_pair[1], buffer, sizeof(buffer)); + REQUIRE(n > 0); + received.append(buffer, n); + + if (arrival.headers == std::chrono::steady_clock::duration::zero()) { + if (auto const header_end = received.find(HEADER_TERMINATOR); + header_end != std::string::npos) + { + arrival.headers = std::chrono::steady_clock::now() - start_time; + expected_total = header_end + HEADER_TERMINATOR.size() + CONTENT_DELAY_BODY_SIZE; + } + } + if (expected_total != 0 && received.size() >= expected_total) { + arrival.body = std::chrono::steady_clock::now() - start_time; + break; + } + } + + writer.join(); + CHECK(write_result.is_ok()); + CHECK(write_result.result() == static_cast(expected_total)); + + session.close(); + ::close(fd_pair[1]); + return arrival; +} +} // namespace + +TEST_CASE("Verify the HTTP/1 write path honors a content delay", "[content_delay]") +{ + HttpHeader::global_init(); + HttpHeader::set_max_content_length(CONTENT_DELAY_BODY_SIZE); + + SECTION("A response without a content delay sends its body immediately") + { + auto const arrival = time_response_arrival(0us); + + CHECK(arrival.headers < CONTENT_DELAY_DURATION); + CHECK(arrival.body < CONTENT_DELAY_DURATION); + } + + SECTION("A response with a content delay sends its headers before waiting") + { + auto const arrival = time_response_arrival(CONTENT_DELAY_DURATION); + + CHECK(arrival.headers < CONTENT_DELAY_DURATION); + CHECK(arrival.body >= CONTENT_DELAY_DURATION); + } +} diff --git a/tests/uranium_tests/delay/content-delay.yaml b/tests/uranium_tests/delay/content-delay.yaml new file mode 100644 index 00000000..9cc75181 --- /dev/null +++ b/tests/uranium_tests/delay/content-delay.yaml @@ -0,0 +1,51 @@ +# @file +# +# Copyright 2026, Verizon Media +# SPDX-License-Identifier: Apache-2.0 +# + +meta: + version: '1.0' + +# Verify the handling of a "delay" node inside a "content" node, which delays +# the response body after the response headers have been sent. This is an +# HTTP/1.x feature, so the session in this file is HTTP/1.1 over TCP. + +sessions: + +# +# A response body delayed by 700 ms behind a Content-Length response. +# +- transactions: + + - client-request: + method: GET + url: /pictures/flower.jpeg + version: '1.1' + headers: + fields: + - [ Host, www.example.com ] + - [ uuid, content-length-request ] + + proxy-request: + url: + - [ path, { value: flower.jpeg, as: contains } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Date, "Sat, 16 Mar 2019 03:11:36 GMT" ] + - [ Content-Type, image/jpeg ] + - [ Content-Length, '3432' ] + - [ Connection, keep-alive ] + content: + size: 3432 + delay: 700ms + + proxy-response: + status: 200 + headers: + fields: + - [ Content-Length, { value: '3432', as: equal } ] diff --git a/tests/uranium_tests/delay/test_delay.py b/tests/uranium_tests/delay/test_delay.py index d9bd2aba..f5d5632d 100644 --- a/tests/uranium_tests/delay/test_delay.py +++ b/tests/uranium_tests/delay/test_delay.py @@ -94,6 +94,51 @@ ) process.stdout.contains('Good', 'The verifier script should report success.') +# +# Test 5: Run transactions with a content delay, which delays the response body +# behind the response headers. +# +case = suite.case("Verify the handling of the content delay specification.") +client = case.add_client("client_content_delay", "content-delay.yaml") +server = case.add_server("server_content_delay", "content-delay.yaml") + +# A content delay is an HTTP/1.x feature, so only an HTTP/1 proxy is needed. +proxy = case.add_proxy("proxy_http_content_delay", listen_port=client.http_port, + server_port=server.http_port) + +server.stdout.contains("Ready with 1 transaction.", + "The server should have parsed 1 transaction.") + +server.stdout.contains( + "Delaying the body for key content-length-request per the content delay specification: 700", + "The server should delay the body of the response.") + +client.stdout.contains( + "1 transaction in 1 session .* in .* milliseconds", + "The client should have reported running the transaction with timing data.") + +client.stdout.excludes("Violation:", + "There should be no verification errors because there are none added.") + +server.stdout.excludes("Violation:", + "There should be no verification errors because there are none added.") + +# +# Test 6: Verify that the timing data indicates that the content delay took +# place. +# +case = suite.case("Verify the content delay replay took an expected amount of time to run.") +client_output = client.stdout.path +# The response delays 700 ms before its body. Without the content delay the +# transaction would finish almost immediately. +expected_min_delay_ms = "700" +process = case.add_process( + "verify-content-delay", + ["python3", verifier_script, client_output, expected_min_delay_ms], + copies=[verifier_script], +) +process.stdout.contains('Good', 'The verifier script should report success.') + def test_uranium_suite(uranium): uranium.run(suite) diff --git a/tests/uranium_tests/delay/verify_duration.py b/tests/uranium_tests/delay/verify_duration.py index 6e075bc3..ab9d2961 100755 --- a/tests/uranium_tests/delay/verify_duration.py +++ b/tests/uranium_tests/delay/verify_duration.py @@ -23,8 +23,10 @@ def line_has_timing_data(line): True >>> line_has_timing_data(r' [1]: 2 transactions in 2 sessions (reuse 1) in 1790 milliseconds (0.1 / millisecond).\\n') True + >>> line_has_timing_data(' [1]: 1 transaction in 1 session (reuse 1) in 732 milliseconds (0.1 / millisecond).') + True """ - line_matcher = re.compile('.*transactions in .* sessions .* in .* milliseconds.*') + line_matcher = re.compile('.*transactions? in .* sessions? .* in .* milliseconds.*') return line_matcher.match(line) is not None From cbaa00acb096b33f77ddf2187a71b4af352c5a33 Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Mon, 31 Aug 2026 08:47:32 +0900 Subject: [PATCH 2/5] format --- tests/unit_tests/test_http.cc | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/tests/unit_tests/test_http.cc b/tests/unit_tests/test_http.cc index 39427c78..b9b1f382 100644 --- a/tests/unit_tests/test_http.cc +++ b/tests/unit_tests/test_http.cc @@ -443,9 +443,8 @@ time_response_arrival(std::chrono::microseconds content_delay) auto const start_time = std::chrono::steady_clock::now(); swoc::Rv write_result{0}; - std::thread writer{[&session, &response, &write_result]() { - write_result = session.write(response); - }}; + std::thread writer{ + [&session, &response, &write_result]() { write_result = session.write(response); }}; std::string received; ResponseArrival arrival{}; @@ -458,8 +457,7 @@ time_response_arrival(std::chrono::microseconds content_delay) received.append(buffer, n); if (arrival.headers == std::chrono::steady_clock::duration::zero()) { - if (auto const header_end = received.find(HEADER_TERMINATOR); - header_end != std::string::npos) + if (auto const header_end = received.find(HEADER_TERMINATOR); header_end != std::string::npos) { arrival.headers = std::chrono::steady_clock::now() - start_time; expected_total = header_end + HEADER_TERMINATOR.size() + CONTENT_DELAY_BODY_SIZE; From 0ddfa2a5e435267808d4322a2edcf77c74f2f1fd Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Mon, 31 Aug 2026 10:13:53 +0900 Subject: [PATCH 3/5] Extend content delay to HTTP/2 and HTTP/3 The HTTP/2 and HTTP/3 write paths hand the whole message to nghttp2 / nghttp3 at once, so a content delay had no place to land. Instead of sleeping mid-write, withhold the body from the library: the data source callback reports NGHTTP2_ERR_DEFERRED / NGHTTP3_ERR_WOULDBLOCK while the stream's content delay is non-zero, which flushes HEADERS and stops. write() then waits out the delay, zeroes the delay, and resumes the stream so the body follows in its own DATA frame. HTTP/2 keeps draining its receive window during the wait so flow control and peer-initiated frames are not stalled. HTTP/3 deliberately does not read: ngtcp2_progress_ingress treats a poll timeout as fatal and closes the session, and silence is the point of the feature anyway. It services ngtcp2's expiry timers in 20 ms slices instead. Both write() paths now hold a shared_ptr to the stream state, since servicing the connection mid-write can retire a stream from the map. Expect: 100-continue requests still skip the delay on all three protocols, matching the existing HTTP/1 behavior. Delayed 100-continue bodies are left for a follow-up. --- README.md | 26 +++-- schema/replay_schema.json | 4 +- src/core/YamlParser.cc | 8 +- src/core/http.h | 11 +- src/core/http2.cc | 93 ++++++++++++++- src/core/http2.h | 26 +++++ src/core/http3.cc | 110 +++++++++++++++++- src/core/http3.h | 25 ++++ tests/unit_tests/test_YamlParser.cc | 15 +++ .../delay/content-delay-http2.yaml | 84 +++++++++++++ .../delay/content-delay-http3.yaml | 62 ++++++++++ tests/uranium_tests/delay/test_delay.py | 102 +++++++++++++++- 12 files changed, 542 insertions(+), 24 deletions(-) create mode 100644 tests/uranium_tests/delay/content-delay-http2.yaml create mode 100644 tests/uranium_tests/delay/content-delay-http3.yaml diff --git a/README.md b/README.md index 8359637e..b9c569cc 100644 --- a/README.md +++ b/README.md @@ -996,18 +996,28 @@ that the proxy's timeouts fire at the point they should. The value uses the same unit-suffixed duration format described in [Session and Transaction Delay Specification](#session-and-transaction-delay-specification). +This works for HTTP/1.x, HTTP/2, and HTTP/3, and for both request and response +bodies. For HTTP/2 and HTTP/3 the headers are put on the wire in their `HEADERS` +frame, the body is withheld from the protocol library for the duration of the +delay, and the stream is then resumed so the body follows in its own `DATA` +frame. + Be aware of the following characteristics of a `content` `delay` node: -* This is an HTTP/1.x feature. HTTP/2 messages express the same behavior with a - `delay` on their `DATA` frame (see [HEADERS and DATA - frame](#headers-and-data-frame)), so specifying a `content` `delay` in a - message which also has a `frames` node is rejected as a replay file error. - HTTP/3 has no equivalent. +* An HTTP/2 message with an explicit `frames` node expresses the same behavior + with a `delay` on its `DATA` frame (see [HEADERS and DATA + frame](#headers-and-data-frame)). Specifying a `content` `delay` in a message + which also has a `frames` node is therefore rejected as a replay file error. * A `content` `delay` composes with a transaction `delay`. A transaction which specifies both waits before its headers and again before its body. -* The delay is inserted whenever a body write follows the headers, including - when that body is empty. It is not inserted for a request carrying `Expect: - 100-continue`, since no body is written at that point. +* Incoming traffic continues to be processed during an HTTP/2 or HTTP/3 content + delay, so flow control and other peer-initiated frames are not stalled behind + it. The HTTP/1.x delay is a plain wait, since there is nothing to multiplex. +* For HTTP/1.x, the delay is inserted whenever a body write follows the headers, + including when that body is empty. For HTTP/2 and HTTP/3 there is no `DATA` + frame to hold back when the body is empty, so the delay is not inserted. +* The delay is not inserted for a request carrying `Expect: 100-continue`, since + no body is written at that point. * If the peer closes the connection during the delay, which is the expected outcome when the delay is being used to trigger a proxy timeout, the subsequent body write fails and is reported. This does not by itself cause diff --git a/schema/replay_schema.json b/schema/replay_schema.json index ce5ac31c..54b10fcf 100644 --- a/schema/replay_schema.json +++ b/schema/replay_schema.json @@ -98,7 +98,7 @@ "type": "string" }, "delay": { - "description": "Time to wait after writing the headers and before writing the body, such as '5s', '250ms', or '17000us'. HTTP/1.x only.", + "description": "Time to wait after writing the headers and before writing the body, such as '5s', '250ms', or '17000us'. Cannot be combined with a 'frames' node.", "type": "string" } } @@ -117,7 +117,7 @@ "type": "number" }, "delay": { - "description": "Time to wait after writing the headers and before writing the body, such as '5s', '250ms', or '17000us'. HTTP/1.x only.", + "description": "Time to wait after writing the headers and before writing the body, such as '5s', '250ms', or '17000us'. Cannot be combined with a 'frames' node.", "type": "string" } } diff --git a/src/core/YamlParser.cc b/src/core/YamlParser.cc index d39f6798..b7290308 100644 --- a/src/core/YamlParser.cc +++ b/src/core/YamlParser.cc @@ -1091,10 +1091,10 @@ YamlParser::populate_http_message(YAML::Node const &node, HttpHeader &message) } } - // A "delay" in a "content" node is honored by the HTTP/1.x write path only. - // A message with an explicit frame sequence is HTTP/2, which expresses the - // same behavior with a delay on its DATA frame. Such a delay would otherwise - // be silently ignored, so reject it wherever it appears in these messages. + // A "delay" in a "content" node delays the body behind the headers. A message + // with an explicit frame sequence expresses the same behavior with a delay on + // its DATA frame. Such a delay would otherwise be silently ignored, so reject + // it wherever it appears in these messages. bool const has_frame_sequence = static_cast(node[YAML_FRAMES_KEY]); auto note_delay_conflicts_with_frames = [&errata](YAML::Node const &delay_node) { errata.note( diff --git a/src/core/http.h b/src/core/http.h index 406e7c91..fc8dde51 100644 --- a/src/core/http.h +++ b/src/core/http.h @@ -647,9 +647,14 @@ class HttpHeader /** How long to wait after writing the headers before writing the body. * - * This is honored by the HTTP/1.x write path only. HTTP/2 messages express - * the same behavior via a per-frame @c delay on a @c DATA frame, and HTTP/3 - * has no support for it. + * This is honored by the HTTP/1.x, HTTP/2, and HTTP/3 write paths. For + * HTTP/2 and HTTP/3 the headers are put on the wire, the body is withheld + * from the protocol library for the duration of the delay, and the stream is + * then resumed so that the body follows in its own DATA frame. + * + * An HTTP/2 message with an explicit @c frames sequence expresses the same + * behavior via a per-frame @c delay on its @c DATA frame, so the two are + * rejected in combination at parse time. */ std::chrono::microseconds _content_delay{0}; diff --git a/src/core/http2.cc b/src/core/http2.cc index 5f26741e..609b5b67 100644 --- a/src/core/http2.cc +++ b/src/core/http2.cc @@ -1475,6 +1475,20 @@ data_read_callback( stream_state = iter->second.get(); } TextView body_sent = ""; + if (stream_state->_content_delay > 0us) { + // The HEADERS frame has to reach the wire before the content delay starts, + // so hand nghttp2 nothing for now. This flushes what has been serialized so + // far and leaves the stream deferred. H2Session::write waits out the delay + // and then resumes the stream, at which point this callback is called again + // with the delay cleared. + errata.note( + S_DIAG, + "Deferring the HTTP/2 DATA frame for key {} of stream id {} per the content delay " + "specification.", + stream_state->_key, + stream_id); + return NGHTTP2_ERR_DEFERRED; + } if (!stream_state->_wait_for_continue) { num_to_copy = std::min(length, stream_state->_send_body_length - stream_state->_send_body_offset); @@ -1564,6 +1578,61 @@ H2Session::frame_delay(HttpHeader const &hdr, H2Frame curr_frame) return errata; } +Errata +H2Session::content_delay(H2StreamState &stream_state) +{ + Errata errata; + + auto const content_delay = stream_state._content_delay; + errata.note( + S_DIAG, + "Delaying the body for key {} of stream id {} per the content delay specification: {}.", + stream_state._key, + stream_state.get_stream_id(), + duration_cast(content_delay)); + // Make sure the diagnostic for the delay is emitted before the body. + errata.sink(); + + std::chrono::duration delay_time = content_delay; + auto const next_time = ClockType::now() + delay_time; + while (delay_time > 0ms) { + // Make use of our delay time to process any incoming frames. + auto &&[progress, progress_errata] = + drain_h2_receive_window(*this, duration_cast(delay_time), "content delay"); + errata.note(std::move(progress_errata)); + if (!errata.is_ok()) { + // A peer which gives up during the delay is the expected outcome for some + // replay files, so make the connection between the two explicit rather + // than reporting a bare read failure. + errata.sink(); + errata.note( + S_DIAG, + "The peer closed the connection or stopped responding during the content delay of {} for " + "key {}.", + duration_cast(content_delay), + stream_state._key); + break; + } + delay_time = next_time - ClockType::now(); + } + + // Let the body flow again regardless of how the delay ended. If the peer is + // gone the write simply fails and is reported by the caller. + stream_state._content_delay = 0us; + if (auto const rv = nghttp2_session_resume_data(this->_session, stream_state.get_stream_id()); + rv != 0) + { + errata.note( + S_ERROR, + "Failed to resume the HTTP/2 DATA frame for key {} on stream {} after the content delay: " + "{}", + stream_state._key, + stream_state.get_stream_id(), + nghttp2_strerror(rv)); + } + return errata; +} + Errata H2Session::submit_headers_frame( HttpHeader const &hdr, @@ -1779,6 +1848,13 @@ H2Session::write(HttpHeader const &hdr) int32_t submit_result = 0; H2StreamState *stream_state = nullptr; std::shared_ptr new_stream_state{nullptr}; + /** A reference held for the duration of this write. + * + * Processing incoming frames, which happens during a content delay, can + * retire a stream from the stream map. Holding a reference keeps + * @a stream_state valid until this write is finished with it. + */ + std::shared_ptr stream_state_reference{nullptr}; if (hdr.is_response()) { stream_id = hdr._stream_id; auto stream_map_iter = _stream_map.find(stream_id); @@ -1786,7 +1862,8 @@ H2Session::write(HttpHeader const &hdr) zret.note(S_ERROR, "Could not find registered stream for stream id: {}", stream_id); return zret; } - stream_state = stream_map_iter->second.get(); + stream_state_reference = stream_map_iter->second; + stream_state = stream_state_reference.get(); } else { new_stream_state = std::make_shared(); stream_state = new_stream_state.get(); @@ -1896,6 +1973,9 @@ H2Session::write(HttpHeader const &hdr) stream_state->_send_body_length = content.size(); stream_state->_send_body_offset = 0; stream_state->_last_data_frame = true; + // A request awaiting a 100 Continue has no body to write at this point, + // so there is nothing to hold back. This matches the HTTP/1 write path. + stream_state->_content_delay = stream_state->_wait_for_continue ? 0us : hdr._content_delay; if (hdr.is_response()) { // Pack the trailer headers. pack_headers( @@ -1959,6 +2039,17 @@ H2Session::write(HttpHeader const &hdr) // Kick off the send logic to put the data on the wire zret.result() = send_nghttp2_data(_session, nullptr, 0, 0, this); + + if (zret.is_ok() && stream_state->_content_delay > 0us) { + // The headers are on the wire and the DATA frame was withheld from + // nghttp2. Wait out the content delay and then let the body follow. + zret.note(content_delay(*stream_state)); + if (zret.is_ok()) { + // Make sure the logging of the delay is emitted before the body. + zret.errata().sink(); + } + zret.result() += send_nghttp2_data(_session, nullptr, 0, 0, this); + } } return zret; diff --git a/src/core/http2.h b/src/core/http2.h index 3fa89135..6bc75740 100644 --- a/src/core/http2.h +++ b/src/core/http2.h @@ -66,6 +66,18 @@ class H2StreamState bool _wait_for_continue = false; bool _last_data_frame = false; bool _wait_for_response_after_100_continue = false; + + /** How long to wait after the HEADERS frame is on the wire before the DATA + * frame is sent. + * + * This is the @c content @c delay of the message being written. It is zero + * for messages which do not specify one. While it is non-zero the nghttp2 + * data source read callback defers the DATA frame so that nghttp2 flushes the + * HEADERS frame and stops. H2Session::write zeroes it and resumes the stream + * once the delay has elapsed. + */ + std::chrono::microseconds _content_delay{0}; + std::string _key; nghttp2_nv *_trailer_to_send = nullptr; @@ -226,6 +238,20 @@ class H2Session : public TLSSession bool request_has_outstanding_stream_dependencies(HttpHeader const &request) const; swoc::Errata frame_delay(HttpHeader const &hdr, H2Frame curr_frame); + + /** Wait out the @c content @c delay of a message whose DATA frame is deferred. + * + * The session is serviced for the duration of the wait so that incoming + * frames, including a peer closing the connection, are processed rather than + * stalled behind the delay. + * + * @param[in,out] stream_state The stream whose DATA frame is deferred. Its + * @c _content_delay is zeroed and the stream resumed before returning. + * + * @return Any errata from servicing the session during the delay. + */ + swoc::Errata content_delay(H2StreamState &stream_state); + swoc::Errata submit_headers_frame( HttpHeader const &hdr, H2StreamState *stream_state, diff --git a/src/core/http3.cc b/src/core/http3.cc index 6399bfa4..ce7f8af5 100644 --- a/src/core/http3.cc +++ b/src/core/http3.cc @@ -57,6 +57,13 @@ constexpr uint64_t H3_STREAM_CREATION_ERROR = 0x103; constexpr bool UNIDIRECTIONAL = true; constexpr unsigned char H3_ALPN[] = {2, 'h', '3'}; +/** The longest single wait taken while serving a @c content @c delay. + * + * Bounding the wait keeps the QUIC connection's timers serviced and shutdown + * requests honored while the body is being held back. + */ +constexpr auto Content_Delay_Service_Interval = 20ms; + char const * nghttp3_error(int error) { @@ -144,6 +151,19 @@ cb_h3_readfunction( *pflags = NGHTTP3_DATA_FLAG_EOF; return 0; } + if (stream_state->content_delay > 0us) { + // The HEADERS frame has to reach the wire before the content delay starts, + // so report that the body is not available yet. H3Session::write waits out + // the delay and then resumes the stream, at which point this callback is + // called again with the delay cleared. + errata.note( + S_DIAG, + "Withholding the HTTP/3 body for key {} of stream id {} per the content delay " + "specification.", + stream_state->key, + stream_id); + return NGHTTP3_ERR_WOULDBLOCK; + } vec[0].base = reinterpret_cast(const_cast(stream_state->body_to_send.data())); vec[0].len = stream_state->body_to_send.size(); @@ -954,6 +974,71 @@ H3Session::pack_headers(HttpHeader const &hdr, nghttp3_nv *&nv_hdr, int &hdr_cou return errata; } +Errata +H3Session::content_delay(H3StreamState &stream_state) +{ + Errata errata; + + auto const content_delay = stream_state.content_delay; + auto const stream_id = stream_state.get_stream_id(); + errata.note( + S_DIAG, + "Delaying the body for key {} of stream id {} per the content delay specification: {}.", + stream_state.key, + stream_id, + duration_cast(content_delay)); + // Make sure the diagnostic for the delay is emitted before the body. + errata.sink(); + + auto const deadline = ClockType::now() + content_delay; + for (auto remaining = content_delay; remaining > 0us; + remaining = duration_cast(deadline - ClockType::now())) + { + // Service the connection in bounded slices so its timers keep running and + // shutdown requests stay responsive. The body itself stays withheld: the + // data reader reports NGHTTP3_ERR_WOULDBLOCK while content_delay is set. + auto const slice = + std::min(duration_cast(remaining), Content_Delay_Service_Interval); + auto &&[progressed, progress_errata] = progress_http3(*this, slice); + static_cast(progressed); + errata.note(std::move(progress_errata)); + if (!errata.is_ok()) { + // A peer which gives up during the delay is the expected outcome for some + // replay files, so make the connection between the two explicit rather + // than reporting a bare I/O failure. + errata.sink(); + errata.note( + S_DIAG, + "The peer closed the connection or stopped responding during the content delay of {} " + "for key {}.", + duration_cast(content_delay), + stream_state.key); + break; + } + if (shutdown_requested()) { + errata.note( + S_DIAG, + "Shutdown was requested during the content delay for key {}.", + stream_state.key); + break; + } + } + + // Let the body flow again regardless of how the delay ended. If the peer is + // gone the write simply fails and is reported by the caller. + stream_state.content_delay = 0us; + if (auto const rv = nghttp3_conn_resume_stream(quic_socket.h3conn, stream_id); rv != 0) { + errata.note( + S_ERROR, + "Failed to resume the HTTP/3 body for key {} on stream {} after the content delay: {} ({})", + stream_state.key, + stream_id, + nghttp3_error(rv), + rv); + } + return errata; +} + swoc::Rv H3Session::write(HttpHeader const &hdr) { @@ -961,6 +1046,13 @@ H3Session::write(HttpHeader const &hdr) auto const key = hdr.get_key(); H3StreamState *stream_state = nullptr; std::shared_ptr new_stream_state; + /** A reference held for the duration of this write. + * + * Servicing the connection, which happens during a content delay, can retire + * a stream from the stream map. Holding a reference keeps @a stream_state + * valid until this write is finished with it. + */ + std::shared_ptr stream_state_reference; int64_t stream_id = 0; if (hdr.is_response()) { @@ -970,7 +1062,8 @@ H3Session::write(HttpHeader const &hdr) zret.note(S_ERROR, "Could not find registered stream for stream id: {}", stream_id); return zret; } - stream_state = spot->second.get(); + stream_state_reference = spot->second; + stream_state = stream_state_reference.get(); } else { auto &&[stream, stream_errata] = quic_socket.open_stream(!UNIDIRECTIONAL); zret.note(std::move(stream_errata)); @@ -1006,6 +1099,9 @@ H3Session::write(HttpHeader const &hdr) nghttp3_data_reader data_reader{.read_data = cb_h3_readfunction}; stream_state->body_to_send = content; stream_state->wait_for_continue = hdr.is_request_with_expect_100_continue(); + // A request awaiting a 100 Continue has no body to write at this point, so + // there is nothing to hold back. This matches the HTTP/1 write path. + stream_state->content_delay = stream_state->wait_for_continue ? 0us : hdr._content_delay; if (hdr.is_response()) { submit_result = nghttp3_conn_submit_response( quic_socket.h3conn, @@ -1063,6 +1159,18 @@ H3Session::write(HttpHeader const &hdr) static_cast(progressed); zret.note(std::move(progress_errata)); } + if (zret.is_ok() && stream_state->content_delay > 0us) { + // The headers are on the wire and the body was withheld from nghttp3. Wait + // out the content delay and then let the body follow. + zret.note(content_delay(*stream_state)); + if (zret.is_ok()) { + // Make sure the logging of the delay is emitted before the body. + zret.errata().sink(); + } + auto &&[progressed, progress_errata] = progress_http3(*this, 0ms); + static_cast(progressed); + zret.note(std::move(progress_errata)); + } return zret; } diff --git a/src/core/http3.h b/src/core/http3.h index 7a60eaaa..9ee73b77 100644 --- a/src/core/http3.h +++ b/src/core/http3.h @@ -135,6 +135,17 @@ class H3StreamState bool wait_for_continue = false; ///< Whether the request waits for a 100 response. size_t num_data_bytes_written = 0; ///< Unacknowledged DATA payload bytes. + /** How long to wait after the HEADERS frame is on the wire before the DATA + * frame is sent. + * + * This is the @c content @c delay of the message being written. It is zero + * for messages which do not specify one. While it is non-zero the nghttp3 + * data reader reports that it would block so that only the HEADERS frame is + * flushed. H3Session::write zeroes it and resumes the stream once the delay + * has elapsed. + */ + std::chrono::microseconds content_delay{0}; + private: bool m_will_receive_request = false; int64_t m_stream_id = 0; @@ -269,6 +280,20 @@ class H3Session : public Session swoc::Errata client_ssl_session_init(SSL_CTX *client_context); swoc::Errata initialize_http3_connection(); swoc::Errata receive_responses(); + + /** Wait out the @c content @c delay of a message whose body is withheld. + * + * The connection is serviced for the duration of the wait so that incoming + * packets, including a peer closing the connection, are processed rather than + * stalled behind the delay. + * + * @param[in,out] stream_state The stream whose body is withheld. Its + * @c content_delay is zeroed and the stream resumed before returning. + * + * @return Any errata from servicing the connection during the delay. + */ + swoc::Errata content_delay(H3StreamState &stream_state); + bool request_has_outstanding_stream_dependencies(HttpHeader const &request) const; private: diff --git a/tests/unit_tests/test_YamlParser.cc b/tests/unit_tests/test_YamlParser.cc index 9556b285..77d975ee 100644 --- a/tests/unit_tests/test_YamlParser.cc +++ b/tests/unit_tests/test_YamlParser.cc @@ -411,6 +411,21 @@ status: 200 CHECK(response._content_delay == 700ms); } + SECTION("A content delay on a request is parsed") + { + auto const node = YAML::Load(R"( +method: POST +url: /a/path +content: + size: 10 + delay: 250ms +)"); + HttpHeader request{true}; + request.set_is_request(); + CHECK(YamlParser::populate_http_message(node, request).is_ok()); + CHECK(request._content_delay == 250ms); + } + SECTION("A malformed content delay fails parsing") { auto const node = YAML::Load(R"( diff --git a/tests/uranium_tests/delay/content-delay-http2.yaml b/tests/uranium_tests/delay/content-delay-http2.yaml new file mode 100644 index 00000000..18d01485 --- /dev/null +++ b/tests/uranium_tests/delay/content-delay-http2.yaml @@ -0,0 +1,84 @@ +# @file +# +# Copyright 2026, Verizon Media +# SPDX-License-Identifier: Apache-2.0 +# + +meta: + version: '1.0' + +# Verify the handling of a "delay" node inside a "content" node for HTTP/2. The +# headers are sent in their HEADERS frame, the delay is inserted, and the body +# then follows in its DATA frame. Both directions are covered: a delayed +# response body from the Verifier server and a delayed request body from the +# Verifier client. + +sessions: + +- protocol: + stack: http2 + tls: + sni: test_sni + + transactions: + + # + # A response body delayed by 700 ms behind the response headers. + # + - client-request: + headers: + fields: + - [ :method, GET ] + - [ :scheme, https ] + - [ :authority, www.example.com ] + - [ :path, /pictures/flower.jpeg ] + - [ uuid, http2-delayed-response-body ] + + proxy-request: + url: + - [ path, { value: flower.jpeg, as: contains } ] + + server-response: + headers: + fields: + - [ :status, 200 ] + - [ Date, "Sat, 16 Mar 2019 03:11:36 GMT" ] + - [ Content-Type, image/jpeg ] + content: + size: 3432 + delay: 700ms + + proxy-response: + status: 200 + + # + # A request body delayed by 700 ms behind the request headers. + # + - client-request: + headers: + fields: + - [ :method, POST ] + - [ :scheme, https ] + - [ :authority, www.example.com ] + - [ :path, /pictures/rose.jpeg ] + - [ Content-Type, image/jpeg ] + - [ uuid, http2-delayed-request-body ] + content: + size: 399 + delay: 700ms + + proxy-request: + url: + - [ path, { value: rose.jpeg, as: contains } ] + + server-response: + headers: + fields: + - [ :status, 200 ] + - [ Date, "Sat, 16 Mar 2019 03:11:36 GMT" ] + - [ Content-Type, image/jpeg ] + content: + size: 32 + + proxy-response: + status: 200 diff --git a/tests/uranium_tests/delay/content-delay-http3.yaml b/tests/uranium_tests/delay/content-delay-http3.yaml new file mode 100644 index 00000000..beb6d371 --- /dev/null +++ b/tests/uranium_tests/delay/content-delay-http3.yaml @@ -0,0 +1,62 @@ +# @file +# +# Copyright 2026, Verizon Media +# SPDX-License-Identifier: Apache-2.0 +# + +meta: + version: '1.0' + +# Verify the handling of a "delay" node inside a "content" node for HTTP/3. The +# headers are sent, the delay is inserted, and the body then follows. +# +# The test proxy only bridges HTTP/3 on the client side to HTTP/1 on the server +# side, so this file exercises the Verifier client's request body. Delayed +# response bodies over HTTP/1 are covered by content-delay.yaml. + +sessions: + +- protocol: + stack: http3 + tls: + sni: test_sni + + transactions: + + # + # A request body delayed by 700 ms behind the request headers. + # + - client-request: + headers: + fields: + - [ :method, POST ] + - [ :scheme, https ] + - [ :authority, www.example.com ] + - [ :path, /pictures/flower.jpeg ] + - [ Content-Type, image/jpeg ] + - [ uuid, http3-delayed-request-body ] + content: + size: 399 + delay: 700ms + + proxy-request: + url: + - [ path, { value: flower.jpeg, as: contains } ] + + headers: + fields: + - [ Content-Length, { value: '399', as: equal } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Date, "Sat, 16 Mar 2019 03:11:36 GMT" ] + - [ Content-Type, image/jpeg ] + - [ Content-Length, '32' ] + content: + size: 32 + + proxy-response: + status: 200 diff --git a/tests/uranium_tests/delay/test_delay.py b/tests/uranium_tests/delay/test_delay.py index f5d5632d..2a8508d1 100644 --- a/tests/uranium_tests/delay/test_delay.py +++ b/tests/uranium_tests/delay/test_delay.py @@ -106,16 +106,14 @@ proxy = case.add_proxy("proxy_http_content_delay", listen_port=client.http_port, server_port=server.http_port) -server.stdout.contains("Ready with 1 transaction.", - "The server should have parsed 1 transaction.") +server.stdout.contains("Ready with 1 transaction.", "The server should have parsed 1 transaction.") server.stdout.contains( "Delaying the body for key content-length-request per the content delay specification: 700", "The server should delay the body of the response.") -client.stdout.contains( - "1 transaction in 1 session .* in .* milliseconds", - "The client should have reported running the transaction with timing data.") +client.stdout.contains("1 transaction in 1 session .* in .* milliseconds", + "The client should have reported running the transaction with timing data.") client.stdout.excludes("Violation:", "There should be no verification errors because there are none added.") @@ -139,6 +137,100 @@ ) process.stdout.contains('Good', 'The verifier script should report success.') +# +# Test 7: Run HTTP/2 transactions with a content delay, one delaying the +# response body and one delaying the request body. +# +case = suite.case("Verify the handling of the content delay specification over HTTP/2.") +client = case.add_client("client_content_delay_http2", "content-delay-http2.yaml") +server = case.add_server("server_content_delay_http2", "content-delay-http2.yaml") + +proxy = case.add_proxy("proxy_http2_content_delay", listen_port=client.https_port, + server_port=server.https_port, use_ssl=True, use_http2_to_2=True) + +server.stdout.contains("Ready with 2 transactions.", + "The server should have parsed 2 transactions.") + +server.stdout.contains( + "Delaying the body for key http2-delayed-response-body of stream id [0-9]+ per the content " + "delay specification: 700", "The server should delay the body of the response.") + +client.stdout.contains( + "Delaying the body for key http2-delayed-request-body of stream id [0-9]+ per the content " + "delay specification: 700", "The client should delay the body of the request.") + +# The bodies have to actually arrive after their delay, not be dropped by the +# deferral. +client.stdout.contains("Received an HTTP/2 body of 3432 bytes for key http2-delayed-response-body", + "The client should receive the delayed response body.") + +server.stdout.contains("Received an HTTP/2 body of 399 bytes for key http2-delayed-request-body", + "The server should receive the delayed request body.") + +client.stdout.excludes("Violation:", + "There should be no verification errors because there are none added.") + +server.stdout.excludes("Violation:", + "There should be no verification errors because there are none added.") + +# +# Test 8: Verify that the timing data indicates that the HTTP/2 content delays +# took place. +# +case = suite.case("Verify the HTTP/2 content delay replay took an expected amount of time to run.") +client_output = client.stdout.path +# The two 700 ms delays overlap, so only one of them is guaranteed to show up in +# the total run time. +expected_min_delay_ms = "700" +process = case.add_process( + "verify-http2-content-delay", + ["python3", verifier_script, client_output, expected_min_delay_ms], + copies=[verifier_script], +) +process.stdout.contains('Good', 'The verifier script should report success.') + +# +# Test 9: Run an HTTP/3 transaction with a content delay on the request body. +# +case = suite.case("Verify the handling of the content delay specification over HTTP/3.") +http3_args = "--poll-timeout 10000" +client = case.add_client("client_content_delay_http3", "content-delay-http3.yaml", + other_args=http3_args) +server = case.add_server("server_content_delay_http3", "content-delay-http3.yaml", + other_args=http3_args) + +proxy = case.add_proxy("proxy_http3_content_delay", listen_port=client.http3_port, + server_port=server.http_port, use_ssl=True, use_http3_to_1=True) + +server.stdout.contains("Ready with 1 transaction.", "The server should have parsed 1 transaction.") + +client.stdout.contains( + "Delaying the body for key http3-delayed-request-body of stream id [0-9]+ per the content " + "delay specification: 700", "The client should delay the body of the request.") + +client.stdout.contains("Sent an HTTP/3 body of 399 bytes for key http3-delayed-request-body", + "The client should send the delayed request body.") + +client.stdout.excludes("Violation:", + "There should be no verification errors because there are none added.") + +server.stdout.excludes("Violation:", + "There should be no verification errors because there are none added.") + +# +# Test 10: Verify that the timing data indicates that the HTTP/3 content delay +# took place. +# +case = suite.case("Verify the HTTP/3 content delay replay took an expected amount of time to run.") +client_output = client.stdout.path +expected_min_delay_ms = "700" +process = case.add_process( + "verify-http3-content-delay", + ["python3", verifier_script, client_output, expected_min_delay_ms], + copies=[verifier_script], +) +process.stdout.contains('Good', 'The verifier script should report success.') + def test_uranium_suite(uranium): uranium.run(suite) From 630183c87814ca0770508fd3323f3e29050b69ed Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Tue, 1 Sep 2026 08:53:54 +0900 Subject: [PATCH 4/5] Verify responses arriving before a delayed request body HTTP/2 and HTTP/3 service ingress while write() waits out a content delay, so a peer can answer before the body goes out. Two things broke in that window: the expected response was attached to the stream only after write() returned, leaving such a response unverified, and the stream state was owned only for the duration of write(), so nghttp2/nghttp3 could call back into freed state once the peer's END_STREAM retired the stream. The expected response is now stamped on the stream when it is created, and ownership is held until the protocol library's stream-close callback. The test proxy grows an EarlyResponse directive to reproduce this: it answers on the request HEADERS instead of waiting for the whole request. Server-side HTTP/3 is not implemented, so the README qualifies HTTP/3 content delay as request bodies only. --- README.md | 6 +- src/core/http2.cc | 23 +++++-- src/core/http2.h | 20 +++++- src/core/http3.cc | 33 +++++++--- src/core/http3.h | 25 ++++++- tests/tools/uranium/proxy/directive_engine.py | 65 ++++++++++++++++++- tests/tools/uranium/proxy/proxy_http2.py | 38 ++++++++++- tests/tools/uranium/proxy/proxy_http3.py | 19 ++++++ .../content-delay-early-response-http2.yaml | 45 +++++++++++++ .../content-delay-early-response-http3.yaml | 43 ++++++++++++ tests/uranium_tests/delay/test_delay.py | 53 +++++++++++++++ 11 files changed, 343 insertions(+), 27 deletions(-) create mode 100644 tests/uranium_tests/delay/content-delay-early-response-http2.yaml create mode 100644 tests/uranium_tests/delay/content-delay-early-response-http3.yaml diff --git a/README.md b/README.md index b9c569cc..d8e2232c 100644 --- a/README.md +++ b/README.md @@ -996,8 +996,10 @@ that the proxy's timeouts fire at the point they should. The value uses the same unit-suffixed duration format described in [Session and Transaction Delay Specification](#session-and-transaction-delay-specification). -This works for HTTP/1.x, HTTP/2, and HTTP/3, and for both request and response -bodies. For HTTP/2 and HTTP/3 the headers are put on the wire in their `HEADERS` +This works for HTTP/1.x, HTTP/2, and HTTP/3. For HTTP/1.x and HTTP/2 it applies +to both request and response bodies. Proxy Verifier does not implement +server-side HTTP/3, so over HTTP/3 only a request body can carry a content +delay. For HTTP/2 and HTTP/3 the headers are put on the wire in their `HEADERS` frame, the body is withheld from the protocol library for the duration of the delay, and the stream is then resumed so the body follows in its own `DATA` frame. diff --git a/src/core/http2.cc b/src/core/http2.cc index 609b5b67..8b5fd71d 100644 --- a/src/core/http2.cc +++ b/src/core/http2.cc @@ -346,7 +346,6 @@ void H2Session::record_stream_state(int32_t stream_id, std::shared_ptr stream_state) { _stream_map[stream_id] = stream_state; - _last_added_stream = stream_state; } bool @@ -737,14 +736,14 @@ H2Session::run_transaction(Txn const &txn) } Errata errata; - auto const previous_last_added_stream = _last_added_stream; + // Register the expected response before the request is written. write() + // services incoming frames while it waits out a content delay, so a response + // which arrives ahead of the delayed request body has to find the expected + // response already attached to its stream. + _specified_response_for_next_request = &txn._rsp; auto &&[bytes_written, write_errata] = this->write(txn._req); + _specified_response_for_next_request = nullptr; errata.note(std::move(write_errata)); - if (errata.is_ok() && _last_added_stream != nullptr && - _last_added_stream != previous_last_added_stream) - { - _last_added_stream->_specified_response = &txn._rsp; - } return errata; } @@ -1303,6 +1302,10 @@ finalize_stream(H2Session *session_data, int32_t stream_id) stream_state._key, elapsed_ms); } + // The peer is done with the stream, but our own half of it may still have a + // body to send: nghttp2 keeps a raw pointer to this state and will call back + // into it. Park the ownership until nghttp2 closes the stream. + session_data->_retired_stream_map.insert_or_assign(stream_id, std::move(iter->second)); session_data->_stream_map.erase(iter); return 0; } @@ -1318,6 +1321,9 @@ on_stream_close_cb( errata.note(S_DIAG, "HTTP/2 stream is closed with id: {}", stream_id); H2Session *session_data = reinterpret_cast(user_data); finalize_stream(session_data, stream_id); + // nghttp2 will not call back with this stream's user data again, so the state + // parked by finalize_stream can go. + session_data->_retired_stream_map.erase(stream_id); return 0; } @@ -1867,6 +1873,9 @@ H2Session::write(HttpHeader const &hdr) } else { new_stream_state = std::make_shared(); stream_state = new_stream_state.get(); + // See the comment on this member: this has to happen before any of the + // request is written. + stream_state->_specified_response = _specified_response_for_next_request; } if (hdr.is_request()) { diff --git a/src/core/http2.h b/src/core/http2.h index 6bc75740..9f5a87c2 100644 --- a/src/core/http2.h +++ b/src/core/http2.h @@ -210,6 +210,16 @@ class H2Session : public TLSSession /// A mapping from stream_id to H2StreamState. std::unordered_map> _stream_map; + /** Stream states retired from @a _stream_map which nghttp2 has not closed yet. + * + * nghttp2 keeps a raw pointer to the stream state as its stream user data and + * hands it back to the data source read callback. A stream is dropped from + * @a _stream_map as soon as the peer ends its half of it, which can happen + * while our own body is still queued behind a content delay or flow control, + * so ownership is parked here until nghttp2 reports the stream closed. + */ + std::unordered_map> _retired_stream_map; + protected: static swoc::Errata client_init(SSL_CTX *&client_context); static swoc::Errata server_init(SSL_CTX *&server_context); @@ -275,7 +285,15 @@ class H2Session : public TLSSession bool _h2_is_negotiated = false; std::deque _ended_streams; - std::shared_ptr _last_added_stream; + + /** The expected response to attach to the next request stream @c write creates. + * + * @c write services incoming frames while it holds a content delay, so the + * expected response has to be on the stream before the request headers go out + * rather than after @c write returns. Otherwise a response which arrives + * ahead of the delayed request body is not verified against. + */ + HttpHeader const *_specified_response_for_next_request = nullptr; #ifndef OPENSSL_NO_NEXTPROTONEG static unsigned char next_proto_list[256]; diff --git a/src/core/http3.cc b/src/core/http3.cc index ce7f8af5..0fa63a40 100644 --- a/src/core/http3.cc +++ b/src/core/http3.cc @@ -419,8 +419,14 @@ cb_h3_end_stream(nghttp3_conn *, int64_t stream_id, void *conn_user_data, void * session->set_stream_has_ended(stream_id, key); if (stream_state->will_receive_response()) { finalize_h3_stream(stream_id, *stream_state); - session->stream_map.erase(stream_id); - session->mark_completed_response_stream(stream_id); + std::shared_ptr retained_state; + if (auto const spot = session->stream_map.find(stream_id); spot != session->stream_map.end()) { + retained_state = std::move(spot->second); + session->stream_map.erase(spot); + } + // Our half of the stream may still have a body to send, and nghttp3 will + // call back into this state with its raw pointer while it does. + session->mark_completed_response_stream(stream_id, std::move(retained_state)); } return 0; } @@ -921,7 +927,7 @@ H3Session::H3Session(TextView const &client_sni, int client_verify_mode) H3Session::~H3Session() { - m_last_added_stream.reset(); + m_completed_response_streams.clear(); quic_socket.reset(); } @@ -1074,6 +1080,9 @@ H3Session::write(HttpHeader const &hdr) stream_id = static_cast(SSL_get_stream_id(stream)); new_stream_state = std::make_shared(hdr.is_request()); stream_state = new_stream_state.get(); + // See the comment on this member: this has to happen before any of the + // request is written. + stream_state->specified_response = m_specified_response_for_next_request; stream_state->set_stream_id(stream_id); record_stream_state(stream_id, new_stream_state); } @@ -1485,14 +1494,15 @@ H3Session::get_a_stream_has_ended() const void H3Session::record_stream_state(int64_t stream_id, std::shared_ptr stream_state) { - stream_map.emplace(stream_id, stream_state); - m_last_added_stream = std::move(stream_state); + stream_map.emplace(stream_id, std::move(stream_state)); } void -H3Session::mark_completed_response_stream(int64_t stream_id) +H3Session::mark_completed_response_stream( + int64_t stream_id, + std::shared_ptr stream_state) { - m_completed_response_streams.insert(stream_id); + m_completed_response_streams.insert_or_assign(stream_id, std::move(stream_state)); } bool @@ -1625,12 +1635,15 @@ Errata H3Session::run_transaction(Txn const &transaction) { Errata errata; + // Register the expected response before the request is written. write() + // services incoming packets while it waits out a content delay, so a response + // which arrives ahead of the delayed request body has to find the expected + // response already attached to its stream. + m_specified_response_for_next_request = &transaction._rsp; auto &&[bytes_written, write_errata] = write(transaction._req); + m_specified_response_for_next_request = nullptr; static_cast(bytes_written); errata.note(std::move(write_errata)); - if (m_last_added_stream != nullptr) { - m_last_added_stream->specified_response = &transaction._rsp; - } return errata; } diff --git a/src/core/http3.h b/src/core/http3.h index 9ee73b77..ea3c62d2 100644 --- a/src/core/http3.h +++ b/src/core/http3.h @@ -241,10 +241,19 @@ class H3Session : public Session void record_stream_state(int64_t stream_id, std::shared_ptr stream_state); /** Remember a response finalized before its close callback. + * + * nghttp3 keeps a raw pointer to the stream state as its stream user data and + * hands it back to the data reader. The stream is dropped from @a stream_map + * as soon as the peer ends its half of it, which can happen while our own + * body is still queued behind a content delay or flow control, so ownership + * is parked here until nghttp3 reports the stream closed. * * @param[in] stream_id The stream identifier. + * @param[in] stream_state The state to retain until the close callback. */ - void mark_completed_response_stream(int64_t stream_id); + void mark_completed_response_stream( + int64_t stream_id, + std::shared_ptr stream_state); /** Remove a remembered finalized response stream. * @@ -299,9 +308,19 @@ class H3Session : public Session private: std::deque m_ended_streams; swoc::IPEndpoint const *m_endpoint = nullptr; - std::shared_ptr m_last_added_stream; std::unordered_set m_finished_streams; - std::unordered_set m_completed_response_streams; + + /// Streams finalized on their end-stream callback, held until they are closed. + std::unordered_map> m_completed_response_streams; + + /** The expected response to attach to the next request stream @c write creates. + * + * @c write services incoming packets while it holds a content delay, so the + * expected response has to be on the stream before the request headers go out + * rather than after @c write returns. Otherwise a response which arrives + * ahead of the delayed request body is not verified against. + */ + HttpHeader const *m_specified_response_for_next_request = nullptr; static SSL_CTX *m_h3_client_context; static SSL_CTX *m_h3_server_context; diff --git a/tests/tools/uranium/proxy/directive_engine.py b/tests/tools/uranium/proxy/directive_engine.py index 82438c4d..89223af9 100644 --- a/tests/tools/uranium/proxy/directive_engine.py +++ b/tests/tools/uranium/proxy/directive_engine.py @@ -72,6 +72,8 @@ def directive_factory(command, value): return CloseConnectionDirective(value) if command.lower() == LocalResponseDirective.get_command_name().lower(): return LocalResponseDirective(value) + if command.lower() == EarlyResponseDirective.get_command_name().lower(): + return EarlyResponseDirective(value) return None @@ -317,6 +319,36 @@ def get_local_response(self): return self._status, self._reason +class EarlyResponseDirective(LocalResponseDirective): + """ + Implement a directive that serves a local response before the request body. + + This is associated with the EarlyResponse=% specification. + It behaves like LocalResponse except that the proxy replies as soon as the + request headers arrive rather than waiting for the request to be complete. + This is how a peer which responds ahead of a delayed request body is + simulated. + + >>> d = EarlyResponseDirective('413') + >>> d.get_local_response() + (413, 'Request Entity Too Large') + >>> d.get_early_response() + (413, 'Request Entity Too Large') + """ + + _command_name = "EarlyResponse" + + @staticmethod + def get_command_name(): + """ + Return the command name associated with this Directive. + """ + return EarlyResponseDirective._command_name + + def get_early_response(self): + return self._status, self._reason + + class DirectiveEngine: """ Implements directive parsing and header manipulation. @@ -338,6 +370,10 @@ class DirectiveEngine: This header requests the proxy to serve a local response with the given status (and optional reason) instead of forwarding the request. + X-Proxy-Directive: EarlyResponse=% + Like LocalResponse, except that the response is served as soon as the + request headers arrive rather than after the entire request is received. + Multiple directives can be passed in the same X-Proxy-Directive by simply appending them in the value of the header. White space may be used as a separator. For instance: @@ -393,9 +429,12 @@ def _directive_value_parser(x_proxy_directive_value): [('SetURL', 'http://example.one:8080/config/settings.yaml?q=3#F')] >>> DirectiveEngine._directive_value_parser("LocalResponse=%<200%>") [('LocalResponse', '200')] + >>> DirectiveEngine._directive_value_parser("EarlyResponse=%<413%>") + [('EarlyResponse', '413')] """ - return re.findall(r"(Delete|Insert|SetURL|CloseConnection|LocalResponse)=%<(.*?)%>", - x_proxy_directive_value) + return re.findall( + r"(Delete|Insert|SetURL|CloseConnection|LocalResponse|EarlyResponse)=%<(.*?)%>", + x_proxy_directive_value) def get_new_url(self): """ @@ -524,6 +563,28 @@ def get_local_response(self): local_response = possible_local_response return local_response + def get_early_response(self): + """ + Return the status and reason for a response to serve before the request body. + + >>> import email.message + >>> headers = email.message.Message() + >>> headers.add_header('X-Proxy-Directive', 'EarlyResponse=%<413%>') + >>> DirectiveEngine(headers).get_early_response() + (413, 'Request Entity Too Large') + + >>> headers = email.message.Message() + >>> headers.add_header('X-Proxy-Directive', 'LocalResponse=%<204%>') + >>> DirectiveEngine(headers).get_early_response() is None + True + """ + early_response = None + for directive in self._directives: + possible_early_response = getattr(directive, "get_early_response", lambda: None)() + if possible_early_response is not None: + early_response = possible_early_response + return early_response + if __name__ == '__main__': import doctest diff --git a/tests/tools/uranium/proxy/proxy_http2.py b/tests/tools/uranium/proxy/proxy_http2.py index f280a993..0818110a 100644 --- a/tests/tools/uranium/proxy/proxy_http2.py +++ b/tests/tools/uranium/proxy/proxy_http2.py @@ -86,6 +86,35 @@ def _close_downstream_connection(self, request_id): self.downstream_closed = True self.sock.close() + def _send_early_response(self, request_headers, stream_id): + """ + Serve an EarlyResponse directive as soon as the request headers arrive. + + The response is sent before the request body is received, which is how a + peer that answers ahead of a delayed request body is simulated. + + Args: + request_headers: The received request headers, pseudo-headers included. + stream_id: The stream of the request. + + Returns: + Whether an early response was sent. + """ + _, regular_headers = self.split_headers(request_headers) + early_response = DirectiveEngine(regular_headers).get_early_response() + if early_response is None: + return False + status, reason = early_response + request_id = regular_headers.get('uuid', '') + print(f"Serving early response for key {request_id} before the request body: " + f"{status} {reason}.") + self.listening_conn.send_headers(stream_id, [ + (':status', str(status)), + ('content-length', '0'), + ], end_stream=True) + self.sock.sendall(self.listening_conn.data_to_send()) + return True + def run_forever(self): self.listening_conn.initiate_connection() @@ -104,6 +133,7 @@ def run_forever(self): stream_id_list = set() frame_sequences = {} resp_from_server = {} + early_responded_streams = set() while True: try: data = self.sock.recv(65535) @@ -163,6 +193,8 @@ def run_forever(self): if isinstance(event, RequestReceived): frame_seq.append('HEADERS') request_info._headers = event.headers + if self._send_early_response(event.headers, stream_id): + early_responded_streams.add(stream_id) if isinstance(event, StreamReset): frame_seq.append('RST_STREAM') @@ -173,7 +205,8 @@ def run_forever(self): print( f'Received RST_STREAM frame with error code {err} on stream {event.stream_id}.' ) - if stream_id not in resp_from_server.keys(): + if (stream_id not in resp_from_server.keys() + and stream_id not in early_responded_streams): ret_vals = self.request_received(request_info._headers, request_info._body_bytes, stream_id) if ret_vals is not None: @@ -182,7 +215,8 @@ def run_forever(self): if isinstance(event, StreamEnded): print('StreamEnded') stream_id_list.add(stream_id) - if stream_id not in resp_from_server.keys(): + if (stream_id not in resp_from_server.keys() + and stream_id not in early_responded_streams): ret_vals = self.request_received(request_info._headers, request_info._body_bytes, stream_id) if ret_vals is not None: diff --git a/tests/tools/uranium/proxy/proxy_http3.py b/tests/tools/uranium/proxy/proxy_http3.py index 5a768f56..4b6789d4 100644 --- a/tests/tools/uranium/proxy/proxy_http3.py +++ b/tests/tools/uranium/proxy/proxy_http3.py @@ -245,8 +245,27 @@ def http_event_received(self, event: H3Event) -> None: self.request_headers = event.headers if event.stream_ended: self.client_request_done_event.set() + elif self._requests_early_response(event.headers): + # Respond without waiting for the rest of the request. This is + # how a peer that answers ahead of a delayed request body is + # simulated. + self.client_request_done_event.set() self.transmit() + def _requests_early_response(self, request_headers) -> bool: + """ + Return whether the request headers carry an EarlyResponse directive. + + Args: + request_headers: The received request headers, pseudo-headers included. + """ + _, regular_headers = self.split_headers(request_headers) + if DirectiveEngine(regular_headers).get_early_response() is None: + return False + request_id = regular_headers.get('uuid', '') + print(f"Serving early response for key {request_id} before the request body.") + return True + async def send_response(self) -> None: await self.client_request_done_event.wait() diff --git a/tests/uranium_tests/delay/content-delay-early-response-http2.yaml b/tests/uranium_tests/delay/content-delay-early-response-http2.yaml new file mode 100644 index 00000000..20a367c6 --- /dev/null +++ b/tests/uranium_tests/delay/content-delay-early-response-http2.yaml @@ -0,0 +1,45 @@ +# @file +# +# Copyright 2026, Verizon Media +# SPDX-License-Identifier: Apache-2.0 +# + +meta: + version: '1.0' + +# Verify that a response which arrives while the Verifier client is holding a +# request body behind a "content" "delay" is still verified. The test proxy +# answers as soon as the request headers arrive, which is before the delayed +# DATA frame goes out, so the expected response has to be registered on the +# stream before the delay begins. The Content-Length rule below is what detects +# a skipped verification: it is reported as never processed if the response is +# not verified against. + +sessions: + +- protocol: + stack: http2 + tls: + sni: test_sni + + transactions: + + - client-request: + headers: + fields: + - [ :method, POST ] + - [ :scheme, https ] + - [ :authority, www.example.com ] + - [ :path, /pictures/flower.jpeg ] + - [ Content-Type, image/jpeg ] + - [ X-Proxy-Directive, "EarlyResponse=%<413%>" ] + - [ uuid, http2-early-response ] + content: + size: 399 + delay: 700ms + + proxy-response: + status: 413 + headers: + fields: + - [ Content-Length, { value: '0', as: equal } ] diff --git a/tests/uranium_tests/delay/content-delay-early-response-http3.yaml b/tests/uranium_tests/delay/content-delay-early-response-http3.yaml new file mode 100644 index 00000000..b083fee1 --- /dev/null +++ b/tests/uranium_tests/delay/content-delay-early-response-http3.yaml @@ -0,0 +1,43 @@ +# @file +# +# Copyright 2026, Verizon Media +# SPDX-License-Identifier: Apache-2.0 +# + +meta: + version: '1.0' + +# The HTTP/3 counterpart of content-delay-early-response-http2.yaml: a response +# which arrives while the Verifier client is holding a request body behind a +# "content" "delay" has to be verified against. The Content-Length rule below +# is what detects a skipped verification: it is reported as never processed if +# the response is not verified against. + +sessions: + +- protocol: + stack: http3 + tls: + sni: test_sni + + transactions: + + - client-request: + headers: + fields: + - [ :method, POST ] + - [ :scheme, https ] + - [ :authority, www.example.com ] + - [ :path, /pictures/flower.jpeg ] + - [ Content-Type, image/jpeg ] + - [ X-Proxy-Directive, "EarlyResponse=%<413%>" ] + - [ uuid, http3-early-response ] + content: + size: 399 + delay: 700ms + + proxy-response: + status: 413 + headers: + fields: + - [ Content-Length, { value: '0', as: equal } ] diff --git a/tests/uranium_tests/delay/test_delay.py b/tests/uranium_tests/delay/test_delay.py index 2a8508d1..33c0fb0f 100644 --- a/tests/uranium_tests/delay/test_delay.py +++ b/tests/uranium_tests/delay/test_delay.py @@ -231,6 +231,59 @@ ) process.stdout.contains('Good', 'The verifier script should report success.') +# +# Test 11: A peer which responds after the request headers but before the +# delayed request body. The response has to be verified against even though it +# arrives while the client is still holding the body back. +# +case = suite.case("Verify an HTTP/2 response received before the delayed request body.") +client = case.add_client("client_early_response_http2", "content-delay-early-response-http2.yaml") + +proxy = case.add_proxy("proxy_http2_early_response", listen_port=client.https_port, server_port=1, + use_ssl=True, use_http2_to_1=True) + +proxy.stdout.contains("Serving early response for key http2-early-response before the request body", + "The proxy should respond before the request body arrives.") + +client.stdout.contains("Received an HTTP/2 response for key http2-early-response", + "The client should receive the early response.") + +client.stdout.contains("Sent an HTTP/2 body of 399 bytes for key http2-early-response", + "The client should still send the delayed request body.") + +client.stdout.excludes("were never processed", + "The early response should be verified rather than skipped.") + +client.stdout.excludes("Violation:", "The early response matches what the replay file expects.") + +client.expect_return_codes(0) + +# +# Test 12: The HTTP/3 version of the early response case. +# +case = suite.case("Verify an HTTP/3 response received before the delayed request body.") +client = case.add_client("client_early_response_http3", "content-delay-early-response-http3.yaml", + other_args=http3_args) + +proxy = case.add_proxy("proxy_http3_early_response", listen_port=client.http3_port, server_port=1, + use_ssl=True, use_http3_to_1=True) + +proxy.stdout.contains("Serving early response for key http3-early-response before the request body", + "The proxy should respond before the request body arrives.") + +client.stdout.contains("Received an HTTP/3 response for key http3-early-response", + "The client should receive the early response.") + +client.stdout.contains("Sent an HTTP/3 body of 399 bytes for key http3-early-response", + "The client should still send the delayed request body.") + +client.stdout.excludes("were never processed", + "The early response should be verified rather than skipped.") + +client.stdout.excludes("Violation:", "The early response matches what the replay file expects.") + +client.expect_return_codes(0) + def test_uranium_suite(uranium): uranium.run(suite) From 1d442b34ed782c4f8a1eb9e346b2c82b907fa085 Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Tue, 1 Sep 2026 10:53:25 +0900 Subject: [PATCH 5/5] Keep an expected content delay from failing its own replay Three ways a content delay could fail the run it was meant to exercise: the delay counted against Transaction_Delay_Cutoff, so anything at or over ten seconds -- the point of the feature -- reported the transaction as too slow; resuming the HTTP/2 DATA frame errored when the peer had already reset the stream, which is the expected outcome when the delay is used to trigger a proxy timeout; and errata.sink() cleared the severity of every drain failure, so a protocol or TLS error during the delay was reported and then swallowed, letting the client exit zero. Each is now distinguished from the failure it was masking or inventing. The HTTP/2 delay also services the session in bounded slices and checks the shutdown flag, matching interruptible_sleep_for on HTTP/1 and the HTTP/3 loop. --- src/core/http.cc | 7 ++++++- src/core/http.h | 8 ++++++++ src/core/http2.cc | 49 ++++++++++++++++++++++++++++++++++++++++------- src/core/http2.h | 8 ++++++++ src/core/http3.cc | 39 +++++++++++++++++++++++++++++++++---- src/core/http3.h | 8 ++++++++ 6 files changed, 107 insertions(+), 12 deletions(-) diff --git a/src/core/http.cc b/src/core/http.cc index 44a715b6..c89e81f0 100644 --- a/src/core/http.cc +++ b/src/core/http.cc @@ -1386,6 +1386,9 @@ Session::write(HttpHeader const &hdr) hdr.get_key()); return zret; } + // This wait was asked for by the replay file, so it does not count + // against Transaction_Delay_Cutoff. + _content_delay_served += hdr._content_delay; } auto &&[body_bytes_written, body_write_errata] = write_body(hdr); auto const body_write_failed = !body_write_errata.is_ok(); @@ -2023,13 +2026,15 @@ Session::run_transactions( break; } auto const before = ClockType::now(); + _content_delay_served = 0us; txn_errata.note(this->run_transaction(txn)); auto const after = ClockType::now(); if (!txn_errata.is_ok()) { txn_errata.note(S_ERROR, R"(Failed HTTP/1 transaction with key: {})", txn._req.get_key()); } - auto const elapsed_ms = duration_cast(after - before); + auto const elapsed_ms = duration_cast(after - before) - + duration_cast(_content_delay_served); if (elapsed_ms > Transaction_Delay_Cutoff) { txn_errata.note( S_ERROR, diff --git a/src/core/http.h b/src/core/http.h index fc8dde51..5761852a 100644 --- a/src/core/http.h +++ b/src/core/http.h @@ -1111,6 +1111,14 @@ class Session /** The number of bytes read across all sockets. */ static std::atomic _num_total_bytes_read; + /** How long @c write has spent waiting out @c content @c delay nodes. + * + * The wait was asked for by the replay file, so it is subtracted from the + * measured transaction duration before that duration is compared against + * @c Transaction_Delay_Cutoff. + */ + std::chrono::microseconds _content_delay_served{0}; + private: virtual swoc::Rv drain_body_internal(HttpHeader &hdr, Txn const &json_txn, swoc::TextView initial); diff --git a/src/core/http2.cc b/src/core/http2.cc index 8b5fd71d..938a7393 100644 --- a/src/core/http2.cc +++ b/src/core/http2.cc @@ -33,6 +33,13 @@ constexpr bool IS_TRAILER = true; size_t constexpr Default_H2_InFlight_Stream_Cap = 32; size_t constexpr H2NoProgressTimeoutBudget = 3; +/** The longest single wait taken while serving a @c content @c delay. + * + * Bounding the wait keeps shutdown requests honored while the body is being + * held back. + */ +constexpr auto Content_Delay_Service_Interval = 20ms; + static ssize_t receive_nghttp2_data( nghttp2_session *session, uint8_t *buf, @@ -1274,7 +1281,8 @@ finalize_stream(H2Session *session_data, int32_t stream_id) auto const &message_start = stream_state._stream_start; auto const message_end = ClockType::now(); - auto const elapsed_ms = duration_cast(message_end - message_start); + auto const elapsed_ms = duration_cast(message_end - message_start) - + duration_cast(stream_state._content_delay_served); auto const specified_response = stream_state._specified_response; if (specified_response && specified_response->_trailer_fields_rules->_rules.size()) { @@ -1602,11 +1610,25 @@ H2Session::content_delay(H2StreamState &stream_state) std::chrono::duration delay_time = content_delay; auto const next_time = ClockType::now() + delay_time; while (delay_time > 0ms) { - // Make use of our delay time to process any incoming frames. - auto &&[progress, progress_errata] = - drain_h2_receive_window(*this, duration_cast(delay_time), "content delay"); + // Service the session in bounded slices so that shutdown requests stay + // responsive and a sub-millisecond remainder does not spin. Incoming frames + // are processed as they arrive; the body itself stays withheld because the + // data source read callback defers the DATA frame while the content delay + // is set. + auto const slice = + std::clamp(duration_cast(delay_time), 1ms, Content_Delay_Service_Interval); + auto &&[progress, progress_errata] = drain_h2_receive_window(*this, slice, "content delay"); errata.note(std::move(progress_errata)); if (!errata.is_ok()) { + if (!this->is_closed()) { + // A protocol or TLS failure is a genuine replay failure and has to keep + // its severity. + errata.note( + S_ERROR, + "Failed to service the HTTP/2 session during the content delay for key {}.", + stream_state._key); + break; + } // A peer which gives up during the delay is the expected outcome for some // replay files, so make the connection between the two explicit rather // than reporting a bare read failure. @@ -1619,8 +1641,18 @@ H2Session::content_delay(H2StreamState &stream_state) stream_state._key); break; } + if (shutdown_requested()) { + errata.note( + S_DIAG, + "Shutdown was requested during the content delay for key {}.", + stream_state._key); + break; + } delay_time = next_time - ClockType::now(); } + // This wait was asked for by the replay file, so it does not count against + // Transaction_Delay_Cutoff. + stream_state._content_delay_served += content_delay; // Let the body flow again regardless of how the delay ended. If the peer is // gone the write simply fails and is reported by the caller. @@ -1628,10 +1660,13 @@ H2Session::content_delay(H2StreamState &stream_state) if (auto const rv = nghttp2_session_resume_data(this->_session, stream_state.get_stream_id()); rv != 0) { + // NGHTTP2_ERR_INVALID_ARGUMENT means the stream is gone or nothing was + // deferred on it. A peer which reset the stream during the delay is the + // expected outcome for some replay files, and a DATA frame nghttp2 never + // reached is sent once flow control allows it, so neither is a failure. errata.note( - S_ERROR, - "Failed to resume the HTTP/2 DATA frame for key {} on stream {} after the content delay: " - "{}", + rv == NGHTTP2_ERR_INVALID_ARGUMENT ? S_DIAG : S_ERROR, + "Did not resume the HTTP/2 DATA frame for key {} on stream {} after the content delay: {}", stream_state._key, stream_state.get_stream_id(), nghttp2_strerror(rv)); diff --git a/src/core/http2.h b/src/core/http2.h index 9f5a87c2..e3cf7544 100644 --- a/src/core/http2.h +++ b/src/core/http2.h @@ -78,6 +78,14 @@ class H2StreamState */ std::chrono::microseconds _content_delay{0}; + /** How long this stream has spent waiting out a @c content @c delay. + * + * The wait was asked for by the replay file, so it is subtracted from the + * measured stream duration before that duration is compared against + * @c Transaction_Delay_Cutoff. + */ + std::chrono::microseconds _content_delay_served{0}; + std::string _key; nghttp2_nv *_trailer_to_send = nullptr; diff --git a/src/core/http3.cc b/src/core/http3.cc index 0fa63a40..1b448774 100644 --- a/src/core/http3.cc +++ b/src/core/http3.cc @@ -122,7 +122,9 @@ finalize_h3_stream(int64_t stream_id, H3StreamState &stream_state) errata.note(S_DIAG, R"(Body content did not match expected value.)"); } - auto const elapsed_ms = duration_cast(ClockType::now() - stream_state.stream_start); + auto const elapsed_ms = + duration_cast(ClockType::now() - stream_state.stream_start) - + duration_cast(stream_state.content_delay_served); if (elapsed_ms > Transaction_Delay_Cutoff) { errata.note( S_ERROR, @@ -714,6 +716,22 @@ progress_http3_ingress(H3Session &session) return zret; } +/** Return whether the QUIC connection has been closed. + * + * @param[in] session The session whose connection to inspect. + * @return Whether the connection is closed, by either peer. + */ +bool +quic_connection_is_closed(H3Session const &session) +{ + auto *connection = session.quic_socket.connection; + if (connection == nullptr) { + return true; + } + SSL_CONN_CLOSE_INFO close_info{}; + return SSL_get_conn_close_info(connection, &close_info, sizeof(close_info)) == 1; +} + swoc::Rv progress_http3(H3Session &session, milliseconds timeout) { @@ -1001,14 +1019,24 @@ H3Session::content_delay(H3StreamState &stream_state) remaining = duration_cast(deadline - ClockType::now())) { // Service the connection in bounded slices so its timers keep running and - // shutdown requests stay responsive. The body itself stays withheld: the - // data reader reports NGHTTP3_ERR_WOULDBLOCK while content_delay is set. + // shutdown requests stay responsive, and so a sub-millisecond remainder + // does not spin. The body itself stays withheld: the data reader reports + // NGHTTP3_ERR_WOULDBLOCK while content_delay is set. auto const slice = - std::min(duration_cast(remaining), Content_Delay_Service_Interval); + std::clamp(duration_cast(remaining), 1ms, Content_Delay_Service_Interval); auto &&[progressed, progress_errata] = progress_http3(*this, slice); static_cast(progressed); errata.note(std::move(progress_errata)); if (!errata.is_ok()) { + if (!quic_connection_is_closed(*this)) { + // A protocol or TLS failure is a genuine replay failure and has to keep + // its severity. + errata.note( + S_ERROR, + "Failed to service the HTTP/3 connection during the content delay for key {}.", + stream_state.key); + break; + } // A peer which gives up during the delay is the expected outcome for some // replay files, so make the connection between the two explicit rather // than reporting a bare I/O failure. @@ -1029,6 +1057,9 @@ H3Session::content_delay(H3StreamState &stream_state) break; } } + // This wait was asked for by the replay file, so it does not count against + // Transaction_Delay_Cutoff. + stream_state.content_delay_served += content_delay; // Let the body flow again regardless of how the delay ended. If the peer is // gone the write simply fails and is reported by the caller. diff --git a/src/core/http3.h b/src/core/http3.h index ea3c62d2..5d9b9b5f 100644 --- a/src/core/http3.h +++ b/src/core/http3.h @@ -146,6 +146,14 @@ class H3StreamState */ std::chrono::microseconds content_delay{0}; + /** How long this stream has spent waiting out a @c content @c delay. + * + * The wait was asked for by the replay file, so it is subtracted from the + * measured stream duration before that duration is compared against + * @c Transaction_Delay_Cutoff. + */ + std::chrono::microseconds content_delay_served{0}; + private: bool m_will_receive_request = false; int64_t m_stream_id = 0;