Logdy

Appearance

Watch out! You're reading a series of articles

Contextual Logging: Tracing Requests Through Your Application ​

Ever tried to debug an issue where a request passes through five different services, ten different methods, and you have no idea which logs belong to which request? Yeah, we've all been there. Let's talk about how to maintain context in your logs across your entire application.

The Problem ​

Here's a typical scenario: A user makes a request to your API, which then:

  1. Validates the request
  2. Calls a database
  3. Makes an external API call
  4. Processes some data
  5. Returns a response

Without proper context, your logs might look like this:

[2024-01-15 10:15:30] Validating user input
[2024-01-15 10:15:30] Querying database
[2024-01-15 10:15:31] Making external API call
[2024-01-15 10:15:31] Processing response

Now imagine 100 concurrent users making requests. Good luck figuring out which logs belong to which request! Let's fix this.

Solution 1: Request Context in TypeScript ​

Here's how to maintain context through an entire request lifecycle using TypeScript:

typescript
// First, create a context interface
interface RequestContext {
    requestId: string;
    userId?: string;
    correlationId: string;
    startTime: number;
}

// Create a context manager using AsyncLocalStorage
import { AsyncLocalStorage } from 'async_hooks';

class ContextManager {
    private static storage = new AsyncLocalStorage<RequestContext>();

    static getContext(): RequestContext | undefined {
        return this.storage.getStore();
    }

    static run(context: RequestContext, callback: () => Promise<any>) {
        return this.storage.run(context, callback);
    }
}

// Create a logger that automatically includes context
class ContextualLogger {
    static log(level: string, message: string, extra: object = {}) {
        const context = ContextManager.getContext();
        console.log(JSON.stringify({
            timestamp: new Date().toISOString(),
            level,
            message,
            ...context,
            ...extra
        }));
    }
}

// Now let's see it in action
class OrderService {
    async processOrder(orderData: any) {
        // Generate a unique request ID
        const requestId = crypto.randomUUID();
        
        // Create a context for this request
        return ContextManager.run({
            requestId,
            userId: orderData.userId,
            correlationId: orderData.correlationId || requestId,
            startTime: Date.now()
        }, async () => {
            try {
                ContextualLogger.log('info', 'Starting order processing', { orderType: orderData.type });
                
                await this.validateOrder(orderData);
                await this.checkInventory(orderData);
                await this.processPayment(orderData);
                await this.updateInventory(orderData);
                
                ContextualLogger.log('info', 'Order processing completed', {
                    duration: Date.now() - ContextManager.getContext()!.startTime
                });
            } catch (error) {
                ContextualLogger.log('error', 'Order processing failed', {
                    error: error.message,
                    stack: error.stack
                });
                throw error;
            }
        });
    }

    private async validateOrder(orderData: any) {
        ContextualLogger.log('debug', 'Validating order', { orderData });
        // Validation logic here
    }

    private async checkInventory(orderData: any) {
        ContextualLogger.log('debug', 'Checking inventory');
        // Inventory check logic here
    }

    private async processPayment(orderData: any) {
        ContextualLogger.log('info', 'Processing payment');
        // Payment processing logic here
    }

    private async updateInventory(orderData: any) {
        ContextualLogger.log('info', 'Updating inventory');
        // Inventory update logic here
    }
}

The logs will look like this:

json
{
    "timestamp": "2024-01-15T10:15:30.123Z",
    "level": "info",
    "message": "Starting order processing",
    "requestId": "123e4567-e89b-12d3-a456-426614174000",
    "userId": "user123",
    "correlationId": "123e4567-e89b-12d3-a456-426614174000",
    "startTime": 1705312530123,
    "orderType": "standard"
}

Solution 2: Context in Go ​

Go makes this even easier with its built-in context package:

go
package main

import (
    "context"
    "github.com/google/uuid"
    "github.com/rs/zerolog"
    "time"
)

// Define context keys
type contextKey string

const (
    RequestIDKey contextKey = "requestId"
    UserIDKey    contextKey = "userId"
    StartTimeKey contextKey = "startTime"
)

// ContextualLogger wraps zerolog.Logger with context awareness
type ContextualLogger struct {
    logger zerolog.Logger
}

func NewContextualLogger() *ContextualLogger {
    return &ContextualLogger{
        logger: zerolog.New(os.Stdout).With().Timestamp().Logger(),
    }
}

func (l *ContextualLogger) WithContext(ctx context.Context) *zerolog.Event {
    event := l.logger.Info()
    
    // Add context values to log if they exist
    if requestID, ok := ctx.Value(RequestIDKey).(string); ok {
        event.Str("requestId", requestID)
    }
    if userID, ok := ctx.Value(UserIDKey).(string); ok {
        event.Str("userId", userID)
    }
    if startTime, ok := ctx.Value(StartTimeKey).(time.Time); ok {
        event.Dur("duration", time.Since(startTime))
    }
    
    return event
}

// OrderService handles order processing
type OrderService struct {
    logger *ContextualLogger
}

func (s *OrderService) ProcessOrder(ctx context.Context, orderData OrderData) error {
    // Create a new context with request information
    ctx = context.WithValue(ctx, RequestIDKey, uuid.New().String())
    ctx = context.WithValue(ctx, UserIDKey, orderData.UserID)
    ctx = context.WithValue(ctx, StartTimeKey, time.Now())

    s.logger.WithContext(ctx).
        Interface("orderData", orderData).
        Msg("Starting order processing")

    if err := s.validateOrder(ctx, orderData); err != nil {
        s.logger.WithContext(ctx).
            Err(err).
            Msg("Order validation failed")
        return err
    }

    if err := s.checkInventory(ctx, orderData); err != nil {
        s.logger.WithContext(ctx).
            Err(err).
            Msg("Inventory check failed")
        return err
    }

    if err := s.processPayment(ctx, orderData); err != nil {
        s.logger.WithContext(ctx).
            Err(err).
            Msg("Payment processing failed")
        return err
    }

    s.logger.WithContext(ctx).
        Msg("Order processing completed successfully")
    return nil
}

func (s *OrderService) validateOrder(ctx context.Context, data OrderData) error {
    s.logger.WithContext(ctx).
        Msg("Validating order")
    // Validation logic here
    return nil
}

func (s *OrderService) checkInventory(ctx context.Context, data OrderData) error {
    s.logger.WithContext(ctx).
        Msg("Checking inventory")
    // Inventory check logic here
    return nil
}

func (s *OrderService) processPayment(ctx context.Context, data OrderData) error {
    s.logger.WithContext(ctx).
        Msg("Processing payment")
    // Payment processing logic here
    return nil
}

Best Practices for Contextual Logging ​

  1. Always Include Request ID: Generate a unique ID for each request and include it in every log message. This is your bread and butter for request tracing.

  2. Use Correlation IDs: If a request spans multiple services, pass a correlation ID through all of them. This helps trace requests across your entire system.

  3. Include Timing Information: Add timestamps and durations to understand how long operations take:

typescript
const start = Date.now();
try {
    await someOperation();
} finally {
    ContextualLogger.log('info', 'Operation completed', {
        duration: Date.now() - start
    });
}
  1. Add Business Context: Include relevant business information that might help debugging:
typescript
ContextualLogger.log('info', 'Processing payment', {
    orderType: order.type,
    paymentMethod: order.paymentMethod,
    customerTier: customer.tier
});

Real-world Impact ​

Proper contextual logging can reduce your debugging time from hours to minutes. Instead of piecing together what happened across different services and method calls, you can simply filter logs by request ID or correlation ID and see the entire flow, complete with timing information and business context.

For example, if a customer reports an issue with order #12345, you can immediately filter logs by that order ID and see every step of the process, from initial request to final response, even if it went through multiple services and dozens of method calls.

Remember: Future you (or your colleagues) will thank you for taking the time to implement proper contextual logging. It's one of those things that seems like extra work until 3 AM when you're trying to figure out why a critical order failed!

Proper contextual logging is not just about debugging - it's about understanding your system's behavior in production. Here's what production-grade logging enables:

  • Incident Response: Quickly trace the root cause of production issues
  • Performance Optimization: Identify bottlenecks with timing data
  • Business Analytics: Extract business metrics from structured logs
  • Capacity Planning: Monitor resource usage patterns
  • Security Auditing: Track suspicious patterns and access attempts

Summary: The Stuff That Really Matters ​

1. Log Things That Future-You Will Thank You For ​

Remember that time you had to debug an issue and the logs were just "Error occurred" with no context? Yeah, let's not do that. Think of logging like leaving notes for your future self who's half-asleep and grumpy. Include the important bits:

  • What happened (duh)
  • When it happened (with timezone!)
  • Who was involved (user IDs, session info)
  • What was the context (transaction IDs, relevant parameters)

But please, for the love of all things holy, don't log passwords or credit card numbers. Your security team will hunt you down.

2. Use Log Levels Like a Pro, Not a Robot ​

Think of log levels as your message's urgency level:

  • DEBUG: "FYI, I'm doing this thing" (like your chatty coworker)
  • INFO: "Hey, this is normal but worth noting" (like your daily standup updates)
  • WARNING: "Uhh, this looks fishy..." (like when your car makes that weird noise)
  • ERROR: "Houston, we have a problem" (but we can handle it)
  • CRITICAL: "EVERYTHING IS ON FIRE 🔥" (time to wake up the on-call team)

3. Structure Your Logs (Because Grep Can Only Take You So Far) ​

JSON logging isn't just a fancy buzzword - it's your best friend when you're trying to make sense of thousands of log lines at 2 AM. It's the difference between playing "find the needle in the haystack" and having a metal detector.

4. Keep It Consistent ​

Pick a format and stick to it. If you're logging user actions in one place with their ID and timestamp, do it everywhere. Inconsistent logging is like having a journal where half the entries are in English and half in interpretive dance - not helpful when you're trying to piece together what happened.

5. Consider Centralized Logging ​

If you're still SSH-ing into individual servers to check logs, we need to talk. It's 2024 - get those logs into a centralized system. Your sanity (and your team) will thank you.

6. Review Your Logs (Before You Have To) ​

Don't wait for something to break to look at your logs. Take a peek now and then. You might catch weird patterns or issues before they become 2 AM emergencies. Plus, it's a great way to make sure your logging is actually useful and not just digital noise.

The Bottom Line ​

Good logging isn't about following a strict rulebook - it's about making life easier for whoever has to figure out what went wrong (spoiler: it's usually you). Keep it meaningful, keep it searchable, and for Pete's sake, keep those sensitive details out of the logs.

Remember: The best logging strategy is the one that helps you sleep better at night, knowing that when something goes wrong, you'll have the breadcrumbs to figure it out. Now go forth and log responsibly! 🚀

Watch out! You're reading a series of articles

Copyright © 2024-present Logdy