Spring Boot WebClient : Closes connection prematurely before response

Question

I am trying to learn spring boot Webclient. In order to understand "non-blocking" HTTP requests, I made two spring boot applications

1. Spring Boot REST API server : This has a simple REST endpoint with a 10 seconds sleep to hold the request.
2. REST Client : A simple (non web) spring boot application which will call the REST API server by using RestTemplate and Webclient. I am using both to visually understand the non blocking behavior.

See the code for the REST API Server

@RestController
@RequestMapping("/api")
public class UserApi {

    @GetMapping(path = "/test")
    public String test() {
        System.out.println("Test Request Started");

        try {
            Thread.sleep(5000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        System.out.println("Test Request Ended");

        return "OK";
    }

}

Code of the REST client

public class RestClient{

    public void restTemplate() {
        RestTemplate restTemplate = new RestTemplate();
        String string = restTemplate.getForObject("http://localhost:8080/api/test", String.class);
        System.out.println(string);
    }

    public void webClient() {
         Mono<String> bodyToMono = WebClient.create("http://localhost:8080/")
                .get()
                .uri("/api/test")
                .retrieve()
                .bodyToMono(String.class);
         bodyToMono.subscribe(System.out::println);
    }
}

And I am calling this class from my Spring Boot Main method as

@SpringBootApplication
public class WebClientApplication {

    public static void main(String[] args) {
        SpringApplication.run(WebClientApplication.class, args);
        RestClient restClient = new RestClient();
        System.out.println("Testing with Webclient");
        restClient.webClient();
        System.out.println("Testing with RestTemplate");
        restClient.restTemplate();
    }

}

Problem :

I get the following exception which I have no reason :

Caused by: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
    |_ checkpoint ⇢ Request to GET http://localhost:8080/api/test [DefaultWebClient]
Stack trace:

If you want to see the detailed log :

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.0.RELEASE)

2020-05-16 16:32:17.506  INFO 9928 --- [  restartedMain] c.w.server.client.WebClientApplication   : Starting WebClientApplication on DESKTOP-054O660 with PID 9928 (D:\eclipse-jee-2019-09-R-win32-x86_64\workspace\WebClientDemoServer\client\target\classes started by Akshay in D:\eclipse-jee-2019-09-R-win32-x86_64\workspace\WebClientDemoServer\client)
2020-05-16 16:32:17.506  INFO 9928 --- [  restartedMain] c.w.server.client.WebClientApplication   : No active profile set, falling back to default profiles: default
2020-05-16 16:32:17.631  INFO 9928 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2020-05-16 16:32:17.631  INFO 9928 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2020-05-16 16:32:19.004 DEBUG 9928 --- [  restartedMain] reactor.netty.tcp.TcpResources           : [http] resources will use the default LoopResources: DefaultLoopResources {prefix=reactor-http, daemon=true, selectCount=4, workerCount=4}
2020-05-16 16:32:19.007 DEBUG 9928 --- [  restartedMain] reactor.netty.tcp.TcpResources           : [http] resources will use the default ConnectionProvider: reactor.netty.resources.PooledConnectionProvider@6eb63cda
2020-05-16 16:32:19.053  INFO 9928 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2020-05-16 16:32:19.121  INFO 9928 --- [  restartedMain] c.w.server.client.WebClientApplication   : Started WebClientApplication in 2.446 seconds (JVM running for 3.272)
Testing with Webclient
2020-05-16 16:32:20.680 DEBUG 9928 --- [  restartedMain] r.netty.resources.DefaultLoopEpoll       : Default Epoll support : false
2020-05-16 16:32:20.688 DEBUG 9928 --- [  restartedMain] r.netty.resources.DefaultLoopKQueue      : Default KQueue support : false
2020-05-16 16:32:20.893 DEBUG 9928 --- [  restartedMain] r.n.resources.PooledConnectionProvider   : Creating a new client pool [PoolFactory {maxConnections=500, pendingAcquireMaxCount=-1, pendingAcquireTimeout=45000, maxIdleTime=-1, maxLifeTime=-1, metricsEnabled=false}] for [localhost:8080]
Testing with RestTemplate
2020-05-16 16:32:21.369 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df] Created a new pooled channel, now 1 active connections and 0 inactive connections
2020-05-16 16:32:21.440 DEBUG 9928 --- [ctor-http-nio-1] reactor.netty.channel.BootstrapHandlers  : [id: 0x77afe9df] Initialized pipeline DefaultChannelPipeline{(BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer#0 = reactor.netty.resources.PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.left.decompressor = io.netty.handler.codec.http.HttpContentDecompressor), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2020-05-16 16:32:21.457 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080] Registering pool release on close event for channel
2020-05-16 16:32:21.458 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080] Channel connected, now 1 active connections and 0 inactive connections
2020-05-16 16:32:21.459 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080] onStateChange(PooledConnection{channel=[id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080]}, [connected])
2020-05-16 16:32:21.473 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080]}}, [configured])
2020-05-16 16:32:21.475 DEBUG 9928 --- [ctor-http-nio-1] r.netty.http.client.HttpClientConnect    : [id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080] Handler is being applied: {uri=http://localhost:8080/api/test, method=GET}
2020-05-16 16:32:21.477 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080] onStateChange(GET{uri=/api/test, connection=PooledConnection{channel=[id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080]}}, [request_prepared])
2020-05-16 16:32:21.517 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080] onStateChange(GET{uri=/api/test, connection=PooledConnection{channel=[id: 0x77afe9df, L:/127.0.0.1:52476 - R:localhost/127.0.0.1:8080]}}, [request_sent])
OK
2020-05-16 16:32:26.476 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 ! R:localhost/127.0.0.1:8080] Channel closed, now 0 active connections and 0 inactive connections
2020-05-16 16:32:26.476 DEBUG 9928 --- [ctor-http-nio-1] r.n.resources.PooledConnectionProvider   : [id: 0x77afe9df, L:/127.0.0.1:52476 ! R:localhost/127.0.0.1:8080] onStateChange(GET{uri=/api/test, connection=PooledConnection{channel=[id: 0x77afe9df, L:/127.0.0.1:52476 ! R:localhost/127.0.0.1:8080]}}, [response_incomplete])
2020-05-16 16:32:26.491  WARN 9928 --- [ctor-http-nio-1] r.netty.http.client.HttpClientConnect    : [id: 0x77afe9df, L:/127.0.0.1:52476 ! R:localhost/127.0.0.1:8080] The connection observed an error

reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response

2020-05-16 16:32:26.491  WARN 9928 --- [ctor-http-nio-1] reactor.netty.channel.FluxReceive        : [id: 0x77afe9df, L:/127.0.0.1:52476 ! R:localhost/127.0.0.1:8080] An exception has been observed post termination

reactor.core.Exceptions$ErrorCallbackNotImplemented: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
Caused by: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
    |_ checkpoint ⇢ Request to GET http://localhost:8080/api/test [DefaultWebClient]
Stack trace:

I am using tomcat in the REST API server :

Logs of server are also attached:

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.0.RELEASE)

2020-05-16 16:36:25.661  INFO 6812 --- [  restartedMain] c.w.s.WebClientDemoServerApplication     : Starting WebClientDemoServerApplication on DESKTOP-054O660 with PID 6812 (D:\eclipse-jee-2019-09-R-win32-x86_64\workspace\WebClientDemoServer\server\target\classes started by Akshay in D:\eclipse-jee-2019-09-R-win32-x86_64\workspace\WebClientDemoServer\server)
2020-05-16 16:36:25.661  INFO 6812 --- [  restartedMain] c.w.s.WebClientDemoServerApplication     : No active profile set, falling back to default profiles: default
2020-05-16 16:36:25.723  INFO 6812 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2020-05-16 16:36:25.723  INFO 6812 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2020-05-16 16:36:26.942  INFO 6812 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-05-16 16:36:26.955  INFO 6812 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-05-16 16:36:26.955  INFO 6812 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.35]
2020-05-16 16:36:27.049  INFO 6812 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-05-16 16:36:27.049  INFO 6812 --- [  restartedMain] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1326 ms
2020-05-16 16:36:27.283  INFO 6812 --- [  restartedMain] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-05-16 16:36:27.455 DEBUG 6812 --- [  restartedMain] reactor.netty.tcp.TcpResources           : [http] resources will use the default LoopResources: DefaultLoopResources {prefix=reactor-http, daemon=true, selectCount=4, workerCount=4}
2020-05-16 16:36:27.471 DEBUG 6812 --- [  restartedMain] reactor.netty.tcp.TcpResources           : [http] resources will use the default ConnectionProvider: reactor.netty.resources.PooledConnectionProvider@7f6d3bcb
2020-05-16 16:36:27.487  INFO 6812 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2020-05-16 16:36:27.533  INFO 6812 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-05-16 16:36:27.549  INFO 6812 --- [  restartedMain] c.w.s.WebClientDemoServerApplication     : Started WebClientDemoServerApplication in 2.36 seconds (JVM running for 3.545)
2020-05-16 16:36:39.781  INFO 6812 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2020-05-16 16:36:39.789  INFO 6812 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2020-05-16 16:36:39.791  INFO 6812 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms
Test Request Started
Test Request Started
Test Request Ended
Test Request Ended

Answer 1

For future readers. I had a similar issue, I've fixed it by adding ReactorClientHttpConnector to Webclient creation process.

BEFORE:

        this.webClient = WebClient.builder()
            .baseUrl(url)
            .build();

AFTER:

        this.webClient = WebClient.builder()
            .baseUrl(url)
            .clientConnector(new ReactorClientHttpConnector(HttpClient.newConnection().compress(true)))
            .build();

Spring Boot version: 2.3.6

Reactor netty version: 0.9.14

Good luck!