Logging Patterns

Logging Patterns

Structured Logging (JSON)

{
  "timestamp": "2024-01-15T10:30:00.123Z",
  "level": "info",
  "service": "order-service",
  "version": "1.2.3",
  "trace_id": "abc123def456",
  "span_id": "789xyz",
  "user_id": "usr_98765",
  "message": "Order created",
  "order_id": "ord_11111",
  "amount_cents": 4999,
  "duration_ms": 42
}

Log Levels — When to Use

ERROR   — unexpected failures requiring immediate attention (5xx, panic)
WARN    — recoverable issues, degraded operation (retry succeeded, circuit open)
INFO    — significant business events (order placed, user registered, job completed)
DEBUG   — detailed diagnostic info (disabled in production by default)
TRACE   — extremely verbose (request/response bodies, SQL queries)

Go Structured Logging (slog)

import "log/slog"

logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
    Level: slog.LevelInfo,
})).With(
    "service", "order-service",
    "version", os.Getenv("APP_VERSION"),
)

// With request context
reqLogger := logger.With(
    "trace_id", r.Header.Get("X-Trace-ID"),
    "user_id",  userID,
)
reqLogger.Info("order created",
    "order_id",    order.ID,
    "amount_cents", order.AmountCents,
    "duration_ms",  time.Since(start).Milliseconds(),
)
reqLogger.Error("payment failed",
    "error", err,
    "order_id", order.ID,
)

Fluent Bit Config (Kubernetes → Loki)

[SERVICE]
    Flush         5
    Log_Level     info
    Parsers_File  parsers.conf

[INPUT]
    Name              tail
    Path              /var/log/containers/*.log
    multiline.parser  docker, cri
    Tag               kube.*
    Mem_Buf_Limit     5MB

[FILTER]
    Name                kubernetes
    Match               kube.*
    Kube_URL            https://kubernetes.default.svc
    Merge_Log           On
    Keep_Log            Off
    K8S-Logging.Parser  On

[OUTPUT]
    Name            loki
    Match           kube.*
    Host            loki.monitoring.svc.cluster.local
    Port            3100
    Labels          job=fluentbit, namespace=$kubernetes['namespace_name'], pod=$kubernetes['pod_name']
    line_format     json

Correlation ID Middleware

import uuid
from contextvars import ContextVar

trace_id_var: ContextVar[str] = ContextVar("trace_id", default="")

class TraceMiddleware:
    async def __call__(self, scope, receive, send):
        trace_id = scope["headers"].get(b"x-trace-id", b"").decode() or str(uuid.uuid4())
        trace_id_var.set(trace_id)
        # Add to response headers
        await self.app(scope, receive, send)

# In logger:
import structlog
structlog.configure(processors=[
    structlog.contextvars.merge_contextvars,
    structlog.processors.JSONRenderer(),
])
log = structlog.get_logger()
log.info("request processed", duration_ms=42)  # trace_id auto-included

Log Sampling (high-traffic services)

// Log 100% of errors, 1% of debug
sampler := zap.NewSamplerWithOptions(
    core,
    time.Second,
    100,   // first 100 per second: log all
    10,    // after that: log every 10th
)

Key Rules

• Log at application boundaries: incoming requests, outgoing calls, job start/end
• Never log passwords, tokens, PII — scrub before writing
• Include trace_id in every log line for distributed tracing correlation
• Use duration_ms not duration — unit ambiguity costs hours during incidents
• Ship logs async; never let logging block the request path