access log: added new START_TIME_LOCAL & EMIT_TIME_LOCAL command (#35280

) Commit Message: access log: added new START_TIME_LOCAL & EMIT_TIME_LOCAL command Additional Description: Same as START_TIME & EMIT_TIME, but use local time zone. close #35116 Risk Level: low. Testing: unit. Docs Changes: added. Release Notes: TODO. Platform Specific Features: n/a. --------- Signed-off-by: doujiang24 <[email protected]>
envoyproxy · Jul 31, 2024 · 3761d87 · 3761d87
1 parent b0cc284
commit 3761d87
Show file tree

Hide file tree

Showing 9 changed files with 116 additions and 17 deletions.
diff --git a/changelogs/current.yaml b/changelogs/current.yaml
@@ -111,5 +111,9 @@ new_features:
     <envoy_v3_api_field_extensions.transport_sockets.tls.v3.CommonTlsContext.custom_tls_certificate_selector>`
     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
@@ -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 <config_access_log_format_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 <https://en.cppreference.com/w/cpp/io/manip/put_time>`_.
   See :ref:`START_TIME <config_access_log_format_start_time>` for additional format specifiers and examples.
 
+.. _config_access_log_format_emit_time_local:
+
+%EMIT_TIME_LOCAL%
+  Same as :ref:`EMIT_TIME <config_access_log_format_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
@@ -92,14 +92,16 @@ 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<std::string, const Formatted> 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<std::chrono::nanoseconds>(time.time_since_epoch());
 
   const std::chrono::seconds epoch_time_seconds =
       std::chrono::duration_cast<std::chrono::seconds>(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<std::chrono::milliseconds>(system_time.time_since_epoch());
@@ -519,14 +528,15 @@ std::string AccessLogDateTimeFormatter::fromTime(const SystemTime& system_time)
       std::chrono::duration_cast<std::chrono::seconds>(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
@@ -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,14 +106,17 @@ 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_;
 };
 
 /**
  * Utility class for access log date/time format with milliseconds support.
  */
 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
@@ -550,8 +550,10 @@ UpstreamPeerCertVEndFormatter::UpstreamPeerCertVEndFormatter(const std::string&
                                    : absl::optional<SystemTime>();
                       })) {}
 
-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<size_t>) {
+              return std::make_unique<SystemTimeFormatter>(
+                  format,
+                  std::make_unique<SystemTimeFormatter::TimeFieldExtractor>(
+                      [](const StreamInfo::StreamInfo& stream_info) -> absl::optional<SystemTime> {
+                        return stream_info.startTime();
+                      }),
+                  true);
+            }}},
           {"EMIT_TIME",
            {CommandSyntaxChecker::PARAMS_OPTIONAL,
             [](const std::string& format, absl::optional<size_t>) {
@@ -1668,6 +1681,17 @@ const StreamInfoFormatterProviderLookupTable& getKnownStreamInfoFormatterProvide
                         return stream_info.timeSource().systemTime();
                       }));
             }}},
+          {"EMIT_TIME_LOCAL",
+           {CommandSyntaxChecker::PARAMS_OPTIONAL,
+            [](const std::string& format, absl::optional<size_t>) {
+              return std::make_unique<SystemTimeFormatter>(
+                  format,
+                  std::make_unique<SystemTimeFormatter::TimeFieldExtractor>(
+                      [](const StreamInfo::StreamInfo& stream_info) -> absl::optional<SystemTime> {
+                        return stream_info.timeSource().systemTime();
+                      }),
+                  true);
+            }}},
           {"DYNAMIC_METADATA",
            {CommandSyntaxChecker::PARAMS_REQUIRED,
             [](const std::string& format, absl::optional<size_t> max_length) {

diff --git 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<absl::optional<SystemTime>(const StreamInfo::StreamInfo& stream_info)>;
   using TimeFieldExtractorPtr = std::unique_ptr<TimeFieldExtractor>;
 
-  SystemTimeFormatter(const std::string& format, TimeFieldExtractorPtr f);
+  SystemTimeFormatter(const std::string& format, TimeFieldExtractorPtr f, bool local_time = false);
 
   // StreamInfoFormatterProvider
   absl::optional<std::string> 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
@@ -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
@@ -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
@@ -4185,16 +4185,21 @@ TEST(SubstitutionFormatterTest, StructFormatterStartTimeTest) {
   absl::node_hash_map<std::string, std::string> 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);