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

发布日期:2020年03月12日本文同步发表于公众号:

Cover

概述

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

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

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

配置

应用配置文件

代码:

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,响应体

使用 Linuxawk 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 之类的日志平台,属于高级用法,请自己搜索。