quic: fix defer logging of request in Access log (#37643)

Commit Message: defer the logging till either last byte ACKed or
QuicStream::OnSoonToBeDestroyed() called.

Additional Description: OnSoonToBeDestroyed() is newly added to be
called before stream object destruction. This is a better place than
QuicStatsGatherer destructor to flush the log if the last byte hasn't
been fully ACKed for whatever reason.

Risk Level: low, behind default-false feature.
Testing: integration tests passed
Docs Changes: N/A
Release Notes: N/A
Platform Specific Features: N/A
Runtime guard: guarded by existing runtime guard
`envoy.reloadable_features.quic_defer_logging_to_ack_listener`
Fixes #29930 for real

---------

Signed-off-by: Dan Zhang <[email protected]>
Co-authored-by: Dan Zhang <[email protected]>

Author: danzh2010

source/common/quic/envoy_quic_server_stream.cc

@@ -421,6 +421,12 @@ void EnvoyQuicServerStream::OnClose() {
     return;
   }
   clearWatermarkBuffer();
+  if (stats_gatherer_->notify_ack_listener_before_soon_to_be_destroyed()) {
+    // Either stats_gatherer_ will do deferred logging upon receiving the last
+    // ACK, or OnSoonToBeDestroyed() will catch all the cases where the stream
+    // is destroyed without receiving the last ACK.
+    return;
+  }
   if (!stats_gatherer_->loggingDone()) {
     stats_gatherer_->maybeDoDeferredLog(/* record_ack_timing */ false);
   }
@@ -539,5 +545,16 @@ void EnvoyQuicServerStream::useCapsuleProtocol() {
 
 void EnvoyQuicServerStream::OnInvalidHeaders() { onStreamError(absl::nullopt); }
 
+void EnvoyQuicServerStream::OnSoonToBeDestroyed() {
+  quic::QuicSpdyServerStreamBase::OnSoonToBeDestroyed();
+  if (stats_gatherer_ != nullptr &&
+      stats_gatherer_->notify_ack_listener_before_soon_to_be_destroyed() &&
+      !stats_gatherer_->loggingDone()) {
+    // Catch all the cases where the stream is destroyed without receiving the
+    // last ACK.
+    stats_gatherer_->maybeDoDeferredLog(/* record_ack_timing */ false);
+  }
+}
+
 } // namespace Quic
 } // namespace Envoy

source/common/quic/envoy_quic_server_stream.h

@@ -65,6 +65,7 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase,
 
   // quic::QuicStream
   void OnStreamFrame(const quic::QuicStreamFrame& frame) override;
+  void OnSoonToBeDestroyed() override;
   // quic::QuicSpdyStream
   void OnBodyAvailable() override;
   bool OnStopSending(quic::QuicResetStreamError error) override;

source/common/quic/quic_stats_gatherer.h

@@ -8,6 +8,7 @@
 #include "envoy/stream_info/stream_info.h"
 
 #include "quiche/quic/core/quic_ack_listener_interface.h"
+#include "quiche/quic/platform/api/quic_flags.h"
 
 namespace Envoy {
 namespace Quic {
@@ -19,7 +20,11 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface {
   explicit QuicStatsGatherer(Envoy::TimeSource* time_source) : time_source_(time_source) {}
   ~QuicStatsGatherer() override {
     if (!logging_done_) {
-      maybeDoDeferredLog(false);
+      if (notify_ack_listener_before_soon_to_be_destroyed_) {
+        ENVOY_LOG_MISC(error, "Stream destroyed without logging.");
+      } else {
+        maybeDoDeferredLog(false);
+      }
     }
   }
 
@@ -51,6 +56,9 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface {
   }
   bool loggingDone() { return logging_done_; }
   uint64_t bytesOutstanding() { return bytes_outstanding_; }
+  bool notify_ack_listener_before_soon_to_be_destroyed() const {
+    return notify_ack_listener_before_soon_to_be_destroyed_;
+  }
 
 private:
   uint64_t bytes_outstanding_ = 0;
@@ -65,6 +73,10 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface {
   bool logging_done_ = false;
   uint64_t retransmitted_packets_ = 0;
   uint64_t retransmitted_bytes_ = 0;
+
+  const bool notify_ack_listener_before_soon_to_be_destroyed_{
+      GetQuicReloadableFlag(quic_notify_ack_listener_earlier) &&
+      GetQuicReloadableFlag(quic_notify_stream_soon_to_destroy)};
 };
 
 } // namespace Quic

source/common/runtime/runtime_features.cc

@@ -135,7 +135,7 @@ FALSE_RUNTIME_GUARD(envoy_reloadable_features_quic_reject_all);
 // For more information about Universal Header Validation, please see
 // https://github.com/envoyproxy/envoy/issues/10646
 FALSE_RUNTIME_GUARD(envoy_reloadable_features_enable_universal_header_validator);
-// TODO(pksohn): enable after canarying fix for https://github.com/envoyproxy/envoy/issues/29930
+// TODO(pksohn): enable after canarying the feature internally without problems.
 FALSE_RUNTIME_GUARD(envoy_reloadable_features_quic_defer_logging_to_ack_listener);
 // TODO(alyssar) evaluate and either make this a config knob or remove.
 FALSE_RUNTIME_GUARD(envoy_reloadable_features_reresolve_null_addresses);

test/integration/quic_http_integration_test.cc

@@ -1417,13 +1417,21 @@ TEST_P(QuicHttpIntegrationTest, DeferredLogging) {
 TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithBlackholedClient) {
   config_helper_.addRuntimeOverride("envoy.reloadable_features.quic_defer_logging_to_ack_listener",
                                     "true");
+  config_helper_.addRuntimeOverride("envoy.reloadable_features.FLAGS_envoy_quiche_reloadable_flag_"
+                                    "quic_notify_stream_soon_to_destroy",
+                                    "true");
+  config_helper_.addRuntimeOverride("envoy.reloadable_features.FLAGS_envoy_quiche_reloadable_flag_"
+                                    "quic_notify_ack_listener_earlier",
+                                    "true");
+
   useAccessLog(
       "%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_"
       "CODE%,%BYTES_RECEIVED%,%ROUTE_NAME%,%VIRTUAL_CLUSTER_NAME%,%RESPONSE_CODE_DETAILS%,%"
       "CONNECTION_TERMINATION_DETAILS%,%START_TIME%,%UPSTREAM_HOST%,%DURATION%,%BYTES_SENT%,%"
       "RESPONSE_FLAGS%,%DOWNSTREAM_LOCAL_ADDRESS%,%UPSTREAM_CLUSTER%,%STREAM_ID%,%DYNAMIC_"
       "METADATA("
-      "udp.proxy.session:bytes_sent)%,%REQ(:path)%,%STREAM_INFO_REQ(:path)%");
+      "udp.proxy.session:bytes_sent)%,%REQ(:path)%,%STREAM_INFO_REQ(:path)%,%DOWNSTREAM_TLS_"
+      "CIPHER%");
   initialize();
 
   // Make a header-only request and delay the response by 1ms to ensure that the ROUNDTRIP_DURATION
@@ -1455,7 +1463,7 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithBlackholedClient) {
   std::string log = entries[0];
 
   std::vector<std::string> metrics = absl::StrSplit(log, ',');
-  ASSERT_EQ(metrics.size(), 21);
+  ASSERT_EQ(metrics.size(), 22);
   EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3");
   EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-");
   EXPECT_GE(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0);
@@ -1465,7 +1473,8 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithBlackholedClient) {
   // Ensure that request headers from top-level access logger parameter and stream info are
   // consistent.
   EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20));
-
+  EXPECT_THAT(/* DOWNSTREAM_TLS_CIPHER */ metrics.at(21),
+              ::testing::MatchesRegex("TLS_(AES_128_GCM|CHACHA20_POLY1305)_SHA256"));
   codec_client_->close();
 }