HttpLogFormatter makes multipart requests unprocessable in Spring

[thinkgruen]

When trying to log a multipart request with a HttpLogFormatter the request body is logged correctly, but when the request eventually reaches Spring's MultipartResolver, it cannot be resolved anymore and a MissingServletRequestPartException is thrown. The behavior in Spring seems similar to #637, but it is reproducible on the latest Logbook version 2.14.0.

Description

I encountered this behavior when I tried to log the body of a multipart request with Logbook. By default, there is a BodyReplacer in place which just replaces the body with <multipart>, so I disabled the existing RequestFilter. Requests would then be logged inside of a custom Sink which uses the JsonHttpLogFormatter to format the request, but it is also reproducible with the DefaultHttpLogFormatter.

Code has been ported from Kotlin to Java for the sake of this report - I hope it's compilable, but at the very least it should be understandable.

class CustomSink extends Sink {
    private HttpLogFormatter jsonHttpLogFormatter = JsonHttpLogFormatter(); // DefaultHttpLogFormatter has the same issue

    @Override
    void write(Precorrelation precorrelation, HttpRequest request) {
        RawJsonAppendingMarker marker =  new RawJsonAppendingMarker("http", jsonHttpLogFormatter.format(precorrelation, request));
        String message = request.getMethod() + request.getRequestUri();
        log.info(marker, message);
    }
   ...
}

When I instead just put a static String inside the RawJsonAppendingMarker, the request comes out intact, so the issue seems to be related to calling the HttpLogFormatter.

Expected Behavior

When formatting a request with a HttpLogFormatter, the request should afterwards still work as expected when it reaches the controller.

Actual Behavior

When formatting a request with a HttpLogFormatter, Spring will not be able to resolve the request afterwards and throw an exception.

Possible Fix

Not sure if that really counts a fix, it's more of a nice-to-have. What I ended up doing to solve the problem is writing my own HandlerInterceptor which logs the request (which is a javax.servlet.http.HttpServletRequest here) as the individual parts. If the request would be resolved by Logbook, maybe instead of being restricted to just logging the body, the user could be able to log individual parts through Filters (e.g. log text, but don't log files).

Steps to Reproduce

either

1. checkout the repo and run the requests mentioned in the readme

or

1. create a simple RestController in Spring which takes a multipart request through POST e.g. public void create(@RequestPart("text") String text) { }
2. disable the default RequestFilter by setting RequestFilter.none() to avoid replacement of the body.
3. create a custom sink for logging similar to the one mentioned above.
4. call HttpLogFormatter.format on the request and precorrelation
5. send a simple multipart request, e.g.

POST http://localhost:8080/test
Accept: application/vnd.api+json
Content-Type: multipart/form-data; boundary=abc

--abc
Content-Disposition: form-data; name="text"
Content-Type: text/plain

Hello World
--abc--

Context

I was unable to log the body of the multipart request in order to understand whether or not it was correctly formatted and had the correct headers and parts.

Your Environment

• Version used: 2.14.0
• Link to your project: HttpLogFormatterDemo

[whiskeysierra]

so the issue seems to be related to calling the HttpLogFormatter.

My guess would be that we're consuming the request body incorrectly or rather that we don't preserve the original one.
I'd advice to dig into Spring (w/ a debugger) and figure out what the body actually contains. Is it empty? Is it incorrectly cut short, etc.?

[danilproger]

My guess would be that we're consuming the request body incorrectly or rather that we don't preserve the original one. I'd advice to dig into Spring (w/ a debugger) and figure out what the body actually contains. Is it empty? Is it incorrectly cut short, etc.?

The problem is that Spring resolves multipart arguments with javax.servlet.http.HttpServletRequest#getParts()

org.zalando.logbook.servlet.RemoteRequest contains inside org.apache.catalina.connector.RequestFacade, which contains inside org.apache.catalina.connector.Request
When logbook logs incoming request, org.zalando.logbook.servlet.RemoteRequest read all data from org.apache.catalina.connector.Request#inputStream and store it in own buffer.
In case incomin request is Json Spring gets this buffer by org.zalando.logbook.servlet.RemoteRequest#getInputStream(), but in case multipart request Spring doesn't use overrode org.zalando.logbook.servlet.RemoteRequest#getInputStream(), Spring uses org.zalando.logbook.servlet.RemoteRequest#getParts(), which delegates to org.apache.catalina.connector.RequestFacade#getParts(), which delegates to org.apache.catalina.connector.Request#getParts(), which uses its own InputStream (this stream has already been read by logbook)

Spring Boot version: 2.5.1
LogBook starter: 2.14.0

@Bean
public Logbook logbook() {
    return Logbook.builder()
            .bodyFilter(none())
            .requestFilter(none())
            .build();
}

[github-actions]

In order to prioritize the support for Logbook, we would like to check whether the old issues are still relevant.
This issue has not been updated for over six months.

• Please check if it is still relevant in latest version of the Logbook.
• If so, please add a descriptive comment to keep the issue open.
• Otherwise, the issue will automatically be closed after a week.

[github-actions]

This issue has automatically been closed due to no activities. If the issue still exists in the latest version of the Logbook, please feel free to re-open it.