Dopo tutto, log4j non è sicuro?

Question

(Questo è su SLES11, Java 7, Tomcat 6, log4j-1.2.16)

Usiamo log4j per scrivere cose diverse su file di log diversi. Ho ereditato questo codice, quindi, nel bene o nel male, la struttura generale è qui per rimanere per il momento.

Il registratore creerà due file di registro: main.log e stats.log. Un certo messaggio di statistiche viene registrato in entrambi i registratori tramite chiamate separate (vedrai sotto) e un sacco di altre cose sono registrate nel registro principale.

Quindi attraverso il nostro codice vedrete cose come Log.logMain(someMessageToLog);. In un unico luogo nel nostro codice (che viene eseguito da più thread) non è la seguente:

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

Il nome del logger principale è main, il nome del previsti logger è stats. Il problema è che a volte sotto carichi pesanti vediamo linee in main.log che contengono la stringa stats INFO. Tutto in main.log dovrebbe avere solo main INFO perché è l'unico logger che si collega a quel file, in più vediamo un output misto in alcune linee. Questo sembra un problema di sicurezza del thread, ma i documenti di log4j dicono che log4j è thread-safe. Ecco un esempio di ciò che intendo:

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

Ecco la classe Log (ridotta a mostrare solo la taglialegna in questione - ci sono in realtà un sacco di altri software in esso, tutto impostato in modo simile a questi):

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; 
    } 

} 

---

Aggiornamento:

Ecco al programma di ittle che (almeno per me) si riprodurre il problema con quanto sopra Log classe:

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

E alcuni esempio di output nei log:

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

e

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

Per quello che vale, da un file main.log di linea 145516, "stats" è apparso in esso 2452 volte. Quindi non è raro, ma non è come succede sempre, anche (e ovviamente questo test è piuttosto estremo).

Answer 1

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

Stai condividendo il PatternLayout tra i due appenders, che secondo il link API di cui sopra:

Questo codice è noto per avere la sincronizzazione e altre questioni che non sono presenti in org. apache.log4j.EnhancedPatternLayout. EnhancedPatternLayout deve essere usato preferibilmente a PatternLayout. EnhancedPatternLayout è distribuito nel compagno extra di log4j.

Quindi creare un nuovo PatternLayout per ogni appender