SpringBoot实践之---记录HTTP请求日志

SpringBoot记录HTTP请求日志

1、需求解读

需求：

框架需要记录每一个HTTP请求的信息，包括请求路径、请求参数、响应状态、返回参数、请求耗时等信息。

需求解读：

Springboot框架提供了多种方式来拦截HTTP请求和响应，只要能够获取到对应的request和response，就可以通过相应的API来获取所需要的信息。

需要注意的是，请求参数可以分为两部分，一部分是GET请求时，请求参数通过URL拼接的方式传到后端，还有一部分是通过POST请求提交Json格式的参数，这种参数会放在request body中传到后端，通过request.getParameterMap是无法获取到的。

2、Spring Boot Actuator

2.1、介绍和使用

Spring Boot Actuator 的关键特性是在应用程序里提供众多 Web 接口，通过它们了解应用程序运行时的内部状况，且能监控和度量Spring Boot 应用程序。

要使用Spring Boot Actuator，首先需要引入依赖包

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>

其次需要开启端口访问权限

management.endpoints.web.exposure.include=httptrace

Spring Boot 应用启动时可以看到控制台的信息如下，代表开启了该端口的访问

image-20180829094800774

浏览器访问/acutator/httptrace就能看到HTTP的请求情况

image-20180829100827244

2.2、默认的HttpTraceRepository

Spring Boot Actuator 默认会把最近100次的HTTP请求记录到内存中，对应的实现类是InMemoryHttpTraceRepository

public class InMemoryHttpTraceRepository implements HttpTraceRepository {

    private int capacity = 100;

    private boolean reverse = true;

    private final List<HttpTrace> traces = new LinkedList<>();

    /**
     * Flag to say that the repository lists traces in reverse order.
     * @param reverse flag value (default true)
     */
    public void setReverse(boolean reverse) {
        synchronized (this.traces) {
            this.reverse = reverse;
        }
    }

    /**
     * Set the capacity of the in-memory repository.
     * @param capacity the capacity
     */
    public void setCapacity(int capacity) {
        synchronized (this.traces) {
            this.capacity = capacity;
        }
    }

    @Override
    public List<HttpTrace> findAll() {
        synchronized (this.traces) {
            return Collections.unmodifiableList(new ArrayList<>(this.traces));
        }
    }

    @Override
    public void add(HttpTrace trace) {
        synchronized (this.traces) {
            while (this.traces.size() >= this.capacity) {
                this.traces.remove(this.reverse ? this.capacity - 1 : 0);
            }
            if (this.reverse) {
                this.traces.add(0, trace);
            }
            else {
                this.traces.add(trace);
            }
        }
    }

}

这里add方法使用了synchronized，默认只存储最近到100条，如果并发量大的话，性能会有所影响

2.3、自定义HttpTraceRepository

我们可以自己实现HttpTraceRepository这个接口，重写add方法并记录trace日志

@Slf4j
public class RemoteHttpTraceRepository implements HttpTraceRepository {

    @Override
    public List<HttpTrace> findAll() {
        return Collections.emptyList();
    }

    @Override
    public void add(HttpTrace trace) {
        String path = trace.getRequest().getUri().getPath();
        String queryPara = trace.getRequest().getUri().getQuery();
        String queryParaRaw = trace.getRequest().getUri().getRawQuery();
        String method = trace.getRequest().getMethod();
        long timeTaken = trace.getTimeTaken();
        String time = trace.getTimestamp().toString();
        log.info("path: {}, queryPara: {}, queryParaRaw: {}, timeTaken: {}, time: {}, method: {}", path, queryPara, queryParaRaw,
                timeTaken, time, method);
    }
}

将该实现类注册到Spring的容器中

@Configuration
@ConditionalOnWebApplication
@ConditionalOnProperty(prefix = "management.trace.http", name = "enabled", matchIfMissing = true)
@EnableConfigurationProperties(HttpTraceProperties.class)
@AutoConfigureBefore(HttpTraceAutoConfiguration.class)
public class TraceConfig {

    @Bean
    @ConditionalOnMissingBean(HttpTraceRepository.class)
    public RemoteHttpTraceRepository traceRepository() {
        return new RemoteHttpTraceRepository();
    }
}

2.4、缺点

目前这种实现可以记录到请求路径、请求耗时、响应状态、请求Header、响应Header等信息，没有办法记录请求参数和响应参数。有人在github上提了个issue，作者回复说这样的设计是为了兼容Spring MVC和WebFlux两种模式，具体可以参考：https://github.com/spring-projects/spring-boot/issues/12953#issuecomment-383830749

3、Spring Boot Filter

3.1、HttpTraceFilter

既然httptrace无法满足现有的需求，我们可以顺着InMemoryHttpTraceRepository这个默认实现往上找，看看谁调用了这个实现类。结果可以发现是被HttpTraceFilter这个拦截器（servlet模式下）进行了调用。

public class HttpTraceFilter extends OncePerRequestFilter implements Ordered {

    // Not LOWEST_PRECEDENCE, but near the end, so it has a good chance of catching all
    // enriched headers, but users can add stuff after this if they want to
    private int order = Ordered.LOWEST_PRECEDENCE - 10;

    private final HttpTraceRepository repository;

    private final HttpExchangeTracer tracer;

    /**
     * Create a new {@link HttpTraceFilter} instance.
     * @param repository the trace repository
     * @param tracer used to trace exchanges
     */
    public HttpTraceFilter(HttpTraceRepository repository, HttpExchangeTracer tracer) {
        this.repository = repository;
        this.tracer = tracer;
    }

    @Override
    public int getOrder() {
        return this.order;
    }

    public void setOrder(int order) {
        this.order = order;
    }

    @Override
    protected void doFilterInternal(HttpServletRequest request,
            HttpServletResponse response, FilterChain filterChain)
            throws ServletException, IOException {
        if (!isRequestValid(request)) {
            filterChain.doFilter(request, response);
            return;
        }
        TraceableHttpServletRequest traceableRequest = new TraceableHttpServletRequest(
                request);
        HttpTrace trace = this.tracer.receivedRequest(traceableRequest);
        int status = HttpStatus.INTERNAL_SERVER_ERROR.value();
        try {
            filterChain.doFilter(request, response);
            status = response.getStatus();
        }
        finally {
            TraceableHttpServletResponse traceableResponse = new TraceableHttpServletResponse(
                    (status != response.getStatus())
                            ? new CustomStatusResponseWrapper(response, status)
                            : response);
            this.tracer.sendingResponse(trace, traceableResponse,
                    request::getUserPrincipal, () -> getSessionId(request));
            this.repository.add(trace);
        }
    }
    ...省略部分代码
}

tracer中会记录HTTP的请求耗时

3.2、自定义HttpTraceFilter获取请求参数

在HttpTraceFilter继承了OncePerRequestFilter，我们可以仿照这个过滤器，定义自己的过滤器去继承OncePerRequestFilter，在doFilterInternal这个方法中获取到HttpServletRequest，HttpServletResponse，这样就可以获取到对应的请求参数和返回参数了。

GET请求时的参数可以通过以下方式进行获取：

String parameterMap = request.getParameterMap()

POST请求会将参数放入request body中，用以下方式进行获取：

String requestBody = IOUtils.toString(request.getInputStream(), Charsets.UTF_8);

很不幸，代码运行会抛出异常

image-20180829111619987

原因是：body里字符的传输是通过HttpServletRequest中的字节流getInputStream()获得的；而这个字节流在读取了一次之后就不复存在了。

解决方法：利用ContentCachingRequestWrapper对HttpServletRequest的请求包一层，该类会将inputstream中的copy一份到自己的字节数组中，这样就不会报错了。读取完body后，需要调用

wrappedResponse.copyBodyToResponse();

将请求还原。

3.3、完整的自定义HttpTraceFilter

@Slf4j
public class HttpTraceLogFilter extends OncePerRequestFilter implements Ordered {

    private static final String NEED_TRACE_PATH_PREFIX = "/api";
    private static final String IGNORE_CONTENT_TYPE = "multipart/form-data";

    private final MeterRegistry registry;

    public HttpTraceLogFilter(MeterRegistry registry) {
        this.registry = registry;
    }


    @Override
    public int getOrder() {
        return Ordered.LOWEST_PRECEDENCE - 10;
    }

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
            throws ServletException, IOException {
        if (!isRequestValid(request)) {
            filterChain.doFilter(request, response);
            return;
        }
        if (!(request instanceof ContentCachingRequestWrapper)) {
            request = new ContentCachingRequestWrapper(request);
        }
        if (!(response instanceof ContentCachingResponseWrapper)) {
            response = new ContentCachingResponseWrapper(response);
        }
        int status = HttpStatus.INTERNAL_SERVER_ERROR.value();
        long startTime = System.currentTimeMillis();
        try {
            filterChain.doFilter(request, response);
            status = response.getStatus();
        } finally {
            String path = request.getRequestURI();
            if (path.startsWith(NEED_TRACE_PATH_PREFIX) && !Objects.equals(IGNORE_CONTENT_TYPE, request.getContentType())) {

                String requestBody = IOUtils.toString(request.getInputStream(), Charsets.UTF_8);
                log.info(requestBody);
                //1. 记录日志
                HttpTraceLog traceLog = new HttpTraceLog();
                traceLog.setPath(path);
                traceLog.setMethod(request.getMethod());
                long latency = System.currentTimeMillis() - startTime;
                traceLog.setTimeTaken(latency);
                traceLog.setTime(LocalDateTime.now().toString());
                traceLog.setParameterMap(JsonMapper.INSTANCE.toJson(request.getParameterMap()));
                traceLog.setStatus(status);
                traceLog.setRequestBody(getRequestBody(request));
                traceLog.setResponseBody(getResponseBody(response));
                log.info("Http trace log: {}", JsonMapper.INSTANCE.toJson(traceLog));
            }
            updateResponse(response);
        }
    }

    private boolean isRequestValid(HttpServletRequest request) {
        try {
            new URI(request.getRequestURL().toString());
            return true;
        } catch (URISyntaxException ex) {
            return false;
        }
    }

    private String getRequestBody(HttpServletRequest request) {
        String requestBody = "";
        ContentCachingRequestWrapper wrapper = WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class);
        if (wrapper != null) {
            try {
                requestBody = IOUtils.toString(wrapper.getContentAsByteArray(), wrapper.getCharacterEncoding());
            } catch (IOException e) {
                // NOOP
            }
        }
        return requestBody;
    }

    private String getResponseBody(HttpServletResponse response) {
        String responseBody = "";
        ContentCachingResponseWrapper wrapper = WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        if (wrapper != null) {
            try {
                responseBody = IOUtils.toString(wrapper.getContentAsByteArray(), wrapper.getCharacterEncoding());
            } catch (IOException e) {
                // NOOP
            }
        }
        return responseBody;
    }

    private void updateResponse(HttpServletResponse response) throws IOException {
        ContentCachingResponseWrapper responseWrapper = WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        Objects.requireNonNull(responseWrapper).copyBodyToResponse();
    }


    @Data
    private static class HttpTraceLog {

        private String path;
        private String parameterMap;
        private String method;
        private Long timeTaken;
        private String time;
        private Integer status;
        private String requestBody;
        private String responseBody;
    }


}

​@Configuration
@ConditionalOnWebApplication
public class HttpTraceConfiguration {

    @ConditionalOnWebApplication(type = Type.SERVLET)
    static class ServletTraceFilterConfiguration {

        @Bean
        public HttpTraceLogFilter httpTraceLogFilter(MeterRegistry registry) {
            return new HttpTraceLogFilter(registry);
        }

    }

}

4、Spring AOP

使用Spring AOP的方式需要自定义注解，并且每个controller的方法上都需要加上这个注解才能进行拦截，对业务代码对编写有强制性的要求，所以没有采用这种方式。