Tomcat send ThreadDeath to one of it's own Threads

[David Delbecq <de...@oma.be>]

Hello,

I experienced a strange behaviour of tomcat a few minutes ago. Container
is configured to do webapp auto reloading when classes changes. I
updated a few WEB-INF/classes/*.properties. Tomcat decided it's time to
reload the webapp because classes did change. However, it killed it's
own webapp loader Thread using a ThreadDeath. As a result, the webapp is
not accessible anymore. I suppose it's a bug from the webapp reloader,
but before submission to bug tracker, i'd appreciate comments.

The result of this problem is
1) webapp does not exist anymore (404 while trying to access it)
2) webapp is marqued in manager as not started, but trying to start it
result in an 'already started' error
3) you must either restart tomcat, either undeploy/redploy the webapp to
get it back working


Error log:
<here, the webapp directory has been altered, webapp need to reload>
760 INFO org.apache.catalina.loader.WebappClassLoader - Illegal access:
this web application instance has been stopped already.  Could not load
org.apache.log4j.spi.ThrowableInformation.  The eventual following stack
trace is caused by an error thrown for debugging purposes as well as to
attempt to terminate the thread which caused the illegal access, and has
no functional impact.
org.apache.catalina.core.ContainerBase - Exception invoking periodic
operation:
java.lang.ThreadDeath
    at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1221)
    at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1181)
    at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:302)
    at org.apache.log4j.spi.LoggingEvent.<init>(LoggingEvent.java:145)
    at org.apache.log4j.Category.forcedLog(Category.java:379)
    at org.apache.log4j.Category.log(Category.java:844)
    at
org.apache.commons.logging.impl.Log4JLogger.error(Log4JLogger.java:193)
    at
org.apache.catalina.core.ApplicationContext.log(ApplicationContext.java:662)
    at
org.apache.catalina.core.ApplicationContextFacade.log(ApplicationContextFacade.java:273)
    at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1104)
    at
org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:900)
    at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:3823)
    at
org.apache.catalina.core.StandardContext.start(StandardContext.java:4087)
    at
org.apache.catalina.core.StandardContext.reload(StandardContext.java:2920)
    at
org.apache.catalina.loader.WebappLoader.backgroundProcess(WebappLoader.java:403)
    at
org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1273)
    at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1561)
    at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1570)
    at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1570)
    at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1550)
    at java.lang.Thread.run(Thread.java:534)
<here, tomcat does nothing more for loading the class>

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Tomcat send ThreadDeath to one of it's own Threads

[David Delbecq <de...@oma.be>]

Darryl L. Miles a écrit :

> David Delbecq wrote:
>
>> I experienced a strange behaviour of tomcat a few minutes ago. Container
>> is configured to do webapp auto reloading when classes changes. I
>> updated a few WEB-INF/classes/*.properties. Tomcat decided it's time to
>> reload the webapp because classes did change. However, it killed it's
>> own webapp loader Thread using a ThreadDeath. As a result, the webapp is
>> not accessible anymore. I suppose it's a bug from the webapp reloader,
>> but before submission to bug tracker, i'd appreciate comments.
>>
>> The result of this problem is
>> 1) webapp does not exist anymore (404 while trying to access it)
>> 2) webapp is marqued in manager as not started, but trying to start it
>> result in an 'already started' error
>> 3) you must either restart tomcat, either undeploy/redploy the webapp to
>> get it back working
>>   
>
> I have also experienced behavior similar to what you describe.  I have
> been able to categorize a few distinct variants.  First of all, can
> you reliably re-create the variant you have just witnessed ?

Not reliably. I was able to reproduce it a few times after the error
occured, but it all seems to be somehow random. Only common step is, it
happens during webapp redeploy, like a container class is using a webapp
class and so keeps it. Note it might be related to another problem i
have in my environnment. If i switch from j2sdk1.4.2_05 to
j2sdk1.4.2_11, tomcat does not start anymore, invoking a class
circularity exception in logger system. I have no clue on what causes
this, but if tomcat tries to use the webapp classloader for it's logging
purpose, that might explain. I maybe have a problem in loggers
configuration i need to investigate (considering 4 different logging
mecanisms are interacting, that could be fun :p )

>
> For some reason that I don't understand the container chooses to use a
> logger instance that is loaded through the WebappClassLoader for its
> own purposes.  Maybe this is mandated in specifications, maybe this is
> so that a web-app has some control internally over context related
> logging events the container generates.  But in my own testing if the
> container sticks with its own logger instance (not loaded via
> WebappClassLoader) then it remain inert to (mis)configuration effects
> the web-app chooses to make.

i don't think it's in specs. Moreover i never wrote any similar rule in
my webapp config. There is no reason tomcat should use my webapp classes
for logging purpose...

>
> I believe the variant you witnessed can be reduced into a simple
> situation where the web-application might reconfigure its logger
> instance (which it rightfully believes its own to do so) in such a way
> to cause problems to the container when it tries to use it later. 
> This problem shows up in a future container logging event.

I believe it's more the container using a class that don't exist anymore
as webapp is undeployed.


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Tomcat send ThreadDeath to one of it's own Threads

["Darryl L. Miles" <da...@netbauds.net>]

David Delbecq wrote:
> I experienced a strange behaviour of tomcat a few minutes ago. Container
> is configured to do webapp auto reloading when classes changes. I
> updated a few WEB-INF/classes/*.properties. Tomcat decided it's time to
> reload the webapp because classes did change. However, it killed it's
> own webapp loader Thread using a ThreadDeath. As a result, the webapp is
> not accessible anymore. I suppose it's a bug from the webapp reloader,
> but before submission to bug tracker, i'd appreciate comments.
>
> The result of this problem is
> 1) webapp does not exist anymore (404 while trying to access it)
> 2) webapp is marqued in manager as not started, but trying to start it
> result in an 'already started' error
> 3) you must either restart tomcat, either undeploy/redploy the webapp to
> get it back working
>   
I have also experienced behavior similar to what you describe.  I have 
been able to categorize a few distinct variants.  First of all, can you 
reliably re-create the variant you have just witnessed ?

For some reason that I don't understand the container chooses to use a 
logger instance that is loaded through the WebappClassLoader for its own 
purposes.  Maybe this is mandated in specifications, maybe this is so 
that a web-app has some control internally over context related logging 
events the container generates.  But in my own testing if the container 
sticks with its own logger instance (not loaded via WebappClassLoader) 
then it remain inert to (mis)configuration effects the web-app chooses 
to make.

I believe the variant you witnessed can be reduced into a simple 
situation where the web-application might reconfigure its logger 
instance (which it rightfully believes its own to do so) in such a way 
to cause problems to the container when it tries to use it later.  This 
problem shows up in a future container logging event.

In your case I think 
org.apache.catalina.core.StandardWrapper#loadServlet() made an innocent 
call to log.error().

Unfortunately this resulted in an exception being thrown.  This does not 
have to be a ThreadDeath exception, it could be almost any Throwable, 
the root problem here is that TC expects its logger to never throw an 
exception no matter what and in some ways a best-effort logger should 
behave this way.  One solution could be to wrap all foreign logger 
instance usage inside the container to catch and eat both Exceptions, 
Errors (aka Throwables).  Or make sure the container's internal code 
never calls a foreign logger, i.e. keep the well configured on that the 
JVM or StandardClassLoader seems to have.  Back to your situation.

Then unfortunately TC was executing inside internal code at the time.

Then unfortunately the Thread of execution for  
org.apache.catalina.core.StandardContext#loadOnStartup() in version 
5.5.16 and older was not adequately protected against exceptions 
occurring in the moment your stack trace show so the threads assigned 
class loader got hosed.  So even if it could have recovered its 
remaining execution would have been with the wrong class loader.


Remy has committed a couple of patches a week or so ago, which would 
address some of these matters for this particular variant, maybe the 
background threads now survives to be invoked again, maybe the thread 
classloader assignment is protected.


For me this is a major problem during development, where an integrated 
IDE is modifying the file layout from under the container, this the 
situation I am continuously getting stung in, maybe in the future some 
guidelines and improvements could be made to allow more seamless 
development in this way (even with major performance loss or complexity 
to achieve) such a solution would result in even greater web-app 
development speeds and much less headache.


-- 
Darryl L. Miles



---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org