From f85d68db7ff5fc173369259d98744d28b36a6855 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 2 May 2018 17:43:49 +0700 Subject: [PATCH 01/46] router: add start timestamp header config Signed-off-by: Dhi Aurrahman --- .../config/filter/http/router/v2/router.proto | 11 ++++ source/common/http/async_client_impl.cc | 2 +- source/common/router/router.cc | 5 ++ source/common/router/router.h | 8 ++- test/common/router/router_test.cc | 57 ++++++++++++++++++- 5 files changed, 77 insertions(+), 6 deletions(-) diff --git a/api/envoy/config/filter/http/router/v2/router.proto b/api/envoy/config/filter/http/router/v2/router.proto index a334c62c48e6c..ce0738ccd97f5 100644 --- a/api/envoy/config/filter/http/router/v2/router.proto +++ b/api/envoy/config/filter/http/router/v2/router.proto @@ -26,4 +26,15 @@ message Router { // an upstream request. Presuming retries are configured, multiple upstream // requests may be made for each downstream (inbound) request. repeated envoy.config.filter.accesslog.v2.AccessLog upstream_log = 3; + + // If set, the specified header will be added to upstream requests with a timestamp + // (in milliseconds) when Envoy starts decoding downstream's request headers. + // + // Example: + // + // .. code-block:: yaml + // + // start_timestamp_header: x-request-start + // + string start_timestamp_header = 4; } diff --git a/source/common/http/async_client_impl.cc b/source/common/http/async_client_impl.cc index ba46b5bf18e95..2a0b67d8b0e69 100644 --- a/source/common/http/async_client_impl.cc +++ b/source/common/http/async_client_impl.cc @@ -34,7 +34,7 @@ AsyncClientImpl::AsyncClientImpl(const Upstream::ClusterInfo& cluster, Stats::St Runtime::RandomGenerator& random, Router::ShadowWriterPtr&& shadow_writer) : cluster_(cluster), config_("http.async-client.", local_info, stats_store, cm, runtime, random, - std::move(shadow_writer), true, false), + std::move(shadow_writer), true, false, EMPTY_STRING), dispatcher_(dispatcher) {} AsyncClientImpl::~AsyncClientImpl() { diff --git a/source/common/router/router.cc b/source/common/router/router.cc index d627135668f94..daf9fadece133 100644 --- a/source/common/router/router.cc +++ b/source/common/router/router.cc @@ -192,6 +192,11 @@ void Filter::sendLocalReply(Http::Code code, const std::string& body, Http::FilterHeadersStatus Filter::decodeHeaders(Http::HeaderMap& headers, bool end_stream) { downstream_headers_ = &headers; + if (!config_.start_timestamp_header_.get().empty()) { + headers.addReferenceKey(config_.start_timestamp_header_, + std::chrono::system_clock::now().time_since_epoch().count()); + } + // Only increment rq total stat if we actually decode headers here. This does not count requests // that get handled by earlier filters. config_.stats_.rq_total_.inc(); diff --git a/source/common/router/router.h b/source/common/router/router.h index 91f266ca76834..5c2f99c02362a 100644 --- a/source/common/router/router.h +++ b/source/common/router/router.h @@ -89,11 +89,12 @@ class FilterConfig { FilterConfig(const std::string& stat_prefix, const LocalInfo::LocalInfo& local_info, Stats::Scope& scope, Upstream::ClusterManager& cm, Runtime::Loader& runtime, Runtime::RandomGenerator& random, ShadowWriterPtr&& shadow_writer, - bool emit_dynamic_stats, bool start_child_span) + bool emit_dynamic_stats, bool start_child_span, + const std::string& start_timestamp_header) : scope_(scope), local_info_(local_info), cm_(cm), runtime_(runtime), random_(random), stats_{ALL_ROUTER_STATS(POOL_COUNTER_PREFIX(scope, stat_prefix))}, emit_dynamic_stats_(emit_dynamic_stats), start_child_span_(start_child_span), - shadow_writer_(std::move(shadow_writer)) {} + start_timestamp_header_(start_timestamp_header), shadow_writer_(std::move(shadow_writer)) {} FilterConfig(const std::string& stat_prefix, Server::Configuration::FactoryContext& context, ShadowWriterPtr&& shadow_writer, @@ -101,7 +102,7 @@ class FilterConfig { : FilterConfig(stat_prefix, context.localInfo(), context.scope(), context.clusterManager(), context.runtime(), context.random(), std::move(shadow_writer), PROTOBUF_GET_WRAPPED_OR_DEFAULT(config, dynamic_stats, true), - config.start_child_span()) { + config.start_child_span(), config.start_timestamp_header()) { for (const auto& upstream_log : config.upstream_log()) { upstream_logs_.push_back(AccessLog::AccessLogFactory::fromProto(upstream_log, context)); } @@ -118,6 +119,7 @@ class FilterConfig { const bool emit_dynamic_stats_; const bool start_child_span_; std::list upstream_logs_; + const Http::LowerCaseString start_timestamp_header_; private: ShadowWriterPtr shadow_writer_; diff --git a/test/common/router/router_test.cc b/test/common/router/router_test.cc index 9ba3ef06697e8..891ea720a328a 100644 --- a/test/common/router/router_test.cc +++ b/test/common/router/router_test.cc @@ -63,10 +63,10 @@ class TestFilter : public Filter { class RouterTestBase : public testing::Test { public: - RouterTestBase(bool start_child_span) + RouterTestBase(bool start_child_span, const std::string& start_timestamp_header = EMPTY_STRING) : shadow_writer_(new MockShadowWriter()), config_("test.", local_info_, stats_store_, cm_, runtime_, random_, - ShadowWriterPtr{shadow_writer_}, true, start_child_span), + ShadowWriterPtr{shadow_writer_}, true, start_child_span, start_timestamp_header), router_(config_) { router_.setDecoderFilterCallbacks(callbacks_); upstream_locality_.set_zone("to_az"); @@ -1628,6 +1628,28 @@ TEST_F(RouterTest, DirectResponseWithBody) { EXPECT_EQ(1UL, config_.stats_.rq_direct_response_.value()); } +TEST_F(RouterTest, NoStartTimestampHeader) { + absl::optional downstream_protocol{Http::Protocol::Http2}; + EXPECT_CALL(*cm_.thread_local_cluster_.cluster_.info_, features()) + .WillOnce(Return(Upstream::ClusterInfo::Features::USE_DOWNSTREAM_PROTOCOL)); + EXPECT_CALL(callbacks_.request_info_, protocol()).WillOnce(ReturnPointee(&downstream_protocol)); + + EXPECT_CALL(cm_, httpConnPoolForCluster(_, _, Http::Protocol::Http2, _)); + EXPECT_CALL(cm_.conn_pool_, newStream(_, _)).WillOnce(Return(&cancellable_)); + expectResponseTimerCreate(); + + Http::TestHeaderMapImpl headers; + HttpTestUtility::addDefaultHeaders(headers); + router_.decodeHeaders(headers, true); + + const Http::LowerCaseString header("x-request-start"); + EXPECT_EQ(nullptr, headers.get(header)); + + EXPECT_CALL(cancellable_, cancel()); + router_.onDestroy(); + EXPECT_TRUE(verifyHostUpstreamStats(0, 0)); +} + TEST(RouterFilterUtilityTest, finalTimeout) { { NiceMock route; @@ -2117,5 +2139,36 @@ TEST_F(RouterTestChildSpan, ResetFlow) { encoder.stream_.resetStream(Http::StreamResetReason::RemoteReset); } +class RouterTestStartTimestampHeader : public RouterTestBase { +public: + RouterTestStartTimestampHeader() : RouterTestBase(false, "X-Request-Start") {} +}; + +TEST_F(RouterTestStartTimestampHeader, WithStartTimestampHeader) { + absl::optional downstream_protocol{Http::Protocol::Http2}; + EXPECT_CALL(*cm_.thread_local_cluster_.cluster_.info_, features()) + .WillOnce(Return(Upstream::ClusterInfo::Features::USE_DOWNSTREAM_PROTOCOL)); + EXPECT_CALL(callbacks_.request_info_, protocol()).WillOnce(ReturnPointee(&downstream_protocol)); + + EXPECT_CALL(cm_, httpConnPoolForCluster(_, _, Http::Protocol::Http2, _)); + EXPECT_CALL(cm_.conn_pool_, newStream(_, _)).WillOnce(Return(&cancellable_)); + expectResponseTimerCreate(); + + Http::TestHeaderMapImpl headers; + HttpTestUtility::addDefaultHeaders(headers); + router_.decodeHeaders(headers, true); + + const Http::LowerCaseString header("x-request-start"); + EXPECT_NE(nullptr, headers.get(header)); + + uint64_t timestamp; + StringUtil::atoul(headers.get(header)->value().c_str(), timestamp); + EXPECT_GT(timestamp, 0); + + EXPECT_CALL(cancellable_, cancel()); + router_.onDestroy(); + EXPECT_TRUE(verifyHostUpstreamStats(0, 0)); +} + } // namespace Router } // namespace Envoy From b0b741b37ea6f056e6a51368063fbd08b5a3e782 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 2 May 2018 17:45:08 +0700 Subject: [PATCH 02/46] docs: update release notes Signed-off-by: Dhi Aurrahman --- docs/root/intro/version_history.rst | 3 +++ 1 file changed, 3 insertions(+) diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 4f716424d7849..7771838092037 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -53,6 +53,9 @@ Version history * logger: added the ability to optionally set the log format via the :option:`--log-format` option. * logger: all :ref:`logging levels ` can be configured at run-time: trace debug info warning error critical. +* router: added the optional + :ref:`start timestamp header` + to send timestamp (in milliseconds) as the value of the specified header in upstream requests. * sockets: added `IP_FREEBIND` socket option support for :ref:`listeners ` and upstream connections via :ref:`cluster manager wide From 4c80a6d882dfd1722f6e70dd70eab852dc9e3741 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 8 May 2018 11:54:53 +0700 Subject: [PATCH 03/46] review: add comment https://github.com/envoyproxy/envoy/pull/3269#discussion_r186580191 Signed-off-by: Dhi Aurrahman --- source/common/router/router.cc | 1 + 1 file changed, 1 insertion(+) diff --git a/source/common/router/router.cc b/source/common/router/router.cc index daf9fadece133..840fab767455e 100644 --- a/source/common/router/router.cc +++ b/source/common/router/router.cc @@ -192,6 +192,7 @@ void Filter::sendLocalReply(Http::Code code, const std::string& body, Http::FilterHeadersStatus Filter::decodeHeaders(Http::HeaderMap& headers, bool end_stream) { downstream_headers_ = &headers; + // If defined, set the specified start timestamp header with timestamp in milliseconds. if (!config_.start_timestamp_header_.get().empty()) { headers.addReferenceKey(config_.start_timestamp_header_, std::chrono::system_clock::now().time_since_epoch().count()); From 3110ce021bb11d97db24c1890e8cef8fe7982e25 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 8 May 2018 11:55:26 +0700 Subject: [PATCH 04/46] review: test that the x-request-start header is not present before the call to decodeHeaders https://github.com/envoyproxy/envoy/pull/3269#discussion_r186587611 Signed-off-by: Dhi Aurrahman --- test/common/router/router_test.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/common/router/router_test.cc b/test/common/router/router_test.cc index 891ea720a328a..595b46d15d22d 100644 --- a/test/common/router/router_test.cc +++ b/test/common/router/router_test.cc @@ -2156,9 +2156,9 @@ TEST_F(RouterTestStartTimestampHeader, WithStartTimestampHeader) { Http::TestHeaderMapImpl headers; HttpTestUtility::addDefaultHeaders(headers); - router_.decodeHeaders(headers, true); - const Http::LowerCaseString header("x-request-start"); + EXPECT_EQ(nullptr, headers.get(header)); + router_.decodeHeaders(headers, true); EXPECT_NE(nullptr, headers.get(header)); uint64_t timestamp; From 42bd291e5b4233d86a152982a4871b9344720ac7 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 9 May 2018 09:06:30 +0700 Subject: [PATCH 05/46] review: use header manipulation facility instead Signed-off-by: Dhi Aurrahman --- .../config/filter/http/router/v2/router.proto | 11 ---- .../configuration/http_conn_man/headers.rst | 3 + docs/root/intro/version_history.rst | 5 +- source/common/http/async_client_impl.cc | 2 +- source/common/router/header_formatter.cc | 7 +++ source/common/router/router.cc | 6 -- source/common/router/router.h | 8 +-- test/common/router/header_formatter_test.cc | 22 +++++++ test/common/router/router_test.cc | 57 +------------------ 9 files changed, 40 insertions(+), 81 deletions(-) diff --git a/api/envoy/config/filter/http/router/v2/router.proto b/api/envoy/config/filter/http/router/v2/router.proto index ce0738ccd97f5..a334c62c48e6c 100644 --- a/api/envoy/config/filter/http/router/v2/router.proto +++ b/api/envoy/config/filter/http/router/v2/router.proto @@ -26,15 +26,4 @@ message Router { // an upstream request. Presuming retries are configured, multiple upstream // requests may be made for each downstream (inbound) request. repeated envoy.config.filter.accesslog.v2.AccessLog upstream_log = 3; - - // If set, the specified header will be added to upstream requests with a timestamp - // (in milliseconds) when Envoy starts decoding downstream's request headers. - // - // Example: - // - // .. code-block:: yaml - // - // start_timestamp_header: x-request-start - // - string start_timestamp_header = 4; } diff --git a/docs/root/configuration/http_conn_man/headers.rst b/docs/root/configuration/http_conn_man/headers.rst index 282b32023080a..4e810634d4db2 100644 --- a/docs/root/configuration/http_conn_man/headers.rst +++ b/docs/root/configuration/http_conn_man/headers.rst @@ -480,3 +480,6 @@ Supported variable names are: found, or if the selected value is not a supported type, then no header is emitted. The namespace and key(s) are specified as a JSON array of strings. Finally, percent symbols in the parameters **do not** need to be escaped by doubling them. + +%START_TIMESTAMP% + The timestamp when the first byte of a request is received. The timestamp unit is in milliseconds. diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 7771838092037..be0fedce0b332 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -53,9 +53,8 @@ Version history * logger: added the ability to optionally set the log format via the :option:`--log-format` option. * logger: all :ref:`logging levels ` can be configured at run-time: trace debug info warning error critical. -* router: added the optional - :ref:`start timestamp header` - to send timestamp (in milliseconds) as the value of the specified header in upstream requests. +* router: added `START_TIMESTAMP` as one of supported variables in :ref:`header + formatters `. The timestamp unit is in milliseconds. * sockets: added `IP_FREEBIND` socket option support for :ref:`listeners ` and upstream connections via :ref:`cluster manager wide diff --git a/source/common/http/async_client_impl.cc b/source/common/http/async_client_impl.cc index 2a0b67d8b0e69..ba46b5bf18e95 100644 --- a/source/common/http/async_client_impl.cc +++ b/source/common/http/async_client_impl.cc @@ -34,7 +34,7 @@ AsyncClientImpl::AsyncClientImpl(const Upstream::ClusterInfo& cluster, Stats::St Runtime::RandomGenerator& random, Router::ShadowWriterPtr&& shadow_writer) : cluster_(cluster), config_("http.async-client.", local_info, stats_store, cm, runtime, random, - std::move(shadow_writer), true, false, EMPTY_STRING), + std::move(shadow_writer), true, false), dispatcher_(dispatcher) {} AsyncClientImpl::~AsyncClientImpl() { diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 8770534d42cd6..66b6aec6a1be2 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -135,6 +135,13 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n return RequestInfo::Utility::formatDownstreamAddressNoPort( *request_info.downstreamLocalAddress()); }; + } else if (field_name == "START_TIMESTAMP") { + field_extractor_ = [](const RequestInfo::RequestInfo& request_info) { + // Returns the start timestamp in milliseconds. + return fmt::format("{}", std::chrono::duration_cast( + request_info.startTime().time_since_epoch()) + .count()); + }; } else if (field_name.find_first_of("UPSTREAM_METADATA") == 0) { field_extractor_ = parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA"))); diff --git a/source/common/router/router.cc b/source/common/router/router.cc index 840fab767455e..d627135668f94 100644 --- a/source/common/router/router.cc +++ b/source/common/router/router.cc @@ -192,12 +192,6 @@ void Filter::sendLocalReply(Http::Code code, const std::string& body, Http::FilterHeadersStatus Filter::decodeHeaders(Http::HeaderMap& headers, bool end_stream) { downstream_headers_ = &headers; - // If defined, set the specified start timestamp header with timestamp in milliseconds. - if (!config_.start_timestamp_header_.get().empty()) { - headers.addReferenceKey(config_.start_timestamp_header_, - std::chrono::system_clock::now().time_since_epoch().count()); - } - // Only increment rq total stat if we actually decode headers here. This does not count requests // that get handled by earlier filters. config_.stats_.rq_total_.inc(); diff --git a/source/common/router/router.h b/source/common/router/router.h index 5c2f99c02362a..91f266ca76834 100644 --- a/source/common/router/router.h +++ b/source/common/router/router.h @@ -89,12 +89,11 @@ class FilterConfig { FilterConfig(const std::string& stat_prefix, const LocalInfo::LocalInfo& local_info, Stats::Scope& scope, Upstream::ClusterManager& cm, Runtime::Loader& runtime, Runtime::RandomGenerator& random, ShadowWriterPtr&& shadow_writer, - bool emit_dynamic_stats, bool start_child_span, - const std::string& start_timestamp_header) + bool emit_dynamic_stats, bool start_child_span) : scope_(scope), local_info_(local_info), cm_(cm), runtime_(runtime), random_(random), stats_{ALL_ROUTER_STATS(POOL_COUNTER_PREFIX(scope, stat_prefix))}, emit_dynamic_stats_(emit_dynamic_stats), start_child_span_(start_child_span), - start_timestamp_header_(start_timestamp_header), shadow_writer_(std::move(shadow_writer)) {} + shadow_writer_(std::move(shadow_writer)) {} FilterConfig(const std::string& stat_prefix, Server::Configuration::FactoryContext& context, ShadowWriterPtr&& shadow_writer, @@ -102,7 +101,7 @@ class FilterConfig { : FilterConfig(stat_prefix, context.localInfo(), context.scope(), context.clusterManager(), context.runtime(), context.random(), std::move(shadow_writer), PROTOBUF_GET_WRAPPED_OR_DEFAULT(config, dynamic_stats, true), - config.start_child_span(), config.start_timestamp_header()) { + config.start_child_span()) { for (const auto& upstream_log : config.upstream_log()) { upstream_logs_.push_back(AccessLog::AccessLogFactory::fromProto(upstream_log, context)); } @@ -119,7 +118,6 @@ class FilterConfig { const bool emit_dynamic_stats_; const bool start_child_span_; std::list upstream_logs_; - const Http::LowerCaseString start_timestamp_header_; private: ShadowWriterPtr shadow_writer_; diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index 7b85846801b63..377e83c8dc9ca 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -16,6 +16,7 @@ #include "gtest/gtest.h" using testing::NiceMock; +using testing::Return; using testing::ReturnPointee; using testing::ReturnRef; @@ -595,6 +596,10 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { { "key": "x-client-ip", "value": "%CLIENT_IP%" + }, + { + "key": "x-request-start", + "value": "%START_TIMESTAMP%" } ] } @@ -604,6 +609,7 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { envoy::api::v2::route::RouteAction route_action = parseRouteFromJson(json).route(); route_action.mutable_request_headers_to_add(0)->mutable_append()->set_value(false); route_action.mutable_request_headers_to_add(1)->mutable_append()->set_value(false); + route_action.mutable_request_headers_to_add(2)->mutable_append()->set_value(false); HeaderParserPtr req_header_parser = Router::HeaderParser::configure(route_action.request_headers_to_add()); @@ -611,12 +617,22 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { {":method", "POST"}, {"static-header", "old-value"}, {"x-client-ip", "0.0.0.0"}}; NiceMock request_info; + time_t start_time_epoch = 1522280158; + SystemTime start_time = std::chrono::system_clock::from_time_t(start_time_epoch); + EXPECT_CALL(request_info, startTime()).WillOnce(Return(start_time)); + req_header_parser->evaluateHeaders(headerMap, request_info); EXPECT_TRUE(headerMap.has("static-header")); EXPECT_EQ("static-value", headerMap.get_("static-header")); EXPECT_TRUE(headerMap.has("x-client-ip")); EXPECT_EQ("127.0.0.1", headerMap.get_("x-client-ip")); + uint64_t timestamp; + StringUtil::atoul(headerMap.get_("x-request-start").c_str(), timestamp); + EXPECT_EQ( + timestamp, + std::chrono::duration_cast(start_time.time_since_epoch()).count()); + typedef std::map CountMap; CountMap counts; headerMap.iterate( @@ -635,6 +651,7 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { EXPECT_EQ(1, counts["static-header"]); EXPECT_EQ(1, counts["x-client-ip"]); + EXPECT_EQ(1, counts["x-request-start"]); } TEST(HeaderParserTest, EvaluateResponseHeaders) { @@ -647,6 +664,10 @@ match: { prefix: "/new_endpoint" } key: "x-client-ip" value: "%CLIENT_IP%" append: true + - header: + key: "x-request-start" + value: "%START_TIMESTAMP%" + append: true response_headers_to_remove: ["x-nope"] )EOF"; @@ -657,6 +678,7 @@ match: { prefix: "/new_endpoint" } NiceMock request_info; resp_header_parser->evaluateHeaders(headerMap, request_info); EXPECT_TRUE(headerMap.has("x-client-ip")); + EXPECT_TRUE(headerMap.has("x-request-start")); EXPECT_TRUE(headerMap.has("x-safe")); EXPECT_FALSE(headerMap.has("x-nope")); } diff --git a/test/common/router/router_test.cc b/test/common/router/router_test.cc index 595b46d15d22d..9ba3ef06697e8 100644 --- a/test/common/router/router_test.cc +++ b/test/common/router/router_test.cc @@ -63,10 +63,10 @@ class TestFilter : public Filter { class RouterTestBase : public testing::Test { public: - RouterTestBase(bool start_child_span, const std::string& start_timestamp_header = EMPTY_STRING) + RouterTestBase(bool start_child_span) : shadow_writer_(new MockShadowWriter()), config_("test.", local_info_, stats_store_, cm_, runtime_, random_, - ShadowWriterPtr{shadow_writer_}, true, start_child_span, start_timestamp_header), + ShadowWriterPtr{shadow_writer_}, true, start_child_span), router_(config_) { router_.setDecoderFilterCallbacks(callbacks_); upstream_locality_.set_zone("to_az"); @@ -1628,28 +1628,6 @@ TEST_F(RouterTest, DirectResponseWithBody) { EXPECT_EQ(1UL, config_.stats_.rq_direct_response_.value()); } -TEST_F(RouterTest, NoStartTimestampHeader) { - absl::optional downstream_protocol{Http::Protocol::Http2}; - EXPECT_CALL(*cm_.thread_local_cluster_.cluster_.info_, features()) - .WillOnce(Return(Upstream::ClusterInfo::Features::USE_DOWNSTREAM_PROTOCOL)); - EXPECT_CALL(callbacks_.request_info_, protocol()).WillOnce(ReturnPointee(&downstream_protocol)); - - EXPECT_CALL(cm_, httpConnPoolForCluster(_, _, Http::Protocol::Http2, _)); - EXPECT_CALL(cm_.conn_pool_, newStream(_, _)).WillOnce(Return(&cancellable_)); - expectResponseTimerCreate(); - - Http::TestHeaderMapImpl headers; - HttpTestUtility::addDefaultHeaders(headers); - router_.decodeHeaders(headers, true); - - const Http::LowerCaseString header("x-request-start"); - EXPECT_EQ(nullptr, headers.get(header)); - - EXPECT_CALL(cancellable_, cancel()); - router_.onDestroy(); - EXPECT_TRUE(verifyHostUpstreamStats(0, 0)); -} - TEST(RouterFilterUtilityTest, finalTimeout) { { NiceMock route; @@ -2139,36 +2117,5 @@ TEST_F(RouterTestChildSpan, ResetFlow) { encoder.stream_.resetStream(Http::StreamResetReason::RemoteReset); } -class RouterTestStartTimestampHeader : public RouterTestBase { -public: - RouterTestStartTimestampHeader() : RouterTestBase(false, "X-Request-Start") {} -}; - -TEST_F(RouterTestStartTimestampHeader, WithStartTimestampHeader) { - absl::optional downstream_protocol{Http::Protocol::Http2}; - EXPECT_CALL(*cm_.thread_local_cluster_.cluster_.info_, features()) - .WillOnce(Return(Upstream::ClusterInfo::Features::USE_DOWNSTREAM_PROTOCOL)); - EXPECT_CALL(callbacks_.request_info_, protocol()).WillOnce(ReturnPointee(&downstream_protocol)); - - EXPECT_CALL(cm_, httpConnPoolForCluster(_, _, Http::Protocol::Http2, _)); - EXPECT_CALL(cm_.conn_pool_, newStream(_, _)).WillOnce(Return(&cancellable_)); - expectResponseTimerCreate(); - - Http::TestHeaderMapImpl headers; - HttpTestUtility::addDefaultHeaders(headers); - const Http::LowerCaseString header("x-request-start"); - EXPECT_EQ(nullptr, headers.get(header)); - router_.decodeHeaders(headers, true); - EXPECT_NE(nullptr, headers.get(header)); - - uint64_t timestamp; - StringUtil::atoul(headers.get(header)->value().c_str(), timestamp); - EXPECT_GT(timestamp, 0); - - EXPECT_CALL(cancellable_, cancel()); - router_.onDestroy(); - EXPECT_TRUE(verifyHostUpstreamStats(0, 0)); -} - } // namespace Router } // namespace Envoy From 4e745701bbdf64807d9ac1380ae4782a489a0d79 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 9 May 2018 10:12:40 +0700 Subject: [PATCH 06/46] Add a test sample to TestParseInternal Signed-off-by: Dhi Aurrahman --- test/common/router/header_formatter_test.cc | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index 377e83c8dc9ca..2b1da0482f166 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -252,6 +252,12 @@ TEST(HeaderParserTest, TestParseInternal) { absl::optional expected_exception_; }; + time_t start_time_epoch = 1522280158; + SystemTime start_time = std::chrono::system_clock::from_time_t(start_time_epoch); + const std::string timestamp = fmt::format( + "{}", + std::chrono::duration_cast(start_time.time_since_epoch()).count()); + static const TestCase test_cases[] = { // Valid inputs {"%PROTOCOL%", {"HTTP/1.1"}, {}}, @@ -271,6 +277,7 @@ TEST(HeaderParserTest, TestParseInternal) { {"%UPSTREAM_METADATA([\"ns\", \t \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA([\"ns\", \n \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA( \t [ \t \"ns\" \t , \t \"key\" \t ] \t )%", {"value"}, {}}, + {"%START_TIMESTAMP%", {timestamp}, {}}, // Unescaped % {"%", {}, {"Invalid header configuration. Un-escaped % at position 0"}}, @@ -405,6 +412,8 @@ TEST(HeaderParserTest, TestParseInternal) { )EOF"); ON_CALL(*host, metadata()).WillByDefault(ReturnRef(metadata)); + ON_CALL(request_info, startTime()).WillByDefault(Return(start_time)); + for (const auto& test_case : test_cases) { Protobuf::RepeatedPtrField to_add; envoy::api::v2::core::HeaderValueOption* header = to_add.Add(); From 79a33208ba56545f6c5ec9b56d24c76a5d58a72c Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 9 May 2018 11:03:00 +0700 Subject: [PATCH 07/46] tsan: check RatelimitIntegrationTest failure Signed-off-by: Dhi Aurrahman From f94e02071ff886b96e8d1dabc4ba7194b8d17952 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Thu, 10 May 2018 06:58:07 +0700 Subject: [PATCH 08/46] Rename it to START_TIME_SINCE_EPOCH Signed-off-by: Dhi Aurrahman --- .../configuration/http_conn_man/headers.rst | 4 ++-- docs/root/intro/version_history.rst | 2 +- source/common/router/header_formatter.cc | 8 +++----- test/common/router/header_formatter_test.cc | 20 ++++++++----------- 4 files changed, 14 insertions(+), 20 deletions(-) diff --git a/docs/root/configuration/http_conn_man/headers.rst b/docs/root/configuration/http_conn_man/headers.rst index 4e810634d4db2..0b8d055c2f04b 100644 --- a/docs/root/configuration/http_conn_man/headers.rst +++ b/docs/root/configuration/http_conn_man/headers.rst @@ -481,5 +481,5 @@ Supported variable names are: namespace and key(s) are specified as a JSON array of strings. Finally, percent symbols in the parameters **do not** need to be escaped by doubling them. -%START_TIMESTAMP% - The timestamp when the first byte of a request is received. The timestamp unit is in milliseconds. +%START_TIME_SINCE_EPOCH% + The timestamp since epoch when the first byte of a request is received. The timestamp unit is in milliseconds. diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 10a3e55caff4b..631a951205429 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -59,7 +59,7 @@ Version history * logger: added the ability to optionally set the log format via the :option:`--log-format` option. * logger: all :ref:`logging levels ` can be configured at run-time: trace debug info warning error critical. -* router: added `START_TIMESTAMP` as one of supported variables in :ref:`header +* router: added `START_TIME_SINCE_EPOCH` as one of supported variables in :ref:`header formatters `. The timestamp unit is in milliseconds. * sockets: added :ref:`capture transport socket extension ` to support recording plain text traffic and PCAP generation. diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 66b6aec6a1be2..fa3e6c6591519 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -135,14 +135,12 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n return RequestInfo::Utility::formatDownstreamAddressNoPort( *request_info.downstreamLocalAddress()); }; - } else if (field_name == "START_TIMESTAMP") { + } else if (field_name == "START_TIME_SINCE_EPOCH") { field_extractor_ = [](const RequestInfo::RequestInfo& request_info) { // Returns the start timestamp in milliseconds. - return fmt::format("{}", std::chrono::duration_cast( - request_info.startTime().time_since_epoch()) - .count()); + return AccessLog::AccessLogFormatUtils::durationToString(request_info.startTime().time_since_epoch()); }; - } else if (field_name.find_first_of("UPSTREAM_METADATA") == 0) { + } else if (field_name.find("UPSTREAM_METADATA") == 0) { field_extractor_ = parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA"))); } else { diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index 2b1da0482f166..e35f383e88e04 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -3,6 +3,7 @@ #include "envoy/api/v2/core/base.pb.h" #include "envoy/http/protocol.h" +#include "common/access_log/access_log_formatter.h" #include "common/config/metadata.h" #include "common/config/rds_json.h" #include "common/router/header_formatter.h" @@ -254,9 +255,8 @@ TEST(HeaderParserTest, TestParseInternal) { time_t start_time_epoch = 1522280158; SystemTime start_time = std::chrono::system_clock::from_time_t(start_time_epoch); - const std::string timestamp = fmt::format( - "{}", - std::chrono::duration_cast(start_time.time_since_epoch()).count()); + const std::string timestamp = + AccessLog::AccessLogFormatUtils::durationToString(start_time.time_since_epoch()); static const TestCase test_cases[] = { // Valid inputs @@ -277,7 +277,7 @@ TEST(HeaderParserTest, TestParseInternal) { {"%UPSTREAM_METADATA([\"ns\", \t \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA([\"ns\", \n \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA( \t [ \t \"ns\" \t , \t \"key\" \t ] \t )%", {"value"}, {}}, - {"%START_TIMESTAMP%", {timestamp}, {}}, + {"%START_TIME_SINCE_EPOCH%", {timestamp}, {}}, // Unescaped % {"%", {}, {"Invalid header configuration. Un-escaped % at position 0"}}, @@ -608,7 +608,7 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { }, { "key": "x-request-start", - "value": "%START_TIMESTAMP%" + "value": "%START_TIME_SINCE_EPOCH%" } ] } @@ -635,12 +635,8 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { EXPECT_EQ("static-value", headerMap.get_("static-header")); EXPECT_TRUE(headerMap.has("x-client-ip")); EXPECT_EQ("127.0.0.1", headerMap.get_("x-client-ip")); - - uint64_t timestamp; - StringUtil::atoul(headerMap.get_("x-request-start").c_str(), timestamp); - EXPECT_EQ( - timestamp, - std::chrono::duration_cast(start_time.time_since_epoch()).count()); + EXPECT_EQ(headerMap.get_("x-request-start").c_str(), + AccessLog::AccessLogFormatUtils::durationToString(start_time.time_since_epoch())); typedef std::map CountMap; CountMap counts; @@ -675,7 +671,7 @@ match: { prefix: "/new_endpoint" } append: true - header: key: "x-request-start" - value: "%START_TIMESTAMP%" + value: "%START_TIME_SINCE_EPOCH%" append: true response_headers_to_remove: ["x-nope"] )EOF"; From 07dc56f831cc42a395a55fb5f00f2cbd0f1bae09 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Thu, 10 May 2018 07:21:52 +0700 Subject: [PATCH 09/46] Fix format Signed-off-by: Dhi Aurrahman --- source/common/router/header_formatter.cc | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index fa3e6c6591519..e9e86fb2e3530 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -138,7 +138,8 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n } else if (field_name == "START_TIME_SINCE_EPOCH") { field_extractor_ = [](const RequestInfo::RequestInfo& request_info) { // Returns the start timestamp in milliseconds. - return AccessLog::AccessLogFormatUtils::durationToString(request_info.startTime().time_since_epoch()); + return AccessLog::AccessLogFormatUtils::durationToString( + request_info.startTime().time_since_epoch()); }; } else if (field_name.find("UPSTREAM_METADATA") == 0) { field_extractor_ = From aef2ed9cef2408cf38fd36eb2fd05bca7dfbf1de Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Mon, 14 May 2018 21:01:12 +0700 Subject: [PATCH 10/46] Allow header parser to accept START_TIME(ARG) Signed-off-by: Dhi Aurrahman --- source/common/router/header_formatter.cc | 37 +++++++-- source/common/router/header_parser.cc | 8 +- test/common/router/header_formatter_test.cc | 85 ++------------------- 3 files changed, 41 insertions(+), 89 deletions(-) diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 387d3e7061bb1..9f4e349647f45 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -112,6 +112,34 @@ parseUpstreamMetadataField(absl::string_view params_str) { }; } +std::function +parseStartTimeField(absl::string_view params_str) { + params_str = StringUtil::trim(params_str); + std::string format; + if (!params_str.empty()) { + if (params_str.front() != '(' || params_str.back() != ')') { + // TODO(dio): Build a better message. + throw EnvoyException("Invalid header configuration. Missing parens."); + } + // TODO(dio): What is the best way of converting absl::string_view to std::string? + format = std::string(params_str.substr(1, params_str.size() - 2)); // trim parens + } + + return [format](const Envoy::RequestInfo::RequestInfo& request_info) -> std::string { + if (format.empty()) { + // TODO(dio): Should the default is timestamp in milliseconds? + // Or should it be AccessLogDateTimeFormatter::fromTime(request_info.startTime())? + return AccessLog::AccessLogFormatUtils::durationToString( + request_info.startTime().time_since_epoch()); + } + // TODO(dio): Extend date_formatter's format to accept more tokens, i.e. + // 1. Timestamp (in ms, us, and ns) since epoch + // 2. ms, us, and ns components. + Envoy::DateFormatter date_formatter(format); + return date_formatter.fromTime(request_info.startTime()); + }; +} + } // namespace RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_name, bool append) @@ -134,13 +162,10 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n return RequestInfo::Utility::formatDownstreamAddressNoPort( *request_info.downstreamLocalAddress()); }; - } else if (field_name == "START_TIME_SINCE_EPOCH") { - field_extractor_ = [](const RequestInfo::RequestInfo& request_info) { - // Returns the start timestamp in milliseconds. - return AccessLog::AccessLogFormatUtils::durationToString( - request_info.startTime().time_since_epoch()); - }; + } else if (field_name.find("START_TIME") == 0) { + field_extractor_ = parseStartTimeField(field_name.substr(STATIC_STRLEN("START_TIME"))); } else if (field_name.find("UPSTREAM_METADATA") == 0) { + // TODO(dio): Check the param in here since we don't check it in the parser anymore. field_extractor_ = parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA"))); } else { diff --git a/source/common/router/header_parser.cc b/source/common/router/header_parser.cc index e56814f7da799..c5ccd74bb576e 100644 --- a/source/common/router/header_parser.cc +++ b/source/common/router/header_parser.cc @@ -102,10 +102,8 @@ parseInternal(const envoy::api::v2::core::HeaderValueOption& header_value_option // Search for first argument string state = ParserState::ExpectString; } else if (!isspace(ch)) { - throw EnvoyException(fmt::format( - "Invalid header configuration. Expecting JSON array of arguments after '{}', but " - "found '{}'", - absl::StrCat(format.substr(start, pos - start)), ch)); + // Consume it as a string argument. + state = ParserState::String; } break; @@ -145,6 +143,8 @@ parseInternal(const envoy::api::v2::core::HeaderValueOption& header_value_option // Skip escaped char. pos++; + } else if (ch == ')') { + state = ParserState::ExpectVariableEnd; } else if (ch == '"') { state = ParserState::ExpectArrayDelimiterOrEnd; } diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index 156daa88a46fe..598eb3a7d5427 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -273,7 +273,7 @@ TEST(HeaderParserTest, TestParseInternal) { {"%UPSTREAM_METADATA([\"ns\", \t \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA([\"ns\", \n \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA( \t [ \t \"ns\" \t , \t \"key\" \t ] \t )%", {"value"}, {}}, - {"%START_TIME_SINCE_EPOCH%", {timestamp}, {}}, + {"%START_TIME%", {timestamp}, {}}, // Unescaped % {"%", {}, {"Invalid header configuration. Un-escaped % at position 0"}}, @@ -303,82 +303,8 @@ TEST(HeaderParserTest, TestParseInternal) { {"Invalid header configuration. Un-terminated variable expression 'VAR after'"}}, {"% ", {}, {"Invalid header configuration. Un-terminated variable expression ' '"}}, - // Un-terminated variable expressions with arguments. - {"%VAR(no array)%", - {}, - {"Invalid header configuration. Expecting JSON array of arguments after " - "'VAR(', but found 'n'"}}, - {"%VAR( no array)%", - {}, - {"Invalid header configuration. Expecting JSON array of arguments after " - "'VAR( ', but found 'n'"}}, - {"%VAR([)", - {}, - {"Invalid header configuration. Expecting '\"' or whitespace after 'VAR([', but found ')'"}}, - {"%VAR([ )", - {}, - {"Invalid header configuration. Expecting '\"' or whitespace after 'VAR([ ', but found " - "')'"}}, - {"%VAR([\"x\")%", - {}, - {"Invalid header configuration. Expecting ',', ']', or whitespace after " - "'VAR([\"x\"', but found ')'"}}, - {"%VAR([\"x\" )%", - {}, - {"Invalid header configuration. Expecting ',', ']', or whitespace after " - "'VAR([\"x\" ', but found ')'"}}, - {"%VAR([\"x\\", - {}, - {"Invalid header configuration. Un-terminated backslash in JSON string after 'VAR([\"x'"}}, - {"%VAR([\"x\"]!", - {}, - {"Invalid header configuration. Expecting ')' or whitespace after " - "'VAR([\"x\"]', but found '!'"}}, - {"%VAR([\"x\"] !", - {}, - {"Invalid header configuration. Expecting ')' or whitespace after " - "'VAR([\"x\"] ', but found '!'"}}, - {"%VAR([\"x\"])!", - {}, - {"Invalid header configuration. Expecting '%' or whitespace after " - "'VAR([\"x\"])', but found '!'"}}, - {"%VAR([\"x\"]) !", - {}, - {"Invalid header configuration. Expecting '%' or whitespace after " - "'VAR([\"x\"]) ', but found '!'"}}, - - // Argument errors - {"%VAR()%", - {}, - {"Invalid header configuration. Expecting JSON array of arguments after 'VAR(', but found " - "')'"}}, - {"%VAR( )%", - {}, - {"Invalid header configuration. Expecting JSON array of arguments after 'VAR( ', but found " - "')'"}}, - {"%VAR([])%", - {}, - {"Invalid header configuration. Expecting '\"' or whitespace after 'VAR([', but found ']'"}}, - {"%VAR( [ ] )%", - {}, - {"Invalid header configuration. Expecting '\"' or whitespace after 'VAR( [ ', but found " - "']'"}}, - {"%VAR([\"ns\",])%", - {}, - {"Invalid header configuration. Expecting '\"' or whitespace after 'VAR([\"ns\",', but " - "found ']'"}}, - {"%VAR( [ \"ns\" , ] )%", - {}, - {"Invalid header configuration. Expecting '\"' or whitespace after 'VAR( [ \"ns\" , ', but " - "found ']'"}}, - {"%VAR({\"ns\": \"key\"})%", - {}, - {"Invalid header configuration. Expecting JSON array of arguments after 'VAR(', but found " - "'{'"}}, - {"%VAR(\"ns\", \"key\")%", - {}, - {"Invalid header configuration. Expecting JSON array of arguments after 'VAR(', but found " - "'\"'"}}, + // TODO(dio): Un-terminated variable expressions with arguments and argument errors are not + // checked anymore. Find a way to check it, either at UPSTREAM_METADATA site or somewhere else. // Invalid arguments {"%UPSTREAM_METADATA%", @@ -604,7 +530,7 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { }, { "key": "x-request-start", - "value": "%START_TIME_SINCE_EPOCH%" + "value": "%START_TIME%" } ] } @@ -667,7 +593,7 @@ match: { prefix: "/new_endpoint" } append: true - header: key: "x-request-start" - value: "%START_TIME_SINCE_EPOCH%" + value: "%START_TIME(OK)%" append: true response_headers_to_remove: ["x-nope"] )EOF"; @@ -682,6 +608,7 @@ match: { prefix: "/new_endpoint" } EXPECT_TRUE(headerMap.has("x-request-start")); EXPECT_TRUE(headerMap.has("x-safe")); EXPECT_FALSE(headerMap.has("x-nope")); + EXPECT_EQ("OK", headerMap.get_("x-request-start")); } } // namespace Router From 1970913e386f34e6b1296ee175005ef7f0c51908 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 15 May 2018 00:23:30 +0700 Subject: [PATCH 11/46] Add replacers Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 54 ++++++++++++++++++++- source/common/common/utility.h | 2 + test/common/router/header_formatter_test.cc | 8 +-- 3 files changed, 59 insertions(+), 5 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 20e28474c74fb..397075f34fb07 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -20,8 +20,60 @@ #include "spdlog/spdlog.h" namespace Envoy { +namespace { + +typedef std::unordered_map> + FunctionMap; + +const FunctionMap& dateFormatterReplacers() { + CONSTRUCT_ON_FIRST_USE( + FunctionMap, + {{"%ms", + [](const SystemTime& time) -> std::string { + const std::chrono::milliseconds epoch_time_ms = + std::chrono::duration_cast(time.time_since_epoch()); + + uint32_t msec = epoch_time_ms.count() % 1000; + std::string msec_str; + msec_str.push_back('0' + (msec / 100)); + msec %= 100; + msec_str.push_back('0' + (msec / 10)); + msec %= 10; + msec_str.push_back('0' + msec); + return msec_str; + }}, + + {"%since_epoch_ms", [](const SystemTime& time) -> std::string { + return fmt::FormatInt( + std::chrono::duration_cast(time.time_since_epoch()) + .count()) + .str(); + }}}); +} + +} // namespace + std::string DateFormatter::fromTime(const SystemTime& time) const { - return fromTime(std::chrono::system_clock::to_time_t(time)); + std::string new_format_string = format_string_; + for (const auto& replacer : dateFormatterReplacers()) { + // TODO(dio): The following is a hammer, need to optimize it since most of the time the + // occurrence of each pattern to be replaced is only once. + std::vector pieces = absl::StrSplit(new_format_string, replacer.first); + if (!pieces.empty()) { + new_format_string = absl::StrJoin(pieces, replacer.second(time)); + } + } + + return fromTime(std::chrono::system_clock::to_time_t(time), new_format_string); +} + +std::string DateFormatter::fromTime(time_t time, const std::string& new_format_string) const { + tm current_tm; + gmtime_r(&time, ¤t_tm); + + std::array buf; + strftime(&buf[0], buf.size(), new_format_string.c_str(), ¤t_tm); + return std::string(&buf[0]); } std::string DateFormatter::fromTime(time_t time) const { diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 7f5bb0a42671e..fec16c4bc0029 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -48,6 +48,8 @@ class DateFormatter { const std::string& formatString() const { return format_string_; } private: + std::string fromTime(time_t time, const std::string& new_format_string) const; + std::string format_string_; }; diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index 598eb3a7d5427..e31cb24d5a20f 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -304,7 +304,8 @@ TEST(HeaderParserTest, TestParseInternal) { {"% ", {}, {"Invalid header configuration. Un-terminated variable expression ' '"}}, // TODO(dio): Un-terminated variable expressions with arguments and argument errors are not - // checked anymore. Find a way to check it, either at UPSTREAM_METADATA site or somewhere else. + // checked anymore. Find a way to check it, either at UPSTREAM_METADATA site or somewhere + // else. // Invalid arguments {"%UPSTREAM_METADATA%", @@ -530,7 +531,7 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { }, { "key": "x-request-start", - "value": "%START_TIME%" + "value": "%START_TIME(%since_epoch_ms)%" } ] } @@ -593,7 +594,7 @@ match: { prefix: "/new_endpoint" } append: true - header: key: "x-request-start" - value: "%START_TIME(OK)%" + value: "%START_TIME(%ms and %since_epoch_ms)%" append: true response_headers_to_remove: ["x-nope"] )EOF"; @@ -608,7 +609,6 @@ match: { prefix: "/new_endpoint" } EXPECT_TRUE(headerMap.has("x-request-start")); EXPECT_TRUE(headerMap.has("x-safe")); EXPECT_FALSE(headerMap.has("x-nope")); - EXPECT_EQ("OK", headerMap.get_("x-request-start")); } } // namespace Router From 90044141b4bc6e347a6a54a343905928fc10d8f1 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 16 May 2018 00:11:15 +0700 Subject: [PATCH 12/46] Use %f as subsecond formatter Signed-off-by: Dhi Aurrahman --- docs/root/configuration/access_log.rst | 10 +- .../configuration/http_conn_man/headers.rst | 16 ++- docs/root/intro/version_history.rst | 2 +- source/common/common/utility.cc | 99 +++++++++++-------- source/common/common/utility.h | 6 +- source/common/router/header_formatter.cc | 16 +-- test/common/router/header_formatter_test.cc | 78 +++++++++++---- 7 files changed, 153 insertions(+), 74 deletions(-) diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index 66ceb0760f6d1..ee1eb96c45ff6 100644 --- a/docs/root/configuration/access_log.rst +++ b/docs/root/configuration/access_log.rst @@ -29,6 +29,8 @@ are noted. The following command operators are supported: +.. _config_access_log_format_start_time: + %START_TIME% HTTP Request start time including milliseconds. @@ -36,12 +38,18 @@ The following command operators are supported: TCP Downstream connection start time including milliseconds. - START_TIME can be customized using a `format string `_, for example: + START_TIME can be customized using a `format string `_. + In addition to that, START_TIME also accepts :code:`%f` to get the subsecond digits. The default is 9 digits (nanosecond). + The number of digits can be specified by specifiying the digit number after :code:`%`, e.g. :code:`%3f` to get 3 digits. + + Examples of formatting START_TIME is as follows: .. code-block:: none %START_TIME(%Y/%m/%dT%H:%M:%S%z %s)% + %START_TIME(%s%3f)% + %BYTES_RECEIVED% HTTP Body bytes received. diff --git a/docs/root/configuration/http_conn_man/headers.rst b/docs/root/configuration/http_conn_man/headers.rst index f303dac4e43c9..dcf352f0784b0 100644 --- a/docs/root/configuration/http_conn_man/headers.rst +++ b/docs/root/configuration/http_conn_man/headers.rst @@ -473,5 +473,17 @@ Supported variable names are: namespace and key(s) are specified as a JSON array of strings. Finally, percent symbols in the parameters **do not** need to be escaped by doubling them. -%START_TIME_SINCE_EPOCH% - The timestamp since epoch when the first byte of a request is received. The timestamp unit is in milliseconds. +%START_TIME% + Request start time including milliseconds. START_TIME can be customized as mentioned in + :ref:`access log format rules`. An example of setting a custom header with + timestamp since epoch in milliseconds is: + +.. code-block:: none + + route: + cluster: www + request_headers_to_add: + - header: + key: "x-request-start" + value: "%START_TIME(%s%3f)%" + append: true \ No newline at end of file diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 4d4255d97fd21..cb84211f84767 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -61,7 +61,7 @@ Version history * logger: added the ability to optionally set the log format via the :option:`--log-format` option. * logger: all :ref:`logging levels ` can be configured at run-time: trace debug info warning error critical. -* router: added `START_TIME_SINCE_EPOCH` as one of supported variables in :ref:`header +* router: added `START_TIME` as one of supported variables in :ref:`header formatters `. The timestamp unit is in milliseconds. * sockets: added :ref:`capture transport socket extension ` to support recording plain text traffic and PCAP generation. diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 397075f34fb07..821a45391fbea 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -20,51 +20,22 @@ #include "spdlog/spdlog.h" namespace Envoy { -namespace { - -typedef std::unordered_map> - FunctionMap; - -const FunctionMap& dateFormatterReplacers() { - CONSTRUCT_ON_FIRST_USE( - FunctionMap, - {{"%ms", - [](const SystemTime& time) -> std::string { - const std::chrono::milliseconds epoch_time_ms = - std::chrono::duration_cast(time.time_since_epoch()); - - uint32_t msec = epoch_time_ms.count() % 1000; - std::string msec_str; - msec_str.push_back('0' + (msec / 100)); - msec %= 100; - msec_str.push_back('0' + (msec / 10)); - msec %= 10; - msec_str.push_back('0' + msec); - return msec_str; - }}, - - {"%since_epoch_ms", [](const SystemTime& time) -> std::string { - return fmt::FormatInt( - std::chrono::duration_cast(time.time_since_epoch()) - .count()) - .str(); - }}}); -} - -} // namespace std::string DateFormatter::fromTime(const SystemTime& time) const { - std::string new_format_string = format_string_; - for (const auto& replacer : dateFormatterReplacers()) { - // TODO(dio): The following is a hammer, need to optimize it since most of the time the - // occurrence of each pattern to be replaced is only once. - std::vector pieces = absl::StrSplit(new_format_string, replacer.first); - if (!pieces.empty()) { - new_format_string = absl::StrJoin(pieces, replacer.second(time)); - } + const std::string new_format_string = setCustomField( + // "%f" is the custom field for subsecond. + "f", + fmt::FormatInt( + std::chrono::duration_cast(time.time_since_epoch()).count()) + .str() + .substr(10)); + + const time_t current_time = std::chrono::system_clock::to_time_t(time); + if (new_format_string.empty()) { + return fromTime(current_time); } - return fromTime(std::chrono::system_clock::to_time_t(time), new_format_string); + return fromTime(current_time, new_format_string); } std::string DateFormatter::fromTime(time_t time, const std::string& new_format_string) const { @@ -76,6 +47,52 @@ std::string DateFormatter::fromTime(time_t time, const std::string& new_format_s return std::string(&buf[0]); } +std::string DateFormatter::setCustomField(const std::string& field, + const std::string& value) const { + size_t found = format_string_.find(field); + if (found == std::string::npos) { + // If no field specifier inside the current format string, return an empty string and quickly + // use the default formatter. + // + // TODO(dio): Use EMPTY_STRING in here. + return ""; + } + + size_t index = found; + std::string new_format_string = format_string_; + + while (found != std::string::npos) { + index = found; + + size_t start = found - 1; + if (start < new_format_string.size()) { + std::string sub = new_format_string.substr(start, 2); + if (sub.at(0) == '%' && sub.size() == 2) { + // This field definitely has no width specifier, e.g. %f. + new_format_string = new_format_string.replace(start, 2, value); + } else { + start = found - 2; + + // This field probably has a valid width specifier, e.g. %3f. + if (start < new_format_string.size()) { + std::string sub = new_format_string.substr(start, 2); + + if (sub.at(0) == '%' && sub.size() == 2) { + uint64_t width; + if (StringUtil::atoul(sub.substr(1, 1).c_str(), width)) { + new_format_string = new_format_string.replace(start, 3, value.substr(0, width)); + } + } + } + } + } + + found = new_format_string.find(field, ++index); + } + + return new_format_string; +} + std::string DateFormatter::fromTime(time_t time) const { tm current_tm; gmtime_r(&time, ¤t_tm); diff --git a/source/common/common/utility.h b/source/common/common/utility.h index fec16c4bc0029..3fdfa0715fd37 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -20,6 +20,10 @@ #include "absl/strings/string_view.h" namespace Envoy { + +typedef std::unordered_map> + CustomDateFormatterMap; + /** * Utility class for formatting dates given a strftime style format string. */ @@ -49,7 +53,7 @@ class DateFormatter { private: std::string fromTime(time_t time, const std::string& new_format_string) const; - + std::string setCustomField(const std::string& field, const std::string& value) const; std::string format_string_; }; diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 9f4e349647f45..5f7cc53f5787b 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -118,23 +118,18 @@ parseStartTimeField(absl::string_view params_str) { std::string format; if (!params_str.empty()) { if (params_str.front() != '(' || params_str.back() != ')') { - // TODO(dio): Build a better message. - throw EnvoyException("Invalid header configuration. Missing parens."); + throw EnvoyException(fmt::format("Invalid header configuration. Expected format " + "START_TIME or START_TIME(%s ...), actual format " + "START_TIME{}", + params_str)); } - // TODO(dio): What is the best way of converting absl::string_view to std::string? format = std::string(params_str.substr(1, params_str.size() - 2)); // trim parens } return [format](const Envoy::RequestInfo::RequestInfo& request_info) -> std::string { if (format.empty()) { - // TODO(dio): Should the default is timestamp in milliseconds? - // Or should it be AccessLogDateTimeFormatter::fromTime(request_info.startTime())? - return AccessLog::AccessLogFormatUtils::durationToString( - request_info.startTime().time_since_epoch()); + return AccessLogDateTimeFormatter::fromTime(request_info.startTime()); } - // TODO(dio): Extend date_formatter's format to accept more tokens, i.e. - // 1. Timestamp (in ms, us, and ns) since epoch - // 2. ms, us, and ns components. Envoy::DateFormatter date_formatter(format); return date_formatter.fromTime(request_info.startTime()); }; @@ -165,7 +160,6 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n } else if (field_name.find("START_TIME") == 0) { field_extractor_ = parseStartTimeField(field_name.substr(STATIC_STRLEN("START_TIME"))); } else if (field_name.find("UPSTREAM_METADATA") == 0) { - // TODO(dio): Check the param in here since we don't check it in the parser anymore. field_extractor_ = parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA"))); } else { diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index e31cb24d5a20f..5e6baa2187a75 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -249,11 +249,6 @@ TEST(HeaderParserTest, TestParseInternal) { absl::optional expected_exception_; }; - const time_t start_time_epoch = 1522280158; - SystemTime start_time = std::chrono::system_clock::from_time_t(start_time_epoch); - const std::string timestamp = - AccessLog::AccessLogFormatUtils::durationToString(start_time.time_since_epoch()); - static const TestCase test_cases[] = { // Valid inputs {"%PROTOCOL%", {"HTTP/1.1"}, {}}, @@ -273,7 +268,7 @@ TEST(HeaderParserTest, TestParseInternal) { {"%UPSTREAM_METADATA([\"ns\", \t \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA([\"ns\", \n \"key\"])%", {"value"}, {}}, {"%UPSTREAM_METADATA( \t [ \t \"ns\" \t , \t \"key\" \t ] \t )%", {"value"}, {}}, - {"%START_TIME%", {timestamp}, {}}, + {"%START_TIME%", {"2018-04-03T23:06:09.123Z"}, {}}, // Unescaped % {"%", {}, {"Invalid header configuration. Un-escaped % at position 0"}}, @@ -303,9 +298,19 @@ TEST(HeaderParserTest, TestParseInternal) { {"Invalid header configuration. Un-terminated variable expression 'VAR after'"}}, {"% ", {}, {"Invalid header configuration. Un-terminated variable expression ' '"}}, - // TODO(dio): Un-terminated variable expressions with arguments and argument errors are not - // checked anymore. Find a way to check it, either at UPSTREAM_METADATA site or somewhere - // else. + // TODO(dio): Un-terminated variable expressions with arguments and argument errors for + // generic %VAR are not checked anymore. Find a way to get the same granularity as before for + // following cases. + {"%UPSTREAM_METADATA(no array)%", + {}, + {"Invalid header configuration. Expected format UPSTREAM_METADATA([\"namespace\", \"k\", " + "...]), actual format UPSTREAM_METADATA(no array), because JSON supplied is not valid. " + "Error(offset 1, line 1): Invalid value.\n"}}, + {"%UPSTREAM_METADATA( no array)%", + {}, + {"Invalid header configuration. Expected format UPSTREAM_METADATA([\"namespace\", \"k\", " + "...]), actual format UPSTREAM_METADATA( no array), because JSON supplied is not valid. " + "Error(offset 2, line 1): Invalid value.\n"}}, // Invalid arguments {"%UPSTREAM_METADATA%", @@ -335,6 +340,8 @@ TEST(HeaderParserTest, TestParseInternal) { )EOF"); ON_CALL(*host, metadata()).WillByDefault(ReturnRef(metadata)); + // "2018-04-03T23:06:09.123Z". + const SystemTime start_time(std::chrono::milliseconds(1522796769123)); ON_CALL(request_info, startTime()).WillByDefault(Return(start_time)); for (const auto& test_case : test_cases) { @@ -531,7 +538,15 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { }, { "key": "x-request-start", - "value": "%START_TIME(%since_epoch_ms)%" + "value": "%START_TIME(%s%3f)%" + }, + { + "key": "x-request-start-default", + "value": "%START_TIME%" + }, + { + "key": "x-request-start-range", + "value": "%START_TIME(%f, %1f, %2f, %3f, %4f, %5f, %6f, %7f, %8f, %9f)%" } ] } @@ -549,17 +564,21 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { {":method", "POST"}, {"static-header", "old-value"}, {"x-client-ip", "0.0.0.0"}}; NiceMock request_info; - const time_t start_time_epoch = 1522280158; - SystemTime start_time = std::chrono::system_clock::from_time_t(start_time_epoch); - EXPECT_CALL(request_info, startTime()).WillOnce(Return(start_time)); + const SystemTime start_time(std::chrono::microseconds(1522796769123456)); + EXPECT_CALL(request_info, startTime()).Times(3).WillRepeatedly(Return(start_time)); req_header_parser->evaluateHeaders(headerMap, request_info); EXPECT_TRUE(headerMap.has("static-header")); EXPECT_EQ("static-value", headerMap.get_("static-header")); EXPECT_TRUE(headerMap.has("x-client-ip")); EXPECT_EQ("127.0.0.1", headerMap.get_("x-client-ip")); - EXPECT_EQ(headerMap.get_("x-request-start").c_str(), - AccessLog::AccessLogFormatUtils::durationToString(start_time.time_since_epoch())); + EXPECT_TRUE(headerMap.has("x-request-start")); + EXPECT_EQ("1522796769123", headerMap.get_("x-request-start")); + EXPECT_TRUE(headerMap.has("x-request-start-default")); + EXPECT_EQ("2018-04-03T23:06:09.123Z", headerMap.get_("x-request-start-default")); + EXPECT_TRUE(headerMap.has("x-request-start-range")); + EXPECT_EQ("123456000, 1, 12, 123, 1234, 12345, 123456, 1234560, 12345600, 123456000", + headerMap.get_("x-request-start-range")); typedef std::map CountMap; CountMap counts; @@ -594,7 +613,19 @@ match: { prefix: "/new_endpoint" } append: true - header: key: "x-request-start" - value: "%START_TIME(%ms and %since_epoch_ms)%" + value: "%START_TIME(%s%3f)%" + append: true + - header: + key: "x-request-start-f" + value: "%START_TIME(f)%" + append: true + - header: + key: "x-request-start-range" + value: "%START_TIME(%f, %1f, %2f, %3f, %4f, %5f, %6f, %7f, %8f, %9f)%" + append: true + - header: + key: "x-request-start-default" + value: "%START_TIME%" append: true response_headers_to_remove: ["x-nope"] )EOF"; @@ -604,11 +635,24 @@ match: { prefix: "/new_endpoint" } HeaderParser::configure(route.response_headers_to_add(), route.response_headers_to_remove()); Http::TestHeaderMapImpl headerMap{{":method", "POST"}, {"x-safe", "safe"}, {"x-nope", "nope"}}; NiceMock request_info; + + // Initialize start_time as 2018-04-03T23:06:09.123Z in microseconds. + const SystemTime start_time(std::chrono::microseconds(1522796769123456)); + EXPECT_CALL(request_info, startTime()).Times(4).WillRepeatedly(Return(start_time)); + resp_header_parser->evaluateHeaders(headerMap, request_info); EXPECT_TRUE(headerMap.has("x-client-ip")); - EXPECT_TRUE(headerMap.has("x-request-start")); EXPECT_TRUE(headerMap.has("x-safe")); EXPECT_FALSE(headerMap.has("x-nope")); + EXPECT_TRUE(headerMap.has("x-request-start")); + EXPECT_EQ("1522796769123", headerMap.get_("x-request-start")); + EXPECT_TRUE(headerMap.has("x-request-start-f")); + EXPECT_EQ("f", headerMap.get_("x-request-start-f")); + EXPECT_TRUE(headerMap.has("x-request-start-default")); + EXPECT_EQ("2018-04-03T23:06:09.123Z", headerMap.get_("x-request-start-default")); + EXPECT_TRUE(headerMap.has("x-request-start-range")); + EXPECT_EQ("123456000, 1, 12, 123, 1234, 12345, 123456, 1234560, 12345600, 123456000", + headerMap.get_("x-request-start-range")); } } // namespace Router From ce1d3a00c1f275643f0a58427b9aa1ad3e1c205a Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 16 May 2018 13:31:26 +0700 Subject: [PATCH 13/46] Add test in accesss_log_formatter Signed-off-by: Dhi Aurrahman --- source/common/common/BUILD | 1 + source/common/common/utility.cc | 15 ++++++++------- source/common/common/utility.h | 5 +++++ .../access_log/access_log_formatter_test.cc | 15 +++++++++++++-- 4 files changed, 27 insertions(+), 9 deletions(-) diff --git a/source/common/common/BUILD b/source/common/common/BUILD index e99c8f4b855a6..1f8465c367646 100644 --- a/source/common/common/BUILD +++ b/source/common/common/BUILD @@ -146,6 +146,7 @@ envoy_cc_library( hdrs = ["utility.h"], deps = [ ":assert_lib", + ":empty_string", ":hash_lib", "//include/envoy/common:interval_set_interface", "//include/envoy/common:time_interface", diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 821a45391fbea..bf4b6608d38a7 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -10,6 +10,7 @@ #include "envoy/common/exception.h" #include "common/common/assert.h" +#include "common/common/empty_string.h" #include "common/common/fmt.h" #include "common/common/hash.h" @@ -24,8 +25,9 @@ namespace Envoy { std::string DateFormatter::fromTime(const SystemTime& time) const { const std::string new_format_string = setCustomField( // "%f" is the custom field for subsecond. - "f", + CustomFields::f(), fmt::FormatInt( + // By default we want nanoseconds. std::chrono::duration_cast(time.time_since_epoch()).count()) .str() .substr(10)); @@ -35,6 +37,7 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { return fromTime(current_time); } + // Send the newly formatted format string to stftime. return fromTime(current_time, new_format_string); } @@ -51,11 +54,9 @@ std::string DateFormatter::setCustomField(const std::string& field, const std::string& value) const { size_t found = format_string_.find(field); if (found == std::string::npos) { - // If no field specifier inside the current format string, return an empty string and quickly - // use the default formatter. - // - // TODO(dio): Use EMPTY_STRING in here. - return ""; + // If no field specifier inside the current format string, return an empty string and + // subsequently use the default formatter. + return EMPTY_STRING; } size_t index = found; @@ -73,7 +74,7 @@ std::string DateFormatter::setCustomField(const std::string& field, } else { start = found - 2; - // This field probably has a valid width specifier, e.g. %3f. + // This field potentially has a valid width specifier, e.g. %3f. if (start < new_format_string.size()) { std::string sub = new_format_string.substr(start, 2); diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 3fdfa0715fd37..4a7a3ac787f16 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -54,6 +54,11 @@ class DateFormatter { private: std::string fromTime(time_t time, const std::string& new_format_string) const; std::string setCustomField(const std::string& field, const std::string& value) const; + + struct CustomFields { + static const std::string& f() { CONSTRUCT_ON_FIRST_USE(std::string, "f"); } + }; + std::string format_string_; }; diff --git a/test/common/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc index d7860ce5d4d43..3fab1b95dad53 100644 --- a/test/common/access_log/access_log_formatter_test.cc +++ b/test/common/access_log/access_log_formatter_test.cc @@ -395,7 +395,7 @@ TEST(AccessLogFormatterTest, CompositeFormatterSuccess) { { const std::string format = "%START_TIME(%Y/%m/%d)%|%START_TIME(%s)%|%START_TIME(bad_format)%|" - "%START_TIME%"; + "%START_TIME%|%START_TIME(%f.%1f.%2f.%3f)%"; time_t test_epoch = 1522280158; SystemTime time = std::chrono::system_clock::from_time_t(test_epoch); @@ -407,7 +407,18 @@ TEST(AccessLogFormatterTest, CompositeFormatterSuccess) { gmtime_r(&test_epoch, &time_val); time_t expected_time_t = mktime(&time_val); - EXPECT_EQ(fmt::format("2018/03/28|{}|bad_format|2018-03-28T23:35:58.000Z", expected_time_t), + EXPECT_EQ(fmt::format("2018/03/28|{}|bad_format|2018-03-28T23:35:58.000Z|000000000.0.00.000", + expected_time_t), + formatter.format(request_header, response_header, response_trailer, request_info)); + } + + { + const std::string format = + "%START_TIME(%s%3f)%|%START_TIME(%s%4f)%|%START_TIME(%s%5f)%|%START_TIME(%s%6f)%"; + const SystemTime start_time(std::chrono::microseconds(1522796769123456)); + EXPECT_CALL(request_info, startTime()).WillRepeatedly(Return(start_time)); + FormatterImpl formatter(format); + EXPECT_EQ("1522796769123|15227967691234|152279676912345|1522796769123456", formatter.format(request_header, response_header, response_trailer, request_info)); } } From e98f1a490c1061cb8f5f45b2aab01591e169da6d Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 16 May 2018 18:35:51 +0700 Subject: [PATCH 14/46] Retry ipv6_test Signed-off-by: Dhi Aurrahman From edbc437524feb4a5d4627a7261f61fd78ad07580 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Thu, 24 May 2018 21:19:27 +0700 Subject: [PATCH 15/46] Add a parser to initialize the format_string_ Signed-off-by: Dhi Aurrahman --- source/common/common/BUILD | 1 + source/common/common/utility.cc | 136 +++++++++++++++++++------------- source/common/common/utility.h | 17 ++-- 3 files changed, 92 insertions(+), 62 deletions(-) diff --git a/source/common/common/BUILD b/source/common/common/BUILD index 1f8465c367646..5c240cf6705dc 100644 --- a/source/common/common/BUILD +++ b/source/common/common/BUILD @@ -150,6 +150,7 @@ envoy_cc_library( ":hash_lib", "//include/envoy/common:interval_set_interface", "//include/envoy/common:time_interface", + "//source/common/singleton:const_singleton", ], ) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index bf4b6608d38a7..ef97b8e14c256 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -13,6 +13,7 @@ #include "common/common/empty_string.h" #include "common/common/fmt.h" #include "common/common/hash.h" +#include "common/singleton/const_singleton.h" #include "absl/strings/ascii.h" #include "absl/strings/match.h" @@ -22,73 +23,96 @@ namespace Envoy { +namespace { + +class SubsecondConstantValues { +public: + const std::string PLACEHOLDER{"000000000"}; + const std::regex PATTERN{"%([1-9])?f", std::regex::optimize}; +}; + +typedef ConstSingleton SubsecondConstants; + +} // namespace + std::string DateFormatter::fromTime(const SystemTime& time) const { - const std::string new_format_string = setCustomField( - // "%f" is the custom field for subsecond. - CustomFields::f(), - fmt::FormatInt( - // By default we want nanoseconds. - std::chrono::duration_cast(time.time_since_epoch()).count()) - .str() - .substr(10)); - - const time_t current_time = std::chrono::system_clock::to_time_t(time); - if (new_format_string.empty()) { - return fromTime(current_time); + struct CachedTime { + std::chrono::seconds epoch_time_seconds; + std::unordered_map formatted; + }; + static thread_local CachedTime cached_time; + + const std::chrono::nanoseconds epoch_time_ns = + std::chrono::duration_cast(time.time_since_epoch()); + + const std::chrono::seconds epoch_time_seconds = + std::chrono::duration_cast(epoch_time_ns); + + if (cached_time.formatted.find(format_string_) == cached_time.formatted.end() || + cached_time.epoch_time_seconds != epoch_time_seconds) { + cached_time.formatted.emplace( + std::make_pair(format_string_, fromTime(std::chrono::system_clock::to_time_t(time)))); + + cached_time.epoch_time_seconds = epoch_time_seconds; } - // Send the newly formatted format string to stftime. - return fromTime(current_time, new_format_string); + // Copy the cached formatted string, then replace its subseconds part. + std::string formatted = cached_time.formatted.at(format_string_); + const char* value = fmt::FormatInt(epoch_time_ns.count()).c_str(); + for (const auto subsecond : subseconds_) { + formatted.replace(subsecond.position_, subsecond.width_, value + 10, subsecond.width_); + } + // TODO(dio): ASSERT formatted length. + return formatted; } -std::string DateFormatter::fromTime(time_t time, const std::string& new_format_string) const { +std::string DateFormatter::parse(const std::string& format_string) { + const auto& specifier_begin = std::sregex_iterator(format_string.begin(), format_string.end(), + SubsecondConstants::get().PATTERN); + const auto& specifier_end = std::sregex_iterator(); + if (specifier_begin == specifier_end) { + return format_string; + } + + std::string new_format_string = EMPTY_STRING; + subseconds_.reserve(std::distance(specifier_begin, specifier_end)); + + auto now = std::chrono::system_clock::now(); + time_t current_time = std::chrono::system_clock::to_time_t(now); tm current_tm; - gmtime_r(&time, ¤t_tm); + gmtime_r(¤t_time, ¤t_tm); + size_t start = 0; + int32_t delta = 0; + int32_t inner_delta = 0; std::array buf; - strftime(&buf[0], buf.size(), new_format_string.c_str(), ¤t_tm); - return std::string(&buf[0]); -} + for (std::sregex_iterator i = specifier_begin; i != specifier_end; ++i) { + const std::smatch& match = *i; + + absl::string_view piece = format_string.substr(start, match.position() - start); + const size_t formatted_length = strftime(&buf[0], buf.size(), piece.data(), ¤t_tm); + delta += static_cast(formatted_length - piece.size()) + inner_delta; + start = match.position() + match.length(); + + // Save a subsecond's position and width inside the rendered format string. + SubsecondSpecifier subsecond(match.position() + delta); + absl::string_view matched_str = match[1].str(); + if (!matched_str.empty()) { + subsecond.width_ = matched_str[0] - '0'; + } + subseconds_.emplace_back(subsecond); -std::string DateFormatter::setCustomField(const std::string& field, - const std::string& value) const { - size_t found = format_string_.find(field); - if (found == std::string::npos) { - // If no field specifier inside the current format string, return an empty string and - // subsequently use the default formatter. - return EMPTY_STRING; - } + absl::string_view placeholder( + SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_)); + absl::StrAppend(&new_format_string, piece, placeholder); - size_t index = found; - std::string new_format_string = format_string_; - - while (found != std::string::npos) { - index = found; - - size_t start = found - 1; - if (start < new_format_string.size()) { - std::string sub = new_format_string.substr(start, 2); - if (sub.at(0) == '%' && sub.size() == 2) { - // This field definitely has no width specifier, e.g. %f. - new_format_string = new_format_string.replace(start, 2, value); - } else { - start = found - 2; - - // This field potentially has a valid width specifier, e.g. %3f. - if (start < new_format_string.size()) { - std::string sub = new_format_string.substr(start, 2); - - if (sub.at(0) == '%' && sub.size() == 2) { - uint64_t width; - if (StringUtil::atoul(sub.substr(1, 1).c_str(), width)) { - new_format_string = new_format_string.replace(start, 3, value.substr(0, width)); - } - } - } - } - } + // This takes into account the difference between the specifier length and the desired + // rendered width. + inner_delta = static_cast(subsecond.width_ - match.length()); + } - found = new_format_string.find(field, ++index); + if (start < format_string.size()) { + absl::StrAppend(&new_format_string, format_string.substr(start)); } return new_format_string; diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 4a7a3ac787f16..90ffb4af75273 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -29,7 +29,7 @@ typedef std::unordered_map subseconds_; - std::string format_string_; + const std::string format_string_; }; /** From 8919c50b442026f8aea014987ea22def6ee389b6 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Thu, 24 May 2018 21:20:20 +0700 Subject: [PATCH 16/46] Add a benchmark for date formatter with subseconds Signed-off-by: Dhi Aurrahman --- test/common/common/utility_speed_test.cc | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/test/common/common/utility_speed_test.cc b/test/common/common/utility_speed_test.cc index d1ceedeff23b9..ca16ad48ac3cd 100644 --- a/test/common/common/utility_speed_test.cc +++ b/test/common/common/utility_speed_test.cc @@ -43,6 +43,23 @@ static void BM_AccessLogDateTimeFormatter(benchmark::State& state) { } BENCHMARK(BM_AccessLogDateTimeFormatter); +// This benchmark is basically similar with the above BM_AccessLogDateTimeFormatter, the only +// difference is the format string input for the Envoy::DateFormatter. +static void BM_DateTimeFormatterWithSubseconds(benchmark::State& state) { + int outputBytes = 0; + + static Envoy::SystemTime time(std::chrono::seconds(1522796769)); + static std::mt19937 prng(1); // PRNG with a fixed seed, for repeatability + static std::uniform_int_distribution distribution(-10, 20); + static Envoy::DateFormatter date_formatter("%s%3f%5f"); + for (auto _ : state) { + time += std::chrono::milliseconds(static_cast(distribution(prng))); + outputBytes += date_formatter.fromTime(time).length(); + } + benchmark::DoNotOptimize(outputBytes); +} +BENCHMARK(BM_DateTimeFormatterWithSubseconds); + static void BM_RTrimStringView(benchmark::State& state) { int accum = 0; for (auto _ : state) { From 0f417da748b0265b895bef1193f1598a323dd39d Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Thu, 24 May 2018 21:32:10 +0700 Subject: [PATCH 17/46] Remove unused typedef Signed-off-by: Dhi Aurrahman --- source/common/common/utility.h | 4 ---- 1 file changed, 4 deletions(-) diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 90ffb4af75273..8977e88637548 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -20,10 +20,6 @@ #include "absl/strings/string_view.h" namespace Envoy { - -typedef std::unordered_map> - CustomDateFormatterMap; - /** * Utility class for formatting dates given a strftime style format string. */ From 106c3e25593178de772cd241e80cb02dd92ee454 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Thu, 24 May 2018 22:29:41 +0700 Subject: [PATCH 18/46] Use shared ptr to cache the format Signed-off-by: Dhi Aurrahman --- source/common/router/header_formatter.cc | 23 ++++++++++++++--------- source/common/router/header_formatter.h | 5 +++++ 2 files changed, 19 insertions(+), 9 deletions(-) diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 5f7cc53f5787b..923806eb2d028 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -113,7 +113,7 @@ parseUpstreamMetadataField(absl::string_view params_str) { } std::function -parseStartTimeField(absl::string_view params_str) { +parseStartTimeField(absl::string_view params_str, DateFormatterSharedPtr& date_formatter) { params_str = StringUtil::trim(params_str); std::string format; if (!params_str.empty()) { @@ -126,13 +126,17 @@ parseStartTimeField(absl::string_view params_str) { format = std::string(params_str.substr(1, params_str.size() - 2)); // trim parens } - return [format](const Envoy::RequestInfo::RequestInfo& request_info) -> std::string { - if (format.empty()) { - return AccessLogDateTimeFormatter::fromTime(request_info.startTime()); - } - Envoy::DateFormatter date_formatter(format); - return date_formatter.fromTime(request_info.startTime()); - }; + if (!format.empty()) { + date_formatter.reset(new Envoy::DateFormatter(format)); + } + + return + [format, date_formatter](const Envoy::RequestInfo::RequestInfo& request_info) -> std::string { + if (format.empty()) { + return AccessLogDateTimeFormatter::fromTime(request_info.startTime()); + } + return date_formatter->fromTime(request_info.startTime()); + }; } } // namespace @@ -158,7 +162,8 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n *request_info.downstreamLocalAddress()); }; } else if (field_name.find("START_TIME") == 0) { - field_extractor_ = parseStartTimeField(field_name.substr(STATIC_STRLEN("START_TIME"))); + field_extractor_ = + parseStartTimeField(field_name.substr(STATIC_STRLEN("START_TIME")), date_formatter_); } else if (field_name.find("UPSTREAM_METADATA") == 0) { field_extractor_ = parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA"))); diff --git a/source/common/router/header_formatter.h b/source/common/router/header_formatter.h index cc99ddacb27e4..99eaa1aac6b27 100644 --- a/source/common/router/header_formatter.h +++ b/source/common/router/header_formatter.h @@ -9,6 +9,10 @@ #include "absl/strings/string_view.h" namespace Envoy { + +class DateFormatter; +typedef std::shared_ptr DateFormatterSharedPtr; + namespace Router { /** @@ -43,6 +47,7 @@ class RequestInfoHeaderFormatter : public HeaderFormatter { private: std::function field_extractor_; const bool append_; + DateFormatterSharedPtr date_formatter_; }; /** From cc6c7c9036472b4b62fee98db0b8c80f30d7cf40 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Fri, 25 May 2018 05:35:02 +0700 Subject: [PATCH 19/46] Try to fix asan build take 1 Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index ef97b8e14c256..db5a6ce7bf28b 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -102,8 +102,8 @@ std::string DateFormatter::parse(const std::string& format_string) { } subseconds_.emplace_back(subsecond); - absl::string_view placeholder( - SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_)); + absl::string_view placeholder = + SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_); absl::StrAppend(&new_format_string, piece, placeholder); // This takes into account the difference between the specifier length and the desired From 4dcfeb06c803a9e78b9f3a493b5084779f27b686 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Fri, 25 May 2018 06:18:58 +0700 Subject: [PATCH 20/46] Try to fix asan build take 2 Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index db5a6ce7bf28b..2be0986877b12 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -89,8 +89,8 @@ std::string DateFormatter::parse(const std::string& format_string) { for (std::sregex_iterator i = specifier_begin; i != specifier_end; ++i) { const std::smatch& match = *i; - absl::string_view piece = format_string.substr(start, match.position() - start); - const size_t formatted_length = strftime(&buf[0], buf.size(), piece.data(), ¤t_tm); + const std::string piece = format_string.substr(start, match.position() - start); + const size_t formatted_length = strftime(&buf[0], buf.size(), piece.c_str(), ¤t_tm); delta += static_cast(formatted_length - piece.size()) + inner_delta; start = match.position() + match.length(); @@ -102,9 +102,8 @@ std::string DateFormatter::parse(const std::string& format_string) { } subseconds_.emplace_back(subsecond); - absl::string_view placeholder = - SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_); - absl::StrAppend(&new_format_string, piece, placeholder); + absl::StrAppend(&new_format_string, piece, + SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_)); // This takes into account the difference between the specifier length and the desired // rendered width. From 7d53b283784da9802186c9270ef9c7ed90e3be02 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Fri, 25 May 2018 07:00:50 +0700 Subject: [PATCH 21/46] Try to fix asan build take 3 Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 2be0986877b12..982dcff56b009 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -96,9 +96,9 @@ std::string DateFormatter::parse(const std::string& format_string) { // Save a subsecond's position and width inside the rendered format string. SubsecondSpecifier subsecond(match.position() + delta); - absl::string_view matched_str = match[1].str(); - if (!matched_str.empty()) { - subsecond.width_ = matched_str[0] - '0'; + const std::string match_str = match[1].str(); + if (!match_str.empty()) { + subsecond.width_ = match_str.at(0) - '0'; } subseconds_.emplace_back(subsecond); From e6cb04e47813f47100db7744b36db2c4444e607b Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Fri, 25 May 2018 07:54:49 +0700 Subject: [PATCH 22/46] Copy the ns value Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 982dcff56b009..7c5b8753a76ad 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -56,13 +56,19 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { cached_time.epoch_time_seconds = epoch_time_seconds; } + if (subseconds_.empty()) { + return cached_time.formatted.at(format_string_); + } + // Copy the cached formatted string, then replace its subseconds part. std::string formatted = cached_time.formatted.at(format_string_); - const char* value = fmt::FormatInt(epoch_time_ns.count()).c_str(); + const std::string value = fmt::FormatInt(epoch_time_ns.count()).str(); for (const auto subsecond : subseconds_) { - formatted.replace(subsecond.position_, subsecond.width_, value + 10, subsecond.width_); + // TODO(dio): Infer the length of second from parsing step. Currently, it is defaulted to 10. + formatted.replace(subsecond.position_, subsecond.width_, value.substr(10, subsecond.width_)); } - // TODO(dio): ASSERT formatted length. + + // TODO(dio): Assert the formatted length. return formatted; } From 96eb0c6d6556148a5a6d978831b9d80fe7a3aaac Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Fri, 25 May 2018 08:37:18 +0700 Subject: [PATCH 23/46] Update release notes Signed-off-by: Dhi Aurrahman --- docs/root/intro/version_history.rst | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 87f476d1090f1..b6ef7c0b64fee 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -9,6 +9,7 @@ Version history * access log: added DYNAMIC_METADATA :ref:`access log formatter `. * access log: added :ref:`HeaderFilter ` to filter logs based on request headers +* access log: added `%([1-9])?f` as one of START_TIME specifiers to render subseconds. * admin: added :http:get:`/config_dump` for dumping the current configuration and associated xDS version information (if applicable). * admin: added :http:get:`/stats/prometheus` as an alternative endpoint for getting stats in prometheus format. @@ -70,8 +71,6 @@ Version history * logger: added the ability to optionally set the log format via the :option:`--log-format` option. * logger: all :ref:`logging levels ` can be configured at run-time: trace debug info warning error critical. -* router: added `START_TIME` as one of supported variables in :ref:`header - formatters `. The timestamp unit is in milliseconds. * router: The behavior of per-try timeouts have changed in the case where a portion of the response has already been proxied downstream when the timeout occurs. Previously, the response would be reset leading to either an HTTP/2 reset or an HTTP/1 closed connection and a partial response. Now, the @@ -80,6 +79,8 @@ Version history to ignore the source port. * router: allow :ref:`cookie routing ` to generate session cookies. +* router: added START_TIME as one of supported variables in :ref:`header + formatters `. * sockets: added :ref:`capture transport socket extension ` to support recording plain text traffic and PCAP generation. * sockets: added `IP_FREEBIND` socket option support for :ref:`listeners From f475839ff782e3361be67cab0fdd2e1207b6d62f Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 29 May 2018 12:30:39 +0700 Subject: [PATCH 24/46] review: simplify parsing step Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 73 +++++++----------------- source/common/common/utility.h | 11 +--- test/common/common/utility_speed_test.cc | 23 ++++++-- 3 files changed, 40 insertions(+), 67 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 7c5b8753a76ad..cccfe26240cea 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -27,7 +27,9 @@ namespace { class SubsecondConstantValues { public: - const std::string PLACEHOLDER{"000000000"}; + const size_t DEFAULT_SECONDS_LENGTH{10}; + const char PLACEHOLDER_CHAR{'?'}; + const std::string PLACEHOLDER{"?????????"}; const std::regex PATTERN{"%([1-9])?f", std::regex::optimize}; }; @@ -38,7 +40,7 @@ typedef ConstSingleton SubsecondConstants; std::string DateFormatter::fromTime(const SystemTime& time) const { struct CachedTime { std::chrono::seconds epoch_time_seconds; - std::unordered_map formatted; + std::unordered_map formatted; }; static thread_local CachedTime cached_time; @@ -56,70 +58,35 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { cached_time.epoch_time_seconds = epoch_time_seconds; } - if (subseconds_.empty()) { + if (subsecond_widths_.empty()) { return cached_time.formatted.at(format_string_); } // Copy the cached formatted string, then replace its subseconds part. std::string formatted = cached_time.formatted.at(format_string_); const std::string value = fmt::FormatInt(epoch_time_ns.count()).str(); - for (const auto subsecond : subseconds_) { - // TODO(dio): Infer the length of second from parsing step. Currently, it is defaulted to 10. - formatted.replace(subsecond.position_, subsecond.width_, value.substr(10, subsecond.width_)); + for (const auto width : subsecond_widths_) { + const std::string subsecond = + value.substr(SubsecondConstants::get().DEFAULT_SECONDS_LENGTH, width); + const size_t placeholder_index = formatted.find(SubsecondConstants::get().PLACEHOLDER_CHAR); + ASSERT(placeholder_index != std::string::npos); + formatted.replace(placeholder_index, width, subsecond); } - // TODO(dio): Assert the formatted length. return formatted; } std::string DateFormatter::parse(const std::string& format_string) { - const auto& specifier_begin = std::sregex_iterator(format_string.begin(), format_string.end(), - SubsecondConstants::get().PATTERN); - const auto& specifier_end = std::sregex_iterator(); - if (specifier_begin == specifier_end) { - return format_string; + std::string new_format_string = format_string; + std::smatch result; + while (regex_search(new_format_string, result, SubsecondConstants::get().PATTERN)) { + const std::string& width_specifier = result[1]; + const size_t width = width_specifier.empty() ? SubsecondConstants::get().PLACEHOLDER.size() + : width_specifier.at(0) - '0'; + subsecond_widths_.emplace_back(width); + new_format_string.replace(result.position(), result.length(), + SubsecondConstants::get().PLACEHOLDER.substr(0, width)); } - - std::string new_format_string = EMPTY_STRING; - subseconds_.reserve(std::distance(specifier_begin, specifier_end)); - - auto now = std::chrono::system_clock::now(); - time_t current_time = std::chrono::system_clock::to_time_t(now); - tm current_tm; - gmtime_r(¤t_time, ¤t_tm); - - size_t start = 0; - int32_t delta = 0; - int32_t inner_delta = 0; - std::array buf; - for (std::sregex_iterator i = specifier_begin; i != specifier_end; ++i) { - const std::smatch& match = *i; - - const std::string piece = format_string.substr(start, match.position() - start); - const size_t formatted_length = strftime(&buf[0], buf.size(), piece.c_str(), ¤t_tm); - delta += static_cast(formatted_length - piece.size()) + inner_delta; - start = match.position() + match.length(); - - // Save a subsecond's position and width inside the rendered format string. - SubsecondSpecifier subsecond(match.position() + delta); - const std::string match_str = match[1].str(); - if (!match_str.empty()) { - subsecond.width_ = match_str.at(0) - '0'; - } - subseconds_.emplace_back(subsecond); - - absl::StrAppend(&new_format_string, piece, - SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_)); - - // This takes into account the difference between the specifier length and the desired - // rendered width. - inner_delta = static_cast(subsecond.width_ - match.length()); - } - - if (start < format_string.size()) { - absl::StrAppend(&new_format_string, format_string.substr(start)); - } - return new_format_string; } diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 8977e88637548..b1f1386dec5fa 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -49,16 +49,7 @@ class DateFormatter { private: std::string parse(const std::string& format_string); - - struct SubsecondSpecifier { - // The default subsecond width specifier is 9 digits (nanoseconds). - SubsecondSpecifier(const size_t position, size_t width = 9) - : position_(position), width_(width) {} - - const size_t position_; - size_t width_; - }; - std::vector subseconds_; + std::vector subsecond_widths_; const std::string format_string_; }; diff --git a/test/common/common/utility_speed_test.cc b/test/common/common/utility_speed_test.cc index ca16ad48ac3cd..5b95b3b58261e 100644 --- a/test/common/common/utility_speed_test.cc +++ b/test/common/common/utility_speed_test.cc @@ -48,10 +48,10 @@ BENCHMARK(BM_AccessLogDateTimeFormatter); static void BM_DateTimeFormatterWithSubseconds(benchmark::State& state) { int outputBytes = 0; - static Envoy::SystemTime time(std::chrono::seconds(1522796769)); - static std::mt19937 prng(1); // PRNG with a fixed seed, for repeatability - static std::uniform_int_distribution distribution(-10, 20); - static Envoy::DateFormatter date_formatter("%s%3f%5f"); + Envoy::SystemTime time(std::chrono::seconds(1522796769)); + std::mt19937 prng(1); // PRNG with a fixed seed, for repeatability + std::uniform_int_distribution distribution(-10, 20); + Envoy::DateFormatter date_formatter("%Y-%m-%dT%H:%M:%s.%3f"); for (auto _ : state) { time += std::chrono::milliseconds(static_cast(distribution(prng))); outputBytes += date_formatter.fromTime(time).length(); @@ -60,6 +60,21 @@ static void BM_DateTimeFormatterWithSubseconds(benchmark::State& state) { } BENCHMARK(BM_DateTimeFormatterWithSubseconds); +static void BM_DateTimeFormatterWithoutSubseconds(benchmark::State& state) { + int outputBytes = 0; + + Envoy::SystemTime time(std::chrono::seconds(1522796769)); + std::mt19937 prng(1); // PRNG with a fixed seed, for repeatability + std::uniform_int_distribution distribution(-10, 20); + Envoy::DateFormatter date_formatter("%Y-%m-%dT%H:%M:%s"); + for (auto _ : state) { + time += std::chrono::milliseconds(static_cast(distribution(prng))); + outputBytes += date_formatter.fromTime(time).length(); + } + benchmark::DoNotOptimize(outputBytes); +} +BENCHMARK(BM_DateTimeFormatterWithoutSubseconds); + static void BM_RTrimStringView(benchmark::State& state) { int accum = 0; for (auto _ : state) { From 724a203f64f3e7442726e5ceb87d8370390775f1 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 29 May 2018 13:37:15 +0700 Subject: [PATCH 25/46] review: reuse access log's formatter Signed-off-by: Dhi Aurrahman --- source/common/router/BUILD | 1 + source/common/router/header_formatter.cc | 37 +++++------------------- 2 files changed, 9 insertions(+), 29 deletions(-) diff --git a/source/common/router/BUILD b/source/common/router/BUILD index 7d4b0cd518425..1960b0c117c6f 100644 --- a/source/common/router/BUILD +++ b/source/common/router/BUILD @@ -226,6 +226,7 @@ envoy_cc_library( "//source/common/common:minimal_logger_lib", "//source/common/common:utility_lib", "//source/common/config:metadata_lib", + "//source/common/http:header_map_lib", "//source/common/json:json_loader_lib", ], ) diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 923806eb2d028..2dce3d8b03344 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -7,6 +7,7 @@ #include "common/common/logger.h" #include "common/common/utility.h" #include "common/config/metadata.h" +#include "common/http/header_map_impl.h" #include "common/json/json_loader.h" #include "common/request_info/utility.h" @@ -112,33 +113,6 @@ parseUpstreamMetadataField(absl::string_view params_str) { }; } -std::function -parseStartTimeField(absl::string_view params_str, DateFormatterSharedPtr& date_formatter) { - params_str = StringUtil::trim(params_str); - std::string format; - if (!params_str.empty()) { - if (params_str.front() != '(' || params_str.back() != ')') { - throw EnvoyException(fmt::format("Invalid header configuration. Expected format " - "START_TIME or START_TIME(%s ...), actual format " - "START_TIME{}", - params_str)); - } - format = std::string(params_str.substr(1, params_str.size() - 2)); // trim parens - } - - if (!format.empty()) { - date_formatter.reset(new Envoy::DateFormatter(format)); - } - - return - [format, date_formatter](const Envoy::RequestInfo::RequestInfo& request_info) -> std::string { - if (format.empty()) { - return AccessLogDateTimeFormatter::fromTime(request_info.startTime()); - } - return date_formatter->fromTime(request_info.startTime()); - }; -} - } // namespace RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_name, bool append) @@ -162,8 +136,13 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n *request_info.downstreamLocalAddress()); }; } else if (field_name.find("START_TIME") == 0) { - field_extractor_ = - parseStartTimeField(field_name.substr(STATIC_STRLEN("START_TIME")), date_formatter_); + field_extractor_ = [field_name](const Envoy::RequestInfo::RequestInfo& request_info) { + const auto formatters = + AccessLog::AccessLogFormatParser::parse(fmt::format("%{}%", field_name)); + ASSERT(formatters.size() == 1); + Http::HeaderMapImpl empty_map; + return formatters.at(0)->format(empty_map, empty_map, empty_map, request_info); + }; } else if (field_name.find("UPSTREAM_METADATA") == 0) { field_extractor_ = parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA"))); From 24518efcead6a139870783903bd1cb75374aba60 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 29 May 2018 14:55:33 +0700 Subject: [PATCH 26/46] Use map to cache access log formatter Signed-off-by: Dhi Aurrahman --- source/common/router/header_formatter.cc | 12 ++++++++---- source/common/router/header_formatter.h | 6 +----- test/common/common/utility_speed_test.cc | 4 ++-- 3 files changed, 11 insertions(+), 11 deletions(-) diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 2dce3d8b03344..18cefb1aad23b 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -136,11 +136,15 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n *request_info.downstreamLocalAddress()); }; } else if (field_name.find("START_TIME") == 0) { - field_extractor_ = [field_name](const Envoy::RequestInfo::RequestInfo& request_info) { - const auto formatters = - AccessLog::AccessLogFormatParser::parse(fmt::format("%{}%", field_name)); - ASSERT(formatters.size() == 1); + const std::string pattern = fmt::format("%{}%", field_name); + if (start_time_formatters_.find(pattern) == start_time_formatters_.end()) { + start_time_formatters_.emplace( + std::make_pair(pattern, AccessLog::AccessLogFormatParser::parse(pattern))); + } + field_extractor_ = [this, pattern](const Envoy::RequestInfo::RequestInfo& request_info) { Http::HeaderMapImpl empty_map; + const auto& formatters = start_time_formatters_.at(pattern); + ASSERT(formatters.size() == 1); return formatters.at(0)->format(empty_map, empty_map, empty_map, request_info); }; } else if (field_name.find("UPSTREAM_METADATA") == 0) { diff --git a/source/common/router/header_formatter.h b/source/common/router/header_formatter.h index 99eaa1aac6b27..7de8ab442a9ff 100644 --- a/source/common/router/header_formatter.h +++ b/source/common/router/header_formatter.h @@ -9,10 +9,6 @@ #include "absl/strings/string_view.h" namespace Envoy { - -class DateFormatter; -typedef std::shared_ptr DateFormatterSharedPtr; - namespace Router { /** @@ -47,7 +43,7 @@ class RequestInfoHeaderFormatter : public HeaderFormatter { private: std::function field_extractor_; const bool append_; - DateFormatterSharedPtr date_formatter_; + std::map> start_time_formatters_; }; /** diff --git a/test/common/common/utility_speed_test.cc b/test/common/common/utility_speed_test.cc index 5b95b3b58261e..1e8b31d1dde88 100644 --- a/test/common/common/utility_speed_test.cc +++ b/test/common/common/utility_speed_test.cc @@ -49,7 +49,7 @@ static void BM_DateTimeFormatterWithSubseconds(benchmark::State& state) { int outputBytes = 0; Envoy::SystemTime time(std::chrono::seconds(1522796769)); - std::mt19937 prng(1); // PRNG with a fixed seed, for repeatability + std::mt19937 prng(1); std::uniform_int_distribution distribution(-10, 20); Envoy::DateFormatter date_formatter("%Y-%m-%dT%H:%M:%s.%3f"); for (auto _ : state) { @@ -64,7 +64,7 @@ static void BM_DateTimeFormatterWithoutSubseconds(benchmark::State& state) { int outputBytes = 0; Envoy::SystemTime time(std::chrono::seconds(1522796769)); - std::mt19937 prng(1); // PRNG with a fixed seed, for repeatability + std::mt19937 prng(1); std::uniform_int_distribution distribution(-10, 20); Envoy::DateFormatter date_formatter("%Y-%m-%dT%H:%M:%s"); for (auto _ : state) { From 0f0b1bfd88f2399774d3d6371893481c425ed35b Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 29 May 2018 17:48:51 +0700 Subject: [PATCH 27/46] review: update docs Signed-off-by: Dhi Aurrahman --- docs/root/configuration/access_log.rst | 26 +++++++++++++++---- .../configuration/http_conn_man/headers.rst | 6 ++--- source/common/router/header_formatter.cc | 2 +- test/common/router/header_formatter_test.cc | 1 - 4 files changed, 25 insertions(+), 10 deletions(-) diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index ee1eb96c45ff6..3b084fc77abe9 100644 --- a/docs/root/configuration/access_log.rst +++ b/docs/root/configuration/access_log.rst @@ -39,16 +39,32 @@ The following command operators are supported: Downstream connection start time including milliseconds. START_TIME can be customized using a `format string `_. - In addition to that, START_TIME also accepts :code:`%f` to get the subsecond digits. The default is 9 digits (nanosecond). - The number of digits can be specified by specifiying the digit number after :code:`%`, e.g. :code:`%3f` to get 3 digits. + In addition to that, START_TIME also accepts following specifiers: + + +------------------------+--------------------------------------------------------------+ + | Specifier | Explanation | + +========================+==============================================================+ + | ``%s`` | The number of seconds since the Epoch. | + +------------------------+--------------------------------------------------------------+ + | ``%f``, ``%{:digit}f`` | Fractional seconds digits, default is 9 digits (nanosecond). | + | +--------------------------------------------------------------+ + | | - ``%3f`` millisecond (3 digits). | + | | - ``%6f`` microsecond (6 digits). | + | | - ``%9f`` nanosecond (9 digits). | + +------------------------+--------------------------------------------------------------+ Examples of formatting START_TIME is as follows: -.. code-block:: none + .. code-block:: none + + %START_TIME(%Y/%m/%dT%H:%M:%S%z %s)% + + # To include millisecond fraction of the second (.000 ... .999). E.g. 1527590590.528. + %START_TIME(%s.%3f)% - %START_TIME(%Y/%m/%dT%H:%M:%S%z %s)% + %START_TIME(%s.%6f)% - %START_TIME(%s%3f)% + %START_TIME(%s.%9f)% %BYTES_RECEIVED% HTTP diff --git a/docs/root/configuration/http_conn_man/headers.rst b/docs/root/configuration/http_conn_man/headers.rst index dcf352f0784b0..dd4974b5d0b75 100644 --- a/docs/root/configuration/http_conn_man/headers.rst +++ b/docs/root/configuration/http_conn_man/headers.rst @@ -474,9 +474,9 @@ Supported variable names are: parameters **do not** need to be escaped by doubling them. %START_TIME% - Request start time including milliseconds. START_TIME can be customized as mentioned in + Request start time. START_TIME can be customized with specifiers as specified in :ref:`access log format rules`. An example of setting a custom header with - timestamp since epoch in milliseconds is: + current time in seconds with the milliseconds resolution: .. code-block:: none @@ -485,5 +485,5 @@ Supported variable names are: request_headers_to_add: - header: key: "x-request-start" - value: "%START_TIME(%s%3f)%" + value: "%START_TIME(%s.%3f)%" append: true \ No newline at end of file diff --git a/source/common/router/header_formatter.cc b/source/common/router/header_formatter.cc index 18cefb1aad23b..b691159879e36 100644 --- a/source/common/router/header_formatter.cc +++ b/source/common/router/header_formatter.cc @@ -142,9 +142,9 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n std::make_pair(pattern, AccessLog::AccessLogFormatParser::parse(pattern))); } field_extractor_ = [this, pattern](const Envoy::RequestInfo::RequestInfo& request_info) { - Http::HeaderMapImpl empty_map; const auto& formatters = start_time_formatters_.at(pattern); ASSERT(formatters.size() == 1); + Http::HeaderMapImpl empty_map; return formatters.at(0)->format(empty_map, empty_map, empty_map, request_info); }; } else if (field_name.find("UPSTREAM_METADATA") == 0) { diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index 5e6baa2187a75..7892658f5a00d 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -3,7 +3,6 @@ #include "envoy/api/v2/core/base.pb.h" #include "envoy/http/protocol.h" -#include "common/access_log/access_log_formatter.h" #include "common/config/metadata.h" #include "common/config/rds_json.h" #include "common/router/header_formatter.h" From f78e7ad5017b21a34793d08275bfcf2aa902bf3c Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 29 May 2018 18:23:59 +0700 Subject: [PATCH 28/46] Fix additional specifiers table format Signed-off-by: Dhi Aurrahman --- docs/root/configuration/access_log.rst | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index 3b084fc77abe9..5a6ba107889cc 100644 --- a/docs/root/configuration/access_log.rst +++ b/docs/root/configuration/access_log.rst @@ -41,17 +41,17 @@ The following command operators are supported: START_TIME can be customized using a `format string `_. In addition to that, START_TIME also accepts following specifiers: - +------------------------+--------------------------------------------------------------+ - | Specifier | Explanation | - +========================+==============================================================+ - | ``%s`` | The number of seconds since the Epoch. | - +------------------------+--------------------------------------------------------------+ - | ``%f``, ``%{:digit}f`` | Fractional seconds digits, default is 9 digits (nanosecond). | - | +--------------------------------------------------------------+ - | | - ``%3f`` millisecond (3 digits). | - | | - ``%6f`` microsecond (6 digits). | - | | - ``%9f`` nanosecond (9 digits). | - +------------------------+--------------------------------------------------------------+ + +------------------------+-------------------------------------------------------------+ + | Specifier | Explanation | + +========================+=============================================================+ + | ``%s`` | The number of seconds since the Epoch | + +------------------------+-------------------------------------------------------------+ + | ``%f``, ``%{:digit}f`` | Fractional seconds digits, default is 9 digits (nanosecond) | + | +-------------------------------------------------------------+ + | | - ``%3f`` millisecond (3 digits) | + | | - ``%6f`` microsecond (6 digits) | + | | - ``%9f`` nanosecond (9 digits) | + +------------------------+-------------------------------------------------------------+ Examples of formatting START_TIME is as follows: From 7aeb76704e0a637bd91779ce8b79ad883f921791 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 29 May 2018 18:40:29 +0700 Subject: [PATCH 29/46] Use [1-9] instead of {:digit} Signed-off-by: Dhi Aurrahman --- docs/root/configuration/access_log.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index 5a6ba107889cc..e97da4bf39f4e 100644 --- a/docs/root/configuration/access_log.rst +++ b/docs/root/configuration/access_log.rst @@ -46,7 +46,7 @@ The following command operators are supported: +========================+=============================================================+ | ``%s`` | The number of seconds since the Epoch | +------------------------+-------------------------------------------------------------+ - | ``%f``, ``%{:digit}f`` | Fractional seconds digits, default is 9 digits (nanosecond) | + | ``%f``, ``%[1-9]f`` | Fractional seconds digits, default is 9 digits (nanosecond) | | +-------------------------------------------------------------+ | | - ``%3f`` millisecond (3 digits) | | | - ``%6f`` microsecond (6 digits) | From 63104474931e5d858a0a4f2456f2c8d4c845d8bc Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 29 May 2018 18:53:11 +0700 Subject: [PATCH 30/46] Fix doc's indentations Signed-off-by: Dhi Aurrahman --- docs/root/configuration/access_log.rst | 5 ++++ .../configuration/http_conn_man/headers.rst | 25 ++++++++++--------- 2 files changed, 18 insertions(+), 12 deletions(-) diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index e97da4bf39f4e..179daf6f53bc5 100644 --- a/docs/root/configuration/access_log.rst +++ b/docs/root/configuration/access_log.rst @@ -66,6 +66,11 @@ The following command operators are supported: %START_TIME(%s.%9f)% + .. attention:: + + Do not include **?** in START_TIME's specifier, since it is used internally as placeholder + for subseconds. + %BYTES_RECEIVED% HTTP Body bytes received. diff --git a/docs/root/configuration/http_conn_man/headers.rst b/docs/root/configuration/http_conn_man/headers.rst index dd4974b5d0b75..da2e70088caa6 100644 --- a/docs/root/configuration/http_conn_man/headers.rst +++ b/docs/root/configuration/http_conn_man/headers.rst @@ -475,15 +475,16 @@ Supported variable names are: %START_TIME% Request start time. START_TIME can be customized with specifiers as specified in - :ref:`access log format rules`. An example of setting a custom header with - current time in seconds with the milliseconds resolution: - -.. code-block:: none - - route: - cluster: www - request_headers_to_add: - - header: - key: "x-request-start" - value: "%START_TIME(%s.%3f)%" - append: true \ No newline at end of file + :ref:`access log format rules`. + + An example of setting a custom header with current time in seconds with the milliseconds resolution: + + .. code-block:: none + + route: + cluster: www + request_headers_to_add: + - header: + key: "x-request-start" + value: "%START_TIME(%s.%3f)%" + append: true \ No newline at end of file From 8a1571f82a01c53d14e9c0633b20d067d6e38d70 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Fri, 1 Jun 2018 06:32:35 +0700 Subject: [PATCH 31/46] No more find() Signed-off-by: Dhi Aurrahman --- docs/root/configuration/access_log.rst | 5 --- source/common/common/utility.cc | 44 +++++++++++++------ source/common/common/utility.h | 10 ++++- .../access_log/access_log_formatter_test.cc | 15 ++++++- test/common/router/header_formatter_test.cc | 4 +- 5 files changed, 54 insertions(+), 24 deletions(-) diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index 179daf6f53bc5..e97da4bf39f4e 100644 --- a/docs/root/configuration/access_log.rst +++ b/docs/root/configuration/access_log.rst @@ -66,11 +66,6 @@ The following command operators are supported: %START_TIME(%s.%9f)% - .. attention:: - - Do not include **?** in START_TIME's specifier, since it is used internally as placeholder - for subseconds. - %BYTES_RECEIVED% HTTP Body bytes received. diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index cccfe26240cea..566baa6005c1d 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -27,7 +27,6 @@ namespace { class SubsecondConstantValues { public: - const size_t DEFAULT_SECONDS_LENGTH{10}; const char PLACEHOLDER_CHAR{'?'}; const std::string PLACEHOLDER{"?????????"}; const std::regex PATTERN{"%([1-9])?f", std::regex::optimize}; @@ -40,6 +39,7 @@ typedef ConstSingleton SubsecondConstants; std::string DateFormatter::fromTime(const SystemTime& time) const { struct CachedTime { std::chrono::seconds epoch_time_seconds; + // A map is used to keep different formatted format strings at a given second. std::unordered_map formatted; }; static thread_local CachedTime cached_time; @@ -58,34 +58,50 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { cached_time.epoch_time_seconds = epoch_time_seconds; } - if (subsecond_widths_.empty()) { + if (subseconds_.empty()) { return cached_time.formatted.at(format_string_); } - // Copy the cached formatted string, then replace its subseconds part. + // Copy the current cached formatted format string, then replace its subseconds part. std::string formatted = cached_time.formatted.at(format_string_); const std::string value = fmt::FormatInt(epoch_time_ns.count()).str(); - for (const auto width : subsecond_widths_) { - const std::string subsecond = - value.substr(SubsecondConstants::get().DEFAULT_SECONDS_LENGTH, width); - const size_t placeholder_index = formatted.find(SubsecondConstants::get().PLACEHOLDER_CHAR); - ASSERT(placeholder_index != std::string::npos); - formatted.replace(placeholder_index, width, subsecond); + for (const auto subsecond : subseconds_) { + // TODO(dio): Infer the length of second from parsing step. Currently, it is defaulted to 10. + const std::string digits = value.substr(10, subsecond.width_); + formatted.replace(subsecond.position_, subsecond.width_, digits); } + // TODO(dio): Assert the formatted length. return formatted; } std::string DateFormatter::parse(const std::string& format_string) { + auto now = std::chrono::system_clock::now(); + time_t current_time = std::chrono::system_clock::to_time_t(now); + tm current_tm; + gmtime_r(¤t_time, ¤t_tm); + std::string new_format_string = format_string; - std::smatch result; - while (regex_search(new_format_string, result, SubsecondConstants::get().PATTERN)) { - const std::string& width_specifier = result[1]; + std::smatch matched; + size_t position = 0; + size_t previous = 0; + std::array buf; + while (regex_search(new_format_string, matched, SubsecondConstants::get().PATTERN)) { + const std::string& width_specifier = matched[1]; const size_t width = width_specifier.empty() ? SubsecondConstants::get().PLACEHOLDER.size() : width_specifier.at(0) - '0'; - subsecond_widths_.emplace_back(width); - new_format_string.replace(result.position(), result.length(), + new_format_string.replace(matched.position(), matched.length(), SubsecondConstants::get().PLACEHOLDER.substr(0, width)); + + const std::string part = new_format_string.substr(previous, matched.position() - previous); + const size_t formatted_length = strftime(&buf[0], buf.size(), part.c_str(), ¤t_tm); + + // Save subsecond's position and width to be used later at data path. + SubsecondSpecifier subsecond(position + formatted_length, width); + subseconds_.emplace_back(subsecond); + + position += formatted_length + width; + previous = matched.position() + width; } return new_format_string; } diff --git a/source/common/common/utility.h b/source/common/common/utility.h index b1f1386dec5fa..1b1020081b227 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -49,7 +49,15 @@ class DateFormatter { private: std::string parse(const std::string& format_string); - std::vector subsecond_widths_; + + struct SubsecondSpecifier { + SubsecondSpecifier(const size_t position, const size_t width) + : position_(position), width_(width) {} + + const size_t position_; + const size_t width_; + }; + std::vector subseconds_; const std::string format_string_; }; diff --git a/test/common/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc index 3fab1b95dad53..af1ec7367059e 100644 --- a/test/common/access_log/access_log_formatter_test.cc +++ b/test/common/access_log/access_log_formatter_test.cc @@ -414,11 +414,22 @@ TEST(AccessLogFormatterTest, CompositeFormatterSuccess) { { const std::string format = - "%START_TIME(%s%3f)%|%START_TIME(%s%4f)%|%START_TIME(%s%5f)%|%START_TIME(%s%6f)%"; + "%START_TIME(%s.%3f)%|%START_TIME(%s.%4f)%|%START_TIME(%s.%5f)%|%START_TIME(%s.%6f)%"; const SystemTime start_time(std::chrono::microseconds(1522796769123456)); EXPECT_CALL(request_info, startTime()).WillRepeatedly(Return(start_time)); FormatterImpl formatter(format); - EXPECT_EQ("1522796769123|15227967691234|152279676912345|1522796769123456", + EXPECT_EQ("1522796769.123|1522796769.1234|1522796769.12345|1522796769.123456", + formatter.format(request_header, response_header, response_trailer, request_info)); + } + + { + const std::string format = + "%START_TIME(segment1:%s.%3f|segment2:%s.%4f|seg3:%s.%6f|.%7f:segm4:%Y)%"; + const SystemTime start_time(std::chrono::microseconds(1522796769123456)); + EXPECT_CALL(request_info, startTime()).WillRepeatedly(Return(start_time)); + FormatterImpl formatter(format); + EXPECT_EQ("segment1:1522796769.123|segment2:1522796769.1234|seg3:1522796769.123456|.1234560:" + "segm4:2018", formatter.format(request_header, response_header, response_trailer, request_info)); } } diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index 7892658f5a00d..1e80c0bb37e0a 100644 --- a/test/common/router/header_formatter_test.cc +++ b/test/common/router/header_formatter_test.cc @@ -612,7 +612,7 @@ match: { prefix: "/new_endpoint" } append: true - header: key: "x-request-start" - value: "%START_TIME(%s%3f)%" + value: "%START_TIME(%s.%3f)%" append: true - header: key: "x-request-start-f" @@ -644,7 +644,7 @@ match: { prefix: "/new_endpoint" } EXPECT_TRUE(headerMap.has("x-safe")); EXPECT_FALSE(headerMap.has("x-nope")); EXPECT_TRUE(headerMap.has("x-request-start")); - EXPECT_EQ("1522796769123", headerMap.get_("x-request-start")); + EXPECT_EQ("1522796769.123", headerMap.get_("x-request-start")); EXPECT_TRUE(headerMap.has("x-request-start-f")); EXPECT_EQ("f", headerMap.get_("x-request-start-f")); EXPECT_TRUE(headerMap.has("x-request-start-default")); From 325fdc5cc8974a105e376a33fcffd3a716ba1484 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Sun, 3 Jun 2018 05:26:15 +0700 Subject: [PATCH 32/46] Move subsecond offsets computation Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 86 +++++++++++++------ .../access_log/access_log_formatter_test.cc | 6 +- 2 files changed, 61 insertions(+), 31 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 566baa6005c1d..0c56578edfeff 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -38,9 +38,15 @@ typedef ConstSingleton SubsecondConstants; std::string DateFormatter::fromTime(const SystemTime& time) const { struct CachedTime { + size_t seconds_length; std::chrono::seconds epoch_time_seconds; + + struct Formatted { + std::vector subsecond_offsets; + std::string value; + }; // A map is used to keep different formatted format strings at a given second. - std::unordered_map formatted; + std::unordered_map formatted; }; static thread_local CachedTime cached_time; @@ -52,57 +58,81 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { if (cached_time.formatted.find(format_string_) == cached_time.formatted.end() || cached_time.epoch_time_seconds != epoch_time_seconds) { - cached_time.formatted.emplace( - std::make_pair(format_string_, fromTime(std::chrono::system_clock::to_time_t(time)))); + time_t current_time = std::chrono::system_clock::to_time_t(time); + + CachedTime::Formatted formatted; + if (subseconds_.empty()) { + formatted.value = fromTime(current_time); + } else { + tm current_tm; + gmtime_r(¤t_time, ¤t_tm); + + formatted.value.clear(); + formatted.subsecond_offsets.clear(); + + size_t position = 0; + int32_t previous = 0; + std::array buf; + for (const auto& subsecond : subseconds_) { + ASSERT(position < format_string_.size()); + const std::string part = format_string_.substr(position, subsecond.position_ - position); + const size_t formatted_length = strftime(&buf[0], buf.size(), part.c_str(), ¤t_tm); + absl::StrAppend(&formatted.value, std::string(&buf[0]), + format_string_.substr(subsecond.position_, subsecond.width_)); + + const int32_t offset = formatted_length - part.size(); + formatted.subsecond_offsets.emplace_back(previous + offset); + + position = subsecond.position_ + subsecond.width_; + previous += offset; + } + if (position < format_string_.size()) { + const std::string last = format_string_.substr(position); + strftime(&buf[0], buf.size(), last.c_str(), ¤t_tm); + absl::StrAppend(&formatted.value, std::string(&buf[0])); + } + } + + cached_time.formatted.emplace(std::make_pair(format_string_, formatted)); + cached_time.seconds_length = fmt::FormatInt(epoch_time_seconds.count()).str().size(); cached_time.epoch_time_seconds = epoch_time_seconds; } + const auto& formatted = cached_time.formatted.at(format_string_); if (subseconds_.empty()) { - return cached_time.formatted.at(format_string_); + return formatted.value; } + ASSERT(subseconds_.size() == formatted.subsecond_offsets.size()); + // Copy the current cached formatted format string, then replace its subseconds part. - std::string formatted = cached_time.formatted.at(format_string_); + std::string formatted_str = formatted.value; const std::string value = fmt::FormatInt(epoch_time_ns.count()).str(); - for (const auto subsecond : subseconds_) { - // TODO(dio): Infer the length of second from parsing step. Currently, it is defaulted to 10. - const std::string digits = value.substr(10, subsecond.width_); - formatted.replace(subsecond.position_, subsecond.width_, digits); + for (size_t i = 0; i < subseconds_.size(); ++i) { + const auto& subsecond = subseconds_.at(i); + const std::string digits = value.substr(cached_time.seconds_length, subsecond.width_); + formatted_str.replace(subsecond.position_ + formatted.subsecond_offsets.at(i), subsecond.width_, + digits); } - // TODO(dio): Assert the formatted length. - return formatted; + ASSERT(formatted_str.size() == formatted.value.size()); + return formatted_str; } std::string DateFormatter::parse(const std::string& format_string) { - auto now = std::chrono::system_clock::now(); - time_t current_time = std::chrono::system_clock::to_time_t(now); - tm current_tm; - gmtime_r(¤t_time, ¤t_tm); - std::string new_format_string = format_string; std::smatch matched; - size_t position = 0; - size_t previous = 0; - std::array buf; while (regex_search(new_format_string, matched, SubsecondConstants::get().PATTERN)) { const std::string& width_specifier = matched[1]; const size_t width = width_specifier.empty() ? SubsecondConstants::get().PLACEHOLDER.size() : width_specifier.at(0) - '0'; new_format_string.replace(matched.position(), matched.length(), SubsecondConstants::get().PLACEHOLDER.substr(0, width)); - - const std::string part = new_format_string.substr(previous, matched.position() - previous); - const size_t formatted_length = strftime(&buf[0], buf.size(), part.c_str(), ¤t_tm); - - // Save subsecond's position and width to be used later at data path. - SubsecondSpecifier subsecond(position + formatted_length, width); + SubsecondSpecifier subsecond(matched.position(), width); subseconds_.emplace_back(subsecond); - - position += formatted_length + width; - previous = matched.position() + width; } + return new_format_string; } diff --git a/test/common/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc index af1ec7367059e..b5da1609d4630 100644 --- a/test/common/access_log/access_log_formatter_test.cc +++ b/test/common/access_log/access_log_formatter_test.cc @@ -424,12 +424,12 @@ TEST(AccessLogFormatterTest, CompositeFormatterSuccess) { { const std::string format = - "%START_TIME(segment1:%s.%3f|segment2:%s.%4f|seg3:%s.%6f|.%7f:segm4:%Y)%"; + "%START_TIME(segment1:%s.%3f|segment2:%s.%4f|seg3:%s.%6f|%s-%3f-asdf-%9f|.%7f:segm5:%Y)%"; const SystemTime start_time(std::chrono::microseconds(1522796769123456)); EXPECT_CALL(request_info, startTime()).WillRepeatedly(Return(start_time)); FormatterImpl formatter(format); - EXPECT_EQ("segment1:1522796769.123|segment2:1522796769.1234|seg3:1522796769.123456|.1234560:" - "segm4:2018", + EXPECT_EQ("segment1:1522796769.123|segment2:1522796769.1234|seg3:1522796769.123456|1522796769-" + "123-asdf-123456000|.1234560:segm5:2018", formatter.format(request_header, response_header, response_trailer, request_info)); } } From 9aba1e9cf3856b7a23cd759cd8c5059ed04a2ad9 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Sun, 3 Jun 2018 11:08:57 +0700 Subject: [PATCH 33/46] Move the offsets calc to fromTimeAndPrepareSubsecondOffsets Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 87 ++++++++++++++++++--------------- source/common/common/utility.h | 4 ++ 2 files changed, 51 insertions(+), 40 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 0c56578edfeff..d7646d5e394dc 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -42,8 +42,8 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { std::chrono::seconds epoch_time_seconds; struct Formatted { - std::vector subsecond_offsets; - std::string value; + SubsecondOffsets subsecond_offsets; + std::string str; }; // A map is used to keep different formatted format strings at a given second. std::unordered_map formatted; @@ -61,38 +61,10 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { time_t current_time = std::chrono::system_clock::to_time_t(time); CachedTime::Formatted formatted; - if (subseconds_.empty()) { - formatted.value = fromTime(current_time); - } else { - tm current_tm; - gmtime_r(¤t_time, ¤t_tm); - - formatted.value.clear(); - formatted.subsecond_offsets.clear(); - - size_t position = 0; - int32_t previous = 0; - std::array buf; - for (const auto& subsecond : subseconds_) { - ASSERT(position < format_string_.size()); - const std::string part = format_string_.substr(position, subsecond.position_ - position); - const size_t formatted_length = strftime(&buf[0], buf.size(), part.c_str(), ¤t_tm); - absl::StrAppend(&formatted.value, std::string(&buf[0]), - format_string_.substr(subsecond.position_, subsecond.width_)); - - const int32_t offset = formatted_length - part.size(); - formatted.subsecond_offsets.emplace_back(previous + offset); - - position = subsecond.position_ + subsecond.width_; - previous += offset; - } - - if (position < format_string_.size()) { - const std::string last = format_string_.substr(position); - strftime(&buf[0], buf.size(), last.c_str(), ¤t_tm); - absl::StrAppend(&formatted.value, std::string(&buf[0])); - } - } + formatted.str = + subseconds_.empty() + ? fromTime(current_time) + : fromTimeAndPrepareSubsecondOffsets(current_time, formatted.subsecond_offsets); cached_time.formatted.emplace(std::make_pair(format_string_, formatted)); cached_time.seconds_length = fmt::FormatInt(epoch_time_seconds.count()).str().size(); @@ -101,22 +73,23 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { const auto& formatted = cached_time.formatted.at(format_string_); if (subseconds_.empty()) { - return formatted.value; + return formatted.str; } ASSERT(subseconds_.size() == formatted.subsecond_offsets.size()); - // Copy the current cached formatted format string, then replace its subseconds part. - std::string formatted_str = formatted.value; - const std::string value = fmt::FormatInt(epoch_time_ns.count()).str(); + // Copy the current cached formatted format string, then replace its subseconds part using the + // prepared subseconds offsets. + std::string formatted_str = formatted.str; + const std::string nanoseconds = fmt::FormatInt(epoch_time_ns.count()).str(); for (size_t i = 0; i < subseconds_.size(); ++i) { const auto& subsecond = subseconds_.at(i); - const std::string digits = value.substr(cached_time.seconds_length, subsecond.width_); + const std::string digits = nanoseconds.substr(cached_time.seconds_length, subsecond.width_); formatted_str.replace(subsecond.position_ + formatted.subsecond_offsets.at(i), subsecond.width_, digits); } - ASSERT(formatted_str.size() == formatted.value.size()); + ASSERT(formatted_str.size() == formatted.str.size()); return formatted_str; } @@ -145,6 +118,40 @@ std::string DateFormatter::fromTime(time_t time) const { return std::string(&buf[0]); } +std::string +DateFormatter::fromTimeAndPrepareSubsecondOffsets(time_t time, + SubsecondOffsets& subsecond_offsets) const { + tm current_tm; + gmtime_r(&time, ¤t_tm); + + std::array buf; + std::string formatted; + + size_t step = 0; + int32_t previous = 0; + for (const auto& subsecond : subseconds_) { + ASSERT(step < format_string_.size()); + const std::string segment = format_string_.substr(step, subsecond.position_ - step); + const size_t formatted_length = strftime(&buf[0], buf.size(), segment.c_str(), ¤t_tm); + absl::StrAppend(&formatted, &buf[0], + format_string_.substr(subsecond.position_, subsecond.width_)); + + const int32_t offset = formatted_length - segment.size(); + subsecond_offsets.emplace_back(previous + offset); + + step = subsecond.position_ + subsecond.width_; + previous += offset; + } + + if (step < format_string_.size()) { + const std::string last_segment = format_string_.substr(step); + strftime(&buf[0], buf.size(), last_segment.c_str(), ¤t_tm); + absl::StrAppend(&formatted, &buf[0]); + } + + return formatted; +} + std::string DateFormatter::now() { time_t current_time_t; time(¤t_time_t); diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 1b1020081b227..07fe63eb3deec 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -50,6 +50,10 @@ class DateFormatter { private: std::string parse(const std::string& format_string); + typedef std::vector SubsecondOffsets; + std::string fromTimeAndPrepareSubsecondOffsets(time_t time, + SubsecondOffsets& subsecond_offsets) const; + struct SubsecondSpecifier { SubsecondSpecifier(const size_t position, const size_t width) : position_(position), width_(width) {} From 94e3addf09332b07d0b116329d66281672795611 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Sun, 3 Jun 2018 11:24:54 +0700 Subject: [PATCH 34/46] Cleanup unused deps and vars Signed-off-by: Dhi Aurrahman --- source/common/common/BUILD | 1 - source/common/common/utility.cc | 3 +-- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/source/common/common/BUILD b/source/common/common/BUILD index 2a93b28103970..fc0e43d110f1b 100644 --- a/source/common/common/BUILD +++ b/source/common/common/BUILD @@ -156,7 +156,6 @@ envoy_cc_library( hdrs = ["utility.h"], deps = [ ":assert_lib", - ":empty_string", ":hash_lib", "//include/envoy/common:interval_set_interface", "//include/envoy/common:time_interface", diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index d7646d5e394dc..bcd6ae33b57ad 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -10,7 +10,6 @@ #include "envoy/common/exception.h" #include "common/common/assert.h" -#include "common/common/empty_string.h" #include "common/common/fmt.h" #include "common/common/hash.h" #include "common/singleton/const_singleton.h" @@ -27,7 +26,6 @@ namespace { class SubsecondConstantValues { public: - const char PLACEHOLDER_CHAR{'?'}; const std::string PLACEHOLDER{"?????????"}; const std::regex PATTERN{"%([1-9])?f", std::regex::optimize}; }; @@ -129,6 +127,7 @@ DateFormatter::fromTimeAndPrepareSubsecondOffsets(time_t time, size_t step = 0; int32_t previous = 0; + subsecond_offsets.reserve(subseconds_.size()); for (const auto& subsecond : subseconds_) { ASSERT(step < format_string_.size()); const std::string segment = format_string_.substr(step, subsecond.position_ - step); From 612f82950c8343a5069668d24d0e5b9a0b0fd2a3 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Sun, 3 Jun 2018 13:20:47 +0700 Subject: [PATCH 35/46] Infer seconds_length only when it is needed Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index bcd6ae33b57ad..b84a8755616c9 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -59,13 +59,14 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { time_t current_time = std::chrono::system_clock::to_time_t(time); CachedTime::Formatted formatted; - formatted.str = - subseconds_.empty() - ? fromTime(current_time) - : fromTimeAndPrepareSubsecondOffsets(current_time, formatted.subsecond_offsets); + if (subseconds_.empty()) { + formatted.str = fromTime(current_time); + } else { + formatted.str = fromTimeAndPrepareSubsecondOffsets(current_time, formatted.subsecond_offsets); + cached_time.seconds_length = fmt::FormatInt(epoch_time_seconds.count()).str().size(); + } cached_time.formatted.emplace(std::make_pair(format_string_, formatted)); - cached_time.seconds_length = fmt::FormatInt(epoch_time_seconds.count()).str().size(); cached_time.epoch_time_seconds = epoch_time_seconds; } From 96f915e16fca1ca4a391ee533d93d8ca7b16b523 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 5 Jun 2018 09:30:05 +0700 Subject: [PATCH 36/46] Precompute the string segments between specifiers Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 52 ++++++++++++++++++++++----------- source/common/common/utility.h | 9 ++++-- 2 files changed, 42 insertions(+), 19 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index b84a8755616c9..05e569bedaed5 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -54,9 +54,15 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { const std::chrono::seconds epoch_time_seconds = std::chrono::duration_cast(epoch_time_ns); - if (cached_time.formatted.find(format_string_) == cached_time.formatted.end() || - cached_time.epoch_time_seconds != epoch_time_seconds) { - time_t current_time = std::chrono::system_clock::to_time_t(time); + const bool new_period = cached_time.epoch_time_seconds != epoch_time_seconds; + if (cached_time.formatted.find(format_string_) == cached_time.formatted.end() || new_period) { + if (new_period) { + // Caching is done only for a second long. We clear it every a new period of second is + // observed. + cached_time.formatted.clear(); + } + + const time_t current_time = std::chrono::system_clock::to_time_t(time); CachedTime::Formatted formatted; if (subseconds_.empty()) { @@ -83,9 +89,9 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { const std::string nanoseconds = fmt::FormatInt(epoch_time_ns.count()).str(); for (size_t i = 0; i < subseconds_.size(); ++i) { const auto& subsecond = subseconds_.at(i); - const std::string digits = nanoseconds.substr(cached_time.seconds_length, subsecond.width_); + absl::string_view digits = nanoseconds.substr(cached_time.seconds_length, subsecond.width_); formatted_str.replace(subsecond.position_ + formatted.subsecond_offsets.at(i), subsecond.width_, - digits); + digits.data()); } ASSERT(formatted_str.size() == formatted.str.size()); @@ -95,14 +101,29 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { std::string DateFormatter::parse(const std::string& format_string) { std::string new_format_string = format_string; std::smatch matched; + size_t step = 0; while (regex_search(new_format_string, matched, SubsecondConstants::get().PATTERN)) { const std::string& width_specifier = matched[1]; const size_t width = width_specifier.empty() ? SubsecondConstants::get().PLACEHOLDER.size() : width_specifier.at(0) - '0'; new_format_string.replace(matched.position(), matched.length(), SubsecondConstants::get().PLACEHOLDER.substr(0, width)); - SubsecondSpecifier subsecond(matched.position(), width); + + ASSERT(step < new_format_string.size()); + + // This records matched position, the width of current subsecond pattern, and also the string + // segment before the matched position. These values will be used later at data path. + SubsecondSpecifier subsecond(matched.position(), width, + new_format_string.substr(step, matched.position() - step)); subseconds_.emplace_back(subsecond); + + step = subsecond.position_ + subsecond.width_; + } + + // To capture the segment after the last subsecond pattern of a format string. E.g. + // %3f-this-is-the-last-%s-segment-%Y-until-this. + if (step < new_format_string.size()) { + last_segment_ = new_format_string.substr(step); } return new_format_string; @@ -126,26 +147,23 @@ DateFormatter::fromTimeAndPrepareSubsecondOffsets(time_t time, std::array buf; std::string formatted; - size_t step = 0; int32_t previous = 0; subsecond_offsets.reserve(subseconds_.size()); for (const auto& subsecond : subseconds_) { - ASSERT(step < format_string_.size()); - const std::string segment = format_string_.substr(step, subsecond.position_ - step); - const size_t formatted_length = strftime(&buf[0], buf.size(), segment.c_str(), ¤t_tm); + const size_t formatted_length = + strftime(&buf[0], buf.size(), subsecond.segment_.c_str(), ¤t_tm); absl::StrAppend(&formatted, &buf[0], - format_string_.substr(subsecond.position_, subsecond.width_)); + SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_)); - const int32_t offset = formatted_length - segment.size(); + // This computes and saves offset of each subsecond pattern to correct its position after the + // previous string segment is formatted. + const int32_t offset = formatted_length - subsecond.segment_.size(); subsecond_offsets.emplace_back(previous + offset); - - step = subsecond.position_ + subsecond.width_; previous += offset; } - if (step < format_string_.size()) { - const std::string last_segment = format_string_.substr(step); - strftime(&buf[0], buf.size(), last_segment.c_str(), ¤t_tm); + if (!last_segment_.empty()) { + strftime(&buf[0], buf.size(), last_segment_.c_str(), ¤t_tm); absl::StrAppend(&formatted, &buf[0]); } diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 07fe63eb3deec..7ee85bed29dd1 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -55,14 +55,19 @@ class DateFormatter { SubsecondOffsets& subsecond_offsets) const; struct SubsecondSpecifier { - SubsecondSpecifier(const size_t position, const size_t width) - : position_(position), width_(width) {} + SubsecondSpecifier(const size_t position, const size_t width, const std::string& segment) + : position_(position), width_(width), segment_(segment) {} const size_t position_; const size_t width_; + + const std::string segment_; }; std::vector subseconds_; + // The last string segment after the last found subsecond pattern. + std::string last_segment_; + const std::string format_string_; }; From d5f082b3ed980abd1f47c8e12c2e30da1e2d8e05 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 5 Jun 2018 10:09:47 +0700 Subject: [PATCH 37/46] Try to fix asan on using stack after scope: digits Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 05e569bedaed5..2fe750a90db6d 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -89,9 +89,8 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { const std::string nanoseconds = fmt::FormatInt(epoch_time_ns.count()).str(); for (size_t i = 0; i < subseconds_.size(); ++i) { const auto& subsecond = subseconds_.at(i); - absl::string_view digits = nanoseconds.substr(cached_time.seconds_length, subsecond.width_); formatted_str.replace(subsecond.position_ + formatted.subsecond_offsets.at(i), subsecond.width_, - digits.data()); + nanoseconds.substr(cached_time.seconds_length, subsecond.width_)); } ASSERT(formatted_str.size() == formatted.str.size()); From b85b275fae957ba3966d345a860caacef881e147 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 5 Jun 2018 15:39:24 +0700 Subject: [PATCH 38/46] Stamp per cache item. Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 2fe750a90db6d..bf94590831cf7 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -37,11 +37,11 @@ typedef ConstSingleton SubsecondConstants; std::string DateFormatter::fromTime(const SystemTime& time) const { struct CachedTime { size_t seconds_length; - std::chrono::seconds epoch_time_seconds; struct Formatted { - SubsecondOffsets subsecond_offsets; std::string str; + SubsecondOffsets subsecond_offsets; + std::chrono::seconds epoch_time_seconds; }; // A map is used to keep different formatted format strings at a given second. std::unordered_map formatted; @@ -54,16 +54,18 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { const std::chrono::seconds epoch_time_seconds = std::chrono::duration_cast(epoch_time_ns); - const bool new_period = cached_time.epoch_time_seconds != epoch_time_seconds; - if (cached_time.formatted.find(format_string_) == cached_time.formatted.end() || new_period) { - if (new_period) { - // Caching is done only for a second long. We clear it every a new period of second is - // observed. - cached_time.formatted.clear(); + // Remove all the expired cached items. + for (const auto& item : cached_time.formatted) { + if (item.second.epoch_time_seconds != epoch_time_seconds) { + cached_time.formatted.erase(item.first); } + } + const auto& item = cached_time.formatted.find(format_string_); + if (item == cached_time.formatted.end()) { const time_t current_time = std::chrono::system_clock::to_time_t(time); + // Build a new formatted format string at current time. CachedTime::Formatted formatted; if (subseconds_.empty()) { formatted.str = fromTime(current_time); @@ -72,8 +74,9 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { cached_time.seconds_length = fmt::FormatInt(epoch_time_seconds.count()).str().size(); } + // Stamp the formatted string using the current epoch time in seconds, and then cache it in. + formatted.epoch_time_seconds = epoch_time_seconds; cached_time.formatted.emplace(std::make_pair(format_string_, formatted)); - cached_time.epoch_time_seconds = epoch_time_seconds; } const auto& formatted = cached_time.formatted.at(format_string_); From 513d4bf68d6084fd1bd51d7a7022afb62c69d4e4 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Tue, 5 Jun 2018 16:51:22 +0700 Subject: [PATCH 39/46] Fix removing an item of a map while iterating it Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index bf94590831cf7..8df94dc7ef4a4 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -55,9 +55,11 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { std::chrono::duration_cast(epoch_time_ns); // Remove all the expired cached items. - for (const auto& item : cached_time.formatted) { - if (item.second.epoch_time_seconds != epoch_time_seconds) { - cached_time.formatted.erase(item.first); + for (auto it = cached_time.formatted.cbegin(); it != cached_time.formatted.cend();) { + if (it->second.epoch_time_seconds != epoch_time_seconds) { + it = cached_time.formatted.erase(it); + } else { + it++; } } From 9a160906f85fea533333dae637c97e47d16cf5b1 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 6 Jun 2018 17:21:23 +0700 Subject: [PATCH 40/46] Remove const PLACEHOLDER Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 8df94dc7ef4a4..a57b71be32cd5 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -26,7 +26,6 @@ namespace { class SubsecondConstantValues { public: - const std::string PLACEHOLDER{"?????????"}; const std::regex PATTERN{"%([1-9])?f", std::regex::optimize}; }; @@ -108,10 +107,10 @@ std::string DateFormatter::parse(const std::string& format_string) { size_t step = 0; while (regex_search(new_format_string, matched, SubsecondConstants::get().PATTERN)) { const std::string& width_specifier = matched[1]; - const size_t width = width_specifier.empty() ? SubsecondConstants::get().PLACEHOLDER.size() - : width_specifier.at(0) - '0'; - new_format_string.replace(matched.position(), matched.length(), - SubsecondConstants::get().PLACEHOLDER.substr(0, width)); + + // When %f is the specifier, the width value should be 9 (the number of nanosecond digits). + const size_t width = width_specifier.empty() ? 9 : width_specifier.at(0) - '0'; + new_format_string.replace(matched.position(), matched.length(), std::string(width, '?')); ASSERT(step < new_format_string.size()); @@ -151,13 +150,12 @@ DateFormatter::fromTimeAndPrepareSubsecondOffsets(time_t time, std::array buf; std::string formatted; - int32_t previous = 0; + size_t previous = 0; subsecond_offsets.reserve(subseconds_.size()); for (const auto& subsecond : subseconds_) { const size_t formatted_length = strftime(&buf[0], buf.size(), subsecond.segment_.c_str(), ¤t_tm); - absl::StrAppend(&formatted, &buf[0], - SubsecondConstants::get().PLACEHOLDER.substr(0, subsecond.width_)); + absl::StrAppend(&formatted, &buf[0], std::string(subsecond.width_, '?')); // This computes and saves offset of each subsecond pattern to correct its position after the // previous string segment is formatted. From e5642baea0c9d5a23ca9e521cb1bc1b8768fae52 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 6 Jun 2018 17:22:26 +0700 Subject: [PATCH 41/46] Add comments to CachedTime struct Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index a57b71be32cd5..edb7c4a59aa47 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -35,12 +35,23 @@ typedef ConstSingleton SubsecondConstants; std::string DateFormatter::fromTime(const SystemTime& time) const { struct CachedTime { + // The string length of a number of seconds since the Epoch. E.g. for "1528270093", the length + // is 10. size_t seconds_length; + // A container object to hold a strftime'd string, its timestamp (in seconds) and a list + // of position offsets for each subsecond specifier found in a format string. struct Formatted { + // The resulted string after format string is passed to strftime at a given point in time. std::string str; - SubsecondOffsets subsecond_offsets; + + // A timestamp (in seconds) when this object is created. std::chrono::seconds epoch_time_seconds; + + // List of offsets for each subsecond specifier found in a format string. This is needed to + // compensate the position of each recorded subsecond specifier due to the possible size + // change of the previous segment (after strftime'd). + SubsecondOffsets subsecond_offsets; }; // A map is used to keep different formatted format strings at a given second. std::unordered_map formatted; From bda6762c2cf030d85f62cdf8935af6e5de54bbcc Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 6 Jun 2018 17:23:17 +0700 Subject: [PATCH 42/46] Remove last_segment_ and streamline replacement Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 58 +++++++++++++++------------------ source/common/common/utility.h | 13 ++++++-- 2 files changed, 37 insertions(+), 34 deletions(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index edb7c4a59aa47..233a9124fdc61 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -64,27 +64,24 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { const std::chrono::seconds epoch_time_seconds = std::chrono::duration_cast(epoch_time_ns); - // Remove all the expired cached items. - for (auto it = cached_time.formatted.cbegin(); it != cached_time.formatted.cend();) { - if (it->second.epoch_time_seconds != epoch_time_seconds) { - it = cached_time.formatted.erase(it); - } else { - it++; + const auto& item = cached_time.formatted.find(format_string_); + if (item == cached_time.formatted.end() || + item->second.epoch_time_seconds != epoch_time_seconds) { + // Remove all the expired cached items. + for (auto it = cached_time.formatted.cbegin(); it != cached_time.formatted.cend();) { + if (it->second.epoch_time_seconds != epoch_time_seconds) { + it = cached_time.formatted.erase(it); + } else { + it++; + } } - } - const auto& item = cached_time.formatted.find(format_string_); - if (item == cached_time.formatted.end()) { const time_t current_time = std::chrono::system_clock::to_time_t(time); // Build a new formatted format string at current time. CachedTime::Formatted formatted; - if (subseconds_.empty()) { - formatted.str = fromTime(current_time); - } else { - formatted.str = fromTimeAndPrepareSubsecondOffsets(current_time, formatted.subsecond_offsets); - cached_time.seconds_length = fmt::FormatInt(epoch_time_seconds.count()).str().size(); - } + formatted.str = fromTimeAndPrepareSubsecondOffsets(current_time, formatted.subsecond_offsets); + cached_time.seconds_length = fmt::FormatInt(epoch_time_seconds.count()).str().size(); // Stamp the formatted string using the current epoch time in seconds, and then cache it in. formatted.epoch_time_seconds = epoch_time_seconds; @@ -92,20 +89,23 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { } const auto& formatted = cached_time.formatted.at(format_string_); - if (subseconds_.empty()) { - return formatted.str; - } - ASSERT(subseconds_.size() == formatted.subsecond_offsets.size()); - // Copy the current cached formatted format string, then replace its subseconds part using the - // prepared subseconds offsets. + // Copy the current cached formatted format string, then replace its subseconds part (when it has + // non-zero width) by correcting its position using prepared subseconds offsets. std::string formatted_str = formatted.str; const std::string nanoseconds = fmt::FormatInt(epoch_time_ns.count()).str(); for (size_t i = 0; i < subseconds_.size(); ++i) { const auto& subsecond = subseconds_.at(i); - formatted_str.replace(subsecond.position_ + formatted.subsecond_offsets.at(i), subsecond.width_, - nanoseconds.substr(cached_time.seconds_length, subsecond.width_)); + + // When subsecond.width_ is zero, skip the replacement. This is the last segment or it has no + // subsecond specifier. + if (subsecond.width_ > 0) { + ASSERT(subsecond.position_ + formatted.subsecond_offsets.at(i) < formatted_str.size()); + formatted_str.replace(subsecond.position_ + formatted.subsecond_offsets.at(i), + subsecond.width_, + nanoseconds.substr(cached_time.seconds_length, subsecond.width_)); + } } ASSERT(formatted_str.size() == formatted.str.size()); @@ -134,10 +134,11 @@ std::string DateFormatter::parse(const std::string& format_string) { step = subsecond.position_ + subsecond.width_; } - // To capture the segment after the last subsecond pattern of a format string. E.g. - // %3f-this-is-the-last-%s-segment-%Y-until-this. + // To capture the segment after the last subsecond pattern of a format string by creating a zero + // width subsecond. E.g. %3f-this-is-the-last-%s-segment-%Y-until-this. if (step < new_format_string.size()) { - last_segment_ = new_format_string.substr(step); + SubsecondSpecifier subsecond(step, 0, new_format_string.substr(step)); + subseconds_.emplace_back(subsecond); } return new_format_string; @@ -175,11 +176,6 @@ DateFormatter::fromTimeAndPrepareSubsecondOffsets(time_t time, previous += offset; } - if (!last_segment_.empty()) { - strftime(&buf[0], buf.size(), last_segment_.c_str(), ¤t_tm); - absl::StrAppend(&formatted, &buf[0]); - } - return formatted; } diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 7ee85bed29dd1..bf8a19f10ad3c 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -54,19 +54,26 @@ class DateFormatter { std::string fromTimeAndPrepareSubsecondOffsets(time_t time, SubsecondOffsets& subsecond_offsets) const; + // A container to hold a subsecond specifier (%f, %Nf) found in a format string. struct SubsecondSpecifier { SubsecondSpecifier(const size_t position, const size_t width, const std::string& segment) : position_(position), width_(width), segment_(segment) {} + // The position/index of a subsecond specifier in a format string. const size_t position_; + + // The width of a subsecond specifier, e.g. given %3f, the width is 3. If %f is set as the + // specifier, the width value should be 9 (the number of nanosecond digits). const size_t width_; + // The string before the current specifier's position and after the previous found specifier. A + // segment may include strftime accepted specifiers. E.g. given "%3f-this-i%s-a-segment-%4f", + // the current specifier is "%4f" and the segment is "-this-i%s-a-segment-". const std::string segment_; }; - std::vector subseconds_; - // The last string segment after the last found subsecond pattern. - std::string last_segment_; + // This holds all subsecond specifiers found in a given format string. + std::vector subseconds_; const std::string format_string_; }; From ec35f6cc2b94db19616a2554681a05c9367d9b07 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 6 Jun 2018 17:23:58 +0700 Subject: [PATCH 43/46] Add test with shorter segments Signed-off-by: Dhi Aurrahman --- test/common/access_log/access_log_formatter_test.cc | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/test/common/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc index b5da1609d4630..b16942fc25ebc 100644 --- a/test/common/access_log/access_log_formatter_test.cc +++ b/test/common/access_log/access_log_formatter_test.cc @@ -413,6 +413,7 @@ TEST(AccessLogFormatterTest, CompositeFormatterSuccess) { } { + // This tests multiple START_TIMEs. const std::string format = "%START_TIME(%s.%3f)%|%START_TIME(%s.%4f)%|%START_TIME(%s.%5f)%|%START_TIME(%s.%6f)%"; const SystemTime start_time(std::chrono::microseconds(1522796769123456)); @@ -432,6 +433,17 @@ TEST(AccessLogFormatterTest, CompositeFormatterSuccess) { "123-asdf-123456000|.1234560:segm5:2018", formatter.format(request_header, response_header, response_trailer, request_info)); } + + { + // This tests START_TIME specifier that has shorter segments when formatted, i.e. + // strftime("%%%%"") equals "%%", %1f will have 1 as its size. + const std::string format = "%START_TIME(%|%%%%|%%%%%f|%s%%%%%3f|%1f%%%%%s)%"; + const SystemTime start_time(std::chrono::microseconds(1522796769123456)); + EXPECT_CALL(request_info, startTime()).WillOnce(Return(start_time)); + FormatterImpl formatter(format); + EXPECT_EQ("|%%|%%123456000|1522796769%%123|1%%1522796769", + formatter.format(request_header, response_header, response_trailer, request_info)); + } } TEST(AccessLogFormatterTest, ParserFailures) { From ea5e62ff24adc7057b2eaeb19dd25c4512e64330 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 6 Jun 2018 18:30:53 +0700 Subject: [PATCH 44/46] Remove % since it is diff on osx vs. linux Signed-off-by: Dhi Aurrahman --- test/common/access_log/access_log_formatter_test.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/common/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc index b16942fc25ebc..6cc11f9234643 100644 --- a/test/common/access_log/access_log_formatter_test.cc +++ b/test/common/access_log/access_log_formatter_test.cc @@ -437,11 +437,11 @@ TEST(AccessLogFormatterTest, CompositeFormatterSuccess) { { // This tests START_TIME specifier that has shorter segments when formatted, i.e. // strftime("%%%%"") equals "%%", %1f will have 1 as its size. - const std::string format = "%START_TIME(%|%%%%|%%%%%f|%s%%%%%3f|%1f%%%%%s)%"; + const std::string format = "%START_TIME(%%%%|%%%%%f|%s%%%%%3f|%1f%%%%%s)%"; const SystemTime start_time(std::chrono::microseconds(1522796769123456)); EXPECT_CALL(request_info, startTime()).WillOnce(Return(start_time)); FormatterImpl formatter(format); - EXPECT_EQ("|%%|%%123456000|1522796769%%123|1%%1522796769", + EXPECT_EQ("%%|%%123456000|1522796769%%123|1%%1522796769", formatter.format(request_header, response_header, response_trailer, request_info)); } } From 22a94a4254bf7171c72ebca4c4c921566d19e886 Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 6 Jun 2018 23:37:18 +0700 Subject: [PATCH 45/46] Use unordered_map instead Signed-off-by: Dhi Aurrahman --- source/common/router/header_formatter.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/common/router/header_formatter.h b/source/common/router/header_formatter.h index 7de8ab442a9ff..a5edb29f181b1 100644 --- a/source/common/router/header_formatter.h +++ b/source/common/router/header_formatter.h @@ -43,7 +43,7 @@ class RequestInfoHeaderFormatter : public HeaderFormatter { private: std::function field_extractor_; const bool append_; - std::map> start_time_formatters_; + std::unordered_map> start_time_formatters_; }; /** From 3f01c64664e6d7470e117c55013ceafde696720b Mon Sep 17 00:00:00 2001 From: Dhi Aurrahman Date: Wed, 6 Jun 2018 23:39:36 +0700 Subject: [PATCH 46/46] Comment on the possibility to have negative offset value Signed-off-by: Dhi Aurrahman --- source/common/common/utility.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index 233a9124fdc61..a3e526b020a74 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -170,7 +170,7 @@ DateFormatter::fromTimeAndPrepareSubsecondOffsets(time_t time, absl::StrAppend(&formatted, &buf[0], std::string(subsecond.width_, '?')); // This computes and saves offset of each subsecond pattern to correct its position after the - // previous string segment is formatted. + // previous string segment is formatted. An offset can be a negative value. const int32_t offset = formatted_length - subsecond.segment_.size(); subsecond_offsets.emplace_back(previous + offset); previous += offset;