无侵入！巧用logback扩展，见识它的强大

Posted 2021-04-24 玩物得志技术

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

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

1. logback日志记录流程

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

1. 执行TurboFilter过滤链：

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

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

   
   

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

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

   
   

3. 当logger的level为ERROR，而日志请求的level是INFO（logger.info("xx")），因为ERROR > INFO，该日志请求被丢弃；相反，当logger的level为DEBUG，而日志请求的level是ERROR（logger.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配置

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

记录异常频率和报警

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

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的定义

然后需要扩展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配置文件即可，希望我今天的几个小例子能抛砖引玉，给大家带来一些灵感。