Reactor netty connection pool drops for no (obvious) reason and hangs.

[marosivanco]

Reactor netty connection pool drops for no (obvious) reason. As a consequence, no new HTTP request can be made and the app just hangs.

We use these metrics to monitor the pool:
reactor_netty_connection_provider_total_connections
reactor_netty_connection_provider_active_connections
reactor_netty_connection_provider_pending_connections

Expected Behavior

Total should be greater than 0.

Actual Behavior

Total suddenly dropped to 0.

Steps to Reproduce

Do not really know how to reproduce. Seems non-deterministic. It happens approximately once per 2-3 months.
There are no errors in the logs.

webClient
    .post()
    .uri("/a")
    .bodyValue(payload)
	// this seems to be the place, where it hangs (according to the logs)
    .retrieve()
    .bodyToMono(String.class)    
    //...

This is the relevant configuration:

HttpClient httpClient = HttpClient
		.create(ConnectionProvider.builder("apns")
				.lifo()
				.maxConnections(maxConnections)
				.metrics(true)
				// no limit
				.pendingAcquireMaxCount(-1)
				.pendingAcquireTimeout(Duration.ofMillis(Long.MAX_VALUE))
				.build()
		)
		.protocol(HttpProtocol.H2)
		.secure(sslSpec -> sslSpec.sslContext(mutualSslContext()))
		.option(CONNECT_TIMEOUT_MILLIS, connectTimeoutMillis)
		.responseTimeout(Duration.ofMillis(responseTimeoutMillis))
		.proxy(spec -> spec.type(HTTP).host(httpProxyHost).port(httpProxyPort));
}
return builder
		.clientConnector(new ReactorClientHttpConnector(httpClient))
		.baseUrl(serverUrl)
		.filter(new MdcLoggingExchangeFilterFunction())
		.build();

Your Environment

• Reactor version(s) used:
  reactor-core@3.4.14
  reactor-extra@3.4.6
  reactor-netty-core@1.0.15
  reactor-netty-http@1.0.15
• Other relevant libraries versions:
  all netty jars @4.1.73
  netty-tcnative-classes@2.0.46
• JVM version:
  openjdk version "11.0.13" 2021-10-19 LTS
  OpenJDK Runtime Environment 18.9 (build 11.0.13+8-LTS)
  OpenJDK 64-Bit Server VM 18.9 (build 11.0.13+8-LTS, mixed mode, sharing)
• OS and version: Linux 3.10.0-1160.11.1.el7.x86_64 MonoHttpClientChannel subscribes to Mono with a null subscriber #1 SMP Fri Dec 18 16:34:56 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

[pderop]

Hi @marosivanco,

Can you provide more informations about the context of the issue (any logs ? any exceptions ? any tcp dumps ?) because at this stage, without any reproducer sample project that we can build and test, it's difficult to imagine what could cause the issue.

One other question: is the problem happening only with 1.0.15 version or also with previous versions ? Indeed, you said that the problem happens approximately once per 2-3 months, but we have released the 1.0.15 version only since last 11th jan ?

thanks

[marosivanco]

Hi @pderop,

I realize there is not much I provide for targeting the issue.
The logs contain no error/exception at the time. I deduced that the webclient hangs because I see log records "I am going to make a webClient call" but no record "Finished".

The instance makes 2 - 3M requests for the issue to manifest. The hanging can be caused by erroneous server or a network infrastructure. I doubt the test project would help here.
The issue also happened prior 1.0.15, although less loggers were turned on, so I cannot confirm the hanging in the webClient.

I see two features of the configuration that are not typical:

• Unlimited pool with infinite acquire timeout. Can this somehow affect the pool resize logic?
• HTTP2 with mutual authentication. Can server certificate change or erroneous handshake lead to such state?

I do not really know how to approach it. All I could get to are these questions:

1. What are the possible reasons for the total connections dropping to zero?
2. Which reactor logs should I turn on to help the investigation?
3. Is there anything else I can do? (turn something on/off in the configuration or any other idea)

Maros.

[marosivanco]

@pderop, @violetagg, could you please point me to the place where is the pool resize logic located? (class/module/project) I am kind of lost in the reactor-* sources...

[violetagg]

@marosivanco I'm seeing that you configured the client for HTTP/2.

For Reactor Netty version < 1.0.14 we use the standard Reactor Pool implementation https://github.com/reactor/reactor-pool/blob/main/src/main/java/reactor/pool/SimpleDequePool.java
with allocation strategy https://github.com/reactor/reactor-pool/blob/edc56c0518575e069839b43a1364a84c9edcc95f/src/main/java/reactor/pool/AllocationStrategies.java#L73

For Reactor Netty version >= 1.0.14 we switched to Reactor Netty specific implementation https://github.com/reactor/reactor-netty/blob/main/reactor-netty-http/src/main/java/reactor/netty/http/client/Http2Pool.java, still using the same allocation strategy as before https://github.com/reactor/reactor-pool/blob/edc56c0518575e069839b43a1364a84c9edcc95f/src/main/java/reactor/pool/AllocationStrategies.java#L73

We do have some fixes with the version 1.0.16 (that we released yesterday), but I cannot say whether they are relevant for your use case.

[marosivanco]

Happened again few days ago. The 1.0.16 patch contains lot of HTTP2 changes, I hope some of them will help. Updated JDK, spring-boot, reactor core and netty.

Environment Update

JVM: OpenJDK 64-Bit Server VM (17.0.1+12, mixed mode, sharing)
Java: version 17.0.1, vendor Red Hat, Inc.
reactor-core@3.4.15
reactor-netty-core@1.0.16
reactor-netty-http@1.0.16

[mgeissen]

We can confirm this issue for our service with reactor-netty version 1.0.16. We found out that the total connection size is decreasing over time until it drops to zero.

Note: The vertical markers in the graph are deployments or autoscaling events.

Our webclient is executing ~160 request/second to different targets. We only see that behavior for targets that are highly under load.

Here is our webclient configuration:

val connectionProvider = ConnectionProvider.builder("connectionprovider")
    .maxConnections(10)
    .metrics(true)
    .build()

val httpClient: reactor.netty.http.client.HttpClient = reactor.netty.http.client.HttpClient.create(connectionProvider)
    .protocol(HttpProtocol.H2, HttpProtocol.HTTP11)
    .secure()
    .compress(true)
    .followRedirect(true)

webClientBuilder
    .clientConnector(ReactorClientHttpConnector(httpClient))
    .build()

This happens for us after upgrading from Spring Boot 2.6.1 to 2.6.4.

For now, we pin the version of reactor-netty to 1.0.13.

[violetagg]

@mgeissen Do you observe exceptions in the logs?

[mgeissen]

@violetagg The only exception during the time (round about 150 times) of the graph is the following:

Exception: io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection reset by peer
Message: An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.

We do not have a stacktrace for this exception in our logs.

[violetagg]

@mgeissen That's very strange. You run with ERROR log level or you have some additional logs, for example logs from Http2ConnectionProvider.

[mgeissen]

@violetagg There is exactly one more exception (at the time of the drop to zero for one of the instances). But we had three instances and the connections drops for every instance to zero. It sounds a little bit strange that one exception leads to errors on all instances. But apart of that there are no more exceptions and no further error logs from netty.

java.lang.NullPointerException: Cannot invoke "io.netty.handler.codec.http2.Http2FrameCodec.connection()" because "frameCodec" is null
	at reactor.netty.http.client.Http2ConnectionProvider$DisposableAcquire.operationComplete(Http2ConnectionProvider.java:320)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552)
	at io.netty.util.concurrent.DefaultPromise.access$200(DefaultPromise.java:35)
	at io.netty.util.concurrent.DefaultPromise$1.run(DefaultPromise.java:502)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)