logging-observability

# Logging & Observability Skill Activate when working with logging systems, distributed tracing, debugging, monitoring, or any observability-related tasks across applications. ## 1. Logging Best Practices ### Log Levels Use appropriate log levels for different severity: | Level | Severity | When to Use | |-------|----------|------------| | **DEBUG** | Low | Development only - detailed info, variable states, control flow. Use sparingly in production. | | **INFO** | Low | Important application lifecycle events - startup, shutdown, config loaded, user actions, key state changes. | | **WARN** | Medium | Recoverable issues - deprecated usage, resource constraints, unexpected but handled conditions. Investigate later. | | **ERROR** | High | Unrecoverable problems - exceptions, failed operations, missing required data. Requires immediate attention. | | **FATAL** | Critical | System-level failures - abort conditions, out of memory, unrecoverable state. System may crash. | ### General Principles - **Actionable**: Logs should help diagnose problems, not just record events - **Contextual**: Include enough context to understand what happened without code inspection - **Consistent**: Use same terminology across codebase for same events - **Sparse**: Don't log everything - unnecessary noise obscures real issues - **Sampling**: In high-volume scenarios, sample logs (10%, 1%, etc.) rather than logging everything - **Structured**: Always use structured format (JSON) for programmatic parsing ## 2. Structured Logging Format ### Standard Fields Every log entry should include: ```json { "timestamp": "2025-11-17T10:30:45.123Z", "level": "ERROR", "message": "Failed to process user request", "service": "auth-service", "version": "1.2.3", "environment": "production", "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736", "span_id": "00f067aa0ba902b7", "parent_span_id": "0af7651916cd43dd", "user_id": "user-12345", "request_id": "req-98765", "path": "/api/users/authenticate", "method": "POST", "status_code": 500, "error": { "type": "InvalidCredentialsError", "message": "Provided credentials do not match", "stack": "Error: InvalidCredentialsError...", "code": "AUTH_INVALID_CREDS" }, "context": { "ip_address": "192.168.1.100", "user_agent": "Mozilla/5.0...", "attempt_number": 3, "rate_limit_remaining": 2 }, "duration_ms": 245, "custom_field": "custom_value" } ``` ### Required vs Optional Fields **Always include:** - timestamp - level - message - trace_id - service - environment **When applicable:** - span_id / parent_span_id (distributed tracing) - user_id (any user action) - request_id (any request) - error (on ERROR/FATAL) - duration_ms (operations) - context (relevant metadata) ## 3. What to Log ### Application Lifecycle ```json // Startup {"timestamp": "...", "level": "INFO", "message": "Service starting", "service": "auth-service", "version": "1.2.3"} // Configuration loaded {"timestamp": "...", "level": "INFO", "message": "Configuration loaded", "config_source": "environment", "environment": "production"} // Database connection established {"timestamp": "...", "level": "INFO", "message": "Database connected", "host": "db.internal", "pool_size": 20} // Shutdown {"timestamp": "...", "level": "INFO", "message": "Service shutting down", "reason": "SIGTERM", "uptime_seconds": 3600} ``` ### User Actions ```json // Login attempt {"timestamp": "...", "level": "INFO", "message": "User login attempt", "user_id": "user-123", "method": "password"} // Data modification {"timestamp": "...", "level": "INFO", "message": "User updated profile", "user_id": "user-123", "fields_changed": ["email", "name"]} // Permission check {"timestamp": "...", "level": "INFO", "message": "Permission check", "user_id": "user-123", "resource": "report-456", "permission": "read", "granted": true} ``` ### External API Calls ```json // API call started {"timestamp": "...", "level": "DEBUG", "message": "External API call", "service": "my-service", "api": "stripe", "endpoint": "/charges", "method": "POST"} // API response {"timestamp": "...", "level": "DEBUG", "message": "API response received", "api": "stripe", "endpoint": "/charges", "status_code": 200, "duration_ms": 145} // API error {"timestamp": "...", "level": "WARN", "message": "External API error", "api": "stripe", "status_code": 429, "error": "rate_limit_exceeded", "retry_after_seconds": 60} ``` ### Errors and Exceptions ```json { "timestamp": "...", "level": "ERROR", "message": "Payment processing failed", "service": "payment-service", "user_id": "user-456", "error": { "type": "PaymentGatewayError", "message": "Connection timeout", "code": "GATEWAY_TIMEOUT", "stack": "PaymentGatewayError: Connection timeout\n at processPayment (payment.ts:45)\n at ..." }, "context": { "amount": 9999, "currency": "USD", "gateway": "stripe" } } ``` ### Performance Metrics ```json // Slow operation {"timestamp": "...", "level": "WARN", "message": "Slow query detected", "duration_ms": 5234, "threshold_ms": 1000, "query": "SELECT * FROM orders WHERE..."} // Resource usage {"timestamp": "...", "level": "INFO", "message": "Memory usage high", "memory_used_mb": 2048, "memory_limit_mb": 2560, "percentage": 80} // Cache statistics {"timestamp": "...", "level": "DEBUG", "message": "Cache stats", "cache_hits": 4521, "cache_misses": 234, "hit_rate": 0.95} ``` ## 4. What NOT to Log **NEVER log:** - Passwords or authentication tokens - API keys or secrets - Private keys or certificates - Database credentials - OAuth tokens or refresh tokens - Credit card numbers - Social security numbers - Email addresses (without redaction in logs) - Personal identification numbers - Medical records - Raw HTTP request/response bodies (especially with auth headers) **Be careful with:** - PII in general (name, phone, address) - redact or use anonymized IDs - Query parameters (may contain secrets) - Request/response headers (often contain authorization) - User input (may contain sensitive data) **Security rule: When in doubt, DON'T log it** ```python # BAD - logging credentials logger.info(f"Login attempt for {username} with password {password}") # GOOD - logging action without sensitive data logger.info("Login attempt", extra={"username": username, "method": "password"}) # BAD - logging full request with auth header logger.debug(f"Request: {request.headers}") # GOOD - logging request metadata logger.debug("Incoming request", extra={ "method": request.method, "path": request.path, "user_agent": request.headers.get('user-agent') }) ``` ## 5. Distributed Tracing ### Trace IDs and Span IDs - **Trace ID**: Unique identifier for entire request flow across services - **Span ID**: Unique identifier for single operation/service call - **Parent Span ID**: Span that initiated current span (for tracing parent-child relationships) Generated once at entry point, propagated through all downstream calls: ``` Request → [Service A, Trace: abc123] ├─ [Span: span1] Database query ├─ [Span: span2] → Service B, parent: span2 └─ [Span: span3] Cache lookup └─ [Span: span4] External API call ``` ### Implementation ```python # Python example with trace context import uuid class RequestContext: def __init__(self, trace_id=None, span_id=None, parent_span_id=None): self.trace_id = trace_id or str(uuid.uuid4()) self.span_id = span_id or str(uuid.uuid4()) self.parent_span_id = parent_span_id # Middleware/decorator def trace_request(func): def wrapper(*args, **kwargs): ctx = RequestContext() return func(*args, context=ctx, **kwargs) return wrapper # Propagate to downstream services def call_downstream_service(service_url, data, context): headers = { 'X-Trace-ID': context.trace_id, 'X-Span-ID': context.span_id, 'X-Parent-Span-ID': context.span_id # Current becomes parent } response = requests.post(service_url, json=data, headers=headers) return response ``` ### Sampling Strategies - **No sampling**: Log all traces (high volume services may be expensive) - **Rate sampling**: Log every Nth request (e.g., 1 in 100) - **Adaptive sampling**: Sample based on error rate, latency, or traffic volume - **Tail sampling**: Sample based on trace outcome (errors always sampled) ```python # Adaptive sampling example def should_sample(trace): # Always sample errors if trace.has_error: return True # Sample slow requests (>1s) if trace.duration_ms > 1000: return True # Sample 1% of normal requests return random.random() < 0.01 ``` ## 6. Performance Logging ### Execution Time ```python import time def log_execution_time(func): def wrapper(*args, **kwargs): start = time.time() try: result = func(*args, **kwargs) duration_ms = (time.time() - start) * 1000 logger.info(f"{func.__name__} completed", extra={ "duration_ms": duration_ms, "status": "success" }) return result except Exception as e: duration_ms = (time.time() - start) * 1000 logger.error(f"{func.__name__} failed", extra={ "duration_ms": duration_ms, "error": str(e) }) raise return wrapper ``` ### Resource Usage ```python import psutil import os def log_resource_usage(): process = psutil.Process(os.getpid()) memory = process.memory_info() logger.info("Resource usage", extra={ "memory_rss_mb": memory.rss / 1024 / 1024, "memory_vms_mb": memory.vms / 1024 / 1024, "cpu_percent": process.cpu_percent(interval=1), "num_threads": process.num_threads() }) ``` ### Slow Query Logs ```python