Improper configuration of logback leads to frequent class loading

1. Frontier

This problem is also encountered in the customer's application system. To tell the truth, I like to show customers problems, so don't put up your posture! !

Briefly describe the problem: logback is crazy about class loading when printing error information, and also throws ClassNotFound error. The method call stack is as follows:

2. Similar questions on stackoverflow

In line with the principle of solving the problem as soon as possible, first search to see if there is a ready-made answer. I found a very similar question " java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy? " on stackoverflow. The thread provided by the foreign netizen is as follows:

 <Sep 9, 2015 9:27:13 AM UTC> <Warning> <Common> <BEA-000632> <Resource Pool "JDBC Data Source-0" shutting down, ignoring 3 resources still in use by applications..>
Exception in thread "Thread-12" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
        at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:125)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:468)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:424)
        at ch.qos.logback.classic.Logger.log(Logger.java:824)
        at org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:225)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.completeTransactionAfterThrowing(TransactionAspectSupport.java:415)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:114)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.cache.interceptor.CacheInterceptor$1.invoke(CacheInterceptor.java:58)
        at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:213)
        at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:66)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
        ................
        at java.lang.Thread.run(Thread.java:701)
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy
        at weblogic.utils.classloaders.GenericClassLoader.findLocalClass(GenericClassLoader.java:297)
        at weblogic.utils.classloaders.GenericClassLoader.findClass(GenericClassLoader.java:270)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.findClass(ChangeAwareClassLoader.java:64)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:323)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:268)
        at weblogic.utils.classloaders.GenericClassLoader.loadClass(GenericClassLoader.java:179)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.loadClass(ChangeAwareClassLoader.java:52)
        ... 18 more
Exception in thread "Thread-18" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
        at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:125)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:468)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:424)
        at ch.qos.logback.classic.Logger.log(Logger.java:824)
        at org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:225)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.completeTransactionAfterThrowing(TransactionAspectSupport.java:415)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:114)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.cache.interceptor.CacheInterceptor$1.invoke(CacheInterceptor.java:58)
        at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:213)
        at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:66)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
        .......................
        at java.lang.Thread.run(Thread.java:701)
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy
        at weblogic.utils.classloaders.GenericClassLoader.findLocalClass(GenericClassLoader.java:297)
        at weblogic.utils.classloaders.GenericClassLoader.findClass(GenericClassLoader.java:270)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.findClass(ChangeAwareClassLoader.java:64)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:323)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:268)
        at weblogic.utils.classloaders.GenericClassLoader.loadClass(GenericClassLoader.java:179)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.loadClass(ChangeAwareClassLoader.java:52)
    ... 18 more

At first glance, it seems to be similar to the problem I encountered, and I even thought it was caused by the version of packaging or logback. I calmed down and looked at my method call stack again, and found that the problem with the foreign friends above is not the same thing [I can't eat hot tofu in a hurry]. ClassNotFound The throwing place is inconsistent, the foreign friend's application reported an error when initializing the LoggingEvent object, and my side LoggingEvent is initialized normally. In the end, I plan to flip through the source code myself to thoroughly understand this problem.

Three, the answer to the source code

In order to quickly locate the problem, directly walk the key method of logback with the method call stack, and quickly found the symptom. The answer is in the construction method of LoggingEvent , as shown in the following figure:

Only when lc.isPackagingDataEnabled() is true, will the calculatePackagingData() method be called. What is the return value of isPackagingDataEnabled() ? Follow up and find that the return value of this method is a member attribute of LoggerContext 0e60f9a7e4b0bf6c6b6343788ad05f79---, the default is false , that must be where the default configuration has been changed:

The simple and violent method, directly search globally packagingDataEnabled where it was quoted, and found that there is a setPackagingDataEnabled() method is specially set, and then look at setPackagingDataEnabled() where been cited. Fortunately, there is only one place to call this method: ch.qos.logback.classic.joran.action.ConfigurationAction#begin , part of the source code is as follows:

 LoggerContext lc = (LoggerContext) context;
// 这里很容联想到，是在配置文件配置新的值
boolean packagingData = OptionHelper.toBoolean(ic.subst(attributes.getValue(PACKAGING_DATA_ATTR)), LoggerContext.DEFAULT_PACKAGING_DATA);
lc.setPackagingDataEnabled(packagingData);

Just look at the default value of PACKAGING_DATA_ATTR this value is affected by which parameter of the configuration file packagingDataEnabled .

Now I know that it must be configured in the configuration file packagingDataEnabled is true , but what this configuration is for, I don't know yet, I checked the official website directly [ official learning address ]:

The official website clearly states that this parameter is based on the stack information, and additionally adds the name and version information of the jar package. And it is also clear that this configuration parameter, although useful, is very expensive [every class triggers a class loading operation].

Fourth, the root of ClassNotFound

At this point, we know that packagingData="true" is configured in logback.xml, which leads to the execution of packagingData related methods. When logback prints error information, it generally outputs thread stack information, causing each line of stack information to trigger class loading, but ClassNotFound What's going on?

In fact, I immediately think of AOP here. First of all, the log output operation of the customer is written in an aspect class, and in Spring, the class where the cut method is located, Spring will recreate a proxy class Bean. Regardless of whether it is created by JDK dynamic proxy or CGLIB dynamic proxy, there is no corresponding class file on the local disk, so during the class loading process, these class files must not be found, and it will throw ClassNotFound error.

In order to verify this conjecture, I locally tried to print the log in the class pointed to by Pointcut and output the stack information:

Through the local stress test, the problem of the customer system was successfully restored. The local stack information is as follows:

5. Ending

After a long time, I finally encountered a slightly interesting problem, which I happily recorded. Focus on the analysis of ideas, of course, for logback or mention:

1. packagingData="true" Do not configure at will, the performance is very poor;
2. Try to use asynchronous logging ;
3. 注意日志格式配置： %F - java源文件名； %L - java源码行数； %C - java类名； %M -java method name, these will result in output thread stack information, which consumes CPU resources;
4. Log compression, pay attention to the compression frequency [do not compress if the disk space is sufficient]
5. immediateFlush default is true , if you want higher log throughput, set it to false; [Accidental application exit may cause a small amount of log loss]

---