Spring Boot WebClient：在响应之前提前关闭连接

Question

我正在尝试学习 spring boot Webclient。为了理解“非阻塞”HTTP请求，我做了两个Spring Boot应用程序

\n\n

\n
1. Spring Boot REST API 服务器：它有一个简单的 REST 端点，有 10 秒的睡眠时间来保存请求。
\n
2. REST 客户端：一个简单的（非 Web）Spring Boot 应用程序，它将使用 RestTemplate 和 Webclient 调用 REST API 服务器。我使用两者来直观地理解非阻塞行为。
\n

\n\n

请参阅 REST API 服务器的代码

\n\n

@RestController\n@RequestMapping("/api")\npublic class UserApi {\n\n    @GetMapping(path = "/test")\n    public String test() {\n        System.out.println("Test Request Started");\n\n        try {\n            Thread.sleep(5000);\n        } catch (InterruptedException e) {\n            e.printStackTrace();\n        }\n\n        System.out.println("Test Request Ended");\n\n        return "OK";\n    }\n\n}\n

\n\n

REST客户端代码

\n\n

public class RestClient{\n\n    public void restTemplate() {\n        RestTemplate restTemplate = new RestTemplate();\n        String string = restTemplate.getForObject("http://localhost:8080/api/test", String.class);\n        System.out.println(string);\n    }\n\n    public void webClient() {\n         Mono<String> bodyToMono = WebClient.create("http://localhost:8080/")\n                .get()\n                .uri("/api/test")\n                .retrieve()\n                .bodyToMono(String.class);\n         bodyToMono.subscribe(System.out::println);\n    }\n}\n

\n\n

我从 Spring Boot Main 方法调用此类

\n\n

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

\n\n

问题 ：

\n\n

我收到以下异常，但没有任何理由：

\n\n

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

\n\n

如果你想查看详细日志：

\n\n

  .   ____          _            __ _ _\n /\\\\ / ___\'_ __ _ _(_)_ __  __ _ \\ \\ \\ \\\n( ( )\\___ | \'_ | \'_| | \'_ \\/ _` | \\ \\ \\ \\\n \\\\/  ___)| |_)| | | | | || (_| |  ) ) ) )\n  \'  |____| .__|_| |_|_| |_\\__, | / / / /\n =========|_|==============|___/=/_/_/_/\n :: Spring Boot ::        (v2.3.0.RELEASE)\n\n2020-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)\n2020-05-16 16:32:17.506  INFO 9928 --- [  restartedMain] c.w.server.client.WebClientApplication   : No active profile set, falling back to default profiles: default\n2020-05-16 16:32:17.631  INFO 9928 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set \'spring.devtools.add-properties\' to \'false\' to disable\n2020-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\'\n2020-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}\n2020-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\n2020-05-16 16:32:19.053  INFO 9928 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729\n2020-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)\nTesting with Webclient\n2020-05-16 16:32:20.680 DEBUG 9928 --- [  restartedMain] r.netty.resources.DefaultLoopEpoll       : Default Epoll support : false\n2020-05-16 16:32:20.688 DEBUG 9928 --- [  restartedMain] r.netty.resources.DefaultLoopKQueue      : Default KQueue support : false\n2020-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]\nTesting with RestTemplate\n2020-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\n2020-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)}\n2020-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\n2020-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\n2020-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])\n2020-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])\n2020-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}\n2020-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])\n2020-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])\nOK\n2020-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\n2020-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])\n2020-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\n\nreactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response\n\n2020-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\n\nreactor.core.Exceptions$ErrorCallbackNotImplemented: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response\nCaused by: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response\n    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: \nError has been observed at the following site(s):\n    |_ checkpoint \xe2\x87\xa2 Request to GET http://localhost:8080/api/test [DefaultWebClient]\nStack trace:\n

\n\n

我在 REST API 服务器中使用 tomcat ：

\n\n

还附上服务器的日志：

\n\n

  .   ____          _            __ _ _\n /\\\\ / ___\'_ __ _ _(_)_ __  __ _ \\ \\ \\ \\\n( ( )\\___ | \'_ | \'_| | \'_ \\/ _` | \\ \\ \\ \\\n \\\\/  ___)| |_)| | | | | || (_| |  ) ) ) )\n  \'  |____| .__|_| |_|_| |_\\__, | / / / /\n =========|_|==============|___/=/_/_/_/\n :: Spring Boot ::        (v2.3.0.RELEASE)\n\n2020-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)\n2020-05-16 16:36:25.661  INFO 6812 --- [  restartedMain] c.w.s.WebClientDemoServerApplication     : No active profile set, falling back to default profiles: default\n2020-05-16 16:36:25.723  INFO 6812 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set \'spring.devtools.add-properties\' to \'false\' to disable\n2020-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\'\n2020-05-16 16:36:26.942  INFO 6812 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)\n2020-05-16 16:36:26.955  INFO 6812 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]\n2020-05-16 16:36:26.955  INFO 6812 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.35]\n2020-05-16 16:36:27.049  INFO 6812 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext\n2020-05-16 16:36:27.049  INFO 6812 --- [  restartedMain] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1326 ms\n2020-05-16 16:36:27.283  INFO 6812 --- [  restartedMain] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService \'applicationTaskExecutor\'\n2020-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}\n2020-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\n2020-05-16 16:36:27.487  INFO 6812 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729\n2020-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 \'\'\n2020-05-16 16:36:27.549  INFO 6812 --- [  restartedMain] c.w.s.WebClientDemoServerApplication     : Started WebClientDemoServerApplication in 2.36 seconds (JVM running for 3.545)\n2020-05-16 16:36:39.781  INFO 6812 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet \'dispatcherServlet\'\n2020-05-16 16:36:39.789  INFO 6812 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet \'dispatcherServlet\'\n2020-05-16 16:36:39.791  INFO 6812 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms\nTest Request Started\nTest Request Started\nTest Request Ended\nTest Request Ended\n

\n

Answer 1

对于未来的读者。我遇到了类似的问题，我通过将ReactorClientHttpConnector添加到 Webclient 创建过程来修复它。

前：

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

后：

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

春季启动版本：2.3.6

反应堆网络版本：0.9.14

祝你好运！