Reactor-netty: Spring Webclient Read Timeout after being idle for several minutes

[phantomedc]

i reproduced this problem in my dev envrionment,I did 4 requests at 2019-09-06 00:10:14.739(t1)、2019-09-06 00:19:51.274(t2)、2019-09-06 00:30:37.992(t3)、2019-09-06 00:33:13.314(t4)，
the request1(at t1), request2(at t2) webclient didn't idle too long time, the requests were processed fine, but request3(at t3), webclient was idle 10minutes, webclient got Read Timeout, then i did request4 , it was processed fine as well.
and i noticed that request1、request2、request3，they used same local port: 59838
but request4 used local port:60928

so i guess that: the connection(or channel in netty) will be cached in the connection pool, reactor netty will manage and reuse it, but when the connection idle too long, the connection may be closed or cut down by remote side(F5 loadbalance or Nginx?) or some other reason, it became disconnected on the link layer, but the connection pool did not realize what happened actually, the connection pool still thinks this connection is connected and provide it to webclient, and boom: read time out.

        HttpClient httpClient = HttpClient.create()
                .tcpConfiguration(tcpClient -> {
                    tcpClient = tcpClient.option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 5000);
                    tcpClient = tcpClient.doOnConnected(conn -> conn
                            .addHandlerLast(new ReadTimeoutHandler(15000, TimeUnit.MILLISECONDS)));
                    return tcpClient;
                });

request1:

2019-09-06 00:10:14.768 [reactor-http-kqueue-5] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x0759376f, L:/10.49.3.9:59838 - R:****.com/****:****] Received response (auto-read:false) : [Server=nginx, Date=Thu, 05 Sep 2019 16:10:15 GMT, Content-Type=application/json, Content-Length=64, Connection=keep-alive, Access-Control-Allow-Headers=Accept, Accept-Encoding, Authorization, Content-Type, Origin, Access-Control-Allow-Methods=GET, OPTIONS, Access-Control-Expose-Headers=Date, Vary=Accept-Encoding, Access-Control-Allow-Credentials=true]
2019-09-06 00:10:14.768 [reactor-http-kqueue-5] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x0759376f, L:/10.49.3.9:59838 - R:****.com/****:****] onStateChange(GET{uri=/api/v1/query?time=1567439463&query****), connection=PooledConnection{channel=[id: 0x0759376f, L:/10.49.3.9:59838 - R:****/****:****]}}, [response_received])
2019-09-06 00:10:14.768 [reactor-http-kqueue-5] DEBUG o.s.web.reactive.function.client.ExchangeFunctions - [1807c047] Response 200 OK

request2:

2019-09-06 00:19:51.272 [reactor-http-kqueue-5] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x0759376f, L:/10.49.3.9:59838 - R:****.com/****:****] Received response (auto-read:false) : [Server=nginx, Date=Thu, 05 Sep 2019 16:19:51 GMT, Content-Type=application/json, Content-Length=64, Connection=keep-alive, Access-Control-Allow-Headers=Accept, Accept-Encoding, Authorization, Content-Type, Origin, Access-Control-Allow-Methods=GET, OPTIONS, Access-Control-Expose-Headers=Date, Vary=Accept-Encoding, Access-Control-Allow-Credentials=true]
2019-09-06 00:19:51.272 [reactor-http-kqueue-5] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x0759376f, L:/10.49.3.9:59838 - R:****.com/****:****] onStateChange(GET{uri=/api/v1/query?time=1567439463&query=****), connection=PooledConnection{channel=[id: 0x0759376f, L:/10.49.3.9:59838 - R:****.com/***:***]}}, [response_received])
2019-09-06 00:19:51.272 [reactor-http-kqueue-5] DEBUG o.s.web.reactive.function.client.ExchangeFunctions - [1a576a1] Response 200 OK

request3:

2019-09-06 00:30:52.998 [reactor-http-kqueue-5] WARN  reactor.netty.http.client.HttpClientConnect - [id: 0x0759376f, L:/10.49.3.9:59838 - R:njyh.data.promes.cloudytrace.com/10.104.232.131:9801] The connection observed an error
io.netty.handler.timeout.ReadTimeoutException: null
    Suppressed: java.lang.Exception: #block terminated with an error

request4:

2019-09-06 00:33:13.338 [reactor-http-kqueue-3] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x47c1f6c3, L:/10.49.3.9:60928 - R:****.com/****:****] Received response (auto-read:false) : [Server=nginx, Date=Thu, 05 Sep 2019 16:33:13 GMT, Content-Type=application/json, Content-Length=64, Connection=keep-alive, Access-Control-Allow-Headers=Accept, Accept-Encoding, Authorization, Content-Type, Origin, Access-Control-Allow-Methods=GET, OPTIONS, Access-Control-Expose-Headers=Date, Vary=Accept-Encoding, Access-Control-Allow-Credentials=true]
2019-09-06 00:33:13.338 [reactor-http-kqueue-3] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x47c1f6c3, L:/10.49.3.9:60928 - R:****.com/****:***] onStateChange(GET{uri=/api/v1/query?time=1567439463&query=****), connection=PooledConnection{channel=[id: 0x47c1f6c3, L:/10.49.3.9:60928 - R:****.com/***:****]}}, [response_received])
2019-09-06 00:33:13.338 [reactor-http-kqueue-3] DEBUG o.s.web.reactive.function.client.ExchangeFunctions - [11c0862d] Response 200 OK

sorry for my poor english

[violetagg]

@phantomedc Reactor Netty version? Can you take a tcpdump?

[phantomedc]

@violetagg Thanks for your reply!

<groupId>io.projectreactor.netty</groupId>
<artifactId>reactor-netty</artifactId>
<version>0.8.9.RELEASE</version>

11:12:41the first request was processed fine
11:28:45 the second one read timeout
11:29:11 after read timeout the 3rd request was processed fine

11:12:41.840537 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [S], seq 68201048, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 390221157 ecr 0,sackOK,eol], length 0
11:12:41.841310 IP 10.104.232.131.sstp-2 > 10.49.3.156.50993: Flags [S.], seq 3016846198, ack 68201049, win 14480, options [mss 1460,nop,wscale 2,sackOK,TS val 2230794084 ecr 390221157], length 0
11:12:41.841380 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [.], ack 1, win 2058, options [nop,nop,TS val 390221158 ecr 2230794084], length 0
11:12:41.842435 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 1:485, ack 1, win 2058, options [nop,nop,TS val 390221159 ecr 2230794084], length 484
11:12:41.866401 IP 10.104.232.131.sstp-2 > 10.49.3.156.50993: Flags [P.], seq 1:521, ack 485, win 5068, options [nop,nop,TS val 2230794090 ecr 390221159], length 520
11:12:41.866434 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [.], ack 521, win 2050, options [nop,nop,TS val 390221180 ecr 2230794090], length 0
11:28:45.572117 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391167785 ecr 2230794090], length 484
11:28:45.618638 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391167830 ecr 2230794090], length 484
11:28:45.852872 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391168060 ecr 2230794090], length 484
11:28:46.119186 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391168321 ecr 2230794090], length 484
11:28:46.445735 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391168641 ecr 2230794090], length 484
11:28:46.890879 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391169081 ecr 2230794090], length 484
11:28:47.583606 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391169761 ecr 2230794090], length 484
11:28:48.760874 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391170921 ecr 2230794090], length 484
11:28:50.907376 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391173041 ecr 2230794090], length 484
11:28:53.057891 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391175161 ecr 2230794090], length 484
11:28:55.218305 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391177281 ecr 2230794090], length 484
11:28:57.373014 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391179401 ecr 2230794090], length 484
11:28:59.528808 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [P.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391181521 ecr 2230794090], length 484
11:29:00.572628 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [F.], seq 969, ack 521, win 2050, options [nop,nop,TS val 391182547 ecr 2230794090], length 0
11:29:01.689753 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [FP.], seq 485:969, ack 521, win 2050, options [nop,nop,TS val 391183641 ecr 2230794090], length 484
11:29:03.841005 IP 10.49.3.156.50993 > 10.104.232.131.sstp-2: Flags [R.], seq 970, ack 521, win 2050, length 0
11:29:11.083584 IP 10.49.3.156.51614 > 10.104.232.131.sstp-2: Flags [S], seq 827103750, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 391192881 ecr 0,sackOK,eol], length 0
11:29:11.084397 IP 10.104.232.131.sstp-2 > 10.49.3.156.51614: Flags [S.], seq 2056207990, ack 827103751, win 14480, options [mss 1460,nop,wscale 2,sackOK,TS val 2231041402 ecr 391192881], length 0
11:29:11.084428 IP 10.49.3.156.51614 > 10.104.232.131.sstp-2: Flags [.], ack 1, win 2058, options [nop,nop,TS val 391192881 ecr 2231041402], length 0
11:29:11.085716 IP 10.49.3.156.51614 > 10.104.232.131.sstp-2: Flags [P.], seq 1:485, ack 1, win 2058, options [nop,nop,TS val 391192883 ecr 2231041402], length 484
11:29:11.108293 IP 10.104.232.131.sstp-2 > 10.49.3.156.51614: Flags [P.], seq 1:521, ack 485, win 4344, options [nop,nop,TS val 2231041408 ecr 391192883], length 520
11:29:11.108325 IP 10.49.3.156.51614 > 10.104.232.131.sstp-2: Flags [.], ack 521, win 2050, options [nop,nop,TS val 391192904 ecr 2231041408], length 0

[phantomedc]

i found it may related to the loadbalance device,
when i connect to the nginx directly,

reactor-netty will receive a FIN flag after being idle for a while(15 seconds in my case):

2019-09-09 15:17:29.110 [reactor-http-kqueue-8] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0xaa7d195c, L:/10.49.3.156:60372 ! R:10.47.197.7/10.47.197.7:9800] Channel closed, now 0 active connections and 0 inactive connections
2019-09-09 15:17:29.110 [reactor-http-kqueue-8] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0xaa7d195c, L:/10.49.3.156:60372 ! R:10.47.197.7/10.47.197.7:9800] onStateChange(PooledConnection{channel=[id: 0xaa7d195c, L:/10.49.3.156:60372 ! R:10.47.197.7/10.47.197.7:9800]}, [disconnecting])

15:17:29.110286 IP 10.47.197.7.davsrc > 10.49.3.156.60372: Flags [F.], seq 440, ack 523, win 122, options [nop,nop,TS val 3455629232 ecr 404632248], length 0
15:17:29.110371 IP 10.49.3.156.60372 > 10.47.197.7.davsrc: Flags [.], ack 441, win 2052, options [nop,nop,TS val 404647118 ecr 3455629232], length 0
15:17:29.110570 IP 10.49.3.156.60372 > 10.47.197.7.davsrc: Flags [F.], seq 523, ack 441, win 2052, options [nop,nop,TS val 404647118 ecr 3455629232], length 0
15:17:29.110874 IP 10.47.197.7.davsrc > 10.49.3.156.60372: Flags [.], ack 524, win 122, options [nop,nop,TS val 3455629233 ecr 404647118], length 0

but when the whole link is:

reactor-netty won't receive a FIN flag from remote side, so the connection won't be handled, until the next request comming, just like the tcpdump log in my last comment.

[violetagg]

@phantomedc If we do not receive FIN for us this connection is still alive. Then the ReadTimeoutHandler will close it because of the timeout.

[phantomedc]

@phantomedc If we do not receive FIN for us this connection is still alive. Then the ReadTimeoutHandler will close it because of the timeout.

yes, it is not reactor netty's bug, i'm gonna close this issue

[gearora]

@phantomedc What solution did you implement to solve the timeouts then?

[benweet]

Using kotlin coroutines with spring boot 2.2, I had this typical issue because the netty server and the webclient were sharing the same event loop, which caused the server to hang under heavy load as all the workers were used by one or the other (only 4 threads by default if server cpu <= 4).

The fix was to use another event loop for all the webclients, keeping the main one dedicated to handling the server requests:

ReactorClientHttpConnector sharedConnector = new ReactorClientHttpConnector(
    HttpClient.create().runOn(LoopResources.create("reactor-webclient")
)

[phantomedc]

@phantomedc What solution did you implement to solve the timeouts then?

it is my loadbalancing device's problem, i change it from http to tcp to disable connections reusing

[asarkar]

@benweet With 0.9.8.RELEASE, there's no runOn method on the HttpClient; there's one on the TcpClient though.