Bug 41059 - WebAppClassLoader clearReferences code break running threads
Summary: WebAppClassLoader clearReferences code break running threads
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 5
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 5.5.20
Hardware: All All
: P3 major with 2 votes (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2006-11-28 11:53 UTC by James Birmingham
Modified: 2011-02-14 08:47 UTC (History)
4 users (show)



Attachments
Adds preliminary pass to clearReferences to prevent untimely class initialization (1.85 KB, patch)
2008-08-07 22:09 UTC, Curt Arnold
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description James Birmingham 2006-11-28 11:53:02 UTC
When the WebAppClassLoader stops it manually sets all static and final 
variables to null in the clearReferences method.  This results in NPEs for any 
thread that was not stopped and not expecting its final or static variables to 
be null.  This is particularly a problem with hot deploys since the unload 
fails and terminating the deploy.
Comment 1 Remy Maucherat 2006-11-28 15:48:25 UTC
You are not supposed to have any threads associated with this classloader at
this point.
Comment 2 Remy Maucherat 2006-11-28 15:53:56 UTC
Note that if you want a "fix", you can offer a patch disabling this code (with a
system property or some other mechanism like that).
Comment 3 James Birmingham 2006-11-29 06:05:59 UTC
Here is a patch that uses a system property to disable this feature.  The 
patch was made against tomcat 5.5.20 source.

--- WebappClassLoader.java.orig 2006-09-12 11:12:42.000000000 -0400
+++ WebappClassLoader.java      2006-11-29 09:03:42.000000000 -0500
@@ -163,7 +163,12 @@ public class WebappClassLoader
      * resources.
      */
     boolean antiJARLocking = false;
-
+
+    /**
+     * Use clearReferences experimental code to deal with possible memory 
leaks.
+     */
+    private static final boolean ENABLE_CLEAR_REFERENCES = Boolean.valueOf
(System.getProperty
("org.apache.catalina.loader.WebappClassLoader.ENABLE_CLEAR_REFERENCES", "true"
)).booleanValue();
+

     // ----------------------------------------------------------- 
Constructors

@@ -1489,7 +1494,9 @@ public class WebappClassLoader

         // Clearing references should be done before setting started to
         // false, due to possible side effects
-        clearReferences();
+        if(ENABLE_CLEAR_REFERENCES) {
+            clearReferences();
+        }

         started = false;
Comment 4 James Birmingham 2006-11-30 05:36:25 UTC
I provided a patch to work around this issue.  
Comment 5 Mark Thomas 2006-12-02 09:12:43 UTC
Just marking as an enhancement.
Comment 6 Remy Maucherat 2006-12-05 02:56:36 UTC
The patch was bad: it is wrong to disable the whole method.
Comment 7 James Birmingham 2006-12-05 05:47:17 UTC
Here is a new patch that disables only the code which resets the static and 
final variables.

--- WebappClassLoader.java.orig 2006-09-12 11:12:42.000000000 -0400
+++ WebappClassLoader.java      2006-12-05 08:34:52.000000000 -0500
@@ -163,7 +163,16 @@ public class WebappClassLoader
      * resources.
      */
     boolean antiJARLocking = false;
-
+
+    /**
+     * Use experimental code in clearReferences to reset static and final 
variables
+     * to deal with possible memory leaks.
+     */
+    private static final boolean ENABLE_NULLING_STATIC_FINAL_REFERENCES =
+            Boolean.valueOf(System.getProperty(
+                    "org.apache.catalina.loader.WebappClassLoader.ENABLE_NULLI
NG_STATIC_FINAL_REFERENCES",
+                    "true")).booleanValue();
+

     // ----------------------------------------------------------- 
Constructors

@@ -1585,46 +1594,48 @@ public class WebappClassLoader

         // Null out any static or final fields from loaded classes,
         // as a workaround for apparent garbage collection bugs
-        Iterator loadedClasses = ((HashMap) resourceEntries.clone()).values
().iterator();
-        while (loadedClasses.hasNext()) {
-            ResourceEntry entry = (ResourceEntry) loadedClasses.next();
-            if (entry.loadedClass != null) {
-                Class clazz = entry.loadedClass;
-                try {
-                    Field[] fields = clazz.getDeclaredFields();
-                    for (int i = 0; i < fields.length; i++) {
-                        Field field = fields[i];
-                        int mods = field.getModifiers();
-                        if (field.getType().isPrimitive()
-                                || (field.getName().indexOf("$") != -1)) {
-                            continue;
-                        }
-                        if (Modifier.isStatic(mods)) {
-                            try {
-                                field.setAccessible(true);
-                                if (Modifier.isFinal(mods)) {
-                                    if (!((field.getType().getName
().startsWith("java."))
-                                            || (field.getType().getName
().startsWith("javax.")))) {
-                                        nullInstance(field.get(null));
+        if(ENABLE_NULLING_STATIC_FINAL_REFERENCES) {
+            Iterator loadedClasses = ((HashMap) resourceEntries.clone
()).values().iterator();
+            while (loadedClasses.hasNext()) {
+                ResourceEntry entry = (ResourceEntry) loadedClasses.next();
+                if (entry.loadedClass != null) {
+                    Class clazz = entry.loadedClass;
+                    try {
+                        Field[] fields = clazz.getDeclaredFields();
+                        for (int i = 0; i < fields.length; i++) {
+                            Field field = fields[i];
+                            int mods = field.getModifiers();
+                            if (field.getType().isPrimitive()
+                                    || (field.getName().indexOf("$") != -1)) {
+                                continue;
+                            }
+                            if (Modifier.isStatic(mods)) {
+                                try {
+                                    field.setAccessible(true);
+                                    if (Modifier.isFinal(mods)) {
+                                        if (!((field.getType().getName
().startsWith("java."))
+                                                || (field.getType().getName
().startsWith("javax.")))) {
+                                            nullInstance(field.get(null));
+                                        }
+                                    } else {
+                                        field.set(null, null);
+                                        if (log.isDebugEnabled()) {
+                                            log.debug("Set field " + 
field.getName()
+                                                    + " to null in class " + 
clazz.getName());
+                                        }
                                     }
-                                } else {
-                                    field.set(null, null);
+                                } catch (Throwable t) {
                                     if (log.isDebugEnabled()) {
-                                        log.debug("Set field " + field.getName
()
-                                                + " to null in class " + 
clazz.getName());
+                                        log.debug("Could not set field " + 
field.getName()
+                                                + " to null in class " + 
clazz.getName(), t);
                                     }
                                 }
-                            } catch (Throwable t) {
-                                if (log.isDebugEnabled()) {
-                                    log.debug("Could not set field " + 
field.getName()
-                                            + " to null in class " + 
clazz.getName(), t);
-                                }
                             }
                         }
-                    }
-                } catch (Throwable t) {
-                    if (log.isDebugEnabled()) {
-                        log.debug("Could not clean fields for class " + 
clazz.getName(), t);
+                    } catch (Throwable t) {
+                        if (log.isDebugEnabled()) {
+                            log.debug("Could not clean fields for class " + 
clazz.getName(), t);
+                        }
                     }
                 }
             }
Comment 8 Michael Moynihan 2007-05-04 09:20:58 UTC
This is causing a problem for me also and I think requires a fix other than the 
patch given here. I get the following stack trace which shows that the error 
occurs on  Tomcat's clean up thread and therefore should be addressed with a 
more permanent fix.

The problem arises because Tomcat tries to null a static/final field of a type 
that has not yet been loaded, which causes the class initializer to run. In my 
case, that initializer fetched a log from Commons Logging, which had 
(presumably) already been "cleaned up" by Tomcat, and threw an NPE.


[FATAL] LoggingInit - Failed to obtain logger returning simple logger for 
CONFIG.com.commons.monitoring.util.Instrument 
<org.apache.commons.logging.LogConfigurationException: 
java.lang.NullPointerException (Caused by java.lang.NullPointerException)
>org.apache.commons.logging.LogConfigurationException: 
java.lang.NullPointerException (Caused by java.lang.NullPointerException)
	at org.apache.commons.logging.impl.LogFactoryImpl.newInstance
(LogFactoryImpl.java:538)
	at org.apache.commons.logging.impl.LogFactoryImpl.getInstance
(LogFactoryImpl.java:235)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:370)
	at com.commons.logging.LoggingInit.getLog(LoggingInit.java:334)
	at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at com.commons.catalog.CatalogUtils.getLog(CatalogUtils.java:75)
	at com.commons.catalog.GenericTrace.<init>(GenericTrace.java:279)
	at com.commons.catalog.SimpleTrace.<init>(SimpleTrace.java:34)
	at com.commons.monitoring.util.Instrument.<clinit>
(AbstractRuntimeInstrument.java:44)
	at sun.misc.Unsafe.ensureClassInitialized(Native Method)
	at sun.reflect.UnsafeFieldAccessorFactory.newFieldAccessor(Unknown 
Source)
	at sun.reflect.ReflectionFactory.newFieldAccessor(Unknown Source)
	at java.lang.reflect.Field.acquireFieldAccessor(Unknown Source)
	at java.lang.reflect.Field.getFieldAccessor(Unknown Source)
	at java.lang.reflect.Field.get(Unknown Source)
	at org.apache.catalina.loader.WebappClassLoader.clearReferences
(WebappClassLoader.java:1612)
	at org.apache.catalina.loader.WebappClassLoader.stop
(WebappClassLoader.java:1496)
	at org.apache.catalina.loader.WebappLoader.stop(WebappLoader.java:734)
	at org.apache.catalina.core.StandardContext.stop
(StandardContext.java:4398)
	at org.apache.catalina.core.ContainerBase.stop(ContainerBase.java:1067)
	at org.apache.catalina.core.ContainerBase.stop(ContainerBase.java:1067)
	at org.apache.catalina.core.StandardEngine.stop(StandardEngine.java:448)
	at org.apache.catalina.core.StandardService.stop
(StandardService.java:510)
	at org.apache.catalina.core.StandardServer.stop(StandardServer.java:734)
	at org.apache.catalina.startup.Catalina.stop(Catalina.java:602)
	at org.apache.catalina.startup.Catalina.start(Catalina.java:577)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:295)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:433)
Caused by: java.lang.NullPointerException


Upgrading Commons Logging to v1.1 on Tomcat's server classpath removes the NPE 
but the problem isn't really fixed.

Possible solution is to use two phases: first collect all the non-null Fields 
(Field.get will cause the declared type to be loaded) then null them.
Comment 9 Curt Arnold 2008-08-07 22:09:08 UTC
Created attachment 22408 [details]
Adds preliminary pass to clearReferences to prevent untimely class initialization

This issue is resulting in bugs (40212 and 43867, specifically maybe others) being reported to log4j.

The patch seems reasonable and compiles, but has not been tested.  I'm putting here and inviting those currently tracking 43867 to check that it fixes the problems that they are observing and add comments here.
Comment 10 Gili 2008-08-08 07:35:19 UTC
Curt's patch fixes the problem without disabling any part of the code.
Comment 11 Gili 2008-09-04 19:04:22 UTC
BTW, this causes Tomcat to hang when shutting down (randomly) for me. It happens rather frequently and is a problem because I restart Tomcat nightly (due to unrelated memory leak problems). I am increasing severity to "major" but leaving the priority as is. Curt I will gladly test out your patch if you can provide me with a drop-in JAR file or otherwise indicate how I can patch my existing Tomcat system without rebuilding the entire thing from source.
Comment 12 Mauro Molinari 2009-01-13 01:57:25 UTC
Could this bug be taken into consideration?

In my case, I have the symptoms outlined in bug #43867 and this is caused by the following situation (I'm using Tomcat 5.5.26):

- WebappClassLoader.clearReferences() at line 1617 inspects some static fields in order to set them to null afterwards, using reflection
- one of these fields seems to be a field of an Axis2 class (I have an Axis2 Servlet with load-on-startup configured in my web.xml); field.get(null) causes the VM to pass through sun.misc.Unsafe.ensureClassInitialized(Class) (in other words: Tomcat is trying to inspect a static field of a class that hasn't ever be initialized before)
- that method of Sun implementation causes specifically org.apache.axis2.context.OperationContext to be initialized; this class has a static field declared as:
private static final Log log = LogFactory.getLog(OperationContext.class);
- this static declaration causes a new Log4JLogger to be created; this is still in charge of the WebappClassLoader, so when Log4JLogger constructor calls getLogger(), a call to org.apache.log4j.LogManager.getLoggerRepository() is made
- however, at this time the static field repositorySelector is null, probabily because it has been set to null by a previous iteration of the same loop that is in running in WebappClassLoader.clearReferences() (this is just a hypothesis)

So, from what I have said, I think that either:
- WebappClassLoader.clearReferences() should skip to inspect fields of classes that have not been initialized yet, otherwise they will be initialized at that point (and it might be too late!)
- I didn't look at Curt's patch, but I assume he worked on this issue and he followed a 2-pass approach that also solves it

I hope this helps in any way.
Mauro.
Comment 13 Gili 2009-01-13 03:31:51 UTC
FYI, Glassfish fixed this bug within a week of being reported: https://glassfish.dev.java.net/issues/show_bug.cgi?id=6637

I'll leave it up to you to draw your own conclusions.
Comment 14 Mark Thomas 2009-07-17 10:30:38 UTC
This has been fixed in trunk and proposed for 6.0.x and 5.5.x

Keep in mind that ENABLE_CLEAR_REFERENCES=true is intended to:
a) work around GC issues in old JVMs (unlikely to an issue with current jvms)
b) work around one source of memory leaks in webapps that are buggy or use buggy libraries

The very nature of the ENABLE_CLEAR_REFERENCES code is that it is likely to cause problems - as it does with log4j. Whilst this patch (thanks for the patch by the way) will reduce the chances or seeing errors, it will not eliminate them.

A better approach is to set ENABLE_CLEAR_REFERENCES=false and to use a profiler to identify and fix the root causes of any memory leaks. A well-written app using well behaved libraries should not need ENABLE_CLEAR_REFERENCES=true

If when doing this you find a memory leak in the Tomcat code (hopefully you won't - all the ones we know about should be fixed) then please open a new Bugzilla entry and report it.
Comment 15 Mark Thomas 2009-07-20 03:18:23 UTC
Thanks again for the patch. It has been applied to 5.5.x and 6.0.x and will be included in 5.5.29 and 6.0.21 onwards.