From 00fe7532a076f038d229a337c91d0d542db77ce5 Mon Sep 17 00:00:00 2001 From: IssaAbuKalbein <86603440+IssaAbuKalbein@users.noreply.github.com> Date: Mon, 11 Dec 2023 19:41:00 +0200 Subject: [PATCH] [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 --- changelogs/current.yaml | 3 +++ .../observability/access_log/usage.rst | 8 ++++++++ envoy/stream_info/stream_info.h | 5 +++++ .../common/formatter/stream_info_formatter.cc | 10 ++++++++++ source/common/stream_info/stream_info_impl.h | 2 ++ .../common/access_log/access_log_impl_test.cc | 20 +++++++++++++++++++ test/mocks/stream_info/mocks.cc | 1 + test/mocks/stream_info/mocks.h | 1 + 8 files changed, 50 insertions(+) diff --git a/changelogs/current.yaml b/changelogs/current.yaml index c352bd116475..5323e6429d56 100644 --- a/changelogs/current.yaml +++ b/changelogs/current.yaml @@ -277,5 +277,8 @@ new_features: added :ref:`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 index fea2b3e52545..03483c0fd49f 100644 --- 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 `_. + See :ref:`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 index 96bcfc5997d8..4091b6eeddc5 100644 --- 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 index 8d1f32e071a9..7d72800f3aaa 100644 --- 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) { + return std::make_unique( + format, + std::make_unique( + [](const StreamInfo::StreamInfo& stream_info) -> absl::optional { + return stream_info.timeSource().systemTime(); + })); + }}}, {"DYNAMIC_METADATA", {CommandSyntaxChecker::PARAMS_REQUIRED, [](const std::string& format, absl::optional max_length) { diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index ca72643ba82c..5d1494640824 100644 --- 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 duration(absl::optional 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 index b8849393601d..46c1860b0ce5 100644 --- 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 index 710848e59b8a..5b92c27f06f2 100644 --- 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 index c22c35debdba..b83a40d7e69c 100644 --- 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)); MOCK_METHOD(std::shared_ptr, upstreamInfo, ()); MOCK_METHOD(OptRef, upstreamInfo, (), (const));