[Spring Boot2] Access log trace

If I wanna trace access logs, I usually configured in nginx and tomcat, only print business logs in java api.

In this case you need check both nginx logs and api logs in monitor tools like kinaba, it’s a little bit inconvenience, so I wanna also add request access logs in api side.

Generally we can create a new interceptor which extends OncePerRequestFilter, it will intercept all the requests and you can define your own logic inside. But it maybe a little complex in POST request, if you intercept and handle POST request body, when the request arrived controller, the request body will be null, because you have read the stream in your interceptor, so you have to create another request wrapper which extends HttpServletRequestWrapper, then pass the request wrapper to the filter chain.

Actually we can make it in more easily way according to spring boot’s component:  spring-boot-starter-actuator. actuator component contains lots of useful endpoints like health check/shutdown hook/metrics and so on. There are also a class named HttpTraceRepository, which will record recent access logs. Specific documentation please go to Spring Boot Actuator.

I extended HttpTraceRepository and combined with Aspectj, which will print both request and parameters to log, and extract it into framework module, any project could include it very easily.

Printed logs as below:

2018-05-03 06:56:10,651 - [http-nio-8080-exec-6] - [INFO ] - [xxx.xxx.xxx.api.framework.aop.LogHttpTraceRepository.around(line:47)] - RequestParam:[1,null,null], ResponseEntity:{"timestamp":1525330570651,"status":200,"error":null,"exception":null,"message":"success","path":null,"method":null,"data":{"experimentId":1,"results":[]}}
2018-05-03 06:56:10,654 - [http-nio-8080-exec-6] - [INFO ] - [xxx.xxx.xxx.api.framework.aop.LogHttpTraceRepository.add(line:32)] - GET http://localhost:8080/v1/employees?deparment_id=1 - 200 - 15ms
2018-05-03 06:56:10,655 - [http-nio-8080-exec-6] - [INFO ] - [xxx.xxx.xxx.api.framework.aop.LogHttpTraceRepository.add(line:34)] - RequestHeader:{host=[localhost:8080], connection=[keep-alive], cache-control=[no-cache], user-agent=[Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 Safari/537.36], postman-token=[e9a16988-64a6-1363-bdbd-6b63fe40da5c], accept=[*/*], dnt=[1], accept-encoding=[gzip, deflate, br], accept-language=[zh-CN,zh;q=0.9,en;q=0.8,ja;q=0.7,zh-TW;q=0.6]}, ResponseHeader:{Content-Type=[application/json;charset=UTF-8], Transfer-Encoding=[chunked], Content-Encoding=[gzip], Vary=[Accept-Encoding], Date=[Thu, 03 May 2018 06:56:10 GMT]}


LogHttpTraceRepository:

@Aspect
@Component
@Slf4j
public class LogHttpTraceRepository implements HttpTraceRepository {

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

    @Override
    public void add(HttpTrace trace) {
        HttpTrace.Request request = trace.getRequest();
        HttpTrace.Response response = trace.getResponse();
        long timeToken = trace.getTimeTaken();

        log.info("{} {} - {} - {}ms", request.getMethod(), request.getUri(),
                response.getStatus(), timeToken);
        log.info("RequestHeader:{}, ResponseHeader:{}", request.getHeaders(), response.getHeaders());
    }

    @Around("execution(* com.xxx..controller.*.*(..))")
    Object around(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        StringBuilder logBuilder = new StringBuilder();
        Optional<String> requestOptional = JsonUtils.toJson(proceedingJoinPoint.getArgs());
        requestOptional.ifPresent(request -> logBuilder.append("RequestParam:").append(request).append(", "));

        Object response = proceedingJoinPoint.proceed();
        Optional<String> responseOptional = JsonUtils.toJson(response);
        responseOptional.ifPresent(res -> logBuilder.append("ResponseEntity:").append(res));

        log.info(logBuilder.toString());
        return response;
    }
}