Dear All, We are facing a problem that JBoss Threads are all consumed causing the whole web application to hang. We investigated the issue and found that all Threads are waiting on a synchronized block inside log4j. exactly in this block of code: public void callAppenders(LoggingEvent event) { int writes = 0; for(Category c = this; c != null; c=c.parent) { // Protected against simultaneous call to addAppender, removeAppender,... synchronized(c) { if(c.aai != null) { writes += c.aai.appendLoopOnAppenders(event); } if(!c.additive) { break; } } } if(writes == 0) { repository.emitNoAppenderWarning(this); } } There are two reported bugs here (41214,44157) and we followed the below recommendations: 1. upgrade log4j from 1.2.15 to 1.2.16. 2. upgrade jdk from 1.5.17 to 1.5.22 ( we cannot go for 1.6.22 right now) More over, we made sure that there are no shared logger i.e. there are new logger for each class and created by that class itself. But the problem exists. Here I collected the thread dump of threads locking the synchronize object over few days. 2011-01-18 "Some Thread1" daemon prio=3 tid=0x011e0b78 nid=0x33a runnable [0x53d7e000..0x53d7fa70] at java.lang.Throwable.fillInStackTrace(Native Method) at java.lang.Throwable. (Throwable.java:181) at org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) at org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) at org.apache.log4j.PatternLayout.format(PatternLayout.java:503) at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) at org.apache.log4j.WriterAppender.append(WriterAppender.java:159) at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) - locked <0x780a04c8> (a org.apache.log4j.ConsoleAppender) at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) at org.apache.log4j.Category.callAppenders(Category.java:203) - locked <0x7807cfa8> (a org.apache.log4j.spi.RootLogger) at org.apache.log4j.Category.forcedLog(Category.java:388) at org.apache.log4j.Category.debug(Category.java:257) ____________________________ 2011-01-17-13:51:28 Thread: Some Thread2 : priority:5, demon:true, threadId:5093, threadState:RUNNABLE, lockName:null java.lang.Throwable.getStackTraceElement(Native Method) java.lang.Throwable.getOurStackTrace(Throwable.java:592) java.lang.Throwable.printStackTrace(Throwable.java:511) org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105) org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) org.apache.log4j.PatternLayout.format(PatternLayout.java:503) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) _____________________________________ 2010-12-27 13:29:47 Thread: Some Thread3 - Pre-Rendering Page - Rendering Page : priority:5, demon:true, threadId:8960, threadState:RUNNABLE, lockName:null java.lang.Throwable.fillInStackTrace(Native Method) java.lang.Throwable.(Throwable.java:181) org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) org.apache.log4j.PatternLayout.format(PatternLayout.java:503) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) ________________________________________ Thread: Some Thread4 : priority:5, demon:true, threadId:8977, threadState:RUNNABLE, lockName:null java.lang.Throwable.getStackTraceElement(Native Method) java.lang.Throwable.getOurStackTrace(Throwable.java:592) java.lang.Throwable.printStackTrace(Throwable.java:511) org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105) org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) org.apache.log4j.PatternLayout.format(PatternLayout.java:503) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) ____________________________________ Thread: Some Thread5 : priority:5, demon:true, threadId:8991, threadState:RUNNABLE, lockName:null java.lang.Throwable.getStackTraceElement(Native Method) java.lang.Throwable.getOurStackTrace(Throwable.java:592) java.lang.Throwable.printStackTrace(Throwable.java:511) org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105) org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) org.apache.log4j.PatternLayout.format(PatternLayout.java:503) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) ____________________________________________________________ Thread: Some Thread6 : priority:5, demon:true, threadId:9017, threadState:RUNNABLE, lockName:null java.lang.Throwable.getStackTraceElement(Native Method) java.lang.Throwable.getOurStackTrace(Throwable.java:592) java.lang.Throwable.printStackTrace(Throwable.java:511) org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105) org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) org.apache.log4j.PatternLayout.format(PatternLayout.java:503) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) ____________________________________________________________ 2011-01-03 18:17:26 Thread: Some Thread 7 : priority:5, demon:true, threadId:38364, threadState:RUNNABLE, lockName:null java.io.FileOutputStream.writeBytes(Native Method) java.io.FileOutputStream.write(FileOutputStream.java:260) java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) java.io.PrintStream.write(PrintStream.java:412) sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(StreamEncoder.java:336) sun.nio.cs.StreamEncoder$CharsetSE.implFlushBuffer(StreamEncoder.java:404) sun.nio.cs.StreamEncoder$CharsetSE.implFlush(StreamEncoder.java:408) sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:152) java.io.OutputStreamWriter.flush(OutputStreamWriter.java:213) org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:57) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:315) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) __________________________________________________________ 2011-01-03 18:22:43 Thread: Some Thread8 : priority:5, demon:true, threadId:9604, threadState:RUNNABLE, lockName:null java.lang.Throwable.getStackTraceElement(Native Method) java.lang.Throwable.getOurStackTrace(Throwable.java:592) java.lang.Throwable.printStackTrace(Throwable.java:511) org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105) org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) org.apache.log4j.PatternLayout.format(PatternLayout.java:503) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) _______________________________________ Thread: Some Thread9: priority:5, demon:true, threadId:38364, threadState:RUNNABLE, lockName:null java.lang.Throwable.getStackTraceElement(Native Method) java.lang.Throwable.getOurStackTrace(Throwable.java:592) java.lang.Throwable.printStackTrace(Throwable.java:511) org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105) org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191) org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64) org.apache.log4j.PatternLayout.format(PatternLayout.java:503) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) ************************ Is there any way to avoid this blocking? Can we add some sort of timeout to release the lock? appreciate your feedback.
we are also experiencing the same issue Thread Dump :- java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.log4j.Category.callAppenders(Category.java:204) - waiting to lock <0x07ff5828> (a org.apache.log4j.spi.RootLogger) at com.wf.fx.fxcore.log.LoggerLog4j.forcedLog(LoggerLog4j.java:242) at org.apache.log4j.Category.info(Category.java:666) at com.wf.fx.fxcore.log.LoggerLog4j.info(LoggerLog4j.java:156
We Managed to solve this problem by doing the following 1. disabling the console appender 2. simplifying the log format by removing the line number and the function name
I am also experiencing the same problem. blow are the thread dump at org.apache.log4j.Category.callAppenders(Category.java:190) - locked <0x5d417b48> (a org.apache.log4j.Logger) at org.apache.log4j.Category.forcedLog(Category.java:375) at org.apache.log4j.Category.log(Category.java:868) I have the following questions: 1. Could you please let me know the procedure to disable the console appender?. 2. Also could you also explain in steps as to how the log format is simplified?
(In reply to siva from comment #3) > 1. Could you please let me know the procedure to disable the console > appender?. > 2. Also could you also explain in steps as to how the log format is > simplified? Those are log4j.properties questions however I am very glad to answer. This is an example on configuration file (please note that you should remove the "stdout" from the first line log4j.rootLogger=debug, R, stdout log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.layout=org.apache.log4j.PatternLayout log4j.appender.stdout.layout.ConversionPattern=[%d] [%t] [%-5p] - [%m]%n #--- syncronized logging log4j.appender.R=org.apache.log4j.DailyRollingFileAppender log4j.appender.R.File=pbt.log log4j.appender.R.layout=org.apache.log4j.PatternLayout log4j.appender.R.layout.ConversionPattern=[%d] [%t] [%-5p] - [%m]%n Now, you may share your file so we can look at it.
Thanks for your quick reply In my case, since I have a lot of configuration files, i have to manually disable the consoleAppender(using the command mentioned) for every config file. Is there any other workaround in the above scenario?. I have the following questions 1. Is disabling the consoleAppender the only possible fix for the above issue in 1.2.x. Can you please specify if there are other alternatives?. 2. Does the patch for bug - 50213 defect resolve the consoleAppender issue ? 3. I understand from comment 6(given by Ralph Goers) in Defect Id: 51047 that this issue was fixed in Log4j 2.0. Ralph also talks about an adapter for the 1.2 API. Could you please provide a reference to the same?. Appreciate your feedback at the earliest.
(In reply to siva from comment #5) > Thanks for your quick reply > > In my case, since I have a lot of configuration files, i have to manually > disable the consoleAppender(using the command mentioned) for every config > file. Is there any other workaround in the above scenario?. > > I have the following questions > > 1. Is disabling the consoleAppender the only possible fix for the above > issue in 1.2.x. Can you please specify if there are other alternatives?. > > 2. Does the patch for bug - 50213 defect resolve the consoleAppender issue ? > > 3. I understand from comment 6(given by Ralph Goers) in Defect Id: 51047 > that this issue was fixed in Log4j 2.0. Ralph also talks about an adapter > for > the 1.2 API. Could you please provide a reference to the same?. > > Appreciate your feedback at the earliest. Hi, the idea behind disabling console Appender is to reduce the IO operations which are causing the lock issue (as per my understanding). Regarding Log4J 2.0 I have no idea as I moved to LogBack and I stopped using Log4J anymore.
Perhaps the quickest way to see how the adapter works is to look at the log4j2 FAQ page: http://logging.apache.org/log4j/2.x/faq.html Basically, you remove the log4j-1.2.x.jar from the classpath, and instead you add the following three log4j2 jars: api, core and 1.2-api. That's it. Your application that is coded against the log4j-1.2.x API will now work with the new log4j2 implementation. You will need to create a log4j2.xml configuration file (slightly different syntax as log4j-1.2.x), but the log4j2 web site has tons of example configurations to get you started.