为 HTTP API 接口增加统一请求日志

概述

增加请求日志，便于在开发阶段，追查错误，在将来上线后，进行线上问题的排查。

统一请求日志要完成以下功能：

记录时间、请求体和响应体；
记录应用特有的一些信息，如当前用户，客户端版本，请求处理时间等；
对于敏感信息，如登录密码，不做记录；
在开发阶段，日志打印到控制台，在服务器上运行阶段，将日志保存到文件；
保存在服务器的日志文件，按日切换文件，并将切出的旧文件压缩保存，并只保留指定一段时间的日志。

配置

应用配置文件

代码：

config/application-staging.yml。

spring:
  application:
    name: http-api-demo
  profiles:
    active: staging

logging:
  file: /kt/log/http-api-demo/http-api-demo.log

在应用配置文件里，配置日志文件保存目录，注意这里 spring.profiles.active 配置的是 staging 环境。

Logback 配置文件

代码：

src/main/resources/logback-spring.xml。

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/spring.log}"/>
    <springProfile name="default,dev">
        <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
        <logger name="org.springframework.jdbc.core" additivity="false" level="DEBUG" >
            <appender-ref ref="CONSOLE" />
        </logger>
    </springProfile>
    <springProfile name="staging,prod">
        <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <encoder>
                <pattern>${FILE_LOG_PATTERN}</pattern>
                <charset>UTF-8</charset>
            </encoder>
            <file>${LOG_FILE}</file>
            <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                <fileNamePattern>${LOG_FILE}.a/%d{yyyyMMdd}.%i.log.gz</fileNamePattern>
                <maxHistory>180</maxHistory>
                <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                    <maxFileSize>100MB</maxFileSize>
                </timeBasedFileNamingAndTriggeringPolicy>
            </rollingPolicy>
        </appender>
        <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
            <appender-ref ref="FILE" />
        </appender>
        <root level="INFO">
            <appender-ref ref="ASYNC"/>
        </root>
    </springProfile>
</configuration>

这个配置文件是 Spring 框架对 Logback 配置文件的扩展，可以将多个 profile 的配置写到一个文件。

可以看到，如果是 default 或者 dev profile，输出到 CONSOLE；如果是 staging 或者 prod profile，输出到文件 ${LOG_FILE}，这个 LOG_FILE 是个变量，就是我们之前在 application-staging.yml 中配置的 logging.file。

历史日志文件将保留 180 天，每个文件最大 100M，压缩后的文件名是 ${LOG_FILE}.a/%d{yyyyMMdd}.%i.log.gz，这里复用了 LOG_FILE 变量.

这相当于当前日志文件名是 /kt/log/http-api-demo/http-api-demo.log，历史文件保存在 /kt/log/http-api-demo/http-api-demo.log.a 目录里，文件名是 日期.序号.log.gz。

代码

日志相关代码不贴出来了，都在这里：

src/main/java/tech/jitao/httpapidemo/config/logging。

有几个要点：

日志记录使用的一些数据是 AuthInterceptor 保存的，比如用户信息等；
为了实现跳过某些接口，在接口上标记 @NoLogging，并且可设定忽略请求或者响应，在 LoggingInterceptor 检测到需要忽略日志的请求，设置变量，在 LoggingFilter 中检测到忽略变量，进行忽略。因为标记是在 Controller 上，Filter 检测不到，所以要多加一个 Interceptor 进行标记检测。

运行

如果想测试的效果，需要：

创建 /kt/log/http-api-demo 目录，或修改成自己的，注意要全路径；
运行时，要指定配置文件全路径。

sudo mkdir -p /kt/log/http-api-demo
build/libs/http-api-demo-1.2.0.jar --spring.config.location=file:${项目目录全路径}/config/application-staging.yml

日志排查

记录的日志格式如下：

yyyy-MM-dd HH:mm:SS.sss  INFO 43746 --- [0.1-8080-exec-1] t.j.h.config.logging.LoggingFilter       : POST /app/account/login 200
<<<<<<<<<<
o= null
v= null
n= null
u= null
q= << omit >>
t= 4 ms
r= {"code":"OK","data":{"id":"6372534490252289024","name":"唐伯虎","avatar":"https://www.jitao.tech/static/flutter-logo.png","username":"tang","birthday":"2020-03-12","balance":"102.4","admin":"N","status":1,"lastLoginTime":"2020-03-12 14:22:09","createTime":"2020-03-12 14:22:09","updateTime":"2020-03-12 14:22:09","accessToken":"D8d8lKFtXdQ15Y5VoZm2UHQI8UZGGk17kArOFR7I"}}
>>>>>>>>>>

各字段意义：

o，操作系统，来自 HTTP Header X-App-Os；
v，客户端版本，来自 HTTP Header X-App-Version；
n，客户端网络，来自 HTTP Header X-App-Network；
u，用户 ID
q，请求体
t，处理时间，毫秒
r，响应体

使用 Linux 的 awk cat grep head less sort tail wc 等命令配合管道进行日志排查。

简单举两个例子 🙋🌰🌰：

检查 ID 为 9527 的用户的登录日志

cat http-api-demo.log | grep -A 10 "POST /app/account/login" | grep -A 4 -B 6 "^u= 9527" | less

获取最慢的几个请求的处理时间，单位是毫秒：

cat http-api-demo.log | grep "^t=" | awk '{print $2}' | sort | tail

更多 Linux 命令，可以发动搜索引擎，一个参考文章：

你需要熟练运用的 12 个命令行工具。

总结

这种日志模式是针对小型应用的一个简单配置，如果是复杂的系统，日志一般会传到 ELK 之类的日志平台，属于高级用法，请自己搜索。

为 HTTP API 接口增加统一请求日志

toc

概述

配置

应用配置文件

Logback 配置文件

代码

运行

日志排查

总结