How to measure request time in Spring Boot including status 404?

user_2365727 0
Viewed 296

I would to measure processing time for each HTTP request in Spring Boot application (like access.log).

For example I could implement GenericFilterBean:

doFilter(ServletRequest request, ServletResponse response, FilterChain chain){
  long start = now();
  try {
    chain.doFilter(request, response);
  } finally {
    long stop = now();
    print(stop - start);
  }
}

If I implement @RestControllerAdvice to handle every exception, then measuring time in doFilter will work good enough (I know there could be issue with filter exceptions).

But there is a problem with 404, because the request does no touch any @RestController and request does not reach @RestControllerAdvice. Request will pass through GenericFilterBean and next Tomcat will dispatch the request to ErrorController with status 404.

For me request is completed when ErrorController is completed. But I do not know how to track the request from entry point to exit point when request is dispatched as error

spring-boot
1 Answers

To keep track of all the requests including 404 implement HandlerInterceptor interface and log the time in afterCompletion method:

public class ApiLogger implements HandlerInterceptor {
    private static final Logger logger = LoggerFactory.getLogger(ApiLogger.class);

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        String requestId = UUID.randomUUID().toString();
        request.setAttribute("requestId", requestId);
        request.setAttribute("startTime", System.currentTimeMillis());
        logger.info("Request start: request id: {}, request path: {}", requestId, request.getRequestURI());
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) {
        String requestId = (String)request.getAttribute("requestId");
        long executeTime = System.currentTimeMillis() - (Long)request.getAttribute("startTime");
        logger.info("Request end: request id: {}, request path: {}, request status: {}, request time: {}", requestId,
                request.getRequestURI(), response.getStatus(), executeTime);
    }
}

Output for 404:

No mapping for GET /api/invalid Request start: request id: e7a6dfe4-b119-4b1d-8f79-c00564232330, request path: /error Request end: request id: e7a6dfe4-b119-4b1d-8f79-c00564232330, request path: /error, request status: 404, request time: 2

Output for 200:

Request start: request id: 9fc1b80d-45e9-41cd-aa72-5871ce0267a4, request path: /api/notification Request end: request id: 9fc1b80d-45e9-41cd-aa72-5871ce0267a4, request path: /api/notification, request status: 200, request time: 2

user_32880410
Related