From 4d99ab1627a9b847b6cd5fba3e4a816b1f5b883c Mon Sep 17 00:00:00 2001 From: Sunay Dagli Date: Fri, 20 Sep 2024 19:57:44 -0700 Subject: [PATCH] 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 Co-authored-by: sunaydagli --- changelogs/current.yaml | 7 ++ source/common/http/conn_manager_impl.cc | 34 ++++++++-- source/common/http/conn_manager_impl.h | 15 ++++- source/common/http/filter_manager.h | 10 +-- source/common/runtime/runtime_features.cc | 1 + test/common/http/conn_manager_impl_test.cc | 76 ++++++++++++++++++++++ 6 files changed, 126 insertions(+), 17 deletions(-) diff --git a/changelogs/current.yaml b/changelogs/current.yaml index 9d61bc564158..256fd4a98fb8 100644 --- a/changelogs/current.yaml +++ b/changelogs/current.yaml @@ -47,6 +47,13 @@ behavior_changes: ` 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 + `. + 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 index ef4bb44f46b7..e06bca9c6a80 100644 --- 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(*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 index d5c9a329286e..aef542307ff1 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -157,6 +157,7 @@ class ConnectionManagerImpl : Logger::Loggable, still_alive_.reset(); } + void log(AccessLog::AccessLogType type); void completeRequest(); const Network::Connection* connection(); @@ -190,7 +191,19 @@ class ConnectionManagerImpl : Logger::Loggable, return filter_manager_.sendLocalReply(code, body, modify_headers, grpc_status, details); } std::list accessLogHandlers() override { - return filter_manager_.accessLogHandlers(); + std::list combined_log_handlers( + filter_manager_.accessLogHandlers()); + std::list 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 index 105168585190..f1698144b390 100644 --- 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 index 085a986b269a..7b28eebbb21b 100644 --- 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 index d98b1008e2fd..44a1dacf4825 100644 --- 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>(); // filter log handler + std::shared_ptr handler( + new NiceMock()); // 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>(); // filter log handler + std::shared_ptr handler( + new NiceMock()); // 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