log4j1死锁问题

背景

听说log4j1在线上会出现死锁，现在我们来看看这个死锁是怎么产生的。

复现死锁场景

log4j.properties的配置如下，
注意需要把不同的logger指定到同一个appender上，如下所示。

log4j.rootLogger=DEBUG,CONSOLE,ROLLING_FILE
log4j.logger.test=INFO,CONSOLE
log4j.additivity.test=false
###################
# Console Appender
###################
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.Threshold=info
log4j.appender.CONSOLE.Target=System.out
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS}  [%t] %-5p %-20c - %m%n

log4j测试版本如下

<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.15</version>
</dependency>

测试代码。

public class FindDeadLock {
    private static Logger logger = Logger.getLogger(FindDeadLock.class);
    private long delay;
    private FindDeadLock(long delay){
        this.delay = delay;
    }
    public static void main(String[] args){
        new Thread(new Runnable() {
            @Override
            public void run() {
                logger.info(new FindDeadLock(100l));
            }
        }).start();
        new DeadLockingObject(5l);
    }

    public String toString(){
        new DeadLockingObject(delay);
        return super.toString();
    }

    private static class DeadLockingObject {
        private static Logger log = Logger.getLogger("test");
        private DeadLockingObject(long delay){
            try {
                Thread.sleep(delay);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            log.info("没有死锁");
        }
    }
}

堆栈信息：

• Thread-0 持有锁：0x00000000da310f18 等待锁：0x00000000da310d48
• main 持有锁：0x00000000da310d48 等待锁:0x00000000da310f18
• 发生死锁。

Java stack information for the threads listed above:
===================================================
"Thread-0":
    at org.apache.log4j.Category.callAppenders(Category.java:205)
    - waiting to lock <0x00000000da310d48> (a org.apache.log4j.Logger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.info(Category.java:666)
    at com.lujunyu.log.FindDeadLock$DeadLockingObject.<init>(FindDeadLock.java:38)
    at com.lujunyu.log.FindDeadLock$DeadLockingObject.<init>(FindDeadLock.java:30)
    at com.lujunyu.log.FindDeadLock.toString(FindDeadLock.java:26)
    at org.apache.log4j.or.DefaultRenderer.doRender(DefaultRenderer.java:37)
    at org.apache.log4j.or.RendererMap.findAndRender(RendererMap.java:80)
    at org.apache.log4j.spi.LoggingEvent.getRenderedMessage(LoggingEvent.java:368)
    at org.apache.log4j.helpers.PatternParser$BasicPatternConverter.convert(PatternParser.java:402)
    at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
    at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
    - locked <0x00000000da310f18> (a org.apache.log4j.ConsoleAppender)
    at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    - locked <0x00000000da310f88> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.info(Category.java:666)
    at com.lujunyu.log.FindDeadLock$1.run(FindDeadLock.java:19)
    at java.lang.Thread.run(Thread.java:745)
"main":
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
    - waiting to lock <0x00000000da310f18> (a org.apache.log4j.ConsoleAppender)
    at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    - locked <0x00000000da310d48> (a org.apache.log4j.Logger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.info(Category.java:666)
    at com.lujunyu.log.FindDeadLock$DeadLockingObject.<init>(FindDeadLock.java:38)
    at com.lujunyu.log.FindDeadLock$DeadLockingObject.<init>(FindDeadLock.java:30)
    at com.lujunyu.log.FindDeadLock.main(FindDeadLock.java:22)

产生原因

Category.java logger对象在获取appender时需要加锁。
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);
  }
}


AppenderSkeleton.java，多个线程使用同一个Appender时，对Appender加锁

  public  synchronized void doAppend(LoggingEvent event) {
    if(closed) {
      LogLog.error("Attempted to append to closed appender named ["+name+"].");
      return;
    }

    if(!isAsSevereAsThreshold(event.getLevel())) {
      return;
    }

    Filter f = this.headFilter;

    FILTER_LOOP:
    while(f != null) {
      switch(f.decide(event)) {
        case Filter.DENY: return;
        case Filter.ACCEPT: break FILTER_LOOP;
        case Filter.NEUTRAL: f = f.getNext();
      }
    }

    this.append(event);    
  }

• 由于日志输出时需要获取两个不同的锁对象，当锁对象产生交叉时就会发生死锁。

如何避免

1. 建议使用log4j2
2. 使用slf4j替代直接使用log4j