Kinoko's TIL Log

Error & Log by Middleware

The Point

Each request produces exactly one log entry, handled by middleware. Errors are only wrapped at boundaries with third-party code. Logging follows the OpenTelemetry standard so logs can plug into any observability backend.

Explanation

Four core principles

1. Every request gets exactly one log

Instead of logging in every handler or function, middleware outputs a single structured log entry when the request completes, containing status code, latency, request ID, and other fields. This avoids scattered log entries for the same request that are hard to correlate.

2. Log should be wrapped in a proper way

Logs should be structured (structured logging) – not fmt.Println("error:", err), but a format with fields:

1{
2  "level": "error",
3  "request_id": "abc-123",
4  "method": "POST",
5  "path": "/orders",
6  "latency_ms": 42,
7  "error": "calling payment sdk: connection refused"
8}

3. Only wrap errors on boundaries with 3rd party code

A boundary is the seam between your code and a system you do not own – calling a DB, calling a third-party SDK, calling an external API are all boundaries.

Errors from third parties lack your context, so wrap once at the boundary. Between internal functions, just pass the error up.

Given the chain: Handler -> getOrder() -> queryOrderFromDB():

 1// Layer 3: DB boundary, the only place to wrap
 2func queryOrderFromDB(ctx context.Context, id int) (*Order, error) {
 3    row, err := db.Query(ctx, "SELECT * FROM orders WHERE id = ?", id)
 4    if err != nil {
 5        // Wrap at the boundary, describe what operation was happening
 6        return nil, fmt.Errorf("querying order id=%d: %w", id, err)
 7    }
 8    // ...
 9}
10
11// Layer 2: internal function, pass up directly, do not re-wrap
12func getOrder(ctx context.Context, id int) (*Order, error) {
13    order, err := queryOrderFromDB(ctx, id)
14    if err != nil {
15        // Just return, no new wrap
16        return nil, err
17    }
18    return order, nil
19}
20
21// Layer 1: handler, also does not wrap -- let middleware handle the log
22func handleGetOrder(w http.ResponseWriter, r *http.Request) {
23    order, err := getOrder(r.Context(), id)
24    if err != nil {
25        // Hand off to middleware, do not log here
26        http.Error(w, "internal error", http.StatusInternalServerError)
27        return
28    }
29    // ...
30}

If every layer wraps, the error message becomes:

handleGetOrder: getOrder: queryOrderFromDB: querying order id=42: connection refused

The repeated function names add no new information – just noise.

Wrapping only at the boundary is much clearer:

querying order id=42: connection refused

The rule: wrap = add new information. No new information, just return err.

4. OTEL compliant logging in middleware

OTEL = OpenTelemetry, the CNCF observability standard that defines a unified format and API for traces, metrics, and logs.

When middleware outputs OTEL-compliant logs, you can plug into any backend (Grafana, Datadog, GCP Cloud Logging) without changing application code.

Request → Middleware (start timer, inject trace context)
           ↓
         Handler (process logic, pass errors up)
           ↓
         Middleware (at the end, log one entry with status / latency / error)

Knowledge Sugar

Why not let each handler log on its own?

Problems with scattered logging:

Middleware-centralized logging means: one request = one log entry = one trace. Searching and debugging become much more intuitive.

Error wrap decision guide

LocationWrap?Reason
Calling DB / third-party SDKYesTheir errors lack your context
Calling another internal serviceUsually yesCross-service boundary
Passing between internal functionsNoJust stacks messages with no new information

#go #observability #til

← Back to Main Page