diff --git a/README.md b/README.md index 40eaa53d..d8e2232c 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,59 @@ 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). + +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. + +Be aware of the following characteristics of a `content` `delay` node: + +* 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. +* 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 + 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..54b10fcf 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'. Cannot be combined with a 'frames' node.", + "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'. Cannot be combined with a 'frames' node.", + "type": "string" } } } diff --git a/src/core/YamlParser.cc b/src/core/YamlParser.cc index c7a9ef2d..b7290308 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 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( + 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..c89e81f0 100644 --- a/src/core/http.cc +++ b/src/core/http.cc @@ -1372,9 +1372,38 @@ 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; + } + // 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(); 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( @@ -1997,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 f3c66679..5761852a 100644 --- a/src/core/http.h +++ b/src/core/http.h @@ -645,6 +645,19 @@ 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, 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}; + /// The parsed headers contain "Connection: close" header. bool _contains_connection_close = false; @@ -1098,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 5f26741e..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, @@ -346,7 +353,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 +743,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; } @@ -1275,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()) { @@ -1303,6 +1310,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 +1329,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; } @@ -1475,6 +1489,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 +1592,88 @@ 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) { + // 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. + 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; + } + 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. + stream_state._content_delay = 0us; + 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( + 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)); + } + return errata; +} + Errata H2Session::submit_headers_frame( HttpHeader const &hdr, @@ -1779,6 +1889,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,10 +1903,14 @@ 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(); + // 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()) { @@ -1896,6 +2017,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 +2083,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..e3cf7544 100644 --- a/src/core/http2.h +++ b/src/core/http2.h @@ -66,6 +66,26 @@ 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}; + + /** 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; @@ -198,6 +218,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); @@ -226,6 +256,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, @@ -249,7 +293,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 6399bfa4..1b448774 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) { @@ -115,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, @@ -144,6 +153,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(); @@ -399,8 +421,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; } @@ -688,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) { @@ -901,7 +945,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(); } @@ -954,6 +998,84 @@ 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, 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::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. + 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; + } + } + // 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. + 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 +1083,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 +1099,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)); @@ -981,6 +1111,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); } @@ -1006,6 +1139,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 +1199,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; } @@ -1377,14 +1525,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 @@ -1517,12 +1666,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 7a60eaaa..5d9b9b5f 100644 --- a/src/core/http3.h +++ b/src/core/http3.h @@ -135,6 +135,25 @@ 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}; + + /** 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; @@ -230,10 +249,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. * @@ -269,14 +297,38 @@ 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: 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/unit_tests/test_YamlParser.cc b/tests/unit_tests/test_YamlParser.cc index 46f0ff0b..77d975ee 100644 --- a/tests/unit_tests/test_YamlParser.cc +++ b/tests/unit_tests/test_YamlParser.cc @@ -393,6 +393,73 @@ 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 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"( +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..b9b1f382 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,123 @@ 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-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/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/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..33c0fb0f 100644 --- a/tests/uranium_tests/delay/test_delay.py +++ b/tests/uranium_tests/delay/test_delay.py @@ -94,6 +94,196 @@ ) 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.') + +# +# 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.') + +# +# 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) 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