Skip to content
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.

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

Add a key to the access default log text format #1800

Merged
merged 5 commits into from
Aug 31, 2023

Conversation

arkodg
Copy link
Contributor

@arkodg arkodg commented Aug 18, 2023

Before

[2023-08-18T22:15:14.085Z] "GET /get HTTP/1.1" 200 - 0 509 1 0 "10.1.3.156" "curl/7.86.0" "ec7ca022-80c8-4e7c-8271-167b260bd190" "www.example.com" "10.102.226.25:3000"

After

{"start_time":"2023-08-30T19:39:16.694Z","method":"GET","x-envoy-origin-path":"/get","protocol":"HTTP/1.1","response_code":"200","response_flags":"-","response_code_details":"via_upstream","connection_termination_details":"-","upstream_transport_failure_reason":"-","bytes_received":"0","bytes_sent":"508","duration":"1","x-envoy-upstream-service-time":"0","x-forwarded-for":"10.1.4.12","user-agent":"curl/7.86.0","x-request-id":"df9cc5ed-8f92-4376-b045-34669dde0ea1",":authority":"www.example.com","upstream_host":"10.110.21.140:3000","upstream_cluster":"httproute/default/backend/rule/0","upstream_local_address":"10.1.4.12:36496","downstream_local_address":"127.0.0.1:10080","downstream_remote_address":"127.0.0.1:53826","requested_server_name":"-","route_name":"httproute/default/backend/rule/0/match/0/www_example_com"}

Fixes: #1446

@arkodg arkodg requested a review from a team as a code owner August 18, 2023 22:40
@arkodg
Copy link
Contributor Author

arkodg commented Aug 18, 2023

apart from adding a key for every field, this PR also adds more fields.

  • There's a bump in char length from 168 to 835
$ echo '[2023-08-18T22:15:14.085Z] "GET /get HTTP/1.1" 200 - 0 509 1 0 "10.1.3.156" "curl/7.86.0" "ec7ca022-80c8-4e7c-8271-167b260bd190" "www.example.com" "10.102.226.25:3000"' | wc -c
     168
$ echo '"start_time":"2023-08-18T22:01:23.901Z","method":"GET","x-envoy-origin-path":"/get","protocol":"HTTP/1.1","response_code":"200","response_flags":"-","response_code_details":"via_upstream","connection_termination_details":"-","upstream_transport_failure_reason":"-","bytes_received":"0","bytes_sent":"511","duration":"0","x-envoy-upstream-service-time":"0","x-forwarded-for":"192.168.65.4","user-agent":"curl/7.86.0","x-request-id":"000985ce-a62d-4899-95f8-c60fa9e5f246",":authority":"www.example.com","upstream_host":"10.104.223.83:3000","upstream_cluster":"default/backend/rule/0/match/0-www.example.com","upstream_local_address":"10.1.3.145:55664","downstream_local_address":"10.1.3.145:10080","downstream_remote_address":"192.168.65.4:50042","requested_server_name":"-","route_name":"default/backend/rule/0/match/0-www.example.com"' | wc -c
     835
  • And the separator is a comma / , instead of a space /

Hoping to hear back on preferences cc @envoyproxy/gateway-maintainers

@arkodg
Copy link
Contributor Author

arkodg commented Aug 18, 2023

also blocked on #1799

@arkodg arkodg marked this pull request as draft August 19, 2023 00:48
@arkodg
Copy link
Contributor Author

arkodg commented Aug 21, 2023

updated access log format to use spaces as the delimiter

@arkodg arkodg marked this pull request as ready for review August 21, 2023 23:56
@codecov
Copy link

codecov bot commented Aug 22, 2023

Codecov Report

Merging #1800 (6838599) into main (3c372dd) will decrease coverage by 0.12%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##             main    #1800      +/-   ##
==========================================
- Coverage   65.25%   65.14%   -0.12%     
==========================================
  Files          86       86              
  Lines       12480    12480              
==========================================
- Hits         8144     8130      -14     
- Misses       3821     3830       +9     
- Partials      515      520       +5     
Files Changed Coverage Δ
internal/xds/translator/accesslog.go 98.19% <ø> (ø)

... and 3 files with indirect coverage changes

@zirain
Copy link
Contributor

zirain commented Aug 22, 2023

updated access log format to use spaces as the delimiter

with this format, can you use a json decoder directly in logstash/fluent?

Alice-Lilith
Alice-Lilith previously approved these changes Aug 23, 2023
Copy link
Member

@Alice-Lilith Alice-Lilith left a comment

Choose a reason for hiding this comment

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

I like this format a lot more than the default EnvoyProxy access logs

@haq204
Copy link
Contributor

haq204 commented Aug 23, 2023

might as well go all the way to format it to be a JSON string so that external log aggregators can parse it as json structured logs

@arkodg
Copy link
Contributor Author

arkodg commented Aug 23, 2023

@zirain @haq204 imo the JSON string format

{"start_time":"2023-08-18T22:01:23.901Z","method":"GET","x-envoy-origin-path":"/get","protocol":"HTTP/1.1","response_code":"200","response_flags":"-","response_code_details":"via_upstream","connection_termination_details":"-","upstream_transport_failure_reason":"-","bytes_received":"0","bytes_sent":"511","duration":"0","x-envoy-upstream-service-time":"0","x-forwarded-for":"192.168.65.4","user-agent":"curl/7.86.0","x-request-id":"000985ce-a62d-4899-95f8-c60fa9e5f246",":authority":"www.example.com","upstream_host":"10.104.223.83:3000","upstream_cluster":"default/backend/rule/0/match/0-www.example.com","upstream_local_address":"10.1.3.145:55664","downstream_local_address":"10.1.3.145:10080","downstream_remote_address":"192.168.65.4:50042","requested_server_name":"-","route_name":"default/backend/rule/0/match/0-www.example.com"}

is a little harder to read compared to

"start_time":"2023-08-21T23:53:03.858Z" "method":"GET" "x-envoy-origin-path":"/get" "protocol":"HTTP/1.1" "response_code":"200" "response_flags":"-" "response_code_details":"via_upstream" "connection_termination_details":"-" "upstream_transport_failure_reason":"-" "bytes_received":"0" "bytes_sent":"511" "duration":"0" "x-envoy-upstream-service-time":"0" "x-forwarded-for":"192.168.65.4" "user-agent":"curl/7.86.0" "x-request-id":"4cb7e358-e1dc-4b94-abf2-bd699d5a11b7" ":authority":"www.example.com" "upstream_host":"10.105.188.194:3000" "upstream_cluster":"default/backend/rule/0/match/0-www.example.com" "upstream_local_address":"10.1.3.194:39338" "downstream_local_address":"10.1.3.194:10080" "downstream_remote_address":"192.168.65.4:47188" "requested_server_name":"-" "route_name":"default/backend/rule/0/match/0-www.example.com"

im fine proceeding either way, since adding a key makes life so much better than before

@zirain
Copy link
Contributor

zirain commented Aug 27, 2023

@zirain @haq204 imo the JSON string format

{"start_time":"2023-08-18T22:01:23.901Z","method":"GET","x-envoy-origin-path":"/get","protocol":"HTTP/1.1","response_code":"200","response_flags":"-","response_code_details":"via_upstream","connection_termination_details":"-","upstream_transport_failure_reason":"-","bytes_received":"0","bytes_sent":"511","duration":"0","x-envoy-upstream-service-time":"0","x-forwarded-for":"192.168.65.4","user-agent":"curl/7.86.0","x-request-id":"000985ce-a62d-4899-95f8-c60fa9e5f246",":authority":"www.example.com","upstream_host":"10.104.223.83:3000","upstream_cluster":"default/backend/rule/0/match/0-www.example.com","upstream_local_address":"10.1.3.145:55664","downstream_local_address":"10.1.3.145:10080","downstream_remote_address":"192.168.65.4:50042","requested_server_name":"-","route_name":"default/backend/rule/0/match/0-www.example.com"}

is a little harder to read compared to

"start_time":"2023-08-21T23:53:03.858Z" "method":"GET" "x-envoy-origin-path":"/get" "protocol":"HTTP/1.1" "response_code":"200" "response_flags":"-" "response_code_details":"via_upstream" "connection_termination_details":"-" "upstream_transport_failure_reason":"-" "bytes_received":"0" "bytes_sent":"511" "duration":"0" "x-envoy-upstream-service-time":"0" "x-forwarded-for":"192.168.65.4" "user-agent":"curl/7.86.0" "x-request-id":"4cb7e358-e1dc-4b94-abf2-bd699d5a11b7" ":authority":"www.example.com" "upstream_host":"10.105.188.194:3000" "upstream_cluster":"default/backend/rule/0/match/0-www.example.com" "upstream_local_address":"10.1.3.194:39338" "downstream_local_address":"10.1.3.194:10080" "downstream_remote_address":"192.168.65.4:47188" "requested_server_name":"-" "route_name":"default/backend/rule/0/match/0-www.example.com"

im fine proceeding either way, since adding a key makes life so much better than before

it's hard to use for other tools, same opinion with @haq204 .

arkodg added 3 commits August 30, 2023 11:28
Before
```
[2023-08-18T22:15:14.085Z] "GET /get HTTP/1.1" 200 - 0 509 1 0 "10.1.3.156" "curl/7.86.0" "ec7ca022-80c8-4e7c-8271-167b260bd190" "www.example.com" "10.102.226.25:3000"
```

After
```
"start_time":"2023-08-18T22:01:23.901Z","method":"GET","x-envoy-origin-path":"/get","protocol":"HTTP/1.1","response_code":"200","response_flags":"-","response_code_details":"via_upstream","connection_termination_details":"-","upstream_transport_failure_reason":"-","bytes_received":"0","bytes_sent":"511","duration":"0","x-envoy-upstream-service-time":"0","x-forwarded-for":"192.168.65.4","user-agent":"curl/7.86.0","x-request-id":"000985ce-a62d-4899-95f8-c60fa9e5f246",":authority":"www.example.com","upstream_host":"10.104.223.83:3000","upstream_cluster":"default/backend/rule/0/match/0-www.example.com","upstream_local_address":"10.1.3.145:55664","downstream_local_address":"10.1.3.145:10080","downstream_remote_address":"192.168.65.4:50042","requested_server_name":"-","route_name":"default/backend/rule/0/match/0-www.example.com"
```

Fixes: envoyproxy#1446

Signed-off-by: Arko Dasgupta <arko@tetrate.io>
Signed-off-by: Arko Dasgupta <arko@tetrate.io>
Signed-off-by: Arko Dasgupta <arko@tetrate.io>
Signed-off-by: Arko Dasgupta <arko@tetrate.io>
@arkodg arkodg force-pushed the key-value-access-log branch from 3372392 to a5be481 Compare August 30, 2023 19:26
@arkodg
Copy link
Contributor Author

arkodg commented Aug 30, 2023

created a compatible json string, ptal @haq204 @zirain

@arkodg arkodg requested review from zirain, Alice-Lilith, a team, kflynn, qicz and Xunzhuo and removed request for a team August 30, 2023 19:40
@qicz
Copy link
Member

qicz commented Aug 31, 2023

so the text and json formats have the same log format?

@arkodg
Copy link
Contributor Author

arkodg commented Aug 31, 2023

so the text and json formats have the same log format?

The default format is Text as JSON string 😄

Copy link
Contributor

@zirain zirain left a comment

Choose a reason for hiding this comment

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

cc @AliceProxy

Copy link
Member

@zhaohuabing zhaohuabing left a comment

Choose a reason for hiding this comment

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

Looks much better than the default one. I always had to check the docs to find out the meaning of the Envoy logs before because lacking of the key before the value :-).

@arkodg arkodg merged commit a324513 into envoyproxy:main Aug 31, 2023
18 checks passed
@arkodg arkodg deleted the key-value-access-log branch August 31, 2023 04:05
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Default to Key, Value based Access Logging to STDOUT
6 participants