Skip to content

Add new field to access log #3907

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
zuercher merged 4 commits into from
Jul 24, 2018
Merged

Add new field to access log #3907

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
abbad13
Add new field to access log
Jul 19, 2018
9291f86
Change name to `RESPONSE_TX_DURATION`
Jul 20, 2018
8481dac
Document %RESPONSE_DURATION% & %RESPONSE_TX_DURATION%
Jul 23, 2018
164ea84
Add entry in the release notes
Jul 23, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 16 additions & 0 deletions docs/root/configuration/access_log.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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%
Expand All @@ -123,6 +131,14 @@ The following command operators are supported:
* **FI**: The request was aborted with a response code specified via :ref:`fault injection <config_http_filters_fault_injection>`.
* **RL**: The request was ratelimited locally by the :ref:`HTTP rate limit filter <config_http_filters_rate_limit>` 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).

Expand Down
1 change: 1 addition & 0 deletions docs/root/intro/version_history.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,7 @@ Version history
<envoy_api_field_config.filter.network.http_connection_manager.v2.HttpConnectionManager.tracing>`.
* 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
===============
Expand Down
20 changes: 17 additions & 3 deletions source/common/access_log/access_log_formatter.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,14 +35,16 @@ FormatterPtr AccessLogFormatUtils::defaultAccessLogFormatter() {
std::string
AccessLogFormatUtils::durationToString(const absl::optional<std::chrono::nanoseconds>& time) {
if (time) {
return fmt::FormatInt(
std::chrono::duration_cast<std::chrono::milliseconds>(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<std::chrono::milliseconds>(time).count()).str();
}

const std::string&
AccessLogFormatUtils::protocolToString(const absl::optional<Http::Protocol>& protocol) {
if (protocol) {
Expand Down Expand Up @@ -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") {

@mattklein123 mattklein123 Jul 23, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this needs a doc update and a release note? https://www.envoyproxy.io/docs/envoy/latest/configuration/access_log?

@rgs1 rgs1 Jul 23, 2018 •
edited
Loading

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mattklein123 %RESPONSE_DURATION% isn't public either... so my thinking was lets have it be private for now and then promote it as publicly available interface/variable? I am happy either way though.

@mattklein123 mattklein123 Jul 23, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What do you mean not public? I think if it's not documented that's a doc bug. Can you fix both? :)

@rgs1 rgs1 Jul 23, 2018

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Haha, sure — diff coming up.

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();
Expand Down
1 change: 1 addition & 0 deletions source/common/access_log/access_log_formatter.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -73,6 +73,7 @@ class AccessLogFormatUtils {
static FormatterPtr defaultAccessLogFormatter();
static const std::string& protocolToString(const absl::optional<Http::Protocol>& protocol);
static std::string durationToString(const absl::optional<std::chrono::nanoseconds>& time);
static std::string durationToString(const std::chrono::nanoseconds& time);

private:
AccessLogFormatUtils();
Expand Down
22 changes: 22 additions & 0 deletions test/common/access_log/access_log_formatter_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<std::chrono::nanoseconds> dur_upstream = std::chrono::nanoseconds(10000000);
EXPECT_CALL(request_info, firstUpstreamRxByteReceived()).WillRepeatedly(Return(dur_upstream));
absl::optional<std::chrono::nanoseconds> 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<std::chrono::nanoseconds> dur_upstream;
EXPECT_CALL(request_info, firstUpstreamRxByteReceived()).WillRepeatedly(Return(dur_upstream));
absl::optional<std::chrono::nanoseconds> 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));
Expand Down