tracing: Add spanID field to access logs and http.vars.span_id placeholder

[YifanYang6]

In PR #5507, the traceid was added to the logs. To further align with the OpenTelemetry Log Correlation specification and achieve complete log correlation using trace context, we have now included the spanid alongside the traceid.

Benchmark Comparison

I conducted benchmarks to assess the performance impact of adding the spanid. Since traceid and spanid are always used together, I modified the existing benchmarks for traceid to include spanid. Below is the performance comparison before and after adding the spanid:

Before:

$ go test -benchtime=3s -count=10 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee before.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor               
BenchmarkServer_LogRequest-64                    3140806              1174 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3026678              1161 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3103068              1156 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3121268              1152 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3098882              1163 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3171706              1147 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3098536              1128 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3198552              1143 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3118201              1159 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3211209              1151 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27751924               127.9 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28101333               125.2 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28519773               124.9 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27652406               126.6 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28332801               124.6 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28507286               125.0 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28651822               126.3 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28575466               130.1 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28702560               128.1 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28392454               125.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2870023              1248 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2934045              1239 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2897414              1240 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2886142              1240 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2973252              1241 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2958910              1214 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2922925              1219 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2962358              1230 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2883412              1225 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          3014709              1151 ns/op             484 B/op          4 allocs/op
PASS
ok      github.com/caddyserver/caddy/v2/modules/caddyhttp       133.403s
  

After:

$ go test -benchtime=3s -count=10 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee after.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor               
BenchmarkServer_LogRequest-64                    3152115              1158 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3094155              1143 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3174631              1132 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3161185              1133 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3190516              1136 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3090571              1154 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3119666              1153 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3145326              1144 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3134314              1135 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3138734              1136 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28379570               133.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28388329               134.3 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28012402               124.0 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28187100               126.3 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28356514               125.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         26432298               125.4 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27307333               124.9 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27985292               133.6 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28657483               132.7 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28491796               124.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2783799              1273 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2767974              1324 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2786803              1295 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2805546              1269 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2816472              1287 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2801752              1299 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2732166              1316 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2740275              1316 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2766216              1293 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2706841              1348 ns/op             548 B/op          4 allocs/op
PASS
ok      github.com/caddyserver/caddy/v2/modules/caddyhttp       134.236s
  

Diff:

$ benchstat before.txt after.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor               
                               │ before.txt  │             after.txt              │
                               │   sec/op    │   sec/op     vs base               │
Server_LogRequest-64             1.154µ ± 1%   1.140µ ± 1%       ~ (p=0.055 n=10)
Server_LogRequest_NopLogger-64   125.9n ± 2%   125.9n ± 6%       ~ (p=0.698 n=10)
Server_LogRequest_WithTrace-64   1.235µ ± 2%   1.297µ ± 2%  +5.06% (p=0.000 n=10)
geomean                          564.0n        570.9n       +1.23%

                               │ before.txt │              after.txt               │
                               │    B/op    │    B/op     vs base                  │
Server_LogRequest-64             419.0 ± 0%   419.0 ± 0%        ~ (p=1.000 n=10) ¹
Server_LogRequest_NopLogger-64   8.000 ± 0%   8.000 ± 0%        ~ (p=1.000 n=10) ¹
Server_LogRequest_WithTrace-64   484.0 ± 0%   548.0 ± 0%  +13.22% (p=0.000 n=10)
geomean                          117.5        122.5        +4.23%
¹ all samples are equal

                               │ before.txt │              after.txt              │
                               │ allocs/op  │ allocs/op   vs base                 │
Server_LogRequest-64             4.000 ± 0%   4.000 ± 0%       ~ (p=1.000 n=10) ¹
Server_LogRequest_NopLogger-64   1.000 ± 0%   1.000 ± 0%       ~ (p=1.000 n=10) ¹
Server_LogRequest_WithTrace-64   4.000 ± 0%   4.000 ± 0%       ~ (p=1.000 n=10) ¹
geomean                          2.520        2.520       +0.00%
¹ all samples are equal

The addition of spanid to the logs led to a slight increase (~5%) in processing time. Memory usage increased in ~13%, as expected.

I also added the http.vars.span_id placeholder, similar to what was done in PR #6308 for the http.vars.trace_id placeholder.

[YifanYang6]

If needed, I can also update the related documentation for these changes in the Caddy website.

[mholt]

Thanks for the PR!

Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?

[YifanYang6]

Thanks for the PR!

Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?

That's correct. The performance impact occurs only when tracing is enabled, as both traceid and spanid are added to the logs only in that scenario.

However, it seemed that my previous benchmarks showed some impact even when tracing wasn't enabled. I reran the benchmarks several times, and the new results confirm that the performance is affected only when spanid is being added. The slight (~3%) increase in runtime observed earlier was likely just measurement noise.

I've also updated the previous benchmark results.

[hairyhenderson]

Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?

yes if you mean s/metrics/tracing/ - this is (or, should be) orthogonal to metrics

[digitaltim-de]

No docs for that... I want to use custom tags, any idea how i can send via caddy custom tags to the tracing?

For example i am using this:

    route {
        @traceable {
            not path /build/* /images/* /favicon-32x32.png
        }

        handle @traceable {
            tracing {
                span "[{http.request.method}] {http.request.uri.path}"
               ##here i want add custom tags for sending to the tracing tool jaeger
            }
        }
       
        push
        php_fastcgi php:9000
        encode zstd gzip
        file_server
    }

    ```

    
    I want add tags(); for the tracing any idea how i can do it?

[francislavoie]

All this does is add the span ID to the logs automatically, when tracing is enabled. That's it. There's not really anything to document.

Tagging is a totally different topic, it's not currently a supported feature.