Bug 40212

Summary: NullPointerException in getLogger when called from ShutdownHook
Product: Log4j - Now in Jira Reporter: Hendrik Brummermann <nhb_web>
Component: OtherAssignee: log4j-dev <log4j-dev>
Status: RESOLVED FIXED    
Severity: normal CC: digulla, ezaustdps, kk_us, mail, serg_main
Priority: P2    
Version: 1.2   
Target Milestone: ---   
Hardware: Other   
OS: Linux   
Attachments: Patch to fix the same NPE in Category.java
Fixed patch

Description Hendrik Brummermann 2006-08-08 14:54:45 UTC
Hi, 

i have a problem with log4j-1.2.13.jar when invoking Logger.getLogger(string)
from a shutdown hook. I have verified that the the string-parameter is not null.

java.lang.NullPointerException
        at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
        at org.apache.log4j.Logger.getLogger(Logger.java:104)
        at de.his.log.LogManager.getLogger(LogManager.java:122)
        at de.his.log.LogManager.getLogger(LogManager.java:81)
        at de.his.utils.SecureProperties.<clinit>(SecureProperties.java:72)
        at sun.misc.Unsafe.ensureClassInitialized(Native Method)
        at
sun.reflect.UnsafeFieldAccessorFactory.newFieldAccessor(UnsafeFieldAccessorFactory.java:25)
        at
sun.reflect.ReflectionFactory.newFieldAccessor(ReflectionFactory.java:122)
        at java.lang.reflect.Field.acquireFieldAccessor(Field.java:917)
        at java.lang.reflect.Field.getFieldAccessor(Field.java:898)
        at java.lang.reflect.Field.get(Field.java:357)
        at
org.apache.catalina.loader.WebappClassLoader.clearReferences(WebappClassLoader.java:1605)
       at
org.apache.catalina.loader.WebappClassLoader.stop(WebappClassLoader.java:1489)
        at org.apache.catalina.loader.WebappLoader.stop(WebappLoader.java:706)
        at org.apache.catalina.core.StandardContext.stop(StandardContext.java:4360)
        at
org.apache.catalina.core.ContainerBase.removeChild(ContainerBase.java:892)
        at org.apache.catalina.startup.HostConfig.undeployApps(HostConfig.java:1159)
        at org.apache.catalina.startup.HostConfig.stop(HostConfig.java:1131)
        at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:312)
        at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at org.apache.catalina.core.ContainerBase.stop(ContainerBase.java:1053)
        at org.apache.catalina.core.ContainerBase.stop(ContainerBase.java:1065)
        at org.apache.catalina.core.StandardEngine.stop(StandardEngine.java:447)
        at org.apache.catalina.core.StandardService.stop(StandardService.java:512)
        at org.apache.catalina.core.StandardServer.stop(StandardServer.java:734)
        at org.apache.catalina.startup.Catalina.stop(Catalina.java:601)
        at
org.apache.catalina.startup.Catalina$CatalinaShutdownHook.run(Catalina.java:644)





Hendrik
Comment 1 Sergio Lissner 2006-09-28 15:03:31 UTC
Another example of this bug:

Exception in thread "Store 
org.riverock.webmill.core.GetWmPortalCatalogLanguageItem Expiry Thread" 
java.lang.NullPointerException
	at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
	at org.apache.log4j.Logger.getLogger(Logger.java:104)
	at org.apache.commons.logging.impl.Log4JLogger.getLogger
(Log4JLogger.java:283)
	at org.apache.commons.logging.impl.Log4JLogger.isDebugEnabled
(Log4JLogger.java:293)
	at net.sf.ehcache.store.DiskStore.expiryThreadMain(DiskStore.java:768)
	at net.sf.ehcache.store.DiskStore.access$700(DiskStore.java:61)
	at net.sf.ehcache.store.DiskStore$ExpiryThread.run(DiskStore.java:942)
Comment 2 Florian Kirchmeir 2006-10-03 00:54:51 UTC
Hi all!
I can still confirm this bug using log4j-1.2.14.
Same stacktrace.

Regards,
Florian
Comment 3 Martin Zdila 2007-03-27 02:58:54 UTC
confirming for log4j-1.2.14.jar too:

Exception in thread "Thread-10" java.lang.NullPointerException
	at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
	at org.apache.log4j.Logger.getLogger(Logger.java:104)
	at 
org.apache.commons.logging.impl.Log4JLogger.getLogger(Log4JLogger.java:229)
	at 
org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:157)
	at 
org.apache.jcs.auxiliary.disk.indexed.IndexedDiskCache$ShutdownHook.run(IndexedDiskCache.java:1523)
Exception in thread "Thread-9" java.lang.NullPointerException
	at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
	at org.apache.log4j.Logger.getLogger(Logger.java:104)
	at 
org.apache.commons.logging.impl.Log4JLogger.getLogger(Log4JLogger.java:229)
	at 
org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:157)
	at 
org.apache.jcs.auxiliary.disk.indexed.IndexedDiskCache$ShutdownHook.run(IndexedDiskCache.java:1523)
Exception in thread "Thread-12" java.lang.NullPointerException
	at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
	at org.apache.log4j.Logger.getLogger(Logger.java:104)
	at 
org.apache.commons.logging.impl.Log4JLogger.getLogger(Log4JLogger.java:229)
	at 
org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:157)
	at 
org.apache.jcs.auxiliary.disk.indexed.IndexedDiskCache$ShutdownHook.run(IndexedDiskCache.java:1523)
Exception in thread "Thread-11" java.lang.NullPointerException
	at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
	at org.apache.log4j.Logger.getLogger(Logger.java:104)
	at 
org.apache.commons.logging.impl.Log4JLogger.getLogger(Log4JLogger.java:229)
	at 
org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:157)
	at 
org.apache.jcs.auxiliary.disk.indexed.IndexedDiskCache$ShutdownHook.run(IndexedDiskCache.java:1523)
Comment 4 Henri Yandell 2007-05-30 15:16:17 UTC
That seems to be at the second of these lines.

  public static Logger getLogger(String name) {
    return repositorySelector.getLoggerRepository().getLogger(name);

So either the repositorySelector is null, or its returning a null
LoggerRepository. If this is always from a shutdown hook (the other reports
don't mention if it's a shutdown hook). setRepositorySelector(..) is never
called, so presumably it's a null from LoggerRepository.

However, DefaultRepositorySelector does not even have an API for removing a
repository once set. That would seem to suggest that the selector was made with
a null LoggerRepository in the first place - but it can't be :)

Nothing Commons-Logging looks like it touches this, so currently I keep
suggesting the NPE can't happen. Need to repeat my steps and see where I screwed up.
Comment 5 Henri Yandell 2007-05-30 15:34:24 UTC
Digging further, I continue to think there's no code way that the NPE can happen.

It's all on shutdown hooks though - so presumably the JVM has pulled the rug. My
instinct is to suggest that Tomcat, EHCache and JCS are all implementing their
shutdown hooks badly - or that log4j isn't very shutdown friendly.

Backing off on this issue in favour of one of the log4j committers :)
Comment 6 ode 2007-06-04 02:35:28 UTC
Hello,

I also have the same problem using log4j 1.2.14. I get the next stack trace in
catalinat.out at tomcat startup (I use Spring as container)

Jun 4, 2007 10:07:40 AM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Jun 4, 2007 10:07:40 AM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/5.5.20
Jun 4, 2007 10:07:40 AM org.apache.catalina.core.StandardHost start
INFO: XML validation disabled
Jun 4, 2007 10:07:40 AM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive xxx_yyy_web.war
Jun 4, 2007 10:07:42 AM org.apache.catalina.core.StandardContext start
SEVERE: Error listenerStart
Jun 4, 2007 10:07:42 AM org.apache.catalina.core.StandardContext start
SEVERE: Context [/xxx_yyy_web] startup failed due to previous errors
ERROR: unable to return the LOG xxx.xxx.xxx.services.security.InputCheckingHelper
java.lang.NullPointerException
        at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
        at org.apache.log4j.Logger.getLogger(Logger.java:104)
        at xxx.xxx.xxx.util.logging.AbstractLogImpl.<init>(AbstractLogImpl.java:20)
        at xxx.xxx.xxx.util.logging.SimpleLogImpl.<init>(SimpleLogImpl.java:14)
        at xxx.xxx.xxx.util.logging.LogFactory.createLog(LogFactory.java:145)
        at xxx.xxx.xxx.util.logging.LogFactory.getLog(LogFactory.java:82)
        at xxx.xxx.xxx.util.logging.LogFactory.getLog(LogFactory.java:48)
        at
xxx.xxx.xxx.services.security.InputCheckingHelper.<clinit>(InputCheckingHelper.java:17)
        at sun.misc.Unsafe.ensureClassInitialized(Native Method)
        at sun.reflect.UnsafeFieldAccessorFactory.newFieldAccessor(Unknown Source)
        at sun.reflect.ReflectionFactory.newFieldAccessor(Unknown Source)
        at java.lang.reflect.Field.acquireFieldAccessor(Unknown Source)
        at java.lang.reflect.Field.getFieldAccessor(Unknown Source)
        at java.lang.reflect.Field.set(Unknown Source)
        at
org.apache.catalina.loader.WebappClassLoader.clearReferences(WebappClassLoader.java:1611)
        at
org.apache.catalina.loader.WebappClassLoader.stop(WebappClassLoader.java:1492)
        at org.apache.catalina.loader.WebappLoader.stop(WebappLoader.java:736)
        at org.apache.catalina.core.StandardContext.stop(StandardContext.java:4393)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:4241)
        at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:759)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:739)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:524)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:809)
        at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:698)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:472)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1122)
        at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:310)
        at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1021)
        at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013)
        at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442)
        at org.apache.catalina.core.StandardService.start(StandardService.java:450)
        at org.apache.catalina.core.StandardServer.start(StandardServer.java:709)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:551)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:294)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:432)

Comment 7 Aaron Digulla 2007-07-06 02:39:42 UTC
I have the same problem during redeploy. It sometimes happens during shutdown
and always when it is started again:

Caused by: java.lang.NullPointerException
	at org.apache.log4j.Category.isEnabledFor(Category.java:746)
	at org.apache.commons.logging.impl.Log4JLogger.isTraceEnabled(Log4JLogger.java:327)
	at net.sf.ehcache.store.MemoryStore.get(MemoryStore.java:137)
	at net.sf.ehcache.Cache.searchInMemoryStore(Cache.java:820)
	at net.sf.ehcache.Cache.get(Cache.java:655)
	at net.sf.ehcache.constructs.blocking.BlockingCache.get(BlockingCache.java:513)
	at
net.sf.ehcache.constructs.blocking.SelfPopulatingCache.get(SelfPopulatingCache.java:71)

My setup is this:

- commons-logging-api 1.1 in tomcat/bin
- commons-logging 1.1 in tomcat/common/lib
- log4j 1.2.14 in tomcat/common/lib
- ehcache 1.2.4 in tomcat/common/lib
- property files in tomcat/common/classes
- commons-logging 1.1 in WEB-INF/lib
- log4j 1.2.14 in WEB-INF/lib
- property files in WEB-INF/classes

I have *two* webapps deployed which use ehcache. My guess is that during
shutdown, the log4j which is used by tomcat itself is destroyed while the webapp
tries to get rid of its copy because there is a mixup in the classloader or a
pointer into log4j from ehcache (which probably uses the tomcat log4j) leaks
into the webapp.
Comment 8 Matt Wiseley 2007-08-18 09:23:15 UTC
I am getting a NullPointerException in LogManager line 188 because
LogManager.repositorySelector is null. The user of LogManager in this case is
the JCS ShrinkerThread class. I only get this exception after Tomcat reloads the
context. My theory is that the static block at the top of LogManager is not
executing for some reason, or is failing. Eclipse apparently can't debug static
blocks, so it's hard for me to see exactly what's happening. Here is a stack trace:

Exception in thread "Thread-2" java.lang.NullPointerException
        at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
        at org.apache.log4j.Logger.getLogger(Logger.java:104)
        at
org.apache.commons.logging.impl.Log4JLogger.getLogger(Log4JLogger.java:229)
        at
org.apache.commons.logging.impl.Log4JLogger.isDebugEnabled(Log4JLogger.java:239)
        at
org.apache.jcs.engine.memory.shrinking.ShrinkerThread.shrink(ShrinkerThread.java:120)
        at
org.apache.jcs.engine.memory.shrinking.ShrinkerThread.run(ShrinkerThread.java:96)
        at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)
Comment 9 Matt Wiseley 2007-08-18 11:03:18 UTC
After some further investigation, I believe the error I previously reported was
caused a stray thread created by JCS that was left running after the context
reloaded. That thread referenced a class with a final static logger. I solved
this problem in my application by adding
JCS.getInstance("someRegionName").dispose(); to the Filter.destroy() method of
one of my Servlet Filters. I don't pretend to know exactly why that fixed it,
but it did. I would consider this is a JCS bug, not a Log4J bug.

Comment 10 Curt Arnold 2007-08-22 19:15:36 UTC
Marking INVALID until it can be shown as a log4j bug with a proposed resolution.
Comment 11 Aaron Digulla 2007-08-23 11:38:34 UTC
I also don't think this is a log4j issue but the NPE usually happens when
something is wrong with the classloader (keeping a static reference to log4j
while the webapp is reloaded or loading log4j in one classloader and then trying
to log from another).

Therefore, I suggest to add a check for a null value here and throw an
IllegalStateException() with this message: "repositorySelector is null. This can
only happen if log4j classes are used from two different classloaders. Look for
stale static references to loggers and make sure that all loggers are loaded via
the same classloader."

That won't fix the issue but will make it much more straightforward to fix the
real problem.
Comment 12 Curt Arnold 2007-08-23 12:42:44 UTC
Added a check of repositorySelector before dereferencing it.  If null, a new repositorySelector is created 
wrapping a NOPLoggerRepository, the guard is nulled and a LogLog.error message is output.  Should 
prevent the NPE's that you are seeing, but you will lose all logging until and unless something changes the 
repository selector.  Immediate feedback would be much appreciated.
Comment 13 Aaron Digulla 2007-08-23 13:02:55 UTC
After looking through the official log4j website, I couldn't find a link to the
trunk. Where is it?
Comment 14 Curt Arnold 2007-08-23 13:28:28 UTC
svn co https://svn.apache.org/repos/asf/logging/log4j/trunk

will get you the current SVN HEAD which is close to the final 1.2.15 release.  (log4j 1.3 has been moved off  
to a thread).  To build, download Maven 2.0.7 and then do a "mvn package".

Staged new website is available at http://svn.apache.org/repos/asf/logging/site/trunk/docs/index.html
Comment 15 Curt Arnold 2007-08-25 06:50:54 UTC
Fix is available in log4j 1.2.15 RC6 and later.
Comment 16 Aaron Digulla 2007-08-25 08:54:45 UTC
Created attachment 20709 [details]
Patch to fix the same NPE in Category.java

Here is a patch which fixes the same issue for Category.isXxxEnabled().

Two comments: Check the TODO in the patch. There are several places where
repository is written to despite the comment in setHierarchy(). To make the
patch compile, I had to make it protected.

Also, I'm not sure if anyone ever calls setHierarchy(null) during shutdown of
Log4j. So feel free to remove the code which uses "nulledBy". Otherwise, this
might help to track down these bugs.
Comment 17 Curt Arnold 2007-08-25 10:10:17 UTC
Can't accept the 2007-08-25 patch since it changes the visibility from protected to private of 
Category.repository which breaks API compatibility.  Should not have been protected, but we are stuck 
with that now.
Comment 18 Aaron Digulla 2007-08-26 04:12:54 UTC
Created attachment 20710 [details]
Fixed patch

Not as safe as the first one but should work equally well in the standard case
(where users don't extend Category). Instead of marking it private, I've
deprecated the field.
Comment 19 Christopher Sahnwaldt 2007-10-25 15:07:30 UTC
This may be related to "NPE in Logging due to classloading"
http://issues.apache.org/bugzilla/show_bug.cgi?id=41939
Comment 20 Aaron Digulla 2007-11-02 13:20:56 UTC
I've followed the bugs mentioned there and I concur: log4j is probably being
confused by the Tomcat classloader clearing all static fields on unload.

This also means that the usual setup (one log4j/commons-logging per tomcat and
per webapp) to get logging per webapp is not safe; if we get NPEs after reload,
this means that tomcat somehow mixes different instances of log4j (because after
reload, there shouldn't be *anything* reachable from the last run even if the GC
couldn't throw the classes out, yet).
Comment 21 Marius Scurtescu 2007-11-14 14:59:45 UTC
It seems that fixing this issue introduced another problem.

After upgrading from 1.2.14 to 1.2.15 the following error show up during shutdown:
log4j:ERROR LogMananger.repositorySelector was null likely due to error in class
reloading, using NOPLoggerRepository.

No errors at all with 1.2.14
Comment 22 Marius Scurtescu 2007-11-14 15:05:25 UTC
Added a separate bug 43867
Comment 23 Curt Arnold 2007-11-20 08:48:05 UTC
Bugs should not span releases and this was reported as fixed in 1.2.15.  Use Bug 43867 for post 1.2.15 
discussion.