observability-structured-logging

Setting up application logging infrastructure

Structured Logging

Scope: JSON logging, log levels, correlation IDs, log aggregation, structured formats

Lines: 387

Last Updated: 2025-10-18

---

When to Use This Skill

Use this skill when:

• Setting up application logging infrastructure
• Migrating from unstructured (text) logs to structured (JSON) logs
• Implementing correlation IDs for request tracing
• Configuring log aggregation systems (ELK, Loki, CloudWatch)
• Designing log levels and filtering strategies
• Building multi-service systems requiring log correlation
• Debugging production issues requiring searchable, queryable logs
• Implementing compliance/audit logging requirements

Don't use for:

• Simple scripts with minimal logging needs
• Local development without aggregation needs (plain text is fine)

---

Core Concepts

Structured vs Unstructured Logging

Unstructured (Text):

2025-10-18 10:23:45 INFO User john@example.com logged in from 192.168.1.1

Structured (JSON):

{
  "timestamp": "2025-10-18T10:23:45.123Z",
  "level": "info",
  "message": "user_login",
  "user_email": "john@example.com",
  "ip_address": "192.168.1.1",
  "service": "auth",
  "trace_id": "a1b2c3d4e5f6"
}

Benefits of Structured Logging:

• Machine-parseable without regex
• Queryable by field (WHERE user_email = "john@example.com")
• Consistent format across services
• Easy to index and aggregate
• Type-safe fields

Log Levels

Standard hierarchy (least to most severe):

1. TRACE: Very detailed debugging (function entry/exit)
2. DEBUG: Detailed debugging information
3. INFO: General informational messages
4. WARN: Warning messages (degraded state, retries)
5. ERROR: Error messages (handled exceptions)
6. FATAL/CRITICAL: Unrecoverable errors (process crashes)

Correlation IDs

Purpose: Track requests across multiple services

Types:

• Trace ID: Unique identifier for entire request flow
• Span ID: Unique identifier for single operation within trace
• Request ID: HTTP request identifier
• Session ID: User session identifier
• User ID: User identifier

Log Aggregation

Common Stacks:

• ELK: Elasticsearch + Logstash + Kibana
• Loki: Grafana Loki (labels-based, cost-efficient)
• CloudWatch Logs: AWS native
• Datadog: Commercial SaaS
• Splunk: Enterprise log management

---

Patterns

Pattern 1: Structured Logger Setup (Python)

import logging
import json
import uuid
from datetime import datetime
from contextvars import ContextVar

# Context variable for correlation ID
correlation_id: ContextVar[str] = ContextVar('correlation_id', default=None)

class StructuredFormatter(logging.Formatter):
    """JSON formatter for structured logging."""

    def __init__(self, service_name: str, environment: str):
        super().__init__()
        self.service_name = service_name
        self.environment = environment

    def format(self, record: logging.LogRecord) -> str:
        log_data = {
            "timestamp": datetime.utcnow().isoformat() + "Z",
            "level": record.levelname.lower(),
            "message": record.getMessage(),
            "logger": record.name,
            "service": self.service_name,
            "environment": self.environment,
        }

        # Add correlation ID if present
        trace_id = correlation_id.get()
        if trace_id:
            log_data["trace_id"] = trace_id

        # Add extra fields from record
        if hasattr(record, 'extra_fields'):
            log_data.update(record.extra_fields)

        # Add exception info if present
        if record.exc_info:
            log_data["exception"] = {
                "type": record.exc_info[0].__name__,
                "message": str(record.exc_info[1]),
                "traceback": self.formatException(record.exc_info)
            }

        return json.dumps(log_data)

def setup_logging(service_name: str, environment: str, level: str = "INFO"):
    """Configure structured logging."""
    logger = logging.getLogger()
    logger.setLevel(getattr(logging, level.upper()))

    # Remove existing handlers
    logger.handlers.clear()

    # Add JSON handler
    handler = logging.StreamHandler()
    handler.setFormatter(StructuredFormatter(service_name, environment))
    logger.addHandler(handler)

    return logger

# Usage
logger = setup_logging("api-service", "production", "INFO")

def log_with_context(level: str, message: str, **kwargs):
    """Log with additional context fields."""
    log_method = getattr(logger, level)

    # Create log record with extra fields
    extra_record = logging.LogRecord(
        name=logger.name,
        level=getattr(logging, level.upper()),
        pathname="",
        lineno=0,
        msg=message,
        args=(),
        exc_info=None
    )
    extra_record.extra_fields = kwargs

    logger.handle(extra_record)

# Example usage
correlation_id.set(str(uuid.uuid4()))

log_with_context("info", "user_login",
    user_id="user_123",
    email="john@example.com",
    ip_address="192.168.1.1"
)

log_with_context("error", "payment_failed",
    user_id="user_123",
    amount=99.99,
    currency="USD",
    error_code="card_declined"
)

Pattern 2: Structured Logger Setup (Go)

package logger

import (
    "context"
    "encoding/json"
    "os"
    "time"

    "github.com/google/uuid"
)

type Level string

const (
    LevelTrace Level = "trace"
    LevelDebug Level = "debug"
    LevelInfo  Level = "info"
    LevelWarn  Level = "warn"
    LevelError Level = "error"
    LevelFatal Level = "fatal"
)

type Logger struct {
    serviceName string
    environment string
    minLevel    Level
}

type LogEntry struct {
    Timestamp   string                 `json:"timestamp"`
    Level       Level                  `json:"level"`
    Message     string                 `json:"message"`
    Service     string                 `json:"service"`
    Environment string                 `json:"environment"`
    TraceID     string                 `json:"trace_id,omitempty"`
    SpanID      string                 `json:"span_id,omitempty"`
    Fields      map[string]interface{} `json:"fields,omitempty"`
}

func New(serviceName, environment string, minLevel Level) *Logger {
    return &Logger{
        serviceName: serviceName,
        environment: environment,
        minLevel:    minLevel,
    }
}

func (l *Logger) log(ctx context.Context, level Level, message string, fields map[string]interface{}) {
    entry := LogEntry{
        Timestamp:   time.Now().UTC().Format(time.RFC3339Nano),
        Level:       level,
        Message:     message,
        Service:     l.serviceName,
        Environment: l.environment,
        Fields:      fields,
    }

    // Extract trace ID from context
    if traceID := ctx.Value("trace_id"); traceID != nil {
        entry.TraceID = traceID.(string)
    }

    if spanID := ctx.Value("span_id"); spanID != nil {
        entry.SpanID = spanID.(string)
    }

    jsonData, _ := json.Marshal(entry)
    os.Stdout.Write(append(jsonData, '\n'))
}

func (l *Logger) Info(ctx context.Context, message string, fields map[string]interface{}) {
    l.log(ctx, LevelInfo, message, fields)
}

func (l *Logger) Error(ctx context.Context, message string, fields map[string]interface{}) {
    l.log(ctx, LevelError, message, fields)
}

// Usage
func main() {
    log := logger.New("api-service", "production", logger.LevelInfo)

    ctx := context.Background()
    ctx = context.WithValue(ctx, "trace_id", uuid.New().String())

    log.Info(ctx, "user_login", map[string]interface{}{
        "user_id": "user_123",
        "email":   "john@example.com",
        "ip":      "192.168.1.1",
    })
}

Pattern 3: Correlation ID Middleware (FastAPI)

from fastapi import FastAPI, Request
from uuid import uuid4
from contextvars import ContextVar
import logging

app = FastAPI()
correlation_id_var: ContextVar[str] = ContextVar('correlation_id')

@app.middleware("http")
async def correlation_id_middleware(request: Request, call_next):
    """Add correlation ID to request context."""
    # Check for existing trace ID from upstream
    trace_id = request.headers.get("X-Trace-ID") or str(uuid4())

    # Set in context
    correlation_id_var.set(trace_id)

    # Add to response headers
    response = await call_next(request)
    response.headers["X-Trace-ID"] = trace_id

    return response

@app.get("/api/users/{user_id}")
async def get_user(user_id: str):
    trace_id = correlation_id_var.get()

    logging.info(
        "Fetching user",
        extra={
            "trace_id": trace_id,
            "user_id": user_id,
            "endpoint": "/api/users"
        }
    )

    # ... fetch user logic

    return {"user_id": user_id, "trace_id": trace_id}

Pattern 4: Log Aggregation with Loki Labels

import logging
from pythonjsonlogger import jsonlogger

class LokiFormatter(jsonlogger.JsonFormatter):
    """Formatter optimized for Grafana Loki."""

    def add_fields(self, log_record, record, message_dict):
        super(LokiFormatter, self).add_fields(log_record, record, message_dict)

        # Loki uses labels for indexing (keep cardinality low)
        log_record['service'] = 'api-service'
        log_record['environment'] = 'production'
        log_record['level'] = record.levelname.lower()

        # High-cardinality fields go in message (not labels)
        log_record['message'] = record.getMessage()
        log_record['timestamp'] = record.created

# Configure handler
handler = logging.StreamHandler()
handler.setFormatter(LokiFormatter())

logger = logging.getLogger()
logger.addHandler(handler)
logger.setLevel(logging.INFO)

# Example log
logger.info(
    "Payment processed",
    extra={
        'user_id': 'user_123',  # High cardinality - not a label
        'amount': 99.99,
        'transaction_id': 'txn_abc123'
    }
)

Pattern 5: Contextual Logger (Rust)

use serde_json::json;
use tracing::{info, error, span, Level};
use tracing_subscriber::{fmt, prelude::*};
use uuid::Uuid;

fn setup_logging() {
    tracing_subscriber::registry()
        .with(fmt::layer().json())
        .init();
}

fn main() {
    setup_logging();

    let trace_id = Uuid::new_v4().to_string();

    // Create span with trace context
    let span = span!(Level::INFO, "request", trace_id = %trace_id);
    let _enter = span.enter();

    info!(
        user_id = "user_123",
        email = "john@example.com",
        "user_login"
    );

    error!(
        user_id = "user_123",
        error_code = "card_declined",
        amount = 99.99,
        "payment_failed"
    );
}

---

Quick Reference

Python Libraries

# Standard library (built-in)
import logging
import json

# JSON formatter
pip install python-json-logger

# Structured logging library
pip install structlog

Go Libraries

go get -u go.uber.org/zap              # Fast structured logging
go get -u github.com/sirupsen/logrus   # Structured logging
go get -u github.com/rs/zerolog        # Zero-allocation JSON logger

Rust Libraries

# Add to Cargo.toml
[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["json"] }
serde_json = "1.0"

Log Level Guidelines

TRACE:   Function entry/exit, variable values
DEBUG:   Detailed diagnostic information
INFO:    Business events, request/response summaries
WARN:    Degraded performance, retries, deprecated usage
ERROR:   Handled errors, failed operations
FATAL:   Unrecoverable errors, immediate shutdown

Essential Fields

Always include:

• timestamp (ISO 8601 UTC)
• level (lowercase: info, warn, error)
• message (event name or description)
• service (service name)

Include when available:

• trace_id (request correlation)
• span_id (operation within trace)
• user_id (user context)
• request_id (HTTP request ID)
• environment (dev/staging/prod)

Loki Label Best Practices

Good labels (low cardinality):

• service, environment, level, host, region

Bad labels (high cardinality):

• user_id, request_id, trace_id, email, ip_address

Rule: If it has >100 unique values, it's a field, not a label.

---

Anti-Patterns

❌ Logging Sensitive Data

# WRONG: PII in logs
logger.info(f"User password: {password}")
logger.info(f"Credit card: {card_number}")

# CORRECT: Redact sensitive data
logger.info(f"User authenticated", extra={"user_id": user_id})
logger.info(f"Payment processed", extra={"last4": card_number[-4:]})

❌ String Concatenation in Logs

# WRONG: Loses structure
logger.info(f"User {user_id} logged in from {ip}")

# CORRECT: Structured fields
logger.info("user_login", extra={"user_id": user_id, "ip": ip})

❌ Excessive Logging

# WRONG: Log spam
for item in items:  # 10,000 items
    logger.info(f"Processing {item}")

# CORRECT: Batch logging
logger.info(f"Processing batch", extra={"count": len(items)})
# ... process items
logger.info(f"Batch complete", extra={"count": len(items), "duration_ms": elapsed})

❌ Unstructured Exception Logging

# WRONG: String-only exception
try:
    process()
except Exception as e:
    logger.error(f"Error: {e}")

# CORRECT: Structured with context
try:
    process()
except Exception as e:
    logger.error(
        "process_failed",
        extra={
            "error_type": type(e).__name__,
            "error_message": str(e),
            "user_id": user_id
        },
        exc_info=True  # Includes traceback
    )

❌ Logging in Hot Paths

# WRONG: Logging in tight loop
for i in range(1_000_000):
    logger.debug(f"Iteration {i}")
    compute()

# CORRECT: Sample or aggregate
if i % 10_000 == 0:
    logger.debug(f"Progress: {i} iterations")

❌ High-Cardinality Loki Labels

# WRONG: High cardinality labels
labels:
  service: api
  user_id: user_123  # Millions of unique values!
  trace_id: abc123   # Billions of unique values!

# CORRECT: Low cardinality labels
labels:
  service: api
  environment: prod
  level: info
# user_id and trace_id go in log fields

---

Related Skills

• metrics-instrumentation.md - Complementary numeric metrics
• distributed-tracing.md - Deep request tracing with spans
• alerting-strategy.md - Log-based alerts and anomaly detection
• dashboard-design.md - Log visualization in Grafana

---

Last Updated: 2025-10-18 Format Version: 1.0 (Atomic)