Log4j không phải là chủ đề an toàn sau khi tất cả?

Question

(Đây là trên SLES11, Java 7, Tomcat 6, log4j-1.2.16)

Chúng tôi sử dụng log4j để viết những thứ khác nhau vào các tệp nhật ký khác nhau. Tôi đã thừa kế mã này, vì vậy tốt hay xấu cấu trúc chung là ở đây để ở lại trong thời gian này.

Trình ghi nhật ký sẽ tạo hai logfiles: main.log và stats.log. Một thông báo thống kê nhất định được ghi vào cả hai logger thông qua các cuộc gọi riêng biệt (bạn sẽ thấy bên dưới) và một loạt các thứ khác được ghi vào nhật ký chính.

Vì vậy, tất cả thông qua mã của chúng tôi, bạn sẽ thấy những thứ như Log.logMain(someMessageToLog);. Ở một nơi duy nhất trong mã của chúng tôi (được thực hiện bởi nhiều chủ đề) có những điều sau đây:

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

Tên của logger chính là main, tên của các số liệu thống kê logger là stats. Vấn đề là đôi khi dưới tải nặng, chúng ta thấy các dòng trong main.log có chuỗi stats INFO trong đó. Mọi thứ trong main.log chỉ nên có main INFO trong đó vì đó là nhật ký ghi nhật ký duy nhất cho tệp đó, cộng với chúng tôi thấy kết quả hỗn hợp trong một số dòng. Điều này có vẻ giống như một vấn đề an toàn thread, nhưng các tài liệu log4j nói log4j là thread-safe. Dưới đây là một ví dụ về những gì tôi có nghĩa là:

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

Dưới đây là lớp Log (rút gọn để chỉ hiển thị các logger trong câu hỏi - có thực sự là một loạt các logger khác trong đó, tất cả các thiết lập tương tự như này):

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

} 

---

cập nhật:

Dưới đây là al chương trình ittle đó (ít nhất là đối với tôi) sẽ tạo lại vấn đề với Log lớp trên:

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

Và một số lượng mẫu trong các bản ghi:

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

và

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

Đối những gì nó có giá trị, trong số 145516 dòng main.log tập tin, "số liệu thống kê" xuất hiện trong nó 2452 lần. Vì vậy, nó không phải là không phổ biến nhưng nó không giống như nó xảy ra tất cả các thời gian, hoặc (và tất nhiên thử nghiệm này là khá cực đoan).

Answer 1

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

Bạn đang chia sẻ PatternLayout giữa hai appenders, mà theo các liên kết API trên:

Mã này được biết là có đồng bộ hóa và các vấn đề khác mà không có mặt trong org. apache.log4j.EnhancedPatternLayout. EnhancedPatternLayout nên được sử dụng tùy theo PatternLayout. EnhancedPatternLayout được phân phối trong phần bổ sung log4j.

Vì vậy, tạo một PatternLayout mới cho mỗi appender