Log4j：事件出现在错误的日志文件中答案

【问题标题】：Log4j: Events appear in the wrong logfileLog4j：事件出现在错误的日志文件中
【发布时间】：2009-08-28 09:10:52
【问题描述】：

为了能够记录和跟踪一些事件，我在我的 java 项目中添加了一个 LoggingHandler 类。在这个类中，我使用了两个不同的 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

或

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 似乎不是完全节省线程的。使用单独的对象同步所有日志/跟踪方法后，一切正常。也许在将消息写入文件之前，lib 正在将消息写入线程不安全的缓冲区？

【问题讨论】：

标签： java file events log4j logging

【解决方案1】：

~~您不需要在记录器上同步，而是在输出流上同步。~~

如果你使用 log4j，输出应该是正确同步的。获得所见内容的唯一方法是两个线程同时写入同一个文件。

是否有可能您为两个附加程序配置了相同的输出文件？不要那样做；每个附加程序都必须有自己的不同文件名。

如果您 100% 确定每个附加程序都写入不同的文件，那么剩下的唯一选择就是您有时使用了错误的记录器。

【讨论】：

如果输出流是指附加程序，附加程序是线程安全的：doAppend 方法是synchronized。
在 fileAppeners 上同步后问题仍然存在（参见上面的示例）。也许我必须将记录器实例放入不同的线程中？
不，正如您在初始化方法中看到的那样，两个附加程序都绑定到不同的文件（logFilename 和 traceFilename），但它们使用相同的 patternLayout。几分钟前，我尝试将日志记录/跟踪移动到不同的线程，但这也没有帮助。
顺便说一句：我使用的是 log4j 1.2 和 Java 1.6.0_14
如果 log4j 1.2 是哪个版本？ 1.2.15？这并不重要，但也许你遇到了一个不为人知的错误。将其移至不同的线程只会使情况变得更糟。

【解决方案2】：

会不会以某种方式多次调用了初始化方法？每次调用都会添加两个新的 appender，它们写入与现有 appender 相同的文件。

【讨论】：

【解决方案3】：

这个问题已有 4 年历史了，但我在 2013 年才遇到同样的问题，我想我已经通过为每个 Appender 创建一个新的 PatternLayout 来解决它。希望对以后遇到同样问题的人有所帮助。

【讨论】：