Change filter and access logger order in access_log_handlers_ (#35959)

Commit Message: Change filter and access logger order in access_log_handlers_ Additional Description: Risk Level: Testing: Docs Changes: Release Notes: Platform Specific Features: Runtime guard: envoy.reloadable_features.http_separate_config_and_filter_access_loggers Fixes: #30859 The effect of this change is to iterate the filter loggers first in order for wasm filters to fully write out dynamic metadata before any access loggers use the data, therefore fixing #30859. Thank you to @wbpcode for the suggestion! This change overrides #35924 and related PRs. --------- Signed-off-by: Sunay Dagli <[email protected]> Co-authored-by: sunaydagli <[email protected]>
envoyproxy · Sep 21, 2024 · 4d99ab1 · 4d99ab1
1 parent decbb66
commit 4d99ab1
Show file tree

Hide file tree

Showing 6 changed files with 126 additions and 17 deletions.
diff --git a/changelogs/current.yaml b/changelogs/current.yaml
@@ -47,6 +47,13 @@ behavior_changes:
     <envoy_v3_api_field_extensions.filters.network.http_connection_manager.v3.HttpConnectionManager.internal_address_config>`
     See the config examples from the above ``internal_address_config`` link. This default no trust internal address can be turned on by
     setting runtime guard ``envoy.reloadable_features.explicit_internal_address_config`` to ``true``.
+- area: http
+  change: |
+    The access log handlers that added by the filters will be evaluated before the access
+    log handlers that configured in the :ref:`access_log configuration
+    <envoy_v3_api_field_extensions.filters.network.http_connection_manager.v3.HttpConnectionManager.access_log>`.
+    This change can be disabled by setting the runtime guard flag
+    ``envoy.reloadable_features.filter_access_loggers_first`` to ``false``.
 
 minor_behavior_changes:
 # *Changes that may cause incompatibilities for some users, but should not for most*

diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc
@@ -357,7 +357,7 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) {
     stream.deferHeadersAndTrailers();
   } else {
     // For HTTP/1 and HTTP/2, log here as usual.
-    stream.filter_manager_.log(AccessLog::AccessLogType::DownstreamEnd);
+    stream.log(AccessLog::AccessLogType::DownstreamEnd);
   }
 
   stream.filter_manager_.destroyFilters();
@@ -827,9 +827,6 @@ ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connect
          "Either routeConfigProvider or (scopedRouteConfigProvider and scopeKeyBuilder) should be "
          "set in "
          "ConnectionManagerImpl.");
-  for (const AccessLog::InstanceSharedPtr& access_log : connection_manager_.config_->accessLogs()) {
-    filter_manager_.addAccessLogHandler(access_log);
-  }
 
   filter_manager_.streamInfo().setStreamIdProvider(
       std::make_shared<HttpStreamIdProviderImpl>(*this));
@@ -900,7 +897,7 @@ ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connect
       // If the request is complete, we've already done the stream-end access-log, and shouldn't
       // do the periodic log.
       if (!streamInfo().requestComplete().has_value()) {
-        filter_manager_.log(AccessLog::AccessLogType::DownstreamPeriodic);
+        log(AccessLog::AccessLogType::DownstreamPeriodic);
         refreshAccessLogFlushTimer();
       }
       const SystemTime now = connection_manager_.timeSource().systemTime();
@@ -918,6 +915,29 @@ ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connect
   }
 }
 
+void ConnectionManagerImpl::ActiveStream::log(AccessLog::AccessLogType type) {
+  const Formatter::HttpFormatterContext log_context{
+      request_headers_.get(), response_headers_.get(), response_trailers_.get(), {}, type,
+      active_span_.get()};
+
+  const bool filter_access_loggers_first =
+      Runtime::runtimeFeatureEnabled("envoy.reloadable_features.filter_access_loggers_first");
+
+  if (!filter_access_loggers_first) {
+    for (const auto& access_logger : connection_manager_.config_->accessLogs()) {
+      access_logger->log(log_context, filter_manager_.streamInfo());
+    }
+  }
+
+  filter_manager_.log(log_context);
+
+  if (filter_access_loggers_first) {
+    for (const auto& access_logger : connection_manager_.config_->accessLogs()) {
+      access_logger->log(log_context, filter_manager_.streamInfo());
+    }
+  }
+}
+
 void ConnectionManagerImpl::ActiveStream::completeRequest() {
   filter_manager_.streamInfo().onRequestComplete();
 
@@ -1370,7 +1390,7 @@ void ConnectionManagerImpl::ActiveStream::decodeHeaders(RequestHeaderMapSharedPt
   const bool upgrade_rejected = filter_manager_.createFilterChain() == false;
 
   if (connection_manager_.config_->flushAccessLogOnNewRequest()) {
-    filter_manager_.log(AccessLog::AccessLogType::DownstreamStart);
+    log(AccessLog::AccessLogType::DownstreamStart);
   }
 
   // TODO if there are no filters when starting a filter iteration, the connection manager
@@ -1846,7 +1866,7 @@ void ConnectionManagerImpl::ActiveStream::encodeHeaders(ResponseHeaderMap& heade
 
   if (state_.is_tunneling_ &&
       connection_manager_.config_->flushAccessLogOnTunnelSuccessfullyEstablished()) {
-    filter_manager_.log(AccessLog::AccessLogType::DownstreamTunnelSuccessfullyEstablished);
+    log(AccessLog::AccessLogType::DownstreamTunnelSuccessfullyEstablished);
   }
   ENVOY_STREAM_LOG(debug, "encoding headers via codec (end_stream={}):\n{}", *this, end_stream,
                    headers);

diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h
@@ -157,6 +157,7 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
       still_alive_.reset();
     }
 
+    void log(AccessLog::AccessLogType type);
     void completeRequest();
 
     const Network::Connection* connection();
@@ -190,7 +191,19 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
       return filter_manager_.sendLocalReply(code, body, modify_headers, grpc_status, details);
     }
     std::list<AccessLog::InstanceSharedPtr> accessLogHandlers() override {
-      return filter_manager_.accessLogHandlers();
+      std::list<AccessLog::InstanceSharedPtr> combined_log_handlers(
+          filter_manager_.accessLogHandlers());
+      std::list<AccessLog::InstanceSharedPtr> config_log_handlers_(
+          connection_manager_.config_->accessLogs());
+      if (!Runtime::runtimeFeatureEnabled(
+              "envoy.reloadable_features.filter_access_loggers_first")) {
+        combined_log_handlers.insert(combined_log_handlers.begin(), config_log_handlers_.begin(),
+                                     config_log_handlers_.end());
+      } else {
+        combined_log_handlers.insert(combined_log_handlers.end(), config_log_handlers_.begin(),
+                                     config_log_handlers_.end());
+      }
+      return combined_log_handlers;
     }
     // 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).

diff --git a/source/common/http/filter_manager.h b/source/common/http/filter_manager.h
@@ -696,15 +696,7 @@ class FilterManager : public ScopeTrackedObject,
   // FilterChainManager
   void applyFilterFactoryCb(FilterContext context, FilterFactoryCb& factory) override;
 
-  void log(AccessLog::AccessLogType access_log_type) {
-    const Formatter::HttpFormatterContext log_context{
-        filter_manager_callbacks_.requestHeaders().ptr(),
-        filter_manager_callbacks_.responseHeaders().ptr(),
-        filter_manager_callbacks_.responseTrailers().ptr(),
-        {},
-        access_log_type,
-        &filter_manager_callbacks_.activeSpan()};
-
+  void log(const Formatter::HttpFormatterContext log_context) {
     for (const auto& log_handler : access_log_handlers_) {
       log_handler->log(log_context, streamInfo());
     }

diff --git a/source/common/runtime/runtime_features.cc b/source/common/runtime/runtime_features.cc
@@ -47,6 +47,7 @@ RUNTIME_GUARD(envoy_reloadable_features_enable_include_histograms);
 RUNTIME_GUARD(envoy_reloadable_features_exclude_host_in_eds_status_draining);
 RUNTIME_GUARD(envoy_reloadable_features_ext_proc_timeout_error);
 RUNTIME_GUARD(envoy_reloadable_features_extend_h3_accept_untrusted);
+RUNTIME_GUARD(envoy_reloadable_features_filter_access_loggers_first);
 RUNTIME_GUARD(envoy_reloadable_features_gcp_authn_use_fixed_url);
 RUNTIME_GUARD(envoy_reloadable_features_getaddrinfo_num_retries);
 RUNTIME_GUARD(envoy_reloadable_features_grpc_side_stream_flow_control);

diff --git a/test/common/http/conn_manager_impl_test.cc b/test/common/http/conn_manager_impl_test.cc
@@ -4493,5 +4493,81 @@ TEST_F(ProxyStatusTest, PopulateProxyStatusAppendToPreviousValue) {
             "SomeCDN, custom_server_name; error=http_response_timeout; details=\"baz; UT\"");
 }
 
+TEST_F(HttpConnectionManagerImplTest, TestFilterAccessLogBeforeConfigAccessLog) {
+  log_handler_ = std::make_shared<NiceMock<AccessLog::MockInstance>>(); // filter log handler
+  std::shared_ptr<AccessLog::MockInstance> handler(
+      new NiceMock<AccessLog::MockInstance>()); // config log handler
+  access_logs_ = {handler};
+  setup();
+  setupFilterChain(1, 0);
+
+  EXPECT_CALL(*decoder_filters_[0], decodeHeaders(_, false))
+      .WillOnce(Return(FilterHeadersStatus::StopIteration));
+  startRequest();
+
+  {
+    InSequence s; // Create an InSequence object to enforce order
+
+    EXPECT_CALL(*log_handler_, log(_, _))
+        .WillOnce(Invoke([](const Formatter::HttpFormatterContext& log_context,
+                            const StreamInfo::StreamInfo& stream_info) {
+          EXPECT_EQ(AccessLog::AccessLogType::DownstreamEnd, log_context.accessLogType());
+          EXPECT_FALSE(stream_info.hasAnyResponseFlag());
+        }));
+
+    EXPECT_CALL(*handler, log(_, _))
+        .WillOnce(Invoke([](const Formatter::HttpFormatterContext& log_context,
+                            const StreamInfo::StreamInfo& stream_info) {
+          // First call to log() is made when a new HTTP request has been received
+          // On the first call it is expected that there is no response code.
+          EXPECT_EQ(AccessLog::AccessLogType::DownstreamEnd, log_context.accessLogType());
+          EXPECT_TRUE(stream_info.responseCode());
+        }));
+  }
+
+  ResponseHeaderMapPtr response_headers{new TestResponseHeaderMapImpl{{":status", "200"}}};
+  decoder_filters_[0]->callbacks_->streamInfo().setResponseCodeDetails("");
+  decoder_filters_[0]->callbacks_->encodeHeaders(std::move(response_headers), true, "details");
+}
+
+TEST_F(HttpConnectionManagerImplTest, TestFilterAccessLogBeforeConfigAccessLogFeatureFalse) {
+  TestScopedRuntime scoped_runtime;
+  scoped_runtime.mergeValues({{"envoy.reloadable_features.filter_access_loggers_first", "false"}});
+  log_handler_ = std::make_shared<NiceMock<AccessLog::MockInstance>>(); // filter log handler
+  std::shared_ptr<AccessLog::MockInstance> handler(
+      new NiceMock<AccessLog::MockInstance>()); // config log handler
+  access_logs_ = {handler};
+  setup();
+  setupFilterChain(1, 0);
+
+  EXPECT_CALL(*decoder_filters_[0], decodeHeaders(_, false))
+      .WillOnce(Return(FilterHeadersStatus::StopIteration));
+  startRequest();
+
+  {
+    InSequence s; // Create an InSequence object to enforce order
+
+    EXPECT_CALL(*handler, log(_, _))
+        .WillOnce(Invoke([](const Formatter::HttpFormatterContext& log_context,
+                            const StreamInfo::StreamInfo& stream_info) {
+          // First call to log() is made when a new HTTP request has been received
+          // On the first call it is expected that there is no response code.
+          EXPECT_EQ(AccessLog::AccessLogType::DownstreamEnd, log_context.accessLogType());
+          EXPECT_TRUE(stream_info.responseCode());
+        }));
+
+    EXPECT_CALL(*log_handler_, log(_, _))
+        .WillOnce(Invoke([](const Formatter::HttpFormatterContext& log_context,
+                            const StreamInfo::StreamInfo& stream_info) {
+          EXPECT_EQ(AccessLog::AccessLogType::DownstreamEnd, log_context.accessLogType());
+          EXPECT_FALSE(stream_info.hasAnyResponseFlag());
+        }));
+  }
+
+  ResponseHeaderMapPtr response_headers{new TestResponseHeaderMapImpl{{":status", "200"}}};
+  decoder_filters_[0]->callbacks_->streamInfo().setResponseCodeDetails("");
+  decoder_filters_[0]->callbacks_->encodeHeaders(std::move(response_headers), true, "details");
+}
+
 } // namespace Http
 } // namespace Envoy