[slf4j-dev] [Bug 15] New: SLF4JLog 'logger' field nulled by Tomcat 5.5.15

[bugzilla-daemon at gil.qos.ch]

http://bugzilla.slf4j.org/show_bug.cgi?id=15

           Summary: SLF4JLog 'logger' field nulled by Tomcat 5.5.15
           Product: SLF4J
           Version: unspecified
          Platform: PC
        OS/Version: Windows XP
            Status: NEW
          Severity: normal
          Priority: P2
         Component: Implementations
        AssignedTo: dev at slf4j.org
        ReportedBy: matt.invoices at llmj.com


Before I begin, let me say that this is NOT a support request.  I understand the
problem and I will describe it after I give you a little background. :-)

I have been working on replacing commons-logging.jar in Tomcat 5.5.15 with a
combination of log4j, jcl104-over-slf4j, and slf4j-log4j12.  I managed to get
the container to boot properly and load all web applications.  However, if I
unload and then re-load an application, I get a NullPointerException the first
time a class which uses a *static* Log instance is loaded.  In my case, this has
happened to be CollectionFactory from the Spring Framework.  However, the
problem arises whenever a class holds a Log instance in a static field.

After several hours of work, I was able to find the problem.  My setup puts the
various log4j and slf4j classes into the Tomcat 'common' classloader and the
Spring jars into the web application class loader.  The end result of this is
that all loggers are cached in the 'loggerMap' field of SLF4FLogFactory and that
this cache is not cleared during an app refresh.  When an application is
restarted after a shut down, all of the loggers are obtained again from this
map.  Not really a problem in and of itself.

Here is the problem: when these loggers are held in static fields on classes in
the web application class loader, Tomcat destroys their internal state on
application shutdown.  The offending lines can be seen starting on line 1583 of
WebappClassLoader.java in the Tomcat 5.5.15 source.  In short, Tomcat's
classloader, as a hedge against state-in-static memory leaks, goes through each
class as it unloads and examines all of its static fields.  For each static
field that it finds, it calls a method called nullInstance() (defined later in
the same source file) which goes through and nulls all references in the object
referenced by the static.  When it hits an SLF4JLog object, this obliterates its
internal 'logger' reference.

When the application is restarted, the static loggers are restored (from SLF4J's
cache) using the existing SLF4JLog instances...which now have null 'logger'
fields.  The end result is a NullPointerException the first time a method is
called on the SLF4JLog instance as none of them do any null checking before
delegating through to 'logger'.

To work around this issue, I defined a static WeakHashMap called
'instanceLoggers' in SLF4JLog and modified the constructor as follows:

  SLF4JLog(Logger logger) {
    this.logger = logger;
    instanceLoggers.put(this, logger);
  }

...and added a getLogger() method:

  private Logger getLogger()
  {
    if (null == logger)
    {
      System.out.println("Retrieving logger for instance SLF4JLog#" +
System.identityHashCode(this) + ".");
      logger = (Logger)instanceLoggers.get(this);
      if (null == logger)
      {
        throw new NullPointerException("Failed to get logger instance for
instance SLF4JLog#" + System.identityHashCode(this) + ".");
      }
    }
    return logger;
  }

...and then replaced all direct references to 'logger' with calls to
getLogger().  (For example, 'logger.info(...)' became 'getLogger().info(...)'.

After these changes were made, everything in Tomcat worked smoothly.  During
restart, the "Retrieving logger..." output was noted for each and every static
Log present in a class loaded by the web application classloader.

This is really a Tomcat issue, so I'm not sure whether you'd want to address it
in the SLF4J code.  You shouldn't have to worry about classloaders rudely
stripping state out of your live objects.  But I decided that it would be best
to let you know about the problem in any case.

P.S. Marking the 'logger' field in SLF4JLog as 'final' does not prevent this
behavior.  Tomcat still overwrites it.

-- 
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.