50614 – Lock in CallAppenders causing all Thread to wait forever

Bug 50614 - Lock in CallAppenders causing all Thread to wait forever

Summary: Lock in CallAppenders causing all Thread to wait forever

Status:	NEW

Alias:	None

Product:	Log4j - Now in Jira
Classification:	Unclassified
Component:	Appender (show other bugs)
Version:	1.2
Hardware:	Sun Solaris

Importance:	P2 major
Target Milestone:	---
Assignee:	log4j-dev

URL:
Keywords:

Depends on:
Blocks:

Reported:	2011-01-19 03:51 UTC by Amr ElAdawy
Modified:	2014-03-13 15:20 UTC (History)
CC List:	2 users (show)

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Amr ElAdawy 2011-01-19 03:51:30 UTC

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.

Comment 1 chauhan.icse 2011-11-17 17:48:17 UTC

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

Comment 2 Amr ElAdawy 2011-11-17 18:18:27 UTC

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

Comment 3 siva 2014-03-10 09:35:55 UTC

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?

Comment 4 Amr ElAdawy 2014-03-11 11:12:05 UTC

(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.

Comment 5 siva 2014-03-13 14:48:36 UTC

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.

Comment 6 Amr ElAdawy 2014-03-13 14:52:00 UTC

(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.

Comment 7 Remko Popma 2014-03-13 15:20:29 UTC

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.