quic: deferred logging of roundtrip response time

changelogs/current.yaml

@@ -5,6 +5,9 @@ behavior_changes:
 
 minor_behavior_changes:
 # *Changes that may cause incompatibilities for some users, but should not for most*
+- area: quic
+  change: |
+    Access logging is now deferred to the QUIC ack listener, and roundtrip response time is added as a downstream timing metric. New runtime flag ``envoy.reloadable_features.quic_defer_logging_to_ack_listener`` can be used for revert this behavior.
 - area: healthcheck
   change: |
     If active HC is enabled and a host is ejected by outlier detection, a successful active health check unejects the host and consider it healthy. This also clears all the outlier detection counters. This behavior change can be reverted by setting ``envoy.reloadable_features_successful_active_health_check_uneject_host`` to ``false``.

docs/root/configuration/observability/access_log/usage.rst

@@ -387,6 +387,19 @@ The following command operators are supported:
 
   Renders a numeric value in typed JSON logs.
 
+%ROUNDTRIP_DURATION%
+  HTTP/3 (QUIC)
+    Total duration in milliseconds of the request from the start time to receiving the final ack from
+    the downstream.
+
+  HTTP/1 and HTTP/2
+    Not implemented ("-").
+
+  TCP/UDP
+    Not implemented ("-").
+
+  Renders a numeric value in typed JSON logs.
+
 %RESPONSE_TX_DURATION%
   HTTP
     Total duration in milliseconds of the request from the first byte read from the upstream host to the last

envoy/http/BUILD

@@ -46,6 +46,7 @@ envoy_cc_library(
         ":metadata_interface",
         ":protocol_interface",
         ":stream_reset_handler_interface",
+        "//envoy/access_log:access_log_interface",
         "//envoy/buffer:buffer_interface",
         "//envoy/grpc:status",
         "//envoy/network:address_interface",

envoy/http/codec.h

@@ -4,6 +4,7 @@
 #include <limits>
 #include <memory>
 
+#include "envoy/access_log/access_log.h"
 #include "envoy/buffer/buffer.h"
 #include "envoy/common/pure.h"
 #include "envoy/grpc/status.h"
@@ -174,6 +175,22 @@ class ResponseEncoder : public virtual StreamEncoder {
    * @param decoder new request decoder.
    */
   virtual void setRequestDecoder(RequestDecoder& decoder) PURE;
+
+  /**
+   * Set headers, trailers, and stream info for deferred logging. This allows HCM to hand off
+   * stream-level details to the codec for logging after the stream may be destroyed (e.g. on
+   * receiving the final ack packet from the client). Note that headers and trailers are const
+   * as they will not be modified after this point.
+   * @param request_header_map Request headers for this stream.
+   * @param response_header_map Response headers for this stream.
+   * @param response_trailer_map Response trailers for this stream.
+   * @param stream_info Stream info for this stream.
+   */
+  virtual void
+  setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr request_header_map,
+                                       Http::ResponseHeaderMapConstSharedPtr response_header_map,
+                                       Http::ResponseTrailerMapConstSharedPtr response_trailer_map,
+                                       StreamInfo::StreamInfo& stream_info) PURE;
 };
 
 /**
@@ -211,7 +228,7 @@ class RequestDecoder : public virtual StreamDecoder {
    * @param headers supplies the decoded headers map.
    * @param end_stream supplies whether this is a header only request.
    */
-  virtual void decodeHeaders(RequestHeaderMapPtr&& headers, bool end_stream) PURE;
+  virtual void decodeHeaders(RequestHeaderMapSharedPtr&& headers, bool end_stream) PURE;
 
   /**
    * Called with a decoded trailers frame. This implicitly ends the stream.
@@ -236,6 +253,11 @@ class RequestDecoder : public virtual StreamDecoder {
    * @return StreamInfo::StreamInfo& the stream_info for this stream.
    */
   virtual StreamInfo::StreamInfo& streamInfo() PURE;
+
+  /**
+   * @return List of shared pointers to access loggers for this stream.
+   */
+  virtual std::list<AccessLog::InstanceSharedPtr> accessLogHandlers() PURE;
 };
 
 /**

envoy/http/header_map.h

@@ -718,6 +718,8 @@ class RequestHeaderMap
   INLINE_REQ_NUMERIC_HEADERS(DEFINE_INLINE_NUMERIC_HEADER)
 };
 using RequestHeaderMapPtr = std::unique_ptr<RequestHeaderMap>;
+using RequestHeaderMapSharedPtr = std::shared_ptr<RequestHeaderMap>;
+using RequestHeaderMapConstSharedPtr = std::shared_ptr<const RequestHeaderMap>;
 using RequestHeaderMapOptRef = OptRef<RequestHeaderMap>;
 using RequestHeaderMapOptConstRef = OptRef<const RequestHeaderMap>;
 
@@ -748,6 +750,8 @@ class ResponseHeaderMap
   INLINE_RESP_NUMERIC_HEADERS(DEFINE_INLINE_NUMERIC_HEADER)
 };
 using ResponseHeaderMapPtr = std::unique_ptr<ResponseHeaderMap>;
+using ResponseHeaderMapSharedPtr = std::shared_ptr<ResponseHeaderMap>;
+using ResponseHeaderMapConstSharedPtr = std::shared_ptr<const ResponseHeaderMap>;
 using ResponseHeaderMapOptRef = OptRef<ResponseHeaderMap>;
 using ResponseHeaderMapOptConstRef = OptRef<const ResponseHeaderMap>;
 
@@ -757,6 +761,8 @@ class ResponseTrailerMap
       public HeaderMap,
       public CustomInlineHeaderBase<CustomInlineHeaderRegistry::Type::ResponseTrailers> {};
 using ResponseTrailerMapPtr = std::unique_ptr<ResponseTrailerMap>;
+using ResponseTrailerMapSharedPtr = std::shared_ptr<ResponseTrailerMap>;
+using ResponseTrailerMapConstSharedPtr = std::shared_ptr<const ResponseTrailerMap>;
 using ResponseTrailerMapOptRef = OptRef<ResponseTrailerMap>;
 using ResponseTrailerMapOptConstRef = OptRef<const ResponseTrailerMap>;
 

envoy/stream_info/stream_info.h

@@ -285,6 +285,9 @@ class DownstreamTiming {
   absl::optional<MonotonicTime> downstreamHandshakeComplete() const {
     return downstream_handshake_complete_;
   }
+  absl::optional<MonotonicTime> lastDownstreamAckReceived() const {
+    return last_downstream_ack_received_;
+  }
 
   void onLastDownstreamRxByteReceived(TimeSource& time_source) {
     ASSERT(!last_downstream_rx_byte_received_);
@@ -302,6 +305,10 @@ class DownstreamTiming {
     // An existing value can be overwritten, e.g. in resumption case.
     downstream_handshake_complete_ = time_source.monotonicTime();
   }
+  void onLastDownstreamAckReceived(TimeSource& time_source) {
+    ASSERT(!last_downstream_ack_received_);
+    last_downstream_ack_received_ = time_source.monotonicTime();
+  }
 
 private:
   absl::flat_hash_map<std::string, MonotonicTime> timings_;
@@ -313,6 +320,8 @@ class DownstreamTiming {
   absl::optional<MonotonicTime> last_downstream_tx_byte_sent_;
   // The time the TLS handshake completed. Set at connection level.
   absl::optional<MonotonicTime> downstream_handshake_complete_;
+  // The time the final ack was received from the client.
+  absl::optional<MonotonicTime> last_downstream_ack_received_;
 };
 
 // Measure the number of bytes sent and received for a stream.

mobile/library/common/http/client.h

@@ -164,6 +164,10 @@ class Client : public Logger::Loggable<Logger::Id::http> {
     }
     bool streamErrorOnInvalidHttpMessage() const override { return false; }
     void setRequestDecoder(RequestDecoder& /*decoder*/) override{};
+    void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr,
+                                              Http::ResponseHeaderMapConstSharedPtr,
+                                              Http::ResponseTrailerMapConstSharedPtr,
+                                              StreamInfo::StreamInfo&) override {}
 
     void encodeMetadata(const MetadataMapVector&) override { PANIC("not implemented"); }
 

source/common/formatter/substitution_formatter.cc

@@ -487,6 +487,17 @@ SubstitutionFormatParser::getKnownFormatters() {
         {CommandSyntaxChecker::PARAMS_REQUIRED | CommandSyntaxChecker::LENGTH_ALLOWED,
          [](const std::string& key, absl::optional<size_t>& max_length) {
            return std::make_unique<EnvironmentFormatter>(key, max_length);
+         }}},
+       {"STREAM_INFO_REQ",
+        {CommandSyntaxChecker::PARAMS_REQUIRED | CommandSyntaxChecker::LENGTH_ALLOWED,
+         [](const std::string& format, absl::optional<size_t>& max_length) {
+           std::string main_header, alternative_header;
+
+           SubstitutionFormatParser::parseSubcommandHeaders(format, main_header,
+                                                            alternative_header);
+
+           return std::make_unique<RequestHeaderFormatter>(main_header, alternative_header,
+                                                           max_length);
          }}}});
 }
 
@@ -913,6 +924,15 @@ const StreamInfoFormatter::FieldExtractorLookupTbl& StreamInfoFormatter::getKnow
                                     return timing.downstreamHandshakeComplete();
                                   });
                             }}},
+                          {"ROUNDTRIP_DURATION",
+                           {CommandSyntaxChecker::COMMAND_ONLY,
+                            [](const std::string&, const absl::optional<size_t>&) {
+                              return std::make_unique<StreamInfoDurationFieldExtractor>(
+                                  [](const StreamInfo::StreamInfo& stream_info) {
+                                    StreamInfo::TimingUtility timing(stream_info);
+                                    return timing.lastDownstreamAckReceived();
+                                  });
+                            }}},
                           {"BYTES_RECEIVED",
                            {CommandSyntaxChecker::COMMAND_ONLY,
                             [](const std::string&, const absl::optional<size_t>&) {
@@ -2183,5 +2203,22 @@ ProtobufWkt::Value EnvironmentFormatter::formatValue(const Http::RequestHeaderMa
   return str_;
 }
 
+StreamInfoRequestHeaderFormatter::StreamInfoRequestHeaderFormatter(
+    const std::string& main_header, const std::string& alternative_header,
+    absl::optional<size_t> max_length)
+    : HeaderFormatter(main_header, alternative_header, max_length) {}
+
+absl::optional<std::string> StreamInfoRequestHeaderFormatter::format(
+    const Http::RequestHeaderMap&, const Http::ResponseHeaderMap&, const Http::ResponseTrailerMap&,
+    const StreamInfo::StreamInfo& stream_info, absl::string_view) const {
+  return HeaderFormatter::format(*stream_info.getRequestHeaders());
+}
+
+ProtobufWkt::Value StreamInfoRequestHeaderFormatter::formatValue(
+    const Http::RequestHeaderMap&, const Http::ResponseHeaderMap&, const Http::ResponseTrailerMap&,
+    const StreamInfo::StreamInfo& stream_info, absl::string_view) const {
+  return HeaderFormatter::formatValue(*stream_info.getRequestHeaders());
+}
+
 } // namespace Formatter
 } // namespace Envoy

source/common/formatter/substitution_formatter.h

@@ -661,5 +661,25 @@ class EnvironmentFormatter : public FormatterProvider {
   ProtobufWkt::Value str_;
 };
 
+/**
+ * FormatterProvider for request headers from StreamInfo (rather than the request_headers param).
+ * Purely for testing.
+ */
+class StreamInfoRequestHeaderFormatter : public FormatterProvider, HeaderFormatter {
+public:
+  StreamInfoRequestHeaderFormatter(const std::string& main_header,
+                                   const std::string& alternative_header,
+                                   absl::optional<size_t> max_length);
+
+  // FormatterProvider
+  absl::optional<std::string> format(const Http::RequestHeaderMap& request_headers,
+                                     const Http::ResponseHeaderMap&,
+                                     const Http::ResponseTrailerMap&, const StreamInfo::StreamInfo&,
+                                     absl::string_view) const override;
+  ProtobufWkt::Value formatValue(const Http::RequestHeaderMap&, const Http::ResponseHeaderMap&,
+                                 const Http::ResponseTrailerMap&, const StreamInfo::StreamInfo&,
+                                 absl::string_view) const override;
+};
+
 } // namespace Formatter
 } // namespace Envoy

source/common/http/conn_manager_impl.cc

@@ -55,7 +55,7 @@
 namespace Envoy {
 namespace Http {
 
-bool requestWasConnect(const RequestHeaderMapPtr& headers, Protocol protocol) {
+bool requestWasConnect(const RequestHeaderMapSharedPtr& headers, Protocol protocol) {
   if (!headers) {
     return false;
   }
@@ -278,7 +278,21 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) {
 
   stream.completeRequest();
   stream.filter_manager_.onStreamComplete();
-  stream.filter_manager_.log();
+
+  // For HTTP/3, skip access logging here and add deferred logging info
+  // to stream info for QuicStatsGatherer to use later.
+  if (codec_ && codec_->protocol() == Protocol::Http3 &&
+      // There was a downstream reset, log immediately.
+      !stream.filter_manager_.sawDownstreamReset() &&
+      // On recreate stream, log immediately.
+      stream.response_encoder_ != nullptr &&
+      Runtime::runtimeFeatureEnabled(
+          "envoy.reloadable_features.quic_defer_logging_to_ack_listener")) {
+    stream.deferHeadersAndTrailers();
+  } else {
+    // For HTTP/1 and HTTP/2, log here as usual.
+    stream.filter_manager_.log();
+  }
 
   stream.filter_manager_.destroyFilters();
 
@@ -966,7 +980,7 @@ void ConnectionManagerImpl::ActiveStream::maybeEndDecode(bool end_stream) {
 // can't route select properly without full headers), checking state required to
 // serve error responses (connection close, head requests, etc), and
 // modifications which may themselves affect route selection.
-void ConnectionManagerImpl::ActiveStream::decodeHeaders(RequestHeaderMapPtr&& headers,
+void ConnectionManagerImpl::ActiveStream::decodeHeaders(RequestHeaderMapSharedPtr&& headers,
                                                         bool end_stream) {
   ENVOY_STREAM_LOG(debug, "request headers complete (end_stream={}):\n{}", *this, end_stream,
                    *headers);

source/common/http/conn_manager_impl.h

@@ -192,7 +192,7 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
     void maybeEndDecode(bool end_stream);
 
     // Http::RequestDecoder
-    void decodeHeaders(RequestHeaderMapPtr&& headers, bool end_stream) override;
+    void decodeHeaders(RequestHeaderMapSharedPtr&& headers, bool end_stream) override;
     void decodeTrailers(RequestTrailerMapPtr&& trailers) override;
     StreamInfo::StreamInfo& streamInfo() override { return filter_manager_.streamInfo(); }
     void sendLocalReply(Code code, absl::string_view body,
@@ -201,6 +201,20 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
                         absl::string_view details) override {
       return filter_manager_.sendLocalReply(code, body, modify_headers, grpc_status, details);
     }
+    std::list<AccessLog::InstanceSharedPtr> accessLogHandlers() override {
+      return filter_manager_.accessLogHandlers();
+    }
+    // Hand off headers/trailers and stream info to the codec's response encoder, for logging later
+    // (i.e. possibly after this stream has been destroyed).
+    //
+    // TODO(paulsohn): Investigate whether we can move the headers/trailers and stream info required
+    // for logging instead of copying them (as is currently done in the HTTP/3 implementation) or
+    // using a shared pointer. See
+    // https://github.com/envoyproxy/envoy/pull/23648#discussion_r1066095564 for more details.
+    void deferHeadersAndTrailers() {
+      response_encoder_->setDeferredLoggingHeadersAndTrailers(request_headers_, response_headers_,
+                                                              response_trailers_, streamInfo());
+    }
 
     // ScopeTrackedObject
     void dumpState(std::ostream& os, int indent_level = 0) const override {
@@ -371,12 +385,12 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
     // both locations, then refer to the FM when doing stream logs.
     const uint64_t stream_id_;
 
-    RequestHeaderMapPtr request_headers_;
+    RequestHeaderMapSharedPtr request_headers_;
     RequestTrailerMapPtr request_trailers_;
 
     ResponseHeaderMapPtr informational_headers_;
-    ResponseHeaderMapPtr response_headers_;
-    ResponseTrailerMapPtr response_trailers_;
+    ResponseHeaderMapSharedPtr response_headers_;
+    ResponseTrailerMapSharedPtr response_trailers_;
 
     // Note: The FM must outlive the above headers, as they are possibly accessed during filter
     // destruction.

source/common/http/filter_manager.h

@@ -670,6 +670,8 @@ class FilterManager : public ScopeTrackedObject,
     }
   }
 
+  std::list<AccessLog::InstanceSharedPtr> accessLogHandlers() { return access_log_handlers_; }
+
   void onStreamComplete() {
     for (auto& filter : decoder_filters_) {
       filter->handle_->onStreamComplete();
@@ -818,6 +820,7 @@ class FilterManager : public ScopeTrackedObject,
   void contextOnContinue(ScopeTrackedObjectStack& tracked_object_stack);
 
   void onDownstreamReset() { state_.saw_downstream_reset_ = true; }
+  bool sawDownstreamReset() { return state_.saw_downstream_reset_; }
 
 protected:
   struct State {
@@ -1119,6 +1122,7 @@ class DownstreamFilterManager : public FilterManager {
                             bool is_head_request,
                             const absl::optional<Grpc::Status::GrpcStatus> grpc_status);
 
+private:
   OverridableRemoteConnectionInfoSetterStreamInfo stream_info_;
   const LocalReply::LocalReply& local_reply_;
   const bool avoid_reentrant_filter_invocation_during_local_reply_;

source/common/http/http1/codec_impl.h

@@ -155,6 +155,10 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder {
   bool streamErrorOnInvalidHttpMessage() const override {
     return stream_error_on_invalid_http_message_;
   }
+  void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr,
+                                            Http::ResponseHeaderMapConstSharedPtr,
+                                            Http::ResponseTrailerMapConstSharedPtr,
+                                            StreamInfo::StreamInfo&) override {}
 
   // For H/1, ResponseEncoder doesn't hold a pointer to RequestDecoder.
   // TODO(paulsohn): Enable H/1 codec to get a pointer to the new

source/common/http/http2/codec_impl.cc

@@ -560,7 +560,7 @@ void ConnectionImpl::ClientStreamImpl::decodeTrailers() {
 }
 
 void ConnectionImpl::ServerStreamImpl::decodeHeaders() {
-  auto& headers = absl::get<RequestHeaderMapPtr>(headers_or_trailers_);
+  auto& headers = absl::get<RequestHeaderMapSharedPtr>(headers_or_trailers_);
   if (Http::Utility::isH2UpgradeRequest(*headers)) {
     Http::Utility::transformUpgradeRequestFromH2toH1(*headers);
   }
@@ -1877,8 +1877,8 @@ void ConnectionImpl::ServerStreamImpl::dumpState(std::ostream& os, int indent_le
   StreamImpl::dumpState(os, indent_level);
 
   // Dump header map
-  if (absl::holds_alternative<RequestHeaderMapPtr>(headers_or_trailers_)) {
-    DUMP_DETAILS(absl::get<RequestHeaderMapPtr>(headers_or_trailers_));
+  if (absl::holds_alternative<RequestHeaderMapSharedPtr>(headers_or_trailers_)) {
+    DUMP_DETAILS(absl::get<RequestHeaderMapSharedPtr>(headers_or_trailers_));
   } else {
     DUMP_DETAILS(absl::get<RequestTrailerMapPtr>(headers_or_trailers_));
   }