Hang with max pool connections 1 and response_incomplete

[stu-mcd]

FYI I no nothing about reactor-netty however I came across the following whilst investigating a Java Azure blob storage read problem

With a PooledConnectionProvider with max connections 1 I am reading from an Azure blob (which internally uses reactor-netty). So the debug output looks like

### READ PART

2020-02-19 10:14:10.298 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX]  onStateChange(GET{uri=YYY, connection=PooledConnection{channel=[id: 0xa380713b, L:/IPADDR:41618 - R:XXX]}}, [disconnecting])
2020-02-19 10:14:10.298 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Releasing channel
2020-02-19 10:14:10.298 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Channel cleaned, now 0 active connections and 1 inactive connections
2020-02-19 10:14:10.299 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Channel acquired, now 1 active connections and 0 inactive connections
2020-02-19 10:14:10.299 DEBUG HttpClientConnect : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Handler is being applied: {uri=YYY, method=GET}
2020-02-19 10:14:10.300 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] onStateChange(GET{uri=YYY, connection=PooledConnection{channel=[id: 0xa380713b, L:/IPADDR:41618 - R:XXX]}}, [request_sent])
2020-02-19 10:14:10.464 DEBUG HttpClientOperations : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Received response (auto-read:false) : [Content-Length=1000, Content-Type=application/octet-stream, Content-Range=bytes 31737266000-31737266999/36285207380, Last-Modified=Sat, 04   Jan 2020 19:29:19 GMT, Accept-Ranges=bytes, ETag="0x8D7914C653EE0E0", Server=Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0, x-ms-request-id=c2a4c0e7-901e- 0089-190d-e78136000000, x-ms-client-request-id=9764e16d-6c0e-4f1a-afbe-d7adbae3e5ce, x-ms-version=2019-02-02, x-ms-meta-earliestExpiry=1609545600, x-ms-  meta-                     orgs=2tQ529v9TgAAlHFk, x-ms-creation-time=Sat, 04 Jan 2020 19:29:19 GMT, x-ms-lease-status=unlocked, x-ms-lease-                state=available, x-ms-blob-               type=BlockBlob, x-ms-server-encrypted=true, Date=Wed, 19 Feb 2020 10:14:09 GMT]
2020-02-19 10:14:10.465 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] onStateChange(GET{uri=YYY, connection=PooledConnection{channel=[id: 0xa380713b, L:/IPADDR:41618 - R:XXX]}},                   [response_received])
2020-02-19 10:14:10.480 DEBUG FluxReceive : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Subscribing inbound receiver [pending: 0, cancelled: false, inboundDone: false]
2020-02-19 10:14:10.480 DEBUG HttpClientOperations : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Received last HTTP packet
### READ PART
2020-02-19 10:14:10.480 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] onStateChange(GET{uri=YYY, connection=PooledConnection{channel=[id: 0xa380713b, L:/IPADDR:41618 - R:XXX]}}, [disconnecting])
2020-02-19 10:14:10.480 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Releasing channel
2020-02-19 10:14:10.480 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Channel cleaned, now 0 active connections and 1 inactive connections
2020-02-19 10:14:10.482 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Channel acquired, now 1 active connections and 0 inactive connections
2020-02-19 10:14:10.482 DEBUG HttpClientConnect : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Handler is being applied: {uri=YYY, method=GET}
2020-02-19 10:14:10.483 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] onStateChange(GET{uri=YYY, connection=PooledConnection{channel=[id: 0xa380713b, L:/IPADDR:41618 - R:XXX]}}, [request_sent])
2020-02-19 10:14:10.566 DEBUG HttpClientOperations : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Received response (auto-read:false) : [Content-Length=1000, Content-Type=application/octet-stream, Content-Range=bytes 31003928000-31003928999/36285207380, Last-Modified=Sat, 04   Jan 2020 19:29:19 GMT, Accept-Ranges=bytes, ETag="0x8D7914C653EE0E0", Server=Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0, x-ms-request-id=c2a4c1c3-901e- 0089-670d-e78136000000, x-ms-client-request-id=ba2df722-04d4-4152-af70-b71d56bb7546, x-ms-version=2019-02-02, x-ms-meta-earliestExpiry=1609545600, x-ms-meta-orgs=2tQ529v9TgAAlHFk, x-ms-creation-time=Sat, 04 Jan 2020 19:29:19 GMT, x-ms-lease-status=unlocked, x-ms-lease-state=available, x-ms-blob-type=BlockBlob, x-ms-server-encrypted=true, Date=Wed, 19 Feb 2020 10:14:09 GMT]
2020-02-19 10:14:10.566 DEBUG PooledConnectionProvider : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] onStateChange(GET{uri=YYY, connection=PooledConnection{channel=[id: 0xa380713b, L:/IPADDR:41618 - R:XXX]}},                   [response_received])
2020-02-19 10:14:10.575 DEBUG FluxReceive : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Subscribing inbound receiver [pending: 0, cancelled: false, inboundDone: false]
2020-02-19 10:14:10.575 DEBUG HttpClientOperations : [id: 0xa380713b, L:/IPADDR:41618 - R:XXX] Received last HTTP packet

Note that my code and the Azure read are all single threaded and blocking.

I then force a tcp reset using iptables e.g.

iptables -A OUTPUT -d 20.38.109.4 -p tcp -j REJECT --reject-with tcp-reset; sleep 1;  iptables -F OUTPUT

This causes AbstractEpollStreamChannel.epollInReady() to catch a "connection reset by peer" and call handleReadException. This is generally handled fine, however if it occurs after the "response_received" it will hang until the Azure timeout for the read triggers.
The logs show "An outbound error could not be processed (Connection closed BEFORE response" (here are the stacks)

  at reactor.netty.channel.ChannelOperations.onError(ChannelOperations.java:208)
  at reactor.core.publisher.Operators.error(Operators.java:182)
  at reactor.core.publisher.MonoError.subscribe(MonoError.java:52)
  at reactor.core.publisher.Mono.subscribe(Mono.java:4105)
  at reactor.netty.NettyOutbound.subscribe(NettyOutbound.java:329)
  at reactor.core.publisher.MonoSource.subscribe(MonoSource.java:58)
  at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
  at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:430)
  at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:503)
  at reactor.netty.resources.PooledConnectionProvider$DisposableAcquire.run(PooledConnectionProvider.java:574)
  at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:164)
  at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:-1)
  at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
  at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:388)
  at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
  at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
  at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
  at java.lang.Thread.run(Thread.java:834)

Creation of the AbortedException

at reactor.netty.http.HttpOperations.then(HttpOperations.java:157)
at reactor.netty.NettyOutbound.subscribe(NettyOutbound.java:329)
at reactor.core.publisher.MonoSource.subscribe(MonoSource.java:58)
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:430)
at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:503)
at reactor.netty.resources.PooledConnectionProvider$DisposableAcquire.run(PooledConnectionProvider.java:574)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:388)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
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:834)

This all causes the PooledConnectionProvider.run() ChannelOperations ops variable to have a channel which is not active. i.e.

ChannelOperations<?, ?> ops = opsFactory.create(pooledConnection, pooledConnection, null);
if (ops != null) {
    ops.bind();
    obs.onStateChange(ops, State.CONFIGURED);
    sink.success(ops);

The ops.channel().isActive() is FALSE, which (though I don't know reactor-netty) seems wrong

Note that though I am using a pool size of 1, the problem seems to be if the pool is full e.g. I have managed to reproduce it using a pool size of 2 (because of the test I can't get Azure to use more than 2 connections).

Steps to Reproduce

Unfortunately since I am using Azure which calls reactor-netty I don't have a way to reproduce without using azure and having access to an Azure blob storage file. Also, it is hard to trigger the reset at the correct time to cause the issue. However I can reproduce this locally in Intellij so I can run any tests or provide any further information as required.

Your Environment

I am using 0.9.4.RELEASE reactor-netty, java 11.0.3 and

io.netty:netty:3.10.6.Final
io.netty:netty-buffer:4.1.44.Final
io.netty:netty-codec:4.1.44.Final
io.netty:netty-codec-http2:4.1.42.Final
io.netty:netty-codec-http:4.1.42.Final
io.netty:netty-codec-socks:4.1.42.Final
io.netty:netty-common:4.1.44.Final
io.netty:netty-handler:4.1.44.Final
io.netty:netty-handler-proxy:4.1.42.Final
io.netty:netty-resolver:4.1.44.Final
io.netty:netty-tcnative-boringssl-static:2.0.26.Final
io.netty:netty-transport:4.1.44.Final
io.netty:netty-transport-native-epoll:4.1.42.Final
io.netty:netty-transport-native-unix-common:4.1.42.Final

I am running on Ubuntu
Linux XXX 4.15.0-64-generic #73-Ubuntu SMP Thu Sep 12 13:16:13 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
netty is using native epoll.

[stu-mcd]

I just tried to hack a "fix", not having a clue how all this works this is of course not what I would expect a proper fix to look like. I changed PooledConnectProvider.run to check that the channel was active and if not to try and flag an error

else if (current == null || !c.isActive()) { // #### Also close if channel not active
    registerClose(pooledRef, pool);
}
if (current != null) {
    if (log.isDebugEnabled()) {
        log.debug(format(c, "Channel acquired, now {} active connections and {} inactive connections"), pool.metrics().acquiredSize(), pool.metrics().idleSize());
    }
    obs.onStateChange(pooledConnection, State.ACQUIRED);

    ChannelOperations<?, ?> ops = opsFactory.create(pooledConnection, pooledConnection, null);
    if (ops != null) {
        ops.bind();
        if (ops.channel().isActive()) {  // ### Check that channel is active
            obs.onStateChange(ops, State.CONFIGURED);
            sink.success(ops);
        } else {
            obs.onStateChange(ops, State.RELEASED);
            sink.error(new AbortedException("Channel should be active"));
    }
}

Which certainly allowed it to recover and continue reading instead of hanging.

[stu-mcd]

Here is the debug logging for when it fails

READ PART: 10345512
2020-02-19 13:53:47.523 DEBUG PooledConnectionProvider : [id: 0xa0f5c3c1, L: - onStateChange(GET{uri=, connection=PooledConnection{channel=[id: 0xa0f5c3c1, L: - R:]}}, [disconnecting])
2020-02-19 13:53:47.523 DEBUG PooledConnectionProvider : [id: 0xa0f5c3c1, L: - R:] Releasing channel
2020-02-19 13:53:47.523 DEBUG PooledConnectionProvider : [id: 0xa0f5c3c1, L: - R:] Channel cleaned, now 0 active connections and 1 inactive connections

io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection reset by peer

2020-02-19 13:53:47.586 DEBUG PooledConnectionProvider : [id: 0xa0f5c3c1, L: ! R:] Channel closed, now 1 active connections and 0 inactive connections
2020-02-19 13:53:47.587 DEBUG PooledConnectionProvider : [id: 0xa0f5c3c1, L: ! R:] Channel acquired, now 1 active connections and 0 inactive connections
2020-02-19 13:53:47.587 DEBUG HttpClientConnect : [id: 0xa0f5c3c1, L: ! R:] Handler is being applied: {uri=, method=GET}
2020-02-19 13:53:47.587 DEBUG ChannelOperations : [id: 0xa0f5c3c1, L: ! R:] An outbound error could not be processed    reactor.netty.channel.AbortedException: Connection has been closed BEFORE response
2020-02-19 13:53:47.588 DEBUG PooledConnectionProvider : [id: 0xa0f5c3c1, L: ! R:] onStateChange(GET{uri=, connection=PooledConnection{channel=[id: 0xa0f5c3c1, L: ! R:]}}, [response_incomplete])
2020-02-19 13:53:55.865  WARN HttpClientConnect : [id: 0xa0f5c3c1, L: ! R:] The connection observed an error    reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response

[violetagg]

@stu-mcd Can you test 0.9.6.BUILD-SNAPSHOT? It might be related to #1017

[stu-mcd]

Hi. I'll be able to give this a try on either Wed or Thurs. Thanks.

[stu-mcd]

Just gave it a quick run. It doesn't fix the problem and there is now a java cast exception

FAIL-LOG.txt

Sorry, not had the time to look through this fully.

[violetagg]

@stu-mcd Can you try again the snapshot
I fixed the class cast 280eb77
and added check for channel not active aa4eb30

[stu-mcd]

That seems to work now. The log it notes the premature close (depending on when the reset occurs) and then the SslProvider being init'ed.
WORK-log.txt