Logging at Scale: Production-Grade Observability

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32

import structlog
import sys
 
logger = structlog.get_logger()
 
def initialize_database():
    try:
        connection = create_database_connection()
        verify_schema_version(connection)
        return connection
    except SchemaVersionMismatch as e:
        # This is FATAL: application cannot safely operate with wrong schema
        logger.critical(
            "database_schema_incompatible",
            expected_version=e.expected,
            actual_version=e.actual,
            remediation="Run database migrations before starting application"
        )
        sys.exit(1)  # FATAL logs typically precede shutdown
    except ConnectionError as e:
        # This might be FATAL at startup, but could be ERROR during runtime
        if is_during_startup():
            logger.critical(
                "database_connection_failed_at_startup",
                error=str(e),
                remediation="Verify database is running and credentials are correct"
            )
            sys.exit(1)
        else:
            # During runtime, retry logic might recover
            logger.error("database_connection_lost", error=str(e))
            raise

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47

public class OrderService {
    private static final Logger logger = LoggerFactory.getLogger(OrderService.class);
    
    public Order createOrder(OrderRequest request) {
        try {
            // Validation failures are NOT errors - they're expected input issues
            ValidationResult validation = validator.validate(request);
            if (!validation.isValid()) {
                logger.info("order_validation_failed",  // INFO, not ERROR
                    kv("user_id", request.getUserId()),
                    kv("violations", validation.getViolations()));
                throw new ValidationException(validation);
            }
            
            // Database failure IS an error - unexpected infrastructure issue
            Order order = orderRepository.save(buildOrder(request));
            
            // Payment failure requires nuanced handling
            PaymentResult payment = paymentService.charge(order);
            if (!payment.isSuccess()) {
                if (payment.getReason() == PaymentFailureReason.INSUFFICIENT_FUNDS) {
                    // Expected business outcome - not an error
                    logger.info("payment_declined_insufficient_funds",
                        kv("order_id", order.getId()),
                        kv("amount", order.getTotal()));
                } else if (payment.getReason() == PaymentFailureReason.NETWORK_ERROR) {
                    // Infrastructure failure - IS an error
                    logger.error("payment_service_network_failure",
                        kv("order_id", order.getId()),
                        kv("retry_count", payment.getRetryCount()),
                        kv("last_error", payment.getErrorMessage()));
                }
                throw new PaymentFailedException(payment);
            }
            
            return order;
            
        } catch (DatabaseException e) {
            // Always LOG as ERROR, then re-throw or handle
            logger.error("order_creation_database_failure",
                kv("user_id", request.getUserId()),
                kv("error_type", e.getClass().getSimpleName()),
                kv("error_message", e.getMessage()));
            throw new OrderCreationException("Database failure", e);
        }
    }
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69

package main
 
import (
    "context"
    "time"
 
    "go.uber.org/zap"
)
 
type CacheClient struct {
    logger *zap.Logger
    cache  Cache
    db     Database
}
 
func (c *CacheClient) GetUser(ctx context.Context, userID string) (*User, error) {
    start := time.Now()
 
    // Try cache first
    user, err := c.cache.Get(ctx, userID)
    if err != nil {
        // Cache miss or failure - this is WARN, not ERROR
        // The operation can still succeed via database
        c.logger.Warn("cache_lookup_failed",
            zap.String("user_id", userID),
            zap.Error(err),
            zap.String("fallback", "database"))
 
        // Fallback to database
        user, err = c.db.GetUser(ctx, userID)
        if err != nil {
            // NOW it's an error - both paths failed
            c.logger.Error("user_lookup_failed",
                zap.String("user_id", userID),
                zap.Error(err))
            return nil, err
        }
    }
 
    // Check if operation was slow
    duration := time.Since(start)
    if duration > 500*time.Millisecond {
        // Slow but successful - WARN
        c.logger.Warn("user_lookup_slow",
            zap.String("user_id", userID),
            zap.Duration("duration", duration),
            zap.Duration("threshold", 500*time.Millisecond))
    }
 
    return user, nil
}
 
func (c *CacheClient) monitorResources() {
    poolStats := c.db.PoolStats()
 
    // Resource warnings based on thresholds
    if poolStats.UsedPercent > 80 {
        c.logger.Warn("db_connection_pool_high",
            zap.Float64("used_percent", poolStats.UsedPercent),
            zap.Int("active_connections", poolStats.Active),
            zap.Int("max_connections", poolStats.Max))
    }
 
    if poolStats.WaitCount > 0 {
        c.logger.Warn("db_connection_pool_contention",
            zap.Int64("waiting_requests", poolStats.WaitCount),
            zap.Duration("wait_duration", poolStats.WaitDuration))
    }
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55

import { logger } from './logger';
 
class OrderProcessor {
    async processOrder(order: Order): Promise<ProcessedOrder> {
        // ✅ Good INFO: Significant business event starting
        logger.info({
            event: 'order_processing_started',
            order_id: order.id,
            customer_id: order.customerId,
            items_count: order.items.length,
            total_cents: order.totalCents,
        });
 
        // ❌ Bad INFO: Too granular, should be DEBUG
        // logger.info({ event: 'validating_order_items' });
        // logger.info({ event: 'checking_inventory_item_1' });
        // logger.info({ event: 'checking_inventory_item_2' });
        
        await this.validateOrder(order);
        await this.reserveInventory(order);
        const payment = await this.processPayment(order);
 
        // ✅ Good INFO: Significant outcome
        logger.info({
            event: 'order_processing_completed',
            order_id: order.id,
            payment_id: payment.id,
            processing_time_ms: Date.now() - startTime,
        });
 
        return { order, payment };
    }
 
    // ✅ Good INFO: State transition
    onCircuitBreakerStateChange(service: string, oldState: string, newState: string): void {
        logger.info({
            event: 'circuit_breaker_state_changed',
            service,
            old_state: oldState,
            new_state: newState,
            reason: 'Failure threshold exceeded',
        });
    }
 
    // ✅ Good INFO: Lifecycle event
    async onApplicationStart(): Promise<void> {
        logger.info({
            event: 'application_started',
            version: process.env.APP_VERSION,
            environment: process.env.NODE_ENV,
            port: process.env.PORT,
            node_version: process.version,
        });
    }
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46

import structlog
 
logger = structlog.get_logger()
 
def calculate_shipping_cost(order):
    logger.debug("shipping_calculation_started",
        order_id=order.id,
        destination_country=order.shipping_address.country,
        total_weight_kg=order.total_weight)
    
    # TRACE: Would show each step of the calculation
    # logger.trace("fetching_base_rates", carrier="fedex")
    
    base_rate = get_base_rate(order.shipping_address)
    logger.debug("base_rate_fetched",
        rate_cents=base_rate,
        zone=base_rate.zone,
        carrier=base_rate.carrier)
    
    # TRACE: Would show each discount rule evaluated
    # for rule in discount_rules:
    #     logger.trace("evaluating_discount_rule", rule_id=rule.id, applies=rule.applies(order))
    
    discounts = calculate_discounts(order, base_rate)
    logger.debug("discounts_applied",
        original_rate_cents=base_rate,
        discount_amount=sum(d.amount for d in discounts),
        discount_count=len(discounts))
    
    final_rate = apply_discounts(base_rate, discounts)
    
    logger.debug("shipping_calculation_complete",
        order_id=order.id,
        final_rate_cents=final_rate,
        calculation_time_ms=elapsed_time())
    
    return final_rate
 
# Conditional expensive logging
def process_complex_request(request):
    # Only compute expensive debug info if DEBUG is enabled
    if logger.isEnabledFor(logging.DEBUG):
        # Expensive serialization only happens if log will be emitted
        logger.debug("request_details",
            full_request=request.to_detailed_dict(),
            computed_hash=expensive_hash_computation(request))

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36

# Acme Corp Logging Standards v2.1
 
## Log Levels
 
### ERROR
Use ERROR when an operation **failed** and **could not complete its intended purpose** due to an **unexpected** condition.
 
**ERROR Examples:**
- Database query threw exception
- Required external service unreachable after retries
- Data corruption detected
- Unhandled exception in request processing
 
**NOT ERROR:**
- User provided invalid input (→ INFO)
- Payment declined by bank (→ INFO)  
- Rate limit triggered (→ WARN)
- Optional feature unavailable (→ WARN)
 
### WARN
Use WARN when something **concerning happened** but the operation **completed** (possibly degraded).
 
**WARN Examples:**
- Circuit breaker opened
- Fallback to secondary data source
- Request latency exceeded 2x p99
- Resource pool utilization > 80%
 
## Common Scenario Guidance
 
| Scenario | Level | Rationale |
|----------|-------|-----------|
| HTTP 4xx response to client | INFO | Client error, server working correctly |
| HTTP 5xx response to client | ERROR | Server failure |
| Retry succeeded | WARN | Issue occurred; worth monitoring |
| All retries exhausted | ERROR | Operation failed |