Skip to content

dfp: adding timing information about DNS resolution #18934

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
alyssawilk merged 9 commits into from
Nov 17, 2021
Merged

dfp: adding timing information about DNS resolution #18934

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
6bd5c2d
dfp: adding timing information about DNS resolution
alyssawilk Nov 8, 2021
18e4576
coverage
alyssawilk Nov 8, 2021
b930d82
rework
alyssawilk Nov 9, 2021
593e8c8
Merge branch 'main' into dfp
alyssawilk Nov 11, 2021
1cbb49d
comments
alyssawilk Nov 11, 2021
3af9872
fix all the mocks
alyssawilk Nov 11, 2021
06eee94
Merge branch 'main' into dfp
alyssawilk Nov 15, 2021
f86b33b
Merge branch 'main' into dfp
alyssawilk Nov 15, 2021
efc9af1
comment
alyssawilk Nov 16, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions envoy/stream_info/stream_info.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -240,6 +240,16 @@ struct UpstreamTiming {

class DownstreamTiming {
public:
void setValue(absl::string_view key, MonotonicTime value) { timings_[key] = value; }

@mattklein123 mattklein123 Nov 16, 2021

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we assert that we don't set a value twice? Not sure.

@alyssawilk alyssawilk Nov 16, 2021

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah I didn't know if folks using this would want to do updates, so left without.


absl::optional<MonotonicTime> getValue(absl::string_view value) const {
auto ret = timings_.find(value);
if (ret == timings_.end()) {
return {};
}
return ret->second;
}

absl::optional<MonotonicTime> lastDownstreamRxByteReceived() const {
return last_downstream_rx_byte_received_;
}
Expand Down
11 changes: 11 additions & 0 deletions source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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
Expand All @@ -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:
Expand Down Expand Up @@ -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();

Expand Down
3 changes: 3 additions & 0 deletions source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
1 change: 1 addition & 0 deletions test/extensions/filters/http/dynamic_forward_proxy/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
10 changes: 10 additions & 0 deletions test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_integration_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand Down Expand Up @@ -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
Expand Down
38 changes: 34 additions & 4 deletions test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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, _))
Expand All @@ -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, _))
Expand All @@ -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}));
Expand All @@ -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, _))
Expand Down Expand Up @@ -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}));
Expand Down Expand Up @@ -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}));
Expand Down Expand Up @@ -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}));
Expand Down Expand Up @@ -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&) {
Expand All @@ -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));
Expand All @@ -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();
Expand All @@ -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&) {
Expand All @@ -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>(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<StreamInfo::UpstreamAddress>(
Expand Down Expand Up @@ -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};
Expand All @@ -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));

Expand Down
20 changes: 20 additions & 0 deletions test/integration/filters/stream_info_to_headers_filter.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,13 @@
#include "gtest/gtest.h"

namespace Envoy {
namespace {

uint64_t toMs(MonotonicTime time) {
return std::chrono::duration_cast<std::chrono::seconds>(time.time_since_epoch()).count();
}

} // namespace

// A filter that sticks stream info into headers for integration testing.
class StreamInfoToHeadersFilter : public Http::PassThroughFilter {
Expand All @@ -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());
Expand Down