I am getting intermittent ReadTimeOut from netty with the below error:
The connection observed an error","logger_name":"reactor.netty.http.client.HttpClientConnect","thread_name":"reactor-http-epoll-3","level":"WARN","level_value":30000,"stack_trace":"io.netty.handler.timeout.ReadTimeoutException: null
One observation we made is this particular endpoint for which we are getting this issue is a POST with no request body. I am now sending a dummy json in body now which the downstream system ignores and now I don't see this error anymore at all.
Below is my code:
protected <T, S> Mono<S> sendMonoRequest(HttpMethod method,
HttpHeaders headers,
T requestBody,
URI uri, Class<S> responseClass) throws ApiException, IOException {
log.info("Calling {} {} {} {}",
method.toString(), uri.toString(), headers.toString(), mapper.writeValueAsString(requestBody));
WebClient.RequestBodySpec requestBodySpec = getWebClient().method(method).uri(uri);
headers.keySet().stream().forEach(headerKey ->
headers.get(headerKey).stream().forEach(headerValue -> requestBodySpec.header(headerKey, headerValue)));
return requestBodySpec
.body(BodyInserters.fromObject(requestBody != null ? requestBody : ""))
.retrieve()
.onStatus(HttpStatus::is4xxClientError, this::doOn4xxError)
.onStatus(HttpStatus::is5xxServerError, this::doOn5xxError)
.onStatus(HttpStatus::isError, this::doOnError)
.bodyToMono(responseClass);
}
protected WebClient getWebClient() {
HttpClient httpClient = HttpClient.create().tcpConfiguration(
client -> client.option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 20000)
.doOnConnected(conn -> conn
.addHandlerLast(new ReadTimeoutHandler(20))
.addHandlerLast(new WriteTimeoutHandler(20))));
ClientHttpConnector connector = new ReactorClientHttpConnector(httpClient);
return WebClient.builder().clientConnector(connector)
.filter(logResponse())
.build();
}
}
To resolve the intemrittent timeouts, I have to send a dummy pojo to sendMonoRequest() for request body. Any ideas ?
Comment From: rstoyanchev
I've edited your comment to improve the formatting. You might want to check out this Mastering Markdown guide for future reference.
Comment From: rstoyanchev
Is it possible that the server does not respond and the client eventually times out? If you can enable logging in Reactor Netty with the wiretap option you can see more specifically how far it gets.
Comment From: tamanna2702
We checked the server's logs as well, they did send the response back in 247 ms but we still got a ReadTimeOut. But I will try to add the wiretap option as well now. Thanks.
Comment From: tamanna2702
Below are the logs after enabling wiretap:
{"@timestamp":"2021-05-07T12:11:11.274+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 - R:SERVER_HOST/93.191.196.166:443] Handler is being applied: {uri=https://SERVER_HOST/v4/customer-api/customers/fred/pin?api-key=CR5105B28, method=POST}","logger_name":"reactor.netty.http.client.HttpClientConnect","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:11.277+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 - R:SERVER_HOST/93.191.196.166:443] WRITE: 507B
+-------------------------------------------------+
| 0 1 2 3 4 5 6 7 8 9 a b c d e f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 4f 53 54 20 2f 76 34 2f 63 75 73 74 6f 6d 65 |POST /v4/custome|
|00000010| 72 2d 63 72 65 64 65 6e 74 69 61 6c 2d 61 70 69 |r-credential-api|
|00000020| 2f 63 75 73 74 6f 6d 65 72 73 2f 66 72 65 64 64 |/customers/fredd|
|00000030| 69 65 2f 63 61 72 64 73 2f 70 69 6e 73 3f 61 70 |ie/cards/pins?ap|
|00000040| 69 2d 6b 65 79 3d 43 52 35 31 30 35 42 32 38 44 |i-key=CR5105B28D|
|00000060| 32 46 34 32 44 38 32 38 20 48 54 54 50 2f 31 2e | HTTP/1.|
|00000070| 31 0d 0a 68 6f 73 74 3a 20 64 66 2d 61 70 69 2d |1..host: SERVER_HOST
|000000a0| 63 63 65 70 74 3a 20 2a 2f 2a 0d 0a 43 6f 6e 74 |ccept: */*..Cont|
|000000b0| 65 6e 74 2d 54 79 70 65 3a 20 61 70 70 6c 69 63 |ent-Type: applic|
|000000c0| 61 74 69 6f 6e 2f 6a 73 6f 6e 0d 0a 44 61 74 65 |ation/json..Date|
|000000d0| 3a 20 46 72 69 2c 20 30 37 20 4d 61 79 20 32 30 |: Fri, 07 May 20|
|000000e0| 32 31 20 31 31 3a 31 31 3a 31 31 20 47 4d 54 0d |21 11:11:11 GMT.|
|000000f0| 0a 75 73 65 72 2d 61 67 65 6e 74 3a 20 65 70 6f |.user-agent: epo|
|00000100| 73 32 0d 0a 78 2d 63 6c 69 65 6e 74 2d 72 65 71 |s2..x-client-req|
|00000110| 75 65 73 74 2d 69 64 3a 20 33 34 37 36 63 38 34 |uest-id: 3476c84|
|00000120| 65 2d 33 30 62 32 2d 34 66 37 39 2d 62 39 31 38 |e-30b2-4f79-b918|
|00000130| 2d 39 64 65 63 38 66 30 65 62 66 37 38 0d 0a 78 |-9dec8f0ebf78..x|
|00000140| 2d 6c 63 2d 63 69 64 3a 20 39 39 31 63 36 66 32 |-lc-cid: 991c6f2|
|00000150| 30 2d 65 36 30 34 2d 34 61 62 33 2d 61 63 39 34 |0-e604-4ab3-ac94|
|00000160| 2d 38 34 34 33 30 31 66 38 62 36 30 30 0d 0a 41 |-844301f8b600..A|
|00000170| 75 74 68 6f 72 69 7a 61 74 69 6f 6e 3a 20 42 61 |uthorization: Ba|
|00000180| 73 69 63 20 51 31 49 31 4d 54 41 31 51 6a 49 34 |sic Q1I1MTA1QjI4|
|00000190| 52 44 41 79 52 54 4d 30 4d 44 63 77 4f 45 45 34 |RDAyRTM0MDcwOEE4|
|000001a0| 51 6a 68 44 4d 6a 45 79 52 6a 51 79 52 44 67 79 |QjhDMjEyRjQyRDgy|
|000001d0| 4f 53 30 31 4f 54 4e 45 51 7a 6b 7a 51 7a 56 43 |OS01OTNEQzkzQzVC|
|000001e0| 51 7a 4d 3d 0d 0a 63 6f 6e 74 65 6e 74 2d 6c 65 |QzM=..content-le|
|000001f0| 6e 67 74 68 3a 20 30 0d 0a 0d 0a |ngth: 0.... |
+--------+-------------------------------------------------+----------------+","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"X-Span-Export":"false","X-B3-SpanId":"4320dba8a999c493","X-B3-TraceId":"4320dba8a999c493","appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:11.278+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 - R:SERVER_HOST/93.191.196.166:443] FLUSH","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"X-Span-Export":"false","X-B3-SpanId":"4320dba8a999c493","X-B3-TraceId":"4320dba8a999c493","appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:11.278+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 - R:SERVER_HOST/93.191.196.166:443] WRITE: 0B","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"X-Span-Export":"false","X-B3-SpanId":"4320dba8a999c493","X-B3-TraceId":"4320dba8a999c493","appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:31.286+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 - R:SERVER_HOST/93.191.196.166:443] The connection observed an error","logger_name":"reactor.netty.http.client.HttpClientConnect","thread_name":"reactor-http-nio-4","level":"WARN","level_value":30000,"stack_trace":"io.netty.handler.timeout.ReadTimeoutException: null
","appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:31.320+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 - R:SERVER_HOST/93.191.196.166:443] CLOSE","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:31.321+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 - R:SERVER_HOST/93.191.196.166:443] CLOSE","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"X-Span-Export":"false","X-B3-SpanId":"4320dba8a999c493","X-B3-TraceId":"4320dba8a999c493","appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:31.328+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 ! R:SERVER_HOST/93.191.196.166:443] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:31.328+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 ! R:SERVER_HOST/93.191.196.166:443] INACTIVE","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:31.329+01:00","@version":1,"message":"[id: 0xce3bc9d5, L:/10.100.3.151:54610 ! R:SERVER_HOST/93.191.196.166:443] UNREGISTERED","logger_name":"reactor.netty.http.client.HttpClient","thread_name":"reactor-http-nio-4","level":"DEBUG","level_value":10000,"appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
{"@timestamp":"2021-05-07T12:11:31.332+01:00","@version":1,"message":"Error occurred while performing the request. Message: null","logger_name":"com.base.api.BaseRestApi","thread_name":"http-nio-8080-exec-6","level":"ERROR","level_value":40000,"stack_trace":"io.netty.handler.timeout.ReadTimeoutException: null
","X-Span-Export":"false","X-B3-SpanId":"4320dba8a999c493","X-B3-TraceId":"4320dba8a999c493","appdynamic_tier_name":"APPDYNAMICS_AGENT_TIER_NAME"}
io.netty.handler.timeout.ReadTimeoutException
Comment From: rstoyanchev
There is no response content from the server it seems.
You can check the server logs for more details on how far it got, or use tcpdump via Wireshark, or try to make requests with curl and see what you get. The Content-Length: 0 in the request body at least should indicate to the server there is no content.
Comment From: spring-projects-issues
If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.
Comment From: spring-projects-issues
Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.