vlambda博客
学习文章列表

无侵入!巧用logback扩展,见识它的强大

相信大家很多的项目代码都会使用logback来记录业务日志,其实logback的能力并非仅仅是记录日志而已,其强大之处在于:可以帮助我们在几乎毫不侵入业务代码的情况下,完成更多功能,如打点数据提交、异常报警、动态控制日志输出等。

今天我将抛砖引玉,给大家分享logback一些最佳实践,更多强大的功能等你去发掘和实践。


1. logback日志记录流程

logback基本概念和使用方法这边就不赘述了,不过为了帮助大家更好地理解下文,首先在这边介绍一下logback记录日志时的工作流程:

  1. 执行TurboFilter过滤链:

    这是一个过滤链,用于判断是否需要执行当前日志的输出。

    如果定义了TurboFilter(关于TurboFilter,下文会有更多介绍),logback会根据定义的先后,依次执行TurboFilterdecide方法,该方法有返回FilterReply枚举类型,DENY:丢弃该条日志请求;NEUTRAL:通过当前filter,执行下一步(可能是下一个TurboFilter,也可能是步骤2ACCEPT:直接跳过,执行步骤3


  2. 根据logger的level和日志请求的level决定是否执行下一步:

    这是logback的基本概念,相信很多人都清楚。


  3. loggerlevelERROR,而日志请求的levelINFOlogger.info("xx")),因为ERROR > INFO,该日志请求被丢弃;相反,当loggerlevelDEBUG,而日志请求的levelERRORlogger.error("xx")),因为ERROR > DEBUG,该日志请求会进入步骤3




  4. LoggingEvent对象创建:

    通过前两个步骤的筛选后,logback会生成LoggingEvent对象,对象中包括了一切日志输出需要的参数信息,如logger名、传入的参数、调用栈、当前线程名、当前时间、MDC变量(MDC介绍见下文)等。

    LoggingEvent对象包含了所有的上下文信息,同时也是后续一系列步骤的入参。


  5. 所有相关的appender会依次执行doAppend方法:

    该步骤包含三个子步骤:

    1. 如果appender中定义了Filter过滤链,则依次执行Filter的decide方法,基本和TurboFilter相似,不同之处在于:

      1. 只要logger发起日志请求,TurboFilter就会被触发,而Filter则必须通过步骤1和步骤2的过滤才会被触发;

      2. TurboFilter的触发发生在LoggingEvent对象被创建之前,因此对性能有苛求的场景,可以尝试使用TurboFilter。

    2. 格式化输出内容:这一步很好理解,即将LoggingEvent对象转换成便于阅读和查找的字符串。一般这一工作交给Layout对象来处理,而较新版的logback中,则交给Encoder来做这个工作。

    3. 日志落盘。


这张时序图取自logback官网,直观地呈现了在我们的业务代码中调用logger.warm("xx")或logger.error("xx", e)时的调用逻辑。


2. 自定义Filter

动态控制日志开关

上文我们知道,logback使用Filter来过滤日志请求,而我想实现自定义的过滤逻辑,只需继承Filter类,并实现decide方法即可。

假如我希望动态调整日志的输出情况,在某些时候只输出当前线程名为anshi-thread,且带有Throwable的日志,则可以这样实现Filter类

无侵入!巧用logback扩展,见识它的强大

logback配置

无侵入!巧用logback扩展,见识它的强大

上面是一个简单的例子,事实上,我们只要配合配置服务(如阿里的ConfigServer或ZooKeeper的配置同步功能),即上面anshi-thread从配置服务读取,就能在运行期间动态地调整不同的日志输出。


记录异常频率和报警

虽然Filter一般用来做日志请求的过滤,但是因为Filter是log的必经之路,我们也可以用来做异常日志的监控工作:比如我们实时统计各异常的出现次数,并对敏感异常进行报警。

无侵入!巧用logback扩展,见识它的强大

logback配置


无侵入!巧用logback扩展,见识它的强大

上面的例子中,我们通过exceptionTimesMap来记录每种异常在一分钟内的出现次数,而每出现一条新异常时,我们进行加1操作,直到异常的出现频率超过一定的阈值,进行报警。



3. PatternLayout扩展:自定义Converter


我相信基本上绝大多数的日志记录场景,都是用PatternLayout做的日志格式化,如上面的例子,用的<pattern>标签,默认即PatternLayout。

常见的pattern如:%d [%t] %5p %c - %m%n,这个pattern中用到的转换器分别为

  1. %d,即日期格式转换器

    对应的Converter类为DateConverter,负责将当前日期时间转换为字符串;

  2. %t,即线程格式转换器

    对应的Converter为ThreadConverter,负责输出当前线程的名字;

  3. %5p,日志级别转换器

    对应的Converter为LevelConverter,负责输出日志级别如DEBUG,ERROR等,其中5表示至用多5个字符来表示;

  4. %c,logger转换器

    对应的Converter为LoggerConverter,负责输出logger name;

  5. %m,日志消息格式化转换器

    对应的Converter为MessageConverter,对应的输出为LoggerEvent的getFormattedMessage。

  6. %n,换行符转换器

    对应的LineSeparatorConverter,输出System.getProperty("line.separator")。

PatternLayout包含的转换器非常多,具体可以查看其静态变量defaultConverterMap,但毕竟受限于其封装,假如我们有特殊的格式输出场景,便需要扩展PatternLayout。


假如有这样的场景:很多系统会将日志输出到Kafka等消息队列,而如果消息队列本身不支持记录机器 IP,则无法回溯日志的源IP,因此我们需要一个IPConverter。IPConverter继承自ClassicConverter,并实现convert方法,返回的字符串即为格式化后的输出字符串。


首先是IPConverter的定义

无侵入!巧用logback扩展,见识它的强大

然后需要扩展PatternLayout,将IPConverter加入到converterMap

logback配置


以上是一个较为简单的Converter实现,在其他场景中,Converter可能需要传入参数,如希望定制日期格式化转换器的输出格式,可以这样配置:%d{HH:mm:ss.SSS},即在Converter表达式后增加括号,括号中的字符串即为输入参数。


再或者,假如我们需要动态地调整日志的异常堆栈深度(举个例子,比如线上故障,不断输出异常日志,磁盘压力雪上加霜,这时候除了通过Filter来关闭日志输出外,还可以减少异常堆栈的深度)。为了实现这个功能,我们可以扩展ExtendedThrowableProxyConverter,通过配置服务动态地调整其lengthOption。


4. 巧用MDC

最后一个非常实用的工具是MDC(Mapped Diagnostic Context),关于MDC可以参考:https://www.slf4j.org/api/org/slf4j/MDC.html


我们可以粗浅地将MDC看做是存在ThreadLocal中的一个Map变量,我们可以随时执行MDC的put、get操作,获取这些变量的内容。而对应的,MDC有其MDCConverter,用法为%X{key}或%mdc{key}。对于多线程应用,尤其是web app,我们可以将request的client ip、请求参数、请求头等信息存入MDC,这样的用法,对于平时问题的排查帮助非常大。


5. 写在最后

除了上述的几种扩展方式和最佳实践外,我们还可以扩展Appender,增加日志的输出形式;也可以扩展RollingPolicy和TriggeringPolicy,定制日志文件的滚动策略,如改变日志滚动的触发方式、改变日志的滚动形式(压缩、备份)等,在这边就不一一举例了。

我们可以看到,Logback的设计扩展性极强,任何一种扩展,几乎完全不需要修改你的业务代码,唯一要做的只不过是实现、继承它的接口,并修改一下loback配置文件即可,希望我今天的几个小例子能抛砖引玉,给大家带来一些灵感。