access_log, router: add subsecond specifier for START_TIME

api/envoy/config/filter/http/router/v2/router.proto

@@ -26,4 +26,15 @@ message Router {
   // an upstream request. Presuming retries are configured, multiple upstream
   // requests may be made for each downstream (inbound) request.
   repeated envoy.config.filter.accesslog.v2.AccessLog upstream_log = 3;
+
+  // If set, the specified header will be added to upstream requests with a timestamp
+  // (in milliseconds) when Envoy starts decoding downstream's request headers.
+  //
+  // Example:
+  //
+  // .. code-block:: yaml
+  //
+  //   start_timestamp_header: x-request-start
+  //
+  string start_timestamp_header = 4;
 }

docs/root/intro/version_history.rst

@@ -53,6 +53,9 @@ 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 the optional
+  :ref:`start timestamp header<envoy_api_field_config.filter.http.router.v2.Router.start_timestamp_header>`
+  to send timestamp (in milliseconds) as the value of the specified header in upstream requests.
 * sockets: added `IP_FREEBIND` socket option support for :ref:`listeners
   <envoy_api_field_Listener.freebind>` and upstream connections via
   :ref:`cluster manager wide

source/common/http/async_client_impl.cc

@@ -34,7 +34,7 @@ AsyncClientImpl::AsyncClientImpl(const Upstream::ClusterInfo& cluster, Stats::St
                                  Runtime::RandomGenerator& random,
                                  Router::ShadowWriterPtr&& shadow_writer)
     : cluster_(cluster), config_("http.async-client.", local_info, stats_store, cm, runtime, random,
-                                 std::move(shadow_writer), true, false),
+                                 std::move(shadow_writer), true, false, EMPTY_STRING),
       dispatcher_(dispatcher) {}
 
 AsyncClientImpl::~AsyncClientImpl() {

source/common/router/router.cc

@@ -192,6 +192,12 @@ void Filter::sendLocalReply(Http::Code code, const std::string& body,
 Http::FilterHeadersStatus Filter::decodeHeaders(Http::HeaderMap& headers, bool end_stream) {
   downstream_headers_ = &headers;
 
+  // If defined, set the specified start timestamp header with timestamp in milliseconds.
+  if (!config_.start_timestamp_header_.get().empty()) {
+    headers.addReferenceKey(config_.start_timestamp_header_,
+                            std::chrono::system_clock::now().time_since_epoch().count());
+  }
+
   // Only increment rq total stat if we actually decode headers here. This does not count requests
   // that get handled by earlier filters.
   config_.stats_.rq_total_.inc();

source/common/router/router.h

@@ -89,19 +89,20 @@ class FilterConfig {
   FilterConfig(const std::string& stat_prefix, const LocalInfo::LocalInfo& local_info,
                Stats::Scope& scope, Upstream::ClusterManager& cm, Runtime::Loader& runtime,
                Runtime::RandomGenerator& random, ShadowWriterPtr&& shadow_writer,
-               bool emit_dynamic_stats, bool start_child_span)
+               bool emit_dynamic_stats, bool start_child_span,
+               const std::string& start_timestamp_header)
       : scope_(scope), local_info_(local_info), cm_(cm), runtime_(runtime),
         random_(random), stats_{ALL_ROUTER_STATS(POOL_COUNTER_PREFIX(scope, stat_prefix))},
         emit_dynamic_stats_(emit_dynamic_stats), start_child_span_(start_child_span),
-        shadow_writer_(std::move(shadow_writer)) {}
+        start_timestamp_header_(start_timestamp_header), shadow_writer_(std::move(shadow_writer)) {}
 
   FilterConfig(const std::string& stat_prefix, Server::Configuration::FactoryContext& context,
                ShadowWriterPtr&& shadow_writer,
                const envoy::config::filter::http::router::v2::Router& config)
       : FilterConfig(stat_prefix, context.localInfo(), context.scope(), context.clusterManager(),
                      context.runtime(), context.random(), std::move(shadow_writer),
                      PROTOBUF_GET_WRAPPED_OR_DEFAULT(config, dynamic_stats, true),
-                     config.start_child_span()) {
+                     config.start_child_span(), config.start_timestamp_header()) {
     for (const auto& upstream_log : config.upstream_log()) {
       upstream_logs_.push_back(AccessLog::AccessLogFactory::fromProto(upstream_log, context));
     }
@@ -118,6 +119,7 @@ class FilterConfig {
   const bool emit_dynamic_stats_;
   const bool start_child_span_;
   std::list<AccessLog::InstanceSharedPtr> upstream_logs_;
+  const Http::LowerCaseString start_timestamp_header_;
 
 private:
   ShadowWriterPtr shadow_writer_;

test/common/router/router_test.cc

@@ -63,10 +63,10 @@ class TestFilter : public Filter {
 
 class RouterTestBase : public testing::Test {
 public:
-  RouterTestBase(bool start_child_span)
+  RouterTestBase(bool start_child_span, const std::string& start_timestamp_header = EMPTY_STRING)
       : shadow_writer_(new MockShadowWriter()),
         config_("test.", local_info_, stats_store_, cm_, runtime_, random_,
-                ShadowWriterPtr{shadow_writer_}, true, start_child_span),
+                ShadowWriterPtr{shadow_writer_}, true, start_child_span, start_timestamp_header),
         router_(config_) {
     router_.setDecoderFilterCallbacks(callbacks_);
     upstream_locality_.set_zone("to_az");
@@ -1628,6 +1628,28 @@ TEST_F(RouterTest, DirectResponseWithBody) {
   EXPECT_EQ(1UL, config_.stats_.rq_direct_response_.value());
 }
 
+TEST_F(RouterTest, NoStartTimestampHeader) {
+  absl::optional<Http::Protocol> downstream_protocol{Http::Protocol::Http2};
+  EXPECT_CALL(*cm_.thread_local_cluster_.cluster_.info_, features())
+      .WillOnce(Return(Upstream::ClusterInfo::Features::USE_DOWNSTREAM_PROTOCOL));
+  EXPECT_CALL(callbacks_.request_info_, protocol()).WillOnce(ReturnPointee(&downstream_protocol));
+
+  EXPECT_CALL(cm_, httpConnPoolForCluster(_, _, Http::Protocol::Http2, _));
+  EXPECT_CALL(cm_.conn_pool_, newStream(_, _)).WillOnce(Return(&cancellable_));
+  expectResponseTimerCreate();
+
+  Http::TestHeaderMapImpl headers;
+  HttpTestUtility::addDefaultHeaders(headers);
+  router_.decodeHeaders(headers, true);
+
+  const Http::LowerCaseString header("x-request-start");
+  EXPECT_EQ(nullptr, headers.get(header));
+
+  EXPECT_CALL(cancellable_, cancel());
+  router_.onDestroy();
+  EXPECT_TRUE(verifyHostUpstreamStats(0, 0));
+}
+
 TEST(RouterFilterUtilityTest, finalTimeout) {
   {
     NiceMock<MockRouteEntry> route;
@@ -2117,5 +2139,36 @@ TEST_F(RouterTestChildSpan, ResetFlow) {
   encoder.stream_.resetStream(Http::StreamResetReason::RemoteReset);
 }
 
+class RouterTestStartTimestampHeader : public RouterTestBase {
+public:
+  RouterTestStartTimestampHeader() : RouterTestBase(false, "X-Request-Start") {}
+};
+
+TEST_F(RouterTestStartTimestampHeader, WithStartTimestampHeader) {
+  absl::optional<Http::Protocol> downstream_protocol{Http::Protocol::Http2};
+  EXPECT_CALL(*cm_.thread_local_cluster_.cluster_.info_, features())
+      .WillOnce(Return(Upstream::ClusterInfo::Features::USE_DOWNSTREAM_PROTOCOL));
+  EXPECT_CALL(callbacks_.request_info_, protocol()).WillOnce(ReturnPointee(&downstream_protocol));
+
+  EXPECT_CALL(cm_, httpConnPoolForCluster(_, _, Http::Protocol::Http2, _));
+  EXPECT_CALL(cm_.conn_pool_, newStream(_, _)).WillOnce(Return(&cancellable_));
+  expectResponseTimerCreate();
+
+  Http::TestHeaderMapImpl headers;
+  HttpTestUtility::addDefaultHeaders(headers);
+  const Http::LowerCaseString header("x-request-start");
+  EXPECT_EQ(nullptr, headers.get(header));
+  router_.decodeHeaders(headers, true);
+  EXPECT_NE(nullptr, headers.get(header));
+
+  uint64_t timestamp;
+  StringUtil::atoul(headers.get(header)->value().c_str(), timestamp);
+  EXPECT_GT(timestamp, 0);
+
+  EXPECT_CALL(cancellable_, cancel());
+  router_.onDestroy();
+  EXPECT_TRUE(verifyHostUpstreamStats(0, 0));
+}
+
 } // namespace Router
 } // namespace Envoy