Stuck Active Connections

[pavelkuchin]

We are having an issues with stuck active connections. At some arbitrary moments number of active connections starts growing till exhaustion of connection pool. Usually it happens few times a day and gets back to normal after service restart. We can't reproduce the issue with integration or load tests and can't correlate it with load. Once number of active connections is growing CPU consumption spikes to 100% and most active threads are reactor-http-epoll. It started at night from November 20 to 21 and since than happens at least few times a day. Last deployment was on Wednesday and we did't have any infrastructure changes on the night on our side. The service is on AWS ECS.

Expected Behavior

Number of active connection should not grow till pool exhaustion.

Actual Behavior

Connections pool gets exhausted by growing number of active connections.

Steps to Reproduce

Reproducible only on production environment at arbitrary moments.

Possible Solution

The only solution we found is to restart the service on regular basis.

Your Environment

• Reactor version(s) used: Dysprosium-SR14

• Reactor Netty: 0.9.14

• JVM version (java -version):
  openjdk 11.0.9 2020-10-20
  OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.9+11)
  OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.9+11, mixed mode)

• OS and version (eg. uname -a): Linux 1e0330d34cf6 4.14.200-155.322.amzn2.x86_64 MonoHttpClientChannel subscribes to Mono with a null subscriber #1 SMP Thu Oct 15 20:11:12 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

[violetagg]

@pavelkuchin Please provide some code how the client is configured and used.
Tell us whether you use exchange or retrieve. With exchange if you do not consume the response body you can cause memory leak and/or connection leak.

[yangbongsoo]

@violetagg Hello I have question about exchange use.
for example, response is success but response status code is 500 and has a response body,
in below code, result.getBody(); method doesn't called. that cause memory leak?

or in onErrorResume, that cause memory leak?
thanks in advance :)

.exchange()
.flatMap(res -> res.toEntity(String.class))
.doOnNext(result -> {
	if (result.getStatusCode() != HttpStatus.OK) {
		throw new RequestFailException();
	}
})
.retryWhen(Retry.any().fixedBackoff(Duration.ofMillis(500)).retryMax(1)
		.doOnRetry((context) -> {
			logger.info("just for log : ", context.exception());
		}))
.doOnSuccess(
		result -> {
				if (result.getStatusCode() == HttpStatus.OK) {
					String body = result.getBody();
				} else {
					// 1. can cause memory leak???
				}
		})
.onErrorResume(error -> {
	// 2. if retry count is over and fail again, can cause memory leak???
	return just(new ResponseEntity<>(HttpStatus.INTERNAL_SERVER_ERROR));
});

[rstoyanchev]

I have question about exchange use.
for example, response is success but response status code is 500 and has a response body,
in below code, result.getBody(); method doesn't called. that cause memory leak?

Yes it can. I suggest using .retrieve().toEntity(String.class). This automatically turns 4xx-5xx status codes into a WebClientResponseException which includes the body content. You can add an additional .onStatus handler to reject any other 2xx-3xx status codes besides OK if necessary.

[pavelkuchin]

Hi Violeta, thanks for getting back so quickly. Here is one example but all our clients are using retrieve method:

        return webClient
                .post()
                .uri(String.format(BASIC_API_URI, apiKey))
                .contentType(MediaType.APPLICATION_JSON)
                .bodyValue(request.getT1())
                .retrieve()
                .bodyToMono(ApiResponse.class)
                .transform(r -> ReactiveUtils.enableMetricsForMono(r, "metric_name"))
                .timeout(Duration.ofSeconds(30))
                .transform(this::handleErrorsAndRetryWithBackoff)
                .flatMapMany(response -> toTranslatedTextOrTranslationError(response, request.getT2()));

and here is initial client configuration:

        HttpClient httpClient = HttpClient.create(
                ConnectionProvider.builder("x")
                        .metrics(true)
                        .build()
        );

        return WebClient.builder()
                .clientConnector(new ReactorClientHttpConnector(httpClient))
                .baseUrl("https://x.com")
                .build();

After experiments we got this, but neither from the settings helped:

        HttpClient httpClient = HttpClient.create(
                ConnectionProvider.builder("x")
                        .pendingAcquireMaxCount(256)
                        .maxConnections(52)
                        .maxIdleTime(Duration.ofSeconds(30))
                        .maxLifeTime(Duration.ofSeconds(60))
                        .evictInBackground(Duration.ofMinutes(5))
                        .metrics(true)
                        .build()
        );

        return WebClient.builder()
                .clientConnector(new ReactorClientHttpConnector(httpClient))
                .baseUrl("https://x.com")
                .build();

[pavelkuchin]

Here are some logs which I think might be related to the problem:

11/29/20
7:38:19.513 PM    
2020-11-30 00:38:19,513 +0000 [reactor-http-epoll-1] [DEBUG] (r.n.r.PooledConnectionProvider:?) [8bbde608-86d7-40e2-90ee-6b84797e9243#jkto] - [id: 0xe31e9eb0, L:/masked:masked - R:masked/masked:masked] Channel connected, now 2 active connections and 0 inactive connections
host = masked/c03060e213b3 source = masked.log sourcetype = log4j
11/29/20
7:38:19.513 PM    
2020-11-30 00:38:19,513 +0000 [reactor-http-epoll-1] [DEBUG] (r.n.r.PooledConnectionProvider:?) [8bbde608-86d7-40e2-90ee-6b84797e9243#jkto] - [id: 0xe31e9eb0, L:/masked:masked - R:masked/masked:masked] Registering pool release on close event for channel
host = masked/c03060e213b3 source = masked.log sourcetype = log4j
11/29/20
7:38:19.511 PM    
2020-11-30 00:38:19,511 +0000 [reactor-http-epoll-1] [DEBUG] (reactor.netty.tcp.SslProvider:?) [44e53d93-1496-4b4c-bf3c-c528d6ac4a16#un4m] - [id: 0xe31e9eb0] SSL enabled using engine SSLEngineImpl and SNI masked:masked
host = masked/c03060e213b3 source = masked.log sourcetype = log4j
11/29/20
7:37:58.133 PM    
2020-11-30 00:37:58,133 +0000 [reactor-http-epoll-3] [DEBUG] (r.n.r.PooledConnectionProvider:?) [bd61425b-58c0-4482-beb8-6970913b46cb#hzsb] - [id: 0x675d970b, L:/masked:masked ! R:masked/masked:masked] onStateChange(PooledConnection{channel=[id: 0x675d970b, L:/masked:masked ! R:masked/masked:masked]}, [disconnecting])
host = masked/c03060e213b3 source = masked.log sourcetype = log4j
11/29/20
7:37:27.964 PM    
2020-11-30 00:37:27,964 +0000 [reactor-http-epoll-3] [DEBUG] (r.n.r.PooledConnectionProvider:?) [bd61425b-58c0-4482-beb8-6970913b46cb#hzsb] - [id: 0x675d970b, L:/masked:masked - R:masked/masked:masked] Channel cleaned, now 0 active connections and 1 inactive connections
host = masked/c03060e213b3 source = masked.log sourcetype = log4j
11/29/20
7:37:27.963 PM    
2020-11-30 00:37:27,963 +0000 [reactor-http-epoll-3] [DEBUG] (r.n.r.PooledConnectionProvider:?) [bd61425b-58c0-4482-beb8-6970913b46cb#hzsb] - [id: 0x675d970b, L:/masked:masked - R:masked/masked:masked] Releasing channel

Unfortunately here I can only see that some other active connection appears from nowhere, maybe there is way to get more detailed log?

[pavelkuchin]

It turned out that one of our clients (one out of 7) uses exchange, and in case of some errors response body might not be used. Can it be that leak in one client affects all others? I'll migrate the client to use retrieve and try with the change.

[violetagg]

It turned out that one of our clients (one out of 7) uses exchange, and in case of some errors response body might not be used. Can it be that leak in one client affects all others? I'll migrate the client to use retrieve and try with the change.

If you use the default HttpResources, this means that all clients share the event loop and connection pool.
Also if you use one and the same HttpClient for many WebClients again they will share the connection pool.

[pavelkuchin]

Hi Violeta, thank you so much for helping with this. It seems it was related to exchange call and responses without valid json so their processing was failing without releasing body. I knew that exchange may cause memory leak but our memory metric didn't show any signs of leak and instead we got the stuck active connections which I didn't anticipate. Closing the issue now.

[pavelkuchin]

Unfortunately I have to reopen this one, we got the issue back today even although we don't have exchange calls anymore.