实现打印异常日志_微服务日志处理

日志处理更多是技术团队文化的一种反映，我们不太会夸奖某位大牛说他日志打的好，所以日志很容易被大家忽视。

本文尝试探讨微服务日志处理的三方面问题：

• 如何日志打印
• 日志搜集
• 日志潜在用途

如何日志打印？

不同的java程序员对于日志打印有不同的习惯。从生产环境bug分析、系统后续运维等角度出发，有一些基础日志是必不可少的。这类日志，不应该依赖于研发人员，而应该由系统框架来实现自动打印。这类日志包括：

1）系统边界日志

• • 比如前端页面对于后台的调用请求，后台的返回数据
  • 一个微服务对于另外一个微服务的请求以及获取到的返回数据
  • 对于第三方系统的调用请求以及获取到的返回数据

2）异常日志

• • 主要指和业务相关的用户自定义异常

了解了哪些日志应该打印，接下来谈一下具体实现。

既然日志的处理属于系统框架的一部分，我们可以考虑提供一个log-util项目，让所有的微服务项目依赖于这个log-util。在log-util里面来提供对上述两类日志的自动处理。

log-util

log-util将主要提供以下功能：

• 统一的logback.xml文件
• 基于AbstractRequestLoggingFilter的请求拦截

对于基于spring cloud的微服务，我们希望能有方式，可以把跨微服务的请求日志，以及某个微服务内部的处理日志关联起来，便于我们分析。spring-cloud-starter-sleuth在这方面提供了很多帮助。我们只需要在log-util的build.gradle文件里面需要添加相关依赖：

compile("org.springframework.cloud:spring-cloud-starter-sleuth")

统一的logback.xml文件

我们可以在log-util里面提供公用的logback.xml，统一日志格式。一个典型的logback.xml内容如下：

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE configuration>
<configuration scan="true" scanPeriod="60000" debug="false">
    <!-- 从当前微服务的application.yml中获取log.dir和spring.application.name等信息 -->
    <property resource="application.yml" />

    <!-- 日志输出格式 -->
    <property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%-5level] [%thread] [%X{X-B3-TraceId:-}] 
[%X{X-B3-SpanId:-}] [%X{url:-}] [%X{ip:-}] [%X{userId:-}] [%logger{32}] [%F:%L]---- %msg%n"/>

    <!-- 标准输出 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <!-- 输出至日志文件，当文件大小超过100MB时，自动存档 -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>${log.dir}/${spring.application.name}.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
            <fileNamePattern>${log.dir}/${spring.application.name}-%i.log</fileNamePattern>
            <minIndex>1</minIndex>
            <maxIndex>30</maxIndex>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <maxFileSize>100MB</maxFileSize>
        </triggeringPolicy>
        <encoder charset="UTF-8">
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="FILE" />
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

LOG_PATTERN字段解释：

• [%d{yyyy-MM-dd HH:mm:ss.SSS}] ，日志打印时间
• [%-5level] ，日志level，比如INFO，WARN，ERROR等
• [%thread] ，线程id
• [%X{X-B3-TraceId:-}] ，spring-cloud-starter-sleuth提供的随机字符串，对于某个请求，在同一个微服务内部的处理流程所打印的日志，该字段一致。由sleuth负责填充。
• [%X{X-B3-SpanId:-}] ，spring-cloud-starter-sleuth提供的随机字符串，对于某个请求，在不同微服务内部的处理流程所打印的日志，该字段一致。由sleuth负责填充。
• [%X{url:-}] ，触发该日志的url调用
• [%X{ip:-}] ，客户端ip（只对于面向app或者pc页面的gateway类微服务有效）
• [%X{userId:-}] ，触发该日志的userid
• [%logger{32}] ，该日志的打印类
• [%F:%L]，该日志打印语句行数

基于AbstractRequestLoggingFilter的请求拦截

LOG_PATTERN中提到的三个字段url、ip和userId，需要我们借助于AbstractRequestLoggingFilter从HttpServletRequest中获取并填充至MDC，然后由logback打印。

public class MyRequestLoggingFilter extends AbstractRequestLoggingFilter {

	@Override
	protected boolean shouldLog(HttpServletRequest request) {
		return true;
	}

	@Override
	protected void beforeRequest(HttpServletRequest request, String message) {
		MDC.put("url", request.getRequestURI());
		
		String ipAddress = request.getHeader("X-FORWARDED-FOR");
		if (ipAddress == null) {
			ipAddress = request.getRemoteAddr();
		}
		MDC.put("ip", ipAddress);
		
                //从redis等session存储里面获取userId并填充至MDC
		MDC.put("userId", "get userId from redis");
	}

	@Override
	protected void afterRequest(HttpServletRequest request, String message) {
		MDC.remove("url");
		MDC.remove("ip");
		MDC.remove("userId");
	}
}

异常日志

借助于spring的 @RestControllerAdvice 注解，我们可以提供一个集中式的异常处理方式。

@RestControllerAdvice
@Slf4j
public class ExceptionHandleController {

	@Autowired
	VoBuilder voBuilder;

	@ExceptionHandler(PetstoreException.class)
	public ResponseEntity<BaseRespVo> handlePetstoreException(PetstoreException ex) {
		log.error("Catch PetstoreException: ", ex);
		BaseRespVo respVo;
		String errorInfo = ex.getErrorInfo();
		if (StringUtils.isNotEmpty(errorInfo)) {
			respVo = voBuilder.failWithErrorMsg(errorInfo);
		} else {
			respVo = voBuilder.failWithPetStoreException(ex);
		}
		return new ResponseEntity<>(respVo, HttpStatus.BAD_REQUEST);
	}
}

我们在ExceptionHandleController类中，可以提供针对各种不同的异常处理方式。上面这个例子中，我们捕获了PetstoreException，并将其转换成一个正常的ResponseEntity，而不是返回一段调用方看不太懂的exception stack。

日志搜集和潜在用途

日志的搜集方式和用途紧密相关，一般来讲，日志可能会有两类用途：

• 生产bug分析。这类用途主要涉及到针对整个业务系统历史日志的搜索。
• 系统行为实时分析。这类用途主要设计到针对日志的实时分析，根据分析结果来生成：1）工单；2）BI分析报表；3）业务紧急情况报警等。

对于这两类用途，我们都建议使用filebeat来搜集日志，logstack也可以达到类似效果，但在系统日志量较大情况下，logstack内存消耗巨大，有潜在风险。

日志搜集完毕，针对不同的用途，后续处理方式不同：

• 针对生产bug分析，filebeat将各个微服务的日志搜集好之后，发送给elastic search做分词和存储，然后通过kibana来查询。
• 针对系统行为实时分析，filebeat则可以将日志发送给kafka，我们再针对不同的业务场景来编写不同的分析程序，从kafka获取日志来做实时分析。

由于我们通过log-util项目统一了所有微服务的日志输出格式，同时在日志中添加了url、ip和userid等重要信息，我们可以借助于kibana，在无需任何额外编码的情况下，来统计一些比较有用的系统实时运营信息：

• 系统实时pv/uv统计
• 实时注册用户数
• 注册用户在全国省份分布（详见kibana中根据ip来定位省份的方式）
• 某活动的实时pv/uv

总结

日志处理对研发和运维团队都有一定要求。我们不会从日志中获取到很多短期利益，但长期来讲，对于日志处理体系的投入，会给我们带来巨大的回报。