[Access Log] Add EMIT_TIME command operator (#31162)

Commit Message: Add EMIT_TIME command operator for access log. Additional Description: Access log currently has only one command operator for timestamp (START_TIME), which is identical for all access logs of the same stream (In case we enable on-start and periodic access log). In this PR, I've added a command operator that presents the timestamp of emitting access log. command operator for the current time in access logging #28736 Risk Level: Testing: Docs Changes: Release Notes: Platform Specific Features: Signed-off-by: Issa Abu Kalbein <[email protected]>
envoyproxy · Dec 11, 2023 · 00fe753 · 00fe753
1 parent 6269243
commit 00fe753
Show file tree

Hide file tree

Showing 8 changed files with 50 additions and 0 deletions.
diff --git a/changelogs/current.yaml b/changelogs/current.yaml
@@ -277,5 +277,8 @@ new_features:
     added :ref:`ignore_query_parameters
     <envoy_v3_api_field_extensions.filters.http.grpc_http1_bridge.v3.Config.ignore_query_parameters>` option for
     automatically stripping query parameters in request URL path.
+- area: access_log
+  change: |
+    Added new access log command operator ``%EMIT_TIME%`` to get the time when the log entry is emitted.
 
 deprecated:
diff --git a/docs/root/configuration/observability/access_log/usage.rst b/docs/root/configuration/observability/access_log/usage.rst
@@ -168,6 +168,14 @@ The following command operators are supported:
 
   In typed JSON logs, START_TIME is always rendered as a string.
 
+.. _config_access_log_format_emit_time:
+
+%EMIT_TIME%
+  The time when log entry is emitted including milliseconds.
+
+  EMIT_TIME can be customized using a `format string <https://en.cppreference.com/w/cpp/io/manip/put_time>`_.
+  See :ref:`START_TIME <config_access_log_format_start_time>` for additional format specifiers and examples.
+
 %REQUEST_HEADERS_BYTES%
   HTTP
     Uncompressed bytes of request headers.

diff --git a/envoy/stream_info/stream_info.h b/envoy/stream_info/stream_info.h
@@ -706,6 +706,11 @@ class StreamInfo {
    */
   virtual MonotonicTime startTimeMonotonic() const PURE;
 
+  /**
+   * @return returns the time source.
+   */
+  virtual TimeSource& timeSource() const PURE;
+
   /**
    * Sets the upstream information for this stream.
    */

diff --git a/source/common/formatter/stream_info_formatter.cc b/source/common/formatter/stream_info_formatter.cc
@@ -1364,6 +1364,16 @@ const StreamInfoFormatterProviderLookupTable& getKnownStreamInfoFormatterProvide
                         return stream_info.startTime();
                       }));
             }}},
+          {"EMIT_TIME",
+           {CommandSyntaxChecker::PARAMS_OPTIONAL,
+            [](const std::string& format, absl::optional<size_t>) {
+              return std::make_unique<SystemTimeFormatter>(
+                  format,
+                  std::make_unique<SystemTimeFormatter::TimeFieldExtractor>(
+                      [](const StreamInfo::StreamInfo& stream_info) -> absl::optional<SystemTime> {
+                        return stream_info.timeSource().systemTime();
+                      }));
+            }}},
           {"DYNAMIC_METADATA",
            {CommandSyntaxChecker::PARAMS_REQUIRED,
             [](const std::string& format, absl::optional<size_t> max_length) {

diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h
@@ -134,6 +134,8 @@ struct StreamInfoImpl : public StreamInfo {
 
   MonotonicTime startTimeMonotonic() const override { return start_time_monotonic_; }
 
+  TimeSource& timeSource() const override { return time_source_; }
+
   absl::optional<std::chrono::nanoseconds> duration(absl::optional<MonotonicTime> time) const {
     if (!time) {
       return {};

diff --git a/test/common/access_log/access_log_impl_test.cc b/test/common/access_log/access_log_impl_test.cc
@@ -1686,6 +1686,26 @@ name: accesslog
   logger->log({&request_headers_, &response_headers_, &response_trailers_}, stream_info_);
 }
 
+TEST_F(AccessLogImplTest, EmitTime) {
+  const std::string yaml = R"EOF(
+name: accesslog
+typed_config:
+  "@type": type.googleapis.com/envoy.extensions.access_loggers.file.v3.FileAccessLog
+  path: /dev/null
+  log_format:
+    text_format_source:
+      inline_string: "%EMIT_TIME%"
+  )EOF";
+
+  InstanceSharedPtr log = AccessLogFactory::fromProto(parseAccessLogFromV3Yaml(yaml), context_);
+  EXPECT_CALL(*file_, write(_));
+
+  log->log({&request_headers_, &response_headers_, &response_trailers_}, stream_info_);
+
+  const std::string time_regex = "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{3}Z$";
+  EXPECT_TRUE(std::regex_match(output_.value(), std::regex(time_regex)));
+}
+
 /**
  * Sample extension filter which allows every 1 of every `sample_rate` log attempts.
  */

diff --git a/test/mocks/stream_info/mocks.cc b/test/mocks/stream_info/mocks.cc
@@ -100,6 +100,7 @@ MockStreamInfo::MockStreamInfo()
       }));
   ON_CALL(*this, startTime()).WillByDefault(ReturnPointee(&start_time_));
   ON_CALL(*this, startTimeMonotonic()).WillByDefault(ReturnPointee(&start_time_monotonic_));
+  ON_CALL(*this, timeSource()).WillByDefault(ReturnPointee(&ts_));
   ON_CALL(*this, currentDuration()).WillByDefault(ReturnPointee(&end_time_));
   ON_CALL(*this, requestComplete()).WillByDefault(ReturnPointee(&end_time_));
   ON_CALL(*this, onRequestComplete()).WillByDefault(Invoke([this]() {

diff --git a/test/mocks/stream_info/mocks.h b/test/mocks/stream_info/mocks.h
@@ -75,6 +75,7 @@ class MockStreamInfo : public StreamInfo {
   MOCK_METHOD(void, onUpstreamHostSelected, (Upstream::HostDescriptionConstSharedPtr host));
   MOCK_METHOD(SystemTime, startTime, (), (const));
   MOCK_METHOD(MonotonicTime, startTimeMonotonic, (), (const));
+  MOCK_METHOD(TimeSource&, timeSource, (), (const));
   MOCK_METHOD(void, setUpstreamInfo, (std::shared_ptr<UpstreamInfo>));
   MOCK_METHOD(std::shared_ptr<UpstreamInfo>, upstreamInfo, ());
   MOCK_METHOD(OptRef<const UpstreamInfo>, upstreamInfo, (), (const));