diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst index c85bd554aa104..94392f404c69f 100644 --- a/docs/root/configuration/access_log.rst +++ b/docs/root/configuration/access_log.rst @@ -102,6 +102,14 @@ The following command operators are supported: TCP Total duration in milliseconds of the downstream connection. +%RESPONSE_DURATION% + HTTP + Total duration in milliseconds of the request from the start time to the first byte read from the + upstream host. + + TCP + Not implemented ("-"). + .. _config_access_log_format_response_flags: %RESPONSE_FLAGS% @@ -123,6 +131,14 @@ The following command operators are supported: * **FI**: The request was aborted with a response code specified via :ref:`fault injection `. * **RL**: The request was ratelimited locally by the :ref:`HTTP rate limit filter ` in addition to 429 response code. +%RESPONSE_TX_DURATION% + HTTP + Total duration in milliseconds of the request from the first byte read from the upstream host to the last + byte sent downstream. + + TCP + Not implemented ("-"). + %UPSTREAM_HOST% Upstream host URL (e.g., tcp://ip:port for TCP connections). diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index eb2bfe7f6752c..588e1225387f5 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -40,6 +40,7 @@ Version history `. * upstream: added configuration option to the subset load balancer to take locality weights into account when selecting a host from a subset. +* access log: added RESPONSE_DURATION and RESPONSE_TX_DURATION. 1.7.0 =============== diff --git a/source/common/access_log/access_log_formatter.cc b/source/common/access_log/access_log_formatter.cc index 933a1cc65a789..88ec956d9d558 100644 --- a/source/common/access_log/access_log_formatter.cc +++ b/source/common/access_log/access_log_formatter.cc @@ -35,14 +35,16 @@ FormatterPtr AccessLogFormatUtils::defaultAccessLogFormatter() { std::string AccessLogFormatUtils::durationToString(const absl::optional& time) { if (time) { - return fmt::FormatInt( - std::chrono::duration_cast(time.value()).count()) - .str(); + return durationToString(time.value()); } else { return UnspecifiedValueString; } } +std::string AccessLogFormatUtils::durationToString(const std::chrono::nanoseconds& time) { + return fmt::FormatInt(std::chrono::duration_cast(time).count()).str(); +} + const std::string& AccessLogFormatUtils::protocolToString(const absl::optional& protocol) { if (protocol) { @@ -221,6 +223,18 @@ RequestInfoFormatter::RequestInfoFormatter(const std::string& field_name) { field_extractor_ = [](const RequestInfo::RequestInfo& request_info) { return AccessLogFormatUtils::durationToString(request_info.firstUpstreamRxByteReceived()); }; + } else if (field_name == "RESPONSE_TX_DURATION") { + field_extractor_ = [](const RequestInfo::RequestInfo& request_info) { + auto downstream = request_info.lastDownstreamTxByteSent(); + auto upstream = request_info.firstUpstreamRxByteReceived(); + + if (downstream && upstream) { + auto val = downstream.value() - upstream.value(); + return AccessLogFormatUtils::durationToString(val); + } + + return UnspecifiedValueString; + }; } else if (field_name == "BYTES_RECEIVED") { field_extractor_ = [](const RequestInfo::RequestInfo& request_info) { return fmt::FormatInt(request_info.bytesReceived()).str(); diff --git a/source/common/access_log/access_log_formatter.h b/source/common/access_log/access_log_formatter.h index b0a1246345c06..b6cb0a8a2775d 100644 --- a/source/common/access_log/access_log_formatter.h +++ b/source/common/access_log/access_log_formatter.h @@ -73,6 +73,7 @@ class AccessLogFormatUtils { static FormatterPtr defaultAccessLogFormatter(); static const std::string& protocolToString(const absl::optional& protocol); static std::string durationToString(const absl::optional& time); + static std::string durationToString(const std::chrono::nanoseconds& time); private: AccessLogFormatUtils(); diff --git a/test/common/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc index fe711bf4f2b1e..44c0ddf9eda84 100644 --- a/test/common/access_log/access_log_formatter_test.cc +++ b/test/common/access_log/access_log_formatter_test.cc @@ -73,6 +73,28 @@ TEST(AccessLogFormatterTest, requestInfoFormatter) { EXPECT_EQ("-", response_duration_format.format(header, header, header, request_info)); } + { + RequestInfoFormatter ttlb_duration_format("RESPONSE_TX_DURATION"); + + absl::optional dur_upstream = std::chrono::nanoseconds(10000000); + EXPECT_CALL(request_info, firstUpstreamRxByteReceived()).WillRepeatedly(Return(dur_upstream)); + absl::optional dur_downstream = std::chrono::nanoseconds(25000000); + EXPECT_CALL(request_info, lastDownstreamTxByteSent()).WillRepeatedly(Return(dur_downstream)); + + EXPECT_EQ("15", ttlb_duration_format.format(header, header, header, request_info)); + } + + { + RequestInfoFormatter ttlb_duration_format("RESPONSE_TX_DURATION"); + + absl::optional dur_upstream; + EXPECT_CALL(request_info, firstUpstreamRxByteReceived()).WillRepeatedly(Return(dur_upstream)); + absl::optional dur_downstream; + EXPECT_CALL(request_info, lastDownstreamTxByteSent()).WillRepeatedly(Return(dur_downstream)); + + EXPECT_EQ("-", ttlb_duration_format.format(header, header, header, request_info)); + } + { RequestInfoFormatter bytes_received_format("BYTES_RECEIVED"); EXPECT_CALL(request_info, bytesReceived()).WillOnce(Return(1));