Bug 48831 - Properly closing JULI FileHandler
Summary: Properly closing JULI FileHandler
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 6
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 6.0.24
Hardware: PC Windows XP
: P2 normal (vote)
Target Milestone: default
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-03-01 09:01 UTC by Konstantin Kolinko
Modified: 2010-03-06 11:21 UTC (History)
0 users



Attachments
2010-03-01_tc7_logging_testing.patch (2.12 KB, application/octet-stream)
2010-03-01 09:01 UTC, Konstantin Kolinko
Details
catalina.2010-03-01.log (6.15 KB, text/plain)
2010-03-01 09:03 UTC, Konstantin Kolinko
Details
localhost.2010-03-01.log (4.50 KB, text/plain)
2010-03-01 09:04 UTC, Konstantin Kolinko
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Kolinko 2010-03-01 09:01:25 UTC
Created attachment 25070 [details]
2010-03-01_tc7_logging_testing.patch

This is a result of testing that I performed for our current trunk to evaluate r910974 that is currently proposed for TC6.

I will first describe my environment. Results and findings will follow below.

Steps to reproduce:
1. With current trunk as of revision 917296 apply the patch that I am attaching to this issue, and build it. The patch:
- adds logging to FileHandler#close().
The logging statement checks that this.writer != null, to do not try logging on a closed handler (thus reopening it).
- sets bufferSize for catalina and localhost handlers
- marks ClassLoaderLogManager#useShutdownHook as volatile

2. Clear the logs folder.
3. Run "catalina.bat start", wait a while and run "catalina.bat stop".

Logs that I'll attach are the result of the above steps.

OS: WindowsXP/SP3, JRE: Sun JRE 6u18
Comment 1 Konstantin Kolinko 2010-03-01 09:03:26 UTC
Created attachment 25071 [details]
catalina.2010-03-01.log
Comment 2 Konstantin Kolinko 2010-03-01 09:04:14 UTC
Created attachment 25072 [details]
localhost.2010-03-01.log
Comment 3 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
org.apache.catalina.loader.WebappClassLoader.clearReferences
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 this.date 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
ClassLoaderLogManager.setUseShutdownHook(true);
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 "catalina.log"). 

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).
Comment 4 Mark Thomas 2010-03-03 17:28:18 UTC
Issues fixed in trunk.
Comment 5 Konstantin Kolinko 2010-03-06 11:21:26 UTC
All issues listed in Comment 3 were fixed in 6.0.x in revision 919742.
Will be in 6.0.26 onwards.
Changing 'Product' from Tomcat 7 to Tomcat 6.