Skip to main content

TP10.2 - Professional Logging System

Objectives of the Lab​

In this lab, you will:

  1. ✅ Configure Logback with logback-spring.xml
  2. ✅ Create environment-specific configurations
  3. ✅ Implement MDC for traceability
  4. ✅ Configure log file rotation
  5. ✅ Add structured logs to the application

Estimated duration: 1h30

Context​

You are taking over the Bookstore application from TP10.1 and adding a professional logging system for monitoring and debugging in production.

Part 1: Logback Configuration​

Create logback-spring.xml​

Create src/main/resources/logback-spring.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">

    <!-- Import Spring Boot defaults -->
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    
    <!-- Properties -->
    <springProperty scope="context" name="APP_NAME" source="spring.application.name" defaultValue="bookstore"/>
    <property name="LOG_PATH" value="${LOG_PATH:-logs}"/>
    <property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{requestId:-N/A}] [%X{userId:-anonymous}] %-5level %logger{36} - %msg%n"/>

    <!-- ===== CONSOLE APPENDER ===== -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%X{requestId:-}] %highlight(%-5level) %cyan(%logger{36}) - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- ===== FILE APPENDER ===== -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}/${APP_NAME}.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/archived/${APP_NAME}.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
            <maxFileSize>10MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>1GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <!-- ===== ERROR FILE APPENDER ===== -->
    <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}/${APP_NAME}-error.log</file>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/archived/${APP_NAME}-error.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
            <maxFileSize>10MB</maxFileSize>
            <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <!-- TODO: Add dev, prod, test profiles -->

</configuration>

Part 2: Logging Profiles​

Add profiles in logback-spring.xml​

    <!-- ===== DEV PROFILE ===== -->
    <springProfile name="dev,local">
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
        
        <!-- Application in DEBUG -->
        <logger name="com.bookstore" level="DEBUG"/>
        
        <!-- SQL Queries -->
        <logger name="org.hibernate.SQL" level="DEBUG"/>
        <logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="TRACE"/>
        
        <!-- Spring Web -->
        <logger name="org.springframework.web" level="DEBUG"/>
    </springProfile>

    <!-- ===== PROD PROFILE ===== -->
    <springProfile name="prod">
        <root level="WARN">
            <appender-ref ref="FILE"/>
            <appender-ref ref="ERROR_FILE"/>
        </root>
        
        <logger name="com.bookstore" level="INFO"/>
    </springProfile>

    <!-- ===== TEST PROFILE ===== -->
    <springProfile name="test">
        <root level="WARN">
            <appender-ref ref="CONSOLE"/>
        </root>
        <logger name="com.bookstore" level="INFO"/>
    </springProfile>

    <!-- ===== DEFAULT ===== -->
    <springProfile name="default">
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="FILE"/>
        </root>
        <logger name="com.bookstore" level="DEBUG"/>
    </springProfile>

Part 3: MDC Filter​

MdcLoggingFilter​

package com.bookstore.filter;

import jakarta.servlet.FilterChain;
import jakarta.servlet.ServletException;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import org.slf4j.MDC;
import org.springframework.core.Ordered;
import org.springframework.core.annotation.Order;
import org.springframework.security.core.Authentication;
import org.springframework.security.core.context.SecurityContextHolder;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;

import java.io.IOException;
import java.util.UUID;

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

    private static final String REQUEST_ID = "requestId";
    private static final String USER_ID = "userId";
    private static final String PATH = "path";
    private static final String METHOD = "method";

    @Override
    protected void doFilterInternal(HttpServletRequest request,
                                     HttpServletResponse response,
                                     FilterChain filterChain) 
            throws ServletException, IOException {
        
        long startTime = System.currentTimeMillis();
        
        try {
            // Generate or retrieve the Request ID
            String requestId = request.getHeader("X-Request-ID");
            if (requestId == null || requestId.isBlank()) {
                requestId = UUID.randomUUID().toString().substring(0, 8);
            }
            
            // Add to MDC
            MDC.put(REQUEST_ID, requestId);
            MDC.put(PATH, request.getRequestURI());
            MDC.put(METHOD, request.getMethod());
            
            // Add User ID if authenticated
            Authentication auth = SecurityContextHolder.getContext().getAuthentication();
            if (auth != null && auth.isAuthenticated() && !"anonymousUser".equals(auth.getPrincipal())) {
                MDC.put(USER_ID, auth.getName());
            }
            
            // Add Request ID to the response
            response.setHeader("X-Request-ID", requestId);
            
            // Continue the chain
            filterChain.doFilter(request, response);
            
        } finally {
            // Log completed request
            long duration = System.currentTimeMillis() - startTime;
            logger.info("Request completed: {} {} - Status: {} - Duration: {}ms",
                MDC.get(METHOD), MDC.get(PATH), response.getStatus(), duration);
            
            // IMPORTANT: Always clear the MDC!
            MDC.clear();
        }
    }
    
    @Override
    protected boolean shouldNotFilter(HttpServletRequest request) {
        // Do not filter static resources
        String path = request.getRequestURI();
        return path.startsWith("/css/") 
            || path.startsWith("/js/") 
            || path.startsWith("/images/")
            || path.equals("/favicon.ico");
    }
}

Part 4: Add Logs to the Code​

BookService with Logging​

package com.bookstore.service;

import com.bookstore.entity.Book;
import com.bookstore.exception.*;
import com.bookstore.repository.BookRepository;
import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;
import org.springframework.transaction.annotation.Transactional;

import java.util.List;

@Service
@RequiredArgsConstructor
@Slf4j
public class BookService {
    
    private final BookRepository bookRepository;
    
    public List<Book> findAll() {
        log.debug("Fetching all books");
        List<Book> books = bookRepository.findAll();
        log.debug("Found {} books", books.size());
        return books;
    }
    
    public Book findById(Long id) {
        log.debug("Finding book with ID: {}", id);
        return bookRepository.findById(id)
            .orElseThrow(() -> {
                log.warn("Book not found with ID: {}", id);
                return new ResourceNotFoundException("Book", id);
            });
    }
    
    @Transactional
    public Book create(Book book) {
        log.info("Creating new book: title='{}', author='{}', isbn='{}'", 
            book.getTitle(), book.getAuthor(), book.getIsbn());
        
        if (bookRepository.existsByIsbn(book.getIsbn())) {
            log.warn("Attempt to create book with duplicate ISBN: {}", book.getIsbn());
            throw new ConflictException("ISBN already exists: " + book.getIsbn());
        }
        
        Book saved = bookRepository.save(book);
        log.info("Book created successfully with ID: {}", saved.getId());
        return saved;
    }
    
    @Transactional
    public Book update(Long id, Book updated) {
        log.info("Updating book with ID: {}", id);
        log.debug("New values: title='{}', price={}", updated.getTitle(), updated.getPrice());
        
        Book existing = findById(id);
        
        if (!existing.getIsbn().equals(updated.getIsbn()) 
                && bookRepository.existsByIsbn(updated.getIsbn())) {
            log.warn("Attempt to change ISBN to existing value: {}", updated.getIsbn());
            throw new ConflictException("ISBN already exists: " + updated.getIsbn());
        }
        
        existing.setTitle(updated.getTitle());
        existing.setAuthor(updated.getAuthor());
        existing.setIsbn(updated.getIsbn());
        existing.setPrice(updated.getPrice());
        existing.setStock(updated.getStock());
        
        Book saved = bookRepository.save(existing);
        log.info("Book {} updated successfully", id);
        return saved;
    }
    
    @Transactional
    public void delete(Long id) {
        log.info("Deleting book with ID: {}", id);
        Book book = findById(id);
        bookRepository.delete(book);
        log.info("Book {} deleted successfully", id);
    }
    
    @Transactional
    public void decreaseStock(Long id, int quantity) {
        log.info("Decreasing stock for book {}: quantity={}", id, quantity);
        
        Book book = findById(id);
        log.debug("Current stock: {}", book.getStock());
        
        if (book.getStock() < quantity) {
            log.warn("Insufficient stock for book {}: available={}, requested={}", 
                id, book.getStock(), quantity);
            throw new BusinessRuleException(
                "INSUFFICIENT_STOCK",
                String.format("Not enough stock. Available: %d, Requested: %d", 
                    book.getStock(), quantity)
            );
        }
        
        book.setStock(book.getStock() - quantity);
        bookRepository.save(book);
        log.info("Stock decreased for book {}: new stock={}", id, book.getStock());
    }
}

GlobalExceptionHandler with Logging​

Update the handler to include appropriate logs:

@ExceptionHandler(ResourceNotFoundException.class)
@ResponseStatus(HttpStatus.NOT_FOUND)
public ErrorResponse handleResourceNotFound(ResourceNotFoundException ex, HttpServletRequest request) {
    // WARN because it's a client error, not a server error
    log.warn("Resource not found: {} at {}", ex.getMessage(), request.getRequestURI());
    return ErrorResponse.of(ex.getErrorCode(), ex.getMessage(), request.getRequestURI());
}

@ExceptionHandler(Exception.class)
@ResponseStatus(HttpStatus.INTERNAL_SERVER_ERROR)
public ErrorResponse handleGeneric(Exception ex, HttpServletRequest request) {
    // ERROR with stack trace for unexpected errors
    log.error("Unexpected error at {}: {}", request.getRequestURI(), ex.getMessage(), ex);
    return ErrorResponse.of("INTERNAL_ERROR", "An unexpected error occurred", request.getRequestURI());
}

Part 5: Test the Logging​

Start with the dev profile​

mvn spring-boot:run -Dspring-boot.run.profiles=dev

Test 1: Create a book​

curl -X POST http://localhost:8080/api/books \
  -H "Content-Type: application/json" \
  -H "X-Request-ID: TEST-001" \
  -d '{
    "title": "Effective Java",
    "author": "Joshua Bloch",
    "isbn": "9780134685991",
    "price": 45.00,
    "stock": 15
  }'

Expected logs:

12:00:00.123 [TEST-001] INFO  BookController - Received create book request
12:00:00.125 [TEST-001] INFO  BookService - Creating new book: title='Effective Java', author='Joshua Bloch', isbn='9780134685991'
12:00:00.150 [TEST-001] INFO  BookService - Book created successfully with ID: 1
12:00:00.155 [TEST-001] INFO  MdcLoggingFilter - Request completed: POST /api/books - Status: 201 - Duration: 32ms

Test 2: Book not found​

curl http://localhost:8080/api/books/999 \
  -H "X-Request-ID: TEST-002"

Expected logs:

12:01:00.100 [TEST-002] DEBUG BookService - Finding book with ID: 999
12:01:00.102 [TEST-002] WARN  BookService - Book not found with ID: 999
12:01:00.103 [TEST-002] WARN  GlobalExceptionHandler - Resource not found: Book with ID '999' not found at /api/books/999
12:01:00.105 [TEST-002] INFO  MdcLoggingFilter - Request completed: GET /api/books/999 - Status: 404 - Duration: 5ms

Test 3: Check log files​

# Check the log file content
cat logs/bookstore.log

# Check the error log file
cat logs/bookstore-error.log

Part 6: Production Configuration (Bonus)​

JSON Logs with Logstash Encoder​

Add the dependency:

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

Add the appender in logback-spring.xml:

<!-- ===== JSON FILE APPENDER (for ELK/Datadog) ===== -->
<appender name="JSON_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_PATH}/${APP_NAME}.json</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>${LOG_PATH}/archived/${APP_NAME}.%d{yyyy-MM-dd}.%i.json.gz</fileNamePattern>
        <maxFileSize>50MB</maxFileSize>
        <maxHistory>7</maxHistory>
    </rollingPolicy>
    <encoder class="net.logstash.logback.encoder.LogstashEncoder">
        <includeMdcKeyName>requestId</includeMdcKeyName>
        <includeMdcKeyName>userId</includeMdcKeyName>
        <includeMdcKeyName>path</includeMdcKeyName>
        <customFields>{"app":"bookstore","env":"prod"}</customFields>
    </encoder>
</appender>

<springProfile name="prod">
    <root level="INFO">
        <appender-ref ref="JSON_FILE"/>
        <appender-ref ref="ERROR_FILE"/>
    </root>
    <logger name="com.bookstore" level="INFO"/>
</springProfile>

Checklist​

  • logback-spring.xml created and functional
  • dev/prod/test profiles configured
  • MdcLoggingFilter implements requestId
  • Structured logs in the service
  • Log files created in /logs
  • File rotation configured
  • X-Request-ID returned in response headers

🎯 Module Completed!​

Congratulations! You have completed Module 10 - Exception Management and Logging.

Summary:

  • Chapter 1: Custom exceptions
  • Chapter 2: @ControllerAdvice
  • Chapter 3: SLF4J
  • Chapter 4: Logback
  • TP10.1: Centralized error handling
  • TP10.2: Logging system

➡️ Back to Module 10

⬅️ Back to Course Plan