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();

    }

}

Normally, you don't bother with appenders in your code. You just get your logger, like `private static final Logger LOGGER = Logger.getLogger( ScheduledAction.class );`, and then just `log()` your messages as desired. If, how, and where those messages are output or stored is defined by your log4j configuration file. See [here](https://logging.apache.org/log4j/2.x/manual/configuration.html) for example, or have a look at the `log4j.properties` syntax. This will allow you to add multiple appenders to each logger and to filter which log messages go where, all through configuration. — JimmyB, Mar 09 '16 at 13:21
Yes I understand but it my case I want to add an appender for the lifetime of the timer method so I can capture any log statements, then remove it, which is why I am adding it programatically — DaveB, Mar 09 '16 at 14:49

Ferran Maylinch · Answer 1 · 2022-02-09T12:43:01.770

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".

score 0 · Answer 2 · answered Feb 09 '22 at 14:56

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

score 0 · Answer 3 · answered Feb 11 '22 at 16:03

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();

log4j - Intercept logging created within a class/method

3 Answers3