Chapter 3: Logging with SLF4J

Introduction

System.out.println() is fine for debugging, but in production, it's unusable. SLF4J with Logback provides you with a professional logging system.

---

🎯 Chapter Objectives

By the end of this chapter, you will know how to:

1. ✅ Use SLF4J in your classes
2. ✅ Understand log levels
3. ✅ Write effective logs
4. ✅ Use MDC for traceability
5. ✅ Avoid common mistakes

---

1. SLF4J: The Logging Facade

Architecture

Your code
    ↓
SLF4J (API/Facade)
    ↓
Logback (Implementation)
    ↓
Console / File / Cloud

Advantage: Change implementation without modifying the code.

Spring Boot includes it by default

<!-- Already included in spring-boot-starter -->
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter</artifactId>
</dependency>
<!-- Contains: spring-boot-starter-logging (SLF4J + Logback) -->

---

2. Creating a Logger

Classic Method

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

@Service
public class UserService {

    private static final Logger log = LoggerFactory.getLogger(UserService.class);

    public User findById(Long id) {
        log.info("Finding user with ID: {}", id);
        return userRepository.findById(id).orElse(null);
    }
}

With Lombok @Slf4j (Recommended)

import lombok.extern.slf4j.Slf4j;

@Slf4j  // ← Automatically generates the logger
@Service
public class UserService {

    public User findById(Long id) {
        log.info("Finding user with ID: {}", id);
        return userRepository.findById(id).orElse(null);
    }
}

---

3. Log Levels

Hierarchy (from least to most critical)

TRACE → DEBUG → INFO → WARN → ERROR

Level	Usage	Example
TRACE	Very fine details	"Entering method X with params..."
DEBUG	Debug information	"Calculated value: 42"
INFO	Normal events	"User logged in", "Order created"
WARN	Potential problems	"Cache miss", "Retrying connection"
ERROR	Errors	"Failed to save", "Connection refused"

Usage

@Slf4j
@Service
public class OrderService {

    public Order processOrder(Order order) {
        log.trace("Entering processOrder with order: {}", order);
        
        log.debug("Validating order items: {} items", order.getItems().size());
        
        log.info("Processing order {} for user {}", order.getId(), order.getUserId());
        
        if (order.getTotal() > 10000) {
            log.warn("Large order detected: {} - Total: {}", order.getId(), order.getTotal());
        }
        
        try {
            return saveOrder(order);
        } catch (Exception e) {
            log.error("Failed to process order {}: {}", order.getId(), e.getMessage(), e);
            throw e;
        }
    }
}

---

4. Best Logging Practices

✅ Use Placeholders

// ✅ GOOD: Placeholders (optimal performance)
log.debug("Processing user {} with email {}", userId, email);

// ❌ BAD: Concatenation (always evaluated)
log.debug("Processing user " + userId + " with email " + email);

✅ Log Exceptions Correctly

try {
    riskyOperation();
} catch (Exception e) {
    // ✅ GOOD: Exception as last parameter (displays stack trace)
    log.error("Operation failed for user {}: {}", userId, e.getMessage(), e);
    
    // ❌ BAD: No stack trace
    log.error("Operation failed: " + e.getMessage());
    
    // ❌ BAD: e.printStackTrace() instead of logging
    e.printStackTrace();
}

✅ Useful and Contextual Logs

// ✅ GOOD: Sufficient context
log.info("Order {} created for user {} - Total: {} - Items: {}", 
    order.getId(), order.getUserId(), order.getTotal(), order.getItems().size());

// ❌ BAD: No context
log.info("Order created");

// ❌ BAD: Too verbose
log.info("Created order object with ID " + order.getId() + " and this order was created by user with ID " + order.getUserId() + "...");

✅ Avoid Log Spam

// ❌ BAD: Log in a loop
for (Item item : items) {
    log.debug("Processing item: {}", item);  // 1000 logs if 1000 items!
}

// ✅ GOOD: Summary log
log.debug("Processing {} items", items.size());
for (Item item : items) {
    // processing...
}
log.debug("Finished processing items");

---

5. Level Checking

For Costly Operations

// If the calculation is costly, check the level first
if (log.isDebugEnabled()) {
    String expensiveDetails = calculateExpensiveDetails(order);
    log.debug("Order details: {}", expensiveDetails);
}

// Alternative with Java 8 Supplier (Logback 1.3+)
log.atDebug()
    .addArgument(() -> calculateExpensiveDetails(order))
    .log("Order details: {}");

---

6. MDC (Mapped Diagnostic Context)

What is MDC?

MDC allows adding context to all logs of a request (userId, requestId, etc.).

Basic Usage

import org.slf4j.MDC;

@Component
public class LoggingFilter implements Filter {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) 
            throws IOException, ServletException {
        
        try {
            // Add context
            MDC.put("requestId", UUID.randomUUID().toString());
            MDC.put("userId", getCurrentUserId());
            
            chain.doFilter(request, response);
        } finally {
            // IMPORTANT: Always clear!
            MDC.clear();
        }
    }
}

Result in Logs

2024-01-15 10:30:00 [requestId=abc-123] [userId=42] INFO  OrderService - Processing order
2024-01-15 10:30:01 [requestId=abc-123] [userId=42] INFO  PaymentService - Payment processed
2024-01-15 10:30:01 [requestId=abc-123] [userId=42] INFO  EmailService - Confirmation sent

Complete Filter with MDC

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

    @Override
    protected void doFilterInternal(HttpServletRequest request, 
                                     HttpServletResponse response, 
                                     FilterChain filterChain) 
            throws ServletException, IOException {
        
        try {
            // Request ID
            String requestId = request.getHeader("X-Request-ID");
            if (requestId == null) {
                requestId = UUID.randomUUID().toString().substring(0, 8);
            }
            MDC.put("requestId", requestId);
            
            // User ID (if authenticated)
            Authentication auth = SecurityContextHolder.getContext().getAuthentication();
            if (auth != null && auth.isAuthenticated()) {
                MDC.put("userId", auth.getName());
            }
            
            // Path
            MDC.put("path", request.getRequestURI());
            
            // Add requestId to the response
            response.setHeader("X-Request-ID", requestId);
            
            filterChain.doFilter(request, response);
            
        } finally {
            MDC.clear();
        }
    }
}

---

7. Logging in Different Layers

Controller

@Slf4j
@RestController
@RequestMapping("/api/orders")
public class OrderController {

    @PostMapping
    public ResponseEntity<Order> create(@RequestBody OrderRequest request) {
        log.info("Received order creation request: {} items", request.getItems().size());
        
        Order order = orderService.create(request);
        
        log.info("Order {} created successfully", order.getId());
        return ResponseEntity.status(HttpStatus.CREATED).body(order);
    }
}

Service

@Slf4j
@Service
public class OrderService {

    public Order create(OrderRequest request) {
        log.debug("Creating order for user {}", request.getUserId());
        
        // Validation
        validateItems(request.getItems());
        
        // Calculation
        BigDecimal total = calculateTotal(request.getItems());
        log.debug("Calculated total: {}", total);
        
        // Save
        Order order = orderRepository.save(toOrder(request, total));
        
        log.info("Order {} saved with total {}", order.getId(), total);
        return order;
    }
}

Repository (optional)

// JPA/Hibernate logs are generally sufficient
// But for custom queries:

@Slf4j
@Repository
public class CustomOrderRepository {

    public List<Order> findComplexQuery(Criteria criteria) {
        log.debug("Executing complex query with criteria: {}", criteria);
        
        List<Order> results = executeQuery(criteria);
        
        log.debug("Query returned {} results", results.size());
        return results;
    }
}

---

8. Quick Configuration

application.properties

# Global level
logging.level.root=INFO

# Level by package
logging.level.com.myapp=DEBUG
logging.level.com.myapp.repository=TRACE

# Show SQL queries
logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE

# Disable noisy logs
logging.level.org.apache.catalina=WARN
logging.level.org.springframework.web=INFO

Recommended Levels

Environment	Root	Application	Hibernate
Dev	INFO	DEBUG	DEBUG
Test	WARN	INFO	WARN
Prod	WARN	INFO	WARN

---

9. Summary

Creating a Logger

// With Lombok (recommended)
@Slf4j
public class MyClass {
    void method() {
        log.info("Message");
    }
}

// Without Lombok
private static final Logger log = LoggerFactory.getLogger(MyClass.class);

Levels

TRACE < DEBUG < INFO < WARN < ERROR

Best Practices

// Placeholders
log.info("User {} logged in", userId);

// Exception with stack trace
log.error("Failed: {}", e.getMessage(), e);

// MDC for context
MDC.put("requestId", "abc-123");

---

🎯 Next Step

You know how to log. Now, let's configure Logback to control where and how logs are written.

➡️ Chapter 4: Logback Configuration

---

⬅️ Back to Module 10