Connection exception occurred, but Pushy still used it

[extraSix]

We found that APNs connection exception occurred, but Pushy still used it.

22:07:00,458 ~ 22:07:00,896 `nioEventLoopGroup-25-1` 1117 errors: IOException: Stream closed before a reply was received
22:07:00,590 `nioEventLoopGroup-25-3` The last `handleNotificationAccepted` for `nioEventLoopGroup-25-3` before `nioEventLoopGroup-25-1` reconnected.
22:07:00,899 ~ 22:07:01,708 `nioEventLoopGroup-25-1` 902 errors: Http2Exception$StreamException: Stream closed before write could take place
22:07:01,606 ~ 22:07:01,655 `nioEventLoopGroup-25-1` 98 errors: java.nio.channels.ClosedChannelException
22:07:01,710 `nioEventLoopGroup-25-1` `handleConnectionRemoved`
22:07:01,828 `nioEventLoopGroup-25-3` start `handleNotificationAccepted`
22:07:02,136 `nioEventLoopGroup-25-1` `handleConnectionAdded`, and then `handleNotificationAccepted`

1. It seems that after encountering the IOException: Stream closed before a reply was received (22:07:00,458 ~ 22:07:00,896), the other requests should be sent by other connections rather than nioEventLoopGroup-25-1. But Pushy still used nioEventLoopGroup-25-1(Http2Exception$StreamException, ClosedChannelException).
2. There is another strange phenomenon where nioEventLoopGroup-25-1 handleConnectionRemoved, and then nioEventLoopGroup-25-3 starts receiving responses.
3. All "handleConnectionRemoved"s were found in nioEventLoopGroup-xx-1. Is it designed in this way?
4. Additionally, I have configured 4 connections, but the other 2 threads are rarely being used. Is this normal?

   EventLoopGroup eventLoopGroup = new NioEventLoopGroup(4);
   ApnsClientBuilder builder = new ApnsClientBuilder()
       .xxx
       .setConnectionTimeout(Duration.of(CONNECTION_TIME_OUT_IN_MS, ChronoUnit.MILLIS))
       .setConcurrentConnections(4)
       .setEventLoopGroup(eventLoopGroup)
       .build();

Thanks!

Here are more infomation: nioEventLoopGroup-25-1 2024-03-21

1. 22:07:00,458 ~ 22:07:00,896 1117 errors:

Caused by: java.io.IOException: Stream closed before a reply was received
    at com.eatthepath.pushy.apns.ApnsClientHandler.<clinit>(ApnsClientHandler.java:84) ~[pushy-0.15.2.jar:?]

5. 22:07:00,899 ~ 22:07:01,708 902 errors:

Caused by: io.netty.handler.codec.http2.Http2Exception$StreamException: Stream closed before write could take place
    at io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:173) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$FlowState.cancel(DefaultHttp2RemoteFlowController.java:481) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$1.onStreamClosed(DefaultHttp2RemoteFlowController.java:105) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.DefaultHttp2Connection.notifyClosed(DefaultHttp2Connection.java:357) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.removeFromActiveStreams(DefaultHttp2Connection.java:1007) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.deactivate(DefaultHttp2Connection.java:963) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultStream.close(DefaultHttp2Connection.java:515) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.DefaultHttp2Connection.close(DefaultHttp2Connection.java:153) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.Http2ConnectionHandler$BaseDecoder.channelInactive(Http2ConnectionHandler.java:217) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.handler.codec.http2.Http2ConnectionHandler.channelInactive(Http2ConnectionHandler.java:432) ~[netty-codec-http2-4.1.86.Final.jar:4.1.86.Final]
    at com.eatthepath.pushy.apns.ApnsClientHandler.channelInactive(ApnsClientHandler.java:514) ~[pushy-0.15.2.jar:?]

6. 22:07:01,606 ~ 22:07:01,655 98 errors:

Caused by: xxx: Server internal error
    at xxx.lambda$send0$2(xxx.java:284) ~[our-notification-server-xxx.jar:?]
    at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:774) ~[?:1.8.0_362]
    at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:750) ~[?:1.8.0_362]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_362]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_362]
    at com.eatthepath.pushy.apns.ApnsClientHandler.onStreamClosed(ApnsClientHandler.java:461) ~[pushy-0.15.2.jar:?]
    xxx
    ... 1 more
Caused by: java.nio.channels.ClosedChannelException
    at io.netty.handler.ssl.SslHandler.channelInactive(SslHandler.java:1065) ~[netty-handler-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:813) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) ~[netty-common-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) ~[netty-common-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) ~[netty-common-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566) ~[netty-transport-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.86.Final.jar:4.1.86.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.86.Final.jar:4.1.86.Final]
    ... 1 more

7. 22:07:01,710 handleConnectionRemoved
8. 22:07:02,136 handleConnectionAdded

[extraSix]

I'm sure you've been busy, just sending again for visbility. @jchambers

[jchambers]

It sounds like everything here is working as intended. To address your questions directly:

It seems that after encountering the IOException…, the other requests should be sent by other connections rather than nioEventLoopGroup-25-1. But Pushy still used nioEventLoopGroup-25-1(Http2Exception$StreamException, ClosedChannelException).

An exception on a channel is generally not fatal. All kinds of exceptions can occur that apply only to a single stream (and thus only a single notification), and closing a connection after every exception would lead to expensive and unnecessary cycling of channels. This is, as near as I can tell, working as intended.

There is another strange phenomenon where nioEventLoopGroup-25-1 handleConnectionRemoved, and then nioEventLoopGroup-25-3 starts receiving responses.

That seems normal to me, but perhaps I don't understand the concern. If I understand the implication correctly, I think you're saying that for a single channel, it appears that the channel is removed from the pool before it begins processing responses. If that's the case, that can certainly happen because the channel pool is using one event loop while the channel itself is using another to process traffic to and from the APNs server. Since they're on different threads, there's no guarantee as to the order in which events from thread A and thread B will be interleaved.

All "handleConnectionRemoved"s were found in nioEventLoopGroup-xx-1. Is it designed in this way?

Yes. Channel pools use a single event loop to make sure pool-related events are processed in order.

Additionally, I have configured 4 connections, but the other 2 threads are rarely being used. Is this normal?

Without knowing specifically how threads are getting mapped to connections in your specific scenario, I don't know, but I don't think that's necessarily unexpected. I don't think Netty guarantees that channels will be evenly distributed across threads in an event loop group, so it may be that multiple channels are getting assigned to the same thread.

In all, none of this sounds alarming or like anything is behaving incorrectly. I don't think there's any action to be taken, and so I'll close this issue for now.