tomcat-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
Subject DO NOT REPLY [Bug 48831] Properly closing JULI FileHandler
Date Mon, 01 Mar 2010 09:56:25 GMT

--- Comment #3 from Konstantin Kolinko <> 2010-03-01 09:56:24
UTC ---
1. The two first "Closing FileHandler" messages in catalina.log apparently
originate from "catalina.bat stop" run.

I added thread.hashCode() to the messages to catch that, but I now see that it
can be demonstrated clearly by running the shutdown command with a different
logging configuration (e.g. from a separate CATALINA_BASE).

2. The same instance of FileHandler is attached to several Loggers.  When
calling ClassLoaderLogManager#resetLogger() or LogManager#resetLogger() we have
a loop on loggers, each of them closes all handlers that it is attached to.
Thus the same handler is closed many times in a row. 

There may be several consequences to that, but one is a clear bug:
- when undeploying a web application
closes not only web application loggers, but through them also the handler that
write to catalina.log and localhost.log and are shared between applications.

The above issue can be seen from attached localhost.log. The logger is closed
twice (note that an instance of PrintWriter is different each time).

It still works because JULI FileHandler#closeWriter() sets FileHandler#date =
"", and subsequent call to FileHandler#publish() will check the date value and
reopen the logger.  There is a certain time span in FileHandler#closeWriter()
between nulling this.writer and resetting and thus some messages
might be lost in-between.

3. In proposed r910974:
note, that Catalina#stop() calls getRuntime().removeShutdownHook(..)
In that case I suppose we should call
to re-enable ClassLoaderLogManager.shutdown(),  or call shutdown() explicitly.

I was not able to observe side effects from this issue, because, as seen from
the logs, LogManager.Cleaner still runs at shutdown and closes the LogHandler
for "catalina.log". Thus, no data loss occurred. But I think there will be
circumstances when it'll be observed.

It can be seen that in case of "catalina.bat stop" LogManager.Cleaner and
ClassLoaderLogManager.Cleaner run in parallel (the first two messages in

4. I think that ClassLoaderLogManager#useShutdownHook has to be volatile.
Otherwise I think ClassLoaderLogManager.Cleaner thread is likely not to see
changes to its value. Though there is no proof.
(ClassLoaderLogManager.shutdown() mentioned in the logs is from "catalina.bat
stop" run).

Configure bugmail:
------- You are receiving this mail because: -------
You are the assignee for the bug.

To unsubscribe, e-mail:
For additional commands, e-mail:

View raw message