Affects: 3.1.5
I am trying to run a spring boot application with a webclient which just sends a simple POST request to another server, in my case being a simple nodejs express server. I created an example application here: https://github.com/brianmarting/webclient-issue
The issue the I have is that the spring boot application sends the POST request to the nodejs server and it says it gets a 200 back, but eventually times out. In the express server I do not receive anything which is also strange. When using postman to POST to the nodejs server it does work so there are no issues there.
I think the problem could be related to this dependency: implementation("io.netty:netty-resolver-dns-native-macos:4.1.100.Final:osx-aarch_64") which should normally fix it, but it does not. It actually did succeed once which makes it even more weird.
Running on: M1 Max macOS ventura Version 13.6
Comment From: snicoll
Thanks for the report. Can you edit the README to explain how to reproduce the problem?
Comment From: brianmarting
Hey @snicoll , I updated the README
Comment From: snicoll
You can see in the logs that it will return a 200 but evenutally will timeout after 5 seconds.
How do I see that? I ran the sample on a MBP M2 with Java 17 and I got this:
2023-10-31T10:10:15.170+01:00 DEBUG 17738 --- [ main] o.s.w.r.f.client.ExchangeFunctions : [62d40e31] HTTP POST http://localhost:9000/test
2023-10-31T10:10:15.401+01:00 DEBUG 17738 --- [ctor-http-nio-2] o.s.w.r.f.client.ExchangeFunctions : [62d40e31] [4588ea5d-1] Response 200 OK
2023-10-31T10:10:15.407+01:00 INFO 17738 --- [ctor-http-nio-2] com.brian.webclientissue.Webclient : success{"message":"OK"}
2023-10-31T10:10:15.407+01:00 INFO 17738 --- [ctor-http-nio-2] com.brian.webclientissue.Webclient : nxt{"message":"OK"}
2023-10-31T10:10:15.407+01:00 INFO 17738 --- [ main] com.brian.webclientissue.Webclient : done{"message":"OK"}
2023-10-31T10:10:15.540+01:00 INFO 17738 --- [ main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint(s) beneath base path '/actuator'
2023-10-31T10:10:15.556+01:00 INFO 17738 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2023-10-31T10:10:15.563+01:00 INFO 17738 --- [ main] c.b.w.WebclientissueApplication : Started WebclientissueApplication in 1.095 seconds (process running for 1.286)
2023-10-31T10:10:16.091+01:00 INFO 17738 --- [)-192.168.1.104] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-10-31T10:10:16.091+01:00 INFO 17738 --- [)-192.168.1.104] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2023-10-31T10:10:16.092+01:00 INFO 17738 --- [)-192.168.1.104] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
(I didn't get any log after that)
Comment From: brianmarting
Strange, I do get the logs
2023-10-31T10:22:35.764+01:00 DEBUG 3042 --- [ main] o.s.w.r.f.client.ExchangeFunctions : [e91af20] HTTP POST http://localhost:9000/test
2023-10-31T10:22:36.056+01:00 DEBUG 3042 --- [ctor-http-nio-2] o.s.w.r.f.client.ExchangeFunctions : [e91af20] [e880445e-1] Response 200 OK
2023-10-31T10:22:40.758+01:00 DEBUG 3042 --- [ parallel-1] o.s.w.r.f.client.ExchangeFunctions : [e91af20] Cancel signal (to close connection)
2023-10-31T10:22:40.761+01:00 INFO 3042 --- [ parallel-1] com.brian.webclientissue.Webclient : successfallback
2023-10-31T10:22:40.761+01:00 INFO 3042 --- [ parallel-1] com.brian.webclientissue.Webclient : nxtfallback
2023-10-31T10:22:40.761+01:00 INFO 3042 --- [ main] com.brian.webclientissue.Webclient : donefallback
2023-10-31T10:22:40.966+01:00 INFO 3042 --- [ main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint(s) beneath base path '/actuator'
2023-10-31T10:22:40.997+01:00 INFO 3042 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2023-10-31T10:22:41.006+01:00 INFO 3042 --- [ main] c.b.w.WebclientissueApplication : Started WebclientissueApplication in 6.462 seconds (process running for 6.988)
2023-10-31T10:22:41.567+01:00 INFO 3042 --- [3)-10.21.47.238] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-10-31T10:22:41.567+01:00 INFO 3042 --- [3)-10.21.47.238] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2023-10-31T10:22:41.568+01:00 INFO 3042 --- [3)-10.21.47.238] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
Comment From: snicoll
I am afraid I don't see how this could be a problem with Spring Framework. It could be an issue in reactor-nettyor the DNS resolver as you've mentioned. I am also on a Mac ARM and I don't have the issue.
Please try to collect more logs and open a reactor or netty issue accordingly.