RestTemplate returns NULL data while using LogbookClientHttpRequestInterceptor

[sergkunz]

Description

Hi, I'm getting NULL data while using LogbookClientHttpRequestInterceptor

Example (Kotlin):

        val restTemplate = RestTemplate()
        val interceptor = LogbookClientHttpRequestInterceptor(logbook)
        restTemplate.interceptors.add(interceptor)
        val response: ResponseEntity<String> = restTemplate.getForEntity("http://localhost:8090/test", String::class.java)
        println(response.body.toString()) // prints null

response.body returns NULL

If I remove LogbookClientHttpRequestInterceptor, response.body returns non-null data

        val restTemplate = RestTemplate()
        val response: ResponseEntity<String> = restTemplate.getForEntity("http://localhost:8090/test", String::class.java)
        println(response.body.toString()) // prints non-null data

Is it a bug or I am doing something wrong?

Expected Behavior

RestTemplate should return non-null data while using LogbookClientHttpRequestInterceptor

Actual Behavior

RestTemplate returns NULL data

Possible Fix

Steps to Reproduce

See example above

Context

Your Environment

• Version used: logbook v2.5.0 (org.zalando:logbook-spring-boot-starter:2.5.0), Spring boot v2.3.0.RELEASE, Kotlin v1.3.72

[fmedisov]

It seems, this bug is fixed in scope of Fix empty response... #948 changes in v2.4.2.

[sergkunz]

Hi, thank you for quick response. But now I'm getting an ResourceAccessException in v2.4.2. It seems it is another bug https://github.com/zalando/logbook/issues/953

org.springframework.web.client.ResourceAccessException: I/O error on GET request for "http://localhost:8090/test": mark/reset not supported; nested exception is java.io.IOException: mark/reset not supported at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:748) at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:674) at org.springframework.web.client.RestTemplate.getForEntity(RestTemplate.java:342) at ru.lamoda.wmsprinting.service.SomeRestClient.doRestQuery(SomeRestClient.kt:49) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:564) at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:305) at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:190) at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:153) at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172) at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165) at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139) at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:403) at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:360) at org.springframework.boot.context.event.EventPublishingRunListener.running(EventPublishingRunListener.java:108) at org.springframework.boot.SpringApplicationRunListeners.running(SpringApplicationRunListeners.java:77) at org.springframework.boot.SpringApplication.run(SpringApplication.java:330) at org.springframework.boot.SpringApplication.run(SpringApplication.java:1237) at org.springframework.boot.SpringApplication.run(SpringApplication.java:1226) at ru.lamoda.wmsprinting.WmsprintingApplicationKt.main(WmsprintingApplication.kt:15) Caused by: java.io.IOException: mark/reset not supported at java.base/java.io.InputStream.reset(InputStream.java:727) at java.base/java.io.FilterInputStream.reset(FilterInputStream.java:224) at java.base/sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.reset(HttpURLConnection.java:3504) at org.zalando.logbook.spring.RemoteResponse$Offering.buffer(RemoteResponse.java:66) at org.zalando.logbook.spring.RemoteResponse.lambda$getBody$0(RemoteResponse.java:160) at org.zalando.fauxpas.ThrowingFunction.apply(ThrowingFunction.java:19) at java.base/java.util.concurrent.atomic.AtomicReference.updateAndGet(AtomicReference.java:210) at org.zalando.logbook.spring.RemoteResponse.getBody(RemoteResponse.java:159) at org.zalando.logbook.HttpMessage.getBodyAsString(HttpMessage.java:28) at org.zalando.logbook.ForwardingHttpMessage.getBodyAsString(ForwardingHttpMessage.java:47) at org.zalando.logbook.FilteredHttpResponse.getBodyAsString(FilteredHttpResponse.java:50) at org.zalando.logbook.json.JsonHttpLogFormatter.prepareBody(JsonHttpLogFormatter.java:64) at org.zalando.logbook.StructuredHttpLogFormatter.prepare(StructuredHttpLogFormatter.java:95) at org.zalando.logbook.StructuredHttpLogFormatter.format(StructuredHttpLogFormatter.java:26) at org.zalando.logbook.DefaultSink.write(DefaultSink.java:26) at org.zalando.logbook.Strategy.write(Strategy.java:119) at org.zalando.logbook.DefaultLogbook$1.lambda$process$0(DefaultLogbook.java:55) at org.zalando.logbook.spring.LogbookClientHttpRequestInterceptor.intercept(LogbookClientHttpRequestInterceptor.java:28) at org.springframework.http.client.InterceptingClientHttpRequest$InterceptingRequestExecution.execute(InterceptingClientHttpRequest.java:93) at org.springframework.http.client.InterceptingClientHttpRequest.executeInternal(InterceptingClientHttpRequest.java:77) at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48) at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53) at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:739)

[s-volkov-1]

One of possible workarounds: different configuration (HttpClient = Apache client).

@Bean
fun httpClientWithLogbook(): HttpClient {
    return HttpClientBuilder.create()
        .addInterceptorFirst(LogbookHttpRequestInterceptor(logbook))
        .addInterceptorLast(LogbookHttpResponseInterceptor())
        .build()
}

@Bean
fun restTemplateXYZ(
    restTemplateBuilder: RestTemplateBuilder,
    httpClientWithLogbook: HttpClient,
    props: CustomHttpClientProperties
): RestTemplate = restTemplateBuilder
    .requestFactory { 
        createHttpRequestFactory(props.readTimeout, props.connectTimeout, httpClient) 
    }
    .build()

private fun createHttpRequestFactory(readTimeout: Int, connectTimeout: Int, httpClient: HttpClient): ClientHttpRequestFactory {
    return HttpComponentsClientHttpRequestFactory(httpClient).apply {
        setReadTimeout(readTimeout)
        setConnectTimeout(connectTimeout)
    }
}

[tonyfarney]

It's necessary to use a buffering client in order to Logbook read the stream and "reset" it (simulating that the stream remains untouched). Otherwise, the first error reported in this issue would happen.

A simple workaround is providing the buffering client to RestTemplate as follows:

ClientHttpRequestFactory factory = new BufferingClientHttpRequestFactory(new SimpleClientHttpRequestFactory());
RestTemplate restTemplate = new RestTemplate(factory);
restTemplate.getInterceptors().add(new LogbookClientHttpRequestInterceptor(logbook));

Maybe it's not necessary change anything in the LogbookClientHttpRequestInterceptor. Just update the documentation about logging with RestTemplate.

[mutyasaisrikar]

I am also facing a similar issue while using a HandlerInterceptor where the request body is fetched to do some processing.

I am trying to read the request body using the below statement in Interceptor, new String(IOUtils.toByteArray(request.getInputStream()))

After this statement, I am not getting RequestBody in the Controller class

The version used: 2.14.0

I think the reason is, that we are using a single input stream and not resetting it after the use.

[tonyfarney]

I am also facing a similar issue while using a HandlerInterceptor where the request body is fetched to do some processing.

I am trying to read the request body using the below statement in Interceptor, new String(IOUtils.toByteArray(request.getInputStream()))

After this statement, I am not getting RequestBody in the Controller class

The version used: 2.14.0

I think the reason is, that we are using a single input stream and not resetting it after the use.

Did you tried my workaround?

https://github.com/zalando/logbook/issues/963#issuecomment-846279233

[mutyasaisrikar]

@tonyfarney, I am using zalando logbook for incoming HTTP calls. So there is no resttemplate.

[tonyfarney]

Maybe it can be helpful: https://www.baeldung.com/spring-reading-httpservletrequest-multiple-times

[mutyasaisrikar]

Thanks for the link. I understand the workaround but it would be helpful if it is done automatically by the library just like before.

[mivchal333]

I had same issue on 2.14.0 version. Resolved by update to latest 2.15.0.

[kasmarian]

Closing the issue as it should be fixed after 2.15.0. Please reopen it if you continue to have issues