Dynamically Create Logback Loggers and Appenders

Question

I need to dynamically create Logback loggers and sundry bits for classes that load and reload dynamically. I have a variable number of these classes though it will be less than 150 all told. Performance is a big concern and this is a highly-threaded and extremely concurrent environment so the idea of using MDC isn't going to fly due to potentially thousands of calls a second when things go wrong. I also don't want to directly pass the loggers into the classes, I'd like them to just pull them out of the air using getLogger as is typical.

Each class has to log all of it's error messages to it's own error file and all of it's trace messages to it's own trace file. Both of the files need to roll over nightly. Additionally, anything logged in the system has to end up in the main system logs too.

I've created the following code snippet to try this idea out. It SEEMS like it would work but the results are not what I'd expect. Here is the test program that can be run directly:

package logbacktesting;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
import ch.qos.logback.classic.filter.LevelFilter;
import ch.qos.logback.core.rolling.RollingFileAppender;
import ch.qos.logback.core.rolling.TimeBasedRollingPolicy;
import ch.qos.logback.core.spi.FilterReply;
import ch.qos.logback.core.util.StatusPrinter;
import org.slf4j.LoggerFactory;

public class Main {

    public static void main(String[] args) {

        Logger templateLogger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("com.myapp");
        LoggerContext loggerContext = templateLogger.getLoggerContext();

        String[] nameList = new String[] {"test1.class", "test2.class"};

        // Set up the pattern
        PatternLayoutEncoder encoder = new PatternLayoutEncoder();
        encoder.setContext(loggerContext);
        encoder.setPattern("%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n");
        encoder.start();

        // Spin over the names to create all the needed objects
        for(int i = 0; i < nameList.length; i++) {

            String name = nameList[i];

            // Set up the roll over policies and the name when it rolls over
            TimeBasedRollingPolicy tracePolicy = new TimeBasedRollingPolicy();
            tracePolicy.setContext( loggerContext );
            tracePolicy.setFileNamePattern( name + "-Trace-%d{yyyy-MM-dd}.log" );
            tracePolicy.setMaxHistory( 30 );

            TimeBasedRollingPolicy errorPolicy = new TimeBasedRollingPolicy();
            errorPolicy.setContext( loggerContext );
            errorPolicy.setFileNamePattern( name + "-Error-logFile.%d{yyyy-MM-dd}.log" );
            errorPolicy.setMaxHistory( 30 );

            // Set up the filters to ensure things get split as expected
            LevelFilter traceFilter = new LevelFilter();
            traceFilter.setContext( loggerContext );
            traceFilter.setLevel( Level.TRACE );
            traceFilter.setOnMatch( FilterReply.ACCEPT );
            traceFilter.setOnMismatch( FilterReply.DENY );

            LevelFilter errorFilter = new LevelFilter();
            errorFilter.setContext( loggerContext );
            errorFilter.setLevel( Level.ERROR );
            errorFilter.setOnMatch( FilterReply.ACCEPT );
            errorFilter.setOnMismatch( FilterReply.DENY );

            // Set up the trace and error appenders
            RollingFileAppender rollingFileAppenderTrace = new RollingFileAppender();
            rollingFileAppenderTrace.setContext(loggerContext);
            rollingFileAppenderTrace.setName(name + "-Trace");
            rollingFileAppenderTrace.setFile(name + "-Trace.log");
            rollingFileAppenderTrace.setEncoder(encoder);
            rollingFileAppenderTrace.setRollingPolicy( tracePolicy );
            rollingFileAppenderTrace.addFilter( traceFilter );
            tracePolicy.setParent( rollingFileAppenderTrace );

            RollingFileAppender rollingFileAppenderError = new RollingFileAppender();
            rollingFileAppenderError.setContext(loggerContext);
            rollingFileAppenderError.setName(name + "-Error");
            rollingFileAppenderError.setFile(name + "-Error.log");
            rollingFileAppenderError.setEncoder(encoder);
            rollingFileAppenderError.setRollingPolicy( errorPolicy );
            rollingFileAppenderError.addFilter( errorFilter );
            errorPolicy.setParent( rollingFileAppenderError );

            // Start everything
            tracePolicy.start();
            errorPolicy.start();
            traceFilter.start();
            errorFilter.start();
            rollingFileAppenderTrace.start();
            rollingFileAppenderError.start();

            // attach the rolling file appenders to the logger
            Logger logger = (ch.qos.logback.classic.Logger) loggerContext.getLogger(name);
            logger.addAppender(rollingFileAppenderTrace);
            logger.addAppender(rollingFileAppenderError);

        }

        StatusPrinter.print(loggerContext);

        // Test it to see what happens
        for(int i = 0; i < nameList.length; i++) {

            String name = nameList[i];

            Logger logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(name);
            logger.error("error message" );
            logger.warn("warn message" );
            logger.info("info message" );
            logger.debug("debug message" );
            logger.trace("trace message" );
        }

        Logger logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("com.myapp");
        logger.error( "generic error message ");


    }

}

Here is the logback.xml file:

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logFile.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE" />
    </root>

</configuration>

If you run this code, it will properly log everything into the main log file. And it will create 2 trace and 2 error logs as expected. But none of the trace messages will end up in the trace log files and both of the error messages will end up in the class2 error file. It's acting like all 4 appenders are being added to the same logger and only the last appender being added actually works. I'd love to understand what I'm doing where here. Thanks!

Answer 1

everything into the main log file

This is because all loggers will "inherit" the appenders from ROOT logger, you can use logger.setAdditive(false) to disable this behaviour.

But i don't know why you don't have any trace log...

perhaps these two links will give you some inspiration

Logback - set log file name programmatically

how-to-create-logback-loggers-dynamically-pragmatically

Answer 2

There were several problems with the code above. First is what Ceki called out: you can't share encoders. Creating two encoders in the loop changed the behavior in the right direction. Second problem was in the XML file, root level should have been trace, not debug. It was obvious after the encoder change.