Spring boot - Log every 4xx and 5xx including the request

Question

I am trying to log (WARNING and ERROR with slf4j) every 4xx and 5xx and the request made from the client including headers and the payload.

I also want to log the response which my application responds with, no matter if it's an exception message generated by Spring itself, or a custom message that I've returned from my controller.

These are my controllers that I am using for testing:

@RequestMapping(path = "/throw", method = RequestMethod.GET)
public String Fail(){
    String nul = null;
    nul.toCharArray();
    return "Hello World";
}

@RequestMapping(path = "/null", method = RequestMethod.GET)
public ResponseEntity Custom() {
    return ResponseEntity.notFound().build();
}

I have tried following methods:

ControllerAdvice
Found out that this is only for handling exceptions. I need to handle any 4xx and 5xx response returned from my controller.

Using filter
By using CommonsRequestLoggingFilter I can log the request, including the payload. However, this does not log when an exception is thrown (which is handled by Spring).

Using interceptor
With interceptor I should be able to intercept both incoming and outgoing data with the following code:

private static final Logger log = LoggerFactory.getLogger(RequestInterceptor.class);

class RequestLog {

    public String requestMethod;
    public String requestUri;
    public String requestPayload;
    public String handlerName;
    public String requestParams;

    RequestLog(String requestMethod, String requestUri, String requestPayload, String handlerName, Enumeration<String> requestParams) {
        this.requestMethod = requestMethod;
        this.requestUri = requestUri;
        this.requestPayload = requestPayload;
        this.handlerName = handlerName;

        StringBuilder stringBuilder = new StringBuilder();

        while (requestParams.hasMoreElements()) {
            stringBuilder
                    .append(";")
                    .append(requestParams.nextElement());
        }

        this.requestParams = stringBuilder.toString();
    }
}

class ResponseLog {
    public int responseStatus;
    public String responsePayload;

    public ResponseLog(int responseStatus, String responsePayload) {
        this.responseStatus = responseStatus;
        this.responsePayload = responsePayload;
    }
}

@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
    String requestUri = request.getRequestURI();

    String requestPayload = request.getReader().lines().collect(Collectors.joining(System.lineSeparator()));
    Enumeration<String> requestParams = request.getParameterNames();
    String requestMethod = request.getMethod();
    String handlerName = handler.toString();

    RequestLog requestLog = new RequestLog(requestMethod, requestUri, requestPayload, handlerName, requestParams);
    String serialized = new ObjectMapper().writeValueAsString(requestLog);

    log.info("Incoming request:" + serialized);

    return super.preHandle(request, response, handler);
}

@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws IOException {
    int responseStatus = response.getStatus();

    boolean is4xx = String.valueOf(responseStatus).startsWith("4");
    boolean is5xx = String.valueOf(responseStatus).startsWith("5");

    if (is4xx || is5xx || ex != null) {
        String responseBody = getResponseBody(response);
        ResponseLog responseLog = new ResponseLog(responseStatus, responseBody);

        String serialized = new ObjectMapper().writeValueAsString(responseLog);
        log.warn("Response to last request:" + serialized);
    }
}

private String getResponseBody(HttpServletResponse response) throws UnsupportedEncodingException {
    String responsePayload = "";
    ContentCachingResponseWrapper wrappedRequest = new ContentCachingResponseWrapper(response);

    byte[] responseBuffer = wrappedRequest.getContentAsByteArray();

    if (responseBuffer.length > 0) {
            responsePayload = new String(responseBuffer, 0, responseBuffer.length, wrappedRequest.getCharacterEncoding());
    }

    return responsePayload;
}

When requesting /throw I get following log from the interceptor:

2017-12-11 21:40:15.619  INFO 12220 --- [nio-8080-exec-1] c.e.demo.interceptor.RequestInterceptor  : Incoming request:{"requestMethod":"GET","requestUri":"/throw","requestPayload":"","handlerName":"public java.lang.String com.example.demo.controllers.IndexController.Fail()","requestParams":""}
2017-12-11 21:40:15.635  WARN 12220 --- [nio-8080-exec-1] c.e.demo.interceptor.RequestInterceptor  : Response to last request:{"responseStatus":200,"responsePayload":""}

*stackTrace because of nullpointer...*

2017-12-11 21:40:15.654  INFO 12220 --- [nio-8080-exec-1] c.e.demo.interceptor.RequestInterceptor  : Incoming request:{"requestMethod":"GET","requestUri":"/error","requestPayload":"","handlerName":"public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)","requestParams":""}
2017-12-11 21:40:15.675  WARN 12220 --- [nio-8080-exec-1] c.e.demo.interceptor.RequestInterceptor  : Response to last request:{"responseStatus":500,"responsePayload":""}

With request to /null:

2017-12-11 21:48:14.815  INFO 12220 --- [nio-8080-exec-3] c.e.demo.interceptor.RequestInterceptor  : Incoming request:{"requestMethod":"GET","requestUri":"/null","requestPayload":"","handlerName":"public org.springframework.http.ResponseEntity com.example.demo.controllers.IndexController.Custom()","requestParams":""}
2017-12-11 21:48:14.817  WARN 12220 --- [nio-8080-exec-3] c.e.demo.interceptor.RequestInterceptor  : Response to last request:{"responseStatus":404,"responsePayload":""}

There are two issues here:

• Response body is always null (even though the client receives error response from Spring). How can I fix this?

• Seems like Spring is redirecting to /error when an exception occurs

TL;DR: I need to log the request to my Spring application and the response (including the payload) to client. How can I solve this problem?

Answer 1

Possible solution using both Filter and ControllerAdvice:

Filter:

@Component
public class LogFilter extends OncePerRequestFilter {

    private static final Logger logger = LoggerFactory.getLogger(LogFilter.class);

    private static final int DEFAULT_MAX_PAYLOAD_LENGTH = 1000;

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, final FilterChain filterChain) throws ServletException, IOException {
        ContentCachingRequestWrapper requestWrapper = new ContentCachingRequestWrapper(request);
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(response);

        logRequest(request);
        filterChain.doFilter(requestWrapper, responseWrapper);
        logResponse(responseWrapper);
    }

    private void logResponse(ContentCachingResponseWrapper responseWrapper) {
            String body = "None";
            byte[] buf = responseWrapper.getContentAsByteArray();

            if (buf.length > 0) {
                int length = Math.min(buf.length, DEFAULT_MAX_PAYLOAD_LENGTH);
                try {
                    body = new String(buf, 0, length, responseWrapper.getCharacterEncoding());
                    responseWrapper.copyBodyToResponse();
                } catch (IOException e) {
                    e.printStackTrace();
                }
            }

        int responseStatus = responseWrapper.getStatusCode();

        boolean is4xx = String.valueOf(responseStatus).startsWith("4");
        boolean is5xx = String.valueOf(responseStatus).startsWith("5");

        if(is4xx) logger.warn("Response: statusCode: {}, body: {}", responseStatus, body);
        else if (is5xx) logger.error("Response: statusCode: {}, body: {}", responseStatus, body);
    }

    private void logRequest(HttpServletRequest request) {
        String body = "None";
        try {
            body = request.getReader().lines().collect(Collectors.joining(System.lineSeparator()));
        } catch (IOException e) {
            e.printStackTrace();
        }
        logger.warn("Incoming request {}: {}", request.getRequestURI() , body);
    }

}

ControllerAdvice:

@Order(Ordered.HIGHEST_PRECEDENCE)
@ControllerAdvice
public class GlobalExceptionHandler extends ResponseEntityExceptionHandler {

    @Override
    protected ResponseEntity<Object> handleNoHandlerFoundException(NoHandlerFoundException ex, HttpHeaders headers, HttpStatus status, WebRequest request) {
        CustomException customException = new CustomException(NOT_FOUND, ex.getMessage(), ex.getLocalizedMessage(), ex);
        ex.printStackTrace();
        return new ResponseEntity<>(customException, customException.getStatus());
    }


    @ResponseBody
    @ExceptionHandler(Exception.class)
    protected ResponseEntity<Object> handleSpringExceptions(HttpServletRequest request, Exception ex) {
        CustomException customException = new CustomException(INTERNAL_SERVER_ERROR, ex.getMessage(), ex.getLocalizedMessage(), ex);
        ex.printStackTrace();
        return new ResponseEntity<>(customException, customException.getStatus());

    }


    @Override
    protected ResponseEntity<Object> handleExceptionInternal(Exception ex, Object body, HttpHeaders headers, HttpStatus status, WebRequest request) {
        CustomException customException = new CustomException(INTERNAL_SERVER_ERROR, ex.getMessage(),ex.getLocalizedMessage(), ex);
        ex.printStackTrace();
        return new ResponseEntity<>(customException, customException.getStatus());
    }
}

The filter can log any request and response that we have handled inside the controller, however the response payload seems to be always empty when an exception is thrown (because Spring handles it and creates a custom message). I am not sure how this works under the hood, but I managed to overcome this problem by using ControllerAdvice in addition (the response is passed through the filter...). Now I can log any 4xx and 5xx properly. If someone has better solution I will accept that instead.

Note: CustomException is just a class with fields that I want to send to the client.

public class CustomException{

    public String timestamp;
    public HttpStatus status;
    public String exceptionMessage;
    public String exceptionType;
    public String messageEn;
    public String messageNo;

    ...
}