diff --git a/changelogs/current.yaml b/changelogs/current.yaml index 40495e59b053..7a0ac131d20b 100644 --- a/changelogs/current.yaml +++ b/changelogs/current.yaml @@ -111,5 +111,9 @@ new_features: ` to allow overriding TLS certificate selection behavior. An extension can select certificate base on the incoming SNI, in both sync and async mode. +- area: access_log + change: | + Added new access log command operators ``%START_TIME_LOCAL%`` and ``%EMIT_TIME_LOCAL%``, + similar to ``%START_TIME%`` and ``%EMIT_TIME%``, but use local time zone. deprecated: diff --git a/docs/root/configuration/observability/access_log/usage.rst b/docs/root/configuration/observability/access_log/usage.rst index 6b9d0fadfcab..657c485a9b7d 100644 --- a/docs/root/configuration/observability/access_log/usage.rst +++ b/docs/root/configuration/observability/access_log/usage.rst @@ -170,6 +170,11 @@ The following command operators are supported: In typed JSON logs, START_TIME is always rendered as a string. +.. _config_access_log_format_start_time_local: + +%START_TIME_LOCAL% + Same as :ref:`START_TIME `, but use local time zone. + .. _config_access_log_format_emit_time: %EMIT_TIME% @@ -178,6 +183,11 @@ The following command operators are supported: EMIT_TIME can be customized using a `format string `_. See :ref:`START_TIME ` for additional format specifiers and examples. +.. _config_access_log_format_emit_time_local: + +%EMIT_TIME_LOCAL% + Same as :ref:`EMIT_TIME `, but use local time zone. + %REQUEST_HEADERS_BYTES% HTTP Uncompressed bytes of request headers. diff --git a/source/common/common/utility.cc b/source/common/common/utility.cc index de988db79f42..463683960a20 100644 --- a/source/common/common/utility.cc +++ b/source/common/common/utility.cc @@ -92,7 +92,8 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { // A map is used to keep different formatted format strings at a given second. absl::node_hash_map formatted; }; - static thread_local CachedTime cached_time; + static thread_local CachedTime cached_time_utc; + static thread_local CachedTime cached_time_local; const std::chrono::nanoseconds epoch_time_ns = std::chrono::duration_cast(time.time_since_epoch()); @@ -100,6 +101,7 @@ std::string DateFormatter::fromTime(const SystemTime& time) const { const std::chrono::seconds epoch_time_seconds = std::chrono::duration_cast(epoch_time_ns); + CachedTime& cached_time = local_time_ ? cached_time_local : cached_time_utc; const auto& item = cached_time.formatted.find(raw_format_string_); if (item == cached_time.formatted.end() || item->second.epoch_time_seconds != epoch_time_seconds) { @@ -203,7 +205,8 @@ DateFormatter::fromTimeAndPrepareSpecifierOffsets(time_t time, SpecifierOffsets& specifier_offsets.reserve(specifiers_.size()); for (const auto& specifier : specifiers_) { std::string current_format = - absl::FormatTime(specifier.segment_, absl::FromTimeT(time), absl::UTCTimeZone()); + absl::FormatTime(specifier.segment_, absl::FromTimeT(time), + local_time_ ? absl::LocalTimeZone() : absl::UTCTimeZone()); absl::StrAppend(&formatted_time, current_format, specifier.second_ ? seconds_str : std::string(specifier.width_, '?')); @@ -501,16 +504,22 @@ void StringUtil::escapeToOstream(std::ostream& os, absl::string_view view) { } } -const std::string& getDefaultDateFormat() { +const std::string& getDefaultDateFormat(bool local_time) { + if (local_time) { + CONSTRUCT_ON_FIRST_USE(std::string, "%Y-%m-%dT%H:%M:%E3S%z"); + } CONSTRUCT_ON_FIRST_USE(std::string, "%Y-%m-%dT%H:%M:%E3SZ"); } -std::string AccessLogDateTimeFormatter::fromTime(const SystemTime& system_time) { +std::string AccessLogDateTimeFormatter::fromTime(const SystemTime& system_time, bool local_time) { struct CachedTime { std::chrono::seconds epoch_time_seconds; std::string formatted_time; }; - static thread_local CachedTime cached_time; + static thread_local CachedTime cached_time_utc; + static thread_local CachedTime cached_time_local; + + CachedTime& cached_time = local_time ? cached_time_local : cached_time_utc; const std::chrono::milliseconds epoch_time_ms = std::chrono::duration_cast(system_time.time_since_epoch()); @@ -519,14 +528,15 @@ std::string AccessLogDateTimeFormatter::fromTime(const SystemTime& system_time) std::chrono::duration_cast(epoch_time_ms); if (cached_time.formatted_time.empty() || cached_time.epoch_time_seconds != epoch_time_seconds) { - cached_time.formatted_time = absl::FormatTime( - getDefaultDateFormat(), absl::FromChrono(system_time), absl::UTCTimeZone()); + cached_time.formatted_time = + absl::FormatTime(getDefaultDateFormat(local_time), absl::FromChrono(system_time), + local_time ? absl::LocalTimeZone() : absl::UTCTimeZone()); cached_time.epoch_time_seconds = epoch_time_seconds; } else { - // Overwrite the digits in the ".000Z" at the end of the string with the + // Overwrite the digits in the ".000Z" or ".000%z" at the end of the string with the // millisecond count from the input time. - ASSERT(cached_time.formatted_time.length() == 24); - size_t offset = cached_time.formatted_time.length() - 4; + ASSERT(cached_time.formatted_time.length() >= 23); + size_t offset = 20; uint32_t msec = epoch_time_ms.count() % 1000; cached_time.formatted_time[offset++] = ('0' + (msec / 100)); msec %= 100; diff --git a/source/common/common/utility.h b/source/common/common/utility.h index 5e1562eda35f..872904b6a47a 100644 --- a/source/common/common/utility.h +++ b/source/common/common/utility.h @@ -44,12 +44,14 @@ const std::string errorDetails(int error_code); */ class DateFormatter { public: - DateFormatter(const std::string& format_string) : raw_format_string_(format_string) { + DateFormatter(const std::string& format_string, bool local_time = false) + : raw_format_string_(format_string), local_time_(local_time) { parse(format_string); } /** - * @return std::string representing the GMT/UTC time based on the input time. + * @return std::string representing the GMT/UTC time based on the input time, + * or local zone time when local_time_ is true. */ std::string fromTime(const SystemTime& time) const; @@ -104,6 +106,9 @@ class DateFormatter { // This is the format string as supplied in configuration, e.g. "foo %3f bar". const std::string raw_format_string_; + + // Whether use local time zone. + const bool local_time_; }; /** @@ -111,7 +116,7 @@ class DateFormatter { */ class AccessLogDateTimeFormatter { public: - static std::string fromTime(const SystemTime& time); + static std::string fromTime(const SystemTime& time, bool local_time = false); }; /** diff --git a/source/common/formatter/stream_info_formatter.cc b/source/common/formatter/stream_info_formatter.cc index 2c183986d136..3e40fa15b4c1 100644 --- a/source/common/formatter/stream_info_formatter.cc +++ b/source/common/formatter/stream_info_formatter.cc @@ -550,8 +550,10 @@ UpstreamPeerCertVEndFormatter::UpstreamPeerCertVEndFormatter(const std::string& : absl::optional(); })) {} -SystemTimeFormatter::SystemTimeFormatter(const std::string& format, TimeFieldExtractorPtr f) - : date_formatter_(format), time_field_extractor_(std::move(f)) { +SystemTimeFormatter::SystemTimeFormatter(const std::string& format, TimeFieldExtractorPtr f, + bool local_time) + : date_formatter_(format, local_time), time_field_extractor_(std::move(f)), + local_time_(local_time) { // Validate the input specifier here. The formatted string may be destined for a header, and // should not contain invalid characters {NUL, LR, CF}. if (std::regex_search(format, getSystemTimeFormatNewlinePattern())) { @@ -566,7 +568,7 @@ SystemTimeFormatter::format(const StreamInfo::StreamInfo& stream_info) const { return absl::nullopt; } if (date_formatter_.formatString().empty()) { - return AccessLogDateTimeFormatter::fromTime(time_field.value()); + return AccessLogDateTimeFormatter::fromTime(time_field.value(), local_time_); } return date_formatter_.fromTime(time_field.value()); } @@ -1658,6 +1660,17 @@ const StreamInfoFormatterProviderLookupTable& getKnownStreamInfoFormatterProvide return stream_info.startTime(); })); }}}, + {"START_TIME_LOCAL", + {CommandSyntaxChecker::PARAMS_OPTIONAL, + [](const std::string& format, absl::optional) { + return std::make_unique( + format, + std::make_unique( + [](const StreamInfo::StreamInfo& stream_info) -> absl::optional { + return stream_info.startTime(); + }), + true); + }}}, {"EMIT_TIME", {CommandSyntaxChecker::PARAMS_OPTIONAL, [](const std::string& format, absl::optional) { @@ -1668,6 +1681,17 @@ const StreamInfoFormatterProviderLookupTable& getKnownStreamInfoFormatterProvide return stream_info.timeSource().systemTime(); })); }}}, + {"EMIT_TIME_LOCAL", + {CommandSyntaxChecker::PARAMS_OPTIONAL, + [](const std::string& format, absl::optional) { + return std::make_unique( + format, + std::make_unique( + [](const StreamInfo::StreamInfo& stream_info) -> absl::optional { + return stream_info.timeSource().systemTime(); + }), + true); + }}}, {"DYNAMIC_METADATA", {CommandSyntaxChecker::PARAMS_REQUIRED, [](const std::string& format, absl::optional max_length) { diff --git a/source/common/formatter/stream_info_formatter.h b/source/common/formatter/stream_info_formatter.h index 89b37fe959ab..8de144eb0d4f 100644 --- a/source/common/formatter/stream_info_formatter.h +++ b/source/common/formatter/stream_info_formatter.h @@ -169,7 +169,7 @@ class SystemTimeFormatter : public StreamInfoFormatterProvider { std::function(const StreamInfo::StreamInfo& stream_info)>; using TimeFieldExtractorPtr = std::unique_ptr; - SystemTimeFormatter(const std::string& format, TimeFieldExtractorPtr f); + SystemTimeFormatter(const std::string& format, TimeFieldExtractorPtr f, bool local_time = false); // StreamInfoFormatterProvider absl::optional format(const StreamInfo::StreamInfo&) const override; @@ -178,6 +178,8 @@ class SystemTimeFormatter : public StreamInfoFormatterProvider { private: const Envoy::DateFormatter date_formatter_; const TimeFieldExtractorPtr time_field_extractor_; + // Whether use local time zone. + const bool local_time_; }; /** diff --git a/test/common/common/utility_test.cc b/test/common/common/utility_test.cc index dad3a15a0ece..3e9550a546d6 100644 --- a/test/common/common/utility_test.cc +++ b/test/common/common/utility_test.cc @@ -603,6 +603,25 @@ TEST(AccessLogDateTimeFormatter, fromTime) { EXPECT_EQ("2018-04-03T23:06:08.999Z", AccessLogDateTimeFormatter::fromTime(time4)); } +TEST(AccessLogDateTimeFormatter, fromTimeLocalTimeZone) { + SystemTime time1(std::chrono::seconds(1522796769)); + EXPECT_EQ( + absl::FormatTime("%Y-%m-%dT%H:%M:%E3S%z", absl::FromChrono(time1), absl::LocalTimeZone()), + AccessLogDateTimeFormatter::fromTime(time1, true)); + SystemTime time2(std::chrono::milliseconds(1522796769123)); + EXPECT_EQ( + absl::FormatTime("%Y-%m-%dT%H:%M:%E3S%z", absl::FromChrono(time2), absl::LocalTimeZone()), + AccessLogDateTimeFormatter::fromTime(time2, true)); + SystemTime time3(std::chrono::milliseconds(1522796769999)); + EXPECT_EQ( + absl::FormatTime("%Y-%m-%dT%H:%M:%E3S%z", absl::FromChrono(time3), absl::LocalTimeZone()), + AccessLogDateTimeFormatter::fromTime(time3, true)); + SystemTime time4(std::chrono::milliseconds(1522796768999)); + EXPECT_EQ( + absl::FormatTime("%Y-%m-%dT%H:%M:%E3S%z", absl::FromChrono(time4), absl::LocalTimeZone()), + AccessLogDateTimeFormatter::fromTime(time4, true)); +} + TEST(Primes, isPrime) { EXPECT_FALSE(Primes::isPrime(0)); EXPECT_TRUE(Primes::isPrime(67)); @@ -1026,6 +1045,25 @@ TEST(DateFormatter, FromTime) { EXPECT_EQ("aaa00", DateFormatter(std::string(3, 'a') + "%H").fromTime(time2)); } +TEST(DateFormatter, FromTimeLocalTimeZone) { + const SystemTime time1(std::chrono::seconds(1522796769)); + EXPECT_EQ( + absl::FormatTime("%Y-%m-%dT%H:%M:%S.000Z", absl::FromChrono(time1), absl::LocalTimeZone()), + DateFormatter("%Y-%m-%dT%H:%M:%S.000Z", true).fromTime(time1)); + EXPECT_EQ(absl::FormatTime("aaa%H", absl::FromChrono(time1), absl::LocalTimeZone()), + DateFormatter(std::string(3, 'a') + "%H", true).fromTime(time1)); + const SystemTime time2(std::chrono::seconds(0)); + EXPECT_EQ( + absl::FormatTime("%Y-%m-%dT%H:%M:%S.000Z", absl::FromChrono(time2), absl::LocalTimeZone()), + DateFormatter("%Y-%m-%dT%H:%M:%S.000Z", true).fromTime(time2)); + EXPECT_EQ(absl::FormatTime("aaa%H", absl::FromChrono(time2), absl::LocalTimeZone()), + DateFormatter(std::string(3, 'a') + "%H", true).fromTime(time2)); + SystemTime time3(std::chrono::milliseconds(1522796769999)); + EXPECT_EQ( + absl::FormatTime("%Y-%m-%dT%H:%M:%E3S%z", absl::FromChrono(time3), absl::LocalTimeZone()), + DateFormatter("%Y-%m-%dT%H:%M:%S.%3f%z", true).fromTime(time3)); +} + // Check the time complexity. Make sure DateFormatter can finish parsing long messy string without // crashing/freezing. This should pass in 0-2 seconds if O(n). Finish in 30-120 seconds if O(n^2) TEST(DateFormatter, ParseLongString) { diff --git a/test/common/formatter/substitution_formatter_fuzz_test.dict b/test/common/formatter/substitution_formatter_fuzz_test.dict index 637faeacff65..d5a69c589b95 100644 --- a/test/common/formatter/substitution_formatter_fuzz_test.dict +++ b/test/common/formatter/substitution_formatter_fuzz_test.dict @@ -1,6 +1,7 @@ # format strings "[%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% \"%REQ(X-FORWARDED-FOR)%\" \"%REQ(USER-AGENT)%\" \"%REQ(X-REQUEST-ID)%\" \"%REQ(:AUTHORITY)%\" \"%UPSTREAM_HOST%\"\x0A" "%START_TIME%" +"%START_TIME_LOCAL%" "%BYTES_RECEIVED%" "%PROTOCOL%" "%RESPONSE_CODE%" diff --git a/test/common/formatter/substitution_formatter_test.cc b/test/common/formatter/substitution_formatter_test.cc index 7fd8e2c491b0..a9613ce63bf9 100644 --- a/test/common/formatter/substitution_formatter_test.cc +++ b/test/common/formatter/substitution_formatter_test.cc @@ -4185,16 +4185,21 @@ TEST(SubstitutionFormatterTest, StructFormatterStartTimeTest) { absl::node_hash_map expected_json_map = { {"simple_date", "2018/03/28"}, {"test_time", fmt::format("{}", expected_time_in_epoch)}, + {"test_time_local", fmt::format("{}", expected_time_in_epoch)}, {"bad_format", "bad_format"}, {"default", "2018-03-28T23:35:58.000Z"}, + {"default_local", + absl::FormatTime("%Y-%m-%dT%H:%M:%E3S%z", absl::FromChrono(time), absl::LocalTimeZone())}, {"all_zeroes", "000000000.0.00.000"}}; ProtobufWkt::Struct key_mapping; TestUtility::loadFromYaml(R"EOF( simple_date: '%START_TIME(%Y/%m/%d)%' test_time: '%START_TIME(%s)%' + test_time_local: '%START_TIME_LOCAL(%s)%' bad_format: '%START_TIME(bad_format)%' default: '%START_TIME%' + default_local: '%START_TIME_LOCAL%' all_zeroes: '%START_TIME(%f.%1f.%2f.%3f)%' )EOF", key_mapping);