diff --git a/envoy/stream_info/stream_info.h b/envoy/stream_info/stream_info.h index 9d187570300b8..90062c43902ba 100644 --- a/envoy/stream_info/stream_info.h +++ b/envoy/stream_info/stream_info.h @@ -240,6 +240,16 @@ struct UpstreamTiming { class DownstreamTiming { public: + void setValue(absl::string_view key, MonotonicTime value) { timings_[key] = value; } + + absl::optional getValue(absl::string_view value) const { + auto ret = timings_.find(value); + if (ret == timings_.end()) { + return {}; + } + return ret->second; + } + absl::optional lastDownstreamRxByteReceived() const { return last_downstream_rx_byte_received_; } diff --git a/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc b/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc index a25f157ea9eae..15d817c9b05bc 100644 --- a/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc +++ b/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc @@ -12,7 +12,15 @@ namespace Envoy { namespace Extensions { namespace HttpFilters { namespace DynamicForwardProxy { +namespace { +void latchTime(Http::StreamDecoderFilterCallbacks* decoder_callbacks, absl::string_view key) { + StreamInfo::DownstreamTiming& downstream_timing = + decoder_callbacks->streamInfo().downstreamTiming(); + downstream_timing.setValue(key, decoder_callbacks->dispatcher().timeSource().monotonicTime()); +} + +} // namespace struct ResponseStringValues { const std::string DnsCacheOverflow = "DNS cache overflow"; const std::string PendingRequestOverflow = "Dynamic forward proxy pending request overflow"; @@ -110,6 +118,7 @@ Http::FilterHeadersStatus ProxyFilter::decodeHeaders(Http::RequestHeaderMap& hea } } + latchTime(decoder_callbacks_, DNS_START); // See the comments in dns_cache.h for how loadDnsCacheEntry() handles hosts with embedded ports. // TODO(mattklein123): Because the filter and cluster have independent configuration, it is // not obvious to the user if something is misconfigured. We should see if @@ -132,6 +141,7 @@ Http::FilterHeadersStatus ProxyFilter::decodeHeaders(Http::RequestHeaderMap& hea addHostAddressToFilterState(host.value()->address()); } + latchTime(decoder_callbacks_, DNS_END); return Http::FilterHeadersStatus::Continue; } case LoadDnsCacheEntryStatus::Loading: @@ -183,6 +193,7 @@ void ProxyFilter::onLoadDnsCacheComplete( const Common::DynamicForwardProxy::DnsHostInfoSharedPtr& host_info) { ENVOY_STREAM_LOG(debug, "load DNS cache complete, continuing after adding resolved host: {}", *decoder_callbacks_, host_info->resolvedHost()); + latchTime(decoder_callbacks_, DNS_END); ASSERT(circuit_breaker_ != nullptr); circuit_breaker_.reset(); diff --git a/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.h b/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.h index a0920e553c704..0bc97e646d328 100644 --- a/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.h +++ b/source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.h @@ -51,6 +51,9 @@ class ProxyFilter public: ProxyFilter(const ProxyFilterConfigSharedPtr& config) : config_(config) {} + static constexpr absl::string_view DNS_START = "envoy.dynamic_forward_proxy.dns_start_ms"; + static constexpr absl::string_view DNS_END = "envoy.dynamic_forward_proxy.dns_end_ms"; + // Http::PassThroughDecoderFilter Http::FilterHeadersStatus decodeHeaders(Http::RequestHeaderMap& headers, bool end_stream) override; diff --git a/test/extensions/filters/http/dynamic_forward_proxy/BUILD b/test/extensions/filters/http/dynamic_forward_proxy/BUILD index ec2a0c9534eda..1dcafd08831a5 100644 --- a/test/extensions/filters/http/dynamic_forward_proxy/BUILD +++ b/test/extensions/filters/http/dynamic_forward_proxy/BUILD @@ -57,6 +57,7 @@ envoy_extension_cc_test( "//source/extensions/filters/http/dynamic_forward_proxy:config", "//source/extensions/key_value/file_based:config_lib", "//test/integration:http_integration_lib", + "//test/integration/filters:stream_info_to_headers_filter_lib", "@envoy_api//envoy/config/bootstrap/v3:pkg_cc_proto", "@envoy_api//envoy/config/cluster/v3:pkg_cc_proto", "@envoy_api//envoy/extensions/filters/network/http_connection_manager/v3:pkg_cc_proto", diff --git a/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_integration_test.cc b/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_integration_test.cc index b8d03fa681b98..b9829dd6286d0 100644 --- a/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_integration_test.cc +++ b/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_integration_test.cc @@ -43,6 +43,10 @@ name: dynamic_forward_proxy max_hosts, max_pending_requests, filename); config_helper_.prependFilter(filter); + config_helper_.prependFilter(fmt::format(R"EOF( +name: stream-info-to-headers-filter +typed_config: + "@type": type.googleapis.com/google.protobuf.Empty)EOF")); config_helper_.addConfigModifier([this](envoy::config::bootstrap::v3::Bootstrap& bootstrap) { // Switch predefined cluster_0 to CDS filesystem sourcing. bootstrap.mutable_dynamic_resources()->mutable_cds_config()->set_resource_api_version( @@ -174,12 +178,18 @@ TEST_P(ProxyFilterIntegrationTest, RequestWithBody) { checkSimpleRequestSuccess(1024, 1024, response.get()); EXPECT_EQ(1, test_server_->counter("dns_cache.foo.dns_query_attempt")->value()); EXPECT_EQ(1, test_server_->counter("dns_cache.foo.host_added")->value()); + // Make sure dns timings are tracked for cache-misses. + ASSERT_FALSE(response->headers().get(Http::LowerCaseString("dns_start")).empty()); + ASSERT_FALSE(response->headers().get(Http::LowerCaseString("dns_end")).empty()); // Now send another request. This should hit the DNS cache. response = sendRequestAndWaitForResponse(request_headers, 512, default_response_headers_, 512); checkSimpleRequestSuccess(512, 512, response.get()); EXPECT_EQ(1, test_server_->counter("dns_cache.foo.dns_query_attempt")->value()); EXPECT_EQ(1, test_server_->counter("dns_cache.foo.host_added")->value()); + // Make sure dns timings are tracked for cache-hits. + ASSERT_FALSE(response->headers().get(Http::LowerCaseString("dns_start")).empty()); + ASSERT_FALSE(response->headers().get(Http::LowerCaseString("dns_end")).empty()); } // Currently if the first DNS resolution fails, the filter will continue with diff --git a/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_test.cc b/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_test.cc index c2150e500dd91..6c6413066ceb8 100644 --- a/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_test.cc +++ b/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_test.cc @@ -103,6 +103,9 @@ TEST_F(ProxyFilterTest, HttpDefaultPort) { EXPECT_CALL(*dns_cache_manager_->dns_cache_, canCreateDnsRequest_()) .WillOnce(Return(circuit_breakers_)); EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(false)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); + Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle* handle = new Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle(); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 80, _)) @@ -126,6 +129,9 @@ TEST_F(ProxyFilterTest, HttpsDefaultPort) { EXPECT_CALL(*dns_cache_manager_->dns_cache_, canCreateDnsRequest_()) .WillOnce(Return(circuit_breakers_)); EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(true)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); + Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle* handle = new Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle(); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 443, _)) @@ -149,6 +155,9 @@ TEST_F(ProxyFilterTest, CacheOverflow) { EXPECT_CALL(*dns_cache_manager_->dns_cache_, canCreateDnsRequest_()) .WillOnce(Return(circuit_breakers_)); EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(true)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); + EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 443, _)) .WillOnce(Return( MockLoadDnsCacheEntryResult{LoadDnsCacheEntryStatus::Overflow, nullptr, absl::nullopt})); @@ -173,6 +182,8 @@ TEST_F(ProxyFilterTest, CircuitBreakerOverflow) { EXPECT_CALL(*dns_cache_manager_->dns_cache_, canCreateDnsRequest_()) .WillOnce(Return(circuit_breakers_)); EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(true)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle* handle = new Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle(); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 443, _)) @@ -213,6 +224,8 @@ TEST_F(ProxyFilterTest, CircuitBreakerOverflowWithDnsCacheResourceManager) { EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(true)); Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle* handle = new Extensions::Common::DynamicForwardProxy::MockLoadDnsCacheEntryHandle(); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 443, _)) .WillOnce(Return( MockLoadDnsCacheEntryResult{LoadDnsCacheEntryStatus::Loading, handle, absl::nullopt})); @@ -301,6 +314,8 @@ TEST_F(ProxyFilterTest, HostRewrite) { EXPECT_CALL(*callbacks_.route_, mostSpecificPerFilterConfig("envoy.filters.http.dynamic_forward_proxy")) .WillOnce(Return(&config)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("bar"), 80, _)) .WillOnce(Return( MockLoadDnsCacheEntryResult{LoadDnsCacheEntryStatus::Loading, handle, absl::nullopt})); @@ -330,6 +345,8 @@ TEST_F(ProxyFilterTest, HostRewriteViaHeader) { EXPECT_CALL(*callbacks_.route_, mostSpecificPerFilterConfig("envoy.filters.http.dynamic_forward_proxy")) .WillOnce(Return(&config)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("bar:82"), 80, _)) .WillOnce(Return( MockLoadDnsCacheEntryResult{LoadDnsCacheEntryStatus::Loading, handle, absl::nullopt})); @@ -377,6 +394,8 @@ TEST_F(UpstreamResolvedHostFilterStateHelper, AddResolvedHostFilterStateMetadata EXPECT_CALL(*dns_cache_manager_->dns_cache_, canCreateDnsRequest_()) .WillOnce(Return(circuit_breakers_)); EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(false)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 80, _)) .WillOnce(Invoke([&](absl::string_view, uint16_t, ProxyFilter::LoadDnsCacheEntryCallbacks&) { @@ -393,6 +412,8 @@ TEST_F(UpstreamResolvedHostFilterStateHelper, AddResolvedHostFilterStateMetadata EXPECT_CALL(*host_info, address()); EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); // Host was resolved successfully, so continue filter iteration. EXPECT_EQ(Http::FilterHeadersStatus::Continue, filter_->decodeHeaders(request_headers_, false)); @@ -410,7 +431,7 @@ TEST_F(UpstreamResolvedHostFilterStateHelper, UpdateResolvedHostFilterStateMetad Upstream::ResourceAutoIncDec* circuit_breakers_( new Upstream::ResourceAutoIncDec(pending_requests_)); - EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, streamInfo()).Times(testing::AnyNumber()); // Pre-populate the filter state with an address. auto& filter_state = callbacks_.streamInfo().filterState(); @@ -432,6 +453,8 @@ TEST_F(UpstreamResolvedHostFilterStateHelper, UpdateResolvedHostFilterStateMetad EXPECT_CALL(*dns_cache_manager_->dns_cache_, canCreateDnsRequest_()) .WillOnce(Return(circuit_breakers_)); EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(false)); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 80, _)) .WillOnce(Invoke([&](absl::string_view, uint16_t, ProxyFilter::LoadDnsCacheEntryCallbacks&) { @@ -447,14 +470,18 @@ TEST_F(UpstreamResolvedHostFilterStateHelper, UpdateResolvedHostFilterStateMetad EXPECT_CALL(*host_info, address()); + EXPECT_CALL(callbacks_, dispatcher()); + EXPECT_CALL(callbacks_, streamInfo()); EXPECT_CALL(callbacks_, streamInfo()); // Host was resolved successfully, so continue filter iteration. EXPECT_EQ(Http::FilterHeadersStatus::Continue, filter_->decodeHeaders(request_headers_, false)); - // We expect FilterState to be populated + // We expect FilterState and resolution times to be populated EXPECT_TRUE( - filter_state->hasData(StreamInfo::UpstreamAddress::key())); + callbacks_.streamInfo().downstreamTiming().getValue(ProxyFilter::DNS_START).has_value()); + EXPECT_TRUE( + callbacks_.streamInfo().downstreamTiming().getValue(ProxyFilter::DNS_END).has_value()); const StreamInfo::UpstreamAddress& updated_address_obj = filter_state->getDataReadOnly( @@ -487,7 +514,8 @@ TEST_F(UpstreamResolvedHostFilterStateHelper, IgnoreFilterStateMetadataNullAddre EXPECT_CALL(*dns_cache_manager_->dns_cache_, canCreateDnsRequest_()) .WillOnce(Return(circuit_breakers_)); EXPECT_CALL(*transport_socket_factory_, implementsSecureTransport()).WillOnce(Return(false)); - + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); EXPECT_CALL(*dns_cache_manager_->dns_cache_, loadDnsCacheEntry_(Eq("foo"), 80, _)) .WillOnce(Invoke([&](absl::string_view, uint16_t, ProxyFilter::LoadDnsCacheEntryCallbacks&) { return MockLoadDnsCacheEntryResult{LoadDnsCacheEntryStatus::InCache, nullptr, host_info}; @@ -501,6 +529,8 @@ TEST_F(UpstreamResolvedHostFilterStateHelper, IgnoreFilterStateMetadataNullAddre })); EXPECT_CALL(*host_info, address()); + EXPECT_CALL(callbacks_, streamInfo()); + EXPECT_CALL(callbacks_, dispatcher()); EXPECT_EQ(Http::FilterHeadersStatus::Continue, filter_->decodeHeaders(request_headers_, false)); diff --git a/test/integration/filters/stream_info_to_headers_filter.cc b/test/integration/filters/stream_info_to_headers_filter.cc index 30aedfe2b6212..8b9bd4f2fd158 100644 --- a/test/integration/filters/stream_info_to_headers_filter.cc +++ b/test/integration/filters/stream_info_to_headers_filter.cc @@ -9,6 +9,13 @@ #include "gtest/gtest.h" namespace Envoy { +namespace { + +uint64_t toMs(MonotonicTime time) { + return std::chrono::duration_cast(time.time_since_epoch()).count(); +} + +} // namespace // A filter that sticks stream info into headers for integration testing. class StreamInfoToHeadersFilter : public Http::PassThroughFilter { @@ -20,6 +27,19 @@ class StreamInfoToHeadersFilter : public Http::PassThroughFilter { } Http::FilterHeadersStatus encodeHeaders(Http::ResponseHeaderMap& headers, bool) override { + const std::string dns_start = "envoy.dynamic_forward_proxy.dns_start_ms"; + const std::string dns_end = "envoy.dynamic_forward_proxy.dns_end_ms"; + StreamInfo::StreamInfo& stream_info = decoder_callbacks_->streamInfo(); + + if (stream_info.downstreamTiming().getValue(dns_start).has_value()) { + headers.addCopy( + Http::LowerCaseString("dns_start"), + absl::StrCat(toMs(stream_info.downstreamTiming().getValue(dns_start).value()))); + } + if (stream_info.downstreamTiming().getValue(dns_end).has_value()) { + headers.addCopy(Http::LowerCaseString("dns_end"), + absl::StrCat(toMs(stream_info.downstreamTiming().getValue(dns_end).value()))); + } if (decoder_callbacks_->streamInfo().upstreamSslConnection()) { headers.addCopy(Http::LowerCaseString("alpn"), decoder_callbacks_->streamInfo().upstreamSslConnection()->alpn());