logging-patterns

name	logging-patterns
description	Java logging best practices with SLF4J, structured logging (JSON), and MDC for request tracing. Includes AI-friendly log formats for debugging. Use when user asks about logging, debugging application flow, or analyzing logs.

Logging Patterns for Java

AI-Friendly Logging

Why JSON Structured Logging?

Aspect	Plain Text	JSON Structured
Parsing	Regex, fragile	JSON parse, reliable
Filtering	grep + awk	jq queries
Context	Manual extraction	Direct field access
Multi-line	Breaks parsing	Single JSON object
AI Analysis	Difficult	Excellent

Recommended Setup for Spring Boot 3.4+

Spring Boot 3.4+ has native structured logging support - no additional dependencies needed.

# application.yml
logging:
  structured:
    format:
      console: ecs  # Elastic Common Schema format
      # Options: ecs, logstash, gelf

Log Format for AI Analysis

{
  "@timestamp": "2024-01-15T10:30:00.123Z",
  "log.level": "INFO",
  "message": "Order processed successfully",
  "service.name": "order-service",
  "trace.id": "abc123",
  "order.id": "ORD-456",
  "customer.id": "CUST-789",
  "processing.time.ms": 150
}

Reading Logs with AI

When asking AI to analyze logs, provide:

1. The JSON log entries (not plain text)
2. The time range of interest
3. Any request/trace IDs
4. The specific question or symptom

---

Quick Setup

Native Structured Logging (Spring Boot 3.4+)

# application.yml
spring:
  application:
    name: my-service

logging:
  structured:
    format:
      console: ecs
  level:
    root: INFO
    com.example: DEBUG
    org.springframework.web: INFO

Profile-Based Switching

# application.yml (default - human readable)
logging:
  level:
    root: INFO

---
# application-prod.yml (production - structured JSON)
logging:
  structured:
    format:
      console: ecs
  level:
    root: WARN
    com.example: INFO

---

Setup for Spring Boot < 3.4

Logstash Logback Encoder

<!-- pom.xml -->
<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>7.4</version>
</dependency>

<!-- logback-spring.xml -->
<configuration>
    <!-- Development: human-readable -->
    <springProfile name="!prod">
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
            </encoder>
        </appender>
    </springProfile>

    <!-- Production: JSON structured -->
    <springProfile name="prod">
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <includeMdcKeyName>requestId</includeMdcKeyName>
                <includeMdcKeyName>userId</includeMdcKeyName>
            </encoder>
        </appender>
    </springProfile>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

---

SLF4J Basics

Logger Declaration

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

// Standard declaration
public class OrderService {
    private static final Logger log = LoggerFactory.getLogger(OrderService.class);
}

// With Lombok (if used)
@Slf4j
public class OrderService {
    // log is available automatically
}

Parameterized Logging

// BAD: String concatenation (always evaluated, even if level disabled)
log.debug("Processing order " + orderId + " for customer " + customerId);

// GOOD: Parameterized (only evaluated if level is enabled)
log.debug("Processing order {} for customer {}", orderId, customerId);

// GOOD: Multiple parameters
log.info("Order {} processed: {} items, total {}",
    orderId, itemCount, totalAmount);

// GOOD: With exception (exception is always the LAST argument)
log.error("Failed to process order {}", orderId, exception);

---

Log Levels

Level	When to Use	Example
ERROR	Something failed, needs attention	Payment processing failed, database connection lost
WARN	Unexpected but recoverable	Retry succeeded, deprecated API called, fallback used
INFO	Normal business events	Order placed, user registered, scheduled job completed
DEBUG	Detailed flow for debugging	Method entry/exit, intermediate values, query parameters
TRACE	Very detailed/verbose	Full request/response bodies, loop iterations

// Level usage examples
log.error("Payment failed for order {}: {}", orderId, e.getMessage(), e);
log.warn("Retry {} of {} for order {}", attempt, maxRetries, orderId);
log.info("Order {} placed successfully. Total: {}", orderId, total);
log.debug("Calculating discount for customer {} with tier {}", customerId, tier);
log.trace("Request body: {}", requestBody);

---

MDC - Mapped Diagnostic Context

Request ID Filter

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class RequestIdFilter extends OncePerRequestFilter {

    private static final String REQUEST_ID_HEADER = "X-Request-ID";
    private static final String MDC_REQUEST_ID = "requestId";

    @Override
    protected void doFilterInternal(HttpServletRequest request,
                                     HttpServletResponse response,
                                     FilterChain filterChain) throws ServletException, IOException {
        try {
            String requestId = request.getHeader(REQUEST_ID_HEADER);
            if (requestId == null || requestId.isBlank()) {
                requestId = UUID.randomUUID().toString().substring(0, 8);
            }

            MDC.put(MDC_REQUEST_ID, requestId);
            response.setHeader(REQUEST_ID_HEADER, requestId);

            filterChain.doFilter(request, response);
        } finally {
            MDC.clear();
        }
    }
}

User Context

@Component
public class UserContextFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest request,
                                     HttpServletResponse response,
                                     FilterChain filterChain) throws ServletException, IOException {
        try {
            Authentication auth = SecurityContextHolder.getContext().getAuthentication();
            if (auth != null && auth.isAuthenticated()) {
                MDC.put("userId", auth.getName());
            }
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove("userId");
        }
    }
}

MDC in Async

// MDC is thread-local - it doesn't propagate to async threads automatically

// Solution: MDC-aware task decorator
@Configuration
@EnableAsync
public class AsyncConfig implements AsyncConfigurer {

    @Override
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(5);
        executor.setMaxPoolSize(10);
        executor.setTaskDecorator(new MdcTaskDecorator());
        executor.initialize();
        return executor;
    }
}

public class MdcTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> contextMap = MDC.getCopyOfContextMap();
        return () -> {
            try {
                if (contextMap != null) {
                    MDC.setContextMap(contextMap);
                }
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }
}

---

What to Log

Business Events

// Log meaningful business events with context
log.info("Order placed: orderId={}, customerId={}, items={}, total={}",
    order.getId(), order.getCustomerId(), order.getItems().size(), order.getTotal());

log.info("Payment processed: orderId={}, method={}, amount={}, transactionId={}",
    orderId, paymentMethod, amount, transactionId);

log.info("User registered: userId={}, email={}, source={}",
    user.getId(), maskEmail(user.getEmail()), registrationSource);

External Calls with Timing

// Log external service calls with duration
public PaymentResult processPayment(PaymentRequest request) {
    long start = System.currentTimeMillis();

    log.info("Calling payment gateway: orderId={}, amount={}",
        request.getOrderId(), request.getAmount());

    try {
        PaymentResult result = paymentGateway.charge(request);

        long duration = System.currentTimeMillis() - start;
        log.info("Payment gateway response: orderId={}, status={}, duration={}ms",
            request.getOrderId(), result.getStatus(), duration);

        return result;
    } catch (Exception e) {
        long duration = System.currentTimeMillis() - start;
        log.error("Payment gateway failed: orderId={}, duration={}ms",
            request.getOrderId(), duration, e);
        throw e;
    }
}

Flow Steps

@Transactional
public Order processOrder(CreateOrderRequest request) {
    log.info("Processing order: customerId={}", request.getCustomerId());

    log.debug("Validating order items: count={}", request.getItems().size());
    validateItems(request.getItems());

    log.debug("Calculating total with discounts");
    BigDecimal total = calculateTotal(request);

    log.debug("Reserving inventory for {} items", request.getItems().size());
    reserveInventory(request.getItems());

    Order order = orderRepository.save(createOrder(request, total));
    log.info("Order created: orderId={}, total={}", order.getId(), total);

    return order;
}

---

What NOT to Log

// NEVER log sensitive data
log.info("User login: {}, password: {}", username, password);        // NEVER
log.info("Card number: {}", cardNumber);                             // NEVER
log.info("Auth token: {}", authToken);                               // NEVER
log.info("SSN: {}", socialSecurityNumber);                           // NEVER

// NEVER log in tight loops (log flooding)
for (int i = 0; i < 1_000_000; i++) {
    log.debug("Processing item {}", i);  // NEVER - floods logs
}

// Instead, log summary
log.info("Processed {} items in {}ms", count, duration);

// DO mask sensitive data when context is needed
log.info("Processing payment for card ending in {}",
    cardNumber.substring(cardNumber.length() - 4));

// DO use a masking utility
public static String maskEmail(String email) {
    int atIndex = email.indexOf('@');
    if (atIndex <= 1) return "***@" + email.substring(atIndex + 1);
    return email.charAt(0) + "***" + email.substring(atIndex);
}

---

Exception Logging

Log Once at Boundary

// BAD: Logging the same exception at every level
@Repository
public class UserRepository {
    public User findById(Long id) {
        try {
            return jdbc.queryForObject(...);
        } catch (DataAccessException e) {
            log.error("DB error", e);  // Log #1
            throw e;
        }
    }
}

@Service
public class UserService {
    public User getUser(Long id) {
        try {
            return userRepository.findById(id);
        } catch (DataAccessException e) {
            log.error("Service error", e);  // Log #2 - same exception!
            throw new UserNotFoundException(id, e);
        }
    }
}

// GOOD: Log once at the boundary (controller/handler level)
@Repository
public class UserRepository {
    public User findById(Long id) {
        return jdbc.queryForObject(...);  // Let it propagate
    }
}

@Service
public class UserService {
    public User getUser(Long id) {
        return userRepository.findById(id)
            .orElseThrow(() -> new UserNotFoundException(id));
    }
}

@RestControllerAdvice
public class GlobalExceptionHandler {
    @ExceptionHandler(Exception.class)
    public ResponseEntity<ErrorResponse> handleException(Exception e, HttpServletRequest request) {
        log.error("Request {} {} failed: {}", request.getMethod(),
            request.getRequestURI(), e.getMessage(), e);  // Log once here
        return ResponseEntity.internalServerError().body(ErrorResponse.of(e));
    }
}

Include Context

// BAD: No context
log.error("Error occurred", e);

// GOOD: Include relevant context
log.error("Failed to process order {}: customer={}, items={}, error={}",
    orderId, customerId, itemCount, e.getMessage(), e);

---

Quick Reference

Situation	Level	Template
Request received	DEBUG	"Received {} {}: params={}"
Business event	INFO	"Order placed: orderId={}, total={}"
External call start	INFO	"Calling {}: request={}"
External call end	INFO	"Response from {}: status={}, duration={}ms"
Retry attempt	WARN	"Retry {}/{} for {}: reason={}"
Validation failure	WARN	"Validation failed: field={}, value={}"
Unhandled exception	ERROR	"Failed to {}: context={}"
Data issue	ERROR	"Data integrity issue: entity={}, id={}"

---

Analyzing Logs

# Find errors in last hour
jq 'select(.["log.level"] == "ERROR")' app.log

# Find slow requests (>1000ms)
jq 'select(.["processing.time.ms"] > 1000)' app.log

# Trace a request across services
jq 'select(.["trace.id"] == "abc123")' app.log

# Count errors by type
jq 'select(.["log.level"] == "ERROR") | .message' app.log | sort | uniq -c | sort -rn

# Find all logs for a specific order
jq 'select(.["order.id"] == "ORD-456")' app.log