NullPointerException when trying to use webClient with wildfly in a gateway service

[magyari44]

Description

I am trying to use logbook for logging http requests and response in a gateway module, in such a way, that the gateway logs the incoming requests from the internet ("origin":"remote","type":"request") and the outgoing requests and responses ("origin":"local","type":"request"; "origin":"remote","type":"response") to inner-services, and at the end the outgoing response to the internet too ("origin":"local","type":"response").

This gateway module uses spring webClient for handling asynchronous requests for inner-services.

I have used the following dependencies, where I am not able to upgrade them:

<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>2.4.13</version>
<relativePath/>

<dependency>
	<groupId>org.zalando</groupId>
	<artifactId>logbook-spring-boot-starter</artifactId>
	<version>2.15.0</version>
</dependency>
<dependency>
	<groupId>org.zalando</groupId>
	<artifactId>logbook-netty</artifactId>
	<version>2.15.0</version>
</dependency>

It works fine for logging all the information but I am getting a NullPointerException too, related to the LogbookFilter, and I am not sure why is this, and what causes it.

Expected Behavior

• Log everything, but do not throw NullPoinerException

Actual Behavior

• It throws a NullPointerException:
  Example:

2024-11-19 11:52:13 10:52:13,258 INFO  [stdout] (default task-1) 2024-11-19 10:52:13.238  INFO 185 --- [ default task-1] c.logbook.async.logbookdemo.DemoLogbook  : {"origin":"remote","type":"request","correlation":"d742767227a71985","protocol":"HTTP/1.1","remote":"172.23.0.1","method":"GET","uri":"http://localhost:8080/gateway/api","host":"localhost","path":"/gateway/api","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Accept-Encoding":["br, deflate, gzip, x-gzip"],"content-length":["0"],"Content-Type":["application/json"],"Cookie":["JSESSIONID=681FBEB58818F31657E3BA6C693072C1.5a7e07a78e2a; JSESSIONID=681FBEB58818F31657E3BA6C693072C1"],"host":["localhost:8080"],"User-Agent":["IntelliJ HTTP Client/IntelliJ IDEA 2024.2.4"]}}
2024-11-19 11:52:13 10:52:13,316 INFO  [io.undertow.servlet] (default task-1) Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-11-19 11:52:13 10:52:13,319 INFO  [stdout] (default task-1) 2024-11-19 10:52:13.318  INFO 185 --- [ default task-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2024-11-19 11:52:13 10:52:13,342 INFO  [stdout] (default task-1) 2024-11-19 10:52:13.340  INFO 185 --- [ default task-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 20 ms
2024-11-19 11:52:13 10:52:13,559 INFO  [stdout] (default task-1) 2024-11-19 10:52:13.547  INFO 185 --- [ default task-1] com.logbook.async.logbookdemo.DemoApi    : redirecting /gateway, to complete uri: http://localhost:8080/service/api
2024-11-19 11:52:16 10:52:16,440 INFO  [stdout] (reactor-http-epoll-2) 2024-11-19 10:52:16.356  INFO 185 --- [or-http-epoll-2] c.logbook.async.logbookdemo.DemoLogbook  : {"origin":"local","type":"request","correlation":"9ca11aafc90e982d","protocol":"HTTP/1.1","remote":"localhost/127.0.0.1:8080","method":"GET","uri":"http://localhost:8080/service/api","host":"localhost","path":"/service/api","scheme":"http","port":"8080","headers":{"Accept":["application/json"],"Content-Type":["application/json"],"host":["localhost:8080"],"user-agent":["ReactorNetty/1.0.13"]}}
2024-11-19 11:52:17 10:52:17,009 INFO  [stdout] (default task-2) 2024-11-19 10:52:16.998  INFO 185 --- [ default task-2] com.logbook.service.DemoLogbook          : {"origin":"remote","type":"request","correlation":"b13e95d2cf9a9941","protocol":"HTTP/1.1","remote":"127.0.0.1","method":"GET","uri":"http://localhost:8080/service/api","host":"localhost","path":"/service/api","scheme":"http","port":"8080","headers":{"Accept":["application/json"],"Content-Type":["application/json"],"host":["localhost:8080"],"user-agent":["ReactorNetty/1.0.13"]}}
2024-11-19 11:52:17 10:52:17,049 INFO  [io.undertow.servlet] (default task-2) Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-11-19 11:52:17 10:52:17,053 INFO  [stdout] (default task-2) 2024-11-19 10:52:17.051  INFO 185 --- [ default task-2] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2024-11-19 11:52:17 10:52:17,182 INFO  [stdout] (default task-2) 2024-11-19 10:52:17.179  INFO 185 --- [ default task-2] o.s.web.servlet.DispatcherServlet        : Completed initialization in 126 ms
2024-11-19 11:52:17 10:52:17,407 INFO  [stdout] (default task-2) 2024-11-19 10:52:17.404  INFO 185 --- [ default task-2] com.logbook.service.DemoApi              : Incoming request!
2024-11-19 11:52:17 10:52:17,576 INFO  [stdout] (default task-2) 2024-11-19 10:52:17.570  INFO 185 --- [ default task-2] com.logbook.service.DemoLogbook          : {"origin":"local","type":"response","correlation":"b13e95d2cf9a9941","duration":1030,"protocol":"HTTP/1.1","status":200,"headers":{"Connection":["keep-alive"],"Content-Length":["16"],"Content-Type":["application/json"],"Date":["Tue, 19 Nov 2024 10:52:17 GMT"],"Server":["WildFly/10"],"X-Powered-By":["Undertow/1"]},"body":"{\"success\":true}"}
2024-11-19 11:52:17 10:52:17,888 INFO  [stdout] (reactor-http-epoll-2) 2024-11-19 10:52:17.882  INFO 185 --- [or-http-epoll-2] c.logbook.async.logbookdemo.DemoLogbook  : {"origin":"remote","type":"response","correlation":"9ca11aafc90e982d","duration":1800,"protocol":"HTTP/1.1","status":200,"headers":{"Connection":["keep-alive"],"content-length":["16"],"Content-Type":["application/json"],"Date":["Tue, 19 Nov 2024 10:52:17 GMT"],"Server":["WildFly/10"],"X-Powered-By":["Undertow/1"]},"body":"{\"success\":true}"}
2024-11-19 11:52:18 10:52:18,167 INFO  [stdout] (default task-3) 2024-11-19 10:52:18.166  INFO 185 --- [ default task-3] c.logbook.async.logbookdemo.DemoLogbook  : {"origin":"local","type":"response","correlation":"d742767227a71985","duration":5646,"protocol":"HTTP/1.1","status":200,"headers":{"Connection":["keep-alive"],"Content-Type":["application/json"],"Date":["Tue, 19 Nov 2024 10:52:18 GMT"],"Server":["WildFly/10"],"Set-Cookie":["JSESSIONID=681FBEB58818F31657E3BA6C693072C1.599f2400d697; path=/gateway"],"Transfer-Encoding":["chunked"],"X-Powered-By":["Undertow/1"]},"body":"{\"headers\":{\"Connection\":[\"keep-alive\"],\"X-Powered-By\":[\"Undertow/1\"],\"Server\":[\"WildFly/10\"],\"Content-Type\":[\"application/json\"],\"Date\":[\"Tue, 19 Nov 2024 10:52:17 GMT\"],\"content-length\":[\"16\"]},\"body\":{\"success\":true},\"statusCode\":\"OK\",\"statusCodeValue\":200}"}
2024-11-19 11:52:18 10:52:18,183 ERROR [io.undertow.request] (default task-3) UT005071: Undertow request failed HttpServerExchange{ GET /gateway/api request {Accept=[*/*], Accept-Encoding=[br, deflate, gzip, x-gzip], Content-Type=[application/json], Cookie=[JSESSIONID=681FBEB58818F31657E3BA6C693072C1.5a7e07a78e2a; JSESSIONID=681FBEB58818F31657E3BA6C693072C1], content-length=[0], User-Agent=[IntelliJ HTTP Client/IntelliJ IDEA 2024.2.4], host=[localhost:8080]} response {Connection=[keep-alive], X-Powered-By=[Undertow/1], Set-Cookie=[JSESSIONID=681FBEB58818F31657E3BA6C693072C1.599f2400d697; path=/gateway], Server=[WildFly/10], Transfer-Encoding=[chunked], Content-Type=[application/json], Date=[Tue, 19 Nov 2024 10:52:18 GMT]}}: java.lang.NullPointerException
2024-11-19 11:52:18 at org.zalando.logbook.servlet.LogbookFilter.write(LogbookFilter.java:85)
2024-11-19 11:52:18 at org.zalando.logbook.servlet.LogbookFilter.lambda$doFilter$0(LogbookFilter.java:71)
2024-11-19 11:52:18 at org.zalando.logbook.servlet.LogbookAsyncListener.onComplete(LogbookAsyncListener.java:17)
2024-11-19 11:52:18 at io.undertow.servlet.spec.AsyncContextImpl$7.run(AsyncContextImpl.java:586)
2024-11-19 11:52:18 at io.undertow.servlet.spec.ServletContextImpl.invokeRunnable(ServletContextImpl.java:901)
2024-11-19 11:52:18 at io.undertow.servlet.spec.AsyncContextImpl.onAsyncComplete(AsyncContextImpl.java:576)
2024-11-19 11:52:18 at io.undertow.servlet.spec.AsyncContextImpl.complete(AsyncContextImpl.java:273)
2024-11-19 11:52:18 at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:345)
2024-11-19 11:52:18 at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
2024-11-19 11:52:18 at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
2024-11-19 11:52:18 at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
2024-11-19 11:52:18 at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
2024-11-19 11:52:18 at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
2024-11-19 11:52:18 at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
2024-11-19 11:52:18 at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
2024-11-19 11:52:18 at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
2024-11-19 11:52:18 at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
2024-11-19 11:52:18 at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
2024-11-19 11:52:18 at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
2024-11-19 11:52:18 at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:209)
2024-11-19 11:52:18 at io.undertow.servlet.spec.AsyncContextImpl$2$1.handleRequest(AsyncContextImpl.java:188)
2024-11-19 11:52:18 at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
2024-11-19 11:52:18 at io.undertow.servlet.spec.AsyncContextImpl$2.run(AsyncContextImpl.java:185)
2024-11-19 11:52:18 at io.undertow.servlet.spec.AsyncContextImpl$6.run(AsyncContextImpl.java:455)
2024-11-19 11:52:18 at io.undertow.servlet.spec.AsyncContextImpl$TaskDispatchRunnable.run(AsyncContextImpl.java:566)
2024-11-19 11:52:18 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
2024-11-19 11:52:18 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2024-11-19 11:52:18 at java.lang.Thread.run(Thread.java:748)
2024-11-19 11:52:18 

Steps to Reproduce

For making it reproducible, there are 3 repositories:

To reproduce:

1. checkout the repositories which is provided later
2. build the modules
3. start the container
4. deploy applications as gateway.war and service.war
5. Invoke the API endpoint

curl -X GET --location "http://localhost:8080/gateway/api" \
    -H "Content-Type: application/json"

6. check the logs

Context

I am trying to use logbook for logging http requests and response in a gateway module, in such a way, that the gateway logs the incoming requests from the internet ("origin":"remote","type":"request") and the outgoing requests and responses ("origin":"local","type":"request"; "origin":"remote","type":"response") to inner-services, and at the end the outgoing response to the internet too ("origin":"local","type":"response").

Your Environment

• Wildfly 10.1.0-r35
• Spring-boot 2.4.13
• logbook 2.15.0

The gateway where the exception is thrown:
https://github.com/magyari44/logbook-gateway

The inner-service which now just responds with an example:
https://github.com/magyari44/logbook-service

The container where I am deploying my applications:
https://github.com/magyari44/logbook-container

[dmytrokozhanov]

We have the same issue with webflux. I also prepared a project with Undertow and the latest Spring and Logbook versions. To reproduce this issue, you can call the endpoint and then close the connection after 10 sec.

Project: https://github.com/KozhanovDmytro/logbook-npe-demo
curl: curl --location 'http://localhost:8080/time/stream'