[logback-user] strange MDC and SMTPAppender behavior

14 Jan 2009

      I'm seeing unexpected behavior when I combine MDC and SMTPAppender.
The MDC values appear to be lost for previous log messages when
MDC.clear is called before Logger.error triggers the actual email.
This does not appear to be a problem with console appender.  Below
is a test program that will reproduce the problem.  A logback.xml
that uses an SMTPAppender and a pattern that includes %mdc is required.

Is there something I'm missing?

Versions:

slf4j-api-1.5.6.jar
logback-core-0.9.14.jar
logback-classic-0.9.14.jar
janino-2.5.14.jar
mail-1.4.1.jar

java version "1.6.0_04"

test program:

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

public class TestMain
{

    public static void main(String[] args)
    {
        Logger logger = LoggerFactory.getLogger("TestMain");

        // test1...
        logger.debug("test1: should not have MDC");
        MDC.put("key1", "val1");
        MDC.put("key2", "val2");
        logger.warn("test1: should have MDC(key1=val1,key2=val2) but
does not");
        MDC.clear();
        logger.debug("test1: should not have MDC");
        logger.error("test1: error message triggers email");

        // test2...
        logger.debug("test2: should not have MDC");
        MDC.put("key1", "val1");
        logger.warn("test2: should have MDC(key1=val1)");
        MDC.put("key2", "val2");
        logger.warn("test2: should have MDC(key1=val1,key2=val2)");
        MDC.put("key3", "val3");
        logger.warn("test2: should have
MDC(key1=val1,key2=val2,key3=val3) but does not");
        MDC.clear();
        logger.debug("test2: should not have MDC");
        logger.error("test2: error message triggers email");

        // test3...
        logger.debug("test3: should not have MDC");
        MDC.put("key1", "val1");
        logger.warn("test3: should have MDC(key1=val1)");
        MDC.put("key2", "val2");
        logger.warn("test3: should have MDC(key1=val1,key2=val2)");
        MDC.put("key3", "val3");
        logger.warn("test3: should have
MDC(key1=val1,key2=val2,key3=val3)");
        MDC.put("key4", "val4");
        logger.warn("test3: should have
MDC(key1=val1,key2=val2,key3=val3,key4=val4) but does not");
        MDC.clear();
        logger.debug("test3: should not have MDC");
        logger.error("test3: error message triggers email");

        // test4...
        logger.debug("test4: should not have MDC");
        MDC.put("key1", "val1");
        logger.warn("test4: should have MDC(key1=val1)");
        MDC.put("key2", "val2");
        logger.error("test4: error message triggers email and has
MDC(key1=val1,key2=val2)");
        MDC.clear();

        logger.debug("test5: should not have MDC");
        MDC.put("key1", "val1");
        logger.warn("test5: should have MDC(key1=val1) but does not");
        MDC.clear();
        logger.debug("test5: should not have MDC");
        MDC.put("key1", "val1");
        logger.warn("test5: should have MDC(key1=val1)");
        logger.error("test5: error message triggers email and should not
have MDC");
    }
}

[logback-user] strange MDC and SMTPAppender behavior

Lucas, Casey