首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >日志那些事儿——Logback源码解析

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

作者头像
LNAmp
发布2018-09-05 15:44:00
2.1K1
发布2018-09-05 15:44:00
举报

前言

在上篇文章日志漫谈中谈到,日志在监控报警、查错分析等方面有着非常重要的应用。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在这,有时间再写!

本文参与 腾讯云自媒体分享计划,分享自作者个人站点/博客。
原始发表:2016.08.21 ,如有侵权请联系 cloudcommunity@tencent.com 删除

本文分享自 作者个人站点/博客 前往查看

如有侵权,请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体分享计划  ,欢迎热爱写作的你一起参与!

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 前言
  • logback背景与配置
  • logback日志打印流程
  • 相关代码分析
    • 关键代码1
    • 关键代码2
    • 关键代码3
    • 关键代码3
    • 后记
    相关产品与服务
    腾讯云代码分析
    腾讯云代码分析(内部代号CodeDog)是集众多代码分析工具的云原生、分布式、高性能的代码综合分析跟踪管理平台,其主要功能是持续跟踪分析代码,观测项目代码质量,支撑团队传承代码文化。
    领券
    问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档