From e8a80ff545515995f3bee582c1cf3e70842aca08 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 24 Oct 2022 21:46:15 +0000 Subject: [PATCH 01/59] HCM ActiveStream has shared pointers to loggable header maps Make the following into shared pointers so they can be used in deferred logging that can be executed after a stream is destroyed: - request header map - response header map - response trailer map Signed-off-by: Paul Sohn --- envoy/http/codec.h | 2 +- envoy/http/header_map.h | 3 +++ source/common/http/conn_manager_impl.cc | 4 ++-- source/common/http/conn_manager_impl.h | 8 ++++---- test/integration/fake_upstream.cc | 2 +- test/integration/fake_upstream.h | 4 ++-- test/mocks/http/stream_decoder.cc | 11 ++++++----- test/mocks/http/stream_decoder.h | 4 ++-- 8 files changed, 21 insertions(+), 17 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 99c696964c584..505bf25ef9d30 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -202,7 +202,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. diff --git a/envoy/http/header_map.h b/envoy/http/header_map.h index 79fe6dc49e0f2..a24af50d1ba9f 100644 --- a/envoy/http/header_map.h +++ b/envoy/http/header_map.h @@ -716,6 +716,7 @@ class RequestHeaderMap INLINE_REQ_NUMERIC_HEADERS(DEFINE_INLINE_NUMERIC_HEADER) }; using RequestHeaderMapPtr = std::unique_ptr; +using RequestHeaderMapSharedPtr = std::shared_ptr; using RequestHeaderMapOptRef = OptRef; using RequestHeaderMapOptConstRef = OptRef; @@ -746,6 +747,7 @@ class ResponseHeaderMap INLINE_RESP_NUMERIC_HEADERS(DEFINE_INLINE_NUMERIC_HEADER) }; using ResponseHeaderMapPtr = std::unique_ptr; +using ResponseHeaderMapSharedPtr = std::shared_ptr; using ResponseHeaderMapOptRef = OptRef; using ResponseHeaderMapOptConstRef = OptRef; @@ -755,6 +757,7 @@ class ResponseTrailerMap public HeaderMap, public CustomInlineHeaderBase {}; using ResponseTrailerMapPtr = std::unique_ptr; +using ResponseTrailerMapSharedPtr = std::shared_ptr; using ResponseTrailerMapOptRef = OptRef; using ResponseTrailerMapOptConstRef = OptRef; diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index 06422fa156e99..dadb00ed1261f 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -54,7 +54,7 @@ namespace Envoy { namespace Http { -bool requestWasConnect(const RequestHeaderMapPtr& headers, Protocol protocol) { +bool requestWasConnect(const RequestHeaderMapSharedPtr& headers, Protocol protocol) { if (!headers) { return false; } @@ -924,7 +924,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); diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 583bea311d922..064fc4af1a288 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -192,7 +192,7 @@ class ConnectionManagerImpl : Logger::Loggable, 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, @@ -367,12 +367,12 @@ class ConnectionManagerImpl : Logger::Loggable, // 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. diff --git a/test/integration/fake_upstream.cc b/test/integration/fake_upstream.cc index af3c9339b0018..deab131d8b541 100644 --- a/test/integration/fake_upstream.cc +++ b/test/integration/fake_upstream.cc @@ -44,7 +44,7 @@ FakeStream::FakeStream(FakeHttpConnection& parent, Http::ResponseEncoder& encode encoder.getStream().addCallbacks(*this); } -void FakeStream::decodeHeaders(Http::RequestHeaderMapPtr&& headers, bool end_stream) { +void FakeStream::decodeHeaders(Http::RequestHeaderMapSharedPtr&& headers, bool end_stream) { absl::MutexLock lock(&lock_); headers_ = std::move(headers); setEndStream(end_stream); diff --git a/test/integration/fake_upstream.h b/test/integration/fake_upstream.h index 2f0db99112b82..ddf4617cc9d5e 100644 --- a/test/integration/fake_upstream.h +++ b/test/integration/fake_upstream.h @@ -219,7 +219,7 @@ class FakeStream : public Http::RequestDecoder, void decodeMetadata(Http::MetadataMapPtr&& metadata_map_ptr) override; // Http::RequestDecoder - void decodeHeaders(Http::RequestHeaderMapPtr&& headers, bool end_stream) override; + void decodeHeaders(Http::RequestHeaderMapSharedPtr&& headers, bool end_stream) override; void decodeTrailers(Http::RequestTrailerMapPtr&& trailers) override; StreamInfo::StreamInfo& streamInfo() override { RELEASE_ASSERT(false, "initialize if this is needed"); @@ -243,7 +243,7 @@ class FakeStream : public Http::RequestDecoder, protected: absl::Mutex lock_; - Http::RequestHeaderMapPtr headers_ ABSL_GUARDED_BY(lock_); + Http::RequestHeaderMapSharedPtr headers_ ABSL_GUARDED_BY(lock_); Buffer::OwnedImpl body_ ABSL_GUARDED_BY(lock_); FakeHttpConnection& parent_; diff --git a/test/mocks/http/stream_decoder.cc b/test/mocks/http/stream_decoder.cc index 76145b6dc43f6..ae778dff5c886 100644 --- a/test/mocks/http/stream_decoder.cc +++ b/test/mocks/http/stream_decoder.cc @@ -7,11 +7,12 @@ namespace Envoy { namespace Http { MockRequestDecoder::MockRequestDecoder() { - ON_CALL(*this, decodeHeaders_(_, _)).WillByDefault(Invoke([](RequestHeaderMapPtr& headers, bool) { - // Check to see that method is not-null. Path can be null for CONNECT and authority can be null - // at the codec level. - ASSERT_NE(nullptr, headers->Method()); - })); + ON_CALL(*this, decodeHeaders_(_, _)) + .WillByDefault(Invoke([](RequestHeaderMapSharedPtr& headers, bool) { + // Check to see that method is not-null. Path can be null for CONNECT and authority can be + // null at the codec level. + ASSERT_NE(nullptr, headers->Method()); + })); } MockRequestDecoder::~MockRequestDecoder() = default; diff --git a/test/mocks/http/stream_decoder.h b/test/mocks/http/stream_decoder.h index 8bf5e5305d4fd..072eca832ba17 100644 --- a/test/mocks/http/stream_decoder.h +++ b/test/mocks/http/stream_decoder.h @@ -23,13 +23,13 @@ class MockRequestDecoder : public RequestDecoder { absl::string_view details)); MOCK_METHOD(StreamInfo::StreamInfo&, streamInfo, ()); - void decodeHeaders(RequestHeaderMapPtr&& headers, bool end_stream) override { + void decodeHeaders(RequestHeaderMapSharedPtr&& headers, bool end_stream) override { decodeHeaders_(headers, end_stream); } void decodeTrailers(RequestTrailerMapPtr&& trailers) override { decodeTrailers_(trailers); } // Http::RequestDecoder - MOCK_METHOD(void, decodeHeaders_, (RequestHeaderMapPtr & headers, bool end_stream)); + MOCK_METHOD(void, decodeHeaders_, (RequestHeaderMapSharedPtr & headers, bool end_stream)); MOCK_METHOD(void, decodeTrailers_, (RequestTrailerMapPtr & trailers)); }; From dd13f8573024de63250ea8b9e466d019af866b40 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 25 Oct 2022 03:59:06 +0000 Subject: [PATCH 02/59] Add deferred logging info to stream info These are the stream-level items currently passed to access loggers (other than the stream info itself). For deferred logging (i.e. after the stream itself might be destroyed), we need shared pointers to these items. Signed-off-by: Paul Sohn --- envoy/stream_info/stream_info.h | 16 ++++++++++++++++ source/common/stream_info/stream_info_impl.h | 9 +++++++++ test/mocks/stream_info/mocks.h | 3 +++ 3 files changed, 28 insertions(+) diff --git a/envoy/stream_info/stream_info.h b/envoy/stream_info/stream_info.h index 7d532305c91e7..da922a3b2eb79 100644 --- a/envoy/stream_info/stream_info.h +++ b/envoy/stream_info/stream_info.h @@ -453,6 +453,12 @@ class UpstreamInfo { virtual absl::optional upstreamProtocol() const PURE; }; +struct DeferredLoggingInfo { + Http::RequestHeaderMapSharedPtr request_header_map = nullptr; + Http::ResponseHeaderMapSharedPtr response_header_map = nullptr; + Http::ResponseTrailerMapSharedPtr response_trailer_map = nullptr; +}; + /** * Additional information about a completed request for logging. */ @@ -758,6 +764,16 @@ class StreamInfo { * This function is called on Envoy fatal errors so should avoid memory allocation. */ virtual void dumpState(std::ostream& os, int indent_level = 0) const PURE; + + /** + * @param deferredLoggingInfo request/response info for deferred logging. + */ + virtual void setDeferredLoggingInfo(const DeferredLoggingInfo deferredLoggingInfo) PURE; + + /** + * @return request/response info for deferred logging. + */ + virtual const absl::optional& deferredLoggingInfo() const PURE; }; // An enum representation of the Proxy-Status error space. diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index c666890849691..9a6a31e746738 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -231,6 +231,14 @@ struct StreamInfoImpl : public StreamInfo { return virtual_cluster_name_; } + void setDeferredLoggingInfo(DeferredLoggingInfo deferredLoggingInfo) override { + deferred_logging_info_ = + absl::make_optional(std::move(deferredLoggingInfo)); + } + const absl::optional& deferredLoggingInfo() const override { + return deferred_logging_info_; + } + bool healthCheck() const override { return health_check_request_; } void healthCheck(bool is_health_check) override { health_check_request_ = is_health_check; } @@ -356,6 +364,7 @@ struct StreamInfoImpl : public StreamInfo { // TODO(agrawroh): Check if the owner of this storage outlives the StreamInfo. We should only copy // the string if it could outlive the StreamInfo. absl::optional virtual_cluster_name_; + absl::optional deferred_logging_info_; private: static Network::ConnectionInfoProviderSharedPtr emptyDownstreamAddressProvider() { diff --git a/test/mocks/stream_info/mocks.h b/test/mocks/stream_info/mocks.h index 97516eaac05dc..b0733dc2244a7 100644 --- a/test/mocks/stream_info/mocks.h +++ b/test/mocks/stream_info/mocks.h @@ -93,6 +93,8 @@ class MockStreamInfo : public StreamInfo { MOCK_METHOD(const absl::optional&, virtualClusterName, (), (const)); MOCK_METHOD(absl::optional, protocol, (), (const)); MOCK_METHOD(void, protocol, (Http::Protocol protocol)); + MOCK_METHOD(void, setDeferredLoggingInfo, (DeferredLoggingInfo deferredLoggingInfo)); + MOCK_METHOD(const absl::optional&, deferredLoggingInfo, (), (const)); MOCK_METHOD(absl::optional, responseCode, (), (const)); MOCK_METHOD(const absl::optional&, responseCodeDetails, (), (const)); MOCK_METHOD(const absl::optional&, connectionTerminationDetails, (), (const)); @@ -158,6 +160,7 @@ class MockStreamInfo : public StreamInfo { std::string filter_chain_name_; absl::optional attempt_count_; absl::optional virtual_cluster_name_; + absl::optional deferred_logging_info_; DownstreamTiming downstream_timing_; }; From bebc3a2eb88973f10df4717025136d016932e304 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 25 Oct 2022 18:39:12 +0000 Subject: [PATCH 03/59] Add "last downstream ack" timing to stream info Signed-off-by: Paul Sohn --- envoy/stream_info/stream_info.h | 9 +++++++++ source/common/stream_info/utility.cc | 8 ++++++++ source/common/stream_info/utility.h | 1 + test/common/stream_info/stream_info_impl_test.cc | 4 ++++ 4 files changed, 22 insertions(+) diff --git a/envoy/stream_info/stream_info.h b/envoy/stream_info/stream_info.h index da922a3b2eb79..59639c5767433 100644 --- a/envoy/stream_info/stream_info.h +++ b/envoy/stream_info/stream_info.h @@ -285,6 +285,9 @@ class DownstreamTiming { absl::optional downstreamHandshakeComplete() const { return downstream_handshake_complete_; } + absl::optional 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 timings_; @@ -313,6 +320,8 @@ class DownstreamTiming { absl::optional last_downstream_tx_byte_sent_; // The time the TLS handshake completed. Set at connection level. absl::optional downstream_handshake_complete_; + // The time the final ack was received from the client. + absl::optional last_downstream_ack_received_; }; // Measure the number of bytes sent and received for a stream. diff --git a/source/common/stream_info/utility.cc b/source/common/stream_info/utility.cc index 5b8cebb2d30ad..9d25b0e5dd47c 100644 --- a/source/common/stream_info/utility.cc +++ b/source/common/stream_info/utility.cc @@ -130,6 +130,14 @@ absl::optional TimingUtility::downstreamHandshakeCompl return duration(timing.value().get().downstreamHandshakeComplete(), stream_info_); } +absl::optional TimingUtility::lastDownstreamAckReceived() { + OptRef timing = stream_info_.downstreamTiming(); + if (!timing) { + return absl::nullopt; + } + return duration(timing.value().get().lastDownstreamAckReceived(), stream_info_); +} + const std::string& Utility::formatDownstreamAddressNoPort(const Network::Address::Instance& address) { if (address.type() == Network::Address::Type::Ip) { diff --git a/source/common/stream_info/utility.h b/source/common/stream_info/utility.h index f4526fbb6fbfa..ab6db6c23ff0a 100644 --- a/source/common/stream_info/utility.h +++ b/source/common/stream_info/utility.h @@ -98,6 +98,7 @@ class TimingUtility { absl::optional lastDownstreamTxByteSent(); absl::optional lastDownstreamRxByteReceived(); absl::optional downstreamHandshakeComplete(); + absl::optional lastDownstreamAckReceived(); private: const StreamInfo& stream_info_; diff --git a/test/common/stream_info/stream_info_impl_test.cc b/test/common/stream_info/stream_info_impl_test.cc index 9cce36e357b48..7cb4caa0eb683 100644 --- a/test/common/stream_info/stream_info_impl_test.cc +++ b/test/common/stream_info/stream_info_impl_test.cc @@ -83,6 +83,10 @@ TEST_F(StreamInfoImplTest, TimingTest) { info.downstreamTiming().onDownstreamHandshakeComplete(test_time_.timeSystem()); dur = checkDuration(dur, timing.downstreamHandshakeComplete()); + EXPECT_FALSE(timing.lastDownstreamAckReceived()); + info.downstreamTiming().onLastDownstreamAckReceived(test_time_.timeSystem()); + dur = checkDuration(dur, timing.lastDownstreamAckReceived()); + EXPECT_FALSE(info.requestComplete()); info.onRequestComplete(); dur = checkDuration(dur, info.requestComplete()); From a13b24f3db9fd0d19510d9f60aacc21051435e53 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Fri, 4 Nov 2022 19:10:32 +0000 Subject: [PATCH 04/59] Add list of access log handlers to RequestDecoder interface Signed-off-by: Paul Sohn --- envoy/http/BUILD | 1 + envoy/http/codec.h | 6 ++++++ source/common/http/conn_manager_impl.h | 3 +++ source/common/http/filter_manager.h | 2 ++ test/integration/fake_upstream.h | 4 ++++ 5 files changed, 16 insertions(+) diff --git a/envoy/http/BUILD b/envoy/http/BUILD index 927feafe5c6fd..cddd7c25e716b 100644 --- a/envoy/http/BUILD +++ b/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", diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 505bf25ef9d30..e69f18c042938 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -14,6 +14,7 @@ #include "envoy/http/stream_reset_handler.h" #include "envoy/network/address.h" #include "envoy/stream_info/stream_info.h" +#include "envoy/access_log/access_log.h" #include "source/common/http/status.h" @@ -227,6 +228,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 accessLogHandlers() PURE; }; /** diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 064fc4af1a288..2dd7bc8c97cad 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -201,6 +201,9 @@ class ConnectionManagerImpl : Logger::Loggable, absl::string_view details) override { return filter_manager_.sendLocalReply(code, body, modify_headers, grpc_status, details); } + std::list accessLogHandlers() override { + return filter_manager_.accessLogHandlers(); + } // Tracing::TracingConfig Tracing::OperationName operationName() const override; diff --git a/source/common/http/filter_manager.h b/source/common/http/filter_manager.h index d4c13ff561ddb..eb76e664f04e7 100644 --- a/source/common/http/filter_manager.h +++ b/source/common/http/filter_manager.h @@ -668,6 +668,8 @@ class FilterManager : public ScopeTrackedObject, } } + std::list accessLogHandlers() { return access_log_handlers_; } + void onStreamComplete() { for (auto& filter : decoder_filters_) { filter->handle_->onStreamComplete(); diff --git a/test/integration/fake_upstream.h b/test/integration/fake_upstream.h index ddf4617cc9d5e..b1fc7be2daf6a 100644 --- a/test/integration/fake_upstream.h +++ b/test/integration/fake_upstream.h @@ -225,6 +225,9 @@ class FakeStream : public Http::RequestDecoder, RELEASE_ASSERT(false, "initialize if this is needed"); return *stream_info_; } + std::list accessLogHandlers() override { + return access_log_handlers_; + } // Http::StreamCallbacks void onResetStream(Http::StreamResetReason reason, @@ -259,6 +262,7 @@ class FakeStream : public Http::RequestDecoder, Http::MetadataMap metadata_map_; absl::node_hash_map duplicated_metadata_key_count_; std::unique_ptr stream_info_; + std::list access_log_handlers_; bool received_data_{false}; bool grpc_stream_started_{false}; }; From ed44a5ec99f83d275889e166bcae69ed93198c57 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Fri, 4 Nov 2022 20:03:49 +0000 Subject: [PATCH 05/59] Add shared ptr to stream's stream_info to RequestDecoder interface We need this because when we defer logging, the old streaminfo owned by the filter manager may be destroyed by the time we want to log using it. Signed-off-by: Paul Sohn --- envoy/http/codec.h | 7 ++++++- source/common/http/conn_manager_impl.h | 3 +++ source/common/http/filter_manager.h | 15 +++++++++------ test/integration/fake_upstream.h | 3 ++- 4 files changed, 20 insertions(+), 8 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index e69f18c042938..37692c7a43b57 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -4,6 +4,7 @@ #include #include +#include "envoy/access_log/access_log.h" #include "envoy/buffer/buffer.h" #include "envoy/common/pure.h" #include "envoy/grpc/status.h" @@ -14,7 +15,6 @@ #include "envoy/http/stream_reset_handler.h" #include "envoy/network/address.h" #include "envoy/stream_info/stream_info.h" -#include "envoy/access_log/access_log.h" #include "source/common/http/status.h" @@ -229,6 +229,11 @@ class RequestDecoder : public virtual StreamDecoder { */ virtual StreamInfo::StreamInfo& streamInfo() PURE; + /** + * @return Shared pointer to the stream_info for this stream. + */ + virtual std::shared_ptr streamInfoSharedPtr() PURE; + /** * @return List of shared pointers to access loggers for this stream. */ diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 2dd7bc8c97cad..19090018e5bba 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -201,6 +201,9 @@ class ConnectionManagerImpl : Logger::Loggable, absl::string_view details) override { return filter_manager_.sendLocalReply(code, body, modify_headers, grpc_status, details); } + std::shared_ptr streamInfoSharedPtr() override { + return filter_manager_.streamInfoSharedPtr(); + } std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } diff --git a/source/common/http/filter_manager.h b/source/common/http/filter_manager.h index eb76e664f04e7..1e06173e5ba14 100644 --- a/source/common/http/filter_manager.h +++ b/source/common/http/filter_manager.h @@ -1029,17 +1029,20 @@ class DownstreamFilterManager : public FilterManager { StreamInfo::FilterState::LifeSpan filter_state_life_span) : FilterManager(filter_manager_callbacks, dispatcher, connection, stream_id, account, proxy_100_continue, buffer_limit, filter_chain_factory), - stream_info_(protocol, time_source, connection.connectionInfoProviderSharedPtr(), - parent_filter_state, filter_state_life_span), + stream_info_(std::make_shared( + protocol, time_source, connection.connectionInfoProviderSharedPtr(), + parent_filter_state, filter_state_life_span)), local_reply_(local_reply) {} // TODO(snowp): This should probably return a StreamInfo instead of the impl. - StreamInfo::StreamInfoImpl& streamInfo() override { return stream_info_; } - const StreamInfo::StreamInfoImpl& streamInfo() const override { return stream_info_; } + StreamInfo::StreamInfoImpl& streamInfo() override { return *stream_info_; } + const StreamInfo::StreamInfoImpl& streamInfo() const override { return *stream_info_; } + + std::shared_ptr streamInfoSharedPtr() { return stream_info_; } void setDownstreamRemoteAddress( const Network::Address::InstanceConstSharedPtr& downstream_remote_address) { - stream_info_.setDownstreamRemoteAddress(downstream_remote_address); + stream_info_->setDownstreamRemoteAddress(downstream_remote_address); } /** @@ -1081,7 +1084,7 @@ class DownstreamFilterManager : public FilterManager { } private: - OverridableRemoteConnectionInfoSetterStreamInfo stream_info_; + std::shared_ptr stream_info_; const LocalReply::LocalReply& local_reply_; }; diff --git a/test/integration/fake_upstream.h b/test/integration/fake_upstream.h index b1fc7be2daf6a..1cff9656166a4 100644 --- a/test/integration/fake_upstream.h +++ b/test/integration/fake_upstream.h @@ -225,6 +225,7 @@ class FakeStream : public Http::RequestDecoder, RELEASE_ASSERT(false, "initialize if this is needed"); return *stream_info_; } + std::shared_ptr streamInfoSharedPtr() override { return stream_info_; } std::list accessLogHandlers() override { return access_log_handlers_; } @@ -261,7 +262,7 @@ class FakeStream : public Http::RequestDecoder, Event::TestTimeSystem& time_system_; Http::MetadataMap metadata_map_; absl::node_hash_map duplicated_metadata_key_count_; - std::unique_ptr stream_info_; + std::shared_ptr stream_info_; std::list access_log_handlers_; bool received_data_{false}; bool grpc_stream_started_{false}; From b9d9c147a25370d31b0dac448c028e0b074c133d Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 18:06:25 +0000 Subject: [PATCH 06/59] Add roundtrip timing to standard substitution formatter Signed-off-by: Paul Sohn --- .../formatter/substitution_formatter.cc | 9 +++++++ .../substitution_formatter_fuzz_test.dict | 1 + .../formatter/substitution_formatter_test.cc | 25 +++++++++++++++++++ 3 files changed, 35 insertions(+) diff --git a/source/common/formatter/substitution_formatter.cc b/source/common/formatter/substitution_formatter.cc index 4d28eb508f990..72e4a4461211c 100644 --- a/source/common/formatter/substitution_formatter.cc +++ b/source/common/formatter/substitution_formatter.cc @@ -913,6 +913,15 @@ const StreamInfoFormatter::FieldExtractorLookupTbl& StreamInfoFormatter::getKnow return timing.downstreamHandshakeComplete(); }); }}}, + {"ROUNDTRIP_DURATION", + {CommandSyntaxChecker::COMMAND_ONLY, + [](const std::string&, const absl::optional&) { + return std::make_unique( + [](const StreamInfo::StreamInfo& stream_info) { + StreamInfo::TimingUtility timing(stream_info); + return timing.lastDownstreamAckReceived(); + }); + }}}, {"BYTES_RECEIVED", {CommandSyntaxChecker::COMMAND_ONLY, [](const std::string&, const absl::optional&) { diff --git a/test/common/formatter/substitution_formatter_fuzz_test.dict b/test/common/formatter/substitution_formatter_fuzz_test.dict index 4886e898c93f3..637faeacff65f 100644 --- a/test/common/formatter/substitution_formatter_fuzz_test.dict +++ b/test/common/formatter/substitution_formatter_fuzz_test.dict @@ -11,6 +11,7 @@ "%RESPONSE_DURATION%" "%RESPONSE_FLAGS%" "%RESPONSE_TX_DURATION%" +"%ROUNDTRIP_DURATION%" "%DOWNSTREAM_HANDSHAKE_DURATION%" "%ROUTE_NAME%" "%UPSTREAM_HOST%" diff --git a/test/common/formatter/substitution_formatter_test.cc b/test/common/formatter/substitution_formatter_test.cc index 5ed398ca19565..d87396b4ff0bb 100644 --- a/test/common/formatter/substitution_formatter_test.cc +++ b/test/common/formatter/substitution_formatter_test.cc @@ -325,6 +325,31 @@ TEST(SubstitutionFormatterTest, streamInfoFormatter) { ProtoEq(ValueUtil::numberValue(25.0))); } + { + StreamInfoFormatter roundtrip_duration_format("ROUNDTRIP_DURATION"); + + EXPECT_EQ(absl::nullopt, + roundtrip_duration_format.format(request_headers, response_headers, response_trailers, + stream_info, body)); + EXPECT_THAT(roundtrip_duration_format.formatValue(request_headers, response_headers, + response_trailers, stream_info, body), + ProtoEq(ValueUtil::nullValue())); + } + + { + StreamInfoFormatter roundtrip_duration_format("ROUNDTRIP_DURATION"); + + EXPECT_CALL(time_system, monotonicTime) + .WillOnce(Return(MonotonicTime(std::chrono::nanoseconds(25000000)))); + stream_info.downstream_timing_.onLastDownstreamAckReceived(time_system); + + EXPECT_EQ("25", roundtrip_duration_format.format(request_headers, response_headers, + response_trailers, stream_info, body)); + EXPECT_THAT(roundtrip_duration_format.formatValue(request_headers, response_headers, + response_trailers, stream_info, body), + ProtoEq(ValueUtil::numberValue(25.0))); + } + { StreamInfoFormatter bytes_received_format("BYTES_RECEIVED"); EXPECT_CALL(stream_info, bytesReceived()).WillRepeatedly(Return(1)); From e9da2a21c6bd635f870edc6126ddd55f47920811 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 18:07:58 +0000 Subject: [PATCH 07/59] Introduce QuicStatsGatherer which implements QuicAckListenerInterface Signed-off-by: Paul Sohn --- source/common/quic/BUILD | 12 ++++++ source/common/quic/quic_stats_gatherer.cc | 35 +++++++++++++++++ source/common/quic/quic_stats_gatherer.h | 47 +++++++++++++++++++++++ 3 files changed, 94 insertions(+) create mode 100644 source/common/quic/quic_stats_gatherer.cc create mode 100644 source/common/quic/quic_stats_gatherer.h diff --git a/source/common/quic/BUILD b/source/common/quic/BUILD index d8fd4460dbb24..94e5c2fd246bd 100644 --- a/source/common/quic/BUILD +++ b/source/common/quic/BUILD @@ -525,3 +525,15 @@ envoy_cc_library( "@com_github_google_quiche//:quic_load_balancer_encoder_lib", ], ) + +envoy_cc_library( + name = "quic_stats_gatherer", + srcs = ["quic_stats_gatherer.cc"], + hdrs = ["quic_stats_gatherer.h"], + tags = ["nofips"], + deps = [ + "//envoy/access_log:access_log_interface", + "//source/common/http:header_map_lib", + "@com_github_google_quiche//:quic_core_ack_listener_interface_lib", + ], +) diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc new file mode 100644 index 0000000000000..ac57b408e3734 --- /dev/null +++ b/source/common/quic/quic_stats_gatherer.cc @@ -0,0 +1,35 @@ +#include "source/common/quic/quic_stats_gatherer.h" +#include "source/common/common/logger.h" + +#include + +namespace Envoy { +namespace Quic { + +void QuicStatsGatherer::OnPacketAcked(int acked_bytes, + quic::QuicTime::Delta /* delta_largest_observed */) { + bytes_outstanding_ -= acked_bytes; + if (bytes_outstanding_ == 0 && fin_sent_) { + DoDeferredLog(); + } +} + +void QuicStatsGatherer::DoDeferredLog() { + for (const std::shared_ptr& stream_info : stream_info_) { + if (!stream_info->deferredLoggingInfo().has_value()) { + continue; + } + if (time_source_ != nullptr) { + stream_info->downstreamTiming().onLastDownstreamAckReceived(*time_source_); + } + auto request_headers = stream_info->deferredLoggingInfo()->request_header_map.get(); + auto response_headers = stream_info->deferredLoggingInfo()->response_header_map.get(); + auto response_trailers = stream_info->deferredLoggingInfo()->response_trailer_map.get(); + for (const auto& log_handler : access_log_handlers_) { + log_handler->log(request_headers, response_headers, response_trailers, *stream_info); + } + } +} + +} // namespace Quic +} // namespace Envoy diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h new file mode 100644 index 0000000000000..2eeada934e1c9 --- /dev/null +++ b/source/common/quic/quic_stats_gatherer.h @@ -0,0 +1,47 @@ +#pragma once + +#include + +#include "envoy/access_log/access_log.h" +#include "envoy/http/codec.h" +#include "envoy/http/header_map.h" +#include "envoy/stream_info/stream_info.h" + +#include "quiche/quic/core/quic_ack_listener_interface.h" + +using Envoy::Http::RequestHeaderMap; +using Envoy::Http::ResponseHeaderMap; +using Envoy::Http::ResponseTrailerMap; + +namespace Envoy { +namespace Quic { + +class QuicStatsGatherer : public quic::QuicAckListenerInterface { +public: + void OnPacketAcked(int acked_bytes, quic::QuicTime::Delta delta_largest_observed) override; + void OnPacketRetransmitted(int /* retransmitted_bytes */) override {} + void AddBytesSent(uint64_t bytes_sent, bool end_stream) { + bytes_outstanding_ += bytes_sent; + fin_sent_ = end_stream; + } + void DoDeferredLog(); + void add_stream_info(std::shared_ptr stream_info) { + if (stream_info != nullptr) { + stream_info_.push_back(stream_info); + } + } + void set_access_log_handlers(std::list handlers) { + access_log_handlers_ = handlers; + } + void set_time_source(Envoy::TimeSource* time_source) { time_source_ = time_source; } + +private: + uint64_t bytes_outstanding_ = 0; + bool fin_sent_ = false; + std::list> stream_info_{}; + std::list access_log_handlers_{}; + Envoy::TimeSource* time_source_ = nullptr; +}; + +} // namespace Quic +} // namespace Envoy From 002cd987f529a304685b643894ae0e11ac7f3c15 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 18:09:55 +0000 Subject: [PATCH 08/59] EnvoyQuicServerStream uses QuicStatsGatherer as ack-listener Signed-off-by: Paul Sohn --- source/common/quic/BUILD | 1 + source/common/quic/envoy_quic_server_stream.cc | 8 ++++++++ source/common/quic/envoy_quic_server_stream.h | 11 ++++++++++- 3 files changed, 19 insertions(+), 1 deletion(-) diff --git a/source/common/quic/BUILD b/source/common/quic/BUILD index 94e5c2fd246bd..54f87a0a28029 100644 --- a/source/common/quic/BUILD +++ b/source/common/quic/BUILD @@ -253,6 +253,7 @@ envoy_cc_library( ":envoy_quic_utils_lib", ":quic_filter_manager_connection_lib", ":quic_stat_names_lib", + ":quic_stats_gatherer", "//source/common/buffer:buffer_lib", "//source/common/common:assert_lib", "//source/common/http:header_map_lib", diff --git a/source/common/quic/envoy_quic_server_stream.cc b/source/common/quic/envoy_quic_server_stream.cc index e3b21c7107c42..a8bf8d4ea2da3 100644 --- a/source/common/quic/envoy_quic_server_stream.cc +++ b/source/common/quic/envoy_quic_server_stream.cc @@ -11,6 +11,7 @@ #include "source/common/http/header_utility.h" #include "source/common/quic/envoy_quic_server_session.h" #include "source/common/quic/envoy_quic_utils.h" +#include "source/common/quic/quic_stats_gatherer.h" #include "quiche/quic/core/http/quic_header_list.h" #include "quiche/quic/core/quic_session.h" @@ -36,6 +37,9 @@ EnvoyQuicServerStream::EnvoyQuicServerStream( headers_with_underscores_action_(headers_with_underscores_action) { ASSERT(static_cast(GetReceiveWindow().value()) > 8 * 1024, "Send buffer limit should be larger than 8KB."); + + stats_gatherer_ = new QuicStatsGatherer(); + set_ack_listener(stats_gatherer_); } void EnvoyQuicServerStream::encode1xxHeaders(const Http::ResponseHeaderMap& headers) { @@ -55,6 +59,7 @@ void EnvoyQuicServerStream::encodeHeaders(const Http::ResponseHeaderMap& headers { IncrementalBytesSentTracker tracker(*this, *mutableBytesMeter(), true); size_t bytes_sent = WriteHeaders(envoyHeadersToHttp2HeaderBlock(headers), end_stream, nullptr); + stats_gatherer_->AddBytesSent(bytes_sent, end_stream); ENVOY_BUG(bytes_sent != 0, "Failed to encode headers."); } @@ -93,6 +98,7 @@ void EnvoyQuicServerStream::encodeData(Buffer::Instance& data, bool end_stream) { IncrementalBytesSentTracker tracker(*this, *mutableBytesMeter(), false); result = WriteBodySlices(span, end_stream); + stats_gatherer_->AddBytesSent(result.bytes_consumed, end_stream); } // QUIC stream must take all. if (result.bytes_consumed == 0 && has_data) { @@ -122,6 +128,7 @@ void EnvoyQuicServerStream::encodeTrailers(const Http::ResponseTrailerMap& trail IncrementalBytesSentTracker tracker(*this, *mutableBytesMeter(), true); size_t bytes_sent = WriteTrailers(envoyHeadersToHttp2HeaderBlock(trailers), nullptr); ENVOY_BUG(bytes_sent != 0, "Failed to encode trailers."); + stats_gatherer_->AddBytesSent(bytes_sent, true); } onLocalEndStream(); } @@ -381,6 +388,7 @@ void EnvoyQuicServerStream::OnClose() { return; } clearWatermarkBuffer(); + stats_gatherer_ = nullptr; } void EnvoyQuicServerStream::clearWatermarkBuffer() { diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index edd3aa60887ca..205aa36220404 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -1,8 +1,10 @@ #pragma once #include "source/common/quic/envoy_quic_stream.h" +#include "source/common/quic/quic_stats_gatherer.h" #include "quiche/quic/core/http/quic_spdy_server_stream_base.h" +#include "quiche/common/platform/api/quiche_reference_counted.h" namespace Envoy { namespace Quic { @@ -18,7 +20,12 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, envoy::config::core::v3::HttpProtocolOptions::HeadersWithUnderscoresAction headers_with_underscores_action); - void setRequestDecoder(Http::RequestDecoder& decoder) { request_decoder_ = &decoder; } + void setRequestDecoder(Http::RequestDecoder& decoder) { + request_decoder_ = &decoder; + stats_gatherer_->add_stream_info(request_decoder_->streamInfoSharedPtr()); + stats_gatherer_->set_access_log_handlers(request_decoder_->accessLogHandlers()); + stats_gatherer_->set_time_source(&connection()->dispatcher().timeSource()); + } // Http::StreamEncoder void encode1xxHeaders(const Http::ResponseHeaderMap& headers) override; @@ -85,6 +92,8 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, Http::RequestDecoder* request_decoder_{nullptr}; envoy::config::core::v3::HttpProtocolOptions::HeadersWithUnderscoresAction headers_with_underscores_action_; + + quiche::QuicheReferenceCountedPointer stats_gatherer_; }; } // namespace Quic From 4b2abadbbe65b5d8c7226a1790631ce70e99ddaf Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 18:10:43 +0000 Subject: [PATCH 09/59] doDeferredStreamDestroy defers logging for H/3 Signed-off-by: Paul Sohn --- source/common/http/conn_manager_impl.cc | 6 +++++- source/common/http/conn_manager_impl.h | 13 +++++++++++++ test/integration/quic_http_integration_test.cc | 12 ++++++++++++ 3 files changed, 30 insertions(+), 1 deletion(-) diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index dadb00ed1261f..bfc803c5481bc 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -278,7 +278,11 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { stream.completeRequest(); stream.filter_manager_.onStreamComplete(); - stream.filter_manager_.log(); + if (codec_ && codec_->protocol() == Protocol::Http3) { + stream.filter_manager_.streamInfo().setDeferredLoggingInfo(stream.deferredLoggingInfo()); + } else { + stream.filter_manager_.log(); + } stream.filter_manager_.destroyFilters(); diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 19090018e5bba..f1e865abc32bb 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -207,6 +207,19 @@ class ConnectionManagerImpl : Logger::Loggable, std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } + StreamInfo::DeferredLoggingInfo deferredLoggingInfo() { + StreamInfo::DeferredLoggingInfo info; + if (requestHeaders()) { + info.request_header_map = request_headers_; + } + if (responseHeaders()) { + info.response_header_map = response_headers_; + } + if (responseTrailers()) { + info.response_trailer_map = response_trailers_; + } + return info; + } // Tracing::TracingConfig Tracing::OperationName operationName() const override; diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index 74a60267222c9..2ccbd18c883e0 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1167,6 +1167,18 @@ TEST_P(QuicHttpIntegrationTest, MultipleNetworkFilters) { codec_client_->close(); } +TEST_P(QuicHttpIntegrationTest, DeferredLogging) { + useAccessLog("%ROUNDTRIP_DURATION%"); + initialize(); + codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); + sendRequestAndWaitForResponse(default_request_headers_, /*request_size=*/0, + default_response_headers_, + /*response_size=*/0, + /*upstream_index=*/0, TestUtility::DefaultTimeout); + codec_client_->close(); + EXPECT_GT(std::stoi(waitForAccessLog(access_log_name_)), 0); +} + class QuicInplaceLdsIntegrationTest : public QuicHttpIntegrationTest { public: void inplaceInitialize(bool add_default_filter_chain = false) { From e04f8ce808d03ebf2982c466c6abb222e304fb47 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 18:45:28 +0000 Subject: [PATCH 10/59] Move ResponseEncoder lower in the file To use RequestDecoder in a later commit. Signed-off-by: Paul Sohn --- envoy/http/codec.h | 68 +++++++++++++++++++++++----------------------- 1 file changed, 34 insertions(+), 34 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 37692c7a43b57..8cfa1b5fae095 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -134,40 +134,6 @@ class RequestEncoder : public virtual StreamEncoder { virtual void enableTcpTunneling() PURE; }; -/** - * Stream encoder used for sending a response (server to client). Virtual inheritance is required - * due to a parallel implementation split between the shared base class and the derived class. - */ -class ResponseEncoder : public virtual StreamEncoder { -public: - /** - * Encode supported 1xx headers. - * Currently 100-Continue, 102-Processing, and 103-Early-Data headers are supported. - * @param headers supplies the 1xx header map to encode. - */ - virtual void encode1xxHeaders(const ResponseHeaderMap& headers) PURE; - - /** - * Encode headers, optionally indicating end of stream. Response headers must - * have a valid :status set. - * @param headers supplies the header map to encode. - * @param end_stream supplies whether this is a header only response. - */ - virtual void encodeHeaders(const ResponseHeaderMap& headers, bool end_stream) PURE; - - /** - * Encode trailers. This implicitly ends the stream. - * @param trailers supplies the trailers to encode. - */ - virtual void encodeTrailers(const ResponseTrailerMap& trailers) PURE; - - /** - * Indicates whether invalid HTTP messaging should be handled with a stream error or a connection - * error. - */ - virtual bool streamErrorOnInvalidHttpMessage() const PURE; -}; - /** * Decodes an HTTP stream. These are callbacks fired into a sink. This interface contains methods * common to both the request and response path. @@ -240,6 +206,40 @@ class RequestDecoder : public virtual StreamDecoder { virtual std::list accessLogHandlers() PURE; }; +/** + * Stream encoder used for sending a response (server to client). Virtual inheritance is required + * due to a parallel implementation split between the shared base class and the derived class. + */ +class ResponseEncoder : public virtual StreamEncoder { +public: + /** + * Encode supported 1xx headers. + * Currently 100-Continue, 102-Processing, and 103-Early-Data headers are supported. + * @param headers supplies the 1xx header map to encode. + */ + virtual void encode1xxHeaders(const ResponseHeaderMap& headers) PURE; + + /** + * Encode headers, optionally indicating end of stream. Response headers must + * have a valid :status set. + * @param headers supplies the header map to encode. + * @param end_stream supplies whether this is a header only response. + */ + virtual void encodeHeaders(const ResponseHeaderMap& headers, bool end_stream) PURE; + + /** + * Encode trailers. This implicitly ends the stream. + * @param trailers supplies the trailers to encode. + */ + virtual void encodeTrailers(const ResponseTrailerMap& trailers) PURE; + + /** + * Indicates whether invalid HTTP messaging should be handled with a stream error or a connection + * error. + */ + virtual bool streamErrorOnInvalidHttpMessage() const PURE; +}; + /** * Stream decoder used for receiving a response (server to client). Virtual inheritance is required * due to a parallel implementation split between the shared base class and the derived class. From b63b4e010441f6751bc155abe1abe185d942e1de Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 19:42:10 +0000 Subject: [PATCH 11/59] Avoid deferring logging for reset cases Signed-off-by: Paul Sohn --- envoy/http/codec.h | 6 ++++++ source/common/http/conn_manager_impl.cc | 4 +++- source/common/http/filter_manager.h | 1 + source/common/http/http1/codec_impl.h | 2 ++ source/common/http/http2/codec_impl.cc | 2 +- source/common/http/http2/codec_impl.h | 3 +++ source/common/quic/envoy_quic_server_stream.h | 2 +- test/integration/quic_http_integration_test.cc | 12 ++++++++++++ test/mocks/http/stream_encoder.h | 1 + 9 files changed, 30 insertions(+), 3 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 8cfa1b5fae095..44f42eeef9157 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -238,6 +238,12 @@ class ResponseEncoder : public virtual StreamEncoder { * error. */ virtual bool streamErrorOnInvalidHttpMessage() const PURE; + + /** + * Set a new request decoder for this ResponseEncoder. + * @param decoder new request decoder. + */ + virtual void setRequestDecoder(RequestDecoder& decoder) PURE; }; /** diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index bfc803c5481bc..8f9790dea6b2d 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -278,7 +278,8 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { stream.completeRequest(); stream.filter_manager_.onStreamComplete(); - if (codec_ && codec_->protocol() == Protocol::Http3) { + if (codec_ && codec_->protocol() == Protocol::Http3 && + !stream.filter_manager_.saw_downstream_reset()) { stream.filter_manager_.streamInfo().setDeferredLoggingInfo(stream.deferredLoggingInfo()); } else { stream.filter_manager_.log(); @@ -1787,6 +1788,7 @@ void ConnectionManagerImpl::ActiveStream::recreateStream( connection_manager_.doEndStream(*this, /*check_for_deferred_close*/ false); RequestDecoder& new_stream = connection_manager_.newStream(*response_encoder, true); + response_encoder->setRequestDecoder(new_stream); // We don't need to copy over the old parent FilterState from the old StreamInfo if it did not // store any objects with a LifeSpan at or above DownstreamRequest. This is to avoid unnecessary // heap allocation. diff --git a/source/common/http/filter_manager.h b/source/common/http/filter_manager.h index 1e06173e5ba14..bb3d8084caa19 100644 --- a/source/common/http/filter_manager.h +++ b/source/common/http/filter_manager.h @@ -808,6 +808,7 @@ class FilterManager : public ScopeTrackedObject, void contextOnContinue(ScopeTrackedObjectStack& tracked_object_stack); void onDownstreamReset() { state_.saw_downstream_reset_ = true; } + bool saw_downstream_reset() { return state_.saw_downstream_reset_; } protected: struct State { diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index ec2cdc51826a3..ca1e36770eb41 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -155,6 +155,8 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { bool streamErrorOnInvalidHttpMessage() const override { return stream_error_on_invalid_http_message_; } + void setRequestDecoder(Http::RequestDecoder& /*decoder*/) override { + } // Http1::StreamEncoderImpl void resetStream(StreamResetReason reason) override; diff --git a/source/common/http/http2/codec_impl.cc b/source/common/http/http2/codec_impl.cc index 743c775de4044..915b5d9884588 100644 --- a/source/common/http/http2/codec_impl.cc +++ b/source/common/http/http2/codec_impl.cc @@ -2305,7 +2305,7 @@ Status ServerConnectionImpl::onBeginHeaders(const nghttp2_frame* frame) { if (connection_.aboveHighWatermark()) { stream->runHighWatermarkCallbacks(); } - stream->request_decoder_ = &callbacks_.newStream(*stream); + stream->setRequestDecoder(callbacks_.newStream(*stream)); stream->stream_id_ = frame->hd.stream_id; LinkedList::moveIntoList(std::move(stream), active_streams_); if (use_new_codec_wrapper_) { diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 3f62402d402c3..552f9418563f0 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -520,6 +520,9 @@ class ConnectionImpl : public virtual Connection, void encodeTrailers(const ResponseTrailerMap& trailers) override { encodeTrailersBase(trailers); } + void setRequestDecoder(Http::RequestDecoder& decoder) override { + request_decoder_ = &decoder; + } // ScopeTrackedObject void dumpState(std::ostream& os, int indent_level) const override; diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index 205aa36220404..a080c4fd0ede6 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -20,7 +20,7 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, envoy::config::core::v3::HttpProtocolOptions::HeadersWithUnderscoresAction headers_with_underscores_action); - void setRequestDecoder(Http::RequestDecoder& decoder) { + void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; stats_gatherer_->add_stream_info(request_decoder_->streamInfoSharedPtr()); stats_gatherer_->set_access_log_handlers(request_decoder_->accessLogHandlers()); diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index 2ccbd18c883e0..24884b877c540 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1179,6 +1179,18 @@ TEST_P(QuicHttpIntegrationTest, DeferredLogging) { EXPECT_GT(std::stoi(waitForAccessLog(access_log_name_)), 0); } +TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { + useAccessLog("%ROUNDTRIP_DURATION%"); + initialize(); + codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); + auto response = codec_client_->makeHeaderOnlyRequest(default_request_headers_); + waitForNextUpstreamRequest(0); + codec_client_->close(); + ASSERT_TRUE(response->waitForReset()); + EXPECT_FALSE(response->complete()); + EXPECT_EQ(waitForAccessLog(access_log_name_), "-"); +} + class QuicInplaceLdsIntegrationTest : public QuicHttpIntegrationTest { public: void inplaceInitialize(bool add_default_filter_chain = false) { diff --git a/test/mocks/http/stream_encoder.h b/test/mocks/http/stream_encoder.h index c15da88f170d2..55718fad09b68 100644 --- a/test/mocks/http/stream_encoder.h +++ b/test/mocks/http/stream_encoder.h @@ -48,6 +48,7 @@ class MockResponseEncoder : public ResponseEncoder { MOCK_METHOD(void, encode1xxHeaders, (const ResponseHeaderMap& headers)); MOCK_METHOD(void, encodeHeaders, (const ResponseHeaderMap& headers, bool end_stream)); MOCK_METHOD(void, encodeTrailers, (const ResponseTrailerMap& trailers)); + MOCK_METHOD(void, setRequestDecoder, (RequestDecoder& decoder)); // Http::StreamEncoder MOCK_METHOD(void, encodeData, (Buffer::Instance & data, bool end_stream)); From acb45babbe23efc1ef00eb26ca50a2888cd1944f Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 21:14:07 +0000 Subject: [PATCH 12/59] QuicStatsGatherer: only log once Avoids re-logging on a zero-byte ack. Signed-off-by: Paul Sohn --- source/common/quic/quic_stats_gatherer.cc | 6 ++++-- source/common/quic/quic_stats_gatherer.h | 1 + 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index ac57b408e3734..6071c232cfccd 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -1,20 +1,22 @@ #include "source/common/quic/quic_stats_gatherer.h" -#include "source/common/common/logger.h" #include +#include "source/common/common/logger.h" + namespace Envoy { namespace Quic { void QuicStatsGatherer::OnPacketAcked(int acked_bytes, quic::QuicTime::Delta /* delta_largest_observed */) { bytes_outstanding_ -= acked_bytes; - if (bytes_outstanding_ == 0 && fin_sent_) { + if (bytes_outstanding_ == 0 && fin_sent_ && !logging_done_) { DoDeferredLog(); } } void QuicStatsGatherer::DoDeferredLog() { + logging_done_ = true; for (const std::shared_ptr& stream_info : stream_info_) { if (!stream_info->deferredLoggingInfo().has_value()) { continue; diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index 2eeada934e1c9..f655e864b6375 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -41,6 +41,7 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { std::list> stream_info_{}; std::list access_log_handlers_{}; Envoy::TimeSource* time_source_ = nullptr; + bool logging_done_ = false; }; } // namespace Quic From 3ba284161b51f86cbae194d6616acc6b85f168a8 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 21:18:14 +0000 Subject: [PATCH 13/59] formatting fixes Signed-off-by: Paul Sohn --- source/common/http/http1/codec_impl.h | 3 +-- source/common/http/http2/codec_impl.h | 4 +--- test/mocks/http/stream_encoder.h | 2 +- 3 files changed, 3 insertions(+), 6 deletions(-) diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index ca1e36770eb41..65010d83ebd8c 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -155,8 +155,7 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { bool streamErrorOnInvalidHttpMessage() const override { return stream_error_on_invalid_http_message_; } - void setRequestDecoder(Http::RequestDecoder& /*decoder*/) override { - } + void setRequestDecoder(Http::RequestDecoder& /*decoder*/) override {} // Http1::StreamEncoderImpl void resetStream(StreamResetReason reason) override; diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 552f9418563f0..6b4e8eaae8caa 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -520,9 +520,7 @@ class ConnectionImpl : public virtual Connection, void encodeTrailers(const ResponseTrailerMap& trailers) override { encodeTrailersBase(trailers); } - void setRequestDecoder(Http::RequestDecoder& decoder) override { - request_decoder_ = &decoder; - } + void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; } // ScopeTrackedObject void dumpState(std::ostream& os, int indent_level) const override; diff --git a/test/mocks/http/stream_encoder.h b/test/mocks/http/stream_encoder.h index 55718fad09b68..efe3626af3ab7 100644 --- a/test/mocks/http/stream_encoder.h +++ b/test/mocks/http/stream_encoder.h @@ -48,7 +48,7 @@ class MockResponseEncoder : public ResponseEncoder { MOCK_METHOD(void, encode1xxHeaders, (const ResponseHeaderMap& headers)); MOCK_METHOD(void, encodeHeaders, (const ResponseHeaderMap& headers, bool end_stream)); MOCK_METHOD(void, encodeTrailers, (const ResponseTrailerMap& trailers)); - MOCK_METHOD(void, setRequestDecoder, (RequestDecoder& decoder)); + MOCK_METHOD(void, setRequestDecoder, (RequestDecoder & decoder)); // Http::StreamEncoder MOCK_METHOD(void, encodeData, (Buffer::Instance & data, bool end_stream)); From c28cebf9045e1b0e9bc04c34e5f93800382b3ab1 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 21:23:43 +0000 Subject: [PATCH 14/59] remove unnecessary include Signed-off-by: Paul Sohn --- source/common/quic/quic_stats_gatherer.cc | 2 -- 1 file changed, 2 deletions(-) diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 6071c232cfccd..806aa7d3c1f3d 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -2,8 +2,6 @@ #include -#include "source/common/common/logger.h" - namespace Envoy { namespace Quic { From 888818c64cf600950a68f1a62c2239bf9651d4dd Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 21:47:59 +0000 Subject: [PATCH 15/59] fix formatting Signed-off-by: Paul Sohn --- source/common/quic/envoy_quic_server_stream.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index a080c4fd0ede6..ddce47bae1d20 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -3,8 +3,8 @@ #include "source/common/quic/envoy_quic_stream.h" #include "source/common/quic/quic_stats_gatherer.h" -#include "quiche/quic/core/http/quic_spdy_server_stream_base.h" #include "quiche/common/platform/api/quiche_reference_counted.h" +#include "quiche/quic/core/http/quic_spdy_server_stream_base.h" namespace Envoy { namespace Quic { From 7564cf006fa9073012b7d8eba55cf17ea8b22e48 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 8 Nov 2022 22:03:37 +0000 Subject: [PATCH 16/59] add 'retransmitted' to dictionary Signed-off-by: Paul Sohn --- tools/spelling/spelling_dictionary.txt | 1 + 1 file changed, 1 insertion(+) diff --git a/tools/spelling/spelling_dictionary.txt b/tools/spelling/spelling_dictionary.txt index 2cd966aa131fb..d16302f853d67 100644 --- a/tools/spelling/spelling_dictionary.txt +++ b/tools/spelling/spelling_dictionary.txt @@ -1124,6 +1124,7 @@ responder restarter resync ret +retransmitted retransmitting retriable retriggers From d512366d526decf657d10ffc67be35c7f8c46e74 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 9 Nov 2022 14:56:32 +0000 Subject: [PATCH 17/59] Add missing methods to MockRequestDecoder Signed-off-by: Paul Sohn --- test/mocks/http/stream_decoder.h | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/mocks/http/stream_decoder.h b/test/mocks/http/stream_decoder.h index 072eca832ba17..d9101fc73271e 100644 --- a/test/mocks/http/stream_decoder.h +++ b/test/mocks/http/stream_decoder.h @@ -31,6 +31,8 @@ class MockRequestDecoder : public RequestDecoder { // Http::RequestDecoder MOCK_METHOD(void, decodeHeaders_, (RequestHeaderMapSharedPtr & headers, bool end_stream)); MOCK_METHOD(void, decodeTrailers_, (RequestTrailerMapPtr & trailers)); + MOCK_METHOD(std::shared_ptr, streamInfoSharedPtr, ()); + MOCK_METHOD(std::list, accessLogHandlers, ()); }; class MockResponseDecoder : public ResponseDecoder { From 31081805fd6c91169115a784702ed6d3395c2642 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 9 Nov 2022 18:01:37 +0000 Subject: [PATCH 18/59] Fix failing tests. No change required to setFromForRecreateStream. Signed-off-by: Paul Sohn --- .../quic/envoy_quic_server_session_test.cc | 40 ++++++++++++++++--- .../quic/envoy_quic_server_stream_test.cc | 13 +++--- .../stream_info/stream_info_impl_test.cc | 2 +- 3 files changed, 43 insertions(+), 12 deletions(-) diff --git a/test/common/quic/envoy_quic_server_session_test.cc b/test/common/quic/envoy_quic_server_session_test.cc index 0067ffe2a79e5..f6c52ade9d58c 100644 --- a/test/common/quic/envoy_quic_server_session_test.cc +++ b/test/common/quic/envoy_quic_server_session_test.cc @@ -291,6 +291,8 @@ TEST_F(EnvoyQuicServerSessionTest, NewStream) { Http::MockRequestDecoder request_decoder; EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(testing::ReturnRef(request_decoder)); + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStreamId stream_id = 4u; auto stream = reinterpret_cast(envoy_quic_session_.GetOrCreateStream(stream_id)); @@ -308,7 +310,7 @@ TEST_F(EnvoyQuicServerSessionTest, NewStream) { headers.OnHeaderBlockEnd(/*uncompressed_header_bytes=*/0, /*compressed_header_bytes=*/0); // Request headers should be propagated to decoder. EXPECT_CALL(request_decoder, decodeHeaders_(_, /*end_stream=*/true)) - .WillOnce(Invoke([&host](const Http::RequestHeaderMapPtr& decoded_headers, bool) { + .WillOnce(Invoke([&host](const Http::RequestHeaderMapSharedPtr& decoded_headers, bool) { EXPECT_EQ(host, decoded_headers->getHostValue()); EXPECT_EQ("/", decoded_headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Get, decoded_headers->getMethodValue()); @@ -352,6 +354,8 @@ TEST_F(EnvoyQuicServerSessionTest, OnResetFrameIetfQuic) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()).Times(3); + EXPECT_CALL(request_decoder, accessLogHandlers()).Times(3); auto stream1 = dynamic_cast(createNewStream(request_decoder, stream_callbacks)); // Receiving RESET_STREAM alone should only close read side. @@ -435,6 +439,8 @@ TEST_F(EnvoyQuicServerSessionTest, ConnectionCloseWithActiveStream) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); EXPECT_CALL(*quic_connection_, SendConnectionClosePacket(quic::QUIC_NO_ERROR, _, "Closed by application")); @@ -450,6 +456,8 @@ TEST_F(EnvoyQuicServerSessionTest, RemoteConnectionCloseWithActiveStream) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); EXPECT_CALL(network_connection_callbacks_, onEvent(Network::ConnectionEvent::RemoteClose)); EXPECT_CALL(stream_callbacks, onResetStream(Http::StreamResetReason::ConnectionFailure, _)); @@ -467,6 +475,8 @@ TEST_F(EnvoyQuicServerSessionTest, NoFlushWithDataToWrite) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); envoy_quic_session_.MarkConnectionLevelWriteBlocked(stream->id()); EXPECT_CALL(*quic_connection_, @@ -484,6 +494,8 @@ TEST_F(EnvoyQuicServerSessionTest, FlushCloseWithDataToWrite) { installReadFilter(); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); envoy_quic_session_.MarkConnectionLevelWriteBlocked(stream->id()); @@ -524,6 +536,8 @@ TEST_F(EnvoyQuicServerSessionTest, WriteUpdatesDelayCloseTimer) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); // Create a stream and write enough data to make it blocked. auto stream = dynamic_cast(createNewStream(request_decoder, stream_callbacks)); @@ -538,7 +552,7 @@ TEST_F(EnvoyQuicServerSessionTest, WriteUpdatesDelayCloseTimer) { request_headers.OnHeaderBlockEnd(/*uncompressed_header_bytes=*/0, /*compressed_header_bytes=*/0); // Request headers should be propagated to decoder. EXPECT_CALL(request_decoder, decodeHeaders_(_, /*end_stream=*/true)) - .WillOnce(Invoke([&host](const Http::RequestHeaderMapPtr& decoded_headers, bool) { + .WillOnce(Invoke([&host](const Http::RequestHeaderMapSharedPtr& decoded_headers, bool) { EXPECT_EQ(host, decoded_headers->getHostValue()); EXPECT_EQ("/", decoded_headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Get, decoded_headers->getMethodValue()); @@ -618,6 +632,8 @@ TEST_F(EnvoyQuicServerSessionTest, FlushCloseNoTimeout) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); // Create a stream and write enough data to make it blocked. auto stream = dynamic_cast(createNewStream(request_decoder, stream_callbacks)); @@ -632,7 +648,7 @@ TEST_F(EnvoyQuicServerSessionTest, FlushCloseNoTimeout) { request_headers.OnHeaderBlockEnd(/*uncompressed_header_bytes=*/0, /*compressed_header_bytes=*/0); // Request headers should be propagated to decoder. EXPECT_CALL(request_decoder, decodeHeaders_(_, /*end_stream=*/true)) - .WillOnce(Invoke([&host](const Http::RequestHeaderMapPtr& decoded_headers, bool) { + .WillOnce(Invoke([&host](const Http::RequestHeaderMapSharedPtr& decoded_headers, bool) { EXPECT_EQ(host, decoded_headers->getHostValue()); EXPECT_EQ("/", decoded_headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Get, decoded_headers->getMethodValue()); @@ -680,6 +696,8 @@ TEST_F(EnvoyQuicServerSessionTest, FlushCloseWithTimeout) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); envoy_quic_session_.MarkConnectionLevelWriteBlocked(stream->id()); @@ -711,6 +729,8 @@ TEST_F(EnvoyQuicServerSessionTest, FlushAndWaitForCloseWithTimeout) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); envoy_quic_session_.MarkConnectionLevelWriteBlocked(stream->id()); @@ -744,6 +764,8 @@ TEST_F(EnvoyQuicServerSessionTest, FlusWriteTransitToFlushWriteWithDelay) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); envoy_quic_session_.MarkConnectionLevelWriteBlocked(stream->id()); @@ -864,6 +886,8 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { installReadFilter(); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; + EXPECT_CALL(request_decoder, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder, accessLogHandlers()); EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(Invoke([&request_decoder, &stream_callbacks](Http::ResponseEncoder& encoder, bool) -> Http::RequestDecoder& { @@ -884,7 +908,7 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { request_headers.OnHeaderBlockEnd(/*uncompressed_header_bytes=*/0, /*compressed_header_bytes=*/0); // Request headers should be propagated to decoder. EXPECT_CALL(request_decoder, decodeHeaders_(_, /*end_stream=*/true)) - .WillOnce(Invoke([&host](const Http::RequestHeaderMapPtr& decoded_headers, bool) { + .WillOnce(Invoke([&host](const Http::RequestHeaderMapSharedPtr& decoded_headers, bool) { EXPECT_EQ(host, decoded_headers->getHostValue()); EXPECT_EQ("/", decoded_headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Get, decoded_headers->getMethodValue()); @@ -907,6 +931,8 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { // send buffer watermark. Http::MockRequestDecoder request_decoder2; Http::MockStreamCallbacks stream_callbacks2; + EXPECT_CALL(request_decoder2, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder2, accessLogHandlers()); EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(Invoke([&request_decoder2, &stream_callbacks2](Http::ResponseEncoder& encoder, bool) -> Http::RequestDecoder& { @@ -916,7 +942,7 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { auto stream2 = dynamic_cast(envoy_quic_session_.GetOrCreateStream(stream_id + 4)); EXPECT_CALL(request_decoder2, decodeHeaders_(_, /*end_stream=*/true)) - .WillOnce(Invoke([&host](const Http::RequestHeaderMapPtr& decoded_headers, bool) { + .WillOnce(Invoke([&host](const Http::RequestHeaderMapSharedPtr& decoded_headers, bool) { EXPECT_EQ(host, decoded_headers->getHostValue()); EXPECT_EQ("/", decoded_headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Get, decoded_headers->getMethodValue()); @@ -937,6 +963,8 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { // high watermark reached upon creation. Http::MockRequestDecoder request_decoder3; Http::MockStreamCallbacks stream_callbacks3; + EXPECT_CALL(request_decoder3, streamInfoSharedPtr()); + EXPECT_CALL(request_decoder3, accessLogHandlers()); EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(Invoke([&request_decoder3, &stream_callbacks3](Http::ResponseEncoder& encoder, bool) -> Http::RequestDecoder& { @@ -947,7 +975,7 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { auto stream3 = dynamic_cast(envoy_quic_session_.GetOrCreateStream(stream_id + 8)); EXPECT_CALL(request_decoder3, decodeHeaders_(_, /*end_stream=*/true)) - .WillOnce(Invoke([&host](const Http::RequestHeaderMapPtr& decoded_headers, bool) { + .WillOnce(Invoke([&host](const Http::RequestHeaderMapSharedPtr& decoded_headers, bool) { EXPECT_EQ(host, decoded_headers->getHostValue()); EXPECT_EQ("/", decoded_headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Get, decoded_headers->getMethodValue()); diff --git a/test/common/quic/envoy_quic_server_stream_test.cc b/test/common/quic/envoy_quic_server_stream_test.cc index 64f2473ab5d88..460c84757030d 100644 --- a/test/common/quic/envoy_quic_server_stream_test.cc +++ b/test/common/quic/envoy_quic_server_stream_test.cc @@ -52,6 +52,8 @@ class EnvoyQuicServerStreamTest : public testing::Test { envoy::config::core::v3::HttpProtocolOptions::ALLOW)), response_headers_{{":status", "200"}, {"response-key", "response-value"}}, response_trailers_{{"trailer-key", "trailer-value"}} { + EXPECT_CALL(stream_decoder_, streamInfoSharedPtr()); + EXPECT_CALL(stream_decoder_, accessLogHandlers()); quic_stream_->setRequestDecoder(stream_decoder_); quic_stream_->addCallbacks(stream_callbacks_); quic_stream_->getStream().setFlushTimeout(std::chrono::milliseconds(30000)); @@ -102,7 +104,7 @@ class EnvoyQuicServerStreamTest : public testing::Test { size_t receiveRequest(const std::string& payload, bool fin, size_t decoder_buffer_high_watermark) { EXPECT_CALL(stream_decoder_, decodeHeaders_(_, /*end_stream=*/false)) - .WillOnce(Invoke([this](const Http::RequestHeaderMapPtr& headers, bool) { + .WillOnce(Invoke([this](const Http::RequestHeaderMapSharedPtr& headers, bool) { EXPECT_EQ(host_, headers->getHostValue()); EXPECT_EQ("/", headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Post, headers->getMethodValue()); @@ -126,7 +128,7 @@ class EnvoyQuicServerStreamTest : public testing::Test { size_t receiveRequestHeaders(bool end_stream) { EXPECT_CALL(stream_decoder_, decodeHeaders_(_, end_stream)) - .WillOnce(Invoke([this](const Http::RequestHeaderMapPtr& headers, bool) { + .WillOnce(Invoke([this](const Http::RequestHeaderMapSharedPtr& headers, bool) { EXPECT_EQ(host_, headers->getHostValue()); EXPECT_EQ("/", headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Post, headers->getMethodValue()); @@ -193,7 +195,7 @@ class EnvoyQuicServerStreamTest : public testing::Test { TEST_F(EnvoyQuicServerStreamTest, GetRequestAndResponse) { EXPECT_CALL(stream_decoder_, decodeHeaders_(_, /*end_stream=*/false)) - .WillOnce(Invoke([this](const Http::RequestHeaderMapPtr& headers, bool) { + .WillOnce(Invoke([this](const Http::RequestHeaderMapSharedPtr& headers, bool) { EXPECT_EQ(host_, headers->getHostValue()); EXPECT_EQ("/", headers->getPathValue()); EXPECT_EQ(Http::Headers::get().MethodValues.Get, headers->getMethodValue()); @@ -454,8 +456,9 @@ TEST_F(EnvoyQuicServerStreamTest, ReadDisableAndReEnableImmediately) { TEST_F(EnvoyQuicServerStreamTest, ReadDisableUponHeaders) { std::string payload(1024, 'a'); EXPECT_CALL(stream_decoder_, decodeHeaders_(_, /*end_stream=*/false)) - .WillOnce(Invoke( - [this](const Http::RequestHeaderMapPtr&, bool) { quic_stream_->readDisable(true); })); + .WillOnce(Invoke([this](const Http::RequestHeaderMapSharedPtr&, bool) { + quic_stream_->readDisable(true); + })); EXPECT_CALL(stream_decoder_, decodeData(_, _)); std::string data = absl::StrCat(spdyHeaderToHttp3StreamPayload(spdy_request_headers_), bodyToHttp3StreamPayload(payload)); diff --git a/test/common/stream_info/stream_info_impl_test.cc b/test/common/stream_info/stream_info_impl_test.cc index 7cb4caa0eb683..34230d27f14a5 100644 --- a/test/common/stream_info/stream_info_impl_test.cc +++ b/test/common/stream_info/stream_info_impl_test.cc @@ -236,7 +236,7 @@ TEST_F(StreamInfoImplTest, SetFrom) { #ifdef __clang__ #if defined(__linux__) #if defined(__has_feature) && !(__has_feature(thread_sanitizer)) - ASSERT_TRUE(sizeof(s1) == 784 || sizeof(s1) == 800 || sizeof(s1) == 808 || sizeof(s1) == 824) + ASSERT_TRUE(sizeof(s1) == 856 || sizeof(s1) == 872 || sizeof(s1) == 896) << "If adding fields to StreamInfoImpl, please check to see if you " "need to add them to setFromForRecreateStream! Current size " << sizeof(s1); From 33275d01df92fe5665eeb942eaf6c135f19c9e55 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Sun, 13 Nov 2022 02:21:47 +0000 Subject: [PATCH 19/59] fix codec tests Signed-off-by: Paul Sohn --- source/common/http/http2/codec_impl.cc | 6 ++-- source/common/http/http2/codec_impl.h | 6 ++-- test/common/http/http1/codec_impl_test.cc | 36 ++++++++++++----------- test/common/http/http2/codec_impl_test.cc | 2 +- 4 files changed, 26 insertions(+), 24 deletions(-) diff --git a/source/common/http/http2/codec_impl.cc b/source/common/http/http2/codec_impl.cc index 915b5d9884588..c7243f0aa36d4 100644 --- a/source/common/http/http2/codec_impl.cc +++ b/source/common/http/http2/codec_impl.cc @@ -609,7 +609,7 @@ void ConnectionImpl::ClientStreamImpl::decodeTrailers() { } void ConnectionImpl::ServerStreamImpl::decodeHeaders() { - auto& headers = absl::get(headers_or_trailers_); + auto& headers = absl::get(headers_or_trailers_); if (Http::Utility::isH2UpgradeRequest(*headers)) { Http::Utility::transformUpgradeRequestFromH2toH1(*headers); } @@ -2140,8 +2140,8 @@ void ConnectionImpl::ServerStreamImpl::dumpState(std::ostream& os, int indent_le StreamImpl::dumpState(os, indent_level); // Dump header map - if (absl::holds_alternative(headers_or_trailers_)) { - DUMP_DETAILS(absl::get(headers_or_trailers_)); + if (absl::holds_alternative(headers_or_trailers_)) { + DUMP_DETAILS(absl::get(headers_or_trailers_)); } else { DUMP_DETAILS(absl::get(headers_or_trailers_)); } diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 6b4e8eaae8caa..4daf02898e3ae 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -500,8 +500,8 @@ class ConnectionImpl : public virtual Connection, void decodeHeaders() override; void decodeTrailers() override; HeaderMap& headers() override { - if (absl::holds_alternative(headers_or_trailers_)) { - return *absl::get(headers_or_trailers_); + if (absl::holds_alternative(headers_or_trailers_)) { + return *absl::get(headers_or_trailers_); } else { return *absl::get(headers_or_trailers_); } @@ -526,7 +526,7 @@ class ConnectionImpl : public virtual Connection, void dumpState(std::ostream& os, int indent_level) const override; RequestDecoder* request_decoder_{}; - absl::variant headers_or_trailers_; + absl::variant headers_or_trailers_; bool streamErrorOnInvalidHttpMessage() const override { return parent_.stream_error_on_invalid_http_messaging_; diff --git a/test/common/http/http1/codec_impl_test.cc b/test/common/http/http1/codec_impl_test.cc index 657dcc53c9244..c92042b4a4b73 100644 --- a/test/common/http/http1/codec_impl_test.cc +++ b/test/common/http/http1/codec_impl_test.cc @@ -383,11 +383,12 @@ void Http1ServerConnectionImplTest::testServerAllowChunkedContentLength(uint32_t #ifdef ENVOY_ENABLE_UHV // Header validation is done by the HCM when header map is fully parsed. EXPECT_CALL(decoder, decodeHeaders_(_, _)) - .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapPtr& headers, bool) -> void { - auto result = header_validator_->validateRequestHeaderMap(*headers); - EXPECT_THAT(headers, HeaderMapEqualIgnoreOrder(&expected_headers)); - ASSERT_TRUE(result.ok()); - })); + .WillOnce( + Invoke([this, &expected_headers](RequestHeaderMapSharedPtr& headers, bool) -> void { + auto result = header_validator_->validateRequestHeaderMap(*headers); + EXPECT_THAT(headers, HeaderMapEqualIgnoreOrder(&expected_headers)); + ASSERT_TRUE(result.ok()); + })); #else EXPECT_CALL(decoder, decodeHeaders_(HeaderMapEqual(&expected_headers), false)); #endif @@ -400,16 +401,17 @@ void Http1ServerConnectionImplTest::testServerAllowChunkedContentLength(uint32_t // sendLocalReply and closes network connection (based on the // stream_error_on_invalid_http_message flag, which in this test is assumed to equal false). EXPECT_CALL(decoder, decodeHeaders_(_, _)) - .WillOnce(Invoke([this, &response_encoder](RequestHeaderMapPtr& headers, bool) -> void { - auto result = header_validator_->validateRequestHeaderMap(*headers); - ASSERT_FALSE(result.ok()); - response_encoder->encodeHeaders(TestResponseHeaderMapImpl{{":status", "400"}, - {"connection", "close"}, - {"content-length", "0"}}, - true); - response_encoder->getStream().resetStream(StreamResetReason::LocalReset); - connection_.state_ = Network::Connection::State::Closing; - })); + .WillOnce( + Invoke([this, &response_encoder](RequestHeaderMapSharedPtr& headers, bool) -> void { + auto result = header_validator_->validateRequestHeaderMap(*headers); + ASSERT_FALSE(result.ok()); + response_encoder->encodeHeaders(TestResponseHeaderMapImpl{{":status", "400"}, + {"connection", "close"}, + {"content-length", "0"}}, + true); + response_encoder->getStream().resetStream(StreamResetReason::LocalReset); + connection_.state_ = Network::Connection::State::Closing; + })); ON_CALL(connection_, write(_, _)).WillByDefault(AddBufferToString(&response)); #else EXPECT_CALL(decoder, decodeHeaders_(_, _)).Times(0); @@ -550,7 +552,7 @@ TEST_P(Http1ServerConnectionImplTest, ContentLengthAllBitsSet) { TestRequestHeaderMapImpl expected_headers{ {"content-length", "3"}, {":path", "/"}, {":method", "POST"}}; EXPECT_CALL(decoder, decodeHeaders_(HeaderMapEqual(&expected_headers), false)) - .WillOnce(Invoke([&](Http::RequestHeaderMapPtr&, bool) -> void { + .WillOnce(Invoke([&](Http::RequestHeaderMapSharedPtr&, bool) -> void { connection_.state_ = Network::Connection::State::Closing; })); EXPECT_CALL(decoder, decodeData(_, _)).Times(0); @@ -1466,7 +1468,7 @@ TEST_P(Http1ServerConnectionImplTest, CloseDuringHeadersComplete) { TestRequestHeaderMapImpl expected_headers{ {"content-length", "5"}, {":path", "/"}, {":method", "POST"}}; EXPECT_CALL(decoder, decodeHeaders_(HeaderMapEqual(&expected_headers), false)) - .WillOnce(Invoke([&](Http::RequestHeaderMapPtr&, bool) -> void { + .WillOnce(Invoke([&](Http::RequestHeaderMapSharedPtr&, bool) -> void { connection_.state_ = Network::Connection::State::Closing; })); EXPECT_CALL(decoder, decodeData(_, _)).Times(0); diff --git a/test/common/http/http2/codec_impl_test.cc b/test/common/http/http2/codec_impl_test.cc index 11963b0949db6..894622b5b4ec7 100644 --- a/test/common/http/http2/codec_impl_test.cc +++ b/test/common/http/http2/codec_impl_test.cc @@ -1442,7 +1442,7 @@ TEST_P(Http2CodecImplTest, ShouldDumpActiveStreamsWithoutAllocatingMemory) { EXPECT_THAT(ostream.contents(), HasSubstr("local_end_stream_: 1")); EXPECT_THAT(ostream.contents(), HasSubstr("pending_trailers_to_encode_: null\n" - " absl::get(headers_or_trailers_): \n" + " absl::get(headers_or_trailers_): \n" " ':scheme', 'http'\n" " ':method', 'GET'\n" " ':authority', 'host'\n" From a605ccfffd6257c7233e887d1e28837b293539a3 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Sun, 13 Nov 2022 22:38:23 +0000 Subject: [PATCH 20/59] Fix tests that wait for access logs on QUIC When waiting for access logs, flush pending client acks by running dispatcher every 25ms (default ack timer). Signed-off-by: Paul Sohn --- test/integration/base_integration_test.cc | 8 +++++++- test/integration/base_integration_test.h | 4 +++- test/integration/http_integration.h | 9 +++++++++ 3 files changed, 19 insertions(+), 2 deletions(-) diff --git a/test/integration/base_integration_test.cc b/test/integration/base_integration_test.cc index 6668a7e82b9e0..abdbc214a47c8 100644 --- a/test/integration/base_integration_test.cc +++ b/test/integration/base_integration_test.cc @@ -469,7 +469,9 @@ void BaseIntegrationTest::useListenerAccessLog(absl::string_view format) { } std::string BaseIntegrationTest::waitForAccessLog(const std::string& filename, uint32_t entry, - bool allow_excess_entries) { + bool allow_excess_entries, + Network::ClientConnection* client_connection) { + // Wait a max of 1s for logs to flush to disk. std::string contents; for (int i = 0; i < 1000; ++i) { @@ -484,6 +486,10 @@ std::string BaseIntegrationTest::waitForAccessLog(const std::string& filename, u << contents; return entries[entry]; } + if (i % 25 == 0 && client_connection != nullptr) { + // Wait 25 ms for default ack timer, then run dispatcher to send pending acks. + client_connection->dispatcher().run(Envoy::Event::Dispatcher::RunType::NonBlock); + } absl::SleepFor(absl::Milliseconds(1)); } RELEASE_ASSERT(0, absl::StrCat("Timed out waiting for access log. Found: '", contents, "'")); diff --git a/test/integration/base_integration_test.h b/test/integration/base_integration_test.h index d2b896564692f..0872c4cac3c45 100644 --- a/test/integration/base_integration_test.h +++ b/test/integration/base_integration_test.h @@ -145,8 +145,10 @@ class BaseIntegrationTest : protected Logger::Loggable { void useListenerAccessLog(absl::string_view format = ""); // Returns all log entries after the nth access log entry, defaulting to log entry 0. // By default will trigger an expect failure if more than one entry is returned. + // If client_connection is provided, flush pending acks to enable deferred logging. std::string waitForAccessLog(const std::string& filename, uint32_t entry = 0, - bool allow_excess_entries = false); + bool allow_excess_entries = false, + Network::ClientConnection* client_connection = nullptr); std::string listener_access_log_name_; diff --git a/test/integration/http_integration.h b/test/integration/http_integration.h index 6cf568d197313..4ebaba83038b4 100644 --- a/test/integration/http_integration.h +++ b/test/integration/http_integration.h @@ -143,6 +143,15 @@ class HttpIntegrationTest : public BaseIntegrationTest { protected: void useAccessLog(absl::string_view format = "", std::vector formatters = {}); + std::string waitForAccessLog(const std::string& filename, uint32_t entry = 0, + bool allow_excess_entries = false, + Network::ClientConnection* client_connection = nullptr) { + if (client_connection == nullptr && codec_client_) { + client_connection = codec_client_->connection(); + } + return BaseIntegrationTest::waitForAccessLog(filename, entry, allow_excess_entries, + client_connection); + }; IntegrationCodecClientPtr makeHttpConnection(uint32_t port); // Makes a http connection object without checking its connected state. From 423b98437d089d95584650965c623aecc8d6543a Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 14 Nov 2022 22:30:53 +0000 Subject: [PATCH 21/59] fix clang-tidy errors Signed-off-by: Paul Sohn --- envoy/stream_info/stream_info.h | 2 +- source/common/http/conn_manager_impl.cc | 2 +- source/common/http/filter_manager.h | 2 +- source/common/quic/envoy_quic_server_stream.cc | 6 +++--- source/common/quic/envoy_quic_server_stream.h | 6 +++--- source/common/quic/quic_stats_gatherer.cc | 4 ++-- source/common/quic/quic_stats_gatherer.h | 14 +++++--------- source/common/stream_info/stream_info_impl.h | 4 ++-- 8 files changed, 18 insertions(+), 22 deletions(-) diff --git a/envoy/stream_info/stream_info.h b/envoy/stream_info/stream_info.h index 59639c5767433..2148a942620ca 100644 --- a/envoy/stream_info/stream_info.h +++ b/envoy/stream_info/stream_info.h @@ -777,7 +777,7 @@ class StreamInfo { /** * @param deferredLoggingInfo request/response info for deferred logging. */ - virtual void setDeferredLoggingInfo(const DeferredLoggingInfo deferredLoggingInfo) PURE; + virtual void setDeferredLoggingInfo(const DeferredLoggingInfo deferred_logging_info) PURE; /** * @return request/response info for deferred logging. diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index 8f9790dea6b2d..df5ed6256d80b 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -279,7 +279,7 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { stream.completeRequest(); stream.filter_manager_.onStreamComplete(); if (codec_ && codec_->protocol() == Protocol::Http3 && - !stream.filter_manager_.saw_downstream_reset()) { + !stream.filter_manager_.sawDownstreamReset()) { stream.filter_manager_.streamInfo().setDeferredLoggingInfo(stream.deferredLoggingInfo()); } else { stream.filter_manager_.log(); diff --git a/source/common/http/filter_manager.h b/source/common/http/filter_manager.h index bb3d8084caa19..c2b9cb5f42ac9 100644 --- a/source/common/http/filter_manager.h +++ b/source/common/http/filter_manager.h @@ -808,7 +808,7 @@ class FilterManager : public ScopeTrackedObject, void contextOnContinue(ScopeTrackedObjectStack& tracked_object_stack); void onDownstreamReset() { state_.saw_downstream_reset_ = true; } - bool saw_downstream_reset() { return state_.saw_downstream_reset_; } + bool sawDownstreamReset() { return state_.saw_downstream_reset_; } protected: struct State { diff --git a/source/common/quic/envoy_quic_server_stream.cc b/source/common/quic/envoy_quic_server_stream.cc index a8bf8d4ea2da3..c1f6a2c3bc910 100644 --- a/source/common/quic/envoy_quic_server_stream.cc +++ b/source/common/quic/envoy_quic_server_stream.cc @@ -59,7 +59,7 @@ void EnvoyQuicServerStream::encodeHeaders(const Http::ResponseHeaderMap& headers { IncrementalBytesSentTracker tracker(*this, *mutableBytesMeter(), true); size_t bytes_sent = WriteHeaders(envoyHeadersToHttp2HeaderBlock(headers), end_stream, nullptr); - stats_gatherer_->AddBytesSent(bytes_sent, end_stream); + stats_gatherer_->addBytesSent(bytes_sent, end_stream); ENVOY_BUG(bytes_sent != 0, "Failed to encode headers."); } @@ -98,7 +98,7 @@ void EnvoyQuicServerStream::encodeData(Buffer::Instance& data, bool end_stream) { IncrementalBytesSentTracker tracker(*this, *mutableBytesMeter(), false); result = WriteBodySlices(span, end_stream); - stats_gatherer_->AddBytesSent(result.bytes_consumed, end_stream); + stats_gatherer_->addBytesSent(result.bytes_consumed, end_stream); } // QUIC stream must take all. if (result.bytes_consumed == 0 && has_data) { @@ -128,7 +128,7 @@ void EnvoyQuicServerStream::encodeTrailers(const Http::ResponseTrailerMap& trail IncrementalBytesSentTracker tracker(*this, *mutableBytesMeter(), true); size_t bytes_sent = WriteTrailers(envoyHeadersToHttp2HeaderBlock(trailers), nullptr); ENVOY_BUG(bytes_sent != 0, "Failed to encode trailers."); - stats_gatherer_->AddBytesSent(bytes_sent, true); + stats_gatherer_->addBytesSent(bytes_sent, true); } onLocalEndStream(); } diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index ddce47bae1d20..4a0e6b5268705 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -22,9 +22,9 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; - stats_gatherer_->add_stream_info(request_decoder_->streamInfoSharedPtr()); - stats_gatherer_->set_access_log_handlers(request_decoder_->accessLogHandlers()); - stats_gatherer_->set_time_source(&connection()->dispatcher().timeSource()); + stats_gatherer_->addStreamInfo(request_decoder_->streamInfoSharedPtr()); + stats_gatherer_->setAccessLogHandlers(request_decoder_->accessLogHandlers()); + stats_gatherer_->setTimeSource(&connection()->dispatcher().timeSource()); } // Http::StreamEncoder diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 806aa7d3c1f3d..286692a0f8446 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -9,11 +9,11 @@ void QuicStatsGatherer::OnPacketAcked(int acked_bytes, quic::QuicTime::Delta /* delta_largest_observed */) { bytes_outstanding_ -= acked_bytes; if (bytes_outstanding_ == 0 && fin_sent_ && !logging_done_) { - DoDeferredLog(); + doDeferredLog(); } } -void QuicStatsGatherer::DoDeferredLog() { +void QuicStatsGatherer::doDeferredLog() { logging_done_ = true; for (const std::shared_ptr& stream_info : stream_info_) { if (!stream_info->deferredLoggingInfo().has_value()) { diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index f655e864b6375..700dde1bf46ad 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -9,10 +9,6 @@ #include "quiche/quic/core/quic_ack_listener_interface.h" -using Envoy::Http::RequestHeaderMap; -using Envoy::Http::ResponseHeaderMap; -using Envoy::Http::ResponseTrailerMap; - namespace Envoy { namespace Quic { @@ -20,20 +16,20 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { public: void OnPacketAcked(int acked_bytes, quic::QuicTime::Delta delta_largest_observed) override; void OnPacketRetransmitted(int /* retransmitted_bytes */) override {} - void AddBytesSent(uint64_t bytes_sent, bool end_stream) { + void addBytesSent(uint64_t bytes_sent, bool end_stream) { bytes_outstanding_ += bytes_sent; fin_sent_ = end_stream; } - void DoDeferredLog(); - void add_stream_info(std::shared_ptr stream_info) { + void doDeferredLog(); + void addStreamInfo(std::shared_ptr stream_info) { if (stream_info != nullptr) { stream_info_.push_back(stream_info); } } - void set_access_log_handlers(std::list handlers) { + void setAccessLogHandlers(std::list handlers) { access_log_handlers_ = handlers; } - void set_time_source(Envoy::TimeSource* time_source) { time_source_ = time_source; } + void setTimeSource(Envoy::TimeSource* time_source) { time_source_ = time_source; } private: uint64_t bytes_outstanding_ = 0; diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index 9a6a31e746738..c532d4384cb3d 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -231,9 +231,9 @@ struct StreamInfoImpl : public StreamInfo { return virtual_cluster_name_; } - void setDeferredLoggingInfo(DeferredLoggingInfo deferredLoggingInfo) override { + void setDeferredLoggingInfo(DeferredLoggingInfo deferred_logging_info) override { deferred_logging_info_ = - absl::make_optional(std::move(deferredLoggingInfo)); + absl::make_optional(std::move(deferred_logging_info)); } const absl::optional& deferredLoggingInfo() const override { return deferred_logging_info_; From 46aa5445f33b93dba0bd4ae02cec3a07d85e8150 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 16 Nov 2022 18:19:50 +0000 Subject: [PATCH 22/59] Add runtime feature for deferred logging in QUIC Signed-off-by: Paul Sohn --- source/common/http/conn_manager_impl.cc | 4 +- source/common/runtime/runtime_features.cc | 1 + .../integration/quic_http_integration_test.cc | 41 +++++++++++++++++-- 3 files changed, 41 insertions(+), 5 deletions(-) diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index df5ed6256d80b..d9498054ac784 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -279,7 +279,9 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { stream.completeRequest(); stream.filter_manager_.onStreamComplete(); if (codec_ && codec_->protocol() == Protocol::Http3 && - !stream.filter_manager_.sawDownstreamReset()) { + !stream.filter_manager_.sawDownstreamReset() && + Runtime::runtimeFeatureEnabled( + "envoy.reloadable_features.quic_defer_logging_to_ack_listener")) { stream.filter_manager_.streamInfo().setDeferredLoggingInfo(stream.deferredLoggingInfo()); } else { stream.filter_manager_.log(); diff --git a/source/common/runtime/runtime_features.cc b/source/common/runtime/runtime_features.cc index 9ef65367e3e45..2325da96cd314 100644 --- a/source/common/runtime/runtime_features.cc +++ b/source/common/runtime/runtime_features.cc @@ -62,6 +62,7 @@ RUNTIME_GUARD(envoy_reloadable_features_no_extension_lookup_by_name); RUNTIME_GUARD(envoy_reloadable_features_original_dst_rely_on_idle_timeout); RUNTIME_GUARD(envoy_reloadable_features_override_request_timeout_by_gateway_timeout); RUNTIME_GUARD(envoy_reloadable_features_postpone_h3_client_connect_to_next_loop); +RUNTIME_GUARD(envoy_reloadable_features_quic_defer_logging_to_ack_listener); RUNTIME_GUARD(envoy_reloadable_features_quic_defer_send_in_response_to_packet); RUNTIME_GUARD(envoy_reloadable_features_skip_delay_close); RUNTIME_GUARD(envoy_reloadable_features_skip_dns_lookup_for_proxied_requests); diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index 24884b877c540..d2af2384e6e79 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1168,7 +1168,7 @@ TEST_P(QuicHttpIntegrationTest, MultipleNetworkFilters) { } TEST_P(QuicHttpIntegrationTest, DeferredLogging) { - useAccessLog("%ROUNDTRIP_DURATION%"); + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); sendRequestAndWaitForResponse(default_request_headers_, /*request_size=*/0, @@ -1176,11 +1176,38 @@ TEST_P(QuicHttpIntegrationTest, DeferredLogging) { /*response_size=*/0, /*upstream_index=*/0, TestUtility::DefaultTimeout); codec_client_->close(); - EXPECT_GT(std::stoi(waitForAccessLog(access_log_name_)), 0); + + std::string log = waitForAccessLog(access_log_name_); + std::string delimiter = ","; + std::string protocol = log.substr(0, log.find(delimiter)); + std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); + EXPECT_EQ(protocol, "HTTP/3"); + EXPECT_GT(std::stoi(roundtrip_duration), 0); +} + +TEST_P(QuicHttpIntegrationTest, DeferredLoggingDisabled) { + config_helper_.addRuntimeOverride("envoy.reloadable_features.quic_defer_logging_to_ack_listener", + "false"); + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); + initialize(); + codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); + sendRequestAndWaitForResponse(default_request_headers_, /*request_size=*/0, + default_response_headers_, + /*response_size=*/0, + /*upstream_index=*/0, TestUtility::DefaultTimeout); + codec_client_->close(); + + // Do not flush client acks. + std::string log = waitForAccessLog(access_log_name_, 0, false, nullptr); + std::string delimiter = ","; + std::string protocol = log.substr(0, log.find(delimiter)); + std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); + EXPECT_EQ(protocol, "HTTP/3"); + EXPECT_EQ(roundtrip_duration, "-"); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { - useAccessLog("%ROUNDTRIP_DURATION%"); + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); auto response = codec_client_->makeHeaderOnlyRequest(default_request_headers_); @@ -1188,7 +1215,13 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { codec_client_->close(); ASSERT_TRUE(response->waitForReset()); EXPECT_FALSE(response->complete()); - EXPECT_EQ(waitForAccessLog(access_log_name_), "-"); + + std::string log = waitForAccessLog(access_log_name_); + std::string delimiter = ","; + std::string protocol = log.substr(0, log.find(delimiter)); + std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); + EXPECT_EQ(protocol, "HTTP/3"); + EXPECT_EQ(roundtrip_duration, "-"); } class QuicInplaceLdsIntegrationTest : public QuicHttpIntegrationTest { From c7bc1ac8b974a5fa4a18d9ae3ae2a332d1503d27 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 16 Nov 2022 18:56:43 +0000 Subject: [PATCH 23/59] Add test case for EnvoyQuicServerStream::resetStream Signed-off-by: Paul Sohn --- .../integration/quic_http_integration_test.cc | 23 +++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index d2af2384e6e79..ffea0316b9bc6 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1224,6 +1224,29 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { EXPECT_EQ(roundtrip_duration, "-"); } +TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithQuicReset) { + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); + initialize(); + codec_client_ = makeHttpConnection(lookupPort("http")); + + // omit required authority header to invoke EnvoyQuicServerStream::resetStream + auto encoder_decoder = codec_client_->startRequest(Http::TestRequestHeaderMapImpl{ + {":method", "GET"}, {":path", "/dynamo/url"}, {":scheme", "http"}}); + request_encoder_ = &encoder_decoder.first; + auto response = std::move(encoder_decoder.second); + + ASSERT_TRUE(response->waitForEndStream()); + codec_client_->close(); + ASSERT_TRUE(response->complete()); + + std::string log = waitForAccessLog(access_log_name_); + std::string delimiter = ","; + std::string protocol = log.substr(0, log.find(delimiter)); + std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); + EXPECT_EQ(protocol, "HTTP/3"); + EXPECT_EQ(roundtrip_duration, "-"); +} + class QuicInplaceLdsIntegrationTest : public QuicHttpIntegrationTest { public: void inplaceInitialize(bool add_default_filter_chain = false) { From d03985ddf7f7199cb6a8cfe039fb2b5ccbe06010 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 16 Nov 2022 19:02:14 +0000 Subject: [PATCH 24/59] add access log documentation Signed-off-by: Paul Sohn --- .../observability/access_log/usage.rst | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/docs/root/configuration/observability/access_log/usage.rst b/docs/root/configuration/observability/access_log/usage.rst index 5d9907cfd7482..ed61c2fd95e37 100644 --- a/docs/root/configuration/observability/access_log/usage.rst +++ b/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 From 8424a37b57781baa821ec6fd862e9edb5128276d Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 16 Nov 2022 19:29:27 +0000 Subject: [PATCH 25/59] add changelog Signed-off-by: Paul Sohn --- changelogs/current.yaml | 3 +++ 1 file changed, 3 insertions(+) diff --git a/changelogs/current.yaml b/changelogs/current.yaml index 208b6f558bd90..7cfb516f2ba65 100644 --- a/changelogs/current.yaml +++ b/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. bug_fixes: # *Changes expected to improve the state of the world and are unlikely to have negative effects* From 21c64f6a45aba99ed13e68a2ebe29789a5f535d7 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 28 Nov 2022 15:41:50 +0000 Subject: [PATCH 26/59] Move ResponseEncoder back where it was and use forward declaration Signed-off-by: Paul Sohn --- envoy/http/codec.h | 81 +++++++++++++++++++++++----------------------- 1 file changed, 41 insertions(+), 40 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 44f42eeef9157..e7a9b4f575af4 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -46,6 +46,7 @@ const char MaxResponseHeadersCountOverrideKey[] = "envoy.reloadable_features.max_response_headers_count"; class Stream; +class RequestDecoder; /** * Error codes used to convey the reason for a GOAWAY. @@ -134,6 +135,46 @@ class RequestEncoder : public virtual StreamEncoder { virtual void enableTcpTunneling() PURE; }; +/** + * Stream encoder used for sending a response (server to client). Virtual inheritance is required + * due to a parallel implementation split between the shared base class and the derived class. + */ +class ResponseEncoder : public virtual StreamEncoder { +public: + /** + * Encode supported 1xx headers. + * Currently 100-Continue, 102-Processing, and 103-Early-Data headers are supported. + * @param headers supplies the 1xx header map to encode. + */ + virtual void encode1xxHeaders(const ResponseHeaderMap& headers) PURE; + + /** + * Encode headers, optionally indicating end of stream. Response headers must + * have a valid :status set. + * @param headers supplies the header map to encode. + * @param end_stream supplies whether this is a header only response. + */ + virtual void encodeHeaders(const ResponseHeaderMap& headers, bool end_stream) PURE; + + /** + * Encode trailers. This implicitly ends the stream. + * @param trailers supplies the trailers to encode. + */ + virtual void encodeTrailers(const ResponseTrailerMap& trailers) PURE; + + /** + * Indicates whether invalid HTTP messaging should be handled with a stream error or a connection + * error. + */ + virtual bool streamErrorOnInvalidHttpMessage() const PURE; + + /** + * Set a new request decoder for this ResponseEncoder. + * @param decoder new request decoder. + */ + virtual void setRequestDecoder(RequestDecoder& decoder) PURE; +}; + /** * Decodes an HTTP stream. These are callbacks fired into a sink. This interface contains methods * common to both the request and response path. @@ -206,46 +247,6 @@ class RequestDecoder : public virtual StreamDecoder { virtual std::list accessLogHandlers() PURE; }; -/** - * Stream encoder used for sending a response (server to client). Virtual inheritance is required - * due to a parallel implementation split between the shared base class and the derived class. - */ -class ResponseEncoder : public virtual StreamEncoder { -public: - /** - * Encode supported 1xx headers. - * Currently 100-Continue, 102-Processing, and 103-Early-Data headers are supported. - * @param headers supplies the 1xx header map to encode. - */ - virtual void encode1xxHeaders(const ResponseHeaderMap& headers) PURE; - - /** - * Encode headers, optionally indicating end of stream. Response headers must - * have a valid :status set. - * @param headers supplies the header map to encode. - * @param end_stream supplies whether this is a header only response. - */ - virtual void encodeHeaders(const ResponseHeaderMap& headers, bool end_stream) PURE; - - /** - * Encode trailers. This implicitly ends the stream. - * @param trailers supplies the trailers to encode. - */ - virtual void encodeTrailers(const ResponseTrailerMap& trailers) PURE; - - /** - * Indicates whether invalid HTTP messaging should be handled with a stream error or a connection - * error. - */ - virtual bool streamErrorOnInvalidHttpMessage() const PURE; - - /** - * Set a new request decoder for this ResponseEncoder. - * @param decoder new request decoder. - */ - virtual void setRequestDecoder(RequestDecoder& decoder) PURE; -}; - /** * Stream decoder used for receiving a response (server to client). Virtual inheritance is required * due to a parallel implementation split between the shared base class and the derived class. From 51f2123c2c9b0d547a50bb19b39dc5c18d0181f2 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 28 Nov 2022 15:46:26 +0000 Subject: [PATCH 27/59] add new runtime flag to release notes Signed-off-by: Paul Sohn --- changelogs/current.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelogs/current.yaml b/changelogs/current.yaml index 7cfb516f2ba65..de2e397fc0194 100644 --- a/changelogs/current.yaml +++ b/changelogs/current.yaml @@ -7,7 +7,7 @@ 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. + 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. bug_fixes: # *Changes expected to improve the state of the world and are unlikely to have negative effects* From b5771a597bfd0ff5cb8887ffffd7c3d1be3899d3 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 28 Nov 2022 16:36:49 +0000 Subject: [PATCH 28/59] Add comments Signed-off-by: Paul Sohn --- envoy/http/codec.h | 2 +- source/common/http/conn_manager_impl.cc | 5 +++++ source/common/quic/quic_stats_gatherer.h | 10 ++++++++++ source/common/stream_info/stream_info_impl.h | 2 ++ 4 files changed, 18 insertions(+), 1 deletion(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index e7a9b4f575af4..0d5fa2f4926b9 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -237,7 +237,7 @@ class RequestDecoder : public virtual StreamDecoder { virtual StreamInfo::StreamInfo& streamInfo() PURE; /** - * @return Shared pointer to the stream_info for this stream. + * @return shared pointer to the stream_info for this stream. */ virtual std::shared_ptr streamInfoSharedPtr() PURE; diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index d9498054ac784..e97a5021ba199 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -278,12 +278,17 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { stream.completeRequest(); stream.filter_manager_.onStreamComplete(); + + // For HTTP/3, skip access logging here and add deferred logging info + // to stream info for QuicStatsGatherer to use later. If there was a + // downstream reset, log here as usual. if (codec_ && codec_->protocol() == Protocol::Http3 && !stream.filter_manager_.sawDownstreamReset() && Runtime::runtimeFeatureEnabled( "envoy.reloadable_features.quic_defer_logging_to_ack_listener")) { stream.filter_manager_.streamInfo().setDeferredLoggingInfo(stream.deferredLoggingInfo()); } else { + // For HTTP/1 and HTTP/2, log here as usual. stream.filter_manager_.log(); } diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index 700dde1bf46ad..5eddf99ec1bd9 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -12,23 +12,33 @@ namespace Envoy { namespace Quic { +// Ack listener that stores access logging information and performs +// logging after the final ack. class QuicStatsGatherer : public quic::QuicAckListenerInterface { public: + // QuicAckListenerInterface void OnPacketAcked(int acked_bytes, quic::QuicTime::Delta delta_largest_observed) override; void OnPacketRetransmitted(int /* retransmitted_bytes */) override {} + + // Add bytes sent for this stream, for internal tracking of bytes acked. void addBytesSent(uint64_t bytes_sent, bool end_stream) { bytes_outstanding_ += bytes_sent; fin_sent_ = end_stream; } + // Log this stream using available stream info and access loggers. void doDeferredLog(); + // Add a pointer to stream info that should be logged. There can be + // multiple in case of a recreated stream (e.g. internal redirect) void addStreamInfo(std::shared_ptr stream_info) { if (stream_info != nullptr) { stream_info_.push_back(stream_info); } } + // Set list of pointers to access loggers. void setAccessLogHandlers(std::list handlers) { access_log_handlers_ = handlers; } + // Set time source, for recording the timestamp of the final ack. void setTimeSource(Envoy::TimeSource* time_source) { time_source_ = time_source; } private: diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index c532d4384cb3d..47b52aa2c84fb 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -364,6 +364,8 @@ struct StreamInfoImpl : public StreamInfo { // TODO(agrawroh): Check if the owner of this storage outlives the StreamInfo. We should only copy // the string if it could outlive the StreamInfo. absl::optional virtual_cluster_name_; + // Headers and trailers required for access logs, stored in StreamInfo for deferred logging (i.e. + // after typical cleanup of a stream). nullopt indicates that deferred logging should be skipped. absl::optional deferred_logging_info_; private: From 3ba8d5933696af7caaadf35f3d55bbbcecb4098a Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 28 Nov 2022 20:30:33 +0000 Subject: [PATCH 29/59] H/2 codec ServerStreamImpl: request decoder member is private Signed-off-by: Paul Sohn --- source/common/http/http2/codec_impl.h | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 4daf02898e3ae..174fa3ac4fe35 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -525,12 +525,14 @@ class ConnectionImpl : public virtual Connection, // ScopeTrackedObject void dumpState(std::ostream& os, int indent_level) const override; - RequestDecoder* request_decoder_{}; absl::variant headers_or_trailers_; bool streamErrorOnInvalidHttpMessage() const override { return parent_.stream_error_on_invalid_http_messaging_; } + + private: + RequestDecoder* request_decoder_{}; }; using ServerStreamImplPtr = std::unique_ptr; From d29a9b9f67f39afc47b334179c5d26496ad3bf11 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 29 Nov 2022 19:17:17 +0000 Subject: [PATCH 30/59] s/doDeferredLog/maybeDoDeferredLog Signed-off-by: Paul Sohn --- source/common/quic/quic_stats_gatherer.cc | 4 ++-- source/common/quic/quic_stats_gatherer.h | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 286692a0f8446..3fc2f12c2ae1b 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -9,11 +9,11 @@ void QuicStatsGatherer::OnPacketAcked(int acked_bytes, quic::QuicTime::Delta /* delta_largest_observed */) { bytes_outstanding_ -= acked_bytes; if (bytes_outstanding_ == 0 && fin_sent_ && !logging_done_) { - doDeferredLog(); + maybeDoDeferredLog(); } } -void QuicStatsGatherer::doDeferredLog() { +void QuicStatsGatherer::maybeDoDeferredLog() { logging_done_ = true; for (const std::shared_ptr& stream_info : stream_info_) { if (!stream_info->deferredLoggingInfo().has_value()) { diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index 5eddf99ec1bd9..4081960c2bf71 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -26,7 +26,7 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { fin_sent_ = end_stream; } // Log this stream using available stream info and access loggers. - void doDeferredLog(); + void maybeDoDeferredLog(); // Add a pointer to stream info that should be logged. There can be // multiple in case of a recreated stream (e.g. internal redirect) void addStreamInfo(std::shared_ptr stream_info) { From a3e30ca2720bfc855049ab71ee269b9e4f5e56c7 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 29 Nov 2022 21:31:48 +0000 Subject: [PATCH 31/59] QuicStatsGatherer: set time source in ctor and remove setter Signed-off-by: Paul Sohn --- source/common/quic/envoy_quic_server_stream.cc | 2 +- source/common/quic/envoy_quic_server_stream.h | 1 - source/common/quic/quic_stats_gatherer.h | 4 ++-- 3 files changed, 3 insertions(+), 4 deletions(-) diff --git a/source/common/quic/envoy_quic_server_stream.cc b/source/common/quic/envoy_quic_server_stream.cc index c1f6a2c3bc910..409acf470a86a 100644 --- a/source/common/quic/envoy_quic_server_stream.cc +++ b/source/common/quic/envoy_quic_server_stream.cc @@ -38,7 +38,7 @@ EnvoyQuicServerStream::EnvoyQuicServerStream( ASSERT(static_cast(GetReceiveWindow().value()) > 8 * 1024, "Send buffer limit should be larger than 8KB."); - stats_gatherer_ = new QuicStatsGatherer(); + stats_gatherer_ = new QuicStatsGatherer(&connection()->dispatcher().timeSource()); set_ack_listener(stats_gatherer_); } diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index 4a0e6b5268705..a20ba9956f53e 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -24,7 +24,6 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, request_decoder_ = &decoder; stats_gatherer_->addStreamInfo(request_decoder_->streamInfoSharedPtr()); stats_gatherer_->setAccessLogHandlers(request_decoder_->accessLogHandlers()); - stats_gatherer_->setTimeSource(&connection()->dispatcher().timeSource()); } // Http::StreamEncoder diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index 4081960c2bf71..bb0112560a534 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -16,6 +16,8 @@ namespace Quic { // logging after the final ack. class QuicStatsGatherer : public quic::QuicAckListenerInterface { public: + QuicStatsGatherer(Envoy::TimeSource* time_source) : time_source_(time_source) {} + // QuicAckListenerInterface void OnPacketAcked(int acked_bytes, quic::QuicTime::Delta delta_largest_observed) override; void OnPacketRetransmitted(int /* retransmitted_bytes */) override {} @@ -38,8 +40,6 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { void setAccessLogHandlers(std::list handlers) { access_log_handlers_ = handlers; } - // Set time source, for recording the timestamp of the final ack. - void setTimeSource(Envoy::TimeSource* time_source) { time_source_ = time_source; } private: uint64_t bytes_outstanding_ = 0; From e1490c743ceef043f225ef3fddc11f20df9b97a6 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 30 Nov 2022 19:15:26 +0000 Subject: [PATCH 32/59] QuicHttpIntegrationTest: check more deferred log metrics Signed-off-by: Paul Sohn --- .../integration/quic_http_integration_test.cc | 65 ++++++++++++------- 1 file changed, 41 insertions(+), 24 deletions(-) diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index ffea0316b9bc6..a91d04fb1da28 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1168,7 +1168,8 @@ TEST_P(QuicHttpIntegrationTest, MultipleNetworkFilters) { } TEST_P(QuicHttpIntegrationTest, DeferredLogging) { - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" + "CODE%,%BYTES_RECEIVED%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); sendRequestAndWaitForResponse(default_request_headers_, /*request_size=*/0, @@ -1178,17 +1179,22 @@ TEST_P(QuicHttpIntegrationTest, DeferredLogging) { codec_client_->close(); std::string log = waitForAccessLog(access_log_name_); - std::string delimiter = ","; - std::string protocol = log.substr(0, log.find(delimiter)); - std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); - EXPECT_EQ(protocol, "HTTP/3"); - EXPECT_GT(std::stoi(roundtrip_duration), 0); + + std::vector metrics = absl::StrSplit(log, ","); + ASSERT_EQ(metrics.size(), 6); + EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); + EXPECT_GT(/* ROUNDTRIP_DURATION */ std::stoi(metrics.at(1)), 0); + EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); + EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingDisabled) { config_helper_.addRuntimeOverride("envoy.reloadable_features.quic_defer_logging_to_ack_listener", "false"); - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" + "CODE%,%BYTES_RECEIVED%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); sendRequestAndWaitForResponse(default_request_headers_, /*request_size=*/0, @@ -1199,15 +1205,19 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingDisabled) { // Do not flush client acks. std::string log = waitForAccessLog(access_log_name_, 0, false, nullptr); - std::string delimiter = ","; - std::string protocol = log.substr(0, log.find(delimiter)); - std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); - EXPECT_EQ(protocol, "HTTP/3"); - EXPECT_EQ(roundtrip_duration, "-"); + std::vector metrics = absl::StrSplit(log, ","); + ASSERT_EQ(metrics.size(), 6); + EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); + EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); + EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); + EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" + "CODE%,%BYTES_RECEIVED%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); auto response = codec_client_->makeHeaderOnlyRequest(default_request_headers_); @@ -1217,15 +1227,19 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { EXPECT_FALSE(response->complete()); std::string log = waitForAccessLog(access_log_name_); - std::string delimiter = ","; - std::string protocol = log.substr(0, log.find(delimiter)); - std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); - EXPECT_EQ(protocol, "HTTP/3"); - EXPECT_EQ(roundtrip_duration, "-"); + std::vector metrics = absl::StrSplit(log, ","); + ASSERT_EQ(metrics.size(), 6); + EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); + EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); + EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_EQ(/* RESPONSE_DURATION */ metrics.at(3), "-"); + EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "0"); + EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithQuicReset) { - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%"); + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" + "CODE%,%BYTES_RECEIVED%"); initialize(); codec_client_ = makeHttpConnection(lookupPort("http")); @@ -1240,11 +1254,14 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithQuicReset) { ASSERT_TRUE(response->complete()); std::string log = waitForAccessLog(access_log_name_); - std::string delimiter = ","; - std::string protocol = log.substr(0, log.find(delimiter)); - std::string roundtrip_duration = log.substr(log.find(delimiter) + 1, log.length()); - EXPECT_EQ(protocol, "HTTP/3"); - EXPECT_EQ(roundtrip_duration, "-"); + std::vector metrics = absl::StrSplit(log, ","); + ASSERT_EQ(metrics.size(), 6); + EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); + EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); + EXPECT_EQ(/* REQUEST_DURATION */ metrics.at(2), "-"); + EXPECT_EQ(/* RESPONSE_DURATION */ metrics.at(3), "-"); + EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "400"); + EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); } class QuicInplaceLdsIntegrationTest : public QuicHttpIntegrationTest { From c55f5b8d0052d81db00c714cab5ee61bed16e484 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Thu, 1 Dec 2022 16:59:37 +0000 Subject: [PATCH 33/59] QuicStatsGatherer: add explicit modifier to ctor Signed-off-by: Paul Sohn --- source/common/quic/quic_stats_gatherer.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index bb0112560a534..fcd5beb5da560 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -16,7 +16,7 @@ namespace Quic { // logging after the final ack. class QuicStatsGatherer : public quic::QuicAckListenerInterface { public: - QuicStatsGatherer(Envoy::TimeSource* time_source) : time_source_(time_source) {} + explicit QuicStatsGatherer(Envoy::TimeSource* time_source) : time_source_(time_source) {} // QuicAckListenerInterface void OnPacketAcked(int acked_bytes, quic::QuicTime::Delta delta_largest_observed) override; From ca4d8f5d556b371f5abf71ef1acaf92e6a41d114 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Thu, 1 Dec 2022 19:50:43 +0000 Subject: [PATCH 34/59] s/DeferredLoggingInfo/DeferredLoggingHeadersAndTrailers Signed-off-by: Paul Sohn --- envoy/stream_info/stream_info.h | 10 ++++++---- source/common/http/conn_manager_impl.cc | 3 ++- source/common/http/conn_manager_impl.h | 4 ++-- source/common/quic/quic_stats_gatherer.cc | 11 +++++++---- source/common/stream_info/stream_info_impl.h | 14 ++++++++------ test/mocks/stream_info/mocks.h | 8 +++++--- 6 files changed, 30 insertions(+), 20 deletions(-) diff --git a/envoy/stream_info/stream_info.h b/envoy/stream_info/stream_info.h index 2148a942620ca..49e8a29e047e3 100644 --- a/envoy/stream_info/stream_info.h +++ b/envoy/stream_info/stream_info.h @@ -462,7 +462,7 @@ class UpstreamInfo { virtual absl::optional upstreamProtocol() const PURE; }; -struct DeferredLoggingInfo { +struct DeferredLoggingHeadersAndTrailers { Http::RequestHeaderMapSharedPtr request_header_map = nullptr; Http::ResponseHeaderMapSharedPtr response_header_map = nullptr; Http::ResponseTrailerMapSharedPtr response_trailer_map = nullptr; @@ -775,14 +775,16 @@ class StreamInfo { virtual void dumpState(std::ostream& os, int indent_level = 0) const PURE; /** - * @param deferredLoggingInfo request/response info for deferred logging. + * @param DeferredLoggingHeadersAndTrailers request/response info for deferred logging. */ - virtual void setDeferredLoggingInfo(const DeferredLoggingInfo deferred_logging_info) PURE; + virtual void setDeferredLoggingHeadersAndTrailers( + const DeferredLoggingHeadersAndTrailers deferred_logging_headers_and_trailers) PURE; /** * @return request/response info for deferred logging. */ - virtual const absl::optional& deferredLoggingInfo() const PURE; + virtual const absl::optional& + deferredLoggingHeadersAndTrailers() const PURE; }; // An enum representation of the Proxy-Status error space. diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index e97a5021ba199..9ffa7ae91f312 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -286,7 +286,8 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { !stream.filter_manager_.sawDownstreamReset() && Runtime::runtimeFeatureEnabled( "envoy.reloadable_features.quic_defer_logging_to_ack_listener")) { - stream.filter_manager_.streamInfo().setDeferredLoggingInfo(stream.deferredLoggingInfo()); + stream.filter_manager_.streamInfo().setDeferredLoggingHeadersAndTrailers( + stream.DeferredLoggingHeadersAndTrailers()); } else { // For HTTP/1 and HTTP/2, log here as usual. stream.filter_manager_.log(); diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index f1e865abc32bb..353f5fe32266e 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -207,8 +207,8 @@ class ConnectionManagerImpl : Logger::Loggable, std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } - StreamInfo::DeferredLoggingInfo deferredLoggingInfo() { - StreamInfo::DeferredLoggingInfo info; + StreamInfo::DeferredLoggingHeadersAndTrailers DeferredLoggingHeadersAndTrailers() { + StreamInfo::DeferredLoggingHeadersAndTrailers info; if (requestHeaders()) { info.request_header_map = request_headers_; } diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 3fc2f12c2ae1b..c4c34a462ff72 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -16,15 +16,18 @@ void QuicStatsGatherer::OnPacketAcked(int acked_bytes, void QuicStatsGatherer::maybeDoDeferredLog() { logging_done_ = true; for (const std::shared_ptr& stream_info : stream_info_) { - if (!stream_info->deferredLoggingInfo().has_value()) { + if (!stream_info->deferredLoggingHeadersAndTrailers().has_value()) { continue; } if (time_source_ != nullptr) { stream_info->downstreamTiming().onLastDownstreamAckReceived(*time_source_); } - auto request_headers = stream_info->deferredLoggingInfo()->request_header_map.get(); - auto response_headers = stream_info->deferredLoggingInfo()->response_header_map.get(); - auto response_trailers = stream_info->deferredLoggingInfo()->response_trailer_map.get(); + auto request_headers = + stream_info->deferredLoggingHeadersAndTrailers()->request_header_map.get(); + auto response_headers = + stream_info->deferredLoggingHeadersAndTrailers()->response_header_map.get(); + auto response_trailers = + stream_info->deferredLoggingHeadersAndTrailers()->response_trailer_map.get(); for (const auto& log_handler : access_log_handlers_) { log_handler->log(request_headers, response_headers, response_trailers, *stream_info); } diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index 47b52aa2c84fb..86af5e2db3ca7 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -231,12 +231,14 @@ struct StreamInfoImpl : public StreamInfo { return virtual_cluster_name_; } - void setDeferredLoggingInfo(DeferredLoggingInfo deferred_logging_info) override { - deferred_logging_info_ = - absl::make_optional(std::move(deferred_logging_info)); + void setDeferredLoggingHeadersAndTrailers( + DeferredLoggingHeadersAndTrailers deferred_logging_headers_and_trailers) override { + deferred_logging_headers_and_trailers_ = absl::make_optional( + std::move(deferred_logging_headers_and_trailers)); } - const absl::optional& deferredLoggingInfo() const override { - return deferred_logging_info_; + const absl::optional& + deferredLoggingHeadersAndTrailers() const override { + return deferred_logging_headers_and_trailers_; } bool healthCheck() const override { return health_check_request_; } @@ -366,7 +368,7 @@ struct StreamInfoImpl : public StreamInfo { absl::optional virtual_cluster_name_; // Headers and trailers required for access logs, stored in StreamInfo for deferred logging (i.e. // after typical cleanup of a stream). nullopt indicates that deferred logging should be skipped. - absl::optional deferred_logging_info_; + absl::optional deferred_logging_headers_and_trailers_; private: static Network::ConnectionInfoProviderSharedPtr emptyDownstreamAddressProvider() { diff --git a/test/mocks/stream_info/mocks.h b/test/mocks/stream_info/mocks.h index b0733dc2244a7..1767b7ef6b33c 100644 --- a/test/mocks/stream_info/mocks.h +++ b/test/mocks/stream_info/mocks.h @@ -93,8 +93,10 @@ class MockStreamInfo : public StreamInfo { MOCK_METHOD(const absl::optional&, virtualClusterName, (), (const)); MOCK_METHOD(absl::optional, protocol, (), (const)); MOCK_METHOD(void, protocol, (Http::Protocol protocol)); - MOCK_METHOD(void, setDeferredLoggingInfo, (DeferredLoggingInfo deferredLoggingInfo)); - MOCK_METHOD(const absl::optional&, deferredLoggingInfo, (), (const)); + MOCK_METHOD(void, setDeferredLoggingHeadersAndTrailers, + (DeferredLoggingHeadersAndTrailers deferredLoggingHeadersAndTrailers)); + MOCK_METHOD(const absl::optional&, + deferredLoggingHeadersAndTrailers, (), (const)); MOCK_METHOD(absl::optional, responseCode, (), (const)); MOCK_METHOD(const absl::optional&, responseCodeDetails, (), (const)); MOCK_METHOD(const absl::optional&, connectionTerminationDetails, (), (const)); @@ -160,7 +162,7 @@ class MockStreamInfo : public StreamInfo { std::string filter_chain_name_; absl::optional attempt_count_; absl::optional virtual_cluster_name_; - absl::optional deferred_logging_info_; + absl::optional deferred_logging_headers_and_trailers_; DownstreamTiming downstream_timing_; }; From 33e3be5343faf686b1344844a2bdff3e2fdd826e Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 5 Dec 2022 18:33:32 +0000 Subject: [PATCH 35/59] QuicStatsGatherer points to one streaminfo at a time Also, set up RedirectIntegrationTest to test H/3 downstream. Signed-off-by: Paul Sohn --- source/common/http/conn_manager_impl.cc | 6 ++-- source/common/quic/envoy_quic_server_stream.h | 2 +- source/common/quic/quic_stats_gatherer.cc | 33 ++++++++++--------- source/common/quic/quic_stats_gatherer.h | 12 +++---- test/integration/BUILD | 1 + test/integration/redirect_integration_test.cc | 18 +++++++--- 6 files changed, 41 insertions(+), 31 deletions(-) diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index 9ffa7ae91f312..52d1540ed78cd 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -280,10 +280,12 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { stream.filter_manager_.onStreamComplete(); // For HTTP/3, skip access logging here and add deferred logging info - // to stream info for QuicStatsGatherer to use later. If there was a - // downstream reset, log here as usual. + // 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.filter_manager_.streamInfo().setDeferredLoggingHeadersAndTrailers( diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index a20ba9956f53e..3d12482042d15 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -22,7 +22,7 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; - stats_gatherer_->addStreamInfo(request_decoder_->streamInfoSharedPtr()); + stats_gatherer_->setStreamInfo(request_decoder_->streamInfoSharedPtr()); stats_gatherer_->setAccessLogHandlers(request_decoder_->accessLogHandlers()); } diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index c4c34a462ff72..29d39c5ce03fc 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -15,22 +15,23 @@ void QuicStatsGatherer::OnPacketAcked(int acked_bytes, void QuicStatsGatherer::maybeDoDeferredLog() { logging_done_ = true; - for (const std::shared_ptr& stream_info : stream_info_) { - if (!stream_info->deferredLoggingHeadersAndTrailers().has_value()) { - continue; - } - if (time_source_ != nullptr) { - stream_info->downstreamTiming().onLastDownstreamAckReceived(*time_source_); - } - auto request_headers = - stream_info->deferredLoggingHeadersAndTrailers()->request_header_map.get(); - auto response_headers = - stream_info->deferredLoggingHeadersAndTrailers()->response_header_map.get(); - auto response_trailers = - stream_info->deferredLoggingHeadersAndTrailers()->response_trailer_map.get(); - for (const auto& log_handler : access_log_handlers_) { - log_handler->log(request_headers, response_headers, response_trailers, *stream_info); - } + if (stream_info_ == nullptr) { + return; + } + if (!stream_info_->deferredLoggingHeadersAndTrailers().has_value()) { + return; + } + if (time_source_ != nullptr) { + stream_info_->downstreamTiming().onLastDownstreamAckReceived(*time_source_); + } + auto request_headers = + stream_info_->deferredLoggingHeadersAndTrailers()->request_header_map.get(); + auto response_headers = + stream_info_->deferredLoggingHeadersAndTrailers()->response_header_map.get(); + auto response_trailers = + stream_info_->deferredLoggingHeadersAndTrailers()->response_trailer_map.get(); + for (const auto& log_handler : access_log_handlers_) { + log_handler->log(request_headers, response_headers, response_trailers, *stream_info_); } } diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index fcd5beb5da560..e1bcb223f3a00 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -29,12 +29,10 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { } // Log this stream using available stream info and access loggers. void maybeDoDeferredLog(); - // Add a pointer to stream info that should be logged. There can be - // multiple in case of a recreated stream (e.g. internal redirect) - void addStreamInfo(std::shared_ptr stream_info) { - if (stream_info != nullptr) { - stream_info_.push_back(stream_info); - } + // Add a pointer to stream info that should be logged. This can be overwritten + // in case of an internal redirect. + void setStreamInfo(std::shared_ptr stream_info) { + stream_info_ = stream_info; } // Set list of pointers to access loggers. void setAccessLogHandlers(std::list handlers) { @@ -44,7 +42,7 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { private: uint64_t bytes_outstanding_ = 0; bool fin_sent_ = false; - std::list> stream_info_{}; + std::shared_ptr stream_info_ = nullptr; std::list access_log_handlers_{}; Envoy::TimeSource* time_source_ = nullptr; bool logging_done_ = false; diff --git a/test/integration/BUILD b/test/integration/BUILD index 1a9851083de20..0e67abcc40a46 100644 --- a/test/integration/BUILD +++ b/test/integration/BUILD @@ -721,6 +721,7 @@ envoy_cc_test_library( "//test/integration/filters:encode_headers_return_stop_all_filter_config_lib", "//test/integration/filters:modify_buffer_filter_config_lib", "//test/integration/filters:passthrough_filter_config_lib", + "//test/integration/filters:pause_filter_for_quic_lib", "//test/integration/filters:pause_filter_lib", "//test/integration/filters:wait_for_whole_request_and_response_config_lib", "//test/mocks/upstream:cluster_info_mocks", diff --git a/test/integration/redirect_integration_test.cc b/test/integration/redirect_integration_test.cc index d746e00979766..bb187b731d297 100644 --- a/test/integration/redirect_integration_test.cc +++ b/test/integration/redirect_integration_test.cc @@ -219,8 +219,7 @@ TEST_P(RedirectIntegrationTest, BasicInternalRedirectDownstreamBytesCount) { upstream_request_->encodeHeaders(redirect_response_, true); expectDownstreamBytesSentAndReceived(BytesCountExpectation(0, 63, 0, 31), BytesCountExpectation(0, 42, 0, 42), - BytesCountExpectation(0, 42, 0, 42), 0); - + BytesCountExpectation(0, 8, 0, 6), 0); waitForNextUpstreamRequest(); upstream_request_->encodeHeaders(default_response_headers_, true); @@ -228,7 +227,7 @@ TEST_P(RedirectIntegrationTest, BasicInternalRedirectDownstreamBytesCount) { ASSERT_TRUE(response->complete()); expectDownstreamBytesSentAndReceived(BytesCountExpectation(140, 63, 121, 31), BytesCountExpectation(77, 42, 77, 42), - BytesCountExpectation(77, 42, 77, 42), 1); + BytesCountExpectation(9, 8, 9, 6), 1); } TEST_P(RedirectIntegrationTest, BasicInternalRedirectUpstreamBytesCount) { @@ -611,9 +610,15 @@ TEST_P(RedirectIntegrationTest, InternalRedirectToDestinationWithResponseBody) { config_helper_.addConfigModifier( [](envoy::extensions::filters::network::http_connection_manager::v3::HttpConnectionManager& hcm) { hcm.set_via("via_value"); }); - config_helper_.prependFilter(R"EOF( + if (downstreamProtocol() == Http::CodecType::HTTP3) { + config_helper_.prependFilter(R"EOF( + name: pause-filter-for-quic + )EOF"); + } else { + config_helper_.prependFilter(R"EOF( name: pause-filter )EOF"); + } initialize(); codec_client_ = makeHttpConnection(lookupPort("http")); @@ -707,7 +712,10 @@ TEST_P(RedirectIntegrationTest, InternalRedirectHandledByDirectResponse) { } INSTANTIATE_TEST_SUITE_P(Protocols, RedirectIntegrationTest, - testing::ValuesIn(HttpProtocolIntegrationTest::getProtocolTestParams()), + testing::ValuesIn(HttpProtocolIntegrationTest::getProtocolTestParams( + {Http::CodecType::HTTP1, Http::CodecType::HTTP2, + Http::CodecType::HTTP3}, + {Http::CodecType::HTTP1, Http::CodecType::HTTP2})), HttpProtocolIntegrationTest::protocolTestParamsToString); } // namespace Envoy From 2b228cfb6023da0b0450904780280fba6e62b4f2 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 6 Dec 2022 16:18:57 +0000 Subject: [PATCH 36/59] Test that new metric is added in internal redirect case Signed-off-by: Paul Sohn --- .../integration/quic_http_integration_test.cc | 71 +++++++++++++++++++ 1 file changed, 71 insertions(+) diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index a91d04fb1da28..64af3820b326b 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1264,6 +1264,77 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithQuicReset) { EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); } +TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { + useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" + "CODE%,%BYTES_RECEIVED%,%RESPONSE_CODE_DETAILS%,%RESP(test-header)%"); + auto handle = config_helper_.createVirtualHost("handle.internal.redirect"); + handle.mutable_routes(0)->set_name("redirect"); + handle.mutable_routes(0)->mutable_route()->mutable_internal_redirect_policy(); + config_helper_.addVirtualHost(handle); + initialize(); + + codec_client_ = makeHttpConnection(lookupPort("http")); + + default_request_headers_.setHost("handle.internal.redirect"); + IntegrationStreamDecoderPtr response = + codec_client_->makeHeaderOnlyRequest(default_request_headers_); + + waitForNextUpstreamRequest(); + + Http::TestResponseHeaderMapImpl redirect_response{{":status", "302"}, + {"content-length", "0"}, + {"location", "http://authority2/new/url"}, + // Test header added to confirm that response + // headers are populated for internal redirects + {"test-header", "test-header-value"}}; + + upstream_request_->encodeHeaders(redirect_response, true); + std::string log = waitForAccessLog(access_log_name_, 0); + std::vector metrics = absl::StrSplit(log, ","); + ASSERT_EQ(metrics.size(), 8); + EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); + // no roundtrip duration for internal redirect. + EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); + EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "302"); + EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); + EXPECT_EQ(/* RESPONSE_CODE_DETAILS */ metrics.at(6), "internal_redirect"); + EXPECT_EQ(/* RESP(test-header) */ metrics.at(7), "test-header-value"); + + waitForNextUpstreamRequest(); + ASSERT(upstream_request_->headers().EnvoyOriginalUrl() != nullptr); + EXPECT_EQ("http://handle.internal.redirect/test/long/url", + upstream_request_->headers().getEnvoyOriginalUrlValue()); + EXPECT_EQ("/new/url", upstream_request_->headers().getPathValue()); + EXPECT_EQ("authority2", upstream_request_->headers().getHostValue()); + + upstream_request_->encodeHeaders(default_response_headers_, true); + + ASSERT_TRUE(response->waitForEndStream()); + ASSERT_TRUE(response->complete()); + EXPECT_EQ("200", response->headers().getStatusValue()); + EXPECT_EQ(1, test_server_->counter("cluster.cluster_0.upstream_internal_redirect_succeeded_total") + ->value()); + // 302 was never returned downstream + EXPECT_EQ(0, test_server_->counter("http.config_test.downstream_rq_3xx")->value()); + EXPECT_EQ(1, test_server_->counter("http.config_test.downstream_rq_2xx")->value()); + + log = waitForAccessLog(access_log_name_, 1); + metrics = absl::StrSplit(log, ","); + ASSERT_EQ(metrics.size(), 8); + EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); + // roundtrip duration populated on final log. + EXPECT_GT(/* ROUNDTRIP_DURATION */ std::stoi(metrics.at(1)), 0); + EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); + EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); + EXPECT_EQ(/* RESPONSE_CODE_DETAILS */ metrics.at(6), "via_upstream"); + // no test header + EXPECT_EQ(/* RESP(test-header) */ metrics.at(7), "-"); +} + class QuicInplaceLdsIntegrationTest : public QuicHttpIntegrationTest { public: void inplaceInitialize(bool add_default_filter_chain = false) { From 63205e53e9a3a8f579137d1abbf16de8469cc520 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 6 Dec 2022 20:02:26 +0000 Subject: [PATCH 37/59] Move deferred logging info out of stream info Instead, allow response encoder to deal with where this info should be stored for logging. Signed-off-by: Paul Sohn --- envoy/http/codec.h | 13 +++++++++++++ envoy/stream_info/stream_info.h | 18 ------------------ source/common/http/conn_manager_impl.cc | 3 +-- source/common/http/conn_manager_impl.h | 12 ++++++------ source/common/http/http1/codec_impl.h | 2 ++ source/common/http/http2/codec_impl.h | 6 ++++-- source/common/quic/envoy_quic_server_stream.h | 4 ++++ source/common/quic/quic_stats_gatherer.cc | 13 ++++++------- source/common/quic/quic_stats_gatherer.h | 10 ++++++++++ source/common/stream_info/stream_info_impl.h | 13 ------------- test/mocks/stream_info/mocks.h | 5 ----- 11 files changed, 46 insertions(+), 53 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 0d5fa2f4926b9..ab1114d5f387e 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -135,6 +135,12 @@ class RequestEncoder : public virtual StreamEncoder { virtual void enableTcpTunneling() PURE; }; +struct DeferredLoggingHeadersAndTrailers { + Http::RequestHeaderMapSharedPtr request_header_map = nullptr; + Http::ResponseHeaderMapSharedPtr response_header_map = nullptr; + Http::ResponseTrailerMapSharedPtr response_trailer_map = nullptr; +}; + /** * Stream encoder used for sending a response (server to client). Virtual inheritance is required * due to a parallel implementation split between the shared base class and the derived class. @@ -173,6 +179,13 @@ class ResponseEncoder : public virtual StreamEncoder { * @param decoder new request decoder. */ virtual void setRequestDecoder(RequestDecoder& decoder) PURE; + + /** + * Set headers and trailers for deferred logging. + * @param headers_and_trailers Headers and trailers from this stream. + */ + virtual void + setDeferredLoggingHeadersAndTrailers(DeferredLoggingHeadersAndTrailers headers_and_trailers) PURE; }; /** diff --git a/envoy/stream_info/stream_info.h b/envoy/stream_info/stream_info.h index 49e8a29e047e3..5d16274a71334 100644 --- a/envoy/stream_info/stream_info.h +++ b/envoy/stream_info/stream_info.h @@ -462,12 +462,6 @@ class UpstreamInfo { virtual absl::optional upstreamProtocol() const PURE; }; -struct DeferredLoggingHeadersAndTrailers { - Http::RequestHeaderMapSharedPtr request_header_map = nullptr; - Http::ResponseHeaderMapSharedPtr response_header_map = nullptr; - Http::ResponseTrailerMapSharedPtr response_trailer_map = nullptr; -}; - /** * Additional information about a completed request for logging. */ @@ -773,18 +767,6 @@ class StreamInfo { * This function is called on Envoy fatal errors so should avoid memory allocation. */ virtual void dumpState(std::ostream& os, int indent_level = 0) const PURE; - - /** - * @param DeferredLoggingHeadersAndTrailers request/response info for deferred logging. - */ - virtual void setDeferredLoggingHeadersAndTrailers( - const DeferredLoggingHeadersAndTrailers deferred_logging_headers_and_trailers) PURE; - - /** - * @return request/response info for deferred logging. - */ - virtual const absl::optional& - deferredLoggingHeadersAndTrailers() const PURE; }; // An enum representation of the Proxy-Status error space. diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index 52d1540ed78cd..1791fea7a5ca5 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -288,8 +288,7 @@ void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) { stream.response_encoder_ != nullptr && Runtime::runtimeFeatureEnabled( "envoy.reloadable_features.quic_defer_logging_to_ack_listener")) { - stream.filter_manager_.streamInfo().setDeferredLoggingHeadersAndTrailers( - stream.DeferredLoggingHeadersAndTrailers()); + stream.deferHeadersAndTrailers(); } else { // For HTTP/1 and HTTP/2, log here as usual. stream.filter_manager_.log(); diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 353f5fe32266e..0b32a71fd411a 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -207,18 +207,18 @@ class ConnectionManagerImpl : Logger::Loggable, std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } - StreamInfo::DeferredLoggingHeadersAndTrailers DeferredLoggingHeadersAndTrailers() { - StreamInfo::DeferredLoggingHeadersAndTrailers info; + void deferHeadersAndTrailers() { + Http::DeferredLoggingHeadersAndTrailers headers_and_trailers; if (requestHeaders()) { - info.request_header_map = request_headers_; + headers_and_trailers.request_header_map = request_headers_; } if (responseHeaders()) { - info.response_header_map = response_headers_; + headers_and_trailers.response_header_map = response_headers_; } if (responseTrailers()) { - info.response_trailer_map = response_trailers_; + headers_and_trailers.response_trailer_map = response_trailers_; } - return info; + response_encoder_->setDeferredLoggingHeadersAndTrailers(std::move(headers_and_trailers)); } // Tracing::TracingConfig diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index 65010d83ebd8c..0867e00f98b20 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -156,6 +156,8 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { return stream_error_on_invalid_http_message_; } void setRequestDecoder(Http::RequestDecoder& /*decoder*/) override {} + void setDeferredLoggingHeadersAndTrailers( + Http::DeferredLoggingHeadersAndTrailers /*headers_and_trailers*/) override {} // Http1::StreamEncoderImpl void resetStream(StreamResetReason reason) override; diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 174fa3ac4fe35..092bc2abdd73f 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -521,6 +521,8 @@ class ConnectionImpl : public virtual Connection, encodeTrailersBase(trailers); } void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; } + void setDeferredLoggingHeadersAndTrailers( + Http::DeferredLoggingHeadersAndTrailers /*headers_and_trailers*/) override {} // ScopeTrackedObject void dumpState(std::ostream& os, int indent_level) const override; @@ -531,8 +533,8 @@ class ConnectionImpl : public virtual Connection, return parent_.stream_error_on_invalid_http_messaging_; } - private: - RequestDecoder* request_decoder_{}; + private: + RequestDecoder* request_decoder_{}; }; using ServerStreamImplPtr = std::unique_ptr; diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index 3d12482042d15..eabb568cd1c87 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -38,6 +38,10 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, bool streamErrorOnInvalidHttpMessage() const override { return http3_options_.override_stream_error_on_invalid_http_message().value(); } + void setDeferredLoggingHeadersAndTrailers( + Http::DeferredLoggingHeadersAndTrailers headers_and_trailers) override { + stats_gatherer_->setDeferredLoggingHeadersAndTrailers(std::move(headers_and_trailers)); + }; // Http::Stream void resetStream(Http::StreamResetReason reason) override; diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 29d39c5ce03fc..778eb221f1329 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -18,18 +18,17 @@ void QuicStatsGatherer::maybeDoDeferredLog() { if (stream_info_ == nullptr) { return; } - if (!stream_info_->deferredLoggingHeadersAndTrailers().has_value()) { + if (!deferred_logging_headers_and_trailers_.has_value()) { return; } if (time_source_ != nullptr) { stream_info_->downstreamTiming().onLastDownstreamAckReceived(*time_source_); } - auto request_headers = - stream_info_->deferredLoggingHeadersAndTrailers()->request_header_map.get(); - auto response_headers = - stream_info_->deferredLoggingHeadersAndTrailers()->response_header_map.get(); - auto response_trailers = - stream_info_->deferredLoggingHeadersAndTrailers()->response_trailer_map.get(); + Http::DeferredLoggingHeadersAndTrailers headers_and_trailers = + deferred_logging_headers_and_trailers_.value(); + auto request_headers = headers_and_trailers.request_header_map.get(); + auto response_headers = headers_and_trailers.response_header_map.get(); + auto response_trailers = headers_and_trailers.response_trailer_map.get(); for (const auto& log_handler : access_log_handlers_) { log_handler->log(request_headers, response_headers, response_trailers, *stream_info_); } diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index e1bcb223f3a00..621905e7ee40c 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -38,12 +38,22 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { void setAccessLogHandlers(std::list handlers) { access_log_handlers_ = handlers; } + // Set headers and trailers used for deferred logging. + void setDeferredLoggingHeadersAndTrailers( + Http::DeferredLoggingHeadersAndTrailers headers_and_trailers) { + deferred_logging_headers_and_trailers_ = + absl::make_optional( + std::move(headers_and_trailers)); + } private: uint64_t bytes_outstanding_ = 0; bool fin_sent_ = false; std::shared_ptr stream_info_ = nullptr; std::list access_log_handlers_{}; + // Headers and trailers required for deferred logging. nullopt indicates that deferred logging + // should be skipped. + absl::optional deferred_logging_headers_and_trailers_; Envoy::TimeSource* time_source_ = nullptr; bool logging_done_ = false; }; diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index 86af5e2db3ca7..c666890849691 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -231,16 +231,6 @@ struct StreamInfoImpl : public StreamInfo { return virtual_cluster_name_; } - void setDeferredLoggingHeadersAndTrailers( - DeferredLoggingHeadersAndTrailers deferred_logging_headers_and_trailers) override { - deferred_logging_headers_and_trailers_ = absl::make_optional( - std::move(deferred_logging_headers_and_trailers)); - } - const absl::optional& - deferredLoggingHeadersAndTrailers() const override { - return deferred_logging_headers_and_trailers_; - } - bool healthCheck() const override { return health_check_request_; } void healthCheck(bool is_health_check) override { health_check_request_ = is_health_check; } @@ -366,9 +356,6 @@ struct StreamInfoImpl : public StreamInfo { // TODO(agrawroh): Check if the owner of this storage outlives the StreamInfo. We should only copy // the string if it could outlive the StreamInfo. absl::optional virtual_cluster_name_; - // Headers and trailers required for access logs, stored in StreamInfo for deferred logging (i.e. - // after typical cleanup of a stream). nullopt indicates that deferred logging should be skipped. - absl::optional deferred_logging_headers_and_trailers_; private: static Network::ConnectionInfoProviderSharedPtr emptyDownstreamAddressProvider() { diff --git a/test/mocks/stream_info/mocks.h b/test/mocks/stream_info/mocks.h index 1767b7ef6b33c..97516eaac05dc 100644 --- a/test/mocks/stream_info/mocks.h +++ b/test/mocks/stream_info/mocks.h @@ -93,10 +93,6 @@ class MockStreamInfo : public StreamInfo { MOCK_METHOD(const absl::optional&, virtualClusterName, (), (const)); MOCK_METHOD(absl::optional, protocol, (), (const)); MOCK_METHOD(void, protocol, (Http::Protocol protocol)); - MOCK_METHOD(void, setDeferredLoggingHeadersAndTrailers, - (DeferredLoggingHeadersAndTrailers deferredLoggingHeadersAndTrailers)); - MOCK_METHOD(const absl::optional&, - deferredLoggingHeadersAndTrailers, (), (const)); MOCK_METHOD(absl::optional, responseCode, (), (const)); MOCK_METHOD(const absl::optional&, responseCodeDetails, (), (const)); MOCK_METHOD(const absl::optional&, connectionTerminationDetails, (), (const)); @@ -162,7 +158,6 @@ class MockStreamInfo : public StreamInfo { std::string filter_chain_name_; absl::optional attempt_count_; absl::optional virtual_cluster_name_; - absl::optional deferred_logging_headers_and_trailers_; DownstreamTiming downstream_timing_; }; From 9b31dcd30db1e24729eed8d7d1777cb030f21533 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Fri, 9 Dec 2022 18:09:44 +0000 Subject: [PATCH 38/59] QuicStatsGatherer logs on quic server stream close And ensure that we don't incorrectly add the final ack time. Signed-off-by: Paul Sohn --- .../common/quic/envoy_quic_server_stream.cc | 3 ++ source/common/quic/envoy_quic_server_stream.h | 2 + source/common/quic/quic_stats_gatherer.cc | 4 +- source/common/quic/quic_stats_gatherer.h | 4 +- .../quic/envoy_quic_server_stream_test.cc | 39 +++++++++++++++++++ 5 files changed, 49 insertions(+), 3 deletions(-) diff --git a/source/common/quic/envoy_quic_server_stream.cc b/source/common/quic/envoy_quic_server_stream.cc index 409acf470a86a..9c00143fb7f8b 100644 --- a/source/common/quic/envoy_quic_server_stream.cc +++ b/source/common/quic/envoy_quic_server_stream.cc @@ -388,6 +388,9 @@ void EnvoyQuicServerStream::OnClose() { return; } clearWatermarkBuffer(); + if (!stats_gatherer_->loggingDone()) { + stats_gatherer_->maybeDoDeferredLog(/* record_ack_timing */ false); + } stats_gatherer_ = nullptr; } diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index eabb568cd1c87..99841da68dd3d 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -87,6 +87,8 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, quic::QuicRstStreamErrorCode rst = quic::QUIC_BAD_APPLICATION_PAYLOAD) override; private: + friend class EnvoyQuicServerStreamTest; + QuicFilterManagerConnectionImpl* filterManagerConnection(); // Deliver awaiting trailers if body has been delivered. diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 778eb221f1329..f16d17d19c0e9 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -13,7 +13,7 @@ void QuicStatsGatherer::OnPacketAcked(int acked_bytes, } } -void QuicStatsGatherer::maybeDoDeferredLog() { +void QuicStatsGatherer::maybeDoDeferredLog(bool record_ack_timing) { logging_done_ = true; if (stream_info_ == nullptr) { return; @@ -21,7 +21,7 @@ void QuicStatsGatherer::maybeDoDeferredLog() { if (!deferred_logging_headers_and_trailers_.has_value()) { return; } - if (time_source_ != nullptr) { + if (time_source_ != nullptr && record_ack_timing) { stream_info_->downstreamTiming().onLastDownstreamAckReceived(*time_source_); } Http::DeferredLoggingHeadersAndTrailers headers_and_trailers = diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index 621905e7ee40c..feb8ab4bcea38 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -28,7 +28,7 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { fin_sent_ = end_stream; } // Log this stream using available stream info and access loggers. - void maybeDoDeferredLog(); + void maybeDoDeferredLog(bool record_ack_timing = true); // Add a pointer to stream info that should be logged. This can be overwritten // in case of an internal redirect. void setStreamInfo(std::shared_ptr stream_info) { @@ -45,6 +45,8 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { absl::make_optional( std::move(headers_and_trailers)); } + bool loggingDone() { return logging_done_; } + uint64_t bytesOutstanding() { return bytes_outstanding_; } private: uint64_t bytes_outstanding_ = 0; diff --git a/test/common/quic/envoy_quic_server_stream_test.cc b/test/common/quic/envoy_quic_server_stream_test.cc index 460c84757030d..0d2d3c71db4cd 100644 --- a/test/common/quic/envoy_quic_server_stream_test.cc +++ b/test/common/quic/envoy_quic_server_stream_test.cc @@ -11,9 +11,11 @@ #include "source/server/active_listener_base.h" #include "test/common/quic/test_utils.h" +#include "test/mocks/access_log/mocks.h" #include "test/mocks/http/mocks.h" #include "test/mocks/http/stream_decoder.h" #include "test/mocks/network/mocks.h" +#include "test/test_common/test_time.h" #include "test/test_common/utility.h" #include "gmock/gmock.h" @@ -101,6 +103,18 @@ class EnvoyQuicServerStreamTest : public testing::Test { } } + void setStatsGathererDetails(std::list access_loggers, + std::shared_ptr stream_info, + Http::DeferredLoggingHeadersAndTrailers headers_and_trailers) { + quic_stream_->stats_gatherer_->setAccessLogHandlers(access_loggers); + quic_stream_->stats_gatherer_->setStreamInfo(stream_info); + quic_stream_->stats_gatherer_->setDeferredLoggingHeadersAndTrailers(headers_and_trailers); + } + + uint64_t statsGathererBytesOutstanding() { + return quic_stream_->stats_gatherer_->bytesOutstanding(); + } + size_t receiveRequest(const std::string& payload, bool fin, size_t decoder_buffer_high_watermark) { EXPECT_CALL(stream_decoder_, decodeHeaders_(_, /*end_stream=*/false)) @@ -753,6 +767,31 @@ TEST_F(EnvoyQuicServerStreamTest, ConnectionCloseAfterEndStreamEncoded) { quic_stream_->encodeHeaders(response_headers_, /*end_stream=*/true); } +// Tests that when stream is cleaned up, QuicStatsGatherer executes any pending logs. +TEST_F(EnvoyQuicServerStreamTest, StatsGathererLogsOnStreamDestruction) { + + // Set up QuicStatsGatherer with required access logger, stream info, headers and trailers. + std::shared_ptr mock_logger(new NiceMock()); + std::list loggers = {mock_logger}; + Event::GlobalTimeSystem test_time_; + Envoy::StreamInfo::StreamInfoImpl s1(Http::Protocol::Http2, test_time_.timeSystem(), nullptr); + std::shared_ptr stream_info = + std::make_shared(s1); + Http::DeferredLoggingHeadersAndTrailers headers_and_trailers; + setStatsGathererDetails(loggers, stream_info, headers_and_trailers); + + receiveRequest(request_body_, false, request_body_.size() * 2); + quic_stream_->encodeHeaders(response_headers_, /*end_stream=*/true); + EXPECT_CALL(quic_session_, MaybeSendStopSendingFrame(_, _)); + EXPECT_CALL(stream_callbacks_, onResetStream(Http::StreamResetReason::LocalReset, _)); + // The stats gatherer has outstanding bytes that have not been acked. + EXPECT_GT(statsGathererBytesOutstanding(), 0); + // Close the stream; incoming acks will no longer invoke the stats gatherer but + // the stats gatherer should log on stream close despite not receiving final downstream ack. + EXPECT_CALL(*mock_logger, log(_, _, _, _)); + quic_stream_->resetStream(Http::StreamResetReason::LocalRefusedStreamReset); +} + TEST_F(EnvoyQuicServerStreamTest, MetadataNotSupported) { Http::MetadataMap metadata_map = {{"key", "value"}}; Http::MetadataMapPtr metadata_map_ptr = std::make_unique(metadata_map); From f5f469fe68579dafb561845a796b81483302ba13 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 12 Dec 2022 16:15:09 +0000 Subject: [PATCH 39/59] fix bad merge Signed-off-by: Paul Sohn --- source/common/http/http1/codec_impl.h | 1 - 1 file changed, 1 deletion(-) diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index 4ea5420a4d7f6..67d7cfd0aff03 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -155,7 +155,6 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { bool streamErrorOnInvalidHttpMessage() const override { return stream_error_on_invalid_http_message_; } - void setRequestDecoder(Http::RequestDecoder& /*decoder*/) override {} void setDeferredLoggingHeadersAndTrailers( Http::DeferredLoggingHeadersAndTrailers /*headers_and_trailers*/) override {} From 613f1c38e3fea659da394225d29335d4cef8b455 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Thu, 22 Dec 2022 21:36:01 +0000 Subject: [PATCH 40/59] Copy stream info for deferred logging instead of using shared ptr Here we revert the change of wrapping the active stream's stream info into a shared pointer. Instead, we copy the stream info to explicitly ensure that all members are properly copied or shared. Originally, we used a shared pointer to ensure that the stream info used in deferred logging could outlive the stream itself. However, at least one member of stream info is a raw pointer (request headers) and runs the risk of pointing at a destroyed object. In the current implementation, this would have been safe, but having stream info be a shared pointer opens us up to similar problems in the future. The explicit copy is a safeguard against that situation. Signed-off-by: Paul Sohn --- envoy/http/codec.h | 10 +-- .../formatter/substitution_formatter.cc | 28 +++++++ .../common/formatter/substitution_formatter.h | 20 +++++ source/common/http/conn_manager_impl.h | 13 +++- source/common/http/filter_manager.h | 15 ++-- source/common/http/http1/codec_impl.h | 3 +- source/common/http/http2/codec_impl.h | 3 +- source/common/quic/envoy_quic_server_stream.h | 5 +- source/common/quic/quic_stats_gatherer.cc | 13 ++-- source/common/quic/quic_stats_gatherer.h | 8 +- source/common/stream_info/BUILD | 1 + source/common/stream_info/stream_info_impl.h | 36 +++++++++ .../quic/envoy_quic_server_session_test.cc | 14 ---- .../quic/envoy_quic_server_stream_test.cc | 14 ++-- .../stream_info/stream_info_impl_test.cc | 66 ++++++++++++++++- test/integration/fake_upstream.h | 1 - .../integration/quic_http_integration_test.cc | 73 ++++++++++++++----- test/mocks/http/stream_decoder.h | 1 - 18 files changed, 237 insertions(+), 87 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 234988fc30384..fc909203aa62b 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -139,6 +139,7 @@ struct DeferredLoggingHeadersAndTrailers { Http::RequestHeaderMapSharedPtr request_header_map = nullptr; Http::ResponseHeaderMapSharedPtr response_header_map = nullptr; Http::ResponseTrailerMapSharedPtr response_trailer_map = nullptr; + std::unique_ptr stream_info = nullptr; }; /** @@ -186,8 +187,8 @@ class ResponseEncoder : public virtual StreamEncoder { * Set headers and trailers for deferred logging. * @param headers_and_trailers Headers and trailers from this stream. */ - virtual void - setDeferredLoggingHeadersAndTrailers(DeferredLoggingHeadersAndTrailers headers_and_trailers) PURE; + virtual void setDeferredLoggingHeadersAndTrailers( + DeferredLoggingHeadersAndTrailers& headers_and_trailers) PURE; }; /** @@ -251,11 +252,6 @@ class RequestDecoder : public virtual StreamDecoder { */ virtual StreamInfo::StreamInfo& streamInfo() PURE; - /** - * @return shared pointer to the stream_info for this stream. - */ - virtual std::shared_ptr streamInfoSharedPtr() PURE; - /** * @return List of shared pointers to access loggers for this stream. */ diff --git a/source/common/formatter/substitution_formatter.cc b/source/common/formatter/substitution_formatter.cc index fdc83c2ca29cc..9f781e31a868b 100644 --- a/source/common/formatter/substitution_formatter.cc +++ b/source/common/formatter/substitution_formatter.cc @@ -487,6 +487,17 @@ SubstitutionFormatParser::getKnownFormatters() { {CommandSyntaxChecker::PARAMS_REQUIRED | CommandSyntaxChecker::LENGTH_ALLOWED, [](const std::string& key, absl::optional& max_length) { return std::make_unique(key, max_length); + }}}, + {"STREAM_INFO_REQ", + {CommandSyntaxChecker::PARAMS_REQUIRED | CommandSyntaxChecker::LENGTH_ALLOWED, + [](const std::string& format, absl::optional& max_length) { + std::string main_header, alternative_header; + + SubstitutionFormatParser::parseSubcommandHeaders(format, main_header, + alternative_header); + + return std::make_unique(main_header, alternative_header, + max_length); }}}}); } @@ -2192,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 max_length) + : HeaderFormatter(main_header, alternative_header, max_length) {} + +absl::optional 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 diff --git a/source/common/formatter/substitution_formatter.h b/source/common/formatter/substitution_formatter.h index fc3be5fac2c6e..9f635f8ac444a 100644 --- a/source/common/formatter/substitution_formatter.h +++ b/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 max_length); + + // FormatterProvider + absl::optional 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 diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index d36f9a2ab2a50..52d5ec9e765e7 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -201,9 +201,6 @@ class ConnectionManagerImpl : Logger::Loggable, absl::string_view details) override { return filter_manager_.sendLocalReply(code, body, modify_headers, grpc_status, details); } - std::shared_ptr streamInfoSharedPtr() override { - return filter_manager_.streamInfoSharedPtr(); - } std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } @@ -218,7 +215,15 @@ class ConnectionManagerImpl : Logger::Loggable, if (responseTrailers()) { headers_and_trailers.response_trailer_map = response_trailers_; } - response_encoder_->setDeferredLoggingHeadersAndTrailers(std::move(headers_and_trailers)); + // Copy this stream's StreamInfo into the deferred logging object, ensuring that the request + // headers pointed to by the StreamInfo lives beyond stream destruction. + std::unique_ptr stream_info = + std::make_unique( + connection_manager_.codec_->protocol(), connection_manager_.time_source_, + connection_manager_.read_callbacks_->connection().connectionInfoProviderSharedPtr()); + stream_info->setFrom(streamInfo(), request_headers_.get()); + headers_and_trailers.stream_info = std::move(stream_info); + response_encoder_->setDeferredLoggingHeadersAndTrailers(headers_and_trailers); } // ScopeTrackedObject diff --git a/source/common/http/filter_manager.h b/source/common/http/filter_manager.h index 6a0005517bffa..6b14b2d52a0b6 100644 --- a/source/common/http/filter_manager.h +++ b/source/common/http/filter_manager.h @@ -1035,20 +1035,17 @@ class DownstreamFilterManager : public FilterManager { StreamInfo::FilterState::LifeSpan filter_state_life_span) : FilterManager(filter_manager_callbacks, dispatcher, connection, stream_id, account, proxy_100_continue, buffer_limit, filter_chain_factory), - stream_info_(std::make_shared( - protocol, time_source, connection.connectionInfoProviderSharedPtr(), - parent_filter_state, filter_state_life_span)), + stream_info_(protocol, time_source, connection.connectionInfoProviderSharedPtr(), + parent_filter_state, filter_state_life_span), local_reply_(local_reply) {} // TODO(snowp): This should probably return a StreamInfo instead of the impl. - StreamInfo::StreamInfoImpl& streamInfo() override { return *stream_info_; } - const StreamInfo::StreamInfoImpl& streamInfo() const override { return *stream_info_; } - - std::shared_ptr streamInfoSharedPtr() { return stream_info_; } + StreamInfo::StreamInfoImpl& streamInfo() override { return stream_info_; } + const StreamInfo::StreamInfoImpl& streamInfo() const override { return stream_info_; } void setDownstreamRemoteAddress( const Network::Address::InstanceConstSharedPtr& downstream_remote_address) { - stream_info_->setDownstreamRemoteAddress(downstream_remote_address); + stream_info_.setDownstreamRemoteAddress(downstream_remote_address); } /** @@ -1092,7 +1089,7 @@ class DownstreamFilterManager : public FilterManager { const absl::optional grpc_status); private: - std::shared_ptr stream_info_; + OverridableRemoteConnectionInfoSetterStreamInfo stream_info_; const LocalReply::LocalReply& local_reply_; }; diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index 67d7cfd0aff03..24f6f6873f20e 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -155,8 +155,7 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { bool streamErrorOnInvalidHttpMessage() const override { return stream_error_on_invalid_http_message_; } - void setDeferredLoggingHeadersAndTrailers( - Http::DeferredLoggingHeadersAndTrailers /*headers_and_trailers*/) override {} + void setDeferredLoggingHeadersAndTrailers(Http::DeferredLoggingHeadersAndTrailers&) 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 diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 057ce1258ae1e..1dae802230f81 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -498,8 +498,7 @@ class ConnectionImpl : public virtual Connection, encodeTrailersBase(trailers); } void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; } - void setDeferredLoggingHeadersAndTrailers( - Http::DeferredLoggingHeadersAndTrailers /*headers_and_trailers*/) override {} + void setDeferredLoggingHeadersAndTrailers(Http::DeferredLoggingHeadersAndTrailers&) override {} // ScopeTrackedObject void dumpState(std::ostream& os, int indent_level) const override; diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index 99841da68dd3d..98f336cc8fef8 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -22,7 +22,6 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; - stats_gatherer_->setStreamInfo(request_decoder_->streamInfoSharedPtr()); stats_gatherer_->setAccessLogHandlers(request_decoder_->accessLogHandlers()); } @@ -39,8 +38,8 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, return http3_options_.override_stream_error_on_invalid_http_message().value(); } void setDeferredLoggingHeadersAndTrailers( - Http::DeferredLoggingHeadersAndTrailers headers_and_trailers) override { - stats_gatherer_->setDeferredLoggingHeadersAndTrailers(std::move(headers_and_trailers)); + Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers) override { + stats_gatherer_->setDeferredLoggingHeadersAndTrailers(headers_and_trailers); }; // Http::Stream diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index f16d17d19c0e9..89c69da575e94 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -15,22 +15,23 @@ void QuicStatsGatherer::OnPacketAcked(int acked_bytes, void QuicStatsGatherer::maybeDoDeferredLog(bool record_ack_timing) { logging_done_ = true; - if (stream_info_ == nullptr) { + if (!deferred_logging_headers_and_trailers_.has_value()) { return; } - if (!deferred_logging_headers_and_trailers_.has_value()) { + Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers = + deferred_logging_headers_and_trailers_.value(); + if (headers_and_trailers.stream_info == nullptr) { return; } if (time_source_ != nullptr && record_ack_timing) { - stream_info_->downstreamTiming().onLastDownstreamAckReceived(*time_source_); + headers_and_trailers.stream_info->downstreamTiming().onLastDownstreamAckReceived(*time_source_); } - Http::DeferredLoggingHeadersAndTrailers headers_and_trailers = - deferred_logging_headers_and_trailers_.value(); auto request_headers = headers_and_trailers.request_header_map.get(); auto response_headers = headers_and_trailers.response_header_map.get(); auto response_trailers = headers_and_trailers.response_trailer_map.get(); for (const auto& log_handler : access_log_handlers_) { - log_handler->log(request_headers, response_headers, response_trailers, *stream_info_); + log_handler->log(request_headers, response_headers, response_trailers, + *headers_and_trailers.stream_info); } } diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index feb8ab4bcea38..a318cacd314b3 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -29,18 +29,13 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { } // Log this stream using available stream info and access loggers. void maybeDoDeferredLog(bool record_ack_timing = true); - // Add a pointer to stream info that should be logged. This can be overwritten - // in case of an internal redirect. - void setStreamInfo(std::shared_ptr stream_info) { - stream_info_ = stream_info; - } // Set list of pointers to access loggers. void setAccessLogHandlers(std::list handlers) { access_log_handlers_ = handlers; } // Set headers and trailers used for deferred logging. void setDeferredLoggingHeadersAndTrailers( - Http::DeferredLoggingHeadersAndTrailers headers_and_trailers) { + Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers) { deferred_logging_headers_and_trailers_ = absl::make_optional( std::move(headers_and_trailers)); @@ -51,7 +46,6 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { private: uint64_t bytes_outstanding_ = 0; bool fin_sent_ = false; - std::shared_ptr stream_info_ = nullptr; std::list access_log_handlers_{}; // Headers and trailers required for deferred logging. nullopt indicates that deferred logging // should be skipped. diff --git a/source/common/stream_info/BUILD b/source/common/stream_info/BUILD index 1dc253ab6c5fe..417a23230b101 100644 --- a/source/common/stream_info/BUILD +++ b/source/common/stream_info/BUILD @@ -13,6 +13,7 @@ envoy_cc_library( hdrs = ["stream_info_impl.h"], deps = [ ":filter_state_lib", + ":stream_id_provider_lib", "//envoy/http:request_id_extension_interface", "//envoy/stream_info:stream_info_interface", "//source/common/common:assert_lib", diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index 9cf98fa380120..33821ea2b5940 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -17,6 +17,7 @@ #include "source/common/common/utility.h" #include "source/common/network/socket_impl.h" #include "source/common/stream_info/filter_state_impl.h" +#include "source/common/stream_info/stream_id_provider_impl.h" #include "absl/strings/str_replace.h" @@ -336,6 +337,41 @@ struct StreamInfoImpl : public StreamInfo { start_time_monotonic_ = info.startTimeMonotonic(); } + // This function is used to copy over every field exposed in the StreamInfo interface, with a + // couple of exceptions noted below. Note that setFromForRecreateStream is reused here. + // * request_headers_ is a raw pointer; to avoid pointer lifetime issues, a request header pointer + // is required to be passed in here. + // * downstream_connection_info_provider_ is always set in the ctor. + void setFrom(StreamInfo& info, Http::RequestHeaderMap* request_headers) { + setFromForRecreateStream(info); + route_name_ = info.getRouteName(); + virtual_cluster_name_ = info.virtualClusterName(); + response_code_ = info.responseCode(); + response_code_details_ = info.responseCodeDetails(); + connection_termination_details_ = info.connectionTerminationDetails(); + upstream_info_ = info.upstreamInfo(); + if (info.requestComplete().has_value()) { + // derive final time from other info's complete duration and start time. + final_time_ = info.startTimeMonotonic() + info.requestComplete().value(); + } + response_flags_ = info.responseFlags(); + health_check_request_ = info.healthCheck(); + route_ = info.route(); + metadata_ = info.dynamicMetadata(); + filter_state_ = info.filterState(); + request_headers_ = request_headers; + upstream_cluster_info_ = info.upstreamClusterInfo(); + auto stream_id_provider = info.getStreamIdProvider(); + if (stream_id_provider.has_value() && stream_id_provider->toStringView().has_value()) { + std::string id{stream_id_provider->toStringView().value()}; + stream_id_provider_ = std::make_shared(std::move(id)); + } + trace_reason_ = info.traceReason(); + filter_chain_name_ = info.filterChainName(); + attempt_count_ = info.attemptCount(); + upstream_bytes_meter_ = info.getUpstreamBytesMeter(); + } + void setIsShadow(bool is_shadow) { is_shadow_ = is_shadow; } bool isShadow() const override { return is_shadow_; } diff --git a/test/common/quic/envoy_quic_server_session_test.cc b/test/common/quic/envoy_quic_server_session_test.cc index 37c21c6802493..85e90671ec021 100644 --- a/test/common/quic/envoy_quic_server_session_test.cc +++ b/test/common/quic/envoy_quic_server_session_test.cc @@ -294,7 +294,6 @@ TEST_F(EnvoyQuicServerSessionTest, NewStream) { Http::MockRequestDecoder request_decoder; EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(testing::ReturnRef(request_decoder)); - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStreamId stream_id = 4u; auto stream = @@ -357,7 +356,6 @@ TEST_F(EnvoyQuicServerSessionTest, OnResetFrameIetfQuic) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()).Times(3); EXPECT_CALL(request_decoder, accessLogHandlers()).Times(3); auto stream1 = dynamic_cast(createNewStream(request_decoder, stream_callbacks)); @@ -442,7 +440,6 @@ TEST_F(EnvoyQuicServerSessionTest, ConnectionCloseWithActiveStream) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); EXPECT_CALL(*quic_connection_, @@ -459,7 +456,6 @@ TEST_F(EnvoyQuicServerSessionTest, RemoteConnectionCloseWithActiveStream) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); EXPECT_CALL(network_connection_callbacks_, onEvent(Network::ConnectionEvent::RemoteClose)); @@ -478,7 +474,6 @@ TEST_F(EnvoyQuicServerSessionTest, NoFlushWithDataToWrite) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); envoy_quic_session_.MarkConnectionLevelWriteBlocked(stream->id()); @@ -497,7 +492,6 @@ TEST_F(EnvoyQuicServerSessionTest, FlushCloseWithDataToWrite) { installReadFilter(); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); @@ -538,7 +532,6 @@ TEST_F(EnvoyQuicServerSessionTest, WriteUpdatesDelayCloseTimer) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); // Create a stream and write enough data to make it blocked. auto stream = @@ -639,7 +632,6 @@ TEST_F(EnvoyQuicServerSessionTest, FlushCloseNoTimeout) { Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); // Create a stream and write enough data to make it blocked. auto stream = @@ -703,7 +695,6 @@ TEST_F(EnvoyQuicServerSessionTest, FlushCloseWithTimeout) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); @@ -736,7 +727,6 @@ TEST_F(EnvoyQuicServerSessionTest, FlushAndWaitForCloseWithTimeout) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); @@ -768,7 +758,6 @@ TEST_F(EnvoyQuicServerSessionTest, FlusWriteTransitToFlushWriteWithDelay) { envoy_quic_session_.setDelayedCloseTimeout(std::chrono::milliseconds(100)); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); quic::QuicStream* stream = createNewStream(request_decoder, stream_callbacks); @@ -886,7 +875,6 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { installReadFilter(); Http::MockRequestDecoder request_decoder; Http::MockStreamCallbacks stream_callbacks; - EXPECT_CALL(request_decoder, streamInfoSharedPtr()); EXPECT_CALL(request_decoder, accessLogHandlers()); EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(Invoke([&request_decoder, &stream_callbacks](Http::ResponseEncoder& encoder, @@ -931,7 +919,6 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { // send buffer watermark. Http::MockRequestDecoder request_decoder2; Http::MockStreamCallbacks stream_callbacks2; - EXPECT_CALL(request_decoder2, streamInfoSharedPtr()); EXPECT_CALL(request_decoder2, accessLogHandlers()); EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(Invoke([&request_decoder2, &stream_callbacks2](Http::ResponseEncoder& encoder, @@ -963,7 +950,6 @@ TEST_F(EnvoyQuicServerSessionTest, SendBufferWatermark) { // high watermark reached upon creation. Http::MockRequestDecoder request_decoder3; Http::MockStreamCallbacks stream_callbacks3; - EXPECT_CALL(request_decoder3, streamInfoSharedPtr()); EXPECT_CALL(request_decoder3, accessLogHandlers()); EXPECT_CALL(http_connection_callbacks_, newStream(_, false)) .WillOnce(Invoke([&request_decoder3, &stream_callbacks3](Http::ResponseEncoder& encoder, diff --git a/test/common/quic/envoy_quic_server_stream_test.cc b/test/common/quic/envoy_quic_server_stream_test.cc index 0d2d3c71db4cd..e0ec10292ab8d 100644 --- a/test/common/quic/envoy_quic_server_stream_test.cc +++ b/test/common/quic/envoy_quic_server_stream_test.cc @@ -54,7 +54,6 @@ class EnvoyQuicServerStreamTest : public testing::Test { envoy::config::core::v3::HttpProtocolOptions::ALLOW)), response_headers_{{":status", "200"}, {"response-key", "response-value"}}, response_trailers_{{"trailer-key", "trailer-value"}} { - EXPECT_CALL(stream_decoder_, streamInfoSharedPtr()); EXPECT_CALL(stream_decoder_, accessLogHandlers()); quic_stream_->setRequestDecoder(stream_decoder_); quic_stream_->addCallbacks(stream_callbacks_); @@ -104,10 +103,8 @@ class EnvoyQuicServerStreamTest : public testing::Test { } void setStatsGathererDetails(std::list access_loggers, - std::shared_ptr stream_info, - Http::DeferredLoggingHeadersAndTrailers headers_and_trailers) { + Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers) { quic_stream_->stats_gatherer_->setAccessLogHandlers(access_loggers); - quic_stream_->stats_gatherer_->setStreamInfo(stream_info); quic_stream_->stats_gatherer_->setDeferredLoggingHeadersAndTrailers(headers_and_trailers); } @@ -774,11 +771,12 @@ TEST_F(EnvoyQuicServerStreamTest, StatsGathererLogsOnStreamDestruction) { std::shared_ptr mock_logger(new NiceMock()); std::list loggers = {mock_logger}; Event::GlobalTimeSystem test_time_; - Envoy::StreamInfo::StreamInfoImpl s1(Http::Protocol::Http2, test_time_.timeSystem(), nullptr); - std::shared_ptr stream_info = - std::make_shared(s1); + std::unique_ptr stream_info = + std::make_unique(Http::Protocol::Http2, + test_time_.timeSystem(), nullptr); Http::DeferredLoggingHeadersAndTrailers headers_and_trailers; - setStatsGathererDetails(loggers, stream_info, headers_and_trailers); + headers_and_trailers.stream_info = std::move(stream_info); + setStatsGathererDetails(loggers, headers_and_trailers); receiveRequest(request_body_, false, request_body_.size() * 2); quic_stream_->encodeHeaders(response_headers_, /*end_stream=*/true); diff --git a/test/common/stream_info/stream_info_impl_test.cc b/test/common/stream_info/stream_info_impl_test.cc index 7969d82fc6f6d..9591105fa9d8a 100644 --- a/test/common/stream_info/stream_info_impl_test.cc +++ b/test/common/stream_info/stream_info_impl_test.cc @@ -6,6 +6,7 @@ #include "envoy/upstream/host_description.h" #include "source/common/common/fmt.h" +#include "source/common/network/address_impl.h" #include "source/common/protobuf/utility.h" #include "source/common/stream_info/stream_id_provider_impl.h" #include "source/common/stream_info/stream_info_impl.h" @@ -231,22 +232,51 @@ TEST_F(StreamInfoImplTest, MiscSettersAndGetters) { TEST_F(StreamInfoImplTest, SetFrom) { StreamInfoImpl s1(Http::Protocol::Http2, test_time_.timeSystem(), nullptr); + // For testing setFromForRecreateStream s1.addBytesReceived(1); s1.downstreamTiming().onLastDownstreamRxByteReceived(test_time_.timeSystem()); + // For testing setFrom + s1.setRouteName("foo"); + s1.setVirtualClusterName(absl::optional("bar")); + s1.setResponseCode(200); + s1.setResponseCodeDetails("OK"); + s1.setConnectionTerminationDetails("baz"); + s1.setUpstreamInfo(std::make_shared()); + s1.upstreamInfo()->upstreamTiming().onLastUpstreamTxByteSent(test_time_.timeSystem()); + s1.onRequestComplete(); + s1.setResponseFlag(FailedLocalHealthCheck); + s1.healthCheck(true); + s1.route_ = std::make_shared>(); + s1.setDynamicMetadata("com.test", MessageUtil::keyValueStruct("test_key", "test_value")); + s1.filterState()->setData("test", std::make_unique(1), + FilterState::StateType::ReadOnly, FilterState::LifeSpan::FilterChain); + Http::TestRequestHeaderMapImpl headers1; + s1.setRequestHeaders(headers1); + Upstream::ClusterInfoConstSharedPtr cluster_info(new NiceMock()); + s1.setUpstreamClusterInfo(cluster_info); + s1.setStreamIdProvider( + std::make_shared("a121e9e1-feae-4136-9e0e-6fac343d56c9")); + s1.setTraceReason(Tracing::Reason::ClientForced); + s1.setFilterChainName("foobar"); + s1.setAttemptCount(5); + #ifdef __clang__ #if defined(__linux__) #if defined(__has_feature) && !(__has_feature(thread_sanitizer)) - ASSERT_TRUE(sizeof(s1) == 856 || sizeof(s1) == 872 || sizeof(s1) == 896) + ASSERT_TRUE(sizeof(s1) == 840) << "If adding fields to StreamInfoImpl, please check to see if you " - "need to add them to setFromForRecreateStream! Current size " + "need to add them to setFromForRecreateStream or setFrom! Current size " << sizeof(s1); #endif #endif #endif StreamInfoImpl s2(Http::Protocol::Http11, test_time_.timeSystem(), nullptr); - s2.setFromForRecreateStream(s1); + Http::TestRequestHeaderMapImpl headers2; + s2.setFrom(s1, &headers2); + + // Copied by setFromForRecreateStream EXPECT_EQ(s1.startTime(), s2.startTime()); EXPECT_EQ(s1.startTimeMonotonic(), s2.startTimeMonotonic()); EXPECT_EQ(s1.downstreamTiming().lastDownstreamRxByteReceived(), @@ -254,6 +284,36 @@ TEST_F(StreamInfoImplTest, SetFrom) { EXPECT_EQ(s1.protocol(), s2.protocol()); EXPECT_EQ(s1.bytesReceived(), s2.bytesReceived()); EXPECT_EQ(s1.getDownstreamBytesMeter(), s2.getDownstreamBytesMeter()); + + // Copied by setFrom + EXPECT_EQ(s1.getRouteName(), s2.getRouteName()); + EXPECT_EQ(s1.virtualClusterName(), s2.virtualClusterName()); + EXPECT_EQ(s1.responseCode(), s2.responseCode()); + EXPECT_EQ(s1.responseCodeDetails(), s2.responseCodeDetails()); + EXPECT_EQ(s1.connectionTerminationDetails(), s2.connectionTerminationDetails()); + EXPECT_EQ(s1.upstreamInfo()->upstreamTiming().last_upstream_tx_byte_sent_, + s2.upstreamInfo()->upstreamTiming().last_upstream_tx_byte_sent_); + EXPECT_EQ(s1.requestComplete(), s2.requestComplete()); + EXPECT_EQ(s1.responseFlags(), s2.responseFlags()); + EXPECT_EQ(s1.healthCheck(), s2.healthCheck()); + EXPECT_NE(s1.route(), nullptr); + EXPECT_EQ(s1.route(), s2.route()); + EXPECT_EQ( + Config::Metadata::metadataValue(&s1.dynamicMetadata(), "com.test", "test_key").string_value(), + Config::Metadata::metadataValue(&s2.dynamicMetadata(), "com.test", "test_key") + .string_value()); + EXPECT_EQ(s1.filterState()->getDataReadOnly("test")->access(), + s2.filterState()->getDataReadOnly("test")->access()); + EXPECT_EQ(*s1.getRequestHeaders(), headers1); + EXPECT_EQ(*s2.getRequestHeaders(), headers2); + EXPECT_TRUE(s2.upstreamClusterInfo().has_value()); + EXPECT_EQ(s1.upstreamClusterInfo(), s2.upstreamClusterInfo()); + EXPECT_EQ(s1.getStreamIdProvider().value().get().toStringView().value(), + s2.getStreamIdProvider().value().get().toStringView().value()); + EXPECT_EQ(s1.traceReason(), s2.traceReason()); + EXPECT_EQ(s1.filterChainName(), s2.filterChainName()); + EXPECT_EQ(s1.attemptCount(), s2.attemptCount()); + EXPECT_EQ(s1.getUpstreamBytesMeter(), s2.getUpstreamBytesMeter()); } TEST_F(StreamInfoImplTest, DynamicMetadataTest) { diff --git a/test/integration/fake_upstream.h b/test/integration/fake_upstream.h index 6e1a324b30d4b..fba183fdffb8a 100644 --- a/test/integration/fake_upstream.h +++ b/test/integration/fake_upstream.h @@ -225,7 +225,6 @@ class FakeStream : public Http::RequestDecoder, RELEASE_ASSERT(false, "initialize if this is needed"); return *stream_info_; } - std::shared_ptr streamInfoSharedPtr() override { return stream_info_; } std::list accessLogHandlers() override { return access_log_handlers_; } diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index 64af3820b326b..74408add496a4 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1168,8 +1168,13 @@ TEST_P(QuicHttpIntegrationTest, MultipleNetworkFilters) { } TEST_P(QuicHttpIntegrationTest, DeferredLogging) { - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" - "CODE%,%BYTES_RECEIVED%"); + 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)%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); sendRequestAndWaitForResponse(default_request_headers_, /*request_size=*/0, @@ -1181,20 +1186,28 @@ TEST_P(QuicHttpIntegrationTest, DeferredLogging) { std::string log = waitForAccessLog(access_log_name_); std::vector metrics = absl::StrSplit(log, ","); - ASSERT_EQ(metrics.size(), 6); + ASSERT_EQ(metrics.size(), 21); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); EXPECT_GT(/* ROUNDTRIP_DURATION */ std::stoi(metrics.at(1)), 0); EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); + // 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)); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingDisabled) { config_helper_.addRuntimeOverride("envoy.reloadable_features.quic_defer_logging_to_ack_listener", "false"); - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" - "CODE%,%BYTES_RECEIVED%"); + 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)%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); sendRequestAndWaitForResponse(default_request_headers_, /*request_size=*/0, @@ -1206,18 +1219,24 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingDisabled) { // Do not flush client acks. std::string log = waitForAccessLog(access_log_name_, 0, false, nullptr); std::vector metrics = absl::StrSplit(log, ","); - ASSERT_EQ(metrics.size(), 6); + ASSERT_EQ(metrics.size(), 21); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); + EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" - "CODE%,%BYTES_RECEIVED%"); + 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)%"); initialize(); codec_client_ = makeHttpConnection(makeClientConnection(lookupPort("http"))); auto response = codec_client_->makeHeaderOnlyRequest(default_request_headers_); @@ -1228,18 +1247,24 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { std::string log = waitForAccessLog(access_log_name_); std::vector metrics = absl::StrSplit(log, ","); - ASSERT_EQ(metrics.size(), 6); + ASSERT_EQ(metrics.size(), 21); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); EXPECT_EQ(/* RESPONSE_DURATION */ metrics.at(3), "-"); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "0"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); + EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithQuicReset) { - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" - "CODE%,%BYTES_RECEIVED%"); + 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)%"); initialize(); codec_client_ = makeHttpConnection(lookupPort("http")); @@ -1255,18 +1280,24 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithQuicReset) { std::string log = waitForAccessLog(access_log_name_); std::vector metrics = absl::StrSplit(log, ","); - ASSERT_EQ(metrics.size(), 6); + ASSERT_EQ(metrics.size(), 21); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); EXPECT_EQ(/* REQUEST_DURATION */ metrics.at(2), "-"); EXPECT_EQ(/* RESPONSE_DURATION */ metrics.at(3), "-"); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "400"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); + EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); } TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { - useAccessLog("%PROTOCOL%,%ROUNDTRIP_DURATION%,%REQUEST_DURATION%,%RESPONSE_DURATION%,%RESPONSE_" - "CODE%,%BYTES_RECEIVED%,%RESPONSE_CODE_DETAILS%,%RESP(test-header)%"); + 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)%,%RESP(test-header)%"); auto handle = config_helper_.createVirtualHost("handle.internal.redirect"); handle.mutable_routes(0)->set_name("redirect"); handle.mutable_routes(0)->mutable_route()->mutable_internal_redirect_policy(); @@ -1291,7 +1322,7 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { upstream_request_->encodeHeaders(redirect_response, true); std::string log = waitForAccessLog(access_log_name_, 0); std::vector metrics = absl::StrSplit(log, ","); - ASSERT_EQ(metrics.size(), 8); + ASSERT_EQ(metrics.size(), 22); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); // no roundtrip duration for internal redirect. EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); @@ -1299,8 +1330,9 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "302"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); - EXPECT_EQ(/* RESPONSE_CODE_DETAILS */ metrics.at(6), "internal_redirect"); - EXPECT_EQ(/* RESP(test-header) */ metrics.at(7), "test-header-value"); + EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); + EXPECT_EQ(/* RESPONSE_CODE_DETAILS */ metrics.at(8), "internal_redirect"); + EXPECT_EQ(/* RESP(test-header) */ metrics.at(21), "test-header-value"); waitForNextUpstreamRequest(); ASSERT(upstream_request_->headers().EnvoyOriginalUrl() != nullptr); @@ -1322,7 +1354,7 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { log = waitForAccessLog(access_log_name_, 1); metrics = absl::StrSplit(log, ","); - ASSERT_EQ(metrics.size(), 8); + ASSERT_EQ(metrics.size(), 22); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); // roundtrip duration populated on final log. EXPECT_GT(/* ROUNDTRIP_DURATION */ std::stoi(metrics.at(1)), 0); @@ -1330,9 +1362,10 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); - EXPECT_EQ(/* RESPONSE_CODE_DETAILS */ metrics.at(6), "via_upstream"); + EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); + EXPECT_EQ(/* RESPONSE_CODE_DETAILS */ metrics.at(8), "via_upstream"); // no test header - EXPECT_EQ(/* RESP(test-header) */ metrics.at(7), "-"); + EXPECT_EQ(/* RESP(test-header) */ metrics.at(21), "-"); } class QuicInplaceLdsIntegrationTest : public QuicHttpIntegrationTest { diff --git a/test/mocks/http/stream_decoder.h b/test/mocks/http/stream_decoder.h index d9101fc73271e..30e2ccf8a5a9f 100644 --- a/test/mocks/http/stream_decoder.h +++ b/test/mocks/http/stream_decoder.h @@ -31,7 +31,6 @@ class MockRequestDecoder : public RequestDecoder { // Http::RequestDecoder MOCK_METHOD(void, decodeHeaders_, (RequestHeaderMapSharedPtr & headers, bool end_stream)); MOCK_METHOD(void, decodeTrailers_, (RequestTrailerMapPtr & trailers)); - MOCK_METHOD(std::shared_ptr, streamInfoSharedPtr, ()); MOCK_METHOD(std::list, accessLogHandlers, ()); }; From 8fc038494eba70d44c89da0bf66d22cc7a68e3f3 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Thu, 22 Dec 2022 22:03:20 +0000 Subject: [PATCH 41/59] add new ResponseEncoder method to DirectStreamCallbacks Signed-off-by: Paul Sohn --- mobile/library/common/http/client.h | 1 + 1 file changed, 1 insertion(+) diff --git a/mobile/library/common/http/client.h b/mobile/library/common/http/client.h index 4a2d459df034c..b697aea1f8545 100644 --- a/mobile/library/common/http/client.h +++ b/mobile/library/common/http/client.h @@ -164,6 +164,7 @@ class Client : public Logger::Loggable { } bool streamErrorOnInvalidHttpMessage() const override { return false; } void setRequestDecoder(RequestDecoder& /*decoder*/) override{}; + void setDeferredLoggingHeadersAndTrailers(Http::DeferredLoggingHeadersAndTrailers&) override {} void encodeMetadata(const MetadataMapVector&) override { PANIC("not implemented"); } From 826b1439c726616e168ff092463fca62575d1a96 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Fri, 23 Dec 2022 20:13:37 +0000 Subject: [PATCH 42/59] udpate MockResponseEncoder Signed-off-by: Paul Sohn --- test/mocks/http/stream_encoder.h | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/mocks/http/stream_encoder.h b/test/mocks/http/stream_encoder.h index efe3626af3ab7..d142b2fe23e73 100644 --- a/test/mocks/http/stream_encoder.h +++ b/test/mocks/http/stream_encoder.h @@ -49,6 +49,8 @@ class MockResponseEncoder : public ResponseEncoder { MOCK_METHOD(void, encodeHeaders, (const ResponseHeaderMap& headers, bool end_stream)); MOCK_METHOD(void, encodeTrailers, (const ResponseTrailerMap& trailers)); MOCK_METHOD(void, setRequestDecoder, (RequestDecoder & decoder)); + MOCK_METHOD(void, setDeferredLoggingHeadersAndTrailers, + (DeferredLoggingHeadersAndTrailers & headers_and_trailers)); // Http::StreamEncoder MOCK_METHOD(void, encodeData, (Buffer::Instance & data, bool end_stream)); From 148e199176cb1a84faf25752a6b744b4c932ee45 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 3 Jan 2023 16:17:45 +0000 Subject: [PATCH 43/59] update SetFrom test streaminfo sizes Signed-off-by: Paul Sohn --- test/common/stream_info/stream_info_impl_test.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/common/stream_info/stream_info_impl_test.cc b/test/common/stream_info/stream_info_impl_test.cc index 9591105fa9d8a..ce6bdcc80ff49 100644 --- a/test/common/stream_info/stream_info_impl_test.cc +++ b/test/common/stream_info/stream_info_impl_test.cc @@ -264,7 +264,7 @@ TEST_F(StreamInfoImplTest, SetFrom) { #ifdef __clang__ #if defined(__linux__) #if defined(__has_feature) && !(__has_feature(thread_sanitizer)) - ASSERT_TRUE(sizeof(s1) == 840) + ASSERT_TRUE(sizeof(s1) == 800 || sizeof(s1) == 816 || sizeof(s1) == 840) << "If adding fields to StreamInfoImpl, please check to see if you " "need to add them to setFromForRecreateStream or setFrom! Current size " << sizeof(s1); From f19f6f23036747da6138d695d6f2c13c954aa3dd Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 3 Jan 2023 16:46:09 +0000 Subject: [PATCH 44/59] fix flaky QuicHttpIntegrationTests for deferred logging Signed-off-by: Paul Sohn --- test/integration/quic_http_integration_test.cc | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/test/integration/quic_http_integration_test.cc b/test/integration/quic_http_integration_test.cc index 74408add496a4..f460758e5b63f 100644 --- a/test/integration/quic_http_integration_test.cc +++ b/test/integration/quic_http_integration_test.cc @@ -1189,8 +1189,8 @@ TEST_P(QuicHttpIntegrationTest, DeferredLogging) { ASSERT_EQ(metrics.size(), 21); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); EXPECT_GT(/* ROUNDTRIP_DURATION */ std::stoi(metrics.at(1)), 0); - EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); - EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_GE(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GE(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); // Ensure that request headers from top-level access logger parameter and stream info are @@ -1222,8 +1222,8 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingDisabled) { ASSERT_EQ(metrics.size(), 21); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); - EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); - EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_GE(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GE(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); @@ -1250,7 +1250,7 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithReset) { ASSERT_EQ(metrics.size(), 21); EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); - EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GE(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); EXPECT_EQ(/* RESPONSE_DURATION */ metrics.at(3), "-"); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "0"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); @@ -1326,8 +1326,8 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); // no roundtrip duration for internal redirect. EXPECT_EQ(/* ROUNDTRIP_DURATION */ metrics.at(1), "-"); - EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); - EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_GE(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GE(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "302"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); @@ -1358,8 +1358,8 @@ TEST_P(QuicHttpIntegrationTest, DeferredLoggingWithInternalRedirect) { EXPECT_EQ(/* PROTOCOL */ metrics.at(0), "HTTP/3"); // roundtrip duration populated on final log. EXPECT_GT(/* ROUNDTRIP_DURATION */ std::stoi(metrics.at(1)), 0); - EXPECT_GT(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); - EXPECT_GT(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); + EXPECT_GE(/* REQUEST_DURATION */ std::stoi(metrics.at(2)), 0); + EXPECT_GE(/* RESPONSE_DURATION */ std::stoi(metrics.at(3)), 0); EXPECT_EQ(/* RESPONSE_CODE */ metrics.at(4), "200"); EXPECT_EQ(/* BYTES_RECEIVED */ metrics.at(5), "0"); EXPECT_EQ(/* request headers */ metrics.at(19), metrics.at(20)); From 9faa8274c72ceaeed9e287c4446c7d988e1abc41 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Thu, 5 Jan 2023 16:40:53 +0000 Subject: [PATCH 45/59] move a comment for code coverage Signed-off-by: Paul Sohn --- source/common/http/conn_manager_impl.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 52d5ec9e765e7..ec26c721a65b8 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -204,6 +204,8 @@ class ConnectionManagerImpl : Logger::Loggable, std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } + // Copy this stream's StreamInfo into the deferred logging object, ensuring that the request + // headers pointed to by the StreamInfo lives beyond stream destruction. void deferHeadersAndTrailers() { Http::DeferredLoggingHeadersAndTrailers headers_and_trailers; if (requestHeaders()) { @@ -215,8 +217,6 @@ class ConnectionManagerImpl : Logger::Loggable, if (responseTrailers()) { headers_and_trailers.response_trailer_map = response_trailers_; } - // Copy this stream's StreamInfo into the deferred logging object, ensuring that the request - // headers pointed to by the StreamInfo lives beyond stream destruction. std::unique_ptr stream_info = std::make_unique( connection_manager_.codec_->protocol(), connection_manager_.time_source_, From 39d9c7ab2620d523f9b568997c896e9bd7318232 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Fri, 6 Jan 2023 19:33:02 +0000 Subject: [PATCH 46/59] Remove intermediate deferred logging object Signed-off-by: Paul Sohn --- envoy/http/codec.h | 21 ++++++++--------- mobile/library/common/http/client.h | 5 +++- source/common/http/conn_manager_impl.h | 16 +++---------- source/common/http/http1/codec_impl.h | 5 +++- source/common/http/http2/codec_impl.h | 5 +++- source/common/quic/envoy_quic_server_stream.h | 11 +++++---- source/common/quic/quic_stats_gatherer.cc | 18 +++++---------- source/common/quic/quic_stats_gatherer.h | 23 +++++++++++-------- .../quic/envoy_quic_server_stream_test.cc | 18 ++++----------- test/mocks/http/stream_encoder.h | 5 +++- 10 files changed, 60 insertions(+), 67 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index fc909203aa62b..59777d9a5d9b5 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -135,13 +135,6 @@ class RequestEncoder : public virtual StreamEncoder { virtual void enableTcpTunneling() PURE; }; -struct DeferredLoggingHeadersAndTrailers { - Http::RequestHeaderMapSharedPtr request_header_map = nullptr; - Http::ResponseHeaderMapSharedPtr response_header_map = nullptr; - Http::ResponseTrailerMapSharedPtr response_trailer_map = nullptr; - std::unique_ptr stream_info = nullptr; -}; - /** * Stream encoder used for sending a response (server to client). Virtual inheritance is required * due to a parallel implementation split between the shared base class and the derived class. @@ -184,11 +177,17 @@ class ResponseEncoder : public virtual StreamEncoder { virtual void setRequestDecoder(RequestDecoder& decoder) PURE; /** - * Set headers and trailers for deferred logging. - * @param headers_and_trailers Headers and trailers from this stream. + * Set headers, trailers, and stream info for deferred logging. + * @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( - DeferredLoggingHeadersAndTrailers& headers_and_trailers) PURE; + virtual void + setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr request_header_map, + Http::ResponseHeaderMapSharedPtr response_header_map, + Http::ResponseTrailerMapSharedPtr response_trailer_map, + std::unique_ptr stream_info) PURE; }; /** diff --git a/mobile/library/common/http/client.h b/mobile/library/common/http/client.h index b697aea1f8545..efcfe571e7092 100644 --- a/mobile/library/common/http/client.h +++ b/mobile/library/common/http/client.h @@ -164,7 +164,10 @@ class Client : public Logger::Loggable { } bool streamErrorOnInvalidHttpMessage() const override { return false; } void setRequestDecoder(RequestDecoder& /*decoder*/) override{}; - void setDeferredLoggingHeadersAndTrailers(Http::DeferredLoggingHeadersAndTrailers&) override {} + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, + Http::ResponseHeaderMapSharedPtr, + Http::ResponseTrailerMapSharedPtr, + std::unique_ptr) override {} void encodeMetadata(const MetadataMapVector&) override { PANIC("not implemented"); } diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index ec26c721a65b8..1de3aad8781fe 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -204,26 +204,16 @@ class ConnectionManagerImpl : Logger::Loggable, std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } - // Copy this stream's StreamInfo into the deferred logging object, ensuring that the request + // Copy this stream's StreamInfo into the response encoder, ensuring that the request // headers pointed to by the StreamInfo lives beyond stream destruction. void deferHeadersAndTrailers() { - Http::DeferredLoggingHeadersAndTrailers headers_and_trailers; - if (requestHeaders()) { - headers_and_trailers.request_header_map = request_headers_; - } - if (responseHeaders()) { - headers_and_trailers.response_header_map = response_headers_; - } - if (responseTrailers()) { - headers_and_trailers.response_trailer_map = response_trailers_; - } std::unique_ptr stream_info = std::make_unique( connection_manager_.codec_->protocol(), connection_manager_.time_source_, connection_manager_.read_callbacks_->connection().connectionInfoProviderSharedPtr()); stream_info->setFrom(streamInfo(), request_headers_.get()); - headers_and_trailers.stream_info = std::move(stream_info); - response_encoder_->setDeferredLoggingHeadersAndTrailers(headers_and_trailers); + response_encoder_->setDeferredLoggingHeadersAndTrailers( + request_headers_, response_headers_, response_trailers_, std::move(stream_info)); } // ScopeTrackedObject diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index 24f6f6873f20e..568848ecc50c4 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -155,7 +155,10 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { bool streamErrorOnInvalidHttpMessage() const override { return stream_error_on_invalid_http_message_; } - void setDeferredLoggingHeadersAndTrailers(Http::DeferredLoggingHeadersAndTrailers&) override {} + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, + Http::ResponseHeaderMapSharedPtr, + Http::ResponseTrailerMapSharedPtr, + std::unique_ptr) 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 diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 1dae802230f81..c34b07d86fda5 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -498,7 +498,10 @@ class ConnectionImpl : public virtual Connection, encodeTrailersBase(trailers); } void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; } - void setDeferredLoggingHeadersAndTrailers(Http::DeferredLoggingHeadersAndTrailers&) override {} + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, + Http::ResponseHeaderMapSharedPtr, + Http::ResponseTrailerMapSharedPtr, + std::unique_ptr) override {} // ScopeTrackedObject void dumpState(std::ostream& os, int indent_level) const override; diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index 98f336cc8fef8..e905654c7e17f 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -24,6 +24,7 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, request_decoder_ = &decoder; stats_gatherer_->setAccessLogHandlers(request_decoder_->accessLogHandlers()); } + QuicStatsGatherer* statsGatherer() { return stats_gatherer_.get(); } // Http::StreamEncoder void encode1xxHeaders(const Http::ResponseHeaderMap& headers) override; @@ -38,8 +39,12 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, return http3_options_.override_stream_error_on_invalid_http_message().value(); } void setDeferredLoggingHeadersAndTrailers( - Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers) override { - stats_gatherer_->setDeferredLoggingHeadersAndTrailers(headers_and_trailers); + Http::RequestHeaderMapSharedPtr request_header_map, + Http::ResponseHeaderMapSharedPtr response_header_map, + Http::ResponseTrailerMapSharedPtr response_trailer_map, + std::unique_ptr stream_info) override { + stats_gatherer_->setDeferredLoggingHeadersAndTrailers( + request_header_map, response_header_map, response_trailer_map, std::move(stream_info)); }; // Http::Stream @@ -86,8 +91,6 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, quic::QuicRstStreamErrorCode rst = quic::QUIC_BAD_APPLICATION_PAYLOAD) override; private: - friend class EnvoyQuicServerStreamTest; - QuicFilterManagerConnectionImpl* filterManagerConnection(); // Deliver awaiting trailers if body has been delivered. diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 89c69da575e94..343cad827f718 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -15,23 +15,17 @@ void QuicStatsGatherer::OnPacketAcked(int acked_bytes, void QuicStatsGatherer::maybeDoDeferredLog(bool record_ack_timing) { logging_done_ = true; - if (!deferred_logging_headers_and_trailers_.has_value()) { - return; - } - Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers = - deferred_logging_headers_and_trailers_.value(); - if (headers_and_trailers.stream_info == nullptr) { + if (stream_info_ == nullptr) { return; } if (time_source_ != nullptr && record_ack_timing) { - headers_and_trailers.stream_info->downstreamTiming().onLastDownstreamAckReceived(*time_source_); + stream_info_->downstreamTiming().onLastDownstreamAckReceived(*time_source_); } - auto request_headers = headers_and_trailers.request_header_map.get(); - auto response_headers = headers_and_trailers.response_header_map.get(); - auto response_trailers = headers_and_trailers.response_trailer_map.get(); + auto request_headers = request_header_map_.get(); + auto response_headers = response_header_map_.get(); + auto response_trailers = response_trailer_map_.get(); for (const auto& log_handler : access_log_handlers_) { - log_handler->log(request_headers, response_headers, response_trailers, - *headers_and_trailers.stream_info); + log_handler->log(request_headers, response_headers, response_trailers, *stream_info_); } } diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index a318cacd314b3..4e076cfcb2c4d 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -33,12 +33,15 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { void setAccessLogHandlers(std::list handlers) { access_log_handlers_ = handlers; } - // Set headers and trailers used for deferred logging. - void setDeferredLoggingHeadersAndTrailers( - Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers) { - deferred_logging_headers_and_trailers_ = - absl::make_optional( - std::move(headers_and_trailers)); + // Set headers, trailers, and stream info used for deferred logging. + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr request_header_map, + Http::ResponseHeaderMapSharedPtr response_header_map, + Http::ResponseTrailerMapSharedPtr response_trailer_map, + std::unique_ptr stream_info) { + request_header_map_ = request_header_map; + response_header_map_ = response_header_map; + response_trailer_map_ = response_trailer_map; + stream_info_ = std::move(stream_info); } bool loggingDone() { return logging_done_; } uint64_t bytesOutstanding() { return bytes_outstanding_; } @@ -47,9 +50,11 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { uint64_t bytes_outstanding_ = 0; bool fin_sent_ = false; std::list access_log_handlers_{}; - // Headers and trailers required for deferred logging. nullopt indicates that deferred logging - // should be skipped. - absl::optional deferred_logging_headers_and_trailers_; + Http::RequestHeaderMapSharedPtr request_header_map_; + Http::ResponseHeaderMapSharedPtr response_header_map_; + Http::ResponseTrailerMapSharedPtr response_trailer_map_; + // nullptr indicates that deferred logging should be skipped. + std::unique_ptr stream_info_; Envoy::TimeSource* time_source_ = nullptr; bool logging_done_ = false; }; diff --git a/test/common/quic/envoy_quic_server_stream_test.cc b/test/common/quic/envoy_quic_server_stream_test.cc index e0ec10292ab8d..910b55eacb6d1 100644 --- a/test/common/quic/envoy_quic_server_stream_test.cc +++ b/test/common/quic/envoy_quic_server_stream_test.cc @@ -102,16 +102,6 @@ class EnvoyQuicServerStreamTest : public testing::Test { } } - void setStatsGathererDetails(std::list access_loggers, - Http::DeferredLoggingHeadersAndTrailers& headers_and_trailers) { - quic_stream_->stats_gatherer_->setAccessLogHandlers(access_loggers); - quic_stream_->stats_gatherer_->setDeferredLoggingHeadersAndTrailers(headers_and_trailers); - } - - uint64_t statsGathererBytesOutstanding() { - return quic_stream_->stats_gatherer_->bytesOutstanding(); - } - size_t receiveRequest(const std::string& payload, bool fin, size_t decoder_buffer_high_watermark) { EXPECT_CALL(stream_decoder_, decodeHeaders_(_, /*end_stream=*/false)) @@ -774,16 +764,16 @@ TEST_F(EnvoyQuicServerStreamTest, StatsGathererLogsOnStreamDestruction) { std::unique_ptr stream_info = std::make_unique(Http::Protocol::Http2, test_time_.timeSystem(), nullptr); - Http::DeferredLoggingHeadersAndTrailers headers_and_trailers; - headers_and_trailers.stream_info = std::move(stream_info); - setStatsGathererDetails(loggers, headers_and_trailers); + quic_stream_->statsGatherer()->setAccessLogHandlers(loggers); + quic_stream_->setDeferredLoggingHeadersAndTrailers(nullptr, nullptr, nullptr, + std::move(stream_info)); receiveRequest(request_body_, false, request_body_.size() * 2); quic_stream_->encodeHeaders(response_headers_, /*end_stream=*/true); EXPECT_CALL(quic_session_, MaybeSendStopSendingFrame(_, _)); EXPECT_CALL(stream_callbacks_, onResetStream(Http::StreamResetReason::LocalReset, _)); // The stats gatherer has outstanding bytes that have not been acked. - EXPECT_GT(statsGathererBytesOutstanding(), 0); + EXPECT_GT(quic_stream_->statsGatherer()->bytesOutstanding(), 0); // Close the stream; incoming acks will no longer invoke the stats gatherer but // the stats gatherer should log on stream close despite not receiving final downstream ack. EXPECT_CALL(*mock_logger, log(_, _, _, _)); diff --git a/test/mocks/http/stream_encoder.h b/test/mocks/http/stream_encoder.h index d142b2fe23e73..9572c7f1adc4f 100644 --- a/test/mocks/http/stream_encoder.h +++ b/test/mocks/http/stream_encoder.h @@ -50,7 +50,10 @@ class MockResponseEncoder : public ResponseEncoder { MOCK_METHOD(void, encodeTrailers, (const ResponseTrailerMap& trailers)); MOCK_METHOD(void, setRequestDecoder, (RequestDecoder & decoder)); MOCK_METHOD(void, setDeferredLoggingHeadersAndTrailers, - (DeferredLoggingHeadersAndTrailers & headers_and_trailers)); + (Http::RequestHeaderMapSharedPtr request_header_map, + Http::ResponseHeaderMapSharedPtr response_header_map, + Http::ResponseTrailerMapSharedPtr response_trailer_map, + std::unique_ptr stream_info)); // Http::StreamEncoder MOCK_METHOD(void, encodeData, (Buffer::Instance & data, bool end_stream)); From 154ca1bdbe887b96b79bfd62a6a120d495f443a1 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Fri, 6 Jan 2023 19:46:32 +0000 Subject: [PATCH 47/59] StreamInfoImplTest: split SetFrom tests Signed-off-by: Paul Sohn --- .../stream_info/stream_info_impl_test.cc | 47 ++++++++++++++----- 1 file changed, 35 insertions(+), 12 deletions(-) diff --git a/test/common/stream_info/stream_info_impl_test.cc b/test/common/stream_info/stream_info_impl_test.cc index ce6bdcc80ff49..770af325c652c 100644 --- a/test/common/stream_info/stream_info_impl_test.cc +++ b/test/common/stream_info/stream_info_impl_test.cc @@ -36,6 +36,19 @@ std::chrono::nanoseconds checkDuration(std::chrono::nanoseconds last, class StreamInfoImplTest : public testing::Test { protected: + void assertStreamInfoSize(StreamInfoImpl stream_info) { +#ifdef __clang__ +#if defined(__linux__) +#if defined(__has_feature) && !(__has_feature(thread_sanitizer)) + ASSERT_TRUE(sizeof(stream_info) == 800 || sizeof(stream_info) == 816 || + sizeof(stream_info) == 840) + << "If adding fields to StreamInfoImpl, please check to see if you " + "need to add them to setFromForRecreateStream or setFrom! Current size " + << sizeof(stream_info); +#endif +#endif +#endif + } DangerousDeprecatedTestTime test_time_; }; @@ -229,14 +242,33 @@ TEST_F(StreamInfoImplTest, MiscSettersAndGetters) { } } +TEST_F(StreamInfoImplTest, SetFromForRecreateStream) { + StreamInfoImpl s1(Http::Protocol::Http2, test_time_.timeSystem(), nullptr); + + s1.addBytesReceived(1); + s1.downstreamTiming().onLastDownstreamRxByteReceived(test_time_.timeSystem()); + + assertStreamInfoSize(s1); + + StreamInfoImpl s2(Http::Protocol::Http11, test_time_.timeSystem(), nullptr); + s2.setFromForRecreateStream(s1); + EXPECT_EQ(s1.startTime(), s2.startTime()); + EXPECT_EQ(s1.startTimeMonotonic(), s2.startTimeMonotonic()); + EXPECT_EQ(s1.downstreamTiming().lastDownstreamRxByteReceived(), + s2.downstreamTiming().lastDownstreamRxByteReceived()); + EXPECT_EQ(s1.protocol(), s2.protocol()); + EXPECT_EQ(s1.bytesReceived(), s2.bytesReceived()); + EXPECT_EQ(s1.getDownstreamBytesMeter(), s2.getDownstreamBytesMeter()); +} + TEST_F(StreamInfoImplTest, SetFrom) { StreamInfoImpl s1(Http::Protocol::Http2, test_time_.timeSystem(), nullptr); - // For testing setFromForRecreateStream + // setFromForRecreateStream s1.addBytesReceived(1); s1.downstreamTiming().onLastDownstreamRxByteReceived(test_time_.timeSystem()); - // For testing setFrom + // setFrom s1.setRouteName("foo"); s1.setVirtualClusterName(absl::optional("bar")); s1.setResponseCode(200); @@ -261,16 +293,7 @@ TEST_F(StreamInfoImplTest, SetFrom) { s1.setFilterChainName("foobar"); s1.setAttemptCount(5); -#ifdef __clang__ -#if defined(__linux__) -#if defined(__has_feature) && !(__has_feature(thread_sanitizer)) - ASSERT_TRUE(sizeof(s1) == 800 || sizeof(s1) == 816 || sizeof(s1) == 840) - << "If adding fields to StreamInfoImpl, please check to see if you " - "need to add them to setFromForRecreateStream or setFrom! Current size " - << sizeof(s1); -#endif -#endif -#endif + assertStreamInfoSize(s1); StreamInfoImpl s2(Http::Protocol::Http11, test_time_.timeSystem(), nullptr); Http::TestRequestHeaderMapImpl headers2; From ecbb802adbefa58343a03178ac706444ce519970 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Mon, 9 Jan 2023 17:37:30 +0000 Subject: [PATCH 48/59] move streaminfo copying into response encoder Signed-off-by: Paul Sohn --- envoy/http/codec.h | 2 +- mobile/library/common/http/client.h | 2 +- source/common/http/conn_manager_impl.h | 11 ++--------- source/common/http/http1/codec_impl.h | 2 +- source/common/http/http2/codec_impl.h | 2 +- source/common/quic/envoy_quic_server_stream.h | 18 ++++++++++++------ .../quic/envoy_quic_server_stream_test.cc | 8 +++----- test/mocks/http/stream_encoder.h | 2 +- 8 files changed, 22 insertions(+), 25 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 59777d9a5d9b5..11e82c574aee6 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -187,7 +187,7 @@ class ResponseEncoder : public virtual StreamEncoder { setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr request_header_map, Http::ResponseHeaderMapSharedPtr response_header_map, Http::ResponseTrailerMapSharedPtr response_trailer_map, - std::unique_ptr stream_info) PURE; + StreamInfo::StreamInfo& stream_info) PURE; }; /** diff --git a/mobile/library/common/http/client.h b/mobile/library/common/http/client.h index efcfe571e7092..df4e5cc9755b6 100644 --- a/mobile/library/common/http/client.h +++ b/mobile/library/common/http/client.h @@ -167,7 +167,7 @@ class Client : public Logger::Loggable { void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, Http::ResponseHeaderMapSharedPtr, Http::ResponseTrailerMapSharedPtr, - std::unique_ptr) override {} + StreamInfo::StreamInfo&) override {} void encodeMetadata(const MetadataMapVector&) override { PANIC("not implemented"); } diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 1de3aad8781fe..5aa0d6539ce02 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -204,16 +204,9 @@ class ConnectionManagerImpl : Logger::Loggable, std::list accessLogHandlers() override { return filter_manager_.accessLogHandlers(); } - // Copy this stream's StreamInfo into the response encoder, ensuring that the request - // headers pointed to by the StreamInfo lives beyond stream destruction. void deferHeadersAndTrailers() { - std::unique_ptr stream_info = - std::make_unique( - connection_manager_.codec_->protocol(), connection_manager_.time_source_, - connection_manager_.read_callbacks_->connection().connectionInfoProviderSharedPtr()); - stream_info->setFrom(streamInfo(), request_headers_.get()); - response_encoder_->setDeferredLoggingHeadersAndTrailers( - request_headers_, response_headers_, response_trailers_, std::move(stream_info)); + response_encoder_->setDeferredLoggingHeadersAndTrailers(request_headers_, response_headers_, + response_trailers_, streamInfo()); } // ScopeTrackedObject diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index 568848ecc50c4..4ae9afc6c03e1 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -158,7 +158,7 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, Http::ResponseHeaderMapSharedPtr, Http::ResponseTrailerMapSharedPtr, - std::unique_ptr) override {} + 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 diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index c34b07d86fda5..0a33ec4c5302a 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -501,7 +501,7 @@ class ConnectionImpl : public virtual Connection, void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, Http::ResponseHeaderMapSharedPtr, Http::ResponseTrailerMapSharedPtr, - std::unique_ptr) override {} + StreamInfo::StreamInfo&) override {} // ScopeTrackedObject void dumpState(std::ostream& os, int indent_level) const override; diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index e905654c7e17f..4c91c8d9af549 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -38,13 +38,19 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, bool streamErrorOnInvalidHttpMessage() const override { return http3_options_.override_stream_error_on_invalid_http_message().value(); } - void setDeferredLoggingHeadersAndTrailers( - Http::RequestHeaderMapSharedPtr request_header_map, - Http::ResponseHeaderMapSharedPtr response_header_map, - Http::ResponseTrailerMapSharedPtr response_trailer_map, - std::unique_ptr stream_info) override { + // Copy this stream's StreamInfo, ensuring that the request headers pointed to by the StreamInfo + // lives beyond stream destruction. + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr request_header_map, + Http::ResponseHeaderMapSharedPtr response_header_map, + Http::ResponseTrailerMapSharedPtr response_trailer_map, + StreamInfo::StreamInfo& stream_info) override { + std::unique_ptr new_stream_info = + std::make_unique( + filterManagerConnection()->dispatcher().timeSource(), + filterManagerConnection()->connectionInfoProviderSharedPtr()); + new_stream_info->setFrom(stream_info, request_header_map.get()); stats_gatherer_->setDeferredLoggingHeadersAndTrailers( - request_header_map, response_header_map, response_trailer_map, std::move(stream_info)); + request_header_map, response_header_map, response_trailer_map, std::move(new_stream_info)); }; // Http::Stream diff --git a/test/common/quic/envoy_quic_server_stream_test.cc b/test/common/quic/envoy_quic_server_stream_test.cc index 910b55eacb6d1..f384a9fa29735 100644 --- a/test/common/quic/envoy_quic_server_stream_test.cc +++ b/test/common/quic/envoy_quic_server_stream_test.cc @@ -761,12 +761,10 @@ TEST_F(EnvoyQuicServerStreamTest, StatsGathererLogsOnStreamDestruction) { std::shared_ptr mock_logger(new NiceMock()); std::list loggers = {mock_logger}; Event::GlobalTimeSystem test_time_; - std::unique_ptr stream_info = - std::make_unique(Http::Protocol::Http2, - test_time_.timeSystem(), nullptr); + Envoy::StreamInfo::StreamInfoImpl stream_info{Http::Protocol::Http2, test_time_.timeSystem(), + nullptr}; quic_stream_->statsGatherer()->setAccessLogHandlers(loggers); - quic_stream_->setDeferredLoggingHeadersAndTrailers(nullptr, nullptr, nullptr, - std::move(stream_info)); + quic_stream_->setDeferredLoggingHeadersAndTrailers(nullptr, nullptr, nullptr, stream_info); receiveRequest(request_body_, false, request_body_.size() * 2); quic_stream_->encodeHeaders(response_headers_, /*end_stream=*/true); diff --git a/test/mocks/http/stream_encoder.h b/test/mocks/http/stream_encoder.h index 9572c7f1adc4f..fd6d20c3b08ba 100644 --- a/test/mocks/http/stream_encoder.h +++ b/test/mocks/http/stream_encoder.h @@ -53,7 +53,7 @@ class MockResponseEncoder : public ResponseEncoder { (Http::RequestHeaderMapSharedPtr request_header_map, Http::ResponseHeaderMapSharedPtr response_header_map, Http::ResponseTrailerMapSharedPtr response_trailer_map, - std::unique_ptr stream_info)); + StreamInfo::StreamInfo& stream_info)); // Http::StreamEncoder MOCK_METHOD(void, encodeData, (Buffer::Instance & data, bool end_stream)); From 5b0aca1fdebf4841e0ee0b3dc27133b7aca0329a Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 10 Jan 2023 15:47:31 +0000 Subject: [PATCH 49/59] QuicStatsGatherer: use explicit types Signed-off-by: Paul Sohn --- source/common/quic/quic_stats_gatherer.cc | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index 343cad827f718..f7ef00117cf1d 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -21,10 +21,10 @@ void QuicStatsGatherer::maybeDoDeferredLog(bool record_ack_timing) { if (time_source_ != nullptr && record_ack_timing) { stream_info_->downstreamTiming().onLastDownstreamAckReceived(*time_source_); } - auto request_headers = request_header_map_.get(); - auto response_headers = response_header_map_.get(); - auto response_trailers = response_trailer_map_.get(); - for (const auto& log_handler : access_log_handlers_) { + Http::RequestHeaderMap* request_headers = request_header_map_.get(); + Http::ResponseHeaderMap* response_headers = response_header_map_.get(); + Http::ResponseTrailerMap* response_trailers = response_trailer_map_.get(); + for (const AccessLog::InstanceSharedPtr& log_handler : access_log_handlers_) { log_handler->log(request_headers, response_headers, response_trailers, *stream_info_); } } From 82efea72f1f6d7f2c4c23a3f5b0798f239cf05d0 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 10 Jan 2023 15:50:18 +0000 Subject: [PATCH 50/59] base integration test: clarify comment about 25ms ack timer Signed-off-by: Paul Sohn --- test/integration/base_integration_test.cc | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/integration/base_integration_test.cc b/test/integration/base_integration_test.cc index af7319c7671af..57c3b14412773 100644 --- a/test/integration/base_integration_test.cc +++ b/test/integration/base_integration_test.cc @@ -527,7 +527,8 @@ std::string BaseIntegrationTest::waitForAccessLog(const std::string& filename, u return entries[entry]; } if (i % 25 == 0 && client_connection != nullptr) { - // Wait 25 ms for default ack timer, then run dispatcher to send pending acks. + // The QUIC default delayed ack timer is 25ms. Wait for any pending ack timers to expire, + // then run dispatcher to send any pending acks. client_connection->dispatcher().run(Envoy::Event::Dispatcher::RunType::NonBlock); } absl::SleepFor(absl::Milliseconds(1)); From 7c65613200875d946a6b4569017b3680b0b3dc1a Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 10 Jan 2023 15:52:55 +0000 Subject: [PATCH 51/59] stream_info_impl_test: suppress unused-parameter warning There is a helper function that does not use its parameter under certain conditions (e.g. tsan). Signed-off-by: Paul Sohn --- test/common/stream_info/BUILD | 1 + 1 file changed, 1 insertion(+) diff --git a/test/common/stream_info/BUILD b/test/common/stream_info/BUILD index afc7eac5f9ead..be305f45a68d0 100644 --- a/test/common/stream_info/BUILD +++ b/test/common/stream_info/BUILD @@ -21,6 +21,7 @@ envoy_cc_test( envoy_cc_test( name = "stream_info_impl_test", srcs = ["stream_info_impl_test.cc"], + copts = ["-Wno-unused-parameter"], deps = [ ":test_int_accessor_lib", "//envoy/http:protocol_interface", From fc87b2ec2a37efc8b0860dfda07d8f505c21a2e0 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 10 Jan 2023 16:04:17 +0000 Subject: [PATCH 52/59] stream_info_impl_test: avoid assertStreamInfoSize unused parameter problem Signed-off-by: Paul Sohn --- test/common/stream_info/BUILD | 1 - .../stream_info/stream_info_impl_test.cc | 18 ++++++++++++------ 2 files changed, 12 insertions(+), 7 deletions(-) diff --git a/test/common/stream_info/BUILD b/test/common/stream_info/BUILD index be305f45a68d0..afc7eac5f9ead 100644 --- a/test/common/stream_info/BUILD +++ b/test/common/stream_info/BUILD @@ -21,7 +21,6 @@ envoy_cc_test( envoy_cc_test( name = "stream_info_impl_test", srcs = ["stream_info_impl_test.cc"], - copts = ["-Wno-unused-parameter"], deps = [ ":test_int_accessor_lib", "//envoy/http:protocol_interface", diff --git a/test/common/stream_info/stream_info_impl_test.cc b/test/common/stream_info/stream_info_impl_test.cc index 770af325c652c..e2c136528d6ae 100644 --- a/test/common/stream_info/stream_info_impl_test.cc +++ b/test/common/stream_info/stream_info_impl_test.cc @@ -37,17 +37,11 @@ std::chrono::nanoseconds checkDuration(std::chrono::nanoseconds last, class StreamInfoImplTest : public testing::Test { protected: void assertStreamInfoSize(StreamInfoImpl stream_info) { -#ifdef __clang__ -#if defined(__linux__) -#if defined(__has_feature) && !(__has_feature(thread_sanitizer)) ASSERT_TRUE(sizeof(stream_info) == 800 || sizeof(stream_info) == 816 || sizeof(stream_info) == 840) << "If adding fields to StreamInfoImpl, please check to see if you " "need to add them to setFromForRecreateStream or setFrom! Current size " << sizeof(stream_info); -#endif -#endif -#endif } DangerousDeprecatedTestTime test_time_; }; @@ -248,7 +242,13 @@ TEST_F(StreamInfoImplTest, SetFromForRecreateStream) { s1.addBytesReceived(1); s1.downstreamTiming().onLastDownstreamRxByteReceived(test_time_.timeSystem()); +#ifdef __clang__ +#if defined(__linux__) +#if defined(__has_feature) && !(__has_feature(thread_sanitizer)) assertStreamInfoSize(s1); +#endif +#endif +#endif StreamInfoImpl s2(Http::Protocol::Http11, test_time_.timeSystem(), nullptr); s2.setFromForRecreateStream(s1); @@ -293,7 +293,13 @@ TEST_F(StreamInfoImplTest, SetFrom) { s1.setFilterChainName("foobar"); s1.setAttemptCount(5); +#ifdef __clang__ +#if defined(__linux__) +#if defined(__has_feature) && !(__has_feature(thread_sanitizer)) assertStreamInfoSize(s1); +#endif +#endif +#endif StreamInfoImpl s2(Http::Protocol::Http11, test_time_.timeSystem(), nullptr); Http::TestRequestHeaderMapImpl headers2; From db5fe3988eb277f307a615adc4d424cdf1f1a4cd Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Tue, 10 Jan 2023 20:00:41 +0000 Subject: [PATCH 53/59] setDeferredLoggingHeadersAndTrailers: make headers shared pointers to const We can't make stream info easily const here, because some of the const getters (e.g. upstreamInfo()) don't provide the shared pointer. Signed-off-by: Paul Sohn --- envoy/http/codec.h | 6 +++--- envoy/http/header_map.h | 3 +++ mobile/library/common/http/client.h | 6 +++--- source/common/http/http1/codec_impl.h | 6 +++--- source/common/http/http2/codec_impl.h | 6 +++--- source/common/quic/envoy_quic_server_stream.h | 9 +++++---- source/common/quic/quic_stats_gatherer.cc | 6 +++--- source/common/quic/quic_stats_gatherer.h | 15 ++++++++------- source/common/stream_info/stream_info_impl.h | 2 +- test/mocks/http/stream_encoder.h | 6 +++--- 10 files changed, 35 insertions(+), 30 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 11e82c574aee6..99fd6644a36fe 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -184,9 +184,9 @@ class ResponseEncoder : public virtual StreamEncoder { * @param stream_info Stream info for this stream. */ virtual void - setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr request_header_map, - Http::ResponseHeaderMapSharedPtr response_header_map, - Http::ResponseTrailerMapSharedPtr response_trailer_map, + setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr request_header_map, + Http::ResponseHeaderMapConstSharedPtr response_header_map, + Http::ResponseTrailerMapConstSharedPtr response_trailer_map, StreamInfo::StreamInfo& stream_info) PURE; }; diff --git a/envoy/http/header_map.h b/envoy/http/header_map.h index c64299d6ba2f3..c190ea4968634 100644 --- a/envoy/http/header_map.h +++ b/envoy/http/header_map.h @@ -718,6 +718,7 @@ class RequestHeaderMap }; using RequestHeaderMapPtr = std::unique_ptr; using RequestHeaderMapSharedPtr = std::shared_ptr; +using RequestHeaderMapConstSharedPtr = std::shared_ptr; using RequestHeaderMapOptRef = OptRef; using RequestHeaderMapOptConstRef = OptRef; @@ -749,6 +750,7 @@ class ResponseHeaderMap }; using ResponseHeaderMapPtr = std::unique_ptr; using ResponseHeaderMapSharedPtr = std::shared_ptr; +using ResponseHeaderMapConstSharedPtr = std::shared_ptr; using ResponseHeaderMapOptRef = OptRef; using ResponseHeaderMapOptConstRef = OptRef; @@ -759,6 +761,7 @@ class ResponseTrailerMap public CustomInlineHeaderBase {}; using ResponseTrailerMapPtr = std::unique_ptr; using ResponseTrailerMapSharedPtr = std::shared_ptr; +using ResponseTrailerMapConstSharedPtr = std::shared_ptr; using ResponseTrailerMapOptRef = OptRef; using ResponseTrailerMapOptConstRef = OptRef; diff --git a/mobile/library/common/http/client.h b/mobile/library/common/http/client.h index df4e5cc9755b6..1b6329a459680 100644 --- a/mobile/library/common/http/client.h +++ b/mobile/library/common/http/client.h @@ -164,9 +164,9 @@ class Client : public Logger::Loggable { } bool streamErrorOnInvalidHttpMessage() const override { return false; } void setRequestDecoder(RequestDecoder& /*decoder*/) override{}; - void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, - Http::ResponseHeaderMapSharedPtr, - Http::ResponseTrailerMapSharedPtr, + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr, + Http::ResponseHeaderMapConstSharedPtr, + Http::ResponseTrailerMapConstSharedPtr, StreamInfo::StreamInfo&) override {} void encodeMetadata(const MetadataMapVector&) override { PANIC("not implemented"); } diff --git a/source/common/http/http1/codec_impl.h b/source/common/http/http1/codec_impl.h index 4ae9afc6c03e1..5d3ea37e8c275 100644 --- a/source/common/http/http1/codec_impl.h +++ b/source/common/http/http1/codec_impl.h @@ -155,9 +155,9 @@ class ResponseEncoderImpl : public StreamEncoderImpl, public ResponseEncoder { bool streamErrorOnInvalidHttpMessage() const override { return stream_error_on_invalid_http_message_; } - void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, - Http::ResponseHeaderMapSharedPtr, - Http::ResponseTrailerMapSharedPtr, + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr, + Http::ResponseHeaderMapConstSharedPtr, + Http::ResponseTrailerMapConstSharedPtr, StreamInfo::StreamInfo&) override {} // For H/1, ResponseEncoder doesn't hold a pointer to RequestDecoder. diff --git a/source/common/http/http2/codec_impl.h b/source/common/http/http2/codec_impl.h index 0a33ec4c5302a..eee33417aeca4 100644 --- a/source/common/http/http2/codec_impl.h +++ b/source/common/http/http2/codec_impl.h @@ -498,9 +498,9 @@ class ConnectionImpl : public virtual Connection, encodeTrailersBase(trailers); } void setRequestDecoder(Http::RequestDecoder& decoder) override { request_decoder_ = &decoder; } - void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr, - Http::ResponseHeaderMapSharedPtr, - Http::ResponseTrailerMapSharedPtr, + void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr, + Http::ResponseHeaderMapConstSharedPtr, + Http::ResponseTrailerMapConstSharedPtr, StreamInfo::StreamInfo&) override {} // ScopeTrackedObject diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index 4c91c8d9af549..75ed5049b92ba 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -40,10 +40,11 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, } // Copy this stream's StreamInfo, ensuring that the request headers pointed to by the StreamInfo // lives beyond stream destruction. - void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr request_header_map, - Http::ResponseHeaderMapSharedPtr response_header_map, - Http::ResponseTrailerMapSharedPtr response_trailer_map, - StreamInfo::StreamInfo& stream_info) override { + void + setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr request_header_map, + Http::ResponseHeaderMapConstSharedPtr response_header_map, + Http::ResponseTrailerMapConstSharedPtr response_trailer_map, + StreamInfo::StreamInfo& stream_info) override { std::unique_ptr new_stream_info = std::make_unique( filterManagerConnection()->dispatcher().timeSource(), diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc index f7ef00117cf1d..be4b83ba70b32 100644 --- a/source/common/quic/quic_stats_gatherer.cc +++ b/source/common/quic/quic_stats_gatherer.cc @@ -21,9 +21,9 @@ void QuicStatsGatherer::maybeDoDeferredLog(bool record_ack_timing) { if (time_source_ != nullptr && record_ack_timing) { stream_info_->downstreamTiming().onLastDownstreamAckReceived(*time_source_); } - Http::RequestHeaderMap* request_headers = request_header_map_.get(); - Http::ResponseHeaderMap* response_headers = response_header_map_.get(); - Http::ResponseTrailerMap* response_trailers = response_trailer_map_.get(); + const Http::RequestHeaderMap* request_headers = request_header_map_.get(); + const Http::ResponseHeaderMap* response_headers = response_header_map_.get(); + const Http::ResponseTrailerMap* response_trailers = response_trailer_map_.get(); for (const AccessLog::InstanceSharedPtr& log_handler : access_log_handlers_) { log_handler->log(request_headers, response_headers, response_trailers, *stream_info_); } diff --git a/source/common/quic/quic_stats_gatherer.h b/source/common/quic/quic_stats_gatherer.h index 4e076cfcb2c4d..9708ab07f5ccd 100644 --- a/source/common/quic/quic_stats_gatherer.h +++ b/source/common/quic/quic_stats_gatherer.h @@ -34,10 +34,11 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { access_log_handlers_ = handlers; } // Set headers, trailers, and stream info used for deferred logging. - void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapSharedPtr request_header_map, - Http::ResponseHeaderMapSharedPtr response_header_map, - Http::ResponseTrailerMapSharedPtr response_trailer_map, - std::unique_ptr stream_info) { + void + setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr request_header_map, + Http::ResponseHeaderMapConstSharedPtr response_header_map, + Http::ResponseTrailerMapConstSharedPtr response_trailer_map, + std::unique_ptr stream_info) { request_header_map_ = request_header_map; response_header_map_ = response_header_map; response_trailer_map_ = response_trailer_map; @@ -50,9 +51,9 @@ class QuicStatsGatherer : public quic::QuicAckListenerInterface { uint64_t bytes_outstanding_ = 0; bool fin_sent_ = false; std::list access_log_handlers_{}; - Http::RequestHeaderMapSharedPtr request_header_map_; - Http::ResponseHeaderMapSharedPtr response_header_map_; - Http::ResponseTrailerMapSharedPtr response_trailer_map_; + Http::RequestHeaderMapConstSharedPtr request_header_map_; + Http::ResponseHeaderMapConstSharedPtr response_header_map_; + Http::ResponseTrailerMapConstSharedPtr response_trailer_map_; // nullptr indicates that deferred logging should be skipped. std::unique_ptr stream_info_; Envoy::TimeSource* time_source_ = nullptr; diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index 33821ea2b5940..b84c575444e4e 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -342,7 +342,7 @@ struct StreamInfoImpl : public StreamInfo { // * request_headers_ is a raw pointer; to avoid pointer lifetime issues, a request header pointer // is required to be passed in here. // * downstream_connection_info_provider_ is always set in the ctor. - void setFrom(StreamInfo& info, Http::RequestHeaderMap* request_headers) { + void setFrom(StreamInfo& info, const Http::RequestHeaderMap* request_headers) { setFromForRecreateStream(info); route_name_ = info.getRouteName(); virtual_cluster_name_ = info.virtualClusterName(); diff --git a/test/mocks/http/stream_encoder.h b/test/mocks/http/stream_encoder.h index fd6d20c3b08ba..e8ce13c2b698a 100644 --- a/test/mocks/http/stream_encoder.h +++ b/test/mocks/http/stream_encoder.h @@ -50,9 +50,9 @@ class MockResponseEncoder : public ResponseEncoder { MOCK_METHOD(void, encodeTrailers, (const ResponseTrailerMap& trailers)); MOCK_METHOD(void, setRequestDecoder, (RequestDecoder & decoder)); MOCK_METHOD(void, setDeferredLoggingHeadersAndTrailers, - (Http::RequestHeaderMapSharedPtr request_header_map, - Http::ResponseHeaderMapSharedPtr response_header_map, - Http::ResponseTrailerMapSharedPtr response_trailer_map, + (Http::RequestHeaderMapConstSharedPtr request_header_map, + Http::ResponseHeaderMapConstSharedPtr response_header_map, + Http::ResponseTrailerMapConstSharedPtr response_trailer_map, StreamInfo::StreamInfo& stream_info)); // Http::StreamEncoder From f3817ca593464b1812c559276e244f191550999d Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 11 Jan 2023 16:37:17 +0000 Subject: [PATCH 54/59] Add comments about passing through headers/trailers for logging Note that we tried to convert StreamInfo to a shared ptr but ran into some difficulty with converting all of the members of the implementations into shared ptrs as well. Signed-off-by: Paul Sohn --- envoy/http/codec.h | 5 ++++- source/common/http/conn_manager_impl.h | 2 ++ source/common/quic/envoy_quic_server_stream.h | 6 ++++-- 3 files changed, 10 insertions(+), 3 deletions(-) diff --git a/envoy/http/codec.h b/envoy/http/codec.h index 99fd6644a36fe..7a906210ab09d 100644 --- a/envoy/http/codec.h +++ b/envoy/http/codec.h @@ -177,7 +177,10 @@ class ResponseEncoder : public virtual StreamEncoder { virtual void setRequestDecoder(RequestDecoder& decoder) PURE; /** - * Set headers, trailers, and stream info for deferred logging. + * 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. diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 5aa0d6539ce02..e7b0cbf3e4fcf 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -204,6 +204,8 @@ class ConnectionManagerImpl : Logger::Loggable, std::list 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). void deferHeadersAndTrailers() { response_encoder_->setDeferredLoggingHeadersAndTrailers(request_headers_, response_headers_, response_trailers_, streamInfo()); diff --git a/source/common/quic/envoy_quic_server_stream.h b/source/common/quic/envoy_quic_server_stream.h index 75ed5049b92ba..399f6262f1b5e 100644 --- a/source/common/quic/envoy_quic_server_stream.h +++ b/source/common/quic/envoy_quic_server_stream.h @@ -38,8 +38,10 @@ class EnvoyQuicServerStream : public quic::QuicSpdyServerStreamBase, bool streamErrorOnInvalidHttpMessage() const override { return http3_options_.override_stream_error_on_invalid_http_message().value(); } - // Copy this stream's StreamInfo, ensuring that the request headers pointed to by the StreamInfo - // lives beyond stream destruction. + + // Accept headers/trailers and stream info from HCM for deferred logging. We pass on the + // header/trailer shared pointers, but copy the non-shared stream info to avoid lifetime issues if + // the stream is destroyed before logging is complete. void setDeferredLoggingHeadersAndTrailers(Http::RequestHeaderMapConstSharedPtr request_header_map, Http::ResponseHeaderMapConstSharedPtr response_header_map, From 22b72f51ab6afb578d3b004ee62e6016ad671454 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Fri, 13 Jan 2023 21:58:35 +0000 Subject: [PATCH 55/59] move build dependencies to address boringssl fips build failures Signed-off-by: Paul Sohn --- test/integration/BUILD | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/integration/BUILD b/test/integration/BUILD index bd37836346540..5326448382d68 100644 --- a/test/integration/BUILD +++ b/test/integration/BUILD @@ -751,7 +751,6 @@ envoy_cc_test_library( "//test/integration/filters:encode_headers_return_stop_all_filter_config_lib", "//test/integration/filters:modify_buffer_filter_config_lib", "//test/integration/filters:passthrough_filter_config_lib", - "//test/integration/filters:pause_filter_for_quic_lib", "//test/integration/filters:pause_filter_lib", "//test/integration/filters:wait_for_whole_request_and_response_config_lib", "//test/mocks/upstream:cluster_info_mocks", @@ -1127,9 +1126,11 @@ envoy_cc_test( "redirect_integration_test.cc", ], shard_count = 4, + tags = ["nofips"], deps = [ ":http_protocol_integration_lib", "//source/common/http:header_map_lib", + "//test/integration/filters:pause_filter_for_quic_lib", "//test/test_common:utility_lib", "@envoy_api//envoy/config/route/v3:pkg_cc_proto", "@envoy_api//envoy/extensions/filters/network/http_connection_manager/v3:pkg_cc_proto", From 26f3cf418cd6a686ba3564a605a60a315e54b29d Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 18 Jan 2023 16:28:34 +0000 Subject: [PATCH 56/59] Add TODO about moving logging objects instead of copying/sharing Signed-off-by: Paul Sohn --- source/common/http/conn_manager_impl.h | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index ee4fd268810f4..0fc013eed51cc 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -206,6 +206,11 @@ class ConnectionManagerImpl : Logger::Loggable, } // 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()); From 763f0b69394d1fe07fb3c351b89b1a9294444360 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 18 Jan 2023 16:32:48 +0000 Subject: [PATCH 57/59] fix bad merge of current.yaml Signed-off-by: Paul Sohn --- changelogs/current.yaml | 48 ----------------------------------------- 1 file changed, 48 deletions(-) diff --git a/changelogs/current.yaml b/changelogs/current.yaml index 2167d4e42bee6..fec4b7792f93d 100644 --- a/changelogs/current.yaml +++ b/changelogs/current.yaml @@ -8,54 +8,6 @@ minor_behavior_changes: - 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: tls - change: | - added support for intermediate CA as trusted ca. The peer certificate issued by an intermediate CA will be trusted by - building valid partial chain. In old days, it can not be verified without trusting its ancestor root CA and building - a full chain. - :ref:`trust_ca`. - This change can be reverted via the ``envoy.reloadable_features.enable_intermediate_ca``. -- area: cache_filter - change: | - add a completion callback to updateHeaders interface. Any external cache implementations will need to update to match this new interface. See changes to simple_http_cache in PR#23666 for example. -- area: cache_filter - change: | - api path of work-in-progress extension changed from ``api/extensions/cache/simple_http_cache`` to ``api/extensions/http/cache/simple_http_cache``, and source code moved, to match extension category. -- area: http filter - change: | - Avoid re-entrant filter invocations if we do a local reply via the filter chain when executing decoder filters. This behavioral change can be temporarily reverted by setting runtime guard ``envoy_reloadable_features_http_filter_avoid_reentrant_local_reply`` to false. -- area: http filters - change: | - change ``StreamEncoderFilter::encode1xxHeaders`` to use its own enum class ``Http::Filter1xxHeadersStatus``. Previously we shared the same enum class for general headers, but the implementation did not support most of them. We also fixed ``StreamEncoderFilter::encode1xxHeaders`` to send local replies without trailing 1xx headers afterward. -- area: oauth2 - change: | - Requests which match the passthrough header now have their own metric ``oauth_passthrough`` and aren't included in ``oauth_success`` anymore. -- area: oauth2 - change: | - query parameters in the :ref:`authorization_endpoint ` are now preserved. -- area: upstream - change: | - detailed health status is used for override host selection. This behavior can be reverted by setting runtime flag ``envoy.reloadable_features.validate_detailed_override_host_statuses`` to false. -- area: rate_limit - change: | - add ``MONTH`` and ``YEAR`` to the unit of time for rate limit. -- area: router - change: | - Virtual cluster statistics are no longer created for routes without any ``virtual_clusters``. Previously statistics for a ``catch all`` virtual cluster were created, but never updated. -- area: jwt_authn - change: | - adjust the refetch time for remote_jwks async_fetch feature. For a good fetch, refetch 5 seconds before jwks cache duration. For a failed fetch, refetch time can be specified by :ref:`failed_refetch_duration ` with default 1 second. -- area: config - change: | - add support for thrift connection draining. This can be disabled by setting the runtime guard ``envoy.reloadable_features.thrift_connection_draining`` to false. -- area: http - change: | - reverting the behavioral change to have ``CONNECT`` and upgrade requests over HTTP/1.1 not delay close. One can reinstate - delay close for upgrades by setting ``envoy.reloadable_features.no_delay_close_for_upgrades`` to ``true``. -- area: tcp - change: | - added :ref:`idle_timeout ` to support per client idle timeout for tcp connection pool. The timeout is guarded by ``envoy.reloadable_features.tcp_pool_idle_timeout`` and timeout defaults to 10 minutes if runtime flag is enabled. - bug_fixes: # *Changes expected to improve the state of the world and are unlikely to have negative effects* From 4dda7d15e852ae95154e7fe0c0895045de61b69f Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Wed, 18 Jan 2023 20:18:29 +0000 Subject: [PATCH 58/59] Fix H/1 codec tests behind ENVOY_ENABLE_UHV Signed-off-by: Paul Sohn --- test/common/http/http1/codec_impl_test.cc | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/common/http/http1/codec_impl_test.cc b/test/common/http/http1/codec_impl_test.cc index 56b926e37158a..f74b30f5e0a16 100644 --- a/test/common/http/http1/codec_impl_test.cc +++ b/test/common/http/http1/codec_impl_test.cc @@ -1282,7 +1282,7 @@ TEST_P(Http1ServerConnectionImplTest, HeaderNameWithUnderscoreAllowed) { #ifdef ENVOY_ENABLE_UHV // Header validation is done by the HCM when header map is fully parsed. EXPECT_CALL(decoder, decodeHeaders_(_, _)) - .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapPtr& headers, bool) -> void { + .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapSharedPtr& headers, bool) -> void { auto result = header_validator_->validateRequestHeaderMap(*headers); EXPECT_THAT(headers, HeaderMapEqualIgnoreOrder(&expected_headers)); ASSERT_TRUE(result.ok()); @@ -1315,7 +1315,7 @@ TEST_P(Http1ServerConnectionImplTest, HeaderNameWithUnderscoreAreDropped) { #ifdef ENVOY_ENABLE_UHV // Header validation is done by the HCM when header map is fully parsed. EXPECT_CALL(decoder, decodeHeaders_(_, _)) - .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapPtr& headers, bool) -> void { + .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapSharedPtr& headers, bool) -> void { auto result = header_validator_->validateRequestHeaderMap(*headers); EXPECT_THAT(headers, HeaderMapEqualIgnoreOrder(&expected_headers)); ASSERT_TRUE(result.ok()); @@ -1352,7 +1352,7 @@ TEST_P(Http1ServerConnectionImplTest, HeaderNameWithUnderscoreCauseRequestReject // sendLocalReply and closes network connection (based on the // stream_error_on_invalid_http_message flag, which in this test is assumed to equal false). EXPECT_CALL(decoder, decodeHeaders_(_, _)) - .WillOnce(Invoke([this, &response_encoder](RequestHeaderMapPtr& headers, bool) -> void { + .WillOnce(Invoke([this, &response_encoder](RequestHeaderMapSharedPtr& headers, bool) -> void { auto result = header_validator_->validateRequestHeaderMap(*headers); ASSERT_FALSE(result.ok()); response_encoder->encodeHeaders(TestResponseHeaderMapImpl{{":status", "400"}, From e870fb98797a5c05fdfe52b85379560042c425b4 Mon Sep 17 00:00:00 2001 From: Paul Sohn Date: Thu, 19 Jan 2023 14:44:40 +0000 Subject: [PATCH 59/59] Fix H/2 codec tests behind ENVOY_ENABLE_UHV Signed-off-by: Paul Sohn --- test/common/http/http2/codec_impl_test.cc | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/common/http/http2/codec_impl_test.cc b/test/common/http/http2/codec_impl_test.cc index cf739138151e0..9427f89db3b19 100644 --- a/test/common/http/http2/codec_impl_test.cc +++ b/test/common/http/http2/codec_impl_test.cc @@ -2726,7 +2726,7 @@ TEST_P(Http2CodecImplTest, HeaderNameWithUnderscoreAreDropped) { #ifdef ENVOY_ENABLE_UHV // Header validation is done by the HCM when header map is fully parsed. EXPECT_CALL(request_decoder_, decodeHeaders_(_, _)) - .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapPtr& headers, bool) -> void { + .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapSharedPtr& headers, bool) -> void { auto result = header_validator_->validateRequestHeaderMap(*headers); EXPECT_THAT(headers, HeaderMapEqualIgnoreOrder(&expected_headers)); ASSERT_TRUE(result.ok()); @@ -2755,7 +2755,7 @@ TEST_P(Http2CodecImplTest, HeaderNameWithUnderscoreAreRejected) { // sendLocalReply and closes network connection (based on the // stream_error_on_invalid_http_message flag, which in this test is assumed to equal false). EXPECT_CALL(request_decoder_, decodeHeaders_(_, _)) - .WillOnce(Invoke([this](RequestHeaderMapPtr& headers, bool) -> void { + .WillOnce(Invoke([this](RequestHeaderMapSharedPtr& headers, bool) -> void { auto result = header_validator_->validateRequestHeaderMap(*headers); ASSERT_FALSE(result.ok()); response_encoder_->encodeHeaders(TestResponseHeaderMapImpl{{":status", "400"}, @@ -2789,7 +2789,7 @@ TEST_P(Http2CodecImplTest, HeaderNameWithUnderscoreAllowed) { #ifdef ENVOY_ENABLE_UHV // Header validation is done by the HCM when header map is fully parsed. EXPECT_CALL(request_decoder_, decodeHeaders_(_, _)) - .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapPtr& headers, bool) -> void { + .WillOnce(Invoke([this, &expected_headers](RequestHeaderMapSharedPtr& headers, bool) -> void { auto result = header_validator_->validateRequestHeaderMap(*headers); EXPECT_THAT(headers, HeaderMapEqualIgnoreOrder(&expected_headers)); ASSERT_TRUE(result.ok());