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
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)
Hi all! I can still confirm this bug using log4j-1.2.14. Same stacktrace. Regards, Florian
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)
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.
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 :)
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)
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.
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)
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.
Marking INVALID until it can be shown as a log4j bug with a proposed resolution.
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.
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.
After looking through the official log4j website, I couldn't find a link to the trunk. Where is it?
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
Fix is available in log4j 1.2.15 RC6 and later.
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.
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.
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.
This may be related to "NPE in Logging due to classloading" http://issues.apache.org/bugzilla/show_bug.cgi?id=41939
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).
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
Added a separate bug 43867
Bugs should not span releases and this was reported as fixed in 1.2.15. Use Bug 43867 for post 1.2.15 discussion.