日志规范与 Logback 配置实践

查一个用户的投诉，我翻了两小时日志

上个月客服转来一个工单：用户说 6 月 20 号下午下过一单，付了钱但订单状态还是"待支付"。我拿着用户 ID 去 ELK 查，搜出来 3800 多条日志，全是这个用户的，而且几个接口的日志混在一起，根本分不清哪几条是同一次请求的。

翻了两个多小时才拼凑出大概的调用链。那天下午我就下了决心，把项目的日志规范整一遍。这篇记录一下我改了哪些地方。

级别不是随便打的

我们项目里当时最常见的毛病是：全部用 info，或者更省事的，到处 System.out.println 和 e.printStackTrace()。

我给自己定的规则：

• ERROR：需要人马上处理的。比如调用下游失败且重试无效、数据库连不上。一条 ERROR 就应该配一条告警。
• WARN：有问题但系统自己扛住了。比如缓存没命中走了兜底、参数校验失败、重试第 1 次失败。可恢复的异常打 WARN 而不是 ERROR。
• INFO：重要的状态变化。订单创建、支付成功、状态机流转。用来还原用户的操作轨迹。
• DEBUG：排查问题用的细节，方法入参出参、中间计算结果。生产默认关掉。

判断标准就一句话：这条日志出问题时，你希望它出现在告警里吗？希望就 ERROR，不希望但想知道就 WARN。

参数校验失败这种最典型，用户填错个手机号，你打 ERROR 然后监控告警响，纯粹是自找麻烦：

// 之前
if (!Pattern.matches(PHONE_REGEX, req.getPhone())) {
    log.error("手机号格式错误: {}", req.getPhone());   // 运维半夜被叫醒
    throw new BizException("手机号格式不正确");
}

// 改成
if (!Pattern.matches(PHONE_REGEX, req.getPhone())) {
    log.warn("param invalid, phone={}, userId={}", req.getPhone(), req.getUserId());
    throw new BizException("手机号格式不正确");
}

还有个必须说的：异常日志要把堆栈打出来。log.error("下单失败") 这种等于没打，只看到一句"失败"，不知道为什么失败。正确写法是把异常对象作为最后一个参数传进去，Logback 会自己展开堆栈：

try {
    orderMapper.insert(order);
} catch (DuplicateKeyException e) {
    // 对，最后一个参数是 e，不要 {} 占位
    log.error("create order dup, orderNo={}", order.getOrderNo(), e);
    throw new BizException("订单已存在");
}

log.error("xxx" + e.getMessage()) 和 e.printStackTrace() 两种写法都不要再用了。前者丢堆栈，后者输出到 System.err，不进文件，还因为 printStackTrace 内部加了 synchronized 有锁竞争。

字符串拼接也别用，用 {} 占位符。差别在于：如果这条日志当前级别不会输出，{} 版本根本不做字符串拼接，直接返回。

log.debug("query result: " + JSON.toJSONString(list));  // 即使 debug 关着，JSON 序列化照样执行
log.debug("query result: {}", JSON.toJSONString(list)); // 关着就不执行

我们有个接口一次查 2000 条数据，JSON 序列化一次要 40 毫秒，就因为这个把 P99 拉高了 40 毫秒。

MDC：把同一次请求的日志串起来

开篇那个工单的痛点，靠 MDC 就解决了。思路是：请求进来时生成一个 traceId 放进 MDC（Mapped Diagnostic Context，本质是 ThreadLocal），日志格式里带上它，之后这个线程打的每条日志都自动带上这个 ID。

用 Servlet Filter 实现，注册一次全局生效：

@Order(Ordered.HIGHEST_PRECEDENCE)
@WebFilter(filterName = "traceFilter", urlPatterns = "/*")
public class TraceFilter implements Filter {

    @Override
    public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain)
            throws IOException, ServletException {
        String traceId = ((HttpServletRequest) req).getHeader("X-Trace-Id");
        if (StringUtils.isBlank(traceId)) {
            traceId = UUID.randomUUID().toString().replace("-", "").substring(0, 16);
        }
        MDC.put("traceId", traceId);
        try {
            chain.doFilter(req, resp);
        } finally {
            MDC.remove("traceId");   // 必须清，线程是复用的
        }
    }
}

那个 finally 里的 MDC.remove() 千万不能省。Tomcat 的线程是池化复用的，不清的话下一个请求会复用上一个请求的 traceId，日志全串味。我就犯过这个错，排查的时候看着两条毫不相干的日志顶着同一个 traceId，差点把我绕进去。

更要注意的是跨线程：MDC 基于 ThreadLocal，子线程拿不到父线程的值。如果你的逻辑里起了线程池异步处理，异步部分的日志就没有 traceId 了。办法是在提交任务时把 MDC 内容抓出来传进去：

// 提交时抓快照
Map<String, String> context = MDC.getCopyOfContextMap();
executor.submit(() -> {
    if (context != null) {
        MDC.setContextMap(context);   // 子线程里恢复
    }
    try {
        handleAsync(msg);
    } finally {
        MDC.clear();
    }
});

日志 pattern 里用 %X{traceId} 取这个值。我们线上用的格式：

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level [%X{traceId:--}] %logger{36} - %msg%n</pattern>

%X{traceId:--} 冒号后面是默认值，没有 traceId 时输出一个短横线，不会出现难看的 []。改造后那个工单，我拿到 traceId 一搜，同一次请求的 23 条日志按顺序排好，5 分钟就定位到是支付回调里有个分支没更新订单状态。

异步日志省下来的时间

我们压测时发现订单接口 P99 有 210 毫秒，看着不太对劲。用 Arthas 抓了个火焰图（其实是 trace 命令看的方法耗时），发现 FileAppender 的写盘操作占了 30 毫秒左右，而且有锁等待。

Logback 的 FileAppender 是同步的，doAppend 方法上有 synchronized，所有要打日志的线程会在这里排队。日志量大的时候这个锁竞争还挺明显。

换成 AsyncAppender：

<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
    <!-- 队列最大容量，默认 256，太小了 -->
    <queueSize>2048</queueSize>
    <!-- 队列剩余容量低于此值时，丢弃 TRACE/DEBUG/INFO 级日志 -->
    <discardingThreshold>0</discardingThreshold>
    <!-- 队列满了是否阻塞等待。true 会保证不丢日志，但会拖慢业务线程 -->
    <neverBlock>false</neverBlock>
    <appender-ref ref="FILE"/>
</appender>

三个参数说一下我的选择：

• queueSize 默认 256 太小，突发日志容易打满。我们设 2048，实测峰值队列长度到过 900。
• discardingThreshold 默认是 queueSize / 5，也就是队列剩 20% 时开始丢 INFO 及以下。我设成 0 表示不丢，宁可慢一点也要留全日志。
• neverBlock 设 false，队列满时业务线程会阻塞等一下。设 true 的话日志直接丢弃，业务是不卡了，但排查时缺日志更难受。

改完压测数据：

P99 降了 32 毫秒，单条日志写入从 310 微秒降到 8 微秒。代价是：进程被 kill -9 时队列里没写完的日志会丢；另外异步日志的堆栈里看不到线程名对应的真实调用顺序了（因为有 AsyncAppender 的 worker 线程中转）。这两个代价我们接受。

其他几条约定

日志切分用 SizeAndTimeBasedRollingPolicy，按天切同时按大小切，避免单天日志过大：

<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
    <fileNamePattern>/data/logs/order/order.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
    <maxFileSize>200MB</maxFileSize>
    <maxHistory>15</maxHistory>
    <totalSizeCap>10GB</totalSizeCap>
</rollingPolicy>

注意 Spring Boot 2.1 里，如果用了 logback-spring.xml 这个文件名（带 -spring），可以用 <springProfile> 标签区分环境；用 logback.xml 则不行，因为它是被 Logback 自己加载的，早于 Spring 容器启动。

最后列几条我们组的硬规矩：

• 禁止 System.out.println 和 e.printStackTrace()，提交前用 git hook 检查。
• 禁止在循环里打日志，2000 次的循环会打出 2000 行。
• 日志里不打敏感信息：手机号打前 3 后 4，身份证号不打，密码绝对不打。
• 每个 ERROR 日志都要能被搜索定位，带上业务主键（订单号、用户 ID）。

改完之后我再去查工单，基本都是两三分钟能定位。这个投入挺值的。

参考

• 官方文档：architecture-practice
• Baeldung 上的相关实战
• StackOverflow 上的相关讨论