tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Prastein, Rebeccah H" <Rebeccah.H.Prast...@questdiagnostics.com>
Subject webapp deploy/undeploy log4j and other weirdnesses
Date Tue, 02 Dec 2008 22:45:32 GMT
The deeper I dig, the more I'm confusing myself, and the more weird
stuff I unearth, so I apologize if this seems disjointed.  I know it's
all a big jumbled mess, and I'll need to chop it up into separate
topics, but if anyone has any clues about *any* of this, I'd be most
appreciative.

I started out with a problem of log4j not writing all of the log
statements to my RollingFileAppender right away - like some sort of I/O
blocking.  If I log enough statements, eventually all of the accumulated
ones write out, but it doesn't seem to be just a time-dependent thing (I
may be wrong about that, though, need to test some more).  So, I thought
maybe it was buffering.  But I have all of the log4j settings related to
buffering set to not buffer, and to flush at the end of each line (and
these are the defaults for FileAppenders anyway).

I'm not using a PropertyConfigurator or a BasicConfigurator, I'm using a
servlet (called Log4JServlet) that loads first on startup, and manually
configuring log4j there so that I can change the logging levels later.

Next, I started getting an unload() exception *after* completing the
Log4JServlet.init() method, complaining about some unspecified exception
in the destroy() method for the Log4JServlet.  The stack trace showed
inability to close a QuietWriter, which is an internally sequestered
part of a log4j WriterAppender.  So evidently there is some Appender
that isn't being closed down properly when my web app is redeployed, and
it only gets GC'd after the Log4JServlet is initialized.  Interestingly,
I'm no longer getting the unload() and Log4JServlet.destroy() parts of
the message any more (since I commented out the
ROOT_LOGGER.removeAllAppenders() and REQUEST_LOGGER.removeAllAppenders()
from Log4JServlet.destroy()), but I'm still intermittently getting the
issues with closing the QuietWriter.

Then, I started getting notices about log4j not being properly
initialized (not having any appenders) for a logger I don't even use,
for org.apache.commons.digester.Digester.sax.  I've searched my web app,
including the spring framework jars, and I haven't found
commons-digester anywhere, so I don't know where this is coming from,
although the error appeared shortly after I got rid of the
log4j.properties file.  I also looked at the other web applications
running on Tomcat, although I would think that Tomcat would keep them
all separate, and I haven't changed Tomcat's default logging at all.
The Log4JServlet is supposed to load before anything else, but I did add
some Spring dependency injection into it, so I'm guessing most likely
Spring uses commons-digester and I just haven't found it yet.  Not a big
deal, just annoying.

Subsequent addition of code to list out all of the Appenders in my
default Hierarchy and suss out the QuietWriters associated with them,
shows a huge number of loggers that I don't explicitly create, most of
them associated with Spring.  There are several associated with apache
and/or Tomcat, or perhaps with the web application context that Tomcat
provides:
	
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/MSScalcu
lator].[default]
	
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/MSScalcu
lator].[webcalculator]
	org.apache.commons.digester.Digester.sax
	org.apache.catalina.session.ManagerBase
	
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/MSScalcu
lator].[jsp]
	
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/MSScalcu
lator]
	
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/MSScalcu
lator].[log4j]
	org.apache.commons.digester.Digester
	
FYI, "/MSScalculator" is the path to my web application, "webcalculator"
is the name of my web application's main servlet in web.xml, and "log4j"
is the name of the Log4JServlet servlet in web.xml.

Oh, and none of the QuietWriter objects that I find by enumerating all
of the Appenders are the ones that I'm seeing exceptions about closing
during servlet finalization.

I actually have two log files that my application appends to:  a debug
log file, and a request log file.  I extended the log4j PatternLayout
that I use for RollingFileAppender for the request log file, to include
a header row at the top of each rolled log file.  It actually writes the
ehader row each time the file is opened, so I expect to see multiple
header rows in a single file as I'm tweaking around.  However, yesterday
I noticed they were always being written in pairs (same timestamp), and
today, in triplets.  This suggests to me that somehow appenders are
sometimes not going away when the app is reloading, and I'm getting two
or now three appenders writing to the same file.  But it's not happening
every time that I reload, or I'd be getting way more than three of
these.

I've also noticed that I'm not getting output to my debug log file at
all any more.  Sigh.

On Friday, to make matters worse, I got an Out of Memory Error (Perm
Gen), three of them actually, each one giving the name of a timer thread
that I use in my main web application.  Those threads are supposed to
die all by themselves after just a few seconds.  I wrote some code to do
a kind of a thread dump, that I call at different points when I'm
confused about what is going on, and today, I found two of them, running
as daemons!  I don't have any code to make them daemons that I know of.

So now, instead of one problem, I'm chasing a bunch of them, but they
seem to fall into two main categories:

1.  Why have I got timer threads hanging around when I redeploy my
webcalculator application?  I need to revisit that code.  Related
question:  How are they turning into daemons?  I don't want them to be
daemons!  This is certainly a bug in my own code, I just need to find
it.

2.  WTF is going on with the log4j appenders during web application
redeployment?  What does Tomcat do with them?  What does Spring do with
them?  Why do they intermittently seem to be incompletely destroyed, or
functioning autonymously?  

Any thoughts appreciated.  I'm going to go back to a simpler version of
my Log4JServlet before I started adding all this debugging stuff, and
see if I can isolate one issue at a time.

Rebeccah




------------------------------------------
The contents of this message, together with any attachments, are
intended only for the use of the person(s) to which they are
addressed and may contain confidential and/or privileged
information. Further, any medical information herein is
confidential and protected by law. It is unlawful for unauthorized
persons to use, review, copy, disclose, or disseminate confidential
medical information. If you are not the intended recipient,
immediately advise the sender and delete this message and any
attachments. Any distribution, or copying of this message, or any
attachment, is prohibited.

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


Mime
View raw message