skip to content

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%

answer

  1. the workers lost something at the boundary
  2. read the panic trace bottom-up
  3. the created by frame names the launcher
  4. a fresh root context carries no values
  5. comma-ok discarded, nil receiver called

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.

solid answer

~50 s

The missing id and the panic are the same bug seen twice. The handler stamps `run_id` from the context, and a helper fetches a `*slog.Logger` out of the context; a goroutine launched with `context.Background()` carries neither, so `ctx.Value` returns nil, the comma-ok assertion yields a nil `*slog.Logger`, and the first method call on it dereferences a nil pointer. I read the panic's stack trace bottom-up: the last line is `created by ... in goroutine N`, which names the exact statement that started the goroutine — that is where the wrong context was handed over. The fix is two-part: pass the run's context into the worker as its first parameter instead of manufacturing a root, and make the accessor total so it returns `slog.Default()` rather than nil when the context carries no logger. Remember that panic kills the whole process, so this aborts the migration mid-run.

code

go · 5 lines
go
// bug: the worker gets a fresh root context, so the run id and logger are gone
go m.process(context.Background(), b)

// fix: hand the worker the run's context
go m.process(runCtx, b)

go deeper

for a junior

Know that a goroutine started with context.Background() gets a context with no values in it, and that a value fetched from a context that never carried it comes back as nil.

for a middle

Explain the mechanism end to end: ctx.Value returns nil, the discarded comma-ok leaves a nil pointer, and the method call on it dereferences that pointer and panics.

for a senior

Demonstrate the diagnosis: read the panic trace bottom-up to the created by frame, connect the missing field and the crash to one handover, and fix both the context passing and the accessor.

for a principal

Own the systemic answer: where root contexts may be created, whether accessors are allowed to return nil at all, and what signal tells you correlation has degraded before a customer question does.

## The symptoms A migration tool walks a table in batches. Its serial phase logs cleanly — every line carries `run_id` — and then it starts a handful of worker goroutines to process batches. From that point the output changes: the worker lines have no `run_id`, and after a few minutes the process dies with ``` panic: runtime error: invalid memory address or nil pointer dereference ``` with the top frames inside `log/slog`. Two symptoms, one cause. ## Why the id disappears Correlation here works by putting the run id in a `context.Context` at the top of the run and having a wrapping `slog.Handler` read it out in `Handle(ctx, record)`. The handler can only ever see the context that was passed to the log call. If a goroutine is launched as ```go go m.process(context.Background(), b) ``` then everything below it holds a fresh root context: no run id, no deadline, no cancellation. `ctx.Value(runKey{})` returns nil, the handler's comma-ok assertion is false, and the attribute is skipped. Nothing errors. The lines are still emitted, still at the right level — they are simply anonymous, which is exactly the batch the support engineer needs and cannot find. ## Why it panics The same codebase also stashes a `*slog.Logger` in the context and fetches it with something like ```go l, _ := ctx.Value(loggerKey{}).(*slog.Logger) l.InfoContext(ctx, "batch started") ``` On a context that never carried a logger, the comma-ok assertion does **not** panic — it yields the zero value, a nil `*slog.Logger`, and discards the false. The panic comes one line later: calling a method on that nil pointer dereferences the logger's handler field. This is the failure mode of a partial accessor combined with an ignored `ok`. ## Reading the trace A Go panic prints the stack of the panicking goroutine, most recent frame first. Read it in two passes: 1. **Top-down for the mechanism.** `runtime.gopanic`, then the `log/slog` frames, then your helper — that tells you it is a nil receiver in the logging path, not a corrupted record. 2. **Bottom-up for the origin.** The final line of a goroutine's trace is `created by <function> in goroutine N`, with the file and line of the `go` statement. That is the handover point where the wrong context was supplied — a line that appears nowhere in the top frames, because the frames of the launching goroutine are not part of this goroutine's stack. This is the single most useful line in the whole dump and the one people skip. Also note: a panic in *any* goroutine terminates the whole program. No other goroutine can recover it, and `recover` only works when called directly by a function deferred by the panicking goroutine. So this does not degrade one batch — it aborts the migration, possibly halfway through a table. ## The fix Two changes, and both are needed: - **Pass the context.** The worker takes `ctx context.Context` as its first parameter and receives the run's context at the `go` statement. Manufacturing `context.Background()` below the top of a program is the smell; the only place a root context should be created is where the run itself begins. - **Make the accessor total.** An accessor that can return nil is a landmine. Return a usable fallback instead: ```go func loggerFrom(ctx context.Context) *slog.Logger { if l, ok := ctx.Value(loggerKey{}).(*slog.Logger); ok { return l } return slog.Default() } ``` Now a lost context degrades to an uncorrelated line rather than a process-killing panic — a much better failure for a two-hour job. ## Making the class of bug visible The reason this survived review is that the degraded state is invisible in normal operation. Worth doing: a test that logs from a worker with a run context and asserts the id is present in the output; a startup line that prints the run id so support has an anchor; and, if the tool is long-lived, a check that no worker path calls `context.Background()` outside `main`. The panic was the lucky part — it is what turned a silent correlation gap into a stack trace pointing at the exact `go` statement.

  • The assertion used the comma-ok form, so why did anything panic at all?
    Because the `ok` was discarded. The comma-ok form does not panic on a failed assertion — it returns the zero value, which for `*slog.Logger` is nil. The panic happens on the next line, when a method is called on that nil pointer and the runtime dereferences it. Either check `ok` or return a fallback from a helper.
  • Only one worker panicked. Why did the whole migration stop?
    A panic that is not recovered terminates the entire process, whichever goroutine raised it. No other goroutine can recover it, and `recover` only works inside a function deferred by the panicking goroutine itself. So one bad batch takes the run down, which is why the accessor should degrade rather than return nil.
  • How would you have caught the missing run id before the panic made it obvious?
    A test that starts the worker path with a run context and asserts the emitted line carries the id catches it directly. Operationally, an ingest-side check for log lines missing the correlation field turns a silent gap into a signal, rather than waiting for a support engineer to fail to find a run.

saying these in an interview costs you the question

  • Blames the logging library rather than the context handed to the goroutine
  • Reads only the top frames and never reaches the created by line
  • Thinks a comma-ok assertion panics when the type does not match
  • Assumes a panic in one goroutine only kills that goroutine
  • Fixes it by recovering in the worker instead of passing the context