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

@@ -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<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.
 * access log: gRPC Access Log Service (ALS) support added for :ref:`HTTP access logs
   <envoy_api_msg_config.accesslog.v2.HttpGrpcAccessLogConfig>`.
 * 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 <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>`.
 * router: added a :ref:`configuration option
   <envoy_api_field_config.filter.http.router.v2.Router.suppress_envoy_headers>` to disable *x-envoy-*
   header generation.

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

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,91 @@
 #include "spdlog/spdlog.h"
 
 namespace Envoy {
+
+namespace {
+
+class SubsecondConstantValues {
+public:
+  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 {
+    size_t seconds_length;
+    std::chrono::seconds epoch_time_seconds;
+
+    struct Formatted {
+      SubsecondOffsets subsecond_offsets;
+      std::string str;
+    };
+    // A map is used to keep different formatted format strings at a given second.
+    std::unordered_map<std::string, const Formatted> 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) {
+    time_t current_time = std::chrono::system_clock::to_time_t(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();
+    }
+
+    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_);
+  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.
+  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 = 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.str.size());
+  return formatted_str;
+}
+
+std::string DateFormatter::parse(const std::string& format_string) {
+  std::string new_format_string = format_string;
+  std::smatch matched;
+  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);
+    subseconds_.emplace_back(subsecond);
+  }
+
+  return new_format_string;
 }
 
 std::string DateFormatter::fromTime(time_t time) const {
@@ -33,6 +117,41 @@ 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, &current_tm);
+
+  std::array<char, 1024> 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(), &current_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(), &current_tm);
+    absl::StrAppend(&formatted, &buf[0]);
+  }
+
+  return formatted;
+}
+
 std::string DateFormatter::now() {
   time_t current_time_t;
   time(&current_time_t);

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,22 @@ 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<int32_t> 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) {}
+
+    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|%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));
   }
 }