¿Log4j no es seguro para subprocesos después de todo?

Question

(Esto es en SLES11, Java 7, Tomcat 6, log4j-1.2.16)

Usamos log4j para escribir cosas diferentes para diferentes archivos de registro. Heredé este código, así que, para bien o para mal, la estructura general llegó para quedarse por el momento.

El registrador creará dos archivos de registro: main.log y stats.log. Se registra un cierto mensaje de estadísticas en ambos registradores a través de llamadas separadas (verás a continuación) y un montón de otras cosas se registran en el registro principal.

Entonces, a través de nuestro código, verá cosas como Log.logMain(someMessageToLog);. En un solo lugar en nuestro código (que es ejecutado por múltiples hilos) existe la siguiente:

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

El nombre del registrador principal es main, el nombre del registrador de estadísticas es stats. El problema es que a veces, bajo una carga pesada, vemos líneas en main.log que tienen la cadena stats INFO en ella. Todo en main.log solo debe tener main INFO porque es el único registro de registrador en ese archivo, además vemos salida mixta en algunas líneas. Esto parece un problema de seguridad de subprocesos, pero los documentos de log4j dicen que log4j es seguro para subprocesos. He aquí un ejemplo de lo que quiero decir:

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

Aquí está la clase Log (simplificada para mostrar sólo los registradores en cuestión - en realidad hay un montón de otros registradores en ella, todos ellos instalados de manera similar a estos):

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

} 

---

actualización:

Aquí hay otros programa poco caras que (al menos para mí) reproducirá el problema con lo anterior clase 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()); 
      } 
     } 
    } 
} 

Y un ejemplo de salida en los registros:

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

y

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

Para lo que vale, de un archivo 145516-line main.log, "stats" aparecieron 2452 veces. Por lo tanto, no es raro, pero tampoco sucede todo el tiempo (y, por supuesto, esta prueba es bastante extrema).

Answer 1

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

Estás compartiendo el PatternLayout entre los dos appenders, que de acuerdo con el enlace de la API anterior:

Este código es conocido por tener la sincronización y otros temas que no están presentes en la org. apache.log4j.EnhancedPatternLayout. EnhancedPatternLayout debe usarse con preferencia a PatternLayout. EnhancedPatternLayout se distribuye en log4j extras companion.

Por lo tanto crear un nuevo PatternLayout para cada appender