Day 120 — Logging & Recovery Interceptors

Month 5 · Week 2 · ⬅ Day 119 · Day 121 ➡ · Journal index

🎯 Learning Objective

Write unary server interceptors for structured request logging and panic recovery, and chain them in the right order.

📚 Topics

• grpc.UnaryServerInterceptor signature and the UnaryHandler it wraps
• grpc.ChainUnaryInterceptor ordering (outermost-first)
• Panic recovery with defer/recover and named return values

📖 Reading / Sources

• gRPC-Go — Interceptor docs
• gRPC-Go interceptor example
• go-grpc-middleware recovery
• Effective Go — defer/recover

📝 Notes

• A gRPC interceptor is middleware: func(ctx, req, *UnaryServerInfo, UnaryHandler) (resp, error). It receives the next handler and decides when (or whether) to call it — the same shape as net/http middleware → [[interceptors]] [[middleware]].
• Register one with grpc.NewServer(grpc.UnaryInterceptor(ic)). For many, use grpc.ChainUnaryInterceptor(a, b, c): a is outermost — it runs first on the way in and last on the way out (the onion model) → [[chain-order]].
• Logging interceptor = do work before handler (capture time.Now()), call it, do work after (log info.FullMethod, latency, status.Code(err)). The before/after split is the whole reason middleware exists → [[observability]].
• Recovery interceptor must use named returns ((resp any, err error)): the deferred closure runs during stack unwinding and assigns err, which only works if the function declares the return variable → [[panic-recovery]] [[named-returns]].
• Convert a recovered panic into a clean status.Errorf(codes.Internal, ...) — never leak the stack to the client; log it server-side instead. A panic in one RPC must not crash the whole process.
• Order matters: put recovery innermost-but-one so it catches handler panics, and logging outermost so it still logs the recovered error. Metrics/tracing usually wrap logging.
• Streaming RPCs use the parallel StreamServerInterceptor + ChainStreamInterceptor; same idea, the handler gets a ServerStream instead of req.

💻 Code Examples

// Recovery interceptor: named returns let the deferred recover set err.
func Recovery(l *slog.Logger) grpc.UnaryServerInterceptor {
    return func(ctx context.Context, req any, info *grpc.UnaryServerInfo,
        handler grpc.UnaryHandler) (resp any, err error) {
        defer func() {
            if r := recover(); r != nil {
                l.Error("panic recovered", "method", info.FullMethod, "panic", r)
                err = status.Errorf(codes.Internal, "internal error")
            }
        }()
        return handler(ctx, req) // any panic below unwinds into the defer
    }
}

srv := grpc.NewServer(grpc.ChainUnaryInterceptor(Logging(log), Recovery(log)))

Stdlib rebuild of the chain (no grpc needed): examples/month-05/interceptors/main.go · Run: go run ./examples/month-05/interceptors

🏋️ Exercises / Practice

Exercise	Status	Link
Chain(...Interceptor) with correct nesting order	✅	exercises/month-05/week-2/chain
Short-circuit (interceptor that doesn't call next)	✅	exercises/month-05/week-2/chain

🐛 Mistakes Made

• Wrote the recovery interceptor with unnamed returns, then recover() had nowhere to put the error → the panic still propagated. Switched to (resp any, err error).
• Logged latency unconditionally before handler returned — meaningless. The time.Since must come after the call.

❓ Open Questions

• Where should request-scoped trace IDs be generated — a dedicated interceptor, or inside the logging one? (Leaning: separate, outermost.)

🧠 Active Recall (answer without looking)

1. Q: In ChainUnaryInterceptor(a, b, c), which interceptor sees the request first?

A

`a` — the first argument is the outermost layer; it runs first inbound and last outbound, with `c` closest to the handler.

1. Q: Why must a recovery interceptor use named return values?

A

The deferred `recover()` runs while the stack unwinds; it can only set the function's `err`/`resp` if they're declared as named returns. With unnamed returns there's no variable to assign, so the panic keeps propagating.

🪶 Feynman Reflection

An interceptor is a wrapper around the real RPC handler. Stack several and you get an onion: the request travels inward through each layer, hits the handler, and the response travels back out through the same layers in reverse. Logging is the outer skin (it sees everything); recovery sits just inside it so it can catch a panic and hand back a tidy error instead of a crash.

🕳️ Knowledge Gaps

• Streaming interceptors and how to wrap ServerStream to intercept individual messages.

✅ Summary

I can write logging and recovery unary interceptors, reason about chain order, and explain why recovery needs named returns.

⏭️ Next Steps / Prep for Tomorrow

• Day 121: auth interceptors — pulling bearer tokens out of metadata.

---

Time spent	Difficulty	Confidence
90 min	🟦🟦⬜⬜⬜	🟦🟦🟦⬜⬜

Suggested commit: feat(examples): unary interceptor chain — logging & recovery (day 120)