为 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 命令，可以发动搜索引擎，一个参考文章：
总结
这种日志模式是针对小型应用的一个简单配置，如果是复杂的系统，日志一般会传到 ELK 之类的日志平台，属于高级用法，请自己搜索。
本文首发于微信公众号：肖念青，转载请保留原始出处信息。
我的个人网站：https://www.jitao.tech
