access_log, router: add subsecond specifier for START_TIME

docs/root/configuration/http_conn_man/headers.rst

@@ -480,3 +480,6 @@ 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_TIMESTAMP%
+    The timestamp when the first byte of a request is received. The timestamp unit is in milliseconds.

docs/root/intro/version_history.rst

@@ -59,6 +59,8 @@ Version history
 * logger: added the ability to optionally set the log format via the :option:`--log-format` option.
 * logger: all :ref:`logging levels <operations_admin_interface_logging>` can be configured
   at run-time: trace debug info warning error critical.
+* router: added `START_TIMESTAMP` as one of supported variables in :ref:`header
+  formatters <config_http_conn_man_headers_custom_request_headers>`. The timestamp unit is in milliseconds.
 * 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/router/header_formatter.cc

@@ -135,6 +135,13 @@ RequestInfoHeaderFormatter::RequestInfoHeaderFormatter(absl::string_view field_n
       return RequestInfo::Utility::formatDownstreamAddressNoPort(
           *request_info.downstreamLocalAddress());
     };
+  } else if (field_name == "START_TIMESTAMP") {
+    field_extractor_ = [](const RequestInfo::RequestInfo& request_info) {
+      // Returns the start timestamp in milliseconds.
+      return fmt::format("{}", std::chrono::duration_cast<std::chrono::milliseconds>(
+                                   request_info.startTime().time_since_epoch())
+                                   .count());
+    };
   } else if (field_name.find_first_of("UPSTREAM_METADATA") == 0) {
     field_extractor_ =
         parseUpstreamMetadataField(field_name.substr(STATIC_STRLEN("UPSTREAM_METADATA")));

test/common/router/header_formatter_test.cc

@@ -16,6 +16,7 @@
 #include "gtest/gtest.h"
 
 using testing::NiceMock;
+using testing::Return;
 using testing::ReturnPointee;
 using testing::ReturnRef;
 
@@ -251,6 +252,12 @@ TEST(HeaderParserTest, TestParseInternal) {
     absl::optional<std::string> expected_exception_;
   };
 
+  time_t start_time_epoch = 1522280158;
+  SystemTime start_time = std::chrono::system_clock::from_time_t(start_time_epoch);
+  const std::string timestamp = fmt::format(
+      "{}",
+      std::chrono::duration_cast<std::chrono::milliseconds>(start_time.time_since_epoch()).count());
+
   static const TestCase test_cases[] = {
       // Valid inputs
       {"%PROTOCOL%", {"HTTP/1.1"}, {}},
@@ -270,6 +277,7 @@ TEST(HeaderParserTest, TestParseInternal) {
       {"%UPSTREAM_METADATA([\"ns\", \t \"key\"])%", {"value"}, {}},
       {"%UPSTREAM_METADATA([\"ns\", \n \"key\"])%", {"value"}, {}},
       {"%UPSTREAM_METADATA( \t [ \t \"ns\" \t , \t \"key\" \t ] \t )%", {"value"}, {}},
+      {"%START_TIMESTAMP%", {timestamp}, {}},
 
       // Unescaped %
       {"%", {}, {"Invalid header configuration. Un-escaped % at position 0"}},
@@ -404,6 +412,8 @@ TEST(HeaderParserTest, TestParseInternal) {
       )EOF");
   ON_CALL(*host, metadata()).WillByDefault(ReturnRef(metadata));
 
+  ON_CALL(request_info, startTime()).WillByDefault(Return(start_time));
+
   for (const auto& test_case : test_cases) {
     Protobuf::RepeatedPtrField<envoy::api::v2::core::HeaderValueOption> to_add;
     envoy::api::v2::core::HeaderValueOption* header = to_add.Add();
@@ -595,6 +605,10 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) {
       {
         "key": "x-client-ip",
         "value": "%CLIENT_IP%"
+      },
+      {
+        "key": "x-request-start",
+        "value": "%START_TIMESTAMP%"
       }
     ]
   }
@@ -604,19 +618,30 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) {
   envoy::api::v2::route::RouteAction route_action = parseRouteFromJson(json).route();
   route_action.mutable_request_headers_to_add(0)->mutable_append()->set_value(false);
   route_action.mutable_request_headers_to_add(1)->mutable_append()->set_value(false);
+  route_action.mutable_request_headers_to_add(2)->mutable_append()->set_value(false);
 
   HeaderParserPtr req_header_parser =
       Router::HeaderParser::configure(route_action.request_headers_to_add());
   Http::TestHeaderMapImpl headerMap{
       {":method", "POST"}, {"static-header", "old-value"}, {"x-client-ip", "0.0.0.0"}};
 
   NiceMock<Envoy::RequestInfo::MockRequestInfo> request_info;
+  time_t start_time_epoch = 1522280158;
+  SystemTime start_time = std::chrono::system_clock::from_time_t(start_time_epoch);
+  EXPECT_CALL(request_info, startTime()).WillOnce(Return(start_time));
+
   req_header_parser->evaluateHeaders(headerMap, request_info);
   EXPECT_TRUE(headerMap.has("static-header"));
   EXPECT_EQ("static-value", headerMap.get_("static-header"));
   EXPECT_TRUE(headerMap.has("x-client-ip"));
   EXPECT_EQ("127.0.0.1", headerMap.get_("x-client-ip"));
 
+  uint64_t timestamp;
+  StringUtil::atoul(headerMap.get_("x-request-start").c_str(), timestamp);
+  EXPECT_EQ(
+      timestamp,
+      std::chrono::duration_cast<std::chrono::milliseconds>(start_time.time_since_epoch()).count());
+
   typedef std::map<std::string, int> CountMap;
   CountMap counts;
   headerMap.iterate(
@@ -635,6 +660,7 @@ TEST(HeaderParserTest, EvaluateHeadersWithAppendFalse) {
 
   EXPECT_EQ(1, counts["static-header"]);
   EXPECT_EQ(1, counts["x-client-ip"]);
+  EXPECT_EQ(1, counts["x-request-start"]);
 }
 
 TEST(HeaderParserTest, EvaluateResponseHeaders) {
@@ -647,6 +673,10 @@ match: { prefix: "/new_endpoint" }
         key: "x-client-ip"
         value: "%CLIENT_IP%"
       append: true
+    - header:
+        key: "x-request-start"
+        value: "%START_TIMESTAMP%"
+      append: true
   response_headers_to_remove: ["x-nope"]
 )EOF";
 
@@ -657,6 +687,7 @@ match: { prefix: "/new_endpoint" }
   NiceMock<Envoy::RequestInfo::MockRequestInfo> request_info;
   resp_header_parser->evaluateHeaders(headerMap, request_info);
   EXPECT_TRUE(headerMap.has("x-client-ip"));
+  EXPECT_TRUE(headerMap.has("x-request-start"));
   EXPECT_TRUE(headerMap.has("x-safe"));
   EXPECT_FALSE(headerMap.has("x-nope"));
 }