Skip to content

logging: Add traceID field to access logs when tracing is active #5507

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

Jump to bottom
Merged
merged 5 commits into from
Apr 27, 2023
Merged

logging: Add traceID field to access logs when tracing is active #5507

merged 5 commits into from
Apr 27, 2023

Conversation

hairyhenderson
Copy link
Collaborator

@hairyhenderson hairyhenderson commented Apr 23, 2023 •
edited
Loading

Tracing is far more useful when we can correlate logs with traces. This is done by adding a traceID field to the access logs.

I've attempted to add this in with a minimum of performance impact, and as such have moved the request logging function out of ServeHTTP and into a new method that can be tested independently. I've added some basic unit tests and a couple of benchmarks to gauge the impact.

Here are benchmark results before the traceID field was added:

$ go test -benchtime=3s -count=5 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee before.txt
goos: darwin
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: Intel(R) Core(TM) i7-10700K CPU @ 3.80GHz
BenchmarkServer_LogRequest-16                    3927310               920.3 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest-16                    3940473               913.4 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest-16                    3886784               913.1 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest-16                    4025732               919.2 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest-16                    3943749               924.9 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3859365               921.3 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3902739               925.0 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3910292               932.5 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3933997               922.4 ns/op           417 B/op       4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3993286               918.3 ns/op           417 B/op       4 allocs/op
PASS
ok      github.com/caddyserver/caddy/v2/modules/caddyhttp       45.867s

After:

$ go test -benchtime=3s -count=5 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee after.txt
goos: darwin
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: Intel(R) Core(TM) i7-10700K CPU @ 3.80GHz
BenchmarkServer_LogRequest-16                    3820621               949.4 ns/op           417 B/op          4 allocs/op
BenchmarkServer_LogRequest-16                    3860674               943.5 ns/op           417 B/op          4 allocs/op
BenchmarkServer_LogRequest-16                    3833852               939.1 ns/op           417 B/op          4 allocs/op
BenchmarkServer_LogRequest-16                    3858829               944.0 ns/op           417 B/op          4 allocs/op
BenchmarkServer_LogRequest-16                    3835098               940.2 ns/op           417 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3306637              1037 ns/op             481 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3424615              1047 ns/op             481 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3484468              1037 ns/op             481 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3476361              1215 ns/op             481 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTraceID-16        3457842              1062 ns/op             481 B/op          4 allocs/op
PASS
ok      github.com/caddyserver/caddy/v2/modules/caddyhttp       47.080s

Here's the diff:

$ benchstat before.txt after.txt 
name                              old time/op    new time/op    delta
Server_LogRequest-16                 918ns ± 1%     943ns ± 1%   +2.73%  (p=0.008 n=5+5)
Server_LogRequest_WithTraceID-16     924ns ± 1%    1080ns ±13%  +16.85%  (p=0.008 n=5+5)

name                              old alloc/op   new alloc/op   delta
Server_LogRequest-16                  417B ± 0%      417B ± 0%     ~     (all equal)
Server_LogRequest_WithTraceID-16      417B ± 0%      481B ± 0%  +15.35%  (p=0.008 n=5+5)

name                              old allocs/op  new allocs/op  delta
Server_LogRequest-16                  4.00 ± 0%      4.00 ± 0%     ~     (all equal)
Server_LogRequest_WithTraceID-16      4.00 ± 0%      4.00 ± 0%     ~     (all equal)

(note: I've edited this to reflect updates since the initial push - there was a performance inconsistency in the benchmark code which I've since fixed)

IMO the ~15% hit is worth the extra field.

@francislavoie
Copy link
Member

Related to #5336

francislavoie
francislavoie reviewed Apr 23, 2023
View reviewed changes
@francislavoie francislavoie added feature ⚙️ New feature or request discussion 💬 The right solution needs to be found labels Apr 23, 2023
@francislavoie francislavoie added this to the v2.7.0 milestone Apr 23, 2023
@hairyhenderson hairyhenderson marked this pull request as ready for review April 23, 2023 17:33
@francislavoie
Copy link
Member

I decided to piggy-back off this PR for #5336.

I don't love this though. This is kinda going into #4649 territory, we're doing allocations for the logging. We could use a sync.Pool for ExtraLogFields but idk 🤔 pooling isn't perfect, long-running requests/connections like websockets will hold onto them for a long time etc. We can throw away my commits if the approach doesn't make sense.

I probably want to move user_id to only log if non-empty (as an extra field essentially), and later on we might want user-configurable extra log fields for things like http.request.uuid or whatever.

mholt
mholt approved these changes Apr 24, 2023
View reviewed changes
Copy link
Member

@mholt mholt left a comment

Choose a reason for hiding this comment

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

Thanks for taking care on this one, to ensure the proper perspective on the variables is captured (since passing arguments into a defer'ed function evaluates the arguments right away, as opposed to later).

Also the benchmarks are really appreciated 😁

And the refactor + tests too!

The very minor performance penalty is only when tracing is enabled, yeah?

Either way, LGTM. Happy to include this in the 2.7 beta. Thank you!

mholt
mholt reviewed Apr 24, 2023
View reviewed changes
mholt
mholt reviewed Apr 24, 2023
View reviewed changes
modules/caddyhttp/server.go Outdated

// preallocate with the amount of known fields
fieldCount := 6
fields := make([]zapcore.Field, fieldCount+len(extra.fields))
Copy link
Member

Choose a reason for hiding this comment

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

As discussed with Francis in Slack, these can be pooled. Doesn't have to happen in this PR, but it would reduce allocations over time as the slices will get reused.

@francislavoie francislavoie enabled auto-merge (squash) April 27, 2023 02:36
@francislavoie francislavoie mentioned this pull request Apr 27, 2023
Closed
@francislavoie francislavoie merged commit f0e3981 into caddyserver:master Apr 27, 2023
@hairyhenderson hairyhenderson deleted the log-traceID branch April 27, 2023 20:50
@YifanYang6 YifanYang6 mentioned this pull request Oct 19, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@francislavoie francislavoie francislavoie left review comments

@mholt mholt mholt approved these changes

Assignees
No one assigned
Labels
discussion 💬 The right solution needs to be found feature ⚙️ New feature or request
Projects
None yet
Milestone
v2.7.0
Development

Successfully merging this pull request may close these issues.
3 participants
@hairyhenderson @francislavoie @mholt