log4j - Intercept logging created within a class/method

Question

I have an App which has many ejb Timer methods which are fired at various intervals, in an attempt to log the performance of these scheduled tasks I have written two methods which log the start and end of every task and records some info such as name, running duration and log info each time the timer fires

The intention with log info was to intercept all logging statements raised from within these methods, output to a string and save...I am doing this by creating a new WriterAppender, appending to the Logger for all logging levels, then when the timer completes capture the string output and remove the appender

This works well but it seems to have 2 unwanted effects:

1) It is stopping any logging from the timer class appearing in our normal file appender logs, eg. the log messages are being captured but they now don't appear in our normal logs (which are configured to show everything > INFO

2) Logging statements from different timers which overlap are appearing in each other logs, I guess this is the result of the Logger working on a single thread, not sure if theres a way around this?

I am no expert in log4j so I am hoping someone can point out a simple fix for 1, 2 or both

Code below shows the 2 methods which are called at start and end of every job

private Writer w = new StringWriter();
private WriterAppender wa;
private Logger logOutput = Logger.getLogger(ScheduledActions.class);

private TimerEvent logStartTimerEvent(ScheduledTask task){

    RedisActions redisActions = (RedisActions)Component.getInstance("redisActions");
    TimerEvent event = new TimerEvent(task);

    //Initialise a new log appender to intercept all log4j entries
    w = new StringWriter();
    Layout l = new PatternLayout("%m%n");
    wa = new WriterAppender(l, w);
    wa.setEncoding("UTF-8");
    wa.setThreshold(Level.ALL);
    wa.activateOptions();

    // Add it to logger
    logOutput = Logger.getLogger(ScheduledActions.class);
    logOutput.addAppender(wa);

    //Push this timer event to redis
    redisActions.addToFixedLengthList(RedisItem.TIMER_HISTORY.getKey()+"_"+task.getName(), gson.toJson(event), 100L);

    return event;
}

private void logEndTimerEvent(TimerEvent event){

    try{

        RedisActions redisActions = (RedisActions)Component.getInstance("redisActions");
        event.setLogInfo(w.toString());
        event.setEndTime(new Date());
        redisActions.editLastMemberInList(RedisItem.TIMER_HISTORY.getKey()+"_"+event.getTask().getName(), gson.toJson(event));
        w.flush();

    } catch (IOException e) {
        e.printStackTrace();
    }finally{
        //clean up the temp log appender
        logOutput.removeAppender(wa);
        wa.close();

    }

}

Answer 1

My final solution is adding an Appender with ThreadContextMapFilter.

    // With %X you will see the thread context values
    var layout = PatternLayout.newBuilder()
            .withPattern("%d{ISO8601_OFFSET_DATE_TIME_HHCMM} [%t] %-5level %c{1.} %X %msg%n%throwable")
            .build();

    var appender = FileAppender.newBuilder()
            .setName(fileId)
            .withFileName("/tmp/my-file.log")
            .setLayout(layout)
            // --- IMPORTANT PART ---
            .setFilter(new ThreadContextMapFilter(
                    Map.of("my-key", List.of("my-value")), true, null, null))
            .build();

    // Add the appender
    // https://logging.apache.org/log4j/2.x/manual/customconfig.html
    appender.start();
    final LoggerContext context = LoggerContext.getContext(false);
    final Configuration config = context.getConfiguration();
    config.addAppender(appender);
    config.getRootLogger().addAppender(appender, null, null);
    context.updateLoggers();

    // --- IMPORTANT PART ---
    try (var ignore = CloseableThreadContext.put("my-key", "my-value")) {
        // the logs here will be captured by the appender
        log.info("This log WILL be captured by the appender");

        // Note: In case you start threads from here,
        // you should pass the ThreadContext to them.
    }

    log.info("This log will NOT be captured by the appender");

    // Wait for the logs to be flushed. Any improvement ideas?
    // https://stackoverflow.com/a/71081005/1121497
    try {
        Thread.sleep(500);
    } catch (InterruptedException ignore) {
    }

    // Remove the appender
    final LoggerContext context = LoggerContext.getContext(false);
    final Configuration config = context.getConfiguration();
    config.getRootLogger().removeAppender(appender.getName());
    context.updateLoggers();
    appender.stop();

Answer 2

Another solution that I am considering, is adding an AbstractAppender to the rootLogger, and from there do whatever with the logs.

I will update this answer when I develop it a bit more.

var layout = PatternLayout.newBuilder()
        .withPattern("%d{ISO8601_OFFSET_DATE_TIME_HHCMM} [%t] %-5level  %c{1.} %X %msg%n%throwable")
        .build();

var rootLogger = (org.apache.logging.log4j.core.Logger) LogManager.getRootLogger();

var appender = new AbstractAppender("intercept-appender", null, layout, false, null) {
    @Override
    public void append(LogEvent event) {
        System.out.println("INTERCEPTED: " + getLayout().toSerializable(event));
    }
};

appender.start();
rootLogger.addAppender(appender);

log.info("Message after adding intercept appender");

Answer 3

I found this old question while trying to do something similar. For now, my solution is creating an independent logger/appender, with a unique loggerId, like:

var loggerId = operation.getId(); // This is a unique ID
var logger = (org.apache.logging.log4j.core.Logger) LogManager.getLogger(loggerId);
var appender = createAppender();
logger.addAppender(appender);

logger.info("using logger");

appender.stop();
logger.removeAppender(appender);

The problem that I have is that I need to pass this logger variable around. I can't use the classic "static logger".