You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2010/03/01 10:01:26 UTC
DO NOT REPLY [Bug 48831] New: Properly closing JULI FileHandler
https://issues.apache.org/bugzilla/show_bug.cgi?id=48831
Summary: Properly closing JULI FileHandler
Product: Tomcat 7
Version: trunk
Platform: PC
OS/Version: Windows XP
Status: NEW
Severity: normal
Priority: P2
Component: Catalina
AssignedTo: dev@tomcat.apache.org
ReportedBy: knst.kolinko@gmail.com
Created an attachment (id=25070)
--> (https://issues.apache.org/bugzilla/attachment.cgi?id=25070)
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
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48831] Properly closing JULI FileHandler
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48831
Mark Thomas <ma...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution| |FIXED
--- Comment #4 from Mark Thomas <ma...@apache.org> 2010-03-03 17:28:18 UTC ---
Issues fixed in trunk.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48831] Properly closing JULI FileHandler
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48831
--- Comment #2 from Konstantin Kolinko <kn...@gmail.com> 2010-03-01 09:04:14 UTC ---
Created an attachment (id=25072)
--> (https://issues.apache.org/bugzilla/attachment.cgi?id=25072)
localhost.2010-03-01.log
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48831] Properly closing JULI FileHandler
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48831
--- Comment #3 from Konstantin Kolinko <kn...@gmail.com> 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).
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48831] Properly closing JULI FileHandler
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48831
Konstantin Kolinko <kn...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Component|Catalina |Catalina
Version|trunk |6.0.24
Product|Tomcat 7 |Tomcat 6
Target Milestone|--- |default
--- Comment #5 from Konstantin Kolinko <kn...@gmail.com> 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.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48831] Properly closing JULI FileHandler
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48831
--- Comment #1 from Konstantin Kolinko <kn...@gmail.com> 2010-03-01 09:03:26 UTC ---
Created an attachment (id=25071)
--> (https://issues.apache.org/bugzilla/attachment.cgi?id=25071)
catalina.2010-03-01.log
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org