Logback(2) 基本配置文章中的【配置 root logger】小节中我们碰到了一个日志打印两次的问题,这里我们可以简单看一下源码理解一下日志打印的大致流程:

我们从这个方法开始

LOGGER.info("Did it again!");

我们从接口找到logback的实现类:

 public void info(String msg) {
        filterAndLog_0_Or3Plus(FQCN, null, Level.INFO, msg, null, null);
    }
private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                    final Throwable t) {
        // step1
        final FilterReply decision = loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);
        // step2
        if (decision == FilterReply.NEUTRAL) {
            if (effectiveLevelInt > level.levelInt) {
                return;
            }
        } else if (decision == FilterReply.DENY) {
            return;
        }
         //step3
        buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
    }

这里面有三个步骤:

  1. 执行TurboFilter的处理逻辑
  2. 根据TurboFilter返回的结果和Level信息做判断,如果不需要写日志则直接退出
  3. 需要写日志了,调用buildLoggingEventAndAppend()方法来构建日志并写入。

TurboFilter我们后续讲到这个配置项再谈,看一下步骤二,我们大致能够知道这段代码是用来检查当前logger配置的日志等级和传入的日志请求指定的日志等级,以决定是否需要打印这条日志

注意:这里就是判断日志打不打印了,所以这里就解释了上文中通过父级的appender输出日志为啥和父级的logger等级无关,因为这里是在判断当前日志是否需要输出了,而appender的调用是在下文中执行的,我们可以继续往下看

假如我们的日志等级满足打印的条件,则执行:

buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
    private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                    final Throwable t) {
        LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
        le.setMarker(marker);
        callAppenders(le);
    }

buildLoggingEventAndAppend方法构建了LoggingEvent对象,当然这个对象目前对我们来说不是那么需要关心的,我们关注后面调用的callAppenders(le);方法,顾名思义这里在调用appender来处理打印日志事宜了。

    public void callAppenders(ILoggingEvent event) {
        int writes = 0;
        for (Logger l = this; l != null; l = l.parent) {
            writes += l.appendLoopOnAppenders(event);
            if (!l.additive) {
                break;
            }
        }
        // No appenders in hierarchy
        if (writes == 0) {
            loggerContext.noAppenderDefinedWarning(this);
        }
    }

callAppenders()方法中我们先看这段循环

for (Logger l = this; l != null; l = l.parent)

this指向当前的logger,我们这里先只要知道,l.parent会指向它的父级logger,例如我们的TestAppender类是在com.exercise.newpac包下,当前的logger的name是com.exercise.newpac.TestAppender,它的parent是`com.exercise.newpac,虽然我们在配置文件里没有配置这个logger,但是他还是生成一个logger对象不断向上遍历,每一次循环都会调用appendLoopOnAppenders,直到ROOT logger为止。所以这里我们从代码层面上解释通了为什么多个appender会导致日志打印两次的问题。

继续看appendLoopOnAppenders()方法:

transient private AppenderAttachableImpl<ILoggingEvent> aai;

private int appendLoopOnAppenders(ILoggingEvent event) {
    if (aai != null) {
      return aai.appendLoopOnAppenders(event);
    } else {
      return 0;
    }
}

这里涉及到AppenderAttachableImpl类的实例aai,这个AppenderAttachableImpl类也挺复杂的,涉及到并发和线程安全。我们先跳过它的细节,将它简化为一个logger中配置的appender list,这样看aai.appendLoopOnAppenders()方法中的代码就简单了:

public int appendLoopOnAppenders(E e) {
    int size = 0;
      for (Appender<E> appender : appenderList) {
        appender.doAppend(e);
        size++;
      }
    return size;
}

每次appendLoopOnAppenders()方法(非aai的)将被调用,这个方法会返回其调用并使用过的appender的个数,方法callAppenders中的writes变量会统计总数。遍历结束后,会检查writes统计的结果,如果为0表明整个过程中都没有任何appender被使用,则会打印警告:

final void noAppenderDefinedWarning(final Logger logger) {
    if (noAppenderWarning++ == 0) {
      getStatusManager().add(
              new WarnStatus("No appenders present in context [" + getName()
                      + "] for logger [" + logger.getName() + "].", logger));
    }
}

所以平时如果看到这个警告,就要注意检查对应logger的appender设置了。