Java Logging with SLF4J and Logback — The Complete Practical Guide

<!-- Add these dependencies to your Maven pom.xml -->
<dependencies>

    <!-- SLF4J API — the facade your code compiles against.
         No logging actually happens from this jar alone. -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>2.0.13</version>
    </dependency>

    <!-- Logback Classic — the actual implementation.
         This jar ALSO provides the SLF4J binding automatically,
         so you do NOT need a separate slf4j-logback-binding artifact. -->
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.5.6</version>
    </dependency>

    <!-- logback-classic already pulls in logback-core transitively,
         so you don't need to declare logback-core explicitly. -->

</dependencies>

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <!-- ─────────────────────────────────────────────
         APPENDER: CONSOLE
         Writes formatted log lines to System.out.
         Good for local dev and containerised apps
         where stdout is captured by the platform.
    ───────────────────────────────────────────── -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <!-- Pattern breakdown:
                 %d{HH:mm:ss.SSS}   — timestamp
                 [%thread]          — thread name (vital for async apps)
                 %-5level           — log level, left-padded to 5 chars
                 %logger{36}        — logger name, truncated to 36 chars
                 - %msg%n           — the actual message, then newline -->
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- ─────────────────────────────────────────────
         APPENDER: ROLLING FILE
         Writes to a file. When the file hits 10MB,
         it rolls over to a new file. Keeps 30 days
         of history and caps total size at 1GB so
         your disk doesn't silently fill up.
    ───────────────────────────────────────────── -->
    <appender name="ROLLING_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- The active log file always has this name -->
        <file>logs/application.log</file>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- Archive pattern: one file per day, gzip compressed -->
            <fileNamePattern>logs/application.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>

            <timeBasedFileNamingAndTriggeringPolicy
                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- Roll over when a single file reaches 10MB -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>

            <!-- Keep 30 days of rolled files -->
            <maxHistory>30</maxHistory>

            <!-- Hard cap on total log storage across all rolled files -->
            <totalSizeCap>1GB</totalSizeCap>
        </rollingPolicy>

        <encoder>
            <!-- File logs include the full logger name for easier grepping -->
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- ─────────────────────────────────────────────
         PACKAGE-LEVEL LOGGER OVERRIDE
         Only log DEBUG and above for our own code.
         This won't affect Hibernate, Spring, or any
         other library — they stay at their own levels.
    ───────────────────────────────────────────── -->
    <logger name="com.theforge" level="DEBUG" additivity="false">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="ROLLING_FILE"/>
    </logger>

    <!-- ─────────────────────────────────────────────
         ROOT LOGGER
         Catches everything not matched by a more
         specific logger above. Set to WARN in prod
         to suppress noisy INFO from libraries.
    ───────────────────────────────────────────── -->
    <root level="WARN">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="ROLLING_FILE"/>
    </root>

</configuration>

package com.theforge.order;

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

/**
 * Real-world service class showing correct SLF4J logging patterns.
 * Notice the Logger is static final — one instance per class, shared
 * across all method calls. Creating a new Logger per method call is
 * wasteful and unnecessary.
 */
public class OrderService {

    // Best practice: logger is static (one per class), final (never reassigned),
    // and named after the class itself for clear log output.
    private static final Logger logger = LoggerFactory.getLogger(OrderService.class);

    public Order placeOrder(String customerId, String productSku, int quantity) {

        // MDC — Mapped Diagnostic Context — attaches key-value pairs to EVERY
        // log line produced on this thread, automatically. This means if you
        // grep your logs for a customerId, you find ALL related log lines,
        // not just the ones where you remembered to include the id manually.
        MDC.put("customerId", customerId);
        MDC.put("productSku", productSku);

        try {
            // INFO: a meaningful business event that always matters
            logger.info("Placing order for {} units of SKU {}", quantity, productSku);

            if (quantity > 1000) {
                // WARN: something unusual, but we're still handling it
                logger.warn("Large order quantity {} for SKU {} — triggering manual review flag",
                        quantity, productSku);
            }

            // DEBUG: internal state useful during development/diagnosis,
            // not noise in normal production operation
            logger.debug("Checking inventory for SKU {} — requested qty: {}", productSku, quantity);

            boolean inventoryAvailable = checkInventory(productSku, quantity);

            if (!inventoryAvailable) {
                // WARN with context — not an error (expected scenario), but needs attention
                logger.warn("Insufficient inventory for SKU {} — requested: {}, available: {}",
                        productSku, quantity, getAvailableStock(productSku));
                throw new InsufficientStockException(productSku, quantity);
            }

            Order createdOrder = persistOrder(customerId, productSku, quantity);

            // Confirm success with the generated orderId — makes log lines self-contained
            logger.info("Order {} successfully created for customer {}",
                    createdOrder.getOrderId(), customerId);

            return createdOrder;

        } catch (DatabaseException dbEx) {
            // ERROR: include the exception as the LAST parameter so Logback
            // prints the full stack trace automatically. Don't call
            // dbEx.getMessage() yourself — you'll lose the stack trace.
            logger.error("Database failure while persisting order for customer {} SKU {}",
                    customerId, productSku, dbEx);
            throw new OrderProcessingException("Order persistence failed", dbEx);

        } finally {
            // CRITICAL: always clear MDC at the end of the request/thread boundary.
            // In thread pool environments, threads are reused. If you don't clear,
            // the next request on this thread inherits your customerId in its logs.
            MDC.clear();
        }
    }

    // ── Stub methods to make the example compile ──────────────────────────────

    private boolean checkInventory(String sku, int qty) {
        return true; // simplified for example
    }

    private int getAvailableStock(String sku) {
        return 500; // simplified for example
    }

    private Order persistOrder(String customerId, String sku, int qty) {
        return new Order("ORD-20240115-7829", customerId, sku, qty);
    }
}

package com.theforge.order;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;

import java.util.List;

import static org.assertj.core.api.Assertions.assertThat;

/**
 * Proves that OrderService emits the correct log events.
 * Log messages are part of your observable behaviour — test them.
 */
class OrderServiceLoggingTest {

    private ListAppender<ILoggingEvent> logCapture;
    private Logger orderServiceLogger;
    private OrderService orderService;

    @BeforeEach
    void attachLogCapture() {
        // Cast to Logback's concrete Logger (not SLF4J's interface)
        // so we can manipulate it programmatically in the test.
        orderServiceLogger = (Logger) LoggerFactory.getLogger(OrderService.class);

        // ListAppender stores every log event in an in-memory list.
        // Perfect for assertions — no file I/O, no console noise.
        logCapture = new ListAppender<>();
        logCapture.start();

        // Attach our capture appender to the service's logger
        orderServiceLogger.addAppender(logCapture);

        // Make sure DEBUG events reach us during the test
        orderServiceLogger.setLevel(Level.DEBUG);

        orderService = new OrderService();
    }

    @AfterEach
    void detachLogCapture() {
        // Always clean up — leaving a stale appender affects other tests
        orderServiceLogger.detachAppender(logCapture);
    }

    @Test
    void shouldLogInfoWhenOrderIsSuccessfullyPlaced() {
        orderService.placeOrder("CUST-881", "WIDGET-42", 3);

        List<ILoggingEvent> capturedEvents = logCapture.list;

        // Assert that at least one INFO message confirms the order was created
        assertThat(capturedEvents)
                .filteredOn(event -> event.getLevel() == Level.INFO)
                .extracting(ILoggingEvent::getFormattedMessage)
                .anyMatch(message -> message.contains("successfully created"));
    }

    @Test
    void shouldLogWarnForLargeOrderQuantity() {
        // A quantity over 1000 should trigger a WARN in OrderService
        orderService.placeOrder("CUST-002", "BULK-SKU-9", 1500);

        List<ILoggingEvent> capturedEvents = logCapture.list;

        assertThat(capturedEvents)
                .filteredOn(event -> event.getLevel() == Level.WARN)
                .extracting(ILoggingEvent::getFormattedMessage)
                .anyMatch(message -> message.contains("Large order quantity"));
    }

    @Test
    void debugMessagesShouldIncludeSkuInformation() {
        orderService.placeOrder("CUST-333", "GADGET-7", 2);

        assertThat(logCapture.list)
                .filteredOn(event -> event.getLevel() == Level.DEBUG)
                .extracting(ILoggingEvent::getFormattedMessage)
                .anyMatch(message -> message.contains("GADGET-7"));
    }
}