log4j的日志——诡异事件

最近公司换机房，出现了一个诡异的问题。就是log4j。情景是这样的：

服务器运行一个crontab任务，在每天凌晨2:10分时候需要把昨天的日志转移到一个目录中，但是第二天去查看crontab运行日志，发现几个日志总是出问题。

线上产生日志在/data0/logs/2013-12-05.a.log，备份日志为/data2/logs。用的:
mv -v /data0/logs/$yerterday.a.log /data2/logs

但是第二天查看，会发现出现:
mv: cannot stat `2013-12-05.a.log': No such file or directory

然后去/data0/logs下查看，这个文件是有的！！其他文件都成功转移，老是有个别文件显示找不到文件。
搞了N久，脚本也没问题，日志也没问题。系统也正常，30台服务器只有2、3台出现，而且不定是哪一天。问了mentor，猜测是log4j的问题：

我们使用了log4j的每天产生一个日志的功能。
线上系统运行产生了a.log日志，今天是12-04，到了12-05的crontab运行前（凌晨2点10分），如果没有新记录写入到a.log，那么log4j可能就不会把a.log改名为2013-12-04.a.log，所以到2点10分的时候，a.log没有改名为2013-12-04.a.log，所以crontab的转移日志会失败。而到了白天，会有新纪录写入到a.log，然后log4j发现日期已经变为2013-12-05，所以会把a.log改名为2013-12-04.a.log，然后产生一个新的a.log，把12-05的记录写入到这个新文件中。

这是我们的猜测，因为对log4j只会简单的使用，所以现在读源码会有点不现实。如果各位碰过过这种诡异的事情，或者解决过这类的问题，那我真是哭爹喊娘的感谢了：） --------------------编程问答-------------------- 个人猜测是多任务处理导致的！很可能是如下情况：
log4j会有一定的缓冲区，当要记录日志的内容达到一定大小后刷新缓冲区将日志内容记录到硬盘文件，问题就在这里！
当日志没有达到一定大小log4j没有刷新缓冲区，此时文件仅仅存在内存中，而恰巧这是另一个转移日志的任务开始去拿那个日志文件，所以就会找不到文件，抛出异常。而随后日志到达一定大小后刷新了缓冲区将文件输出到硬盘上。这样就会出现你上班时可以查看到文件，但是程序却抛出了异常。

根本原因就是多任务并行，在操作同一个资源时出现了先后顺序错乱的问题。
--------------------编程问答-------------------- 没遇到过 --------------------编程问答--------------------

引用 1 楼 peng_hao1988 的回复:

个人猜测是多任务处理导致的！很可能是如下情况：
log4j会有一定的缓冲区，当要记录日志的内容达到一定大小后刷新缓冲区将日志内容记录到硬盘文件，问题就在这里！
当日志没有达到一定大小log4j没有刷新缓冲区，此时文件仅仅存在内存中，而恰巧这是另一个转移日志的任务开始去拿那个日志文件，所以就会找不到文件，抛出异常。而随后日志到达一定大小后刷新了缓冲区将文件输出到硬盘上。这样就会出现你上班时可以查看到文件，但是程序却抛出了异常。

根本原因就是多任务并行，在操作同一个资源时出现了先后顺序错乱的问题。

你这个缓冲区的概念让我耳目一新。但是这应该和异常不会产生联系吧？比如你用stringbuffer，不显式的flush刷新是完全可以的。所以log4j的这个问题只能算是缓冲区考虑问题不全面吧。

因为我觉得正常使用每天产生日志的都希望是：

第二天有新纪录，产生到新的文件中。
第二天没记录，你不产生新的a.log我忍了。但是你最起码把这个文件改名为2013-12-04.a.log吧，你也不改名，让我们处理日志时候很头疼，这就很不厚道。 --------------------编程问答--------------------

引用 3 楼 niushuai666 的回复:

Quote: 引用 1 楼 peng_hao1988 的回复:

个人猜测是多任务处理导致的！很可能是如下情况：
log4j会有一定的缓冲区，当要记录日志的内容达到一定大小后刷新缓冲区将日志内容记录到硬盘文件，问题就在这里！
当日志没有达到一定大小log4j没有刷新缓冲区，此时文件仅仅存在内存中，而恰巧这是另一个转移日志的任务开始去拿那个日志文件，所以就会找不到文件，抛出异常。而随后日志到达一定大小后刷新了缓冲区将文件输出到硬盘上。这样就会出现你上班时可以查看到文件，但是程序却抛出了异常。

根本原因就是多任务并行，在操作同一个资源时出现了先后顺序错乱的问题。

你这个缓冲区的概念让我耳目一新。但是这应该和异常不会产生联系吧？比如你用stringbuffer，不显式的flush刷新是完全可以的。所以log4j的这个问题只能算是缓冲区考虑问题不全面吧。

因为我觉得正常使用每天产生日志的都希望是：

第二天有新纪录，产生到新的文件中。
第二天没记录，你不产生新的a.log我忍了。但是你最起码把这个文件改名为2013-12-04.a.log吧，你也不改名，让我们处理日志时候很头疼，这就很不厚道。

我只是举例说明一个一种场景，就是某些资源可能仅仅是存在一个虚拟的位置如内存（没有及时输出到硬盘），不会被其他程序去读。就拿文件流来说吧，你new一个文件流把它放到缓冲流中，当你new完后文件对象已近已近存在内存了，可以再文件大小没有超出缓冲区时，硬盘上是看不到文件的，这是如果让其他任务直接去硬盘上读取文件肯定就要抛异常了。

你的问题很可能就是这种场景下发生的，即转移文件的任务拿到了文件的相关信息（文件引用，包括文件路径、类型等等），然后就去硬盘的路径下去读取该文件，而其恰巧文件没有及时输出到硬盘导致没有在物理位置找到。

换言之就是你转移文件的任务没有在恰当的时机读取文件。晚上系统可能还在输出日志，当转移文件的任务启动后就出现了两个任务同时操作一个资源，就出现我上面说的问题。log4j可以配置日志到指定位置的，你这个转移日志的工作完全没有必要。 --------------------编程问答-------------------- --------------------编程问答-------------------- 高并发访问，这事无解，不是log4j的问题，是java文件操作api就这样。
高并发写入的时候换文件，就这个问题，写代码复现过。
synchronized关键字在这个问题上没用
不要用那个daily什么的appender好了 --------------------编程问答-------------------- 学习学习学习 --------------------编程问答--------------------

引用 4 楼 peng_hao1988 的回复:

Quote: 引用 3 楼 niushuai666 的回复:

Quote: 引用 1 楼 peng_hao1988 的回复:

个人猜测是多任务处理导致的！很可能是如下情况：
log4j会有一定的缓冲区，当要记录日志的内容达到一定大小后刷新缓冲区将日志内容记录到硬盘文件，问题就在这里！
当日志没有达到一定大小log4j没有刷新缓冲区，此时文件仅仅存在内存中，而恰巧这是另一个转移日志的任务开始去拿那个日志文件，所以就会找不到文件，抛出异常。而随后日志到达一定大小后刷新了缓冲区将文件输出到硬盘上。这样就会出现你上班时可以查看到文件，但是程序却抛出了异常。

根本原因就是多任务并行，在操作同一个资源时出现了先后顺序错乱的问题。

你这个缓冲区的概念让我耳目一新。但是这应该和异常不会产生联系吧？比如你用stringbuffer，不显式的flush刷新是完全可以的。所以log4j的这个问题只能算是缓冲区考虑问题不全面吧。

因为我觉得正常使用每天产生日志的都希望是：

第二天有新纪录，产生到新的文件中。
第二天没记录，你不产生新的a.log我忍了。但是你最起码把这个文件改名为2013-12-04.a.log吧，你也不改名，让我们处理日志时候很头疼，这就很不厚道。

我只是举例说明一个一种场景，就是某些资源可能仅仅是存在一个虚拟的位置如内存（没有及时输出到硬盘），不会被其他程序去读。就拿文件流来说吧，你new一个文件流把它放到缓冲流中，当你new完后文件对象已近已近存在内存了，可以再文件大小没有超出缓冲区时，硬盘上是看不到文件的，这是如果让其他任务直接去硬盘上读取文件肯定就要抛异常了。

你的问题很可能就是这种场景下发生的，即转移文件的任务拿到了文件的相关信息（文件引用，包括文件路径、类型等等），然后就去硬盘的路径下去读取该文件，而其恰巧文件没有及时输出到硬盘导致没有在物理位置找到。

换言之就是你转移文件的任务没有在恰当的时机读取文件。晚上系统可能还在输出日志，当转移文件的任务启动后就出现了两个任务同时操作一个资源，就出现我上面说的问题。log4j可以配置日志到指定位置的，你这个转移日志的工作完全没有必要。

引用 6 楼 eastoneking 的回复:

高并发访问，这事无解，不是log4j的问题，是java文件操作api就这样。
高并发写入的时候换文件，就这个问题，写代码复现过。
synchronized关键字在这个问题上没用
不要用那个daily什么的appender好了

--------------------编程问答--------------------

引用 4 楼 peng_hao1988 的回复:

Quote: 引用 3 楼 niushuai666 的回复:

Quote: 引用 1 楼 peng_hao1988 的回复:

个人猜测是多任务处理导致的！很可能是如下情况：
log4j会有一定的缓冲区，当要记录日志的内容达到一定大小后刷新缓冲区将日志内容记录到硬盘文件，问题就在这里！
当日志没有达到一定大小log4j没有刷新缓冲区，此时文件仅仅存在内存中，而恰巧这是另一个转移日志的任务开始去拿那个日志文件，所以就会找不到文件，抛出异常。而随后日志到达一定大小后刷新了缓冲区将文件输出到硬盘上。这样就会出现你上班时可以查看到文件，但是程序却抛出了异常。

根本原因就是多任务并行，在操作同一个资源时出现了先后顺序错乱的问题。

你这个缓冲区的概念让我耳目一新。但是这应该和异常不会产生联系吧？比如你用stringbuffer，不显式的flush刷新是完全可以的。所以log4j的这个问题只能算是缓冲区考虑问题不全面吧。

因为我觉得正常使用每天产生日志的都希望是：

第二天有新纪录，产生到新的文件中。
第二天没记录，你不产生新的a.log我忍了。但是你最起码把这个文件改名为2013-12-04.a.log吧，你也不改名，让我们处理日志时候很头疼，这就很不厚道。

我只是举例说明一个一种场景，就是某些资源可能仅仅是存在一个虚拟的位置如内存（没有及时输出到硬盘），不会被其他程序去读。就拿文件流来说吧，你new一个文件流把它放到缓冲流中，当你new完后文件对象已近已近存在内存了，可以再文件大小没有超出缓冲区时，硬盘上是看不到文件的，这是如果让其他任务直接去硬盘上读取文件肯定就要抛异常了。

你的问题很可能就是这种场景下发生的，即转移文件的任务拿到了文件的相关信息（文件引用，包括文件路径、类型等等），然后就去硬盘的路径下去读取该文件，而其恰巧文件没有及时输出到硬盘导致没有在物理位置找到。

换言之就是你转移文件的任务没有在恰当的时机读取文件。晚上系统可能还在输出日志，当转移文件的任务启动后就出现了两个任务同时操作一个资源，就出现我上面说的问题。log4j可以配置日志到指定位置的，你这个转移日志的工作完全没有必要。

哦，不好意思。误解了你的答案：）
嗯，现在看来，你的分析是非常正确的。我会去看一下log4j这个自动备份的配置再来更新。
再次表示感谢：） --------------------编程问答-------------------- --------------------编程问答-------------------- 肯定有问题啊，要操作日志只能用log4j去配。或者停掉你的服务器然后再用其它的方式去操作日志文件 --------------------编程问答--------------------

引用 11 楼 u011631266 的回复:

肯定有问题啊，要操作日志只能用log4j去配。或者停掉你的服务器然后再用其它的方式去操作日志文件

还有，如果你用的是DailyRollingFileAppender记录的话，2点记录的是当天的日志，晚上2点的话你应该去记录前一天的吧，2点的日志为空是很正常的吧
--------------------编程问答--------------------

补充：Java ,  Java EE