加入公司以来，参与了很多个项目的开发维护；也排查处理过很多线上问题；为了写 Mock 测试，也专门去日志系统上扒拉过不少日志等等。在整个过程中，对日志的认识有了不少更深刻的认识和体会。也发现不少问题。这里先从存在的问题展开论述。

日志存在的问题
从个人的眼光上来看，当前的系统存在如下问题：
1.必要日志没有打印出来，导致在追踪问题或测试代码时，带来不必要的麻烦。比如查看一个接口的返回值用于 Mock 测试；再比如 RPC 调用报错，返回值以及错误信息没有打印到日志中，不知道具体错误原因是什么。
2.日志抽取中日志路径配置错误，导致日志重复收集，带来不必要的处理和存储成本。
3.日志代码不规范，导致不必要的性能消耗；或者大促时，日志降级不生效。
4.日志框架繁多，造成造成冲突，遗漏部分日志。
5.日志配置不规范，不利于日志的采集和清洗。
6.日志和调用链路物理隔离，查看一个请求的整个调用链路上的日志非常不方便，不利于问题的快速排查和定位。

大家的系统中，存在什么样的日志问题？欢迎留言交流讨论。针对这些问题，我觉得有些地方值得发力一下。然后，做了一些探索，总结一下，以备后续使用。

日志最佳实践探索
对于日志的使用，相信所有的开发人员都比较清楚，网上也有大量资料，相关日志框架的官方文档，也写的非常详尽，这里就不再赘述。本文从一个角度对日志规范进行探究：在排查问题时，能否通过日志来尽快地了解系统运行状态，定位问题原因？另外，由于 Java 的日志框架特别多，有一些比较容易迷惑的问题，尝试做出一点总结。

系统运行后，不严格地说，再去观察系统运行状态，就类似于在黑夜中行走。此时，向你扔过来一块板砖，那么，事后如何追责呢？请问：你能否成功躲开这块叫做 Bug 的板砖？

日志用来记录用户操作、系统运行状态等，是一个系统的重要组成部分。然而，由于日志通常不属于系统的核心功能，但是在日志对于排查问题，有无可替代的作用，理应得到所有开发人员的重视（不重视，怎么甩锅？！）！
If dog is a man’s best friend,
logs are software engineer’s best friend.
— Geshan Manandhar

Logging best practices

好的日志可以帮助系统的开发和运维人员：
1.了解线上系统的运行状态
2.快速准确定位线上问题
3.发现系统瓶颈
4.预警系统潜在风险
5.挖掘产品最大价值
6.可以将一个流程完整串起来（比如orderId）
……

不好的日志导致：
1.对系统的运行状态一知半解，甚至一无所知
2.系统出现问题无法定位，或者需要花费巨大的时间和精力
3.无法发现系统瓶颈，不知优化从何做起
4.无法基于日志对系统运行过程中的错误和潜在风险进行监控和报警
5.对挖掘用户行为和提升产品价值毫无帮助
……

日志从功能来说，可分为诊断日志、统计日志、审计日志。统计日志一般由运维组负责；而审计日志，一般是需要通过代码来实现。这里重点来说说诊断日志。

诊断日志， 典型的有：
1.请求入口和出口
2.外部服务调用和返回
3.资源消耗操作: 如读写文件等
4.容错行为： 如云硬盘的副本修复操作
5.程序异常： 如数据库无法连接
6.后台操作：定期执行删除的线程
7.启动、关闭、配置加载

好的日志就像好的文章一样，绝不是一遍就可以写好的，而需要在实际的运维过程中，结合线上问题的定位，不断地进行优化。最关键的一点是，团队要重视日志优化这件事情，不要让日志的质量持续降低（当项目变大时，项目的代码也存在一样的问题，越写越乱）。

此处有以下几个比较好的实践：
1.在定位问题的过程中完善日志，如果定位问题花费了很长时间，那就说明系统日志还存在问题，需要进一步完善和优化；
2.需要思考是否可以通过优化日志，来提前预判该问题是否可能发生（如某种资源耗尽而导致的错误，可以对资源的使用情况进行记录）
3.定义好整个团队记录日志的规范，保证每个开发记录的日志格式统一；特别需要说明的是，对于DEBUG/TRACE级别的日志，也需要定义好清晰的格式，而不是由开发人员自由发挥；
4.整个团队（包括开发，运维和测试）定期对记录的日志内容进行Review；
5.开发做运维，通过在查问题的过程来优化日志记录的方式；
6.运维或测试在日志中发现的问题，都需要及时向开发人员反映；

日志框架选型
slf4j + logback
Jar 包选择

Figure 1. Slf4j 桥接其他日志框架
基于 slf4j + logback 的日志框架依赖

<properties>
    <slf4j.version>1.7.30</slf4j.version>
    <log4j.version>2.13.3</log4j.version>
</properties>

<dependencies>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.2.3</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>log4j-over-slf4j</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jcl-over-slf4j</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jul-to-slf4j</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-to-slf4j</artifactId>
        <version>${log4j.version}</version>
    </dependency>
</dependencies>

logback 日志配置

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- 日志文件目录 -->
    <property name="log.location" value="/export/Logs/《《APP_NAME》》"/>
    <!-- 日志样式 -->
    <property name="log.pattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{80}[%L] - %msg%n"/>

    <!-- 将 JUL 的日志级别映射为 logback 的日志级别 -->
    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
        <resetJUL>true</resetJUL>
    </contextListener>

    <!-- 控制台 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder charset="UTF-8">
            <pattern>${log.pattern}</pattern>
        </encoder>
    </appender>

    <!-- 如果使用 Spring Boot 发布应用，则需要配置该 Appender。 -->
    <!-- 如果使用 Tomcat 发布应用，则不需要配置该 Appender。 -->
    <appender name="CATALINA" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 如果配置了该 Appender，则在 digger 中只需要添加该日志文件路径即可。 -->
        <file>${log.location}/catalina.log</file>
        <append>true</append>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log.location}/catalina.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy
                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>100</maxHistory>
        </rollingPolicy>
        <encoder charset="UTF-8">
            <pattern>${log.pattern}</pattern>
        </encoder>
    </appender>

    <appender name="APP" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.location}/app.log</file>
        <append>true</append>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${log.location}/app.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>30GB</totalSizeCap>
        </rollingPolicy>

        <encoder charset="UTF-8">
            <pattern>${log.pattern}</pattern>
        </encoder>
    </appender>

    <logger name="com.xxx" level="WARN"/>

    <root level="INFO">
        <!-- 堆代码 duidaima.com -->
        <!-- 下面三选一即可。 -->
        <!-- 如果使用 Tomcat 发布，如果想要 Tomcat 的日志，则使用则留下 CONSOLE。 -->
        <!-- 如果使用 Tomcat 发布，如果不想要 Tomcat 的日志，则使用则留下 APP。 -->
        <!-- 如果使用 Spring Boot 发布，则留下 CATALINA； -->
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="APP"/>
        <appender-ref ref="CATALINA"/>
    </root>
</configuration>

slf4j + log4j 2
log4j 2 的优势
Jar 包选择

Figure 2. log4j 2 桥接其他日志框架
基于 slf4j + log4j 2 的日志框架依赖

<properties>
    <slf4j.version>1.7.30</slf4j.version>
    <log4j.version>2.13.3</log4j.version>
</properties>


<dependencies>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-1.2-api</artifactId>
        <version>${log4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>${log4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-jcl</artifactId>
        <version>${log4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-jul</artifactId>
        <version>${log4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>${log4j.version}</version>
    </dependency>
</dependencies>

logback 日志配置

// TODO

典型代码评审

// 错误示例：无论日志是否打印出来，都会执行 toJson 操作，但是 toJson 耗时很高。
log.info("响应结果: {}", toJson(proceed));


// 正确示例
if (log.isInfoEnabled()) {
    log.info("响应结果:{}", toJson(proceed));
}
// 错误实例：手动提前异常消息
log.error("error param: {}, result: {}, exception: {}",
               toJson(param), toJson(result), exception.getMessage());


// 正确实例
log.error("error param: {}, result: {}",
               toJson(paramDto), toJson(result), exception);
// 错误示例：无意义前缀
log.info("##### 昵称: {}", name));


// 正确示例
log.info("昵称: {}", name));

日志参数拼接方法

package org.slf4j.helpers;

import java.text.MessageFormat;
import java.util.HashMap;
import java.util.Map;

final public class MessageFormatter {
    static final char DELIM_START = '{';
    static final char DELIM_STOP = '}';
    static final String DELIM_STR = "{}";
    private static final char ESCAPE_CHAR = '\\';

    // 堆代码 duidaima.com
    // 日志参数拼接的最终实现
    final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray, Throwable throwable) {

        if (messagePattern == null) {
            return new FormattingTuple(null, argArray, throwable);
        }

        if (argArray == null) {
            return new FormattingTuple(messagePattern);
        }

        int i = 0;
        int j;
        // use string builder for better multicore performance
        StringBuilder sbuf = new StringBuilder(messagePattern.length() + 50);

        int L;
        for (L = 0; L < argArray.length; L++) {

            j = messagePattern.indexOf(DELIM_STR, i);

            if (j == -1) {
                // no more variables
                if (i == 0) { // this is a simple string
                    return new FormattingTuple(messagePattern, argArray, throwable);
                } else { // add the tail string which contains no variables and return
                    // the result.
                    sbuf.append(messagePattern, i, messagePattern.length());
                    return new FormattingTuple(sbuf.toString(), argArray, throwable);
                }
            } else {
                if (isEscapedDelimeter(messagePattern, j)) {
                    if (!isDoubleEscaped(messagePattern, j)) {
                        L--; // DELIM_START was escaped, thus should not be incremented
                        sbuf.append(messagePattern, i, j - 1);
                        sbuf.append(DELIM_START);
                        i = j + 1;
                    } else {
                        // The escape character preceding the delimiter start is
                        // itself escaped: "abc x:\\{}"
                        // we have to consume one backward slash
                        sbuf.append(messagePattern, i, j - 1);
                        deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
                        i = j + 2;
                    }
                } else {
                    // normal case
                    sbuf.append(messagePattern, i, j);
                    // 判断需要拼接，这调用工具方法，进行参数拼接
                    deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
                    i = j + 2;
                }
            }
        }
        // append the characters following the last {} pair.
        sbuf.append(messagePattern, i, messagePattern.length());
        return new FormattingTuple(sbuf.toString(), argArray, throwable);
    }

    // special treatment of array values was suggested by 'lizongbo'
    private static void deeplyAppendParameter(StringBuilder sbuf, Object o, Map<Object[], Object> seenMap) {
        if (o == null) {
            sbuf.append("null");
            return;
        }
        if (!o.getClass().isArray()) {
            // 简单对象直接拼接
            safeObjectAppend(sbuf, o);
        } else {
            // check for primitive array types because they
            // unfortunately cannot be cast to Object[]
            if (o instanceof boolean[]) {
                booleanArrayAppend(sbuf, (boolean[]) o);
            } else if (o instanceof byte[]) {
                byteArrayAppend(sbuf, (byte[]) o);
            } else if (o instanceof char[]) {
                charArrayAppend(sbuf, (char[]) o);
            } else if (o instanceof short[]) {
                shortArrayAppend(sbuf, (short[]) o);
            } else if (o instanceof int[]) {
                intArrayAppend(sbuf, (int[]) o);
            } else if (o instanceof long[]) {
                longArrayAppend(sbuf, (long[]) o);
            } else if (o instanceof float[]) {
                floatArrayAppend(sbuf, (float[]) o);
            } else if (o instanceof double[]) {
                doubleArrayAppend(sbuf, (double[]) o);
            } else {
                objectArrayAppend(sbuf, (Object[]) o, seenMap);
            }
        }
    }

    // 基于 append 来实现日志参数拼接
    private static void safeObjectAppend(StringBuilder sbuf, Object o) {
        try {
            String oAsString = o.toString();
            sbuf.append(oAsString);
        } catch (Throwable t) {
            Util.report("SLF4J: Failed toString() invocation on an object of type [" + o.getClass().getName() + "]", t);
            sbuf.append("[FAILED toString()]");
        }

    }
}

增加 TraceId + SpanId
了解了一下内部的分布式追踪框架，可以获得到分布式追踪的信息，这样就可以从中取出 TraceId；另外，研究了一下 logback 的日志处理，可以发现可以通过继承 MessageConverter 来完成定制化。大概代码如下：

public class TraceMessageConverter extends MessageConverter {
    @Override
    public String convert(ILoggingEvent event) {
        // 获取 span
        long traceId = span.getTraceId();
        long spanId = span.getSpanId();
        String msg = super.convert(event);
        return "traceId=" + traceId + ", spanId=" + spanId + ", " + msg;
    }
}

这样的话，如果能打通分布式追踪系统和日志系统的关联，就可以将分布式追踪和日志关联起来了，方便排查问题。