Log4j: события появляются в неправильном лог-файле

Question

Чтобы иметь возможность регистрировать и отслеживать некоторые события, я добавил класс LoggingHandler в свой проект Java. Внутри этого класса я использую два разных экземпляра log4j logger - один для регистрации события и один для отслеживания события в разных файлах. Блок инициализации класса выглядит следующим образом:

public void initialize()
{
    System.out.print("starting logging server ...");

    // create logger instances
    logLogger = Logger.getLogger("log");
    traceLogger = Logger.getLogger("trace");

    // create pattern layout
    String conversionPattern = "%c{2} %d{ABSOLUTE} %r %p %m%n";
    try
    {
        patternLayout = new PatternLayout();
        patternLayout.setConversionPattern(conversionPattern);
    }
    catch (Exception e)
    {
        System.out.println("error: could not create logger layout pattern");
        System.out.println(e);
        System.exit(1);
    }

    // add pattern to file appender
    try
    {
        logFileAppender = new FileAppender(patternLayout, logFilename, false);
        traceFileAppender = new FileAppender(patternLayout, traceFilename, false);
    }
    catch (IOException e)
    {
        System.out.println("error: could not add logger layout pattern to corresponding appender");
        System.out.println(e);
        System.exit(1);
    }

    // add appenders to loggers
    logLogger.addAppender(logFileAppender);
    traceLogger.addAppender(traceFileAppender);

    // set logger level
    logLogger.setLevel(Level.INFO);
    traceLogger.setLevel(Level.INFO);

    // start logging server
    loggingServer = new LoggingServer(logLogger, traceLogger, serverPort, this);
    loggingServer.start();

    System.out.println(" done");
}

Чтобы убедиться, что только один поток использует функциональность экземпляра средства ведения журнала, в то же время каждый метод ведения журнала / трассировки вызывает метод ведения журнала .info () внутри синхронизированного блока. Один пример выглядит так:

    public void logMessage(String message)
{
    synchronized (logLogger)
    {
        if (logLogger.isInfoEnabled() && logFileAppender != null)
        {
            logLogger.info(instanceName + ": " + message);
        }
    }
} 

Если я смотрю на файлы журналов, я вижу, что иногда событие появляется не в том файле. Один пример:

trace 10:41:30,773 11080 INFO masterControl(192.168.2.21): string broadcast message was  pushed from 1267093 to vehicle 1055293 (slaveControl 1)
trace 10:41:30,784 11091 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1156513 to vehicle 1105792 (slaveControl 1)
trace 10:41:30,796 11103 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1104306 to vehicle 1055293 (slaveControl 1)
trace 10:41:30,808 11115 INFO masterControl(192.168.2.21): vehicle 1327879 was pushed to slave control 1
10:41:30,808 11115 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1101572 to vehicle 106741 (slaveControl 1)
trace 10:41:30,820 11127 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1055293 to vehicle 1104306 (slaveControl 1)

Я думаю, что проблема возникает каждый раз, когда два события происходят одновременно (здесь: 10: 41: 30,808). У кого-нибудь есть идеи, как решить мою проблему? Я уже пытался добавить sleep () после вызова метода, но это не помогло ...

BR

Markus

Edit:

logtrace  11:16:07,75511:16:07,755  1129711297  INFOINFO  masterControl(192.168.2.21): string broadcast message was pushed from 1291400 to vehicle 1138272 (slaveControl 1)masterControl(192.168.2.21): vehicle 1333770 was added to slave control 1

или

log 11:16:08,562 12104 INFO 11:16:08,562 masterControl(192.168.2.21): string broadcast message was pushed from 117772 to vehicle 1217744 (slaveControl 1)

12104 INFO masterControl (192.168.2.21): автомобиль 1169775 переведен в режим подчиненного управления 1

Редактировать 2:

Кажется, что проблема возникает, только если методы ведения журнала вызываются из потока RMI (мой клиент / сервер обменивается информацией с использованием соединений RMI). ...

Редактировать 3:

Я решил проблему самостоятельно: похоже, что log4j НЕ полностью сохраняет потоки. После синхронизации всех методов log / trace с использованием отдельного объекта все работает нормально. Может быть, библиотека записывает сообщения в небезопасный буфер перед записью их в файл?

Answer 1

Может ли быть так, что метод инициализации вызывается более одного раза? При каждом вызове добавляются два новых приложения, которые записывают в тот же файл, что и существующие приложения.

Answer 2

Этому вопросу 4 года, но я только что столкнулся с этой же проблемой в 2013 году, и, думаю, я исправил ее, создав новый шаблон PatternLayout для каждого Appender. Надеюсь, что в будущем это поможет кому-то еще с той же проблемой.

Answer 3

Вам не нужно синхронизироваться на вашем регистраторе, но на выходном потоке.

Если вы используете log4j, выходные данные должны быть правильно синхронизированы. Единственный способ получить то, что вы видите, состоит в том, что два потока пишут в один и тот же файл одновременно.

Возможно ли, что вы настроили два приложения с одним выходным файлом? Не делай этого; у каждого аппендера должно быть свое собственное имя файла.

Если вы на 100% уверены, что каждый аппендер пишет в отдельный файл, остается только один вариант - вы иногда используете неправильный регистратор.