谈这个问题的起因是组里的开发打印日志的很随意,结果要么日志爆炸导致机器受不了,要么日志缺失排查问题同学受不了。本文的目的是定义什么时候应该打日志、采用哪个级别的日志。
1. 日志分级
级别 | 分级 | 典型场景 |
---|---|---|
ERROR | 阻塞业务 | 1. 数据库/中间件/接口连接失败、调用异常 2. 关键数据缺失、未捕获的异常 |
WARN | 潜在问题 | 1. 缓存击穿、磁盘空间不足 2. 用户输入参数错误 3. 第三方接口返回警告 |
INFO | 关键节点 | 1. 登录、下单、配送、成单, 订单状态变更 2. 定时任务执行、缓存数据加载 3. 关键接口的出入参,大流量接口要考虑采样 |
DEBUG | 排查问题 | 1. 和第三方接口/中间件交互的详细内容(出入参) 2. 方法内部变量、缓存数据 3. 循环和分支的走向,以及中间状态,方法的重试 |
2. 日志位置
1. 指导原则
- 避免重复,在可完全推断程序执行流程的情况下,越少越好
- 记录上下文,调用链路的唯一标识(用户ID、设备ID、业务ID等等),避免无意义的日志
- 不要吞没异常
- 避免过度日志,避免循环中打印INFO日志
- 高频调用,要考虑运维的压力,考虑采样/DEBUG,减少输出
2. 方法定义
1. 方法入口
参数校验失败用WARN,通过后打印参数用DEBUG级别,核心方法用INFO,调用量大时对INFO日志采样或降级为DEBUG
public Resp<List<LangVO>> availableLanguages(@RequestHeader(TENANT_ID) Long tenantId,@RequestHeader(USER_ID) Long userId) {
if (userId == null || userId <= 0) {
log.warn("availableLanguages : invliad userId, userId={}", tenantId, userId);
return Resp.fail(code1)
}
if (log.isDebugEnabled()) {
log.debug("availableLanguages : tenantId: {}, userId: {}", tenantId, userId);
}
...
}
如果是重要接口,可以用INFO打印入参
public Resp<List<LangVO>> availableLanguages(@RequestHeader(TENANT_ID) Long tenantId,@RequestHeader(USER_ID) Long userId) {
if (rateLimiter.tryAcquire()) {
log.info("availableLanguages : tenantId: {}, userId: {}", tenantId, userId);
}
...
}
当然为了代码美观,你可以将入参的打印逻辑用AOP封装,将参数校验的逻辑提取到专门的校验方法,自定业务异常及Assert工具返回响应。
2. 方法出口
方法返回值,默认用DEBUG打印,核心方法用INFO,和入参一样,如果调用频率过高,对日志采样或降级为DEBUG
private <T, R extends Signed> Optional<R> formSubmit(String uri, T form, TypeReference<Result<R>> typeReference) throws Exception {
...
if(log.isDebugEnabbled()) {
log.debug("formSubmit , response: {}", result.getData());
}
return Optional.of(result.getData());
}
3. 外部调用
1. 调用前后
包括任意的HTTP请求、中间件读写、系统调用等等,包括
- 调用后的出入参DEBUG
- 校验响应结果,校验失败的话打印ERROR
private <T, R extends Signed> Optional<R> formSubmit(String uri, T form, TypeReference<Result<R>> typeReference) throws Exception {
...
String data = HttpUtil.post(URL + uri, params);
if (log.isDebugEnabled()) { // DEBUG,下打印对应出入参
log.debug("formSubmit , request: {} , response: {}", params, data);
}
Result<R> result = JSONUtil.toBean(data, typeReference, true);
if (result == null || !result.isSuccess() || !verifyData(result.getData())) { // 响应异常,用ERROR打印
log.error("formSubmit , response failed. uri: {}, request: {}, response: {}", uri, params, data);
return Optional.empty();
}
...
}
2. 异常处理
private <T, R extends Signed> Optional<R> formSubmit(String uri, T form, TypeReference<Result<R>> typeReference) {
try {
...
String data = HttpUtil.post(URL + uri, params);
...
} catch(Exception e) {
log.error("formSubmit failed, uri:{}, params:{}, data:{}", uri, params, data, e);
}
}
4. 分支和状态
1. 分支
默认使用DEBUG打印,核心逻辑可以用INFO,高频采样或者降级为DEBUG。可以不在每个分支都打印,但是要基于日志能判断程序的走向。
public FaValidateItemVO getCheckItem(VerifyItemDTO validateItemVO, Client client) {
...
if (BizTypeEnum.isNeedPasskey(typeEnum)) {
log.debug("getCheckItem need passkey, typeEnum:{}", typeEnum);
}
if (isLogin()) {
Resp<BalanceDTO> balance = feigin.totalAsset(uid);
log.debug("getCheckItem login , balance:{}", balance);
if (!balance.isSuccess() || balance.amount <= 0) {
skip2Fa = true;
}
}
...
}
2. 复杂状态
方法内部有复杂状态,记录状态值有助于排查问题的话,也可以打印。
3. 最佳实践
1. 用户标识
除了上述分级、位置,我还需要关注的一个问题是,为了方便查找对应的日志,我们需要在日志中统一加上客户端ID、业务ID(用户ID、订单ID等)。如果使用的是logback的话,可以通过写入MDC,并修改日志的parttern实现。如果是Spring MVC应用,我们可以加一个
@Slf4j
@Configuration
public class DebugHandleInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
String uid = clientInfoDTO.getUserId());
MDC.put("uid", uid); // 用户ID
String clt = clientInfoDTO.getClientCode();
MDC.put("did", clt); // 设备ID,同一个设备这个ID不变
return true;
}
@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
MDC.clear();
}
注册这个拦截器后,可以在logback的配置文件中使用这两个变量
<configuration>
...
<!--appender-->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d %-5level [%thread] %X{uid} %X{did} %logger: %desensitive(%msg) %n</pattern>
</encoder>
</appender>
...
</configuration>
2. 数据脱敏
logback提供了CompositeConverter供我们扩展,在transform中对要打印的内容进行替换。
public class DesensitiveConverter extends CompositeConverter<ILoggingEvent> {
@Override
protected String transform(ILoggingEvent event, String in) {
return return msg.replaceAll("\"?email\"?[:=][^,&]*[,&]?", "**** ");
}
}
在logback的配置文件中注册这个CompositeConverter
<conversionRule conversionWord="desensitive" converterClass="com.keyniu.DesensitiveConverter"/>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d %-5level [%thread] %X{uid} %X{clt} %logger: %desensitive(%msg) %n</pattern>
</encoder>
</appender>