一场由deepClone引发的血案——log4j日志停写问题的排查和原理

最新推荐文章于 2024-08-28 08:59:02 发布

dcross

最新推荐文章于 2024-08-28 08:59:02 发布

阅读量543

点赞数

分类专栏： Java Web技术文章标签： log4j java file

本文链接：https://blog.csdn.net/dcross/article/details/84283082

版权

Java 同时被 2 个专栏收录

7 篇文章 0 订阅

订阅专栏

Web技术

5 篇文章 0 订阅

订阅专栏

一个月前系统开始发生一个奇怪的现象，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)

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