Day637.日志记录问题 -Java业务开发常见错误
Posted 阿昌喜欢吃黄桃
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了Day637.日志记录问题 -Java业务开发常见错误相关的知识，希望对你有一定的参考价值。
日志记录问题
Hi，我是阿昌，今天学习记录的是日志框架相关的内容
有些人可能觉得，记录日志还不简单，无非是几个常用的 API 方法，比如 debug、info、warn、error；
其实也有不少的坑都是记录日志引起的，容易出错主要在于三个方面：
- 日志框架众多，不同的类库可能会使用不同的日志框架，如何兼容是一个问题。
配置复杂且容易出错。 - 日志配置文件通常很复杂，因此有些开发同学会从其他项目或者网络上复制一份配置文件，但却不知道如何修改，甚至是胡乱修改，造成很多问题。比如，重复记录日志的问题、同步日志的性能问题、异步记录的错误配置问题。
- 日志记录本身就有些误区，比如没考虑到日志内容获取的代价、胡乱使用日志级别等。
Logback、Log4j、Log4j2、commons-logging、JDK 自带的 java.util.logging 等，都是 Java 体系的日志框架，确实非常多。
而不同的类库，还可能选择使用不同的日志框架。这样一来，日志的统一管理就变得非常困难。
为了解决这个问题，就有了 SLF4J（Simple Logging Facade For Java），如下图所示：
SLF4J 实现了三种功能：
- 一是提供了统一的
日志门面 API，即图中紫色部分，实现了中立的日志记录 API。 - 二是
桥接功能，即图中蓝色部分，用来把各种日志框架的 API（图中绿色部分）桥接到 SLF4J API。这样一来，即便你的程序中使用了各种日志 API 记录日志，最终都可以桥接到 SLF4J 门面 API。 - 三是
适配功能，即图中红色部分，可以实现 SLF4J API 和实际日志框架（图中灰色部分）的绑定。SLF4J 只是日志标准，我们还是需要一个实际的日志框架。日志框架本身没有实现 SLF4J API，所以需要有一个前置转换。Logback 就是按照 SLF4J API 标准实现的，因此不需要绑定模块做转换。
需要理清楚的是，虽然可以使用 log4j-over-slf4j 来实现 Log4j 桥接到 SLF4J，也可以使用 slf4j-log4j12 实现 SLF4J 适配到 Log4j，也把它们画到了一列，但是它不能同时使用它们，否则就会产生死循环。jcl 和 jul 也是同样的道理。
虽然图中有 4 个灰色的日志实现框架，但我看到的业务系统使用最广泛的是 Logback 和 Log4j，它们是同一人开发的。
Logback 可以认为是 Log4j 的改进版本，我更推荐使用。所以，关于日志框架配置的案例，我都会围绕 Logback 展开。Spring Boot 是目前最流行的 Java 框架，它的日志框架也用的是 Logback。那，为什么我们没有手动引入 Logback 的包，就可以直接使用 Logback 了呢？
查看 Spring Boot 的 Maven 依赖树，可以发现 spring-boot-starter 模块依赖了 spring-boot-starter-logging 模块，而 spring-boot-starter-logging 模块又帮我们自动引入了 logback-classic（包含了 SLF4J 和 Logback 日志框架）和 SLF4J 的一些适配器。其中，log4j-to-slf4j 用于实现 Log4j2 API 到 SLF4J 的桥接，jul-to-slf4j 则是实现 java.util.logging API 到 SLF4J 的桥接：
一、日志重复问题
第一个案例是，logger 配置继承关系导致日志重复记录。首先，定义一个方法实现 debug、info、warn 和 error 四种日志的记录：
@Log4j2
@RequestMapping("logging")
@RestController
public class LoggingController
@GetMapping("log")
public void log()
log.debug("debug");
log.info("info");
log.warn("warn");
log.error("error");
然后，使用下面的 Logback 配置：
- 第 11 和 12 行设置了全局的日志级别为 INFO，日志输出使用 CONSOLE Appender。
- 第 3 到 7 行，首先将 CONSOLE Appender 定义为 ConsoleAppender，也就是把日志输出到控制台（System.out/System.err）；然后通过 PatternLayout 定义了日志的输出格式。关于格式化字符串的各种使用方式，你可以进一步查阅官方文档。
- 第 8 到 10 行实现了一个 Logger 配置，将应用包的日志级别设置为 DEBUG、日志输出同样使用 CONSOLE Appender。
<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
</layout>
</appender>
<logger name="org.geekbang.time.commonmistakes.logging" level="DEBUG">
<appender-ref ref="CONSOLE"/>
</logger>
<root level="INFO">
<appender-ref ref="CONSOLE"/>
</root>
</configuration>
这段配置看起来没啥问题，但执行方法后出现了日志重复记录的问题：
从配置文件的第 9 和 12 行可以看到，CONSOLE 这个 Appender 同时挂载到了两个 Logger 上，一个是我们定义的 ，一个是 ，由于我们定义的 继承自 ，所以同一条日志既会通过 logger 记录，也会发送到 root 记录，因此应用 package 下的日志出现了重复记录。
后来我了解到，这个同学如此配置的初衷是实现自定义的 logger 配置，让应用内的日志暂时开启 DEBUG 级别的日志记录。其实，他完全不需要重复挂载 Appender，去掉 下挂载的 Appender 即可：
<logger name="org.geekbang.time.commonmistakes.logging" level="DEBUG"/>
如果自定义的 需要把日志输出到不同的 Appender，比如将应用的日志输出到文件 app.log、把其他框架的日志输出到控制台，可以设置 的 additivity 属性为 false，这样就不会继承 的 Appender 了：
<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>app.log</file>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
</encoder>
</appender>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
</layout>
</appender>
<logger name="org.geekbang.time.commonmistakes.logging" level="DEBUG" additivity="false">
<appender-ref ref="FILE"/>
</logger>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</configuration>
第二个案例是，错误配置 LevelFilter 造成日志重复记录。
一般互联网公司都会使用 ELK 三件套来统一收集日志，有一次我们发现 Kibana 上展示的日志有部分重复，一直怀疑是 Logstash 配置错误，但最后发现还是 Logback 的配置错误引起的。
这个项目的日志是这样配置的：在记录日志到控制台的同时，把日志记录按照不同的级别记录到两个文件中：
<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
<property name="logDir" value="./logs" />
<property name="app.name" value="common-mistakes" />
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
</layout>
</appender>
<appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
<File>$logDir/$app.name_info.log</File>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
</filter>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<appender name="ERROR_FILE" class="ch.qos.logback.core.FileAppender
">
<File>$logDir/$app.name_error.log</File>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>WARN</level>
</filter>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="INFO_FILE"/>
<appender-ref ref="ERROR_FILE"/>
</root>
</configuration>
- 第 31 到 35 行定义的 root 引用了三个 Appender。
- 第 5 到 9 行是第一个 ConsoleAppender，用于把所有日志输出到控制台。
- 第 10 到 19 行定义了一个 FileAppender，用于记录文件日志，并定义了文件名、记录日志的格式和编码等信息。最关键的是，第 12 到 14 行定义的 LevelFilter 过滤日志，将过滤级别设置为 INFO，目的是希望 _info.log 文件中可以记录 INFO 级别的日志。
- 第 20 到 30 行定义了一个类似的 FileAppender，并使用 ThresholdFilter 来过滤日志，过滤级别设置为 WARN，目的是把 WARN 以上级别的日志记录到另一个 _error.log 文件中。运行一下测试程序：
可以看到，_info.log 中包含了 INFO、WARN 和 ERROR 三个级别的日志，不符合我们的预期；
error.log 包含了 WARN 和 ERROR 两个级别的日志。因此，造成了日志的重复收集。你可能会问，这么明显的日志重复为什么没有及时发现？一些公司使用自动化的 ELK 方案收集日志，日志会同时输出到控制台和文件，开发人员在本机测试时不太会关心文件中记录的日志，而在测试和生产环境又因为开发人员没有服务器访问权限，所以原始日志文件中的重复问题并不容易发现。
为了分析日志重复的原因，我们来复习一下 ThresholdFilter 和 LevelFilter 的配置方式。
分析 ThresholdFilter 的源码发现，当日志级别大于等于配置的级别时返回 NEUTRAL，继续调用过滤器链上的下一个过滤器；
否则，返回 DENY 直接拒绝记录日志：
public class ThresholdFilter extends Filter<ILoggingEvent>
public FilterReply decide(ILoggingEvent event)
if (!isStarted())
return FilterReply.NEUTRAL;
if (event.getLevel().isGreaterOrEqual(level))
return FilterReply.NEUTRAL;
else
return FilterReply.DENY;
在这个案例中，把 ThresholdFilter 设置为 WARN，可以记录 WARN 和 ERROR 级别的日志。
LevelFilter 用来比较日志级别，然后进行相应处理：如果匹配就调用 onMatch 定义的处理方式，默认是交给下一个过滤器处理（AbstractMatcherFilter 基类中定义的默认值）；否则，调用 onMismatch 定义的处理方式，默认也是交给下一个过滤器处理。
public class LevelFilter extends AbstractMatcherFilter<ILoggingEvent>
public FilterReply decide(ILoggingEvent event)
if (!isStarted())
return FilterReply.NEUTRAL;
if (event.getLevel().equals(level))
return onMatch;
else
return onMismatch;
public abstract class AbstractMatcherFilter<E> extends Filter<E>
protected FilterReply onMatch = FilterReply.NEUTRAL;
protected FilterReply onMismatch = FilterReply.NEUTRAL;
和 ThresholdFilter 不同的是，LevelFilter 仅仅配置 level 是无法真正起作用的。由于没有配置 onMatch 和 onMismatch 属性，所以相当于这个过滤器是无用的，导致 INFO 以上级别的日志都记录了。
定位到问题后，修改方式就很明显了：配置 LevelFilter 的 onMatch 属性为 ACCEPT，表示接收 INFO 级别的日志；配置 onMismatch 属性为 DENY，表示除了 INFO 级别都不记录：
<appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
<File>$logDir/$app.name_info.log</File>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
...
</appender>
这样修改后，_info.log 文件中只会有 INFO 级别的日志，不会出现日志重复的问题了。
二、异步日志问题
掌握了把日志输出到文件中的方法后，我们接下来面临的问题是，如何避免日志记录成为应用的性能瓶颈。这可以帮助我们解决，磁盘（比如机械磁盘）IO 性能较差、日志量又很大的情况下，如何记录日志的问题。
测试一下，记录日志的性能问题，定义如下的日志配置，一共有两个 Appender：
- FILE 是一个 FileAppender，用于记录所有的日志；
- CONSOLE 是一个 ConsoleAppender，用于记录带有 time 标记的日志。
<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>app.log</file>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
</encoder>
</appender>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%dyyyy-MM-dd HH:mm:ss.SSS] [%thread] [%-5level] [%logger40:%line] - %msg%n</pattern>
</layout>
<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
<evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
<marker>time</marker>
</evaluator>
<onMismatch>DENY</onMismatch>
<onMatch>ACCEPT</onMatch>
</filter>
</appender>
<root level="INFO">
<appender-ref ref="FILE"/>
<appender-ref ref="CONSOLE"/>
</root>
</configuration>
不知道你有没有注意到，这段代码中有个 EvaluatorFilter（求值过滤器），用于判断日志是否符合某个条件。在后续的测试代码中，我们会把大量日志输出到文件中，日志文件会非常大，如果性能测试结果也混在其中的话，就很难找到那条日志。
所以，这里我们使用 EvaluatorFilter 对日志按照标记进行过滤，并将过滤出的日志单独输出到控制台上。在这个案例中，我们给输出测试结果的那条日志上做了 time 标记。配合使用标记和 EvaluatorFilter，实现日志的按标签过滤，是一个不错的小技巧。
如下测试代码中，实现了记录指定次数的大日志，每条日志包含 1MB 字节的模拟数据，最后记录一条以 time 为标记的方法执行耗时日志：
@GetMapping("performance")
public void performance(@RequestParam(name = "count", defaultValue = "1000") int count)
long begin = System.currentTimeMillis();
String payload = IntStream.rangeClosed(1, 1000000)
.mapToObj(__ -> "a")
.collect(Collectors.joining("")) + UUID.randomUUID().toString();
IntStream.rangeClosed(1, count).forEach(i -> log.info(" ", i, payload));
Marker timeMarker = MarkerFactory.getMarker("time");
log.info(timeMarker, "took ms", System.currentTimeMillis() - begin);
执行程序后可以看到，记录 1000 次日志和 10000 次日志的调用耗时，分别是 6.3 秒和 44.5 秒：
对于只记录文件日志的代码了来说，这个耗时挺长的。为了分析其中原因，我们需要分析下 FileAppender 的源码。
FileAppender 继承自 OutputStreamAppender，查看 OutputStreamAppender 源码的第 30 到 33 行发现，在追加日志的时候，是直接把日志写入 OutputStream 中，属于同步记录日志：
public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E>
private OutputStream outputStream;
boolean immediateFlush = true;
@Override
protected void append(E eventObject)
if (!isStarted())
return;
subAppend(eventObject);
protected void subAppend(E event)
if (!isStarted())
return;
try
//编码LoggingEvent
byte[] byteArray = this.encoder.encode(event);
//写字节流
writeBytes(byteArray);
catch (IOException ioe)
...
private void writeBytes(byte[] byteArray) throws IOException
if(byteArray == null || byteArray.length == 0)
return;
lock.lock()AD637使用笔记