В конце концов, log4j не безопасен для потоков? - PullRequest
Новая
       22

В конце концов, log4j не безопасен для потоков?

6 голосов
/ 23 марта 2012

(это на SLES11, Java 7, Tomcat 6, log4j-1.2.16)

Мы используем log4j для записи разных вещей в разные лог-файлы. Я унаследовал этот код, так что, хорошо это или плохо, общая структура здесь пока остается.

Регистратор создаст два файла журнала: main.log и stats.log. Определенное статистическое сообщение регистрируется в обоих регистраторах с помощью отдельных вызовов (вы увидите ниже), а целый ряд других вещей регистрируется в основном журнале.

Так что во всем нашем коде вы увидите такие вещи, как Log.logMain(someMessageToLog);. В одном месте нашего кода (который выполняется несколькими потоками) есть следующее: 

String statsMessage = createStatsMessage();
Log.logMain(statsMessage);
Log.logStats(statsMessage);

Имя главного регистратора - main, имя регистратора статистики - stats. Проблема в том, что иногда при большой нагрузке мы видим строки в main.log, в которых есть строка stats INFO. Все в main.log должно содержать только main INFO, потому что это единственный регистратор, регистрирующий этот файл, плюс мы видим смешанный вывод в некоторых строках. Это похоже на проблему безопасности потока, но в документации log4j говорится, что log4j является потокобезопасным. Вот пример того, что я имею в виду: 

2012-03-21 16:01:34,7742012-03-21 16:01:34,774| | stats main INFO   [INFO  http-8080-18]:  [message redacted]. 
2012-03-21 16:01:36,380| main 2012-03-21 16:01:36,380| INFO   [stats INFO  http-8080-15]: [message redacted]. 
2012-03-21 16:01:37,465| main INFO  2012-03-21 16:01:37,465 [| stats http-8080-1]: [message redacted].

Вот класс Log (урезанный, чтобы показать только те регистраторы, о которых идет речь - на самом деле в нем есть куча других регистраторов, все настроены так же): 

import org.apache.log4j.*;

import java.io.IOException;

final public class Log
{
    private static final String LOG_IDENTIFIER_MAINLOG = "main";
    private static final String LOG_IDENTIFIER_STATSLOG = "stats";

    private static final String MAIN_FILENAME = "/var/log/app_main.log";
    private static final String STATS_FILENAME = "/var/log/app_stats.log";

    private static final int BACKUP_INDEX = 40;
    private static final String BACKUP_SIZE = "10MB";

    private static final PatternLayout COMMON_LAYOUT =
        new PatternLayout("%d| %c %-6p [%t]: %m.%n");

    private static Logger mainLogger;
    private static Logger statsLogger;

    public static void init() {
        init(MAIN_FILENAME, STATS_FILENAME);
    }

    public static void init(String mainLogFilename,
                            String statsLogFilename) {
        mainLogger = initializeMainLogger(mainLogFilename);
        statsLogger = initializeStatsLogger(statsLogFilename);
    }

    public static void logMain(String message) {
        if (mainLogger != null) {
            mainLogger.info(message);
        }
    }

    public static void logStats(String message) {
        if (statsLogger != null) {
            statsLogger.info(message);
        }
    }

    private static Logger getLogger(String loggerIdentifier) {
        Logger logger = Logger.getLogger(loggerIdentifier);
        logger.setAdditivity(false);
        return logger;
    }

    private static boolean addFileAppender(Logger logger,
                                           String logFilename,
                                           int    maxBackupIndex,
                                           String maxSize) {
        try {
            RollingFileAppender appender =
                new RollingFileAppender(COMMON_LAYOUT, logFilename);
            appender.setMaxBackupIndex(maxBackupIndex);
            appender.setMaxFileSize(maxSize);
            logger.addAppender(appender);
        }
        catch (IOException ex) {
            ex.printStackTrace();
            return false;
        }
        return true;
    }

    private static Logger initializeMainLogger(String filename) {
        Logger logger = getLogger(LOG_IDENTIFIER_MAINLOG);
        addFileAppender(logger, filename, BACKUP_INDEX, BACKUP_SIZE);
        logger.setLevel(Level.INFO);
        return logger;
    }

    private static Logger initializeStatsLogger(String filename) {
        Logger logger = getLogger(LOG_IDENTIFIER_STATSLOG);
        addFileAppender(logger, filename, BACKUP_INDEX, BACKUP_SIZE);
        logger.setLevel(Level.INFO);
        return logger;
    }

}

Обновление:

Вот небольшая программа, которая (по крайней мере для меня) воспроизведет проблему с указанным выше классом Log: 

final public class Stress
{
    public static void main(String[] args) throws Exception {
        if (args.length != 2) {
            Log.init();
        }
        else {
            Log.init(args[0], args[1]);
        }

        for (;;) {
            // I know Executors are preferred, but this
            // is a quick & dirty test program
            Thread t = new Thread(new TestLogging());
            t.start();
        }
    }

    private static final class TestLogging implements Runnable
    {
        private static int counter = 0;

        @Override
        public void run() {
            String msg = new StringBuilder("Count is: ")
                .append(counter++).toString();

            Log.logMain(msg);
            Log.logStats(msg);

            try {
                Thread.sleep(1);
            }
            catch (InterruptedException e) {
                Log.logMain(e.getMessage());
            }
        }
    }
}

И некоторые примеры вывода в логах: 

$ grep stats main.log    
2012-03-23 15:30:35,919| stats 2012-03-23 15:30:35,919| main INFO  INFO   [ [Thread-313037]: Thread-313036]: Count is: 312987.
2012-03-23 15:30:35,929| stats INFO   [Thread-313100]: Count is: 313050.
2012-03-23 15:30:35,937| stats INFO   [Thread-313168]: Count is: 313112.
2012-03-23 15:30:35,945| stats INFO   [Thread-313240]: Count is: 313190.
2012-03-23 15:30:35,946| stats INFO   [Thread-313251]: Count is: 313201.
2012-03-23 15:30:35,949| stats INFO   [2012-03-23 15:30:35,949| main INFO  Thread-313281]: Count is: 313231.
2012-03-23 15:30:35,954| stats INFO   [Thread-313331]: Count is: 313281.
2012-03-23 15:30:35,956| 2012-03-23 15:30:35,956stats | main INFOINFO   [   [Thread-313356]: Count is: 313306.
2012-03-23 15:30:35,9562012-03-23 15:30:35,956| main | INFO  stats  [INFOThread-313359]:   Count is: 313309.
2012-03-23 15:30:35,962| stats INFO  2012-03-23 15:30:35,962| main INFO   [Thread-313388]:  [Count is: 313338.

и 

$ grep main stats.log
2012-03-23 15:30:35,913| 2012-03-23 15:30:35,913| main INFO   [Thread-312998]: Count is: 312948.
2012-03-23 15:30:35,915| main INFO   [Thread-313014]: Count is: 312964.
2012-03-23 15:30:35,919| stats 2012-03-23 15:30:35,919| main INFO  INFO   [ [Thread-313037]: Thread-313036]: Count is: 312987.
2012-03-23 15:30:35,931| main INFO   [Thread-313116]: Count is: 313066.
2012-03-23 15:30:35,947| main INFO   [2012-03-23 15:30:35,947Thread-313264]: | Count is: 313214.
2012-03-23 15:30:35,949| stats INFO   [2012-03-23 15:30:35,949| main INFO  Thread-313281]: Count is: 313231.
2012-03-23 15:30:35,956| 2012-03-23 15:30:35,956stats | main INFOINFO   [   [Thread-313356]: Count is: 313306.
2012-03-23 15:30:35,9562012-03-23 15:30:35,956| main | INFO  stats  [INFOThread-313359]:   Count is: 313309.
2012-03-23 15:30:35,962| stats INFO  2012-03-23 15:30:35,962| main INFO   [Thread-313388]:  [Count is: 313338.

Что бы это ни стоило, из файла main.log с 145516 строками "статистика" обнаруживалась в нем 2452 раза. Так что это не редкость, но не всегда так бывает (и, конечно, этот тест довольно экстремальный).

1 Ответ

11 голосов
/ 24 марта 2012

http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html

Вы делитесь PatternLayout между двумя приложениями, которые в соответствии с вышеуказанной ссылкой API:

Известно, что этот код имеет проблемы с синхронизацией и другие проблемы, которых нет в org.apache.log4j.EnhancedPatternLayout. EnhancedPatternLayout следует использовать в предпочтении к PatternLayout. EnhancedPatternLayout распространяется в дополнении log4j extras.

Так что создайте новый PatternLayout для каждого приложения

...