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

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

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,

Маркус

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

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

or

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 НЕ полностью сохраняет потоки. После синхронизации всех методов лога/трассировки с помощью отдельного объекта все работает нормально. Может быть, библиотека записывает сообщения в небезопасный для потоков буфер, прежде чем записывать их в файл?


person Markus    schedule 28.08.2009    source источник


Ответы (3)


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

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

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

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

person Aaron Digulla    schedule 28.08.2009
comment
Если под выходным потоком вы имеете в виду аппендер, аппендеры являются потокобезопасными: метод doAppend равен synchronized. - person Vinay Sajip; 28.08.2009
comment
После синхронизации файловых приложений проблема все еще существует (см. пример выше). Может быть, мне нужно поместить экземпляры регистратора в разные потоки? - person Markus; 28.08.2009
comment
Нет, как вы можете видеть в методе инициализации, оба приложения связаны с разными файлами (logFilename и traceFilename), но они используют один и тот же шаблон. Несколько минут назад я пытался перенести регистрацию/отслеживание в разные потоки, но это тоже не помогло. - person Markus; 28.08.2009
comment
Кстати: я использую log4j 1.2 и Java 1.6.0_14. - person Markus; 28.08.2009
comment
Какая версия, если log4j 1.2? 1.2.15? Не то чтобы это имело значение, но, возможно, вы столкнулись с неясной ошибкой. Перемещение его в разные потоки должно только усугубить ситуацию. - person Aaron Digulla; 28.08.2009
comment
Ооо, конечно это версия 1.2.15. Я отправил свою проблему в список рассылки пользователей log4j. Может у них есть решение моей проблемы... - person Markus; 28.08.2009
comment
Я не вижу в ваших примерах, что содержимое двух переменных отличается, но если вы видите два файла на жестком диске, то все в порядке. - person Aaron Digulla; 28.08.2009
comment
Что это за LoggingServer? Регистрация удаленная? - person Aaron Digulla; 28.08.2009
comment
Да, на жестком диске есть два файла. LoggingServer получает сообщения журнала/трассировки как LoggingEvents от клиента (моя программа имеет клиент-серверную архитектуру) и добавляет эти сообщения в экземпляры регистратора. Чтобы изолировать ошибку, я в настоящее время отключил сервер. - person Markus; 28.08.2009
comment
Поскольку log4j сохраняет потоки, и вы не пишете в один и тот же файл из двух потоков, единственный оставшийся вариант — иногда вы используете неправильный регистратор. - person Aaron Digulla; 28.08.2009
comment
Оба потока используют функциональность моего класса loggingHandler. Поэтому они пишут в один и тот же файл. Я думаю, что обычно синхронизированный блок должен избегать, чтобы я получал такие странные сообщения журнала. Посмотрю еще раз на своих регистраторах. Может быть, вы правы. - person Markus; 28.08.2009

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

person Wolfgang    schedule 28.08.2009

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

person lancex    schedule 22.11.2013