[FIXED] log request body string in RestController ExceptionHandler

Issue

• the final goal:

log request body string in RestController's @ExceptionHandler.

• explanations

By default, when request is invalid json, springboot throws a HttpMessageNotReadableException, but the message is very generic, and not including specific request body. This makes investigating hard. On the other hand, I can log every request string using Filters, but this way logs will be flooded with too many success ones. I only want to log the request when it is invalid. What I really want is in @ExceptionHandler I'll get that string(previously got somewhere) and log as ERROR.

To illustrate the problem, I created a demo project in github.

• the controller:

@RestController
public class GreetController {
    protected static final Logger log = LogManager.getLogger();

    @PostMapping("/")
    public String greet(@RequestBody final WelcomeMessage msg) {
        // if controller successfully returned (valid request),
        // then don't want any request body logged
        return "Hello " + msg.from;
    }

    @ExceptionHandler({HttpMessageNotReadableException.class})
    public String addStudent(HttpMessageNotReadableException e) {
        // this is what I really want!
        log.error("{the request body string got somewhere, such as Filters }"); 
        return "greeting from @ExceptionHandler";
    }
}

• the client

  1. valid request curl -H "Content-Type: application/json" http://localhost:8080 --data '{"from":"jim","message":"nice to meet you!"}'

  2. invalid request(invalid json) curl -H "Content-Type: application/json" http://localhost:8080 --data '{"from":"jim","message""nice to meet you!"}'

I once tried HandlerInterceptor but will get some error like

'java.lang.IllegalStateException: Cannot call getInputStream() after getReader() has already been called for the current request'.

after some searching 1 2, I decided to use Filter with ContentCachingRequestWrapper.

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        final HttpServletRequest httpServletRequest = (HttpServletRequest) request;
        ContentCachingRequestWrapper cachedRequest = new ContentCachingRequestWrapper(httpServletRequest);
        chain.doFilter(cachedRequest, response);
        String requestBody = IOUtils.toString(cachedRequest.getContentAsByteArray(), cachedRequest.getCharacterEncoding());
        log.info(requestBody);
    }

This code works well except that the log is after the RestController. if I change the order:

        String requestBody = IOUtils.toString(cachedRequest.getReader());
        log.info(requestBody);
        chain.doFilter(cachedRequest, response);

Works for invalid request, but when request is valid, got following exception:

com.example.demo.GreetController : Required request body is missing: public java.lang.String com.example.demo.GreetController.greet(com.example.demo.WelcomeMessage)

I also tried getContentAsByteArray, getInputStream and getReader methods since some tutorials say the framework checks for specific method call.

Tried CommonsRequestLoggingFilter as suggested by @M. Deinum.

But all in vain.

Now I'm bit confused. Can anyone explain the executing order of RestController and Filter, when request is valid and invalid? Is there any easier way(less code) to achive my ultimate goal? thanks!

I'm using springboot 2.6.3, jdk11.

Solution

1. Create a filter that wraps your request in a ContentCachingRequestWrapper (nothing more nothing less).

2. Use the HttpServletRequest as a parameter in your exception handling method as an argument

3. Check if instance of ContentCachingRequestWrapper

4. Use the getContentAsByteArray to get the content.

Something like this.

public class CachingFilter extends OncePerRequestFilter {

protected abstract void doFilterInternal(
            HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
            throws ServletException, IOException {

  filterChain.doFilter(new ContentCachingRequestWrapper(request), new ContentCachingResponseWrapper(response));
}

NOTE: I wrapped the response as well, just in case you wanted that as well.

Now in your exception handling method use the HttpServletRequest as an argument and use that to your advantage.

@ExceptionHandler({HttpMessageNotReadableException.class})
public String addStudent(HttpMessageNotReadableException e, HttpServletRequest req) {
  if (req instanceof ContentCachingRequestWrapper) {
    ContentCachingRequestWrapper wrapper = (ContentCachingRequestWrapper) req;
    log.error(new String(wrapper.getContentAsByteArray()));
  }
  return "greeting from @ExceptionHandler";
}

It could be that multiple filters add a wrapper to the HttpServletRequest so you might need to iterate over those wrappers, you could also use this

private Optional<ContentCachingRequestWrapper> findWrapper(ServletRequest req) {
    ServletRequest reqToUse = req;
    while (reqToUse instanceof ServletRequestWrapper) {
        if (reqToUse instanceof ContentCachingRequestWrapper) {
            return Optional.of((ContentCachingRequestWrapper) reqToUse);
        }
        reqToUse = ((ServletRequestWrapper) reqToUse).getRequest();
    }
    return Optional.empty();
}

Your exception handler would then look something like this

@ExceptionHandler({HttpMessageNotReadableException.class})
public String addStudent(HttpMessageNotReadableException e, HttpServletRequest req) {
  Optional<ContentCachingRequestWrapper) wrapper = findWrapper(req);
  wrapper.ifPresent(it -> log.error(new String(it.getContentAsByteArray())));
 
  return "greeting from @ExceptionHandler";
}

But that might depend on your filter order and if there are multiple filters adding wrappers.

Answered By - M. Deinum
Answer Checked By - Robin (JavaFixing Admin)