skip to content

Distributed Tracing Hooks

The three places a Go program touches a trace: the context value carrying the current span, the headers on an outbound request, and the log record that must name the same request.

part ofGo (Golang)overview, primer and where to startread it →
on this pageshow

explore

questions

11

How do you write a slog.Handler that adds a run id from the context to every record?

level: middleimportance: must knowfreq 60%

answer

  1. the handler is the single install point
  2. Handle receives more than the record
  3. wrap the real handler, delegate down
  4. AddAttrs, then call the inner handler
  5. re-wrap in WithAttrs or lose it

basics

~20 s

Wrap another slog.Handler. In Handle(ctx, record), look the run id up with ctx.Value, attach it with Record.AddAttrs, then call the wrapped handler's Handle. Callers must use the Context-taking log methods for the id to arrive.

solid answer

~40 s

`slog.Handler` has four methods: `Enabled(ctx, level)`, `Handle(ctx, record)`, `WithAttrs`, `WithGroup`. I write a small type holding an inner handler and implement `Handle` to read the id out of the context — `ctx.Value(runKey{})`, keyed by an unexported type — add it with `r.AddAttrs(slog.String("run_id", id))`, and delegate to the inner handler. `Enabled` forwards straight through; `WithAttrs` and `WithGroup` must return my wrapper around the inner handler's result, otherwise a derived logger silently loses the stamping. I install it once with `slog.New(myHandler)` and, if the codebase logs through the package default, `slog.SetDefault`. The value in the context is set at the top of the run, and from then on every `InfoContext`/`ErrorContext` call in that call tree correlates without threading an id parameter through every function.

code

go · 26 lines
go
type runKey struct{}

func WithRunID(ctx context.Context, id string) context.Context {
	return context.WithValue(ctx, runKey{}, id)
}

type runHandler struct{ inner slog.Handler }

func (h runHandler) Enabled(ctx context.Context, l slog.Level) bool {
	return h.inner.Enabled(ctx, l)
}

func (h runHandler) Handle(ctx context.Context, r slog.Record) error {
	if id, ok := ctx.Value(runKey{}).(string); ok {
		r.AddAttrs(slog.String("run_id", id))
	}
	return h.inner.Handle(ctx, r)
}

func (h runHandler) WithAttrs(as []slog.Attr) slog.Handler {
	return runHandler{h.inner.WithAttrs(as)}
}

func (h runHandler) WithGroup(name string) slog.Handler {
	return runHandler{h.inner.WithGroup(name)}
}

go deeper

for a junior

Know that the handler, not the log call, is where a run id gets attached, and that the record's fields come from an interface method called Handle that receives a context.

for a middle

Be able to write the wrapper live: the four interface methods, the comma-ok lookup, AddAttrs, delegation to the inner handler, and re-wrapping in WithAttrs and WithGroup.

for a senior

Talk about the silent failure modes — a dropped wrapper, a call site using the non-context method — and the test that catches each before an incident does.

for a principal

Own the convention: one handler installed at the process root, a fixed set of identity fields, and a clear rule on what may ride in the context versus what stays an explicit parameter.

## The shape of the problem A migration tool walks a table in batches. Every line it emits over the next two hours belongs to one run, and a support engineer chasing one customer's run through a day of output needs a `run_id` on all of them. Threading a `runID string` parameter into every function that might log is invasive and gets forgotten. The standard answer in `log/slog` is to put the identity in the `context.Context` once and have the *handler* stamp it. ## The Handler interface ```go type Handler interface { Enabled(context.Context, Level) bool Handle(context.Context, Record) error WithAttrs(attrs []Attr) Handler WithGroup(name string) Handler } ``` Two of those methods receive a context, and `Handle` is the one that matters here: it is called with the context the caller passed to `InfoContext`, `ErrorContext` or `Logger.Log`, and it is handed the `slog.Record` about to be written. ## The wrapper The idiom is a decorator over a real handler: ```go type runKey struct{} type runHandler struct{ inner slog.Handler } func (h runHandler) Handle(ctx context.Context, r slog.Record) error { if id, ok := ctx.Value(runKey{}).(string); ok { r.AddAttrs(slog.String("run_id", id)) } return h.inner.Handle(ctx, r) } ``` Points worth stating in an interview: - **The comma-ok assertion is not optional.** Plenty of log lines will be emitted from contexts that never carried a run id — startup, shutdown, tests. A bare `.(string)` assertion panics on those. - **`Record.AddAttrs` appends to the record you were given.** If your handler fans the same record out to more than one destination, take `r = r.Clone()` first so the copies do not share attribute storage. - **Forward, do not swallow.** `Handle` must call the inner handler; it is the thing that actually formats and writes. ## The three methods people forget `Enabled` is a straight delegation: `return h.inner.Enabled(ctx, l)`. `WithAttrs` and `WithGroup` are the trap. It is tempting to embed `slog.Handler` in the struct and let the promoted methods handle those two — but the promoted `WithAttrs` returns the *inner* handler, so any logger derived from yours drops the wrapper and quietly stops stamping run ids. Implement both to re-wrap: ```go func (h runHandler) WithAttrs(as []slog.Attr) slog.Handler { return runHandler{h.inner.WithAttrs(as)} } ``` This is the single most common defect in hand-rolled context handlers, and it fails silently: the lines still appear, the field is just missing on some of them. ## Installing it and feeding it ```go h := runHandler{inner: slog.NewJSONHandler(os.Stdout, nil)} slog.SetDefault(slog.New(h)) ``` `slog.New` builds a `*slog.Logger` over the handler; `slog.SetDefault` makes the package-level `slog.InfoContext` shorthand use it too, which matters in a codebase where not every component is handed a logger. The other half is the context. At the top of the run you derive one context that carries the id and pass it down: ```go ctx = context.WithValue(ctx, runKey{}, id) ``` From then on the obligation on call sites is exactly one thing: use the Context-taking log methods. `logger.Info("...")` gets `context.Background()` and comes out unstamped no matter how good your handler is. ## What belongs in the context, and what does not Keep the context value small and identity-shaped: a run id, a batch number, a customer id, a request id. It is data other things want too — an error message, a metric label, the id you print to the operator at the end. Do not push whole subsystems through it. ## Testing it The handler is easy to test without a running service: build one over `slog.NewJSONHandler` writing into a `bytes.Buffer`, log once with a context carrying an id and once with `context.Background()`, and assert the field is present in the first line and absent from the second. Add a case that derives a logger through `WithAttrs` and logs again — that is the case that catches the dropped-wrapper bug, and it is the one people leave out.

  • What breaks if you embed slog.Handler in the wrapper struct instead of implementing WithAttrs and WithGroup?
    The promoted `WithAttrs`/`WithGroup` return the *inner* handler, not your wrapper. Any logger derived from the original keeps logging, but silently stops stamping the run id, so you get a mix of correlated and uncorrelated lines from the same process. Implement both methods and re-wrap the inner handler's result.
  • A helper deep in the call chain logs without the run's context. What can the handler do about it?
    Nothing. The handler can only read the context it is handed, so a call using `Info` or one that was passed a fresh `context.Background()` produces an unstamped line. The fix is upstream: thread the run's context into that helper as its first parameter and log with the Context-taking methods.
  • Does the handler get the context when the level is being tested, not just when a record is written?
    Yes. `Handler.Enabled(ctx, level)` also receives it, so a handler can make an admission decision per context — for example letting one flagged run through at debug while everything else stays at info. Keep that logic cheap: `Enabled` runs for every candidate line.

saying these in an interview costs you the question

  • Uses a bare type assertion on the context value and panics when absent
  • Embeds the handler and never re-wraps in WithAttrs
  • Formats the id into the message string instead of an attribute
  • Expects the id to appear on plain Info calls too
  • Puts a whole request object in the context for the handler to read
open as a page

Why build an outbound call with http.NewRequestWithContext instead of http.NewRequest?

level: middleimportance: must knowfreq 72%

basics

~10 s

http.NewRequest gives the request context.Background(), so the outbound call ignores the caller's deadline and cancellation and carries none of the per-request state your code keeps in a context.Context. NewRequestWithContext attaches the caller's context instead.

open as a page

In Go's log/slog, what does Logger.InfoContext give you that Logger.Info does not?

level: juniorimportance: should knowfreq 55%

basics

~10 s

Logger.InfoContext passes your context.Context down to the handler's Handle method, so the handler can read request-scoped data such as a run id out of it. Logger.Info passes context.Background() instead, so that data never arrives.

open as a page

How do you attach an X-Trace-Id header to an outbound *http.Request, and how does Header.Set differ from Header.Add?

level: juniorimportance: should knowfreq 60%

basics

~20 s

Build the request, then call req.Header.Set("X-Trace-Id", id) before sending it. Set replaces every value already stored under that key; Add appends another value and keeps the earlier ones. Both store the key in canonical form.

open as a page

Why should a request's tracing span be carried in context.Context rather than stored in a struct field?

level: juniorimportance: should knowfreq 48%

basics

~20 s

A span belongs to one request, but a service struct is shared by every concurrent request, so a field is raced on and overwritten. context.Context is per request and flows down to exactly that request's callees.

open as a page

Why does reading req.Header["x-trace-id"] give nil when the client really did send that header?

level: middleimportance: should knowfreq 48%

basics

~20 s

Indexing an http.Header is an ordinary case-sensitive Go map lookup. net/http stores parsed header names in canonical form, so the key in the map is X-Trace-Id. Read it with r.Header.Get("x-trace-id"), which canonicalises the key for you.

open as a page

What happens to a request's tracing span when a helper calls context.Background() instead of taking the caller's ctx?

level: middleimportance: should knowfreq 40%

basics

~20 s

context.Background returns an empty root that carries no values, so the span lookup below that helper finds nothing. The work is recorded under no span, or starts a fresh unparented trace, leaving a hole in the request's timeline.

open as a page

A migration tool's batch workers log without the run id and one panics inside a log/slog call. How do you diagnose it?

level: seniorimportance: should knowfreq 45%

basics

~20 s

Both symptoms share one cause: the workers were started with a fresh context.Background(), so the handler finds no run id and a logger fetched from that context is nil. The panic's created by frame names the launch site.

open as a page

Would you put a *slog.Logger in context.Context, or put the ids there and let the handler read them?

level: seniorimportance: nice to knowfreq 35%

basics

~20 s

Prefer small identity values in the context, stamped by a slog.Handler: one install point, and every logger over that handler correlates. A logger in the context needs every call site to fetch it, and a missing one is nil.

open as a page

A newly added Go service starts a fresh trace instead of continuing the caller's X-Trace-Id. How do you find where the header is lost?

level: seniorimportance: nice to knowfreq 32%

basics

~20 s

Split the chain at the process boundary first. Log httputil.DumpRequest in the receiving handler to see which header keys arrived: if X-Trace-Id is absent there, the sender or a proxy dropped it; if present, the reading code is wrong.

open as a page

A handler detaches after-response span work with context.WithoutCancel(r.Context()); the goroutine profile shows those goroutines climbing all day. What went wrong?

level: seniorimportance: nice to knowfreq 28%

basics

~20 s

context.WithoutCancel keeps the request's values but strips its cancellation and deadline, so the detached work has no stop condition left and any stuck call parks a goroutine forever. Give the detached context its own timeout and bound how many can run.

open as a page