Avoid parsing request body in DispatcherServlet for "parameters={masked}" log message

[mibollma]

Affects: spring-webmvc-5.3.20 and possibly many more

When having trace logging enabled... e.g.

logging:
  level:
    org.springframework.web: TRACE

and sending a POST request with content type application/x-www-form-urlencoded, the body of the request may be consumed by trace logging and only an empty stream or reader be available for the application.

The reason seems to be this line: https://github.com/spring-projects/spring-framework/blob/main/spring-webmvc/src/main/java/org/springframework/web/servlet/DispatcherServlet.java#L988

Even though it only attempts to check for existence of parameters it also triggers parsing of parameters which seems to consume the request body.

[quaff]

Yes, It will cause request::setCharacterEncoding not working.

[sbrannen]

Potentially related to:

• CommonsMultipartResolver and DEBUG logging lead to empty fileMap in MultipartHttpServletRequest #27350

[rstoyanchev]

This happens transparently when request parameters are accessed. It's how the Servlet API works. We can't prevent it from happening entirely but rather accept that it can happen.

There are two ways form data can be used. For data binding, which is the most convenient way to handle form data, it makes no difference because we bind from request parameters. For @RequestBody, the message converter relies on ServletServerHttpRequest, which reconstitutes the body content from request parameters. So, in most cases you shouldn't notice any of this.

Did you run into a specific issue or just happened to notice?

[mibollma]

Hi @rstoyanchev,

Thanks for your reply.
I came across this issue when trying to forward the raw body content to another network service.

I understand this might happen transparently (e.g. the FormContentFilter implementation has a similar effect on PATCH requests).
However in my opinion it would be better to avoid this to be triggered solely by the log level if possible.
I just wouldn't expect the application behaviour to change when I switch from WARN to DEBUG or TRACE.
What do you think?

[rstoyanchev]

I think it's important to show "masked" for request parameters in order to hint that there is something to see if logging is changed. We could however print the same when the content-type is "application/x-www-form-urlencoded" and thus avoid the getParameters.size() check for that case.