Bug 27371 - java.lang.ThreadDeath caused by log4j when reloading Tomcat app
Summary: java.lang.ThreadDeath caused by log4j when reloading Tomcat app
Status: CLOSED INVALID
Alias: None
Product: Log4j - Now in Jira
Classification: Unclassified
Component: Layout (show other bugs)
Version: 1.2
Hardware: PC Linux
: P3 normal
Target Milestone: ---
Assignee: log4j-dev
URL:
Keywords:
: 36616 (view as bug list)
Depends on:
Blocks: 26372
  Show dependency tree
 
Reported: 2004-03-02 15:02 UTC by Marc Guillemot
Modified: 2014-02-17 13:44 UTC (History)
5 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Marc Guillemot 2004-03-02 15:02:54 UTC
In Tomcat 5, I get a java.lang.ThreadDeath exception when I reload my
application.  The origin lies in the log4j library:

java.lang.ThreadDeath
        at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1270)
        at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1230)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:315)
        at org.apache.log4j.HTMLLayout.format(HTMLLayout.java:129)
        at org.apache.log4j.net.SMTPAppender.sendBuffer(Unknown Source)
        at org.apache.log4j.net.SMTPAppender.append(Unknown Source)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.log(Category.java:864)
        at org.apache.commons.logging.impl.Log4JLogger.error(Log4JLogger.java:192)
        at
org.apache.catalina.session.StandardManager.start(StandardManager.java:706)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:4226)
        at
org.apache.catalina.core.StandardContext.reload(StandardContext.java:2990)
        at
org.apache.catalina.manager.ManagerServlet.reload(ManagerServlet.java:1019)
        at org.apache.catalina.manager.ManagerServlet.doGet(ManagerServlet.java:377)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:743)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:284)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:204)
        at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:257)
        at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
        at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
        at
org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:245)
        at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:199)
        at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
        at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:587)
        at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:149)
        at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
        at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:184)
        at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
        at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:164)
        at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:149)
        at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
        at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:156)
        at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
        at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
        at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:972)
        at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:206)
        at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:833)
        at
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:732)
        at
org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:619)
        at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:688)
        at java.lang.Thread.run(Thread.java:536)

According to Tomcat developers, it is "This is the old issue of log4j trying to
use the previous classloader" (cf bug #26372).
Comment 1 Jacob Kjome 2004-03-03 05:17:19 UTC
This is generally caused by using configureAndWatch() when configuring Log4j
which starts up a thread which won't stop unless specifically shut down by
LogManager.shutdown().  This should be done in the contextDestroyed() method of
a servlet context listener.  I have never seen this issue since I began calling
shutdown().  BTW, if you are using configureAndWatch() in a web environment,
don't.  It isn't a good idea.  Better to have a configuration servlet or other
mechanism to dynamically modify Log4j workings at runtime than to have Log4j
spawn a thread.  It will only cause you grief.  I'm marking this as worksforme.
 Please reopen if the suggested solution does not work for you.

Jake
Comment 2 Marc Guillemot 2004-03-03 09:30:38 UTC
I don't use (explicitely) configureAndWatch().
In my webapp I just place a log4j.xml in the /WEB-INF/classes directory and I
let log4j configures itself automagically. According to the javadoc
documentation (for the log4j.properties, no mention of log4j.xml) the automatic
configuration uses configure() and not configureAndWatch().
I'll show if LogManager.shutdown() at context destruction helps.
Comment 3 Yann Cébron 2004-03-19 12:04:59 UTC
Jacob,

thanks for your suggestion - this fixes the problem for about 80% of the time, 
but I'm still getting sporadious ThreadDeaths when reloading via the Ant-Tasks.

I'm configuring log4j via a .properties-file.

Any other suggestions?
Comment 4 Marc Guillemot 2004-03-19 12:10:30 UTC
It doesn't solve the problem for me either.
Furthermore I think that a shutdown() of log4j can't bring the expected
behavior. Indeed Tomcat classes use lo4j too (through commons-logging) and would
need to log after a contextDestroyed() method of a context listener has been called.
Comment 5 Jacob Kjome 2004-03-19 15:41:14 UTC
Yaan, are you saying that the ThreadDeath message still contains references to
Log4j in the stack trace after using LogManager.shutdown()?  Or does it now look
like it is coming from something else?  Do you (or any other libraries in your
app) start threads in your app that you don't clean up at application shutdown?


Marc, same question to you.  Furthermore, LogManager.shutdown() shuts down the
LoggerRepository connected to the current running application.  This is decided
based on the type of repository selector being used.  You are correct that, by
default, the default logger repository is used and if LogManager.shutdown() is
used without havin used a custom logger repository selector, it will shut down
logging for all applications using that logger repository.  However, there are
two ways to avoid this affecting other apps....

1.  Put log4j.jar in WEB-INF/lib which automatically scopes the default logger
repository to the current webapp, not to the rest of the server.  This is thanks
to Tomcat's implementation of servlet spec recommended classloading behavior
where the WebappClassLoader is checked first for libraries to load rather than
using normal Java2 classloading behavior where the parent classloader would be
checked first.  Do this for all of your apps and you will have complete logging
separation without taking any further steps.

2.  Use a custom repository selector.  This will provide for a separate logger
repository based on, for instance, each app's JNDI context or Classloader.  Read
more about this here....
http://nagoya.apache.org/wiki/apachewiki.cgi?Log4JProjectPages/AppContainerLogging

Using this, you can have a single instance of Log4j at the server level which is
also avialable to all applications and all logging will be separated for all. 
As such, LogManager.shutdown() calls will only affect the application it was
called from.


Jake
Comment 6 Marc Guillemot 2004-03-23 16:05:10 UTC
Jake,

the ThreadDeath always comes from log4j. As far as I know, I don't have threads
that are not cleaned up.

To 1: I use a log4j.jar per application. My logj.jar are already in WEB-INF/lib

To 2: I have to take time to look at it. It seems interesting.
Comment 7 Yann Cébron 2004-03-24 09:56:02 UTC
Jacob,

thanks for getting back. I tried hard (about 20 times) and provoked another 
stacktrace for you ;-)

*****
java.lang.ThreadDeath
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1227)
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1187)
	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:372)
	at org.apache.log4j.Category.log(Category.java:864)
	at org.apache.commons.logging.impl.Log4JLogger.error
(Log4JLogger.java:192)
	at org.apache.catalina.session.StandardManager.start
(StandardManager.java:659)
	at org.apache.catalina.core.StandardContext.start
(StandardContext.java:4199)
	at org.apache.catalina.core.StandardContext.reload
(StandardContext.java:2963)
	at org.apache.catalina.manager.ManagerServlet.reload
(ManagerServlet.java:972)
	at org.apache.catalina.manager.ManagerServlet.doGet
(ManagerServlet.java:330)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter
(ApplicationFilterChain.java:237)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter
(ApplicationFilterChain.java:157)
	at org.apache.catalina.core.StandardWrapperValve.invoke
(StandardWrapperValve.java:214)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardContextValve.invokeInternal
(StandardContextValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke
(StandardContextValve.java:152)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke
(AuthenticatorBase.java:540)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:102)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardHostValve.invoke
(StandardHostValve.java:137)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.valves.ErrorReportValve.invoke
(ErrorReportValve.java:117)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:102)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardEngineValve.invoke
(StandardEngineValve.java:109)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
	at org.apache.coyote.tomcat5.CoyoteAdapter.service
(CoyoteAdapter.java:160)
	at org.apache.coyote.http11.Http11Processor.process
(Http11Processor.java:793)
	at 
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnectio
n(Http11Protocol.java:702)
	at org.apache.tomcat.util.net.TcpWorkerThread.runIt
(PoolTcpEndpoint.java:571)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run
(ThreadPool.java:644)
	at java.lang.Thread.run(Thread.java:534)

*** 

I don't start any threads myself nor do the libraries I use (well, I suppose - 
using Struts and the usual commons-* stuff), my log4j-1.2.8-jar is in my WEB-
INF/lib, I'm not using *any* shared libraries, all of them are in the 
webapp's /lib (went through this pain often enough..).

This is a real problem when reloading applications in TC used on production 
servers since it will kill the application - only solution is to restart TC..
Comment 8 Thorsten Völkel 2004-05-24 14:07:22 UTC
I think there is a solution for the above problem (stack trace).
Normally you call the logger within each class like this:

Logger myLogger = Logger.getLogger(MyClass.class)

Now lets suppose yout classes name is not MyClass but instead MyOwnClass and 
you call your logger
as shown above. Then the argument does not match the correct class name
and you will get the described stack trace.

So check each call of your logger for the appropriate class names. That should 
fix the problem.


Thorsten
Comment 9 Igor 2004-07-22 12:10:03 UTC
I have the same problem with tomcat 5.0.24. It happens when jsp page has 
errors - I reload context and tomcat gives ThreadDeath exception when I try to 
call this jsp using browser. Tomcat works correctly for some time and then this 
exception occur after next reload.
Comment 10 Chris 2004-07-22 21:22:12 UTC
But log4J doesnt cause a ThreadDeath when in Tomcat 4.*... so is it something 
with tomcat 5???

also, in my stacktrace it is not even in log4J...  and my app used to work in 
Tomcat4.1.28... now I am in the latest 5.* and I get this error...

Thanks, 
Chris

java.lang.ThreadDeath
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1229)
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1189)
	at java.beans.Introspector.instantiate(Introspector.java:1322)
	at java.beans.Introspector.findExplicitBeanInfo(Introspector.java:393)
	at java.beans.Introspector.<init>(Introspector.java:342)
	at java.beans.Introspector.getBeanInfo(Introspector.java:144)
	at org.apache.commons.beanutils.PropertyUtils.getPropertyDescriptors
(PropertyUtils.java:949)
	at org.apache.commons.beanutils.PropertyUtils.getPropertyDescriptors
(PropertyUtils.java:979)
	at org.apache.commons.beanutils.PropertyUtils.getPropertyDescriptor
(PropertyUtils.java:887)
	at org.apache.commons.beanutils.PropertyUtils.getSimpleProperty
(PropertyUtils.java:1172)
	at org.apache.commons.beanutils.PropertyUtils.getNestedProperty
(PropertyUtils.java:772)
	at org.apache.commons.beanutils.PropertyUtils.getProperty
(PropertyUtils.java:801)
	at org.apache.catalina.core.StandardWrapperValve.invoke
(StandardWrapperValve.java:255)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardContextValve.invokeInternal
(StandardContextValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke
(StandardContextValve.java:152)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardHostValve.invoke
(StandardHostValve.java:137)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.valves.ErrorReportValve.invoke
(ErrorReportValve.java:117)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:102)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardEngineValve.invoke
(StandardEngineValve.java:109)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.ContainerBase.invoke
(ContainerBase.java:929)
	at org.apache.coyote.tomcat5.CoyoteAdapter.service
(CoyoteAdapter.java:160)
	at org.apache.coyote.http11.Http11Processor.process
(Http11Processor.java:793)
	at 
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnecti
on(Http11Protocol.java:702)
	at org.apache.tomcat.util.net.TcpWorkerThread.runIt
(PoolTcpEndpoint.java:571)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run
(ThreadPool.java:644)
	at java.lang.Thread.run(Thread.java:534)
Comment 11 Jacob Kjome 2004-07-23 03:34:44 UTC
Chris,

Can you describe what you were doing to get that stack trace?  Were you
restarting the webapp?  I don't see that in the stack trace, but you never know.
 It would be great to prove that this is more an issue with Tomcat5 than with
Log4j.  Your stack trace helps make the case since it doesn't seem to be related
to Log4j, although it could be that the same issue is happening, just in a
different library.

Jake
Comment 12 Chris 2004-07-23 14:47:00 UTC
Thanks for following up.  Upon further investigation, I only get this error 
when running Tomcat in debug mode with the sysdeo plugin for eclipse (Tomcat 
5, Eclipse 3.0).  I think it is a classloader problem in Sysdeo (saw a post 
online of someone who had the same idea).  When running Tomcat in standalone 
mode with the same app I do not get a ThreadDeath, so Im fine with closing 
this bug... Sorry for the inconvenience... Chris
Comment 13 Igor 2004-07-23 15:22:43 UTC
This error occurs in Tomcat 5.0.24 with context that has Axis library. Besides 
Axis library there are ordinary jsp pages. Error occurs when tomcat was 
reloaded, and jsp page with syntax error is being compiled
Comment 14 Chris 2004-07-23 16:29:58 UTC
Actually, my problem was not with Sysdeo.  I replaced Sysdeo with MyEclipse 
debugging plugin, and got the same error.  I reverted back to Tomcat 4.1.28, 
and I do not get the error.  I started Tomcat, hit the controller of my app 
and got the Stacktrace in the other post by me...  I hope this is fixed soon 
as we need features in the newer Servlet spec...  Thanks!  ps. If you have 
trouble reproducing this, I can zip up my open source dev env and post it for 
someone, and you can debug my app and see the error.  :)
Comment 15 Jacob Kjome 2004-07-23 18:50:24 UTC
Chris, can you just attach it to this bug report?

Jake
Comment 16 Allistair Crossley 2004-08-02 15:07:59 UTC
We are getting this error simply by compiling classes to our webapp classes 
directory. This happens _nearly_ on every compile we do, but never used to 
happen. 

SEVERE: Exception invoking periodic operation:
java.lang.ThreadDeath
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1229)
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1189)
	at java.lang.ClassLoader.loadClassInternal(Unknown Source)
	at org.apache.log4j.spi.LoggingEvent.<init>(LoggingEvent.java:145)
	at org.apache.log4j.Category.forcedLog(Category.java:372)
	at org.apache.log4j.Category.log(Category.java:864)
	at org.apache.commons.logging.impl.Log4JLogger.error
(Log4JLogger.java:192)
	at org.apache.catalina.session.StandardManager.start
(StandardManager.java:659)
	at org.apache.catalina.core.StandardContext.start
(StandardContext.java:4272)
	at org.apache.catalina.core.StandardContext.reload
(StandardContext.java:3021)
	at org.apache.catalina.core.StandardContext.backgroundProcess
(StandardContext.java:4629)
	at 
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChild
ren(ContainerBase.java:1619)
	at 
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChild
ren(ContainerBase.java:1628)
	at 
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChild
ren(ContainerBase.java:1628)
	at 
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run
(ContainerBase.java:1608)
	at java.lang.Thread.run(Unknown Source)

As I say, we can reproduce this almost at will with a recompile of classes 
which of course makes Tomcat reload.
Comment 17 Ceki Gulcu 2004-08-02 15:17:44 UTC
From a cursory looks, it looks more like a Tomcat bug related to commons-
logging rather than log4j itself. Maybe this bug should be filed as a Tomcat
bug rather than a log4j bug?
Comment 18 Claudio Corsi 2004-08-02 18:45:48 UTC
It looks like Ceki is right. I looked at the WebClassLoader source at it is
throwing the ThreadDeath exception because the WebClassLoader was stopped. Did
you not mention that you get this exception everytime that you hot deploy your
web application?

Here is the code within tomcat that is throwing the exception:

  // Don't load classes if class loader is stopped
  if (!started) {
     log.info(sm.getString("webappClassLoader.stopped"));
     throw new ThreadDeath();
  }

The sm variable is a static protected variable. It seems to me that it is not
properly being reset somehow.
Comment 19 Claudio Corsi 2004-08-02 19:10:55 UTC
I just realized that I incorrectly mentioned the sm variable instead of the
started variable in my previous explanation. I meant to say the started variable
was not set correctly becaues the classes start method was not called before
trying to use the classload to load the class. It still is a bug within the
tomcat code base and not the log4j code base.

Sorry about that :-(
Comment 20 Yoav Shapira 2004-08-05 13:19:18 UTC
Adding tomcat-dev@jakarta.apache.org as we should keep track of this.  What's 
the solution then?  Not log at all while restarting a webapp?
Comment 21 Yoav Shapira 2004-08-05 19:36:59 UTC
--- Begin Text by Craig McClanahan ---
The reason that LogFactory instances are stored in a map keyed by
context class loader was to meet a functional requirement that each
webapp could have independently configured constellations of Log
instances, created by independent LogFactory instances, per webapp --
even if commons-logging.jar itself is installed into a shared class
loader (i.e. common/lib or shared/lib in Tomcat).  This is why you
can't just use a static variable, because there would only be one
LogFactory instance across the entire Tomcat JVM.  In addition, there
is no other reasonable key that is specific to a webapp, but *not*
specific to the Servlet API (tying commons-logging use to require
servlet.jar would not be a good thing).

In order to allow cleanup of these allocated instances, the
LogFactory.release() method may be used to ask a LogFactory to release
all of its Log instances.  In addition, the static
LogFactory.release(ClassLoader) method releases references to the
LogFactory instance for that class loader.  I believe that both of
these APIs were just added in 1.0.4.

Inside Tomcat, then, a webapp using c-l can add a
ServletContextListener whose contextDestroyed() method calls the
appropriate release methods to clean up.
--- End text by Craig McClanahan ---

So to the people who reported this: please try adding such a 
ServletContextListener and using the above methods that Craig mentioned, and 
let us know if that makes the error go away.
Comment 22 Allistair Crossley 2004-08-06 16:25:19 UTC
I can confirm that the following does _not_ solve the ThreadDeath exception 
when Tomcat reloads the context following a class compile.

import org.apache.log4j.LogManager;
import org.apache.commons.logging.LogFactory;

public void contextDestroyed(ServletContextEvent scE) {		
    LogManager.shutdown();
    LogFactory.releaseAll();
}
Comment 23 Claudio Corsi 2004-08-06 17:55:38 UTC
It seems to me that tomcat reuses these classloaders and I have a feeling that
when the classloader is being reused. The classloader start method does not get
called, causing the classloader to not have been "started", generating the
ThreadDeath exception whenever the loadClass method is called.
Comment 24 Yoav Shapira 2004-08-06 17:57:17 UTC
What are you basing this on?  Any code references would be nice.
Comment 25 Claudio Corsi 2004-08-07 00:55:49 UTC
I was looking at the WebappClassLoader class and it contains a started attribute
that is used to determine that if the WebappClassLoader instance was started
before it can be used to load classes. The started attribute is set using the
classes start and stop methods. The ThreadDeath exception is being thrown
because when the WebappClassLoader instance is calling the loadClass method it
checks that the started attribute is true. If it isn't, it throws the
ThreadDeath exception.

I then looked at the StandardContext class. It contains a method called reload
that is used whenever it wants to reload that particular web application
associated to that instance of StandardContext. I also noticed that the
StandardContext method will associate a single WebappLoader to the
StandardContext instance. This WebappLoader contain the ClassLoader used by this
StandardContext web application. The assignment of the WebappLoader is done only
once and it is done within the start method only. This method initially checks
if the WebappLoader has been associated to the StandardContext. It will then
only assign a WebappLoader to the StandardContext if their was none.

I deduced by looking at these sections of the code that it seems like whenever a
 StandardContext web application is being reloaded. Its WebappLoader
WebappClassLoader start method is not be called before loading any of the web
application classes. It does seem like its stop method is being called whenever
the web application is being stopped.

This is why I believe that the WebappClassLoader is not being properly setup
before being used.

I am basing this on looking at the code only. I have not tried to debug this
case. It is only a theory based on observations and nothing else.
Comment 26 Alex Smirnoff 2004-08-31 20:11:35 UTC
I've got the same exception, but without log4j envolvement. To reproduce try 
this:

1. In TC 5.0.27 login to admin application.
2. Under the Host->Create New Context create the new context pointing to some 
JSP webapp outside standard webapps directory.
3. When finished successfuly, try to invoke this application and you should get 
ThreadDeath exception.

BTW, it is working fine when deploying to the standard webapps directory.

Here is a stack:

java.lang.ThreadDeath
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1229)
	at org.apache.catalina.loader.WebappClassLoader.loadClass
(WebappClassLoader.java:1189)
	at org.apache.jasper.compiler.Parser.parseCustomTag(Parser.java:1316)
	at org.apache.jasper.compiler.Parser.parseElements(Parser.java:1560)
	at org.apache.jasper.compiler.Parser.parse(Parser.java:126)
	at org.apache.jasper.compiler.ParserController.doParse
(ParserController.java:220)
	at org.apache.jasper.compiler.ParserController.parse
(ParserController.java:101)
	at org.apache.jasper.compiler.Compiler.generateJava(Compiler.java:203)
	at org.apache.jasper.compiler.Compiler.compile(Compiler.java:470)
	at org.apache.jasper.compiler.Compiler.compile(Compiler.java:451)
	at org.apache.jasper.compiler.Compiler.compile(Compiler.java:439)
	at org.apache.jasper.JspCompilationContext.compile
(JspCompilationContext.java:511)
	at org.apache.jasper.servlet.JspServletWrapper.service
(JspServletWrapper.java:295)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile
(JspServlet.java:292)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:236)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter
(ApplicationFilterChain.java:237)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter
(ApplicationFilterChain.java:157)
	at org.apache.catalina.core.StandardWrapperValve.invoke
(StandardWrapperValve.java:214)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardContextValve.invokeInternal
(StandardContextValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke
(StandardContextValve.java:152)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardHostValve.invoke
(StandardHostValve.java:137)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.valves.ErrorReportValve.invoke
(ErrorReportValve.java:117)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:102)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardEngineValve.invoke
(StandardEngineValve.java:109)
	at org.apache.catalina.core.StandardValveContext.invokeNext
(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke
(StandardPipeline.java:520)
	at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
	at org.apache.coyote.tomcat5.CoyoteAdapter.service
(CoyoteAdapter.java:160)
	at org.apache.coyote.http11.Http11Processor.process
(Http11Processor.java:799)
...
Comment 27 Yoav Shapira 2004-09-22 14:12:59 UTC
Per Jay Paulsen's findings archived at http://marc.theaimsgroup.com/?
t=109578393000004&r=1&w=2, please try adding the Introspector.flush call to 
your shutdown code and re-testing.  Thanks.
Comment 28 vd 2004-11-23 23:05:52 UTC
Running the embedded Tomcat 5.5.4, after I stop and start() a web context, I got
the following exception (and the AxisServlet does not run).  However, with the
exact same web application in the standalone Tomcat 5.5.4, I don't get any
exception (and the AxisServlet runs ok)

- Starting Coyote HTTP/1.1 on http-80
- Illegal access: this web application instance has been stopped already.  Could
not load META-INF/services/org.apache.axis.EngineConfigurationFactory.  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.
- Illegal access: this web application instance has been stopped already.  Could
not load org/apache/axis/configuration/EngineConfigurationFactoryServlet.class.
 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.
- Illegal access: this web application instance has been stopped already.  Could
not load org.apache.axis.configuration.EngineConfigurationFactoryServlet.  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.
- StandardWrapper.Throwable
java.lang.ThreadDeath
    at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1221)
    at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1181)
    at org.apache.commons.discovery.ResourceClass$1.run(ResourceClass.java:77)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.commons.discovery.ResourceClass.loadClass(ResourceClass.java:73)
    at
org.apache.axis.configuration.EngineConfigurationFactoryFinder$1.run(EngineConfigurationFactoryFinder.java:122)
    at java.security.AccessController.doPrivileged(Native Method)
    at
org.apache.axis.configuration.EngineConfigurationFactoryFinder.newFactory(EngineConfigurationFactoryFinder.java:113)
    at
org.apache.axis.transport.http.AxisServletBase.getEngineEnvironment(AxisServletBase.java:247)
    at
org.apache.axis.transport.http.AxisServletBase.getEngine(AxisServletBase.java:170)
    at
org.apache.axis.transport.http.AxisServletBase.getOption(AxisServletBase.java:370)
    at org.apache.axis.transport.http.AxisServletBase.init(AxisServletBase.java:110)
    at javax.servlet.GenericServlet.init(GenericServlet.java:211)
    at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1053)
    at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:886)
    at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:3817)
    at org.apache.catalina.core.StandardContext.start(StandardContext.java:4079)


- Servlet /axis threw load() exception
javax.servlet.ServletException: Servlet.init() for servlet AdminServlet threw
exception
    at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1095)
    at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:886)
    at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:3817)
    at org.apache.catalina.core.StandardContext.start(StandardContext.java:4079)
Comment 29 vd 2004-11-23 23:35:40 UTC
I meant the AdminServlet did not run.  The AxisServlet ran fine.
Comment 30 Yegor Jbanov 2005-02-09 00:42:45 UTC
Hi!

I'm also experiencing ThreadDeath with Log4j on Tomcat 5.0.28 (bundled with
NetBeans 4.0) when restarting applications. I understand you've already seen a
lot of stack traces in this discussion.  So I'll just give a part of mine:

==========================================
Caused by: java.lang.ThreadDeath
    at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1229)
    at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1189)
    at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:302)
    at org.apache.log4j.NDC.get(NDC.java:201)
    at org.apache.log4j.spi.LoggingEvent.getNDC(LoggingEvent.java:229)
etc...
==========================================

Seems like NDC is arranging its instances in a Hashtable with key being the
current thread. That might be the reason of such behaviour. Have you thought of
switching to ThreadLocal? I'm not sure about how it may affect the performance
though.

Thanks
Comment 31 Brett Randall 2005-02-09 01:08:02 UTC
I'm not sure why this issue remains open, given that #26372 has been closed.

Whenever there is a ThreadDeath thrown from WebappClassLoader.loadClass() during 
a webapp restart, it is due to Tomcat invalidating the webapp's ClassLoader 
while threads are still executing a (long-running) service() method (or even 
lifecycle method).  Tomcat waits 2 seconds, then invalidates the ClassLoader and 
restarts the app, resulting in a ThreadDeath thrown by the ClassLoader if new 
class load requests occur.  See my comment in #26372 .

Given that #26372 has been marked invalid (read as -1 for a configurable [or 
perhaps longer] wait-time for current requests to complete, prior to 
invalidating the ClassLoader and restarting the webapp), I think that this issue 
should now be closed.

This is a Tomcat issue for restartable webapps, not a log4j issue.
Comment 32 Mark Womack 2005-07-01 23:22:22 UTC
Closing as consensus indicates that it is a Tomcat issue.  Wish there was a 
better resolution than "INVALID", but that seems to be the closest fit.
Comment 33 fred hu 2005-08-04 14:57:59 UTC
I found a solution. copy the log4j jar file and rename to another file name, 
such as log4j-1.2.6.jar. put the both log4j jar files to WEB-INF lib directory.
Comment 34 Jacob Kjome 2005-08-04 15:45:05 UTC
Your solution seems more like black magic to me.  What do you think you've
fixed?  And what is it about having 2 log4j jars in WEB-INF/lib changes the
thread death behavior?  You do realize that the thread death stuff is sporadic,
right?  You've performed an action and have found that you haven't gotten the
error.  You attribute the success to your action where, in reality, you can't
know whether it was your action or dumb luck that led to success... unless you
actually do know the real cause/effect relationship.  If so, we're all ears! 
Until then, this is black magic.

Jake
Comment 35 Gili 2005-10-24 15:07:28 UTC
*** Bug 36616 has been marked as a duplicate of this bug. ***
Comment 36 Allistair Crossley 2005-10-24 17:32:38 UTC
although many comments say log4j has nothing to do with it which is 
theoretically probably true, most of the time it appears like log4j is causing 
the issue. my latest threaddeath which i get around 5 times per day I suppose 
after about 5 reloads indicates

INFO: 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.

It does always appear to be this SPI class as long as I can remember. A naiive 
thought but perhaps if there were a way to stop this class entering loadClass 
at the wrong time the threaddeath would disappear for most common cases since 
everyone uses log4j with tomcat.

Comment 37 Gili 2005-10-24 18:01:55 UTC
I second that motion. I also keep on seeing that
"org.apache.log4j.spi.ThrowableInformation" error and I redeploy my application
a few hundred times a day (while developing under Netbeans) so this issue is
very critical to me. It would also be invaluable to have a minimal testcase for
this. Yoav (of Tomcat) has mentioned he'd work on a fix for this issue but we
need a testcase first (he can't reproduce it on his end).
Comment 38 Remy Maucherat 2005-10-24 18:08:07 UTC
(In reply to comment #36)
> although many comments say log4j has nothing to do with it which is 
> theoretically probably true, most of the time it appears like log4j is causing 
> the issue. my latest threaddeath which i get around 5 times per day I suppose 
> after about 5 reloads indicates
> 
> INFO: 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.
> 
> It does always appear to be this SPI class as long as I can remember. A naiive 
> thought but perhaps if there were a way to stop this class entering loadClass 
> at the wrong time the threaddeath would disappear for most common cases since 
> everyone uses log4j with tomcat.

I don't see the point of blaming log4j as is. It's the same problem with any
shared library which would keep objects related to a webapp, while at the same
time being disconnected from the lifecycle (at best, memory leaking will occur).
I'd say the concept is to be blamed, but there are few solutions.

Problems can also be caused by not setting the context classloader well (I did
fix some more issues related to this in 5.5.9+, as JULI is quite sensitive to
that). I think the current code is now clean related to this.
Comment 39 Allistair Crossley 2005-10-24 18:36:40 UTC
hey,

i wasn't really blaming log4j, i just noted from the many many posts for this 
bug that log4j came up a lot and taking a pragmatic view thought it may be 
addressable. however, i appreciate that if you were to do that, then where 
would you stop if other libs caused the same issue. it wouldn't be good to 
pollute tomcat's code to bypass known issues for sure. i jsut think that since 
it's mostly this log4j class causing the issue, someone somewhere could change 
the root cause.

i don't know .. just thinking out load ;)

Comment 40 Gili 2005-10-24 18:45:47 UTC
Remy,

I am using Tomcat 5.5.9, and log4j is only being loaded within the webapp
context (not global) and I still get this problem.

To date everyone keeps on talking theory but no one had yet to offer a practical
solution. Both Brett and Yoav have suggested one, which is to allow a
configurable timeout value before the ClassLoader is invalidated. Granted it's
not foolproof (who knows how big the timeout needs to be), but at least it's a
practical solution. You mention there are some other solutions, what are some of
your practical solutions to this problem?
Comment 41 Darryl Miles 2005-10-27 10:08:37 UTC
Idea, would it be possible to swap class loaders like a DJ does with Records. 
Let the class loader still exist beyond the contextDestroy() call.  But only for
a limited wall clock time or until the next re-deploy for the same context
(whichever comes first).  We don't want to hold N generations of class loaders
during multiple re-deploys.

I'm not sure if Java allows this, but can a supperior management thread poll all
its child threads (or all threads in the JVM) and enquire details about the
execution context of that thread.  This would allow a background poll of all
threads to occurr to identify which execution threads are still using a class
loader that we are trying to shutdown.  If there are none we can cleanup sooner.

This seems like an obvious need from the JVM given the long running nature of
the JVM and the hierarchical class loader mechanism.

I do understand the servlet spec does not mandate what happens, so what we get
is a bonus to us, but I'm more for the view of lets be a leader and write an
implementation thats robust and useful to the general population then maybe a
specification will be written from it for other implementors follow.  Maybe this
is as odds with TCs boilerplate implementation, but when an issue causes so much
pain to the community its time to bear arms.
Comment 42 Remy Maucherat 2005-10-27 10:14:04 UTC
(In reply to comment #41)
> Idea, would it be possible to swap class loaders like a DJ does with Records. 
> Let the class loader still exist beyond the contextDestroy() call.

No.
Comment 43 Gili 2005-10-31 19:31:38 UTC
Ok, no reply from Remy. So on the one hand this isn't a log4j issue, on the
other hand it isn't being fixed in Tomcat... I'll ask again, does anyone have a
minimal testcase for reproducing this issue?
Comment 44 Brett Randall 2005-11-06 23:21:05 UTC
The testcase is fairly straightforward - all you need is a servlet with a
service() method with say a (generous) twenty second sleep in it (during which
you will request a reload of the context), followed by any code that will cause
a class to be loaded.  Hit the servlet with a service request, and reload the
webapp during the sleep.  Tomcat will have invalidated the classloader (and
reloaded the context) by the time the sleep completes, and you should see a
ThreadDeath thrown.
Comment 45 Gili 2005-11-07 07:11:41 UTC
Brett,

There seems to be a mismatch between your test-case description and what I've
been experiencing on my end. What I see on my end is request #1 is run to
termination, I request a reload of the webapp, Tomcat's manager fails the reload
operation and indicates a ThreadDeath has occured. I fully expect the request to
get ThreadDeath if it continues running beyond the scope of a context reload but
what I am seeing (and I consider this a bug) is Tomcat dishing out a ThreadDeath
to a completely unrelated request. If I try sending out request #2 after the
reload operation returns ThreadDeath, the request will fail with yet another
exception. From this point onward Tomcat is in some sort of bad state and no
matter how many times I try manager stop/start/reload it'll always fail. I am
forced to fully shutdown Tomcat and restart it. New requests to the webapp now work.

You can read more about this here:
http://www.netbeans.org/issues/show_bug.cgi?id=62529

Do you have any idea why this is occuring? I have been unable to narrow this
down to a minimal testcase. I saw it once in my minimal testcase, but too rare
to be of any use. In my original application I see it on the first
manager/reload request. I will continue trying to isolate the problem.
Comment 46 Brett Randall 2005-11-08 10:58:24 UTC
Gili,

You asked for a minimal testcase showing ThreadDeath being thrown, so that's
what I described :).  You should try it out - perhaps it will assist in
understanding the specifics of the problem you are having there.

You should bear in mind that this is no longer considered a bug, as the issue is
pretty well understood now.  To re-raise as a bug you would need to be able to
demostrate incorrect behaviour by Tomcat's classloaders.  There are workarounds
for the fact that Tomcat does not allow the service() threads timeout to be
configured.  Other invalid references to classloaders may be harder to track
down, perhaps this is what you are experiencing.

I couldn't see any of your stack-traces above.  Perhaps they will highlight the
operation that caused the ThreadDeath to be thrown.
Comment 47 Darryl Miles 2005-11-09 21:17:22 UTC
(In reply to comment #45)
I request a reload of the webapp, Tomcat's manager fails the reload
> operation and indicates a ThreadDeath has occured. I fully expect the request to
> get ThreadDeath if it continues running beyond the scope of a context reload but
> what I am seeing (and I consider this a bug) is Tomcat dishing out a ThreadDeath
> to a completely unrelated request. If I try sending out request #2 after the
> reload operation returns ThreadDeath, the request will fail with yet another
> exception. From this point onward Tomcat is in some sort of bad state and no
> matter how many times I try manager stop/start/reload it'll always fail. I am
> forced to fully shutdown Tomcat and restart it. New requests to the webapp now
work.


The annoyance I get is that Tomcat states the ThreadDeath that occurs wont upset
the re-deployed web-app, but it does.  No further requests to tomcat on the
web-app are possible.  The only way out is a container restart.  I think maybe
this is a genuine different problem but I've no proof yet.


Maybe as a helpful suggestion, Tomcat could emit in the ThreadDeath exception
message the Thread.getId() and Thread.getName() of the thread that is dying,
this would be useful anyway to help fix your application and put us developers
in the picture as to exactly what died.

throw new java.lang.ThreadDeath("of
Thread#"+Thread.currentThread().getThreadId()+" "+Thread.currentThread().getName());

Would such a trival patch be accepted ?


Unfortunatly I've had no time this week to investigate further, I'm eyeing up
hacking on JMP (Java Profiler) to get a class loader report from heap snapshots
then dumping out all references between objects that cross to a different class
loader.  Maybe someone knows of a tool already for this ?