logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject [Bug 41214] Deadlock with RollingFileAppender
Date Fri, 06 Jul 2012 04:46:22 GMT
https://issues.apache.org/bugzilla/show_bug.cgi?id=41214

--- Comment #43 from msm <marc_sm2003@yahoo.com.br> ---
(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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message