Bug 48716 - Embedded Tomcat JULI aggressively resetting default logging configuration
Embedded Tomcat JULI aggressively resetting default logging configuration
Status: RESOLVED FIXED
Product: Tomcat 6
Classification: Unclassified
Component: Catalina
6.0.24
All All
: P2 normal (vote)
: default
Assigned To: Tomcat Developers Mailing List
:
: 49791 49792 (view as bug list)
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2010-02-09 14:29 UTC by Henning Blohm
Modified: 2014-02-17 13:43 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Henning Blohm 2010-02-09 14:29:26 UTC
When using Tomcat embedded in conjunction with default JDK logging, any removal of a StandardContext instance from the Host container will lead to a reset of all JDK logging configuration.

This is due to 

StandardContext.stop() 

calling 

WebappLoader.stop() 

calling 

org.apache.juli.logging.LogFactory.release(ClassLoader) 

which in turn calls 

LogManager.getLogManager().reset();

and the fact that, when using JDK logging, LogManager.getLogManager returns the default log manager rather that JULI's log manager. 

Suggestion: Check whether the log manager is actually JULI's.
Comment 1 Mark Thomas 2010-02-10 01:43:42 UTC
If you use the standard LogManager then you are going to get memory leaks. You need to be using JULI or another LogManager implementation that is class loader aware.

If this call is only used with JULI then other class loader aware LogManager implementations will have no opportunity to clean up.

On the basis that there may be some valid embedded use cases where you do need to disable the call to reset(), then a better approach is probably to make this configurable, with the default that the call takes place.
Comment 2 Henning Blohm 2010-02-10 01:57:51 UTC
Mark,

if JULI would test for its implementation of LogManager, it would work as it does now by default and would not create further harm in cases where it does not own the LogManager.

If my web apps use JDK Logging as well (and say do not register handlers and your own levels or so), what memory leaks would I need to expect (except that logger names will not be released)? Can elaborate on that please?

Thanks, 
  Henning
Comment 3 Mark Thomas 2010-02-10 02:08:45 UTC
> if JULI would test for its implementation of LogManager, it would work as it
> does now by default and would not create further harm in cases where it does
> not own the LogManager.

Using the standard LogManager causes harm. Again, removing this call provides no opportunity for class loader aware LogManagers (including but not limited to JULI) to do the correct clean-up.

> If my web apps use JDK Logging as well (and say do not register handlers and
> your own levels or so), what memory leaks would I need to expect (except that
> logger names will not be released)? Can elaborate on that please?

That is a question for the users mailing list, not Bugzilla.
Comment 4 Henning Blohm 2010-02-10 02:18:54 UTC
(In reply to comment #3)
> > if JULI would test for its implementation of LogManager, it would work as it
> > does now by default and would not create further harm in cases where it does
> > not own the LogManager.
> 
> Using the standard LogManager causes harm. Again, removing this call provides
> no opportunity for class loader aware LogManagers (including but not limited to
> JULI) to do the correct clean-up.
> 

I didn't say that the call should be removed. I suggested to make it smarter, so that it will not reset the default LogManager. As I am not a developer with JULI or Tomcat for that matter, I do not want to go beyond describing the problem though.

> > If my web apps use JDK Logging as well (and say do not register handlers and
> > your own levels or so), what memory leaks would I need to expect (except that
> > logger names will not be released)? Can elaborate on that please?
> 
> That is a question for the users mailing list, not Bugzilla.

Well thanks. There is a POST on the mailing list regarding this issue.
Comment 5 Mark Thomas 2010-02-10 23:39:32 UTC
Fixed in trunk and proposed for 6.0.x. Given the potentially nasty side-effects in nearly all use cases, it is deliberately undocumented.
Comment 6 Konstantin Kolinko 2010-02-11 14:04:05 UTC
For reference: the current users@ thread discussing this:
http://marc.info/?t=126558517300003&r=1&w=2
Comment 7 Mark Thomas 2010-02-23 23:47:48 UTC
This has been fixed in 6.0.x and will be included in 6.0.25 onwards.
Comment 8 Mark Thomas 2010-08-22 09:34:08 UTC
*** Bug 49792 has been marked as a duplicate of this bug. ***
Comment 9 Mark Thomas 2010-08-22 09:34:36 UTC
*** Bug 49791 has been marked as a duplicate of this bug. ***
Comment 10 S. Ali Tokmen 2010-08-22 10:02:08 UTC
This is not fixed: Tomcat 6.0.29 and 7.0.2 still removes all handlers of all Java loggers.

Here is the code executed by Catalina:

        // Clear the classloader reference in common-logging
        if (clearReferencesLogFactoryRelease) {
            org.apache.juli.logging.LogFactory.release(this);
        }

... which looks correct. But, JULI actually ignores the given ClassLoader and calls:

        java.util.logging.LogManager.getLogManager().reset();

Which basically removes all handlers of all loggers of the Java util logger. Note that the comment on JULI says it should remvoe only things from JULI, that is UNTRUE.

The correct implementation would, I guess, look like that:

    To clean up all of the current Web application's loggers:

    get all loggers' names
    for each logger
        get all handlers
        for each handler
            if the handler's class can be loaded using the WebAppClassLoader
               AND cannot be loaded using the WebAppClassLoader's parent
            then
              remove this handler
            else don't touch
              // that logger belongs to some other application
              // or to Tomcat itself
Comment 11 Mark Thomas 2010-08-22 10:33:39 UTC
Your analysis is incorrect. This is issue is resolved.

You need to look more carefully at the implementation of reset() and getLoggerNames()
Comment 12 S. Ali Tokmen 2010-08-22 11:06:38 UTC
Hello

Well, I'm currently analyzing the java.util.logging.LogManager.java (version: 1.55 09/05/17 | SUN PROPRIETARY/CONFIDENTIAL.)

JULI calls:

    java.util.logging.LogManager.getLogManager()

that, returns the following:

    // The global LogManager object
    private static LogManager manager;

The static "manager" variable is defined in java.util.logging.LogManager, which is in the Java SE classloader. It is therefore the same instance for all the JVM.

That (UNIQUE) instance has an attribute:

    private Hashtable<String,Logger> loggers = new Hashtable<String,Logger>()

Finally, getLoggerNames() returns:

    public synchronized Enumeration<String> getLoggerNames() {
	return loggers.keys();
    }

As a result, I do not see how come java.util.logging.LogManager.getLogManager().reset() could reset anything else than the whole JVM's loggers, hence how this bug can be resolved fixed.
Comment 13 Richard Evans 2010-10-07 08:29:10 UTC
I agree with the analysis in the previous comment.  All the loggers in the VM are being reset.

There is a property clearReferencesLogFactoryRelease in the WebappClassLoader but I cannot find any way to set it in server.xml.  It is not recognized on the Context or Loader elements.
Comment 14 Mark Thomas 2010-10-07 09:27:45 UTC
The standard LogManager can't be used with Tomcat. If it is used, then a range of problems will occur including logger mix-ups and memory leaks. The expectation is that JULI's LogManager is used.

The assumption is that in the rare scenarios where it is safe to use the standard LogManager (and I suspect there are very, very few of these) they would be embedded scenarios where clearReferencesLogFactoryRelease could be set this directly on the class loader. In a standard Tomcat install setting this option will cause nothing but problems.

The property could be exposed on the Context but I'm reluctant to expose an option that has no upside. If there was a valid use case for setting this in a standard Tomcat install then an enhancement request to that effect would be considered but right now I don't see a valid use case.
Comment 15 Henning Blohm 2010-10-07 10:41:50 UTC
(In reply to comment #14)
> The standard LogManager can't be used with Tomcat. If it is used, then a range
> of problems will occur including logger mix-ups and memory leaks. The
> expectation is that JULI's LogManager is used.
> 
> The assumption is that in the rare scenarios where it is safe to use the
> standard LogManager (and I suspect there are very, very few of these) they
> would be embedded scenarios where clearReferencesLogFactoryRelease could be set
> this directly on the class loader. In a standard Tomcat install setting this
> option will cause nothing but problems.
> 
> The property could be exposed on the Context but I'm reluctant to expose an
> option that has no upside. If there was a valid use case for setting this in a
> standard Tomcat install then an enhancement request to that effect would be
> considered but right now I don't see a valid use case.

Mark, 

your comments on this issue are truely irritating. There are people that really want to use the standard log manager. I want to. Registering application level log handlers is the exception. Let people handle it.

The way it is handled now breaks the use of the standard LogManager - which is none of Tomcat's business. We will certainly not make JULI the underpinning of our infrastructure (that could - but as it stands will not - embed Tomcat) just because you don't like the standard LogManager.

Those mixups and memory leaks are mostly insignifcant to the development scenario and much less so in production scenarios - supposing you hit the problem at all. Imposing JULI on the world just to be right is not reasonable.

Henning
Comment 16 S. Ali Tokmen 2010-10-07 14:27:23 UTC
(In reply to comment #15)
> Imposing JULI on the world just to be right is not reasonable.

I cannot agree more. Tomcat, as a Java application like any other, should NOT be imposing a logger but rather reuse the existing logger.

(Bis repetita) The correct implementation for this memory leak avoiding mechanism would, I guess, look like that:

    To clean up all of the current Web application's loggers:

    get all loggers' names
    for each logger
        get all handlers
        for each handler
            if the handler's class can be loaded using the WebAppClassLoader
               AND cannot be loaded using the WebAppClassLoader's parent
            then
              remove this handler
            else don't touch
              // that logger belongs to some other application
              // or to Tomcat itself
Comment 17 Mark Thomas 2010-10-07 17:21:52 UTC
(In reply to comment #16)
> (In reply to comment #15)
> > Imposing JULI on the world just to be right is not reasonable.
> 
> I cannot agree more. Tomcat, as a Java application like any other, should NOT
> be imposing a logger but rather reuse the existing logger.

That simply isn't an option.

This isn't about being right, neither is it about not liking the standard LogManger, it is the result of long - and in some cases bitter - experience of committers, contributors and users of the issues (memory leaks, locked JARs, mixed up log messages) associated with log managers of all forms in the complex class loader environment that is a Servlet container.

This isn't limited to the default LogManager implementation, if you look back in the archives you'll find similar issues associated with commons logging and - if memory server me correctly - log4j as well.

JULI was the Tomcat community's solution to these problems and it has worked very well. There are far less class loader / memory leak / logging type issues reported to the users list now than there were when I first got started on this project. Like any code, JULI has had some bugs along the way but is now very stable.

Like any requirement, support for working with the standard LogManager is going be considered based on:
- how invasive any change is
- how many users are likely to use it
- the likelihood of it causing problems for users that turn into questions on the users list.

This last point is a real concern in this case. Not using JULI would cause potentially hard to diagnose problems for many users. The user's mailing list doesn't need the extra questions.

Despite the tone of the previous comments (please try and remember the committers are doing this because they enjoy it - people don't do things by choice that aren't fun and this bug is heading rapidly towards not being fun), I have been giving this some more thought.

A previous suggestion was to only call reset() if JULI was the LogManager. My objection to that approach remains - it doesn't allow for alternative class loader aware LogManager implementations. However, a slight variation of that idea could work - call reset() unless the current LogManager is the standard java.util.logging.LogManager. The downside is that unless exactly that LogManager is used, reset() is still going to get called.

Would a change to LogFactory.release() that checked for java.util.logging.LogManager and logged a warning rather than called reset() in that case meet your requirements?

(Might have to skip logging a message - could get into circular dependency issues)
Comment 18 Henning Blohm 2010-10-08 04:50:46 UTC
Not calling 

LogManager.getLogManager().reset();

when it is java.util.logging.LogManager would help.

I suppose a mix of this with cleaning up what is JULI's looks promising (possibly like S. Ali suggested, or similarly - sorry, I didn't look into the code again and it's been a while).

Developers that define (for whatever reason) application local handlers can either rely on JULI to clean up or register a context listener and clean up on their own (e.g. use commons logging ServletContextCleaner if applicable) - if they want to make sure.

In any case, usage of java.util.logging outside of the web container would not be harmed.

Sounds good to me.

Thanks,
  Henning
Comment 19 Mark Thomas 2010-10-08 08:31:47 UTC
I've added the additional check before the reset() call to trunk and it will be in 7.0.4 onwards.

For users that want to use the default LogManager, as long as applications are not reloaded the worst that should happen is loggers being shared across multiple applications.

If application reload is required and memory leaks are not acceptable then the suggested approach in comment #10 / comment #16 should address any potential memory leak issues and could be implemented as a ServletContextListener. I don't propose adding this code to the Tomcat code-base.
Comment 20 S. Ali Tokmen 2010-10-09 09:26:24 UTC
Hello Mark

(In reply to comment #19)
> I've added the additional check before the reset() call to trunk and it will be
> in 7.0.4 onwards.

I guess the patch is the one I see by inspecting the Tomcat source code using:

    svn diff -r 1005801:1005802 http://svn.apache.org/repos/asf/tomcat/trunk/

Which has the following check before the call ro reset():

    if(!LogManager.getLogManager().getClass().getName().equals("java.util.logging.LogManager"))

The fix is good for me, thank you. Could you please also port it to Tomcat 6.0.x ?

When trying to find the fix suggested in my comments, I've actually seen that the LogManager doesn't have a removeLogger method; which makes the actual patch pretty complex.

Cheers

S. Ali Tokmen
http://ali.tokmen.com/
Comment 21 Konstantin Kolinko 2010-10-15 07:19:15 UTC
I proposed r1005802 for backport to 6.0.
Though maybe we can enhance that to print some warning when it happens, or maybe just one warning at startup time.

BTW, I have a use case where the default LogManager is useful for us. That is not in production, but during development only.

We have several webapps where there is a WEB-INF/classes/logging.properties file that is configured to do not output anything to the console.  When we debug those applications it is helpful to use the default LogManager instead of JULI, so that those logging.properties are ignored and all debug output goes to the console.
Comment 22 Mark Thomas 2010-10-19 12:45:51 UTC
Patch applied to 6.0.x and will be in 6.0.30 onwards