access_log, router: add subsecond specifier for START_TIME

docs/root/configuration/access_log.rst

@@ -29,18 +29,42 @@ are noted.
 
 The following command operators are supported:
 
+.. _config_access_log_format_start_time:
+
 %START_TIME%
   HTTP
     Request start time including milliseconds.
 
   TCP
     Downstream connection start time including milliseconds.
 
-  START_TIME can be customized using a `format string <http://en.cppreference.com/w/cpp/io/manip/put_time>`_, for example:
+  START_TIME can be customized using a `format string <http://en.cppreference.com/w/cpp/io/manip/put_time>`_.
+  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

docs/root/configuration/http_conn_man/headers.rst

@@ -472,3 +472,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<config_access_log_format_start_time>`.
+
+    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

docs/root/intro/version_history.rst

@@ -9,6 +9,7 @@ Version history
 * access log: added DYNAMIC_METADATA :ref:`access log formatter <config_access_log_format>`.
 * access log: added :ref:`HeaderFilter <envoy_api_msg_config.filter.accesslog.v2.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.
@@ -83,6 +84,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 <envoy_api_msg_route.RouteAction.HashPolicy.Cookie>` to
   generate session cookies.
+* router: added START_TIME as one of supported variables in :ref:`header
+  formatters <config_http_conn_man_headers_custom_request_headers>`.
 * sockets: added :ref:`capture transport socket extension <operations_traffic_capture>` to support
   recording plain text traffic and PCAP generation.
 * sockets: added `IP_FREEBIND` socket option support for :ref:`listeners

source/common/common/BUILD

@@ -156,9 +156,11 @@ envoy_cc_library(
     hdrs = ["utility.h"],
     deps = [
         ":assert_lib",
+        ":empty_string",
         ":hash_lib",
         "//include/envoy/common:interval_set_interface",
         "//include/envoy/common:time_interface",
+        "//source/common/singleton:const_singleton",
     ],
 )
 

source/common/common/utility.cc

@@ -10,8 +10,10 @@
 #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"
 
 #include "absl/strings/ascii.h"
 #include "absl/strings/match.h"
@@ -20,8 +22,88 @@
 #include "spdlog/spdlog.h"
 
 namespace Envoy {
+
+namespace {
+
+class SubsecondConstantValues {
+public:
+  const char PLACEHOLDER_CHAR{'?'};
+  const std::string PLACEHOLDER{"?????????"};
+  const std::regex PATTERN{"%([1-9])?f", std::regex::optimize};
+};
+
+typedef ConstSingleton<SubsecondConstantValues> SubsecondConstants;
+
+} // namespace
+
 std::string DateFormatter::fromTime(const SystemTime& time) const {
-  return fromTime(std::chrono::system_clock::to_time_t(time));
+  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<std::string, const std::string> formatted;
+  };
+  static thread_local CachedTime cached_time;
+
+  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);
+
+  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;
+  }
+
+  if (subseconds_.empty()) {
+    return cached_time.formatted.at(format_string_);
+  }
+
+  // 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 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(&current_time, &current_tm);
+
+  std::string new_format_string = format_string;
+  std::smatch matched;
+  size_t position = 0;
+  size_t previous = 0;
+  std::array<char, 1024> 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(), &current_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;
 }
 
 std::string DateFormatter::fromTime(time_t time) const {

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,18 @@ class DateFormatter {
   const std::string& formatString() const { return format_string_; }
 
 private:
-  std::string format_string_;
+  std::string parse(const std::string& format_string);
+
+  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<SubsecondSpecifier> subseconds_;
+
+  const std::string format_string_;
 };
 
 /**

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",
     ],
 )

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 {

source/common/router/header_formatter.h

@@ -43,6 +43,7 @@ class RequestInfoHeaderFormatter : public HeaderFormatter {
 private:
   std::function<std::string(const Envoy::RequestInfo::RequestInfo&)> field_extractor_;
   const bool append_;
+  std::map<std::string, std::vector<AccessLog::FormatterPtr>> start_time_formatters_;
 };
 
 /**

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;
       }

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,29 @@ 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("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));
   }
 }

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<long> distribution(-10, 20);
+  Envoy::DateFormatter date_formatter("%Y-%m-%dT%H:%M:%s.%3f");
+  for (auto _ : state) {
+    time += std::chrono::milliseconds(static_cast<int>(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<long> distribution(-10, 20);
+  Envoy::DateFormatter date_formatter("%Y-%m-%dT%H:%M:%s");
+  for (auto _ : state) {
+    time += std::chrono::milliseconds(static_cast<int>(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) {