UnsupportedOperationException in LogbookHttpRequestInterceptor with Spring Boot 3.2.0 and Apache Http Client 5

[marcindabrowski]

Description

After upgrade to Spring Boot 3.2.0 (Spring Framework 6.1.1) I'm getting this exception:

Caused by: java.lang.UnsupportedOperationException: null
	at org.springframework.http.client.HttpComponentsClientHttpRequest$BodyEntity.getContent(HttpComponentsClientHttpRequest.java:146) ~[spring-web-6.1.1.jar:6.1.1]
	at org.apache.hc.client5.http.impl.classic.RequestEntityProxy.getContent(RequestEntityProxy.java:100) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.core5.http.io.entity.EntityUtils.toByteArray(EntityUtils.java:135) ~[httpcore5-5.2.3.jar:5.2.3]
	at org.zalando.logbook.httpclient5.HttpEntities.copy(HttpEntities.java:23) ~[logbook-httpclient5-3.6.0.jar:na]
	at org.zalando.logbook.httpclient5.LocalRequest$Offering.buffer(LocalRequest.java:86) ~[logbook-httpclient5-3.6.0.jar:na]
	at org.zalando.logbook.httpclient5.LocalRequest.lambda$getBody$3(LocalRequest.java:251) ~[logbook-httpclient5-3.6.0.jar:na]
	at org.zalando.fauxpas.ThrowingFunction.apply(ThrowingFunction.java:19) ~[faux-pas-0.9.0.jar:na]
	at java.base/java.util.concurrent.atomic.AtomicReference.updateAndGet(AtomicReference.java:210) ~[na:na]
	at org.zalando.logbook.httpclient5.LocalRequest.getBody(LocalRequest.java:250) ~[logbook-httpclient5-3.6.0.jar:na]
	at org.zalando.logbook.HttpMessage.getBodyAsString(HttpMessage.java:44) ~[logbook-api-3.6.0.jar:na]
	at org.zalando.logbook.ForwardingHttpMessage.getBodyAsString(ForwardingHttpMessage.java:47) ~[logbook-api-3.6.0.jar:na]
	at org.zalando.logbook.core.FilteredHttpRequest.getBodyAsString(FilteredHttpRequest.java:92) ~[logbook-core-3.6.0.jar:na]
	at org.zalando.logbook.json.JsonHttpLogFormatter.prepareBody(JsonHttpLogFormatter.java:65) ~[logbook-json-3.6.0.jar:na]
	at org.zalando.logbook.StructuredHttpLogFormatter.prepare(StructuredHttpLogFormatter.java:72) ~[logbook-api-3.6.0.jar:na]
	at org.zalando.logbook.StructuredHttpLogFormatter.format(StructuredHttpLogFormatter.java:20) ~[logbook-api-3.6.0.jar:na]
	at org.zalando.logbook.core.DefaultSink.write(DefaultSink.java:27) ~[logbook-core-3.6.0.jar:na]
	at org.zalando.logbook.Strategy.write(Strategy.java:69) ~[logbook-api-3.6.0.jar:na]
	at org.zalando.logbook.core.DefaultLogbook$1.write(DefaultLogbook.java:60) ~[logbook-core-3.6.0.jar:na]
	at org.zalando.logbook.httpclient5.LogbookHttpRequestInterceptor.process(LogbookHttpRequestInterceptor.java:28) ~[logbook-httpclient5-3.6.0.jar:na]
	at org.apache.hc.core5.http.protocol.DefaultHttpProcessor.process(DefaultHttpProcessor.java:107) ~[httpcore5-5.2.3.jar:5.2.3]
	at org.apache.hc.client5.http.impl.classic.MainClientExec.execute(MainClientExec.java:114) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ConnectExec.execute(ConnectExec.java:188) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ProtocolExec.execute(ProtocolExec.java:192) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.HttpRequestRetryExec.execute(HttpRequestRetryExec.java:96) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ContentCompressionExec.execute(ContentCompressionExec.java:152) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.RedirectExec.execute(RedirectExec.java:115) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.InternalHttpClient.doExecute(InternalHttpClient.java:170) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:87) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:55) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.apache.hc.client5.http.classic.HttpClient.executeOpen(HttpClient.java:183) ~[httpclient5-5.2.1.jar:5.2.1]
	at org.springframework.http.client.HttpComponentsClientHttpRequest.executeInternal(HttpComponentsClientHttpRequest.java:95) ~[spring-web-6.1.1.jar:6.1.1]
	at org.springframework.http.client.AbstractStreamingClientHttpRequest.executeInternal(AbstractStreamingClientHttpRequest.java:70) ~[spring-web-6.1.1.jar:6.1.1]
	at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:66) ~[spring-web-6.1.1.jar:6.1.1]
	at org.springframework.http.client.InterceptingClientHttpRequest$InterceptingRequestExecution.execute(InterceptingClientHttpRequest.java:101) ~[spring-web-6.1.1.jar:6.1.1]

This is because HttpComponentsClientHttpRequest has been reworked in Spring Framework 6.1.

Expected Behavior

Zalando request interceptor shouldn't fail when there is no body to intercept.
But I think some more work should be done, because with previous version of Spring Framework it was working.

Steps to Reproduce

1. Add LogbookHttpRequestInterceptor to the HttpClientBuilder via addRequestInterceptorLast
2. Create Spring RestTemplate with built HttpClient
3. Make a POST request with Base64 encoded body, with text/plain content type

Your Environment

• Version used:
  • Logbook: 3.6.0
  • Spring Boot: 3.2.0
  • Apache Http Client: 5.2.1

[marcindabrowski]

I think that good workaround for this would be putting everything in LogbookHttpRequestInterceptor.process method with try catch and ignore this error.
Interceptor shouldn't fail the whole request in case the work it did failed.
It is more important to make a call than log its body.
WDYT?

[marcindabrowski]

I mean something like that:

    try {
        LocalRequest request = new LocalRequest(httpRequest, entity);
        final ResponseProcessingStage stage = logbook.process(request).write();
        context.setAttribute(Attributes.STAGE, stage);
      } catch (HttpException | IOException exception) {
        throw exception;
      } catch (Exception ignored) {
      }
    }

[kasmarian]

Thank you for reporting @marcindabrowski, I believe the fix from #1701 should address the root cause here. I'll be part of 3.7.0. I'll close the issue so that it gets to the release log, bug feel free to re-open it, if it's not fully addressed.

[marcindabrowski]

OK @kasmarian. Thanks for the fix.

But I think that you should reconsider how your interceptors are working.
Since they are not affecting the request and responses, the failure in your code shouldn't affect the HTTP communication.
So it would be nice if you catch all Exceptions generated by your code like I suggested.

And I'm not sure if your fix will work.
There is a repeatable, and I think that you can use writeTo only if it is returning true.

[kasmarian]

And I'm not sure if your fix will work.

I also had this concern at first, but as Logbook copies the entity and then sets it back in the original Request or Response, repeatable is not a hard requirement here. But, of course, it all comes with the cost of additional memory allocation to store the buffered value.

As per wrapping all interceptors in try-catch, it's something we could discuss further in a separate issue, maybe? As not the initial maintainer of the project, I'm wondering now why this was not implemented in the first place. Also, if we do it for httpclient5, it would make sense to be consistent and also have this for other clients.

[marcindabrowski]

As per wrapping all interceptors in try-catch, it's something a could discuss further in a separate issue, maybe? As not the initial maintainer of the project, I'm wondering now why this was not implemented in the first place. Also, if we do it for httpclient5, it would make sense to be consistent and also have this for other clients.

I've created new feature request: #1702