access_log, router: add subsecond specifier for START_TIME (#3269)

This change adds %f, %[1-9]f specifier to get subseconds for START_TIME.
As an example, START_TIME(%s%3f) gets a timestamp in milliseconds.

This also adds START_TIME as one of the supported variables in header formatter.

Risk Level: Low, since this is an optional feature.

Testing: unit and manual tests.

Docs Changes:

added subsecond specifier for START_TIME for both access_log and router header formatter.
added START_TIME as one of the supported variables in header formatter.
Release Notes:

added subsecond specifier for START_TIME for both access_log and router header formatter.
added START_TIME as one of the supported variables in header formatter.
Fixes #1966
Fixes #2877

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

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,127 @@
 #include "spdlog/spdlog.h"
 
 namespace Envoy {
+
+namespace {
+
+class SubsecondConstantValues {
+public:
+  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 {
+    // 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<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);
+
+  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, &current_tm);
+
+  std::array<char, 1024> 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(), &current_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(&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,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<int32_t> 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<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::unordered_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;
       }