log4j日志停写有关问题的排查和原理

2012-12-19

log4j日志停写问题的排查和原理一个月前系统开始发生一个奇怪的现象，log4j日志会突然停写，开始并没有很关

log4j日志停写问题的排查和原理

一个月前系统开始发生一个奇怪的现象，log4j日志会突然停写，开始并没有很关注，总以为是系统的原因，后来发现在多台机器上依然发生，这个问题开始被重视。

说一下问题排查的路径：

最开始怀疑是org.apache.log4j.DailyRollingFileAppender的问题，换成org.apache.log4j.FileAppender后，问题依然工程里日志包冲突的问题，因为工程里有log4j,sel4j,logback等多个包，将self4j和logback的依赖去掉后，问题依然。也换过commons-logging包，log4j包的版本，还是无效系统的内存，磁盘，CPU，句柄数全部正常...
经过多天的观察，终于发现日志停写的规律，每天早上8点开始停写（由于是org.apache.log4j.DailyRollingFileAppender，每天都会生成一个新的文件）。8点时，有一个任务，调用了一些接口，经过排查，终于定位到一个修改的方法，每次这个修改方法执行的时候，日志就会被停写。为什么普通的业务代码会造成日志的停写呢？
修改方法里有这样一段

Cloner cloner = new Cloner();PricingCpmTrans pricingCpmTrans = cloner.deepClone(oldPricingCpmTrans);

?这里使用了一个第三方jar，Cloner（罪魁祸首啊），而在PricingCpmTrans里有一个Log对象
?我们看下Cloner是怎么做这个deepClone的

?先将对象newInstance出来?然后递归的查找对象里的所有属性，并赋值既然这样，那PricingCpmTrans里的Log对象也会被复制成一个新的，那如果有问题，也最多是这个对象的日志有问题，为什么所有的日志都不打了呢？
让我们接着看Log类里有什么？
Log里最后写日志是使用?FileOutputStream 进行，里面有一段：

    private static native void initIDs();        static {initIDs();    }

?
而initIDs做了什么？

JNIEXPORT void JNICALL        Java_sun_nio_ch_IOUtil_initIDs(JNIEnv *env, jclass clazz)        {            OSVERSIONINFO ver;            ver.dwOSVersionInfoSize = sizeof(ver);            GetVersionEx(&ver);            if (ver.dwPlatformId == VER_PLATFORM_WIN32_NT) {               onNT = JNI_TRUE;            }                    clazz = (*env)->FindClass(env, "java/io/FileDescriptor");            fd_fdID = (*env)->GetFieldID(env, clazz, "fd", "I");            handle_fdID = (*env)->GetFieldID(env, clazz, "handle", "J");        }

?
系统生成一个指针指向?FileOutputStream?的?FileDescriptor（文件描述符）里的fd，也就是说文件对象里会持有一个系统的文件描述符的数字id
但在deepClone时，虽然FileOutputStream 对象被复制了，但这个数字ID是int的，所以还是这个数字ID当?PricingCpmTrans?被系统垃圾回收时?FileOutputStream 也被系统回收了

    protected void finalize() throws IOException {        if (fd != null) {            if (fd == FileDescriptor.out || fd == FileDescriptor.err) {                flush();            } else {                /*                 * Finalizer should not release the FileDescriptor if another                 * stream is still using it. If the user directly invokes                 * close() then the FileDescriptor is also released.                 */                runningFinalize.set(Boolean.TRUE);                try {                    close();                } finally {                    runningFinalize.set(Boolean.FALSE);                }            }        }    }    private native void close0() throws IOException;

?系统回收调用了close方法
所以当对象被回收时，指向文件的指针被删除了，导致虽然原来的log对象持有着这个句柄，但系统中这个句柄已经被删除了，导致日志再也无法输出，如果用控制台输入可以捕获到这个异常

java.io.IOException: 句柄无效。at java.io.FileOutputStream.writeBytes(Native Method)at java.io.FileOutputStream.write(FileOutputStream.java:282)at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276)at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:57)

再看下文件描述符的结构图，可能更好理解了

log4j日志停写有关问题的排查和原理

进程到文件表的关系还在，但文件表到具体的文件节点的关系已经被丢失了，导致日志无法输出。

总结下这次的经验教训：

使用第三方包一定要慎重查问题还是要先让它重现任何说系统问题或是网络问题来掩盖异常的都是耍流氓

热点排行

编程

log4j日志停写有关问题的排查和原理