Connection reset by peer

[abraxascorner]

Hi,

I am using client for sending both standard and voip push messages and have the following exception occurs from time to time in my logs:

WARN - ApnsClientHandler - APNs client pipeline caught an exception.
java.io.IOException: Connection reset by peer
    at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
    at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:192)
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
    at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:221)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:871)
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:245)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:112)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:510)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:467)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:381)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:353)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)

I am connecting client on the load of my app and some other application calls mine when I need to send voip notification:
client instantiation:

@PostConstruct
private void init() {
    try {
        client = new ApnsClient<>(new File(keyStoreFilePath), keyStorePassword);

        client.connect(ApnsClient.DEVELOPMENT_APNS_HOST).addListener(future -> logger.info("APNS client initialized and connected to gateway."));
    }
    catch (SSLException e) {
        logger.error("Failed to initialize APNS client. {}", e.getMessage());
    }
}

And code for sending notifications:

ApnsPayloadBuilder payloadBuilder = new ApnsPayloadBuilder();
payloadBuilder.setAlertBody("voip");
if (message != null)
    payloadBuilder.setAlertBody(message);

if (data != null) {
    for (Map.Entry<String, String> entry : data.entrySet())
        payloadBuilder.addCustomProperty(entry.getKey(), entry.getValue());
}

String payload = payloadBuilder.buildWithDefaultMaximumLength();

Date expirationDate = null;
if (timeout != null)
    expirationDate = DateUtils.addSeconds(new Date(), timeout);

logger.info("Sending voip iOS notification {}.", uid);

SimpleApnsPushNotification pushNotification = new SimpleApnsPushNotification(token, DEFAULT_VOIP_TOPIC, payload, expirationDate);
Future<PushNotificationResponse<SimpleApnsPushNotification>> sendNotificationFuture =
        client.sendNotification(pushNotification);
try {
    PushNotificationResponse<SimpleApnsPushNotification> response = sendNotificationFuture.get();

    if (response.isAccepted()) {
        logger.debug("Voip push notitification for {} accepted by APNs gateway.", token);
        return true;
    }
    else {
        logger.warn("Voip notification for {} rejected by the APNs gateway: {}", token, response.getRejectionReason());

        if (response.getTokenInvalidationTimestamp() != null) {
                logger.info("System will stop sending voip notifications to user {}, because she probably uninstalled the app.", user);
            }
        }
    }
}
catch (ExecutionException e) {
    logger.error("Failed to send voip push notification to {}. {}", token, e.getMessage());

    if (e.getCause() instanceof ClientNotConnectedException) {
        logger.info("Waiting for client to reconnect.");
        try {
            client.getReconnectionFuture().await();
            logger.info("Reconnected.");
        }
        catch (InterruptedException e1) {
            logger.error("Reconnecting failed. {}", e1.getMessage());
        }
    }
}
catch (InterruptedException e) {
    logger.error("Failed to send voip push notification to {}. {}", token, e.getMessage());
}

return false;

Is there something I am doing wrong?

[jchambers]

the following exception occurs from time to time in my logs

How often is "from time to time?" Are notifications ever sent as expected?

[abraxascorner]

Yep, notifications are sent regulary, but when there is a bigger timeout between sending notifications, the first notification sending throws this error and after that, next one is sent normally.
To help in debugging, I use one cert for normal and voip push. And my token is generated when I install app through Xcode, so it is development token. And from my code, as you can see, I am using dev apple servers for push.

[jchambers]

Hm. Sounds like we might be getting a server-initiated IdleTimeout, and we're just not expecting traffic from the server that's not a response to an attempt to send a notification. The docs are very unclear as to when this might happen, or what we're supposed to do about it.

I'll try to set up some experiments with really verbose logging to see if the IdleTimeout theory pans out. If it does, I guess we can just automatically reconnect. We could also send PING frames at regular intervals to monitor the health of the connection and maybe prevent idle timeouts (since the docs are unclear as to when an idle timeout might happen, it's not clear if PING frames would actually prevent a timeout).

[panchenko]

Might be reconnect can happen only when sending the next notification? I am just thinking of a case when system is mostly idle at night time, why should be pinging/reconnecting all night?

[abraxascorner]

And a little more info. This code is working:

ApnsPayloadBuilder payloadBuilder = new ApnsPayloadBuilder();

        payloadBuilder.setAlertBody(message);

        if (data != null) {
            for (Map.Entry<String, String> entry : data.entrySet())
                payloadBuilder.addCustomProperty(entry.getKey(), entry.getValue());
        }

        String payload = payloadBuilder.buildWithDefaultMaximumLength();

        Date expirationDate = null;
        if (timeout != null)
            expirationDate = DateUtils.addSeconds(new Date(), timeout);

        logger.info("Sending voip iOS notification {} to {}.", uid, token);

            SimpleApnsPushNotification notification = new SimpleApnsPushNotification(token, DEFAULT_VOIP_TOPIC, payload, expirationDate, DeliveryPriority.IMMEDIATE);
            client.sendNotification(notification).addListener(new GenericFutureListener<Future<PushNotificationResponse<SimpleApnsPushNotification>>>() {
                @Override
                public void operationComplete(Future<PushNotificationResponse<SimpleApnsPushNotification>> future) throws Exception {
                    try {
                        PushNotificationResponse<SimpleApnsPushNotification> response = future.get();
                        if (response.isAccepted())
                            logger.debug("Sending voip notification {} to {} was successful.", uid, response.getPushNotification().getToken());
                        else {
                            logger.warn("Sending voip notification {} to {} failed. Reason: {}", uid, response.getPushNotification().getToken(), response.getRejectionReason());

                            if (response.getTokenInvalidationTimestamp() != null) {
                                    logger.info("System will stop sending notifications to user {}, because she probably uninstalled the app.", user);
                                }
                            }
                        }
                    }
                    catch (ExecutionException e) {
                        logger.error("Sending notification {} to some recipient failed. {}", uid, e.getMessage());

                        if (e.getCause() instanceof ClientNotConnectedException) {
                            logger.info("Waiting for client to reconnect.");
                            try {
                                client.getReconnectionFuture().await();
                                logger.info("Reconnected.");
                            }
                            catch (InterruptedException e1) {
                                logger.error("Reconnecting failed. {}", e1.getMessage());
                            }
                        }
                    }
                    catch (InterruptedException e) {
                        logger.error("Sending notification {} to some recipient failed. {}", uid, e.getMessage());
                    }
                }
            });

        return true;

[jchambers]

I am just thinking of a case when system is mostly idle at night time, why should be pinging/reconnecting all night?

@panchenko Well, to turn the question around, what's the cost in doing so? One perspective is that the caller asked us to connect, so they still expect us to be connected and ready to blast notifications through as quickly as possible.

This code is working…

@abraxascorner Can you summarize what's different about that code and how it's behaving differently than your first example?

[abraxascorner]

Well, the only difference I see is that in first example, I am getting the future object (since I want to return if apns accepted notification) and in other example I am adding listener.
This part of code:

SimpleApnsPushNotification pushNotification = new SimpleApnsPushNotification(token, DEFAULT_VOIP_TOPIC, payload, expirationDate);
Future<PushNotificationResponse<SimpleApnsPushNotification>> sendNotificationFuture =
        client.sendNotification(pushNotification);
try {
    PushNotificationResponse<SimpleApnsPushNotification> response = sendNotificationFuture.get();

Building notifs and catching of ex are the same.
And since I deployed code last night, I didn't saw any connection reset ex in my log files and notifications are sent and received ok.

[abraxascorner]

Ou, and one more thing, sorry for not bringing sooner, last night I noticed. I am using 0.54 or 0.52 and not 0.6 version (I don't have code at the moment). I updated to the newest version and tonight (CET time :)), I will test on 0.6 version.

[abraxascorner]

Ok, new info. :)
I have updated to 0.6 and now after this ex, code goes into reconnection block, reconnect and try to send message again, which goes successfull.

[jchambers]

I have updated to 0.6 and now after this ex, code goes into reconnection block, reconnect and try to send message again, which goes successfull.

So… does that mean you think this is fixed in 0.6?

[abraxascorner]

Well, I don't know. :)
Now, my code goes into reconnection block, I call same method again and it delivers push, so I found the solution and you can consider this solved. But, maybe it can prevent, in a some way, for connection not to stay alive on client side when they are close on server side?

[abraxascorner]

Thank you for all the help.

[jchambers]

maybe it can prevent, in a some way, for connection not to stay alive on client side when they are close on server side?

#266 adds an idle state handler that will send PING frames when a client is idle. That should help us detect closed connections more quickly, and should also prevent connections from closing due to inactivity.