Add content delay for server chaos testing

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

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"
             }
           }
         }

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<bool>(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)) {

src/core/http.cc

@@ -1372,9 +1372,38 @@ Session::write(HttpHeader const &hdr)
   if (header_bytes_written == static_cast<ssize_t>(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<milliseconds>(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<milliseconds>(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<chrono::milliseconds>(after - before);
+    auto const elapsed_ms = duration_cast<chrono::milliseconds>(after - before) -
+                            duration_cast<chrono::milliseconds>(_content_delay_served);
     if (elapsed_ms > Transaction_Delay_Cutoff) {
       txn_errata.note(
           S_ERROR,

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<uint64_t> _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<size_t>
   drain_body_internal(HttpHeader &hdr, Txn const &json_txn, swoc::TextView initial);