"I think this is reproducable"

You think wrong: it works for me. I did cleanup the handling of
"java.util.zip.ZipException: No such file or directory", however.

This is reproducable by me, I can now confirm this.  If you needed me to provide
a sample web-app and steps to reproduce I'll spend the time finding the smallest
test case that should allow you to observe this problem too.

First I will test your changes, please confirm the changes have been released to
HEAD and if you remember which file(s) were changed.

Thanks for your efforts.

I have managed to test this situation out again, with current 5.5.14-beta, the
multiple ZIP failures are gone, handling looks much cleaner, but Tomcat's still
upset and every 10 seconds an NPE (the 2nd stack dump) occurs.


To re-create this situation I just did a rename of the application directory like:

mv $CATALINA_BASE/webapps/ROOT /tmp/ROOT

Please advise what I can do myself to help track down the persistant NPE problem
to help you fix it.


09-Dec-2005 15:51:08
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor processChildren
SEVERE: Exception invoking periodic operation:
java.lang.NoClassDefFoundError: org/apache/log4j/spi/ThrowableInformation
        at org.apache.log4j.spi.LoggingEvent.<init>(LoggingEvent.java:154)
        at org.apache.log4j.Category.forcedLog(Category.java:388)
        at org.apache.log4j.Category.log(Category.java:853)
        at org.apache.commons.logging.impl.Log4JLogger.error(Log4JLogger.java:193)
        at
org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:3772)
        at org.apache.catalina.core.StandardContext.stop(StandardContext.java:4310)
        at
org.apache.catalina.core.ContainerBase.removeChild(ContainerBase.java:892)
        at
org.apache.catalina.startup.HostConfig.checkResources(HostConfig.java:1019)
        at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1178)
        at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:292)
        at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at
org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1304)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1568)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1577)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1557)
        at java.lang.Thread.run(Thread.java:595)
09-Dec-2005 15:51:18 org.apache.catalina.startup.HostConfig checkResources
INFO: Undeploying context []
09-Dec-2005 15:51:18
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor processChildren
SEVERE: Exception invoking periodic operation:
java.lang.NullPointerException
        at
org.apache.catalina.core.ContainerBase.removeChild(ContainerBase.java:883)
        at
org.apache.catalina.startup.HostConfig.checkResources(HostConfig.java:1019)
        at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1178)
        at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:292)
        at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at
org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1304)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1568)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1577)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1557)
        at java.lang.Thread.run(Thread.java:595)


Reopened for attention as the original issue still persists.

Created attachment 17813 [details]
Gracefully recover from Filter.destroy() web-app generated exceptions

Shoot from hip diff, based on listenerStop() logic but applied to
Filter.destroy().  Sorry I'm unable to build TC5 from SVN or the -src package.

I'm taking the thought here that I know I have active filters on my web-app and
the reason why it affects me is that when I renamed the directory I removed the
JVMs ability to find and load the Filter#destroy() function.

In any case this patch feels like the correct thing to do.

Okay my first patch doesn't work I've deleted it, but highlights another problem
I will generate a test case for at a later date.

I have attached a WAR test case for this bug now (works for me on 5.5.16).  A
recap of the steps needed to reproduce:

* Unzip the WAR and work with exploded WAR it to a dir TCBug37498
* Start up TC (without it deployed but with autoDeploy enabled in the webapps
directory).
* Move the TCBug37498 directory into the webapps directory and wait 30 seconds
for it to deploy.
* Then move the webapps/TCBug37498 directory outside the webapps directory maybe
into /tmp.
* Now watch the TC logs and try to access the context (or any context) from that
point on.


I found the problem is caused by a loging statement generated by TC, but it is
somehow using a logger instance that was loaded by the WebappClassLoader.

My web-application has local copies of apache-commons-logging and log4j as I
expect the to be 100% isoloted from the logging mechanism TC itself uses.


The problem occur at this point and the extra code helps you see the problem in
org/apache/catalina/core/StandardContext.java:3768 inside #listenerStop()

try {
    fireContainerEvent("beforeContextDestroyed", listener);
    listener.contextDestroyed(event);
    fireContainerEvent("afterContextDestroyed", listener);
} catch (Throwable t) {
    fireContainerEvent("afterContextDestroyed", listener);
    try {
        // This call uses the web-app's logger not TCs
        //  because some classes to perform this call are coming from the
        //  contexts WEB-INF/lib/*.jar files WebappClassLoader this call 
        //  spits out a ClassNotFoundException and that breaks TCs
        //  undeployment mechanism by now allowing #stop() to complete
        // vvvvvvvvvvvvv
        getLogger().error
         (sm.getString("standardContext.listenerStop",
         listeners[j].getClass().getName()), t);
    } catch(Throwable tt) {
        // vvvvvv I added this catch() block and the extra debug output
        // the catch block fixes the problem by returning control to TC
        // so it can complete undeployment
        System.err.println("listenerStop(): exception in ");
        tt.printStackTrace();
        System.err.println("listenerStop(): ...from... ");
        t.printStackTrace();
        System.err.println("ClassLoader on getLogger() is " +
getLogger().getClass().getClassLoader());
        System.err.println("ClassLoader on context is " +
context.getClass().getClassLoader());
        System.err.println("ClassLoader on this is " +
this.getClass().getClassLoader());
    }
    ok = false;
}


getLogger().getClass().getClassLoader() == WebappClassLoader
this.getClass().getClassLoader() == StandardClassLoader

Maybe this is 100% correct and expected behaviour.  But the problem that occurs
is the call to log the Tomcat Container situation relys on the web-apps class
files (which we just deleted/removed).

I would have expected the logger TC itself uses to be isolated from the logger
my web-app is using by the different class loaders being used.  I would guess
the $CATALINA_HOME/bin/commons-logging-api.jar would be the instance
StandardContext.getLogger() would always return.


This is the output I got with the above code in place.

Mar 16, 2006 9:41:26 AM org.apache.catalina.startup.HostConfig checkResources
INFO: Undeploying context [/TCBug37498]
DEBUG 09:41:26,106 (SecurityContextFilter.java:destroy:41)  -Executing filter
#destroy()
DEBUG 09:41:26,106 (ApplicationLifecycleListener.java:contextDestroyed:27) 
-contextDestroyed on "TCBug37498"
INFO  09:41:26,107 (ApplicationLifecycleListener.java:contextDestroyed:30) 
-contextDestroyed on "TCBug37498"  done!
listenerStop(): exception in
java.lang.NoClassDefFoundError: org/apache/log4j/spi/ThrowableInformation
        at org.apache.log4j.spi.LoggingEvent.<init>(LoggingEvent.java:154)
        at org.apache.log4j.Category.forcedLog(Category.java:388)
        at org.apache.log4j.Category.log(Category.java:853)
        at org.apache.commons.logging.impl.Log4JLogger.error(Log4JLogger.java:193)
        at
org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:3774)
        at org.apache.catalina.core.StandardContext.stop(StandardContext.java:4340)
        at
org.apache.catalina.core.ContainerBase.removeChild(ContainerBase.java:892)
        at
org.apache.catalina.startup.HostConfig.checkResources(HostConfig.java:1013)
        at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1172)
        at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:292)
        at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at
org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1305)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1569)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1578)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1558)
        at java.lang.Thread.run(Thread.java:595)
listenerStop(): ...from...
java.lang.NoClassDefFoundError: org/apache/log4j/helpers/NullEnumeration
        at org.apache.log4j.Category.getAllAppenders(Category.java:410)
        at org.apache.log4j.Category.closeNestedAppenders(Category.java:223)
        at org.apache.log4j.Hierarchy.shutdown(Hierarchy.java:447)
        at org.apache.log4j.LogManager.shutdown(LogManager.java:227)
        at
testpackage.ApplicationLifecycleListener.contextDestroyed(ApplicationLifecycleListener.java:34)
        at
org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:3770)
        at org.apache.catalina.core.StandardContext.stop(StandardContext.java:4340)
        at
org.apache.catalina.core.ContainerBase.removeChild(ContainerBase.java:892)
        at
org.apache.catalina.startup.HostConfig.checkResources(HostConfig.java:1013)
        at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1172)
        at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:292)
        at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at
org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1305)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1569)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1578)
        at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1558)
        at java.lang.Thread.run(Thread.java:595)
ClassLoader on getLogger() is WebappClassLoader
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@b05236

ClassLoader on context is org.apache.catalina.loader.StandardClassLoader@79a5f739
ClassLoader on this is org.apache.catalina.loader.StandardClassLoader@79a5f739


Okay.. I think I may have a proper path for this problem, during the setup of
the Context in StandardContext#start() we zap the logger instance for use while
re run some web-app related method.

I think we should also zap it again when we unbind and return that thread back
to the containter execution context so all future logging is done with TCs
logging instances from StandardClassLoader.

Please explain any specific objections to that.  I realize logging and
ClassLoaders are a nightmare.

This new patch correctly makes the error message get reported by TC and
undeployment seems to complete allowing a new deployment for the same context to
occur again.

There are other places in the StandardContext where bind and unbind are used so
maybe flipping which logging via what ClassLoader we are using should be a part
of that bind/unbind process.

Created attachment 17907 [details]
Test Case WAR file but use in exploded form

Contents of the WAR:

$ jar -tvf TCBug37498.war
    39 Thu Mar 16 01:34:06 GMT 2006 META-INF/MANIFEST.MF
  1268 Thu Mar 16 01:14:12 GMT 2006
WEB-INF/classes/testpackage/SecurityContextFilter.java
 38015 Sat Jan 28 12:13:20 GMT 2006 WEB-INF/lib/commons-logging-1.0.4.jar
350627 Sat Jan 28 12:13:18 GMT 2006 WEB-INF/lib/log4j-1.2.11.jar
   443 Thu Mar 16 01:28:08 GMT 2006 index.jsp
  2175 Thu Mar 16 01:31:56 GMT 2006
WEB-INF/classes/testpackage/SecurityContextFilter.class
  1236 Thu Mar 16 01:20:58 GMT 2006 WEB-INF/classes/testpackage/DefaultServlet.java
  2092 Thu Mar 16 01:31:56 GMT 2006
WEB-INF/classes/testpackage/ApplicationLifecycleListener.class
  1301 Thu Mar 16 01:16:40 GMT 2006
WEB-INF/classes/testpackage/ApplicationLifecycleListener.java
  1297 Thu Mar 16 01:17:52 GMT 2006 WEB-INF/web.xml
    62 Thu Mar 16 01:22:38 GMT 2006 filtered/index.jsp
  1097 Thu Mar 16 01:32:42 GMT 2006 WEB-INF/classes/log4j.properties
  2018 Thu Mar 16 01:31:56 GMT 2006 WEB-INF/classes/testpackage/DefaultServlet.class

Created attachment 17908 [details]
This 2 line patch fixes the bug for me

(In reply to comment #5)
> getLogger().getClass().getClassLoader() == WebappClassLoader
> this.getClass().getClassLoader() == StandardClassLoader
> 
> Maybe this is 100% correct and expected behaviour

How did you guess ? ;)

> .  But the problem that occurs
> is the call to log the Tomcat Container situation relys on the web-apps class
> files (which we just deleted/removed).

The files are "deleted/removed" after, when stopping the classloader. In
listenerStop, the classloader is fully able to load any class, and the context
classloader is also correctly set.

> Okay.. I think I may have a proper path for this problem, during the setup of
> the Context in StandardContext#start() we zap the logger instance for use while
> re run some web-app related method.

This is because some (bad) components may call getLogger before the context
classloader is correctly set. This is not the case here.

> I think we should also zap it again when we unbind and return that thread back
> to the containter execution context so all future logging is done with TCs
> logging instances from StandardClassLoader.

This is not "future logging", this is perfectly valid logging, done in the
application context, which is still available.

> Please explain any specific objections to that. 

The issues is that there's no reason to do that.

> I realize logging and
> ClassLoaders are a nightmare.

No. Only certain technologies have issues. You would have no issues with
java.util.logging, for example.

Your points noted.  They do however seem to be more subjective than objective,
maybe you would re-phrase them in a technical manner so everyone can better
understand the technical point of view you are trying to convey.


Some other alternative solutions I can suggest

* dont use a standard logger class directly from any code that may in the future
end up relying on the web-app own logging implementation.  A new wrapper class
that would be able to catch any exception (generated by the web-app logger class
chain) and divert that back to TCs own logger class chain.

* wrap all code that may in the future rely on web-app's own logging
implementation with try { } catch() blocks so TC container code is not affected
by exceptions raised from within it (which maybe what the web-ap itself is
programmed to do, what I mean by this is that if the logging implementation
within the web-app is designed to allow 100 lines to be emited than after that
it throws out exceptions, thats the web-app's choice to make I'm then saying TCs
stability should be in no way affected by that choice).

if any have any suggestions of your own please share.


With reference to your "future logging" comment, it doesn't make any sense given
this bug report and suggests you may not have taken all the details in.

(In reply to comment #10)(In reply to comment #10)
> Your points noted.  They do however seem to be more subjective than objective,
> maybe you would re-phrase them in a technical manner so everyone can better
> understand the technical point of view you are trying to convey.

Whatever.

> Some other alternative solutions I can suggest

I do not see how they make any sense, that's the issue.

> With reference to your "future logging" comment, it doesn't make any sense given
> this bug report and suggests you may not have taken all the details in.

Ok, no problem, I will ignore this bug report, then.

More childish behaviour from Remy what a supprise.

Please cite technical grounds, your personal opinion does not matter Remy its
purely subjective that doesn't do an OSS project any good.  Your work and effort
on Tomcat is appreciated but you if you can't make a factual technical argument
to backup your view then why make comment at all.

Please don't resolve this bug again unless you actually address it.

Was a patch ever actually applied to a Tomcat release to fix this problem?

We are running tomcoat 5.5.17, and are experiencing this problem, and are 
having to actually shutdown/restart Tomcat to undeploy/redeploy our 
application.

(In reply to comment #13)
> Was a patch ever actually applied to a Tomcat release to fix this problem?
> We are running tomcoat 5.5.17, and are experiencing this problem, and are 
> having to actually shutdown/restart Tomcat to undeploy/redeploy our 
> application.

Correction:  we are using 5.5.16 ...not 5.5.17.

I would also like to know if anyone in the Tomcat community is planning to fix
this bug.  I have just encountered it in 5.5.15 running on Ubuntu. 
Specifically, when I shut down TC via bin/shutdown.sh, I get
java.lang.NoClassDefFoundError: org/apache/log4j/spi/ThrowableInformation.

I have tried to reproduce and isolate the problem without success.  It is
especially strange as this is a test server which has been running stably for
several months now, and we have not encountered this issue before.  I will
investigate further, following the lines of Darryl's suggestions, because if I
cannot deal with issue, we will have to look at an alternative JDK1.5 compatible
webapp server, because I cannot put this Tomcat in production.

I must also say that I find the childish nature of Remy's comments extremely
unsettling.  I have been using Tomcat for the last 4 years, and have put webapps
in production on both TC 4.x and 5.0, ontop of both RedHat 9, Mandrake, Centos
and Solaris.  TC has its 'known issues', but in general one of the things I like
about it is that it is simple, predictable.  Therefore perhaps a more mature
member of the TC team could have a look at this?

Darryl and Mike, I will post my findings here, and meanwhile please let me know
if you find any consistently applicable workarounds (including a TC upgrade).

I coin the term, "Tomcat web-app logger hijacking", if a container is going to
hijack the applications choice of logger then the container needs to provide
adequte protections and safe gaurds against any undesirable behavour that logger
may have.

I believe this problem can be fixed by putting a wrapper class between the
logging calls the container makes and the calls to the hijacked logger instance.
 This wrapper traps and ignores unwanted exceptions (and optionally provides
fallback logging to the container's logfile and/or stderr).  As per comment #10

Remy did commit a patch a while ago in his attempt to fix the problem by
catching the exception further up the stack trace (than the loging method call).
 But this doesn't work as the webapp on that context is no longer functional or
deployable in situations where that new catch() is executed.  This is probably
because the entire housekeeping process during the undeploy did not finish and
so the container is left in unusable state.

I'm not sure NEEDINFO is the correct status as I think the cause and problem is
fully understood now.  Maybe NEEDPATCH is really the case here but only one
committer has shown interest in this problem and their opinion on the matter is
clearly documented.  So why would anyone go to the trouble of creating a patch.

Created attachment 23069 [details]
Proposed patch

I have been reviewing this issue and it appears that the original bug report is actually multiple inter-related issues. Using a later version where a number of these have been fixed makes this a lot easier to get one's head around.

The original test case is still valid but the log4j jar should be replaced with the latest version as the version included appears to suffer from jar locking when used on later Tomcat versions.

The remaining issue is that the undeploy is triggered by deleting the exploded directory. When the logging mechanism tries to load the additional classes it requires it can't since the JAR has been deleted. The exception this causes means that the context is not correctly cleaned up. This also causes issues for subsequent re-deployments.

Undeployment via the manager does not experience this issue since in this scenario the jars are not deleted until later in the process.

A temporary work-around may be to use the context listener to ensure the class(es) required by the logger during shutdown is loaded (I haven't tested this).

I do not believe the proposed two line patch is correct since it would redirect logging to Tomcat in cases where this is not necessary. I have attached an alternative patch which I will propose for inclusion in 5.5.x.

The patch has been applied to 5.5.x and will be included in 5.5.28 onwards.