Logging Best Practices

---

Definition

---

Structured Logging

// UNSTRUCTURED (bad for parsing)
log.info("User [email protected] placed order 12345 for $99.99");

// STRUCTURED (machine-parseable)
log.info("Order placed",
    kv("userId", "user-123"),
    kv("orderId", "12345"),
    kv("amount", 99.99),
    kv("currency", "USD")
);

// Output (JSON):
{
    "timestamp": "2024-01-15T10:30:00.123Z",
    "level": "INFO",
    "message": "Order placed",
    "userId": "user-123",
    "orderId": "12345",
    "amount": 99.99,
    "currency": "USD",
    "service": "order-service",
    "traceId": "abc-123"
}

// SLF4J with Logback/Log4j2
import static net.logstash.logback.argument.StructuredArguments.*;

logger.info("Order created",
    kv("orderId", order.getId()),
    kv("customerId", order.getCustomerId()),
    kv("total", order.getTotal()),
    kv("itemCount", order.getItems().size())
);

// With MDC (Mapped Diagnostic Context)
MDC.put("requestId", requestId);
MDC.put("userId", userId);
try {
    // All logs in this scope include requestId and userId
    logger.info("Processing request");
} finally {
    MDC.clear();
}

---

What to Log

// REQUEST/RESPONSE BOUNDARIES
@RestController
class OrderController {

    @PostMapping("/orders")
    public Order createOrder(@RequestBody CreateOrderRequest request) {
        logger.info("Received create order request",
            kv("customerId", request.getCustomerId()),
            kv("itemCount", request.getItems().size())
        );

        Order order = orderService.create(request);

        logger.info("Order created successfully",
            kv("orderId", order.getId()),
            kv("total", order.getTotal())
        );

        return order;
    }
}

// BUSINESS EVENTS
logger.info("Payment processed",
    kv("orderId", orderId),
    kv("paymentMethod", "CREDIT_CARD"),
    kv("amount", amount)
);

logger.info("User registered",
    kv("userId", user.getId()),
    kv("email", maskEmail(user.getEmail()))  // Masked!
);

// ERRORS WITH CONTEXT
try {
    processPayment(order);
} catch (PaymentException e) {
    logger.error("Payment processing failed",
        kv("orderId", order.getId()),
        kv("customerId", order.getCustomerId()),
        kv("amount", order.getTotal()),
        kv("paymentMethod", paymentMethod),
        kv("errorCode", e.getCode()),
        e  // Include stack trace
    );
    throw e;
}

// PERFORMANCE
long startTime = System.currentTimeMillis();
List<Product> products = productService.search(query);
long duration = System.currentTimeMillis() - startTime;

logger.info("Product search completed",
    kv("query", query),
    kv("resultCount", products.size()),
    kv("durationMs", duration)
);

---

What NOT to Log

// DON'T LOG SENSITIVE DATA

// BAD: Logging passwords
logger.info("Login attempt", kv("password", password));

// BAD: Logging full credit card
logger.info("Payment", kv("cardNumber", cardNumber));

// BAD: Logging PII without masking
logger.info("User data", kv("ssn", ssn));

// GOOD: Mask sensitive data
logger.info("Login attempt", kv("username", username));
logger.info("Payment", kv("cardLast4", cardNumber.substring(12)));
logger.info("User data", kv("ssnLast4", "***-**-" + ssn.substring(7)));

// DON'T LOG HIGH VOLUME INTERNAL OPERATIONS

// BAD: Logging inside tight loops
for (Item item : items) {
    logger.debug("Processing item", kv("itemId", item.getId()));
    process(item);
}

// GOOD: Log aggregates
logger.info("Processing items batch",
    kv("batchSize", items.size())
);
for (Item item : items) {
    process(item);
}
logger.info("Batch processing complete",
    kv("successCount", successCount),
    kv("failureCount", failureCount)
);

// SENSITIVE DATA PATTERNS TO AVOID
// - Passwords, API keys, tokens
// - SSN, credit card numbers
// - Health information
// - Personal addresses
// - Session IDs (can enable hijacking)

---

Correlation IDs

// CORRELATION ID: Trace requests across services

// Generate at entry point (API Gateway or first service)
@Component
class RequestIdFilter implements Filter {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response,
                         FilterChain chain) {
        String requestId = request.getHeader("X-Request-ID");
        if (requestId == null) {
            requestId = UUID.randomUUID().toString();
        }

        MDC.put("requestId", requestId);
        try {
            HttpServletResponse httpResponse = (HttpServletResponse) response;
            httpResponse.setHeader("X-Request-ID", requestId);
            chain.doFilter(request, response);
        } finally {
            MDC.clear();
        }
    }
}

// Propagate to downstream services
@Component
class FeignRequestInterceptor implements RequestInterceptor {

    @Override
    public void apply(RequestTemplate template) {
        String requestId = MDC.get("requestId");
        if (requestId != null) {
            template.header("X-Request-ID", requestId);
        }
    }
}

// Now logs across services share requestId:
// Order Service:
{"requestId": "abc-123", "message": "Creating order", ...}
// Payment Service:
{"requestId": "abc-123", "message": "Processing payment", ...}
// Inventory Service:
{"requestId": "abc-123", "message": "Reserving items", ...}

// Query all logs for a request:
// requestId:"abc-123"

---

Log Aggregation

---

Tips & Tricks

---

• *