I'm using log4j 1.04 in a threaded environment, each thread logging to the console (FileAppender to stdout) and to its own log file (RollingFileAppenders). I get the following stack trace at regular intervals: java.lang.NullPointerException at org.apache.log4j.FileAppender.subAppend(FileAppender.java:441) at org.apache.log4j.FileAppender.append(FileAppender.java:219) at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221) at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders (AppenderAttachableImpl.java:56) at org.apache.log4j.Category.callAppenders(Category.java:258) at org.apache.log4j.Category.forcedLog(Category.java:454) at org.apache.log4j.Category.debug(Category.java:315) at com.dyncorp.dynride.scheduler.MasterScheduler.run (MasterScheduler.java:203) at java.lang.Thread.run(Thread.java:484) This didn't ever happen in 0.9! Let me know if you need any additional info! Following is the log configuration file: # Set root category priority to INFO, but no appenders log4j.rootCategory=INFO # Database log log4j.category.Database=INFO, APP_DB, stdout # Schedule Control Thread log4j.category.SchedulerControlThread=DEBUG, APP_SCT, stdout # Ride Matcher log4j.category.RideMatch=DEBUG, APP_RM, stdout # Scheduler log4j.category.MasterScheduler=DEBUG, A1, stdout # Data Pull log4j.category.DATA_PULL_DMR=DEBUG, APP_DP, stdout # Postprocesor log4j.category.BuildData=DEBUG, APP_BD log4j.appender.stdout=org.apache.log4j.FileAppender log4j.appender.stdout.File=System.out log4j.appender.stdout.layout=org.apache.log4j.PatternLayout # Pattern to output the caller's file name and line number. log4j.appender.stdout.layout.ConversionPattern=%5p [%t] (%F:%L) - %m%n # APP_DP is set to be a RollingFileAppender log4j.appender.APP_DP=org.apache.log4j.RollingFileAppender log4j.appender.APP_DP.File=DataPullDMR.log log4j.appender.APP_DP.MaxBackupIndex=5 log4j.appender.APP_DP.MaxFileSize=512KB # APP_DP uses PatternLayout. log4j.appender.APP_DP.layout=org.apache.log4j.PatternLayout log4j.appender.APP_DP.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n # A1 is set to be a RollingFileAppender log4j.appender.A1=org.apache.log4j.RollingFileAppender log4j.appender.A1.File=MasterScheduler.log log4j.appender.A1.MaxBackupIndex=5 log4j.appender.A1.MaxFileSize=512KB # A1 uses PatternLayout. log4j.appender.A1.layout=org.apache.log4j.PatternLayout log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n # APP_DB is set to be a RollingFileAppender log4j.appender.APP_DB=org.apache.log4j.RollingFileAppender log4j.appender.APP_DB.File=Database.log log4j.appender.APP_DB.MaxBackupIndex=5 log4j.appender.APP_DB.MaxFileSize=512KB # APP_DB uses PatternLayout. log4j.appender.APP_DB.layout=org.apache.log4j.PatternLayout log4j.appender.APP_DB.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n # APP_SCT is set to be a RollingFileAppender log4j.appender.APP_SCT=org.apache.log4j.RollingFileAppender log4j.appender.APP_SCT.File=ScheduleControlThread.log log4j.appender.APP_SCT.MaxBackupIndex=5 log4j.appender.APP_SCT.MaxFileSize=512KB # APP_SCT uses PatternLayout. log4j.appender.APP_SCT.layout=org.apache.log4j.PatternLayout log4j.appender.APP_SCT.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n # APP_RM is set to be a RollingFileAppender log4j.appender.APP_RM=org.apache.log4j.RollingFileAppender log4j.appender.APP_RM.File=RideMatcher.log log4j.appender.APP_RM.MaxBackupIndex=5 log4j.appender.APP_RM.MaxFileSize=512KB # APP_RM uses PatternLayout. log4j.appender.APP_RM.layout=org.apache.log4j.PatternLayout log4j.appender.APP_RM.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n # APP_BD is set to be a RollingFileAppender log4j.appender.APP_BD=org.apache.log4j.RollingFileAppender log4j.appender.APP_BD.File=BuildData.log log4j.appender.APP_BD.MaxBackupIndex=5 log4j.appender.APP_BD.MaxFileSize=512KB # APP_BD uses PatternLayout. log4j.appender.APP_BD.layout=org.apache.log4j.PatternLayout log4j.appender.APP_BD.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n
Dave, Are you by any way configuring any of the appenders while still using them? Can you try to reproduce the problem with a smaller set of appenders? Ceki
Ceki, The only thing I change while the program is still running is the priority - sometimes I change the category priorities between DEBUG and WARN. However the problem can occur while I've been away from my desk for a while so I am not sure it is related. I will do a new config file that has the same categories, but all using the same appender instead of several different appenders. Will let you know how that works. -- Dave
OK, the new log config file has two appenders, stdout and a file. After a while I got this stack trace: java.lang.NullPointerException at org.apache.log4j.FileAppender.subAppend(FileAppender.java:441) at org.apache.log4j.RollingFileAppender.subAppend (RollingFileAppender.java:258) at org.apache.log4j.FileAppender.append(FileAppender.java:219) at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221) at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders (AppenderAttachableImpl.java:56) at org.apache.log4j.Category.callAppenders(Category.java:258) at org.apache.log4j.Category.forcedLog(Category.java:454) at org.apache.log4j.Category.debug(Category.java:315) at com.dyncorp.dynride.scheduler.MasterScheduler.run (MasterScheduler.java:203) at java.lang.Thread.run(Thread.java:484) -- Dave
The region where the null pointer exception occurs is copied below. protected void subAppend(LoggingEvent event) { this.qw.write(this.layout.format(event)); <--- qw used here if(layout.ignoresThrowable()) { if(event.throwable != null) { event.throwable.printStackTrace(this.tp); } // in case we received this event from a remote client else if (event.throwableInformation != null) { this.qw.write(event.throwableInformation); } } if(this.immediateFlush) { this.qw.flush(); <--- this is line 441 } } It seems that this.qw is not set or set to null. However, this cannot happen since this situation is checked against in checkEntryConditions method before entering subAppend. Moreover, this.qw is used at the beginning of the subAppend method. I am stumped. What kind of JVM is this? OS? JIT?
I saw the same thing... With only two concurrent threads, it seems relatively rare. The more concurrent threads, the faster the exception happens... Does any other object have a reference to qw? I call PropertyConfigurator.configure as the first statement in most of my run() methods, would that cause a problem? -- Dave
I forgot to give you my java info... c:>java -version java version "1.3.0" Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.0-C) Java HotSpot(TM) Client VM (build 1.3.0-C, mixed mode) This is Sun's JVM running on Windows 2000 Advanced Server. -- Dave
Calling PropertyConfigurator.configure will have the effect of first removing/closing all appenders for categories mentioned in the config file. This might well be the source of the problem but the NullPointerException is most probably a log4j bug. I suppose that when you call PropertyCOnfigurator.configure() you pass a filename as a parameter. Right?
Bug synopsis: PropertyConfigurator closes an appedner while another thread is in subAppend. Solution: In FileAppender make the close method synchronized.
Yes - I call PropertyConfigurator.configure("SomeFileName.properties"). -- Dave
Fixed in recent log4j release.