1

We're seeing the following exception in a large Swing / Spring based application. The error occurs during a user interaction that triggers Spring to report a warning via commons-logging warn(String, Throwable) which in turn calls log4j. Unfortunately I've been unable to separate this issue into a self contained example.

Exception in thread "AWT-EventQueue-0" java.lang.NoClassDefFoundError: org/apache/log4j/spi/ThrowableInformation
    at org.apache.log4j.spi.LoggingEvent.<init>(LoggingEvent.java:165)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:234)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:487)
    <company specific code>
    at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:311)
    at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:749)
    at java.awt.EventQueue.access$500(EventQueue.java:97)
    at java.awt.EventQueue$3.run(EventQueue.java:702)
    at java.awt.EventQueue$3.run(EventQueue.java:696)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:75)
    at java.awt.EventQueue.dispatchEvent(EventQueue.java:719)
    at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:201)
    at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
    at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
    at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)
Caused by: java.lang.ClassNotFoundException: org.apache.log4j.spi.ThrowableInformation
    at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:331)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    ... 27 more

Environment

  • Java 8u40 on Windows XP SP3, log4j-1.2.17, commons-logging-1.1.1, spring-4.1.2
  • No classloading infrastructure like OSGI, web containers etc. in use
  • No Java agents, profilers, testing tools in use
  • No unusual -XX or -D arguments

Observations / things I've tried

  • Manually printing out the classpath via System.getProperty("java.class.path") to verify the log4j JAR is present - yes it is, and only ONE version is present 1.2.17
  • The class that cannot be loaded varies between runs, sometimes ThowableInformation, sometimes ThrowableRenderer etc, but it always fails.
  • If the following is placed in the application static void main() then log4j classes are correctly loaded and a warning is seen in the console AND the exception does not occur later. <== This confirms that the log4j JAR is visible from the application, assuming there aren't multiple classloaders in play...

Code

Log logger = LogFactory.getLog(getClass());
logger.warn("foo", new Exception());
  • Successfully referenced classes that cannot be loaded later from entry point of the application e.g. ThowableInformation

Code 

380        if (result == null) {
381            throw new ClassNotFoundException(name); // <=== here 
382        }
383        return result;
  • Placed breakpoints in IOException in case a "too many open files" error - not triggered.
  • Used -verbose and -Dsun.misc.URLClassPath.debug=true JVM options to debug classloading... This shows that various classes ARE loaded from the log4j jar...

For example

[Loaded org.apache.log4j.Category from file:/<path redacted>/log5j-1.2.17.jar]
[Loaded org.apache.log4j.Logger from file:/<path redacted>/log5j-1.2.17.jar]
[Loaded org.apache.log4j.Priority from file:/<path redacted>/log5j-1.2.17.jar]
  • Placed breakpoints in ClassNotFoundException to find out more information
    • I can see Launcher$AppClassLoader has a URLClassLoader ucp
    • ucp contains loaders of type URLClassPath$FileLoader and URLClassPath$JarLoader
    • I've found the instance of $JarLoader which references log4j-1.2.17.
    • Even though the same instance of sun.misc.Launcher$AppClassLoader previously loaded log4j classes from the JAR it seems it is no longer able to...
    • The only difference I can see between the early class-loading working and later class-loading failing is that the closed attribute of URLClassPath$JarLoader is set to true when it fails...

My theories

  • Some resource limit is being reached at which classes can no longer be loaded, but for some reason this is not being reported.
  • Spring, core Java or commons-logging are using a private class-loading infrastructure that cannot see the log4j JAR.

My question

  • Anyone else come up against this?
  • Possible causes of ClassNotFoundException that could be intermittent? How can I trap them?
  • More debugging suggestions - I'm all out of ideas.
Adam
  • 35,919
  • 9
  • 100
  • 137
  • Do you have any other version of log4j on your classpath? – El Guapo Aug 13 '15 at 14:37
  • Sorry... I guess I didn't read that "in-depthly". – El Guapo Aug 13 '15 at 14:38
  • use -verbose to see if you really have log4j in your classpath. It sure don't look like it. Is this a servlet or some other multiple-classpath environment? – bmargulies Aug 13 '15 at 14:39
  • Maybe http://stackoverflow.com/questions/9872510/tomcat-7-java-lang-noclassdeffounderror-org-apache-log4j-spi-throwableinforma –  Aug 14 '15 at 11:17

1 Answers1

0

Root cause

The URLClassLoader had been closed, this has the unfortunate effect of Java reporting ClassNotFoundException.

Background

To support an earlier version of the application that used OSGI/Spring-DM we had beans in our spring XML which allowed resources to be loaded from the correct bundles, this was a horrible hack, but the only way that it could be done at the time given code, resources and XML files were in different bundles...

<bean id="classLoader" class="org.example.internal.PluginModuleClassLoader" factory-method="getClassLoader" />
<bean id="imageLoader" class="org.example.ImageLoader">
   <property name="classLoader" ref="classLoader" />
</bean>

public class PluginModuleClassLoader {
   public static ClassLoader getClassLoader() {
      return PluginModuleClassLoader.class.getClassLoader();
   }
}

We upgraded Spring 6 months ago from (2.5.5 to 4.1.2) and removed OSGI as it had no benefit, however the now legacy PluginModuleClassLoader mechanism was left in place due to cost of removing it from 60+ bundles.

How it got closed

The user interaction in question closes one application context and loads another... This has the side effect of destroying the application context. Spring automatically destroys all the beans. In the case of the classLoader bean it calls automagically finds the close() method, i.e. URLClassLoader.close() which means all subsequent looks fail with ClassNotFoundException

Adam
  • 35,919
  • 9
  • 100
  • 137