Reactor WebClient大文件传输后连接复用触发PrematureCloseException

问题复现场景 #

网关配置路由规则，将请求转发至对外暴露actuator端点的下游Web应用，复现规律如下：

• 按顺序先请求actuator/logfile端点（返回日志文件大小约70MB），后续请求actuator/health端点时，连接池复用已有连接，第二次请求会抛出PrematureCloseException异常
• 单独连续请求actuator/health端点多达200次也不会出现任何错误，连接池的连接复用、新建逻辑均运行正常

已验证现象 #

• 禁用连接池可彻底解决该问题
• 将连接池的max-lifetime、max-idle超时参数设置为极小值（效果等效于禁用连接池）也可规避问题
• 两次请求之间间隔数秒，等待使用新建连接发起调用时同样不会触发异常

故障运行日志 #

2022-06-15 16:59:51,523 r.n.r.PooledConnectionProvider: [a3b5326c] Created a new pooled channel, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 16:59:51,580 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] Registering pool release on close event for channel
2022-06-15 16:59:51,580 r.n.r.PooledConnectionProvider: [a3b5326c, L:/*** - R:***] Channel connected, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 16:59:51,617 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] onStateChange(PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}, [connected])
2022-06-15 16:59:51,618 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [configured])
2022-06-15 16:59:51,618 r.n.h.c.HttpClientConnect: [a3b5326c-1, L:/*** - R:***] Handler is being applied: {uri=***/actuator/logfile, method=GET}
2022-06-15 16:59:51,618 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_prepared])
2022-06-15 16:59:51,618 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_sent])
2022-06-15 16:59:51,654 r.n.h.c.HttpClientOperations: [a3b5326c-1, L:/*** - R:***] Received response (auto-read:false) : [Date=Wed, 15 Jun 2022 14:59:51 GMT, Server=Apache, Vary=Origin,Access-Control-Request-Method,Access-Control-Request-Headers, Accept-Ranges=bytes, X-Content-Type-Options=nosniff, X-XSS-Protection=1; mode=block, Cache-Control=no-cache, no-store, max-age=0, must-revalidate, Pragma=no-cache, Expires=0, Strict-Transport-Security=max-age=31536000 ; includeSubDomains, X-Frame-Options=DENY, Content-Type=text/plain;charset=UTF-8, content-length=78644765]
2022-06-15 16:59:51,654 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [response_received])
2022-06-15 17:00:09,625 r.n.h.c.HttpClientOperations: [a3b5326c-1, L:/*** - R:***] Received last HTTP packet
2022-06-15 17:00:09,625 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [response_completed])
2022-06-15 17:00:09,625 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [disconnecting])
2022-06-15 17:00:09,625 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] Releasing channel
2022-06-15 17:00:09,625 r.n.r.PooledConnectionProvider: [a3b5326c, L:/*** - R:***] Channel cleaned, now: 0 active connections, 1 inactive connections and 0 pending acquire requests.

2022-06-15 17:00:10,995 r.n.r.PooledConnectionProvider: [a3b5326c, L:/*** - R:***] Channel acquired, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 17:00:10,995 r.n.h.c.HttpClientConnect: [a3b5326c-2, L:/*** - R:***] Handler is being applied: {uri=***/actuator/health, method=GET}
2022-06-15 17:00:10,995 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-2, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/health, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_prepared])
2022-06-15 17:00:10,996 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-2, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/health, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_sent])
2022-06-15 17:00:26,034 r.n.r.PooledConnectionProvider: [a3b5326c-2, L:/*** ! R:***] Channel closed, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 17:00:26,034 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-2, L:/*** ! R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/health, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** ! R:***]}}, [response_incomplete])
2022-06-15 17:00:26,034 WARN  r.n.h.c.HttpClientConnect: [a3b5326c-2, L:/*** ! R:***] The connection observed an error
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response

使用组件版本 #

• Spring Cloud Gateway 2021.0.3
• reactor-netty 1.0.19
• Java 11

问题根因 #

日志显示70MB的logfile响应传输耗时接近18秒，响应完成后连接被放回空闲池仅1秒左右，第二次复用该连接发送health请求时就触发了连接关闭报错。
该问题本质是下游的Apache服务器在完成大体积响应传输后，主动触发连接关闭逻辑，向网关侧发送FIN报文；但Reactor Netty连接池在归还连接时未检测到连接已处于半关闭状态，将不可用的连接放回了空闲队列。后续复用该连接发送请求时，客户端还未收到响应就感知到连接断开，最终抛出PrematureCloseException。
连续请求小体积的health接口时，连接占用时间短、资源消耗低，下游服务不会主动关闭连接，因此不会触发该异常。

修复方案 #

• 配置Reactor Netty客户端的连接活性检测，在从连接池获取连接时自动校验连接可用性，过滤半关闭的失效连接，参考配置如下：

@Bean
public HttpClient httpClient() {
    return HttpClient.create()
            .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 3000)
            .responseTimeout(Duration.ofSeconds(10))
            .poolConfig(PoolConfig.fromDefaults()
                    // 获取连接时懒检测空闲连接有效性
                    .idleResourceDetection(IdleResourceDetection.LAZY)
                    .build());
}

• 调整下游Web服务器（Apache/Tomcat等）的连接超时时间、最大单连接请求数配置，避免大响应传输完成后立即主动关闭连接。
• 若无需长连接复用，可直接配置禁用连接池，或调小连接最大空闲时间、最大生命周期参数，让连接在被服务端关闭前就被客户端主动回收，规避失效连接复用问题。

内容的提问来源于stack exchange，提问作者Daniel