log4j 1.2.17 和 java8u162 不会翻转日志文件答案

【问题标题】：Log files are not getting rolled over with log4j 1.2.17 and java8u162log4j 1.2.17 和 java8u162 不会翻转日志文件
【发布时间】：2018-05-28 11:50:07
【问题描述】：

我们在生产环境中面临一个问题，在某些情况下日志文件没有得到翻转。我们正在使用 Log4j 版本 1.2.17 以及 apache.commons-logging。创建自定义附加程序以滚动文件。 appender 扩展了 Log4j 的 FileAppender。下面是 subAppend(LoggingEvent event) 方法的算法：

long n = System.currentTimeMillis();
// Has the time come to roll the log file?
if (n >= nextCheck)
{
 now.setTime(n);
    nextCheck = rc.getNextCheckMillis(now);

    rollOver();
    reachedMaxSize = false;

 else
 {
     File f = new File(getFile());

     // Has the log file has exceeded its maximum size?
     if (!reachedMaxSize && f.length() > maxFileSize)
     {
         // Log file has reached it maximum size.
         reachedMaxSize = true;

         // Log one last message to the file stating the max has been reached.
         LoggingEvent exeededEvent = new LoggingEvent(
                      getClass().getName(),
                      Logger.getLogger(getClass().getName()),
                      Priority.ERROR,
                      "Maximum log file size has been reached ("+maxFileSize/1024+"KB)",
                      null);
       super.subAppend(exeededEvent);
     }

 // If the log has not reached its max size, write it. Otherwise,
 // send log event to stdout.
 if (!reachedMaxSize)
 {
     super.subAppend(event);
 }
 else
 {
     System.out.println(event.getRenderedMessage());
 }

这里是 Log4j.properties 文件

log4j.rootLogger=INFO,RCFLog

log4j.appender.RCFLog=com.ge.medit.util.logging.MaxFileSizeRollingFileAppender
log4j.appender.RCFLog.File=runtime/logs/rcf.log
log4j.appender.RCFLog.DatePattern=yyyyMMdd'_'{0}
log4j.appender.RCFLog.Encoding=UTF-8
log4j.appender.RCFLog.Append=true

log4j.appender.ConsoleLog=org.apache.log4j.ConsoleAppender
log4j.appender.ConsoleLog.layout=org.apache.log4j.PatternLayout
log4j.appender.ConsoleLog.layout.ConversionPattern=%p [%t] %c{1}: %m%n

log4j.appender.RCFLog.layout=org.apache.log4j.PatternLayout
log4j.appender.RCFLog.layout.ConversionPattern=@%d{yyyyMMdd HH:mm:ss.SSS}@ %p {%t} %c{1}: %m%n

log4j.logger.GUIEVT=INFO

根据观察，系统上的日期发生了变化。日期设置为当前日期前 3 个月。

Current Date- 10th May 2018
nextCheck - 11th May 2018 00:00
Changed Date- 10th March 2018
No backup is created as a condition at line 3 failed.

5 月 11 日再次经过 12 小时后，日期更改为当前日期。到那时，文件的时间戳已更改为 3 月 10 日。由于没有 RollOver，下一次检查仍然是 2018 年 5 月 11 日 00:00。但是在 5 月 12 日 00:00，文件应该已经按照第 3 行的条件翻转，并且应该创建了一个新文件，但没有发生。此外，该文件已达到最大大小。从那时起，在系统重新启动之前没有任何日志。

Java 版本是 java8u162。虽然我找不到任何说明它是否与 java 相关的帖子。

我尝试在测试环境中重现相同的场景，但一切都按预期工作。

有人在使用 Log4j 时遇到过此类问题吗？请分享您的意见。提前致谢。

【问题讨论】：

标签： java log4j apache-commons-logging fileappender

【解决方案1】：

我认为最好的办法就是调试代码，log4j 可以像调试任何其他代码一样调试，没有这个我们只能推测。

我从您的配置中看到，您使用的是com.ge.medit.util.logging.MaxFileSizeRollingFileAppender 这不是 log4j 的标准滚动文件附加程序（可能是您公司的自定义附加程序，可能有问题）。

如果无法调试，我只能提供一些提示，希望能有所帮助。

通常翻转（参见“翻转”功能）是作为一系列文件的“重命名”来实现的。我曾经见过（再次，只是推测）这种方法只有在以下情况下才有效：
- 您对文件有权限
- 您的应用程序拥有文件中的唯一句柄（尤其与 Windows 操作系统相关）。

在调试中很容易跟踪，因为从技术上讲，重命名可能是使用 java.io.File#renameTo 完成的，根据重命名操作是成功还是失败返回 true/false。

为了模拟这种情况，您可以部署“隐藏”代码，它只是用消息“淹没”日志（您可以使用 JMX、内部 web servlet/消息处理程序 - 任何您想要的，但里面可以包含循环中的大量日志消息（假），如下所示：

class MyHiddenMBean {
    Logger logger = ...
    public void doLogManyTimes(int times) {
         for(int i = 0; i < times; i++) {
             logger.info("Artificial Logging Message : " + i);
         }
    } 
}

您将立即达到最大文件（当然，您可以故意将其设置得非常小以更快地模拟），然后您将能够看到为什么 renameTo 不起作用

【讨论】：

非常感谢您的回复。我尝试模拟相同的场景，但它工作正常。我尝试的另一件事是放置 -Dlog4j.debug = true 但这会在控制台上写入日志，我们的应用程序主要在 c++ 中，这会触发 java 中的子应用程序运行。所以我看不到内部日志消息。另一种猜测是文件由于某种原因被锁定。那么再次如何找到它是否真的被锁定了？
我认为您应该检查除java进程之外的其他人是否保留了文件句柄。例如，在 linux 中，有一个“lsof”命令可以显示这一点。任何 hava 应用程序（即使它是从外部进程启动的）都可以轻松调试。为此，您应该为 JVM 设置几个标志。甚至还有一个启动 JVM 的标志，并立即等待，直到远程调试器通过某个暴露的 TCP 端口 (stackoverflow.com/questions/975271/…) 连接后才继续进行

【解决方案2】：

我知道了文件未备份的原因。有多个日期更改。据观察，日期首先更改为 10/05/2036，然后更改为 2021 年并更改回 10/03/2018，之后我们最终将日期更改为当前日期 11/05/2018。

因此，当日期更改为未来日期 2036 年 10 月 5 日。 nextCheck 日期已更新为 2036 年 11 月 5 日。再次将日期更改回当前日期时，如果条件失败（现在（11/05/2018 >= 11/05/2036）。因此，仅当日期更改为 2036 年 11 月 5 日或更多时才会进行备份。

需要将条件 if (n >= nextCheck) 更改为 if (n >= nextCheck || nextCheck - n > TimeConstants.MILLISECONDS_PER_DAY。此更改尚待测试。

感谢 @Mark Bramnik 的快速回复。

【讨论】：