diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index 66ceb0760f6d1..e97da4bf39f4e 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,11 +38,33 @@ 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 following specifiers: -.. code-block:: none + +------------------------+-------------------------------------------------------------+ + | Specifier | Explanation | + +========================+=============================================================+ + | ``%s`` | The number of seconds since the Epoch | + +------------------------+-------------------------------------------------------------+ + | ``%f``, ``%[1-9]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 + + %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(%s.%6f)% - %START_TIME(%Y/%m/%dT%H:%M:%S%z %s)% + %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 10cd4e7a7b6f5..895b048cc8afb 100644 --- a/docs/root/configuration/http_conn_man/headers.rst +++ b/docs/root/configuration/http_conn_man/headers.rst @@ -475,3 +475,19 @@ 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_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 diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 571f6bbdaea5f..61d41ca39a17a 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. * access log: gRPC Access Log Service (ALS) support added for :ref:`HTTP access logs `. * admin: added :http:get:`/config_dump` for dumping the current configuration and associated xDS @@ -91,6 +92,8 @@ Version history which supports inverting all other match types to match based on headers which are not a desired value. * router: allow :ref:`cookie routing ` to generate session cookies. +* router: added START_TIME as one of supported variables in :ref:`header + formatters `. * router: added a :ref:`configuration option ` to disable *x-envoy-* header generation. diff --git a/source/common/common/BUILD b/source/common/common/BUILD index bae3d314a4781..fc0e43d110f1b 100644 --- a/source/common/common/BUILD +++ b/source/common/common/BUILD @@ -159,6 +159,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 20e28474c74fb..a3e526b020a74 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -12,6 +12,7 @@ #include "common/common/assert.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" @@ -20,8 +21,127 @@ #include "spdlog/spdlog.h" namespace Envoy { + +namespace { + +class SubsecondConstantValues { +public: + const std::regex PATTERN{"%([1-9])?f", std::regex::optimize}; +}; + +typedef ConstSingleton SubsecondConstants; + +} // namespace + std::string DateFormatter::fromTime(const SystemTime& time) const { - return fromTime(std::chrono::system_clock::to_time_t(time)); + 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; + + // 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; + }; + 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); + + 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 time_t current_time = std::chrono::system_clock::to_time_t(time); + + // Build a new formatted format string at current time. + CachedTime::Formatted formatted; + 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; + cached_time.formatted.emplace(std::make_pair(format_string_, formatted)); + } + + const auto& formatted = cached_time.formatted.at(format_string_); + ASSERT(subseconds_.size() == formatted.subsecond_offsets.size()); + + // 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); + + // 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()); + return formatted_str; +} + +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]; + + // 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()); + + // 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 by creating a zero + // width subsecond. E.g. %3f-this-is-the-last-%s-segment-%Y-until-this. + if (step < new_format_string.size()) { + SubsecondSpecifier subsecond(step, 0, new_format_string.substr(step)); + subseconds_.emplace_back(subsecond); + } + + return new_format_string; } std::string DateFormatter::fromTime(time_t time) const { @@ -33,6 +153,32 @@ 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 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], std::string(subsecond.width_, '?')); + + // This computes and saves offset of each subsecond pattern to correct its position after the + // 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; + } + + 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 7f5bb0a42671e..bf8a19f10ad3c 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -25,7 +25,7 @@ namespace Envoy { */ class DateFormatter { public: - DateFormatter(const std::string& format_string) : format_string_(format_string) {} + DateFormatter(const std::string& format_string) : format_string_(parse(format_string)) {} /** * @return std::string representing the GMT/UTC time based on the input time. @@ -48,7 +48,34 @@ class DateFormatter { const std::string& formatString() const { return format_string_; } private: - std::string format_string_; + std::string parse(const std::string& format_string); + + typedef std::vector SubsecondOffsets; + 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_; + }; + + // This holds all subsecond specifiers found in a given format string. + std::vector subseconds_; + + const std::string format_string_; }; /** 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 7040577b44ab9..b691159879e36 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" @@ -134,7 +135,19 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n return RequestInfo::Utility::formatDownstreamAddressNoPort( *request_info.downstreamLocalAddress()); }; - } else if (field_name.find_first_of("UPSTREAM_METADATA") == 0) { + } else if (field_name.find("START_TIME") == 0) { + 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) { + 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) { field_extractor_ = parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA"))); } else { diff --git a/source/common/router/header_formatter.h b/source/common/router/header_formatter.h index cc99ddacb27e4..a5edb29f181b1 100644 --- a/source/common/router/header_formatter.h +++ b/source/common/router/header_formatter.h @@ -43,6 +43,7 @@ class RequestInfoHeaderFormatter : public HeaderFormatter { private: std::function field_extractor_; const bool append_; + std::unordered_map> start_time_formatters_; }; /** 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/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc index d7860ce5d4d43..6cc11f9234643 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,41 @@ 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)); + } + + { + // 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)); + EXPECT_CALL(request_info, startTime()).WillRepeatedly(Return(start_time)); + FormatterImpl formatter(format); + 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|%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|1522796769-" + "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)); } } diff --git a/test/common/common/utility_speed_test.cc b/test/common/common/utility_speed_test.cc index d1ceedeff23b9..1e8b31d1dde88 100644 --- a/test/common/common/utility_speed_test.cc +++ b/test/common/common/utility_speed_test.cc @@ -43,6 +43,38 @@ 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; + + Envoy::SystemTime time(std::chrono::seconds(1522796769)); + 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) { + time += std::chrono::milliseconds(static_cast(distribution(prng))); + outputBytes += date_formatter.fromTime(time).length(); + } + benchmark::DoNotOptimize(outputBytes); +} +BENCHMARK(BM_DateTimeFormatterWithSubseconds); + +static void BM_DateTimeFormatterWithoutSubseconds(benchmark::State& state) { + int outputBytes = 0; + + Envoy::SystemTime time(std::chrono::seconds(1522796769)); + std::mt19937 prng(1); + 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) { diff --git a/test/common/router/header_formatter_test.cc b/test/common/router/header_formatter_test.cc index f9a96e74a494f..1e80c0bb37e0a 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; @@ -266,6 +267,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%", {"2018-04-03T23:06:09.123Z"}, {}}, // Unescaped % {"%", {}, {"Invalid header configuration. Un-escaped % at position 0"}}, @@ -295,82 +297,19 @@ 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)%", + // 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. 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. 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. Expecting JSON array of arguments after 'VAR(', but found " - "'\"'"}}, + {"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%", @@ -400,6 +339,10 @@ 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) { Protobuf::RepeatedPtrField to_add; envoy::api::v2::core::HeaderValueOption* header = to_add.Add(); @@ -591,6 +534,18 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { { "key": "x-client-ip", "value": "%DOWNSTREAM_REMOTE_ADDRESS_WITHOUT_PORT%" + }, + { + "key": "x-request-start", + "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)%" } ] } @@ -600,6 +555,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()); @@ -607,11 +563,21 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) { {":method", "POST"}, {"static-header", "old-value"}, {"x-client-ip", "0.0.0.0"}}; NiceMock request_info; + 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_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; @@ -631,6 +597,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) { @@ -643,6 +610,22 @@ match: { prefix: "/new_endpoint" } key: "x-client-ip" value: "%DOWNSTREAM_REMOTE_ADDRESS_WITHOUT_PORT%" append: true + - header: + key: "x-request-start" + 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"; @@ -651,10 +634,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-safe")); EXPECT_FALSE(headerMap.has("x-nope")); + EXPECT_TRUE(headerMap.has("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")); + 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