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