https://issues.apache.org/bugzilla/show_bug.cgi?id=41214
--- Comment #43 from msm <[email protected]> --- (In reply to comment #42) I didn't think exactly about getting a snapshot. I just thought defining "message" instance field as the type String would fix the bug merely because inside toString() method of the String class there isn't any Log4j call. The same idea applies when calling org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep() method at the beginning, in the constructor. I believe I achieved the goal. This bug can be easily reproduced. See below. Create the following classes: com.a.AnObject com.b.AnException com.c.AnObjectThread com.d.AnExceptionThread com.main.RootLoggerThread com.main.Main ============== package com.a; import org.apache.log4j.Logger; public class AnObject { private static final Logger LOGGER = Logger.getLogger(AnObject.class); private final String name; public AnObject(String name) { this.name = name; } @Override public String toString() { try { Thread.sleep(4000); } catch (InterruptedException ex) { ex.printStackTrace(); } LOGGER.info("Logging DEBUG in AnObject [" + name + "]"); return name; } } ============== ============== package com.b; import org.apache.log4j.Logger; public class AnException extends RuntimeException { private static final Logger LOGGER = Logger.getLogger(AnException.class); public AnException() { super(); } public AnException(String msg) { super(msg); } public AnException(Throwable t) { super(t); } public AnException(String msg, Throwable t) { super(msg, t); } @Override public String getMessage() { try { Thread.sleep(4000); } catch (InterruptedException ex) { ex.printStackTrace(); } LOGGER.error("Logging ERROR in AnException"); return super.getMessage(); } } ============== ============== package com.c; import com.a.AnObject; import org.apache.log4j.Logger; public class AnObjectThread extends Thread { private static final Logger LOGGER = Logger.getLogger(AnObjectThread.class); public AnObjectThread(String threadName) { super(threadName); } @Override public void run() { AnObject anObject = new AnObject("Object created in AnObjectThread"); LOGGER.info(anObject); } } ============== ============== package com.d; import com.b.AnException; import org.apache.log4j.Logger; public class AnExceptionThread extends Thread { private static final Logger LOGGER = Logger.getLogger(AnExceptionThread.class); public AnExceptionThread(String threadName) { super(threadName); } @Override public void run() { LOGGER.info("Just logging INFO in AnExceptionThread", new AnException("test exception", new AnException("cause exception"))); } } ============== ============== package com.main; import org.apache.log4j.Logger; public class RootLoggerThread extends Thread { private static final Logger LOGGER = Logger.getLogger(RootLoggerThread.class); public RootLoggerThread(String threadName) { super(threadName); } @Override public void run() { LOGGER.info("Just logging INFO in RootLoggerThread"); } } ============== ============== package com.main; import com.c.AnObjectThread; import com.d.AnExceptionThread; /** * Bug 41214 reproduction. * * https://issues.apache.org/bugzilla/show_bug.cgi?id=41214 * * @author Marcelo S. Miashiro */ public class Main { public static void main(String[] args) { RootLoggerThread rootLoggerThread = new RootLoggerThread("RootLoggerThread"); AnObjectThread anObjectThread = new AnObjectThread("AnObjectThread"); AnExceptionThread anExceptionThread = new AnExceptionThread("AnExceptionThread"); anExceptionThread.start(); anObjectThread.start(); try { // To reproduce the bug, com.a.AnObject.toString() and com.b.AnException.getMessage() // methods must be called before rootLogger Thread.sleep(2000); } catch (InterruptedException ex) { ex.printStackTrace(); } rootLoggerThread.start(); } } ============== And, of course, create the log4j.properties file with the following content: ============== log4j.rootLogger=INFO, ConsoleAppender log4j.logger.com.c=INFO, ConsoleAppender log4j.logger.com.d=INFO, ConsoleAppender log4j.appender.ConsoleAppender=org.apache.log4j.ConsoleAppender log4j.appender.ConsoleAppender.layout=org.apache.log4j.PatternLayout log4j.appender.ConsoleAppender.layout.ConversionPattern=[%d{dd-MM-yyyy HH:mm:ss,SSS}][%-5p][%c] %M : %m%n ============== Try running the Main class with log4j version 1.2.17 firstly without the fix I suggested. You see a deadlock happening. Try using jconsole to see what's going on. You'll see in jconsole something like this: ============== Name: AnExceptionThread State: BLOCKED on org.apache.log4j.ConsoleAppender@13e75a5 owned by: AnObjectThread Total blocked: 2 Total waited: 0 Stack trace: org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66) org.apache.log4j.Category.callAppenders(Category.java:206) - locked org.apache.log4j.Logger@147e668 org.apache.log4j.Category.forcedLog(Category.java:391) org.apache.log4j.Category.info(Category.java:683) com.d.AnExceptionThread.run(AnExceptionThread.java:19) ============== ============== Name: AnObjectThread State: BLOCKED on org.apache.log4j.spi.RootLogger@157b46f owned by: RootLoggerThread Total blocked: 1 Total waited: 1 Stack trace: org.apache.log4j.Category.callAppenders(Category.java:205) org.apache.log4j.Category.forcedLog(Category.java:391) org.apache.log4j.Category.info(Category.java:666) com.a.AnObject.toString(AnObject.java:24) org.apache.log4j.or.DefaultRenderer.doRender(DefaultRenderer.java:37) org.apache.log4j.or.RendererMap.findAndRender(RendererMap.java:80) org.apache.log4j.spi.LoggingEvent.getRenderedMessage(LoggingEvent.java:368) org.apache.log4j.helpers.PatternParser$BasicPatternConverter.convert(PatternParser.java:402) org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65) org.apache.log4j.PatternLayout.format(PatternLayout.java:506) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310) org.apache.log4j.WriterAppender.append(WriterAppender.java:162) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251) - locked org.apache.log4j.ConsoleAppender@13e75a5 org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66) org.apache.log4j.Category.callAppenders(Category.java:206) - locked org.apache.log4j.Logger@12c4c57 org.apache.log4j.Category.forcedLog(Category.java:391) org.apache.log4j.Category.info(Category.java:666) com.c.AnObjectThread.run(AnObjectThread.java:20) ============== ============== Name: RootLoggerThread State: BLOCKED on org.apache.log4j.ConsoleAppender@13e75a5 owned by: AnObjectThread Total blocked: 1 Total waited: 0 Stack trace: org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66) org.apache.log4j.Category.callAppenders(Category.java:206) - locked org.apache.log4j.spi.RootLogger@157b46f org.apache.log4j.Category.forcedLog(Category.java:391) org.apache.log4j.Category.info(Category.java:666) com.main.RootLoggerThread.run(RootLoggerThread.java:18) ============== After applying the fix I suggested, no more deadlock happens. I have already submitted the patch to Log4j team. -- You are receiving this mail because: You are the assignee for the bug. --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
