MDC Poisoning — SLF4J/Logback Thread Pool Fix

<!-- 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 {\n\n    // Best practice: logger is static (one per class), final (never reassigned),\n    // and named after the class itself for clear log output.\n    private static final Logger logger = LoggerFactory.getLogger(OrderService.class);\n\n    public Order placeOrder(String customerId, String productSku, int quantity) {\n\n        // MDC — Mapped Diagnostic Context — attaches key-value pairs to EVERY\n        // log line produced on this thread, automatically. This means if you\n        // grep your logs for a customerId, you find ALL related log lines,\n        // not just the ones where you remembered to include the id manually.\n        MDC.put(\"customerId\", customerId);\n        MDC.put(\"productSku\", productSku);\n\n        try {\n            // INFO: a meaningful business event that always matters\n            logger.info(\"Placing order for {} units of SKU {}\", quantity, productSku);\n\n            if (quantity > 1000) {\n                // WARN: something unusual, but we're still handling it\n                logger.warn(\"Large order quantity {} for SKU {} — triggering manual review flag\",\n                        quantity, productSku);\n            }\n\n            // DEBUG: internal state useful during development/diagnosis,\n            // not noise in normal production operation\n            logger.debug(\"Checking inventory for SKU {} — requested qty: {}\", productSku, quantity);\n\n            boolean inventoryAvailable = checkInventory(productSku, quantity);\n\n            if (!inventoryAvailable) {\n                // WARN with context — not an error (expected scenario), but needs attention\n                logger.warn(\"Insufficient inventory for SKU {} — requested: {}, available: {}\",\n                        productSku, quantity, getAvailableStock(productSku));\n                throw new InsufficientStockException(productSku, quantity);\n            }\n\n            Order createdOrder = persistOrder(customerId, productSku, quantity);\n\n            // Confirm success with the generated orderId — makes log lines self-contained\n            logger.info(\"Order {} successfully created for customer {}\",\n                    createdOrder.getOrderId(), customerId);\n\n            return createdOrder;\n\n        } catch (DatabaseException dbEx) {\n            // ERROR: include the exception as the LAST parameter so Logback\n            // prints the full stack trace automatically. Don't call\n            // dbEx.getMessage() yourself — you'll lose the stack trace.\n            logger.error(\"Database failure while persisting order for customer {} SKU {}\",\n                    customerId, productSku, dbEx);\n            throw new OrderProcessingException(\"Order persistence failed\", dbEx);\n\n        } finally {\n            // CRITICAL: always clear MDC at the end of the request/thread boundary.\n            // In thread pool environments, threads are reused. If you don't clear,\n            // the next request on this thread inherits your customerId in its logs.\n            MDC.clear();\n        }\n    }\n\n    // ── Stub methods to make the example compile ──────────────────────────────\n\n    private boolean checkInventory(String sku, int qty) {\n        return true; // simplified for example\n    }\n\n    private int getAvailableStock(String sku) {\n        return 500; // simplified for example\n    }\n\n    private Order persistOrder(String customerId, String sku, int qty) {\n        return new Order(\"ORD-20240115-7829\", customerId, sku, qty);\n    }\n}",
        "output": "14:23:01.442 [main] INFO  c.t.order.OrderService - Placing order for 3 units of SKU WIDGET-42\n14:23:01.445 [main] DEBUG c.t.order.OrderService - Checking inventory for SKU WIDGET-42 — requested qty: 3\n14:23:01.451 [main] INFO  c.t.order.OrderService - Order ORD-20240115-7829 successfully created for customer CUST-881\n\nNote: The MDC values (customerId, productSku) appear in each line when your\nlogback.xml pattern includes %X{customerId} and %X{productSku} in the encoder pattern."
      }

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"));
    }
}

<!-- Wrap the rolling file appender in an async appender -->
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <!-- Maximum number of log events in the queue before discarding -->
    <queueSize>512</queueSize>

    <!-- Discard TRACE/DEBUG/INFO when the queue exceeds this percentage (default 80) -->
    <discardingThreshold>0</discardingThreshold>

    <!-- Never block the application thread -- always prefer dropping events -->
    <neverBlock>true</neverBlock>

    <!-- The real appender that does I/O (rolling file) -->
    <appender-ref ref="ROLLING_FILE"/>
</appender>

<!-- Then reference ASYNC instead of ROLLING_FILE in your logger config -->
<logger name="com.theforge" level="DEBUG" additivity="false">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="ASYNC"/>
</logger>

// io.thecodeforge
<!-- The ONLY logging dependency you need for Logback in Spring Boot 3.x -->
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
    <!-- Exclude default Logback if switching to Log4j2 -->
    <exclusions>
        <exclusion>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>

<!-- When migrating to Log4j2, add this as the single binding -->
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

// io.thecodeforge
<configuration>
    <!-- Your app's custom level -->
    <logger name="com.yourcompany.orderservice" level="DEBUG" />

    <!-- Silence third-party noise -->
    <logger name="org.hibernate.SQL" level="WARN" />
    <logger name="org.apache.tomcat.util.net" level="ERROR" />
    <logger name="org.springframework.web" level="WARN" />

    <!-- Production root level -->
    <root level="INFO">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="FILE" />
    </root>

    <!-- Profile-specific overrides -->
    <springProfile name="dev">
        <logger name="org.hibernate.SQL" level="TRACE" />
    </springProfile>
</configuration>