Logback

在日常开发中经常通过打印日志记录程序执行的步骤或者排查问题，如下代码类似很多，但是，它是如何执行的呢？

package chapters;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
// 省略...
Logger logger = LoggerFactory.getLogger(LogbackTest.class);
logger.info(" {} is best player in world", "Greizmann");

本文以Logback日志框架来分析以上代码的实现。

slf4j

如今日志框架常用的有log4j、log4j2、jul(common-log)以及logback。假如项目中用的是jul，如今想改成用log4j，如果直接引用java.util.logging包中Logger，需要修改大量代码，为了解决这个麻烦的事情，Ceki Gülcü 大神开发了slf4j(Simple Logging Facade for Java) 。slf4j 是众多日志框架抽象的门面接口，有了slf4j 想要切换日志实现，只需要把对应日志jar替换和添加对应的适配器。

image.png

Logback 实现了 SLF4J ,少了中间适配层， Logback也是Ceki Gülcü 大神开发的。

Logger & Appender & Layouts

Logback 主要的三个类 logger，appender和layouts。这三个组件一起作用可以满足我们开发中根据消息的类型以及日志的级别打印日志到不同的地方。

Logger

ch.qos.logback.classic.Logger类结构：

image.png

Logger 依附在LoggerContext上，LoggerContext负责生产Logger，通过一个树状的层次结构来进行管理。Logger 维护着当前节点的日志级别及level值。logger按 "." 分代（层级），日志级别有继承能力，如：名字为 chapters.LogbackTest 如果没有设置日志级别，会继承它的父类chapters 日志级别。所有日志的老祖宗都是ROOT名字的Logger，默认DEBUG级别。当前节点设置了日志级别不会考虑父类的日志级别。Logger 通过日志级别控制日志的启用和禁用。日志级别 TRACE < DEBUG < INFO < WARN < ERROR。

接下来我们结合配置文件看一下Logger属性对应的配置标签：

<configuration>
  <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">
    <MDCKey>username</MDCKey>
    <Value>sebastien</Value>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>/Users/wolf/study/logback/logback-examples/myApp.log</file>
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>

  <logger name="chapters.LogbackTest" level="DEBUG"></logger>

  <root>
    <appender-ref ref="FILE"/>
  </root>
</configuration>

• name：logger 标签中 name 属性值。

• level：logger 标签中 level 属性值。

• parent：封装了父类 "chapters"，以及"chapters"的父类“ROOT”的logger对象。

• aai：appender-ref 标签，及这里对应 FileAppender 的实现类对象。如果没有appender-ref标签该值为null。

• loggerContext：维护着过滤器，如 turbo 过滤器等。

Appender

Appender 作用是控制日志输出的目的地。日志输出的目的地是多元化，你可以把日志输出到console、file、remote socket server、MySQL、PostgreSQL、Oracle 或者其它的数据库、JMS、remote UNIX Syslog daemons 中。一个日志可以输出到多个目的地。如

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>/Users/wolf/study/logback/logback-examples/myApp.log</file>
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>

  <root>
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE"/>
  </root>
</configuration>

该xml配置把日志输出到了myApp.log文件和console中。

Layouts/Encoder

有上面Logger和Appender两大组件，日志已经输出到目的地了，但是这样打印的日志不太友好，就用Layouts或Encoder美化一下日志输出格式吧。Encoder 在 logback 0.9.19 版本引进。在之前的版本中，大多数的 appender 依赖 layout 将日志事件转换为 string，然后再通过 java.io.Writer 写出。在之前的版本中，用户需要在 FileAppender 中内置一个 PatternLayout。在 0.9.19 之后的版本中，FileAppender 以及子类需要一个 encoder 而不是 layout。

源码

Logger创建

Logger logger = LoggerFactory.getLogger(LogbackTest.class);

接下来我们根据源码分析一下logger的初始化。分析源码之前还是按照老规矩来一张接口调用时序图吧。

image.png

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

public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
}

获取一个ILoggerFactory，即LoggerContext。然后从其获取到Logger对象。

第3步：org.slf4j.LoggerFactory#getILoggerFactory

public static ILoggerFactory getILoggerFactory() {
    return getProvider().getLoggerFactory();
}

第4步：org.slf4j.LoggerFactory#getProvider

static SLF4JServiceProvider getProvider() {
    if (INITIALIZATION_STATE == UNINITIALIZED) {
        synchronized (LoggerFactory.class) {
            if (INITIALIZATION_STATE == UNINITIALIZED) {
                INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                performInitialization();
            }
        }
    }
    switch (INITIALIZATION_STATE) {
    case SUCCESSFUL_INITIALIZATION:
        return PROVIDER;
    case NOP_FALLBACK_INITIALIZATION:
        return NOP_FALLBACK_FACTORY;
    case FAILED_INITIALIZATION:
        throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
    case ONGOING_INITIALIZATION:
        return SUBST_PROVIDER;
    }
    throw new IllegalStateException("Unreachable code");
}

对SLF4JServiceProvider初始化，即LogbackServiceProvider对象。然后检查初始化状态，如果成功就返回PROVIDER。

第5步：org.slf4j.LoggerFactory#performInitialization

private final static void performInitialization() {
    bind();
    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
        versionSanityCheck();
    }
}

第6步：org.slf4j.LoggerFactory#bind

private final static void bind() {
    try {
        // 加载 SLF4JServiceProvider 
        List<SLF4JServiceProvider> providersList = findServiceProviders();
        reportMultipleBindingAmbiguity(providersList);
        if (providersList != null && !providersList.isEmpty()) {
           PROVIDER = providersList.get(0);
           // SLF4JServiceProvider.initialize()
           PROVIDER.initialize();
           INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(providersList);
            fixSubstituteLoggers();
            replayEvents();
            SUBST_PROVIDER.getSubstituteLoggerFactory().clear();
        } else {
            // 省略代码。。。
        }
    } catch (Exception e) {
        // 失败，设置状态值，上报
        failedBinding(e);
        throw new IllegalStateException("Unexpected initialization failure", e);
    }
}

通过ServiceLoader加载LogbackServiceProvider，然后进行初始化相关字段。初始化成功后把初始化状态设置成功状态值。

第7步：ch.qos.logback.classic.spi.LogbackServiceProvider#initialize

public void initialize() {
    // 初始化默认的loggerContext
    defaultLoggerContext = new LoggerContext();
    defaultLoggerContext.setName(CoreConstants.DEFAULT_CONTEXT_NAME);
    initializeLoggerContext();
    markerFactory = new BasicMarkerFactory();
    mdcAdapter = new LogbackMDCAdapter();
}

创建名字为default的LoggerContext对象，并初始化一些字段默认值。

ch.qos.logback.classic.LoggerContext#LoggerContext

public LoggerContext() {
    super();
    this.loggerCache = new ConcurrentHashMap<String, Logger>();
    this.loggerContextRemoteView = new LoggerContextVO(this);
    this.root = new Logger(Logger.ROOT_LOGGER_NAME, null, this);
    this.root.setLevel(Level.DEBUG);
    loggerCache.put(Logger.ROOT_LOGGER_NAME, root);
    initEvaluatorMap();
    size = 1;
    this.frameworkPackages = new ArrayList<String>();
}

初始化LoggerContext时设置了ROOT的Logger，日志级别为DEBUG。

第8步：ch.qos.logback.classic.spi.LogbackServiceProvider#initializeLoggerContext

private void initializeLoggerContext() {
    try {
        try {
            new ContextInitializer(defaultLoggerContext).autoConfig();
        } catch (JoranException je) {
            Util.report("Failed to auto configure default logger context", je);
        }
        // 省略代码。。。
    } catch (Exception t) { // see LOGBACK-1159
        Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
    }
}

把第7步初始化好的LoggerContext当做参数传入ContextInitializer，构建其对象。然后解析配置文件。

第9步：ch.qos.logback.classic.util.ContextInitializer#autoConfig

public void autoConfig() throws JoranException {
    StatusListenerConfigHelper.installIfAsked(loggerContext);
    // (1) 从指定路径获取
    URL url = findURLOfDefaultConfigurationFile(true);
    if (url != null) {
        configureByResource(url);
    } else {
        // (2) 从运行环境中获取
        Configurator c = EnvUtil.loadFromServiceLoader(Configurator.class);
        if (c != null) {
            // 省略代码。。。
        } else {
            // （3）设置默认的
            BasicConfigurator basicConfigurator = new BasicConfigurator();
            basicConfigurator.setContext(loggerContext);
            basicConfigurator.configure(loggerContext);
        }
    }
}

首先从指定的路径获取资源URL,如果存在就进行解析；如果不存在再从运行环境中获取配置；如果以上都没有最后会构建一个BasicConfigurator当作默认的。

BasicConfigurator 在configure 方法中定义了基本Root logger

    public void configure(LoggerContext lc) {
        this.addInfo("Setting up default configuration.");
        ConsoleAppender<ILoggingEvent> ca = new ConsoleAppender();
        ca.setContext(lc);
        ca.setName("console");
        LayoutWrappingEncoder<ILoggingEvent> encoder = new LayoutWrappingEncoder();
        encoder.setContext(lc);
        TTLLLayout layout = new TTLLLayout();
        layout.setContext(lc);
        layout.start();
        encoder.setLayout(layout);
        ca.setEncoder(encoder);
        ca.start();
        Logger rootLogger = lc.getLogger("ROOT");
        rootLogger.addAppender(ca);
    }

从lc.getLogger("ROOT") 可以看出 root logger 就是LoggerContext 的变量
final Logger root = new Logger("ROOT", (Logger)null, this);
可以从Level 的方法看出，default 的log level 就是10000， 也就是debug level。

 public static Level toLevel(int val) {
        return toLevel(val, DEBUG);
    }

ch.qos.logback.classic.util.ContextInitializer#findURLOfDefaultConfigurationFile

public URL findURLOfDefaultConfigurationFile(boolean updateStatus) {
    ClassLoader myClassLoader = Loader.getClassLoaderOfObject(this);
    // 启动参数中获取
    URL url = findConfigFileURLFromSystemProperties(myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }
    // logback-test.xml
    url = getResource(TEST_AUTOCONFIG_FILE, myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }
    //logback.groovy
    url = getResource(GROOVY_AUTOCONFIG_FILE, myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }
    // logback.xml
    return getResource(AUTOCONFIG_FILE, myClassLoader, updateStatus);
}

先从启动参数中查找logback.configurationFile参数值，如果没有再从classpath中一次查找logback-test.xml -> logback.groovy -> logback.xml 。由此可知文件的优先级是 启动参数 -> logback-test.xml -> logback.groovy -> logback.xml

第10步：ch.qos.logback.classic.util.ContextInitializer#configureByResource

public void configureByResource(URL url) throws JoranException {
    if (url == null) {
        throw new IllegalArgumentException("URL argument cannot be null");
    }
    final String urlString = url.toString();
    if (urlString.endsWith("groovy")) {
         // 省略代码。。。
    } else if (urlString.endsWith("xml")) {
        JoranConfigurator configurator = new JoranConfigurator();
        configurator.setContext(loggerContext);
        configurator.doConfigure(url);
    } else {
        // 省略代码。。。
    }
}

根据文件后缀判断是 groovy或者xml，然后交给不同的配置解析器处理。这里也是把第7步中的LoggerContext传进去，继续封装它的字段值。

第12步：ch.qos.logback.core.joran.GenericConfigurator#doConfigure(org.xml.sax.InputSource)

public final void doConfigure(final InputSource inputSource) throws JoranException {

    long threshold = System.currentTimeMillis();
    SaxEventRecorder recorder = new SaxEventRecorder(context);
    recorder.recordEvents(inputSource);
    // 处理配置文件，封装到 LoggerContext 中
    playEventsAndProcessModel(recorder.saxEventList);
    StatusUtil statusUtil = new StatusUtil(context);
    if (statusUtil.noXMLParsingErrorsOccurred(threshold)) {
        registerSafeConfiguration(recorder.saxEventList);
    }
}

真正解析配置文件的逻辑在playEventsAndProcessModel方法中，这里就不展开分析了。到这一步LoggerContext基本初始化完成了。

第13步：ch.qos.logback.classic.LoggerContext#getLogger(java.lang.String)

@Override
public Logger getLogger(final String name) {
    // 省略代码。。。 
    if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
        return root;
    }

    int i = 0;
    Logger logger = root;
    // 从缓存中获取， 有直接返回
    Logger childLogger = (Logger) loggerCache.get(name);
    if (childLogger != null) {
        return childLogger;
    }

    // if the desired logger does not exist, them create all the loggers
    // in between as well (if they don't already exist)
    String childName;
    while (true) {
        int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
        if (h == -1) {
            childName = name;
        } else {
            childName = name.substring(0, h);
        }
        // move i left of the last point
        i = h + 1;
        synchronized (logger) {
            childLogger = logger.getChildByName(childName);
            if (childLogger == null) {
                childLogger = logger.createChildByName(childName);
                loggerCache.put(childName, childLogger);
                incSize();
            }
        }
        logger = childLogger;
        if (h == -1) {
            return childLogger;
        }
    }
}

经过前面漫长的对LoggerContext进行初始化工作，这一步就是从LoggerContext获取Logger对象。如果缓存中直接返回。否则通过“.”分代构建层次结构。

日志执行步骤

上一节Logger创建完成，接下来分析一下打日志的流程。

logger.info(" {} is best player in world", "Greizmann");

image.png

第1步：ch.qos.logback.classic.Logger#info(java.lang.String, java.lang.Object)

public void info(String format, Object arg) {
    filterAndLog_1(FQCN, null, Level.INFO, format, arg, null);
}

把接口的日志级别（Level.INFO）传到下一个方法。

第2步：ch.qos.logback.classic.Logger#filterAndLog_1

private void filterAndLog_1(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param, final Throwable t) {
    // 先通过turboFilter过滤
    final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);
    // 判断日志级别
    if (decision == FilterReply.NEUTRAL) {
        if (effectiveLevelInt > level.levelInt) {
            return;
        }
    } else if (decision == FilterReply.DENY) {
        return;
    }

    buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
}

如果TurboFilter过滤器存在就会执行相关操作，并返回FilterReply。如果结果是FilterReply.DENY本条日志消息直接丢弃；如果是FilterReply.NEUTRAL会继续判断日志级别是否在该方法级别之上；如果是FilterReply.ACCEPT直接跳到下一步。

第3步：ch.qos.logback.classic.Logger#buildLoggingEventAndAppend

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);
}

创建了LoggingEvent对象，该对象包含日志请求所有相关的参数，请求的 logger，日志请求的级别，日志信息，与日志一同传递的异常信息，当前时间，当前线程，以及当前类的各种信息和 MDC。其实打印日志就是一个事件，所以这个对象是相关重要，下面全部是在操作该对象。

第4步：ch.qos.logback.classic.Logger#callAppenders

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);
    }
}

第5步：ch.qos.logback.classic.Logger#appendLoopOnAppenders

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

从当前Logger到父节点遍历，直到AppenderAttachableImpl不为空（有appender-ref 标签）。

第6步：ch.qos.logback.core.spi.AppenderAttachableImpl#appendLoopOnAppenders

public int appendLoopOnAppenders(E e) {
    int size = 0;
    final Appender<E>[] appenderArray = appenderList.asTypedArray();
    final int len = appenderArray.length;
    for (int i = 0; i < len; i++) {
        appenderArray[i].doAppend(e);
        size++;
    }
    return size;
}

如果设置了多个日志输出目的地，这里就是循环调用对应的Appender进行输出。

第7步：ch.qos.logback.core.UnsynchronizedAppenderBase#doAppend

public void doAppend(E eventObject) {
    if (Boolean.TRUE.equals(guard.get())) {
        return;
    }

    try {
        guard.set(Boolean.TRUE);
        if (!this.started) {
            if (statusRepeatCount++ < ALLOWED_REPEATS) {
                addStatus(new WarnStatus("Attempted to append to non started appender [" + name + "].", this));
            }
            return;
        }

        if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
            return;
        }

        this.append(eventObject);

    } catch (Exception e) {
        if (exceptionCount++ < ALLOWED_REPEATS) {
            addError("Appender [" + name + "] failed to append.", e);
        }
    } finally {
        guard.set(Boolean.FALSE);
    }
}

通过ThreadLocal控制递归导致的重复提交

第8步：ch.qos.logback.core.OutputStreamAppender#append

protected void append(E eventObject) {
    if (!isStarted()) {
        return;
    }

    subAppend(eventObject);
}

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

protected void subAppend(E event) {
    if (!isStarted()) {
        return;
    }
    try {
        if (event instanceof DeferredProcessingAware) {
            // 拼接日志信息（填充占位符），设置当前线程以及MDC等信息
            ((DeferredProcessingAware) event).prepareForDeferredProcessing();
        }
        byte[] byteArray = this.encoder.encode(event);
        writeBytes(byteArray);
    } catch (IOException ioe) {
        this.started = false;
        addStatus(new ErrorStatus("IO failure in appender", this, ioe));
    }
}

Encoder在这里惨淡登场，返回byte数组。

第10步：ch.qos.logback.core.encoder.LayoutWrappingEncoder#encode

public byte[] encode(E event) {
    String txt = layout.doLayout(event);
    return convertToBytes(txt);
}

Encoder先把LoggerEvent交给Layout，Layout组装日志信息，在每条信息后加上换行符。

第11步：ch.qos.logback.core.OutputStreamAppender#writeBytes

private void writeBytes(byte[] byteArray) throws IOException {
    if(byteArray == null || byteArray.length == 0)
        return;

    lock.lock();
    try {
        this.outputStream.write(byteArray);
        if (immediateFlush) {
            this.outputStream.flush();
        }
    } finally {
        lock.unlock();
    }
}

使用AQS锁控制并发问题。这也是Logback性能不如 Log4j2的原因。后面有时间分析一下Log4j2。