Adding trace id to access log with rs/zerolog

This is an code based on opentelemetry dice example which uses rs/zerolog and adds trace id to logs.

Working code example can be found on GitHub

TraceIDHandler

This is a standard access logger. What is extra here is

traceID := traceIDHandler("trace_id", "span_id")

traceIDHandler adds those two fields to zerolog if it finds them in context.

func requestLogger(next http.Handler) http.Handler {
	h := hlog.NewHandler(logger)
	accessHandler := hlog.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) {
		hlog.FromRequest(r).Info().
			Str("method", r.Method).
			Stringer("url", r.URL).
			Int("status", status).
			Int("size", size).
			Dur("duration", duration).
			Msg("access log")
	})
	addr := hlog.RemoteAddrHandler("ip")
	userAgent := hlog.UserAgentHandler("user_agent")
	traceID := traceIDHandler("trace_id", "span_id")
	requestID := hlog.RequestIDHandler("req_id", "X-Request-Id")

	return h(addr(userAgent(traceID(requestID(accessHandler(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		next.ServeHTTP(w, r)
	})))))))
}

func traceIDHandler(traceFieldKey, spanFieldKey string) func(next http.Handler) http.Handler {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			spanContext := trace.SpanFromContext(r.Context()).SpanContext()
			traceID := spanContext.TraceID().String()
			spanID := spanContext.SpanID().String()
			if traceID != "" {
				l := zerolog.Ctx(r.Context())
				l.UpdateContext(func(c zerolog.Context) zerolog.Context {
					return c.Str(traceFieldKey, traceID)
				})
			}
			if spanID != "" {
				l := zerolog.Ctx(r.Context())
				l.UpdateContext(func(c zerolog.Context) zerolog.Context {
					return c.Str(spanFieldKey, spanID)
				})
			}
			next.ServeHTTP(w, r)
		})
	}
}

Adding requestLogger middleware

To have access logger working, we need to change

handler := otelhttp.NewHandler(mux, "/")

to

handler := otelhttp.NewHandler(requestLogger(mux), "/")

Contextual logging in HTTP handler

To have proper tracing ids in logs, we need to pass context. In func rolldice

//...
roll := 1 + rand.Intn(6)

rollValueAttr := attribute.Int("roll.value", roll)
span.SetAttributes(rollValueAttr)
rollCnt.Add(ctx, 1, metric.WithAttributes(rollValueAttr))

l := zerolog.Ctx(ctx)
l.Info().Ctx(ctx).Int("value", roll).Msg("roll")
//...

Testing

We can test our endpoint with curl. In response we are getting X-Request-Id.

$ curl -v 127.0.0.1:8888/rolldice
*   Trying 127.0.0.1:8888...
* Connected to 127.0.0.1 (127.0.0.1) port 8888 (#0)
> GET /rolldice HTTP/1.1
> Host: 127.0.0.1:8888
> User-Agent: curl/8.1.2
> Accept: */*
>
< HTTP/1.1 200 OK
< X-Request-Id: co0totvnl535vf6rnob0
< Date: Sun, 25 Feb 2024 22:14:57 GMT
< Content-Length: 2
< Content-Type: text/plain; charset=utf-8
<
6
* Connection #0 to host 127.0.0.1 left intact

In server logs there are more information. We can see that our request have trace id 5fdc14f10cb4c2d1f253f853c16162e7. Both log messages share the same trace id.

 go run .
// first log "roll"
{"level":"info","ip":"127.0.0.1:59065","user_agent":"curl/8.1.2","trace_id":"5fdc14f10cb4c2d1f253f853c16162e7","span_id":"47e1ebf518ef9e7d","req_id":"co0totvnl535vf6rnob0","value":6,"time":"2024-03-25T21:20:07+01:00","message":"roll"}
// access log, both have same trace id
{"level":"info","ip":"127.0.0.1:59065","user_agent":"curl/8.1.2","trace_id":"5fdc14f10cb4c2d1f253f853c16162e7","span_id":"47e1ebf518ef9e7d","req_id":"co0totvnl535vf6rnob0","method":"GET","url":"/rolldice","status":200,"size":2,"duration":1.260792,"time":"2024-03-25T21:20:07+01:00","message":"access log"}

{
        "Name": "roll",
        "SpanContext": {
                "TraceID": "5fdc14f10cb4c2d1f253f853c16162e7",
                "SpanID": "7f39c00b122c6044",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "Parent": {
                "TraceID": "5fdc14f10cb4c2d1f253f853c16162e7",
                "SpanID": "47e1ebf518ef9e7d",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "SpanKind": 1,
        "StartTime": "2024-03-25T21:20:07.035488+01:00",
        "EndTime": "2024-03-25T21:20:07.036643458+01:00",
        "Attributes": [
                {
                        "Key": "roll.value",
                        "Value": {
                                "Type": "INT64",
                                "Value": 6
                        }
                }
        ],
        "Events": null,
        "Links": null,
        "Status": {
                "Code": "Unset",
                "Description": ""
        },
        "DroppedAttributes": 0,
        "DroppedEvents": 0,
        "DroppedLinks": 0,
        "ChildSpanCount": 0,
        "Resource": [
                {
                        "Key": "service.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "unknown_service:___go_build_zerolog_traceid"
                        }
                },
                {
                        "Key": "telemetry.sdk.language",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go"
                        }
                },
                {
                        "Key": "telemetry.sdk.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "opentelemetry"
                        }
                },
                {
                        "Key": "telemetry.sdk.version",
                        "Value": {
                                "Type": "STRING",
                                "Value": "1.24.0"
                        }
                }
        ],
        "InstrumentationLibrary": {
                "Name": "rolldice",
                "Version": "",
                "SchemaURL": ""
        }
}
{
        "Name": "/",
        "SpanContext": {
                "TraceID": "5fdc14f10cb4c2d1f253f853c16162e7",
                "SpanID": "47e1ebf518ef9e7d",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "Parent": {
                "TraceID": "00000000000000000000000000000000",
                "SpanID": "0000000000000000",
                "TraceFlags": "00",
                "TraceState": "",
                "Remote": false
        },
        "SpanKind": 2,
        "StartTime": "2024-03-25T21:20:07.035326+01:00",
        "EndTime": "2024-03-25T21:20:07.036709792+01:00",
        "Attributes": [
                {
                        "Key": "http.method",
                        "Value": {
                                "Type": "STRING",
                                "Value": "GET"
                        }
                },
                {
                        "Key": "http.scheme",
                        "Value": {
                                "Type": "STRING",
                                "Value": "http"
                        }
                },
                {
                        "Key": "net.host.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "127.0.0.1"
                        }
                },
                {
                        "Key": "net.host.port",
                        "Value": {
                                "Type": "INT64",
                                "Value": 8888
                        }
                },
                {
                        "Key": "net.sock.peer.addr",
                        "Value": {
                                "Type": "STRING",
                                "Value": "127.0.0.1"
                        }
                },
                {
                        "Key": "net.sock.peer.port",
                        "Value": {
                                "Type": "INT64",
                                "Value": 59065
                        }
                },
                {
                        "Key": "user_agent.original",
                        "Value": {
                                "Type": "STRING",
                                "Value": "curl/8.1.2"
                        }
                },
                {
                        "Key": "http.target",
                        "Value": {
                                "Type": "STRING",
                                "Value": "/rolldice"
                        }
                },
                {
                        "Key": "net.protocol.version",
                        "Value": {
                                "Type": "STRING",
                                "Value": "1.1"
                        }
                },
                {
                        "Key": "http.route",
                        "Value": {
                                "Type": "STRING",
                                "Value": "/rolldice"
                        }
                },
                {
                        "Key": "http.wrote_bytes",
                        "Value": {
                                "Type": "INT64",
                                "Value": 2
                        }
                },
                {
                        "Key": "http.status_code",
                        "Value": {
                                "Type": "INT64",
                                "Value": 200
                        }
                }
        ],
        "Events": null,
        "Links": null,
        "Status": {
                "Code": "Unset",
                "Description": ""
        },
        "DroppedAttributes": 0,
        "DroppedEvents": 0,
        "DroppedLinks": 0,
        "ChildSpanCount": 1,
        "Resource": [
                {
                        "Key": "service.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "unknown_service:___go_build_zerolog_traceid"
                        }
                },
                {
                        "Key": "telemetry.sdk.language",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go"
                        }
                },
                {
                        "Key": "telemetry.sdk.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "opentelemetry"
                        }
                },
                {
                        "Key": "telemetry.sdk.version",
                        "Value": {
                                "Type": "STRING",
                                "Value": "1.24.0"
                        }
                }
        ],
        "InstrumentationLibrary": {
                "Name": "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp",
                "Version": "0.49.0",
                "SchemaURL": ""
        }
}

Resources