日志那些事儿——Logback源码解析

前言

在上篇文章日志漫谈中谈到,日志在监控报警、查错分析等方面有着非常重要的应用。Logback作为目前最火的日志系统,本文就简单分析一下logback日志打印的过程。

logback背景与配置

Logback是一个开源的日志组件,是log4j的作者开发的用来替代log4j的。

logback由三个部分组成,logback-core, logback-classic, logback-access。其中logback-core是其他两个模块的基础。

logback一般不能单独使用需要和slf4j配合使用,slf4j定义日志接口,具体实现由logback提供。关于slf4j怎么和logback配合本文暂不赘述,本文主要讨论logback的日志打印过程。

要使用logback,除了引入logback的相关jar包之外,还应该在classpath下放置logback.xml(不是唯一的做法),logback.xml配置一般如下:

<?xml version="1.0" encoding="UTF-8"?>
<!-- Logback Configuration. -->
<configuration debug="false">
   <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">      <target>System.out</target>
      <encoding>${loggingCharset}</encoding>
           <layout class="ch.qos.logback.classic.PatternLayout">
         <pattern><![CDATA[  %d %-4relative [%thread] %-5level %logger{35} - %msg%n ]]>
</pattern>
      </layout>
   </appender>
<appender name="FILE"   class="ch.qos.logback.core.rolling.RollingFileAppender">   <file>${loggingRoot}/some.log</file>
   <encoding>${loggingCharset}</encoding>
     <append>true</append> 
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">      <FileNamePattern>${loggingRoot}/some.%d{yyyy-MM-dd}.log      </FileNamePattern>
      <!-- keep 30 days' worth of history -->      <MaxHistory>30</MaxHistory>
   </rollingPolicy>
   <layout class="ch.qos.logback.classic.PatternLayout">
      <pattern>%d %-4relative [%thread] %-5level %logger{35} - %msg%n      </pattern>
   </layout>
</appender>
<logger name="logger1">
   <level value="INFO" />
   <appender-ref ref="FILE" />
</logger>
<root>
   <level value="${loggingLevel}" />
   <appender-ref ref="FILE" />
</root>
</configuration>

配置文件中主要包含了logger、root、appender、rollingPolicy、layout、pattern等元素,这几个元素就是整个logger体系中最最重要的几个组成部分。 其中: Logger: 日志记录器,把它关联到应用对应的context上后,主要用于存放日志对象,定义日志类型,级别。 Appender: 指定日志输出的目的地,目的地可以是控制台,文件,或者数据库等 Layout: 负责把事件转换成字符串,格式化日志信息的输出

logback日志打印流程

当我们配置了上述logback.xml以后,我们通常通过

Logger logger1 = LoggerFactory.getLogger("logger1");
logger1.info("This is a test for logging,msg:{}","I love xiaojin");

的方式使用,现在我们来看看调用logger1.info(),到底发生了什么事情。下图是logger1.info()的简略流程图:

logback logger流程图.jpg

从图中可以看出,整个过程中起关键作用的几个类为:AppenderAttatchableImpl,OutputStreamAppender、Encoder、Layout、OutputStream。这几类和配置文件中相应元素一一对应。logback通过类的继承和组合层层封装方法,最后通过OutputStream写入到控制台(ConsoleAppender)或者是文件(FileAppender)中。

为了对Appender、encoder、Layout、OutputStream有个整体的认识,先给出一张logback中上述各类的类图。

logback loginfo相关类全景图.jpg

可以看出,Appender、encoder、Layout、OutputStream是其中的核心,上图列出了我们经常使用的一些Appender,例如ConsoleAppender、RollingFileAppender;文件的滚动策略:TimeBasedRollingPolicy;格式化日志输出的PatternLayout,以及相应的pattern“%d %-4relative [%thread] %-5level %logger{35} - %msg%n”。

相关代码分析

上面的两张图列出了日志打印的过程和相关类,下面将通过关键代码分析Logback是如何将上述类串起来的。

关键代码1

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); 
 }}
public int appendLoopOnAppenders(E e) {
  int size = 0;  r.lock();
  try {
    for (Appender<E> appender : appenderList) {
      appender.doAppend(e);
      size++;
    }
  } finally {
    r.unlock();
  }
  return size;
}

上述第一段代码位于Logger.java中,logger会通过parent组成一条链路,通过每个logger都可以拥有多个Appender,上述代码会沿着Logger链路依次调用logger.appendLoopOnAppenders方法,直到logger.additive属性为false。第二段代码位于AppenderAttachableImpl中,logger.appendLoopOnAppenders实际上就是调用了AppenderAttachableImpl.appendLoopOnAppenders,该代码遍历logger中的所有appender调用Appender.doAppend(e)方法。

关键代码2

因为我们目前主要使用的还是FileAppender,所以下面的代码都是以RollingFileAppender为例。

@Override
protected void subAppend(E event) {
  synchronized (triggeringPolicy) {
    if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
      rollover();
    }
  }
  super.subAppend(event);}
  protected void subAppend(E event) {
    if (!isStarted()) {
      return;
    }
    try {  
      if (event instanceof DeferredProcessingAware) {
        ((DeferredProcessingAware) event).prepareForDeferredProcessing();
      }
      synchronized (lock) {
        writeOut(event);
      }
    } catch (IOException ioe) {
      this.started = false;
      addStatus(new ErrorStatus("IO failure in appender", this, ioe));
    }
  }
protected void writeOut(E event) throws IOException { 
 this.encoder.doEncode(event);
}

前面讲到logger会调用到Appender.doAppend(),经过层层封装最后会调用到Appender.subAppend()。第一段代码在RollingFileAppender中,可以看出先进行了一次triggeringPolicy的校验,然后调用了父类的subAppend();下面一个就是RollingFileAppender的父类OutputStreamAppender的subAppender(),而其又调用了writeOut方法,而writeOut调用了Encoder.doEncode方法。

关键代码3

上面提到了在RollingFileAppender.subAppender中会进行一次triggeringPolicy的校验。

 public boolean isTriggeringEvent(File activeFile, final E event) {
    long time = getCurrentTime();
    if (time >= nextCheck) {
      Date dateOfElapsedPeriod = dateInCurrentPeriod;
      elapsedPeriodsFileName = tbrp.fileNamePatternWCS
          .convert(dateOfElapsedPeriod);
      setDateInCurrentPeriod(time);
      computeNextCheck();
      return true;
    } else {
      return false;
    }

调用的默认是DefaultTimeBasedFileNamingAndTriggeringPolicy#isTriggeringEvent方法,这个主要是干啥用呢。考虑到我们使用了RollingFileAppender,我们需要日志按天滚动,例如今天是0820,所以今天的日志名应该为some.log,而昨天打的日志将会重命名为some.log.2016-08-19,当然这个是根据配置文件中FileNamePattern元素决定的。而isTriggeringEvent方法就是用来判决当前需不需要对日志名进行rollover(重命名),我们能想到的方法就是去查看日志文件的lastModified的时间与当前时间比较,如果当前时间已经是第二天了,那么应该将some.log重命名为some.log.XXXXXX,XXXX应该是日志修改时间的格式化时间,同时新建一个some.log的文件,并且将日志写入到some.log。logback基本上就是这么做的,但是为了提高效率避免每次都检查,logback会计算出nextChecktime,下次需要check的时间,这个时间有可能是lastModified的第二天凌晨(初始化阶段),有可能是当前时间的第二天凌晨(触发了rollover的时候),这样logback只需要在超过nextChecktime时才需要去rollover。

关键代码3

  public void doEncode(E event) throws IOException {
    String txt = layout.doLayout(event);
    outputStream.write(convertToBytes(txt));
    outputStream.flush();
  }
public String doLayout(ILoggingEvent event) {
    if (!isStarted()) {
      return CoreConstants.EMPTY_STRING;
    }
    return writeLoopOnConverters(event);
  }
protected String writeLoopOnConverters(E event) {
    StringBuilder buf = new StringBuilder(128);
    Converter<E> c = head;
    while (c != null) {
      c.write(buf, event);
      c = c.getNext();
    }
    return buf.toString();
  }
public void start() {
    if(pattern == null || pattern.length() == 0) {
      addError("Empty or null pattern.");
      return;
    }
    try { 
      Parser<E> p = new Parser<E>(pattern);
      if (getContext() != null) {
        p.setContext(getContext());
      }
      Node t = p.parse();
      this.head = p.compile(t, getEffectiveConverterMap());
      if (postCompileProcessor != null) {
        postCompileProcessor.process(head);
      }
      setContextForConverters(head);
      ConverterUtil.startConverters(this.head);
      super.start();
    } catch (ScanException sce) {
      StatusManager sm = getContext().getStatusManager();
      sm.add(new ErrorStatus("Failed to parse pattern \"" + getPattern()
          + "\".", this, sce));
    }
  }
  static {

    defaultConverterMap.put("d", DateConverter.class.getName());
    defaultConverterMap.put("date", DateConverter.class.getName());

    defaultConverterMap.put("r", RelativeTimeConverter.class.getName());
    defaultConverterMap.put("relative", RelativeTimeConverter.class.getName());

    defaultConverterMap.put("level", LevelConverter.class.getName());
    defaultConverterMap.put("le", LevelConverter.class.getName());
    defaultConverterMap.put("p", LevelConverter.class.getName());

    defaultConverterMap.put("t", ThreadConverter.class.getName());
    defaultConverterMap.put("thread", ThreadConverter.class.getName());

    defaultConverterMap.put("lo", LoggerConverter.class.getName());
    defaultConverterMap.put("logger", LoggerConverter.class.getName());
    defaultConverterMap.put("c", LoggerConverter.class.getName());

    defaultConverterMap.put("m", MessageConverter.class.getName());
    defaultConverterMap.put("msg", MessageConverter.class.getName());
    defaultConverterMap.put("message", MessageConverter.class.getName());

    defaultConverterMap.put("C", ClassOfCallerConverter.class.getName());
    defaultConverterMap.put("class", ClassOfCallerConverter.class.getName());

    defaultConverterMap.put("M", MethodOfCallerConverter.class.getName());
    defaultConverterMap.put("method", MethodOfCallerConverter.class.getName());

    defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
    defaultConverterMap.put("line", LineOfCallerConverter.class.getName());

    defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
    defaultConverterMap.put("file", FileOfCallerConverter.class.getName());

    defaultConverterMap.put("X", MDCConverter.class.getName());
    defaultConverterMap.put("mdc", MDCConverter.class.getName());

    defaultConverterMap.put("ex", ThrowableProxyConverter.class.getName());
    defaultConverterMap.put("exception", ThrowableProxyConverter.class
        .getName());
    defaultConverterMap.put("throwable", ThrowableProxyConverter.class
        .getName());

    defaultConverterMap.put("xEx", ExtendedThrowableProxyConverter.class.getName());
    defaultConverterMap.put("xException", ExtendedThrowableProxyConverter.class
        .getName());
    defaultConverterMap.put("xThrowable", ExtendedThrowableProxyConverter.class
        .getName());

    defaultConverterMap.put("nopex", NopThrowableInformationConverter.class
        .getName());
    defaultConverterMap.put("nopexception",
        NopThrowableInformationConverter.class.getName());

    defaultConverterMap.put("cn", ContextNameAction.class.getName());
    defaultConverterMap.put("contextName", ContextNameConverter.class.getName());
    
    defaultConverterMap.put("caller", CallerDataConverter.class.getName());

    defaultConverterMap.put("marker", MarkerConverter.class.getName());

    defaultConverterMap.put("property", PropertyConverter.class.getName());

    
    defaultConverterMap.put("n", LineSeparatorConverter.class.getName());
  }

前面提到输出日志的最终任务会落到Enconder#doEncode身上,第一段代码位于LayoutWrappingEncoder.java中,doEncode会最终调用Layout.doLayout得到格式化的文本,然后使用outputStream输出。第二段代码位于PatternLayout.java中,doLayout会调用writeLoopOnConverters,而writeLoopOnConverters会将日志文件通过Converter链进行格式化。Converter链是怎么产生的呢?请看第三段代码,看来是通过配置的pattern得到的,大体上是通过Parser去解析我们配置的pattern("%d %-4relative [%thread] %-5level %logger{35} - %msg%n"),parser通过识别"%"来判决是关键词还是普通文本,例如[]就是普通文件,relative/msg/n等都是关键字。Node t = p.parse();将pattern转化成Node链,Node有多种例如KeywordNode。通过p.compile(t, getEffectiveConverterMap())得到Convert链,主要是将Node链转化成Convert链,PatternLayout中列出了所有的Convert与pattern中名字的对应关系(最后一段代码),例如d代表DateConverter,level 代码LevelConverter等。

其实我们的日志信息在经过Converter链格式化之前还经过了一次格式化。我们通常会使用logger.info("somemsg:{}",{}),使用"{}"作为占位符,logback会将其替换成后面出现的参数,这个过程是怎么发生的呢?

  public LoggingEvent(String fqcn, Logger logger, Level level, String message,
      Throwable throwable, Object[] argArray) {
    this.fqnOfLoggerClass = fqcn;
    this.loggerName = logger.getName();
    this.loggerContext = logger.getLoggerContext();
    this.loggerContextVO = loggerContext.getLoggerContextRemoteView();
    this.level = level;

    this.message = message;

    FormattingTuple ft = MessageFormatter.arrayFormat(message, argArray);
    formattedMessage = ft.getMessage();

    if (throwable == null) {
      argumentArray = ft.getArgArray();
      throwable = ft.getThrowable();
    } else {
      this.argumentArray = argArray;
    }

    if (throwable != null) {
      this.throwableProxy = new ThrowableProxy(throwable);
      LoggerContext lc = logger.getLoggerContext();
      if (lc.isPackagingDataEnabled()) {
        this.throwableProxy.calculatePackagingData();
      }
    }

    timeStamp = System.currentTimeMillis();

    // ugly but under the circumstances acceptable
    LogbackMDCAdapter logbackMDCAdapter = (LogbackMDCAdapter) MDC
        .getMDCAdapter();
    mdcPropertyMap = logbackMDCAdapter.getPropertyMap();
  }
    FormattingTuple ft = MessageFormatter.arrayFormat(message, argArray);
    formattedMessage = ft.getMessage();

IloggingEvent非常重要,是log信息的携带者,其实现类为LoggingEvent,在实例化LoggingEvent时,使用MessageFormatter和FormattingTuple将{}占位符进行了替换。

后记

已经深夜了,很困!感觉还有很多东西没有提到,思绪又很乱。没有提到Appender/Encoder/Layout的初始化过程,其实上述接口都实现了LifeCycle(非常像tomcat),显式调用start完成初始化过程。初始化过程中做了很多事情上面没有提到,没有讲到logback.xml的解析过程,也没有提到slf4j与logback怎么结合。列个todo在这,有时间再写!

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏大内老A

ASP.NET MVC Controller激活系统详解:默认实现

Controller激活系统最终通过注册的ControllerFactory创建相应的Conroller对象,如果没有对ControllerFactory类型或...

23390
来自专栏Java学习网

高性能Java解析器实现过程详解

高性能Java解析器实现过程详解 如果你没有指定数据或语言标准的或开源的Java解析器, 可能经常要用Java实现你自己的数据或语言解析器。或者,可能有很多解析...

45760
来自专栏PHP在线

PHP 底层的运行机制与原理

原文出处: nowamagic 欢迎分享原创到伯乐头条 PHP说简单,但是要精通也不是一件简单的事。我们除了会使用之外,还得知道它底层的工作原理。 PHP是...

46270
来自专栏Java Web

Java 面试知识点解析(四)——版本特性篇(1)

在遨游了一番 Java Web 的世界之后,发现了自己的一些缺失,所以就着一篇深度好文:知名互联网公司校招 Java 开发岗面试知识点解析 ,来好好的对 Jav...

50460
来自专栏java思维导图

Java 10 已发布!时隔 6 月带来 109 项新特性

关键时刻,第一时间送达! 期待已久,没有跳票的 Java 10 已正式发布! ? 为了更快地迭代,以及跟进社区反馈,Java 的版本发布周期变更为了每六个月一次...

29870
来自专栏屈定‘s Blog

设计模式--Builder模式的思考

在日常开发中总是会遇到多参数的情况,那么对于多参数,尤其是可选参数众多的情况,可能有如下的一些解决方案.

28090
来自专栏Nian糕的私人厨房

ECMAScript7 async/await 异步解决方案

Async 函数作为异步解决方案的最优解,async/await 特性能让我们编写出相比回调地狱和 Promise 链式调用更直观、更容易理解的代码,Async...

8150
来自专栏xingoo, 一个梦想做发明家的程序员

基于Dubbo的http自动测试工具分享

公司是采用微服务来做模块化的,各个模块之间采用dubbo通信。好处就不用提了,省略了之前模块间复杂的http访问。不过也遇到一些问题: PS: Githu...

46080
来自专栏Albert陈凯

2018-04-06 JDK 新特性总览

JDK5新特性 自动装箱与拆箱 枚举 静态导入 可变参数(Varargs) 内省(introspector) 泛型(Generic) For-Eac...

33540
来自专栏精讲JAVA

JDK 10 的 109 项新特性

虽然感觉 JDK9 发布才仅仅几周的时间,然而,随着新的 OpenJDK 的发布节奏,JDK10 已经到达发布候选里程碑阶段。

16720

扫码关注云+社区

领取腾讯云代金券