zalando/logbook

RESTEASY003765: Response is closed

niallrox opened this issue · 4 comments

niallrox commented

Hello.

Exception that response is already closed is thrown, while involve logbook into keycloak admin client.

Steps to reproduce.

Using
SB3
and

    implementation("org.keycloak:keycloak-admin-client:23.0.3")
    implementation("org.zalando:logbook-spring-boot-starter:3.7.2")
    implementation("org.zalando:logbook-jaxrs:3.7.2")

Bean with client

    @Bean
    fun surdoRealm(
        keycloakProperties: KeycloakProperties,
        resteasyClient: ResteasyClient
    ): RealmResource {
        val keycloak = KeycloakBuilder.builder()
            .serverUrl(keycloakProperties.host)
            .realm(keycloakProperties.realm)
            .grantType(OAuth2Constants.CLIENT_CREDENTIALS)
            .clientId(keycloakProperties.clientId)
            .clientSecret(keycloakProperties.clientSecret)
            .resteasyClient(resteasyClient)
            .build()

        return keycloak.realm(keycloakProperties.realm)
    }

    @Bean
    fun loggingClient(logbook: Logbook): ResteasyClient {
        val clientBuilder = ClientBuilderWrapper.create(SSLContext.getDefault(), false) as ResteasyClientBuilder
        clientBuilder.register(JacksonProvider::class.java, JACKSON_PROVIDER_PRIORITY)
        val client = clientBuilder.build()
        client.register(LogbookClientFilter(logbook))
        return client
    }

application.yml

logbook:
  predicate:
    include:
      - path: /**
    exclude:
      - path: /actuator/health
      - path: /internal/**
  filter.enabled: true
  secure-filter.enabled: true
  format.style: http
  strategy: body-only-if-status-at-least
  obfuscate:
    headers:
      - Authorization
      - X-Secret
    parameters:
      - access_token
      - password
  write:
    chunk-size: 1000
  attribute-extractors:
    - type: JwtFirstMatchingClaimExtractor
      claim-names: [ "sub", "subject" ]
      claim-key: Principal
    - type: JwtAllMatchingClaimsExtractor
      claim-names: [ "sub", "iat" ]

This is the log

2024-02-23 14:10:43,554 ?[39mTRACE?[0;39m [?[34mTest worker?[0;39m] [] ?[33morg.zalando.logbook.core.DefaultHttpLogWriter?[0;39m: Outgoing Request: 80c7b39f63628838
Remote: localhost
POST http://localhost:57696/realms/master/protocol/openid-connect/token HTTP/1.1
Accept: application/json
Content-Type: application/x-www-form-urlencoded

grant_type=password&username=admin&password=XXX&client_id=admin-cli
2024-02-23 14:10:43,589 ?[39mTRACE?[0;39m [?[34mTest worker?[0;39m] [] ?[33morg.zalando.logbook.core.DefaultHttpLogWriter?[0;39m: Incoming Response: 80c7b39f63628838
Duration: 35 ms
HTTP/1.1 200 OK
Cache-Control: no-store
content-length: 1822
Content-Type: application/json
Pragma: no-cache
Referrer-Policy: no-referrer
Set-Cookie: KEYCLOAK_LOCALE=; Version=1; Comment=Expiring cookie; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Max-Age=0; Path=/realms/master/; HttpOnly, KC_RESTART=; Version=1; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Max-Age=0; Path=/realms/master/; HttpOnly, KC_AUTH_STATE=; Version=1; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Max-Age=0; Path=/realms/master/
Strict-Transport-Security: max-age=31536000; includeSubDomains
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block

{"access_token":"XXX","expires_in":60,"refresh_expires_in":1800,"refresh_token":"XXX","token_type":"Bearer","not-before-policy":0,"session_state":"f6dc8be8-52a1-448f-8042-5f6b777eca74","scope":"profile email"}

And the error
jakarta.ws.rs.client.ResponseProcessingException: java.lang.IllegalStateException: RESTEASY003765: Response is closed.

I think after logbook read and log the response, client can't parse it, because you can't read response more than once. However, I haven't found another solution or sink implementation which could provide me that opportunity.
Thanks in advance.

lukasniemeier-zalando commented

@niallrox would you be able to provide a small Github repository that showcases the problem (i.e. your classes and configuration from above)?

niallrox commented

Unfortunately, I can't share the whole repository, it's private. However, I will create a small repo that reproduces the same issue and easy to run. I'll do it approximately in 2 days.

de-winter commented

Hey,

i recently tried to integrate Logbook in our Quarkus applications and observed a similar behavior.
Logging Container Request/Responses and Client Requests work fine, Client responses are logged, are however followed by said error...

I also provided a repository showcasing the error:
https://github.com/de-winter/logbook-client-response-error-example

Quarkus (with RESTEasy) 3.11
Logbook 3.9

Test execution:


2024-06-24 15:07:38,142 TRACE [org.zal.log.Logbook] (main) Outgoing Request: d4bf46af15ac4c98
Remote: localhost
POST http://localhost:8081/hello HTTP/1.1
Accept: text/plain
Content-Type: application/json

World
2024-06-24 15:07:38,153 TRACE [org.zal.log.Logbook] (executor-thread-1) Incoming Request: dea912a673fcc338
Remote: localhost:8081
POST http://localhost:8081/hello HTTP/1.1
Accept: text/plain
Connection: Keep-Alive
Content-Length: 5
Content-Type: application/json
Host: localhost:8081
User-Agent: Apache-HttpClient/4.5.14 (Java/17.0.6)

World
2024-06-24 15:07:38,154 TRACE [org.zal.log.Logbook] (executor-thread-1) Outgoing Response: dea912a673fcc338
Duration: 1 ms
HTTP/1.1 200 OK
Content-Type: text/plain;charset=UTF-8

Hello World
2024-06-24 15:07:38,158 TRACE [org.zal.log.Logbook] (main) Incoming Response: d4bf46af15ac4c98
Duration: 21 ms
HTTP/1.1 200 OK
content-length: 11
Content-Type: text/plain;charset=UTF-8

Hello World

jakarta.ws.rs.ProcessingException: RESTEASY004640: Stream is closed

	at org.jboss.resteasy.client.jaxrs.internal.ClientResponse.getEntityStream(ClientResponse.java:144)
	at org.jboss.resteasy.client.jaxrs.internal.ClientResponseContextImpl.getEntityStream(ClientResponseContextImpl.java:128)
	at org.jboss.resteasy.microprofile.client.PartialResponse.<init>(PartialResponse.java:52)
	at org.jboss.resteasy.microprofile.client.ExceptionMapping.filter(ExceptionMapping.java:86)
	at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterResponse(ClientInvocation.java:667)
	at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:428)
	at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:134)
	at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:103)
	at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:61)
	at jdk.proxy5/jdk.proxy5.$Proxy71.hello(Unknown Source)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at io.quarkus.restclient.runtime.QuarkusProxyInvocationHandler.invoke(QuarkusProxyInvocationHandler.java:165)
	at jdk.proxy5/jdk.proxy5.$Proxy74.hello(Unknown Source)
	at example.logbook.ExampleTest.testHelloClient(ExampleTest.java:30)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at io.quarkus.test.junit.QuarkusTestExtension.runExtensionMethod(QuarkusTestExtension.java:1017)
	at io.quarkus.test.junit.QuarkusTestExtension.interceptTestMethod(QuarkusTestExtension.java:831)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
  • 👍2