logback源码分析

引子

最近排查一个线上异常，发现起因是日志打印不完整，使用的日志框架正是 logback，在排查问题的过程中深入学习了相关源码，虽然最后没有得到可靠的结论，排查过程中没有发现有对单条日志大小进行限制的配置，我认为是数据落盘的时候丢失了一部分。

slf4j

Java 的日志框架常用的有 log4j、logback、jul(common-log)以及 log4j2。为了实现不同日志框架之间的无缝切换，Ceki Gülcü 大神开发了 slf4j(Simple Logging Facade for Java) 。slf4j 是众多日志框架抽象的门面接口，有了 slf4j 想要切换日志实现，只需要把对应日志 jar 替换和添加对应的适配器。

抽象概念

logback 日志框架提出的抽象概念比较少，易于理解。只有 logger 和 appender，而且这两个概念还可以通过配置文件来理解其作用。

Java 对抽象设计的要求会比较高一些，对于一个框架来说，理解了它核心抽象，那基本就理解了它的核心实现。对于我们学习源码来说，分析清楚作者为什么要设计这个抽象，为什么不能再细分？也是一个不错的思考点。

logger

主要功能有两个：

  • 谁来打印日志，也就是日志的数据源来自哪里
  • 控制打印的日志级别
    再看看配置文件中是如何配置它的：
    1
    2
    3
    4
    5
    6
    7
    8
    <logger name="promotion_middle_result_logger">  
        <level value="INFO" />  %% 配置日志级别 %%
        <appender-ref ref="asyncPromotionMidResulAppender"/>  %% 绑定appender %%
    </logger>

    <root level="WARN">  
        <appender-ref ref="consoleAsync"/>  
    </root>
    ch.qos.logback.classic.Logger 的所有属性如下：

需要注意的有三点：

  1. parent 和 childrenList 维护了一个 Logger 的继承树，继承是依据 name 来的，以 name 中的“.”划分层级。所有继承树的根节点是 Root。它的作用是子节点可以继承父节点的配置，日志级别，appender 等
  2. loggerContext 用于生成 logger，一般来说，context 都会包含整个处理逻辑最重要的信息
  3. AppenderAttachableImpl 是指配置的 appender 信息

Appender

主要功能是指定日志输出到哪里，但也有一些附加功能：

  1. 指定日志输出位置：console、file、数据库等
  2. encoder：指定日志打印格式
  3. 还有一些额外配置，如文件大小，文件名格式等
    看配置信息：
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    <appender class="ch.qos.logback.core.rolling.RollingFileAppender" name="promotionMidResulAppender">  
        <file>${LOG_HOME}/promotion_middle_result.log</file>  
        <!--文件滚动保存策略-->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> 
            <fileNamePattern>${LOG_HOME}/promotion_middle_result.log.%d{yyyy-MM-dd-HH}.gz</fileNamePattern>  
            <maxHistory>10</maxHistory>  
        </rollingPolicy>  
        <!--日志输出格式-->
        <encoder>  
            <pattern>[%d{yyyy-MM-dd HH:mm:ss}] %m%n</pattern>  
        </encoder>  
    </appender>  

    <!--异步输出的配置-->
    <appender  name="asyncPromotionMidResulAppender" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="promotionMidResulAppender"/>  
        <queueSize>1500</queueSize>  
        <discardingThreshold>0</discardingThreshold>  
    </appender>

源码解析

LogContext 初始化

步骤 1：
logContext 的初始化是从获取 logger 开始的

1
private static final Logger log = LoggerFactory.getLogger("promotion_middle_result.logger");

步骤 2：
org.slf4j.LoggerFactory # getLogger (java.lang.String)

1
2
3
4
public static Logger getLogger(String name) {  
  ILoggerFactory iLoggerFactory = getILoggerFactory(); // logContext初始化
  return iLoggerFactory.getLogger(name);  
}

步骤 3：
org.slf4j.LoggerFactory # getILoggerFactory

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
public static ILoggerFactory getILoggerFactory() {  
  // 由状态字段来控制是否初始化好了
  if (INITIALIZATION_STATE == UNINITIALIZED) {  
    INITIALIZATION_STATE = ONGOING_INITIALIZATION;  
    performInitialization();  
  }  
  switch (INITIALIZATION_STATE) {  
    case SUCCESSFUL_INITIALIZATION:  
      return StaticLoggerBinder.getSingleton().getLoggerFactory();  
    case NOP_FALLBACK_INITIALIZATION:  
      return NOP_FALLBACK_FACTORY;  
    case FAILED_INITIALIZATION:  
      throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);  
    case ONGOING_INITIALIZATION:  
      // support re-entrant behavior.  
      // See also http://bugzilla.slf4j.org/show_bug.cgi?id=106      
      return TEMP_FACTORY;  
  }
  // 这种写法可以借鉴
  throw new IllegalStateException("Unreachable code");  
}

这里的 INITIALIZATION_STATE 字段没有使用 volatile 修饰，因为对这个值的读写过程并没有并发安全问题。后面会看到 logContext 的初始化是借助类加载过程初始化的，只会执行一次

步骤 4：
org.slf4j.LoggerFactory # performInitialization

1
2
3
4
5
6
7
private final static void performInitialization() {
  // 开始要绑定日志框架了，slf4j毕竟就是一个门面框架
  bind();  
  if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {  
    versionSanityCheck();  
  }  
}

步骤 5：
org.slf4j.LoggerFactory # bind

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
private final static void bind() {  
  try {  
    // 找到所有可以绑定的日志框架，依据是org/slf4j/impl/StaticLoggerBinder.class类
    Set staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
    // 提示有多个日志框架可用
    reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);  
    // 这里其实是为了将StaticLoggerBinder加载入内存
    StaticLoggerBinder.getSingleton();  
    INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;  
    reportActualBinding(staticLoggerBinderPathSet);  
    emitSubstituteLoggerWarning();  
  } catch (NoClassDefFoundError ncde) {  
    ...
  } catch (java.lang.NoSuchMethodError nsme) {  
    ...
  } catch (Exception e) {  
    failedBinding(e);  
    throw new IllegalStateException("Unexpected initialization failure", e);  
  }
}

这里的逻辑断层了，可能会无法理解，该如何初始化 logContext（ps：其中一个重要步骤是解析 logback.xml），一般遇到这种情况，只能根据前一个步骤提示的 org/slf4j/impl/StaticLoggerBinder.class 来找线索了

这里还有个感受是，源码注释并不多，但是并不妨碍理解，函数名命名的很讲究。不过我们平时写业务代码时，还是最好加上中文注释，方便后面人全局搜索

步骤 6：
org.slf4j.impl.StaticLoggerBinder # init

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
void init() {  
    try {  
        try {  
		    // 配置文件在这里加载
            new ContextInitializer(defaultLoggerContext).autoConfig();  
        } catch (JoranException je) {  
            Util.report("Failed to auto configure default logger context", je);  
        }  
        // logback-292
        if (!StatusUtil.contextHasStatusListener(defaultLoggerContext)) {  
            StatusPrinter.printInCaseOfErrorsOrWarnings(defaultLoggerContext);  
        }  
        contextSelectorBinder.init(defaultLoggerContext, KEY);  
        initialized = true;  
    } catch (Exception t) { // see LOGBACK-1159  
        Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);  
    }  
}

其他细节就不看了，这里解析了配置文件，并初始化了 logContext 对象

日志打印

日志框架会将每一条日志当作了一个事件来处理。如果是同步打印，那么就是直接写入文件。如果是异步打印，则会用一个队列来收集事件，最后由日志线程来遍历队列写入文件。
这里我将分析异步过程。
步骤 1：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,  
                final Throwable t) {  
  
    final FilterReply decision = loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);  
   // 判断日志级别
    if (decision == FilterReply.NEUTRAL) {  
        if (effectiveLevelInt > level.levelInt) {  
            return;  
        }  
    } else if (decision == FilterReply.DENY) {  
        return;  
    }
    // 构建LoggingEvent对象
    buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);  
}

步骤 2：
ch.qos.logback.classic.Logger # buildLoggingEventAndAppend

1
2
3
4
5
6
7
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);  
}

步骤 3：
ch.qos.logback.classic.Logger # callAppenders

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
public void callAppenders(ILoggingEvent event) {  
    int writes = 0;  
    // 这里遍历了logger继承树
    for (Logger l = this; l != null; l = l.parent) {  
	    // 遍历这个logger绑定的appenders
        writes += l.appendLoopOnAppenders(event); 
        if (!l.additive) {
            break;
        }
    }  
    // No appenders in hierarchy  
    if (writes == 0) {  
        loggerContext.noAppenderDefinedWarning(this);  
    }  
}

步骤 4：
ch.qos.logback.core.spi.AppenderAttachableImpl # appendLoopOnAppenders

1
2
3
4
5
6
7
8
9
10
11
public int appendLoopOnAppenders(E e) {  
    int size = 0;  
    final Appender<E>[] appenderArray = appenderList.asTypedArray();  
    final int len = appenderArray.length;  
    // 遍历appender
    for (int i = 0; i < len; i++) {  
        appenderArray[i].doAppend(e);  
        size++;  
    }
    return size;  
}

步骤 5：
ch.qos.logback.core.AsyncAppenderBase # append

1
2
3
4
5
6
7
protected void append(E eventObject) {  
    if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {  
        return;  
    }  
    preprocess(eventObject);  
    put(eventObject);  
}

步骤 6：
ch.qos.logback.core.AsyncAppenderBase # put

1
2
3
4
5
6
7
8
9
private void put(E eventObject) {  
    if (neverBlock) {
	    // 队列满了就直接丢弃
        blockingQueue.offer(eventObject);  
    } else {  
	    // 这里会阻塞一下
        putUninterruptibly(eventObject);  
    }  
}

到这里业务线程就执行完毕了，主要是将 loggingEvent 放入队列。接下来视角切换到日志线程。

步骤 7：
ch.qos.logback.core.AsyncAppenderBase.Worker # run

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
public void run() {  
    AsyncAppenderBase<E> parent = AsyncAppenderBase.this;  
    AppenderAttachableImpl<E> aai = parent.aai;  
  
    // loop while the parent is started  
    while (parent.isStarted()) {  
        try {  
	        // 遍历队列元素
            E e = parent.blockingQueue.take();  
            aai.appendLoopOnAppenders(e);  
        } catch (InterruptedException ie) {  
            break;  
        }  
    }  
  
    addInfo("Worker thread will flush remaining events before exiting. ");  
  
    for (E e : parent.blockingQueue) {  
        aai.appendLoopOnAppenders(e);  
        parent.blockingQueue.remove(e);  
    }  
  
    aai.detachAndStopAllAppenders();  
}

步骤 8：
ch.qos.logback.core.spi.AppenderAttachableImpl # appendLoopOnAppenders

1
2
3
4
5
6
7
8
9
10
11
public int appendLoopOnAppenders(E e) {  
    int size = 0;  
    final Appender<E>[] appenderArray = appenderList.asTypedArray();  
    final int len = appenderArray.length;  
    // 还是需要遍历appender
    for (int i = 0; i < len; i++) {  
        appenderArray[i].doAppend(e);  
        size++;  
    }  
    return size;  
}

步骤 9：
ch.qos.logback.core.OutputStreamAppender # subAppend

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
protected void subAppend(E event) {  
    if (!isStarted()) {  
        return;  
    }  
    try {  
        // this step avoids LBCLASSIC-139  
        if (event instanceof DeferredProcessingAware) {  
            ((DeferredProcessingAware) event).prepareForDeferredProcessing();  
        }  
        // the synchronization prevents the OutputStream from being closed while we  
        // are writing. It also prevents multiple threads from entering the same        // converter. Converters assume that they are in a synchronized block.        // lock.lock();  
        // 日志格式化输出在这里
        byte[] byteArray = this.encoder.encode(event);  
        // 这里就直接写入文件了
        writeBytes(byteArray);  
  
    } catch (IOException ioe) {  
        // as soon as an exception occurs, move to non-started state  
        // and add a single ErrorStatus to the SM.        this.started = false;  
        addStatus(new ErrorStatus("IO failure in appender", this, ioe));  
    }  
}

总结

本文从 logContext初始化 和 日志打印流程 两个角度分析 logback 的源码。整体流程并不复杂，可以自己去多点几次。
个人认为看源码是需要学习到一些东西的，比如设计模式，代码格式，函数命名等之类的。

工具框架
#日志
logback源码分析
http://ttoobbyyy.github.io/2024/01/06/logback源码分析/
作者
jianren.xiao
发布于
2024年1月6日
许可协议