Logback日志框架-日志打印过程及Logger继承特性源码分析

摘要

上一篇《Logback日志框架初始化全过程源码解析》分析了Logback的整个初始化过程以及Logger的创建，这篇文章将继续分析Logger的打印过程，上篇文章没有介绍Logback的架构，所以我们先会简单介绍下Logback的基础组成模块；然后再介绍下logback.xml 配置文件中的主要元素和他们之间的协作关系，重点说明下Logger的继承特性；接着梳理下整个日志打印过程，带着这些概念进入源码去一一验证，最后做个简单的总结。

正文

Logback基础组成模块

Logback主要分为3个模块：

• logback-core

  core模块是其他两个模块的基础

• logback-classic

  classic模块依赖core模块，她是其实是log4j的升级版，logback-classic天然实现了SLF4J API，所以我们可以在Log4j、Jul等日志框架之间随意切换而不需要改动我们的业务代码。

• logback-access

  access模块主要用于和Servlet容器结合提供记录HTTP请求日志的功能，通常不使用。

一般使用Logback时我们会引用slf4j-api、logback-core和logback-classic等3个依赖。

Logback配置

logback 提供多种配置方式:

• 通过实现com.qos.logback.classic.spi.Configurator接口来进行配置

  上文《Logback日志框架初始化全过程源码解析》中提到如果Logback初始化过程中如果找不到配置文件，且用户也没有实现Configurator接口，则会使用默认配置BasicConfigurator，她其实就实现了Configurator接口。

• 通过加载配置文件

配置文件其实也提供2类：logback.grovy和logback.xml

两者大同小异，只是语法不同而已，在这里我们选择比较熟悉和常用的logback.xml进行简单解释。

<configuration>
    <property name="pattern" value="%date %level [%thread] %logger{10} [%file : %line] %msg%n"/>
    
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>${pattern}</Pattern>
        </layout>
    </appender>
    
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>${fileName:-demo.log}</file>
        <encoder>
            <pattern>${pattern}</pattern>
        </encoder>
    </appender>
    
    <logger name="com" level="warn" additivity="false">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="FILE"/>
    </logger>

    <logger name="com.cw" level="info" additivity="false">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="FILE"/>
    </logger>
    
    <logger name="com.cw.demo" additivity="false">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="FILE"/>
    </logger>

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

logback.xml中我们主要看6个xml元素:

appender

appender主要用来指定日志信息最终输出到什么位置，console、file或者socket等。

layout

layout用来根据pattern规则格式化日志内容，将日志event转换为String类型，然后通过java.io.Writer输出。

encoder

encoder是0.9.19版本之后出现的，她和layout作用本质上是相同的，都会通过pattern规则将日志内容格式化，不同点是，encoder将日志event转化为byte数组，然后写到OutputStream。

0.9.19版本之后官方推荐encoder来代替layout，具体原因，官方给出如下解释:

Why the breaking change?

Layouts, as discussed in detail in the next chapter, are only able to transform an event into a String. Moreover, given that a layout has no control over when events get written out, layouts cannot aggregate events into batches. Contrast this with encoders which not only have total control over the format of the bytes written out, but also control when (and if) those bytes get written out.

意思是说，Layouts只能将日志event转化为String，不能够控制何时将日志event写出，无法将多个event集合到一组。而encoder不仅能控制日志bytes数据的格式，还能控制是否以及何时写出数据。简单来讲就是encoder比layout牛逼，能用encoder就不用layout。当然对于之前的使用layout的老代码，官方也提供一些适配class例如LayoutWrappingEncoder

pattern

pattern主要用来定义日志的输出格式等，详见PatternLayout。

logger

logger可以与我代码中LoggerFactory.getLogger产生的Logger对象相对应，她有三个属性：

• name : 日志名称，用于Logger对象初始化的时候定位到配置文件中具体的配置。

• level：标识日志的有效等级，日志等级具有继承性。

  例如:

  logback.xml中name="com.cw"的logger（取别名Lc）等级是info， name="com.cw.demo"的logger（取别名为Ld），Lc是Ld的父级，而Ld没有设置日志等级，那么她的等级就继承子父级Lc的info，

  如果Lc也没有等级，那么会继续往上找到name="com"这个祖先，继承这个祖先的日志等级warn。

• additivity：标识该日志对象是否要将日志event向父级输出，默认为true，一般我们会设置为false，防止一段日志信息被重复打印到多个日志文件中，无形中增加了日志文件的大小，稍后会结合源码做分析。

appender-ref

appender-ref作用是将一个logger对象和具体的appender绑定，指定该logger将通过哪个appender将日志输出到何处。一个logger可存在多个appender-ref，也就是说可以同时绑定多个appender。

root

root其实是个特殊的logger，看名字就知道她是一个根节点，是所有logger的祖先，配置文件中必须得有一个root。

日志打印源码分析

过滤和创建LogEvent

这里我们以我们常用的logger.info() 为入口，info()中实际是调用filterAndLog_1()方法，

这个方法做2件事，过滤和创建LoggingEvent并推送给实际绑定的Appender对象

public final class Logger implements org.slf4j.Logger, LocationAwareLogger, AppenderAttachable<ILoggingEvent>, Serializable {
   
    public void info(String format, Object arg) {
        filterAndLog_1(FQCN, null, Level.INFO, format, arg, null);
    }

    private void filterAndLog_1(final String localFQCN, final Marker marker, final Level         level, final String msg, final Object param, final Throwable t) {

        /**
         * 这里先经过一串过滤器处理，根据传入的marker满足的条件不同返回不同的结果，
         * FilterReply.NEUTRAL 表示中立的意思
         */
        final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);

        /**
         * 过滤后返回NEUTRAL则进一步判断当前想要打印的日志等级"INFO"是否高于或者等于有效日志级别。
         * 如果小于有效日志级别，则表示该日志无效，直接返回，不做具体输出动作。
         */
        if (decision == FilterReply.NEUTRAL) {
            if (effectiveLevelInt > level.levelInt) {
                return;
            }
        } else if (decision == FilterReply.DENY) {
            return;
        }
        
        buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
    }

    /**
      * 创建日志Event, 推送到与logger绑定的所有appender中
      */
    private void buildLoggingEventAndAppend(
        final String localFQCN, final Marker marker, 
        final Level level, final String msg, 
        final Object[] params, final Throwable t) {

        // 创建日志Event
        LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
        le.setMarker(marker);
        
        //推送到与logger绑定的所有appender中
        callAppenders(le);
    }
    
    public void callAppenders(ILoggingEvent event) {
        int writes = 0;

        /**
         * 这里有个熟悉的单词additive，上面我们介绍logger的时候说到，
         * 她是logger的一个属性，默认为true
         * 结合这段代码我们看下，for循环中，先将event, 推给当前logger的Appenders中，并且累加
         * writes，紧接着判断additive，
         * 如果为true则，取logger的父级，继续将event推给父级logger的Appender中，
         * 以此类推，直至遇到某个父级或者祖先的additive为false，则break跳出循环，
         * 或者 送到root日志根节点为止。
         * 这几解释了additive的作用了。
         */
        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);
        }
    }
    
    private int appendLoopOnAppenders(ILoggingEvent event) {
        if (aai != null) {
            return aai.appendLoopOnAppenders(event);
        } else {
            return 0;
        }
    }
    
    /**
     * appenderList是与Logger绑定的Appender
     * 例如上述logback.xml中name="FILE"的logger绑定的
     * Appender 就是ch.qos.logback.core.FileAppender类。
     * 因为每个logger可以同时绑定多个Appender所以这里用数组appenderList来存储这些Appender。
     */
    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;
    }
}

通过FileAppender打印到文件

logback.xml中name="FILE"的logger绑定的 Appender 是ch.qos.logback.core.FileAppender类，那么我们就以FileAppender为例分析下日志写入到文件的整个流程。

FIleAppender类的继承关系图：

FileAppender.png

整个流程如下：

FileAppender 指定日志打印的目标文件，并指定文件的输出流OutputStream给OutputStreamAppender，

目标文件的指定动作是发生在logger的初始化过程中，通过加载解析logback.xml找到name="FILE"的<appender>元素，读取子元素<file>的值来获取文件；

OutputStreamAppender 提供一个基础服务，她继承UnsynchronizedAppenderBase抽象类并实现其中的

append(E eventObject)抽象方法，进行具体的日志格式化和打印动作，其实就是向FileAppender提供的输出流中输入格式化后的日志；

通过名称可看出UnsynchronizedAppenderBase并未做线程安全方面的措施，而是将线程安全方面的问题交给子类自己去处理，OutputStreamAppender确实也自己处理了，她通过在writeBytes(byte[] byteArray)方法中加入 ReentrantLock重入锁来保证日志写入的线程安全。

接下来我们从下到上依次来分析下几个类中重要的方法:

FileAppender

public class FileAppender<E> extends OutputStreamAppender<E> {
    ...
    
    /**
     * 
     */
    public void start() {
        int errors = 0;
        if (getFile() != null) {
            ...

            /**
             * 检查该日志文件是否以及被其他Appender绑定了,如果没被绑定则返回false
             */
            if (checkForFileCollisionInPreviousFileAppenders()) {
                addError("Collisions detected with FileAppender/RollingAppender instances defined earlier. Aborting.");
                addError(MORE_INFO_PREFIX + COLLISION_WITH_EARLIER_APPENDER_URL);
                errors++;
            } else {
               
                try {
                    /**
                      * 打开未被其他Appender绑定的文件输出流给OutputStreamAppender，
                      * 用于后续的日志输入。
                      */
                    openFile(getFile());
                } catch (java.io.IOException e) {
                    errors++;
                    addError("openFile(" + fileName + "," + append + ") call failed.", e);
                }
            }
        } else {
            errors++;
            addError("\"File\" property not set for appender named [" + name + "].");
        }
        if (errors == 0) {
            super.start();
        }
    }
    
    /**
     * 检查该日志文件是否以及被其他Appender绑定了，如果是的话就返回true
     * 否则记录appender的名称和日志文件名称，表示当前文件已经被Appender绑定了，
     * 不能再和别的Appender绑定，然后返回false
     */
    protected boolean checkForFileCollisionInPreviousFileAppenders() {
        boolean collisionsDetected = false;
        if (fileName == null) {
            return false;
        }
        @SuppressWarnings("unchecked")
        Map<String, String> map = (Map<String, String>) context.getObject(CoreConstants.FA_FILENAME_COLLISION_MAP);
        if (map == null) {
            return collisionsDetected;
        }
        for (Entry<String, String> entry : map.entrySet()) {
            if (fileName.equals(entry.getValue())) {
                addErrorForCollision("File", entry.getValue(), entry.getKey());
                collisionsDetected = true;
            }
        }
        if (name != null) {
            map.put(getName(), fileName);
        }
        return collisionsDetected;
    }
    /**
     * 创建个ResilientFileOutputStream输出流，             
     * 给OutputStreamAppender中的，outputStream成员变量；
     * 文件必须是可写的；
     * 虽然该方法是public的但是不要直接调用，
     * 而是通过start方法一步步设置还成员变量的后再调用
     */
    public void openFile(String file_name) throws IOException {
        lock.lock();
        try {
            File file = new File(file_name);
            boolean result = FileUtil.createMissingParentDirectories(file);
            if (!result) {
                addError("Failed to create parent directories for [" + file.getAbsolutePath() + "]");
            }
            ResilientFileOutputStream resilientFos = new ResilientFileOutputStream(file, append, bufferSize.getSize());
            resilientFos.setContext(context);
            setOutputStream(resilientFos);
        } finally {
            lock.unlock();
        }
    }
  ...
}

OutputStreamAppender

public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E> {
    protected Encoder<E> encoder;
    protected final ReentrantLock lock = new ReentrantLock(false);
    private OutputStream outputStream;

    boolean immediateFlush = true;

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

    /**
       * 真正的的写入操作
       * <p>
       * Most subclasses of <code>WriterAppender</code> will need to override this
       * method.
       */
    protected void subAppend(E event) {
        if (!isStarted()) {
            return;
        }
        try {
            // this step avoids LBCLASSIC-139
            if (event instanceof DeferredProcessingAware) {
                ((DeferredProcessingAware) event).prepareForDeferredProcessing();
            }
            // 格式化日志文件
            byte[] byteArray = this.encoder.encode(event);
            // 写入日志到特定的输出流中，使用ReentrantLock保证线程安全
            writeBytes(byteArray);
        } catch (IOException ioe) {
            this.started = false;
            addStatus(new ErrorStatus("IO failure in appender", this, ioe));
        }
    }
 
    /**
    * 传入一个已经打开的outputStream，
    * 例如FileAppender 中打开的ResilientFileOutputStream
    */
    public void setOutputStream(OutputStream outputStream) {
        lock.lock();
        try {
            // close any previously opened output stream
            closeOutputStream();
            this.outputStream = outputStream;
            if (encoder == null) {
                addWarn("Encoder has not been set. Cannot invoke its init method.");
                return;
            }
            encoderInit();
        } finally {
            lock.unlock();
        }
    }

    ...

    /**
     * 写入日志到特定的输出流中，使用ReentrantLock保证线程安全
     */
    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();
        }
    }
}

UnsynchronizedAppenderBase

abstract public class UnsynchronizedAppenderBase<E> extends ContextAwareBase implements Appender<E> {

    protected boolean started = false;
    
    /**
     * guard 用来防止appender 重复调用自己的doAppend方法
     */
    private ThreadLocal<Boolean> guard = new ThreadLocal<Boolean>();

    /**
     * Appenders are named.
     */
    protected String name;

    private FilterAttachableImpl<E> fai = new FilterAttachableImpl<E>();

    private int statusRepeatCount = 0;
    private int exceptionCount = 0;

    static final int ALLOWED_REPEATS = 3;

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

            /**
              * append是个抽象方法，所以此处会调用append方法的具体实现
              * 例如OutputStreamAppender类中实现的该方法
              */
            this.append(eventObject);

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

    abstract protected void append(E eventObject);

至此整个日志打印过程结束了。

总结

本文主要通过FileAppender类为例详细分析了整个日志的打印流程，除了FileAppender 还有一些我们常用的Appender，例如：

ConsoleAppender: 打印日志到控制台
RollingFileAppender: 可以根据一定的规则对日志进行切割备份，如：日期、日志大小等规则

文中就不一一介绍了，他们的流程都大同小异，留个感兴趣的同学自己去分析。