Strange connection error after long idle time

[Mathias]

I'm testing pushy out on my test server, and i've had this weird thing a couple of times now. After the connection has been idle for a long time, and then a new push request is sent, i get an OK confirmation, but the connection is reset just after, making Pushy reconnect. The push message does not reach my phone.

Log file to illustrate the problem:

15-03-20 15:12:26.871 [nioEventLoopGroup-2-1] TRACE c.r.pushy.apns.ApnsConnection - TestPushManager-connection-0 sending SendableApnsPushNotification [sequenceNumber=10, token=xxxxx, payload=payload that gets delivered}, deliveryInvalidation=null]

15-03-20 15:12:26.873 [nioEventLoopGroup-2-1] TRACE c.r.pushy.apns.ApnsConnection - TestPushManager-connection-0 successfully wrote notification 10

---long inactive time ---

15-03-20 23:09:19.215 [nioEventLoopGroup-2-1] TRACE c.r.pushy.apns.ApnsConnection - TestPushManager-connection-0 sending SendableApnsPushNotification [sequenceNumber=11, token=xxx, payload=payload that does NOT get detlivered,}, deliveryInvalidation=null]

15-03-20 23:09:19.392 [nioEventLoopGroup-2-1] TRACE c.r.pushy.apns.ApnsConnection - TestPushManager-connection-0 successfully wrote notification 11

15-03-20 23:09:21.077 [nioEventLoopGroup-2-1] DEBUG c.r.pushy.apns.ApnsConnection - TestPushManager-connection-0 caught an exception.

java.io.IOException: Connection reset by peer

at sun.nio.ch.FileDispatcher.read0(Native Method) ~[na:1.6.0_22]

at sun.nio.ch.SocketDispatcher.read(Unknown Source) ~[na:1.6.0_22]

at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source) ~[na:1.6.0_22]

at sun.nio.ch.IOUtil.read(Unknown Source) ~[na:1.6.0_22]

at sun.nio.ch.SocketChannelImpl.read(Unknown Source) ~[na:1.6.0_22]

at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:311) ~[netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:881) ~[netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:225) ~[netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119) ~[netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511) [netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468) [netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382) [netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354) [netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116) [netty-all-4.0.24.Final.jar:4.0.24.Final]

at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137) [netty-all-4.0.24.Final.jar:4.0.24.Final]

at java.lang.Thread.run(Unknown Source) [na:1.6.0_22]

15-03-20 23:09:21.571 [nioEventLoopGroup-2-1] TRACE c.relayrides.pushy.apns.PushManager - Connection closed: ApnsConnection [name=TestPushManager-connection-0]

15-03-20 23:09:21.733 [pool-1-thread-1] DEBUG c.r.pushy.apns.ApnsConnection - TestPushManager-connection-1 beginning connection process.

15-03-20 23:09:22.235 [nioEventLoopGroup-2-1] DEBUG c.r.pushy.apns.ApnsConnection - TestPushManager-connection-1 connected; waiting for TLS handshake.

15-03-20 23:09:23.069 [nioEventLoopGroup-2-1] DEBUG c.r.pushy.apns.ApnsConnection - TestPushManager-connection-1 successfully completed TLS handshake.

15-03-20 23:09:23.070 [nioEventLoopGroup-2-1] TRACE c.relayrides.pushy.apns.PushManager - Connection succeeded: ApnsConnection [name= TestPushManager-connection-1]

15-03-20 23:11:45.178 [nioEventLoopGroup-2-1] TRACE c.r.pushy.apns.ApnsConnection - TestPushManager-connection-1 sending SendableApnsPushNotification [sequenceNumber=1, token=xxxx, payload=gets delivered again}, deliveryInvalidation=null]

15-03-20 23:11:45.179 [nioEventLoopGroup-2-1] TRACE c.r.pushy.apns.ApnsConnection - TestPushManager-connection-1 successfully wrote notification 1

It seems weird that i get a confirmation that the notification was received, but an exception right after. Is this some known problem?

[Jon Chambers]

It sounds like your connection died, but because the APNs protocol provides no means of checking connection health, we didn't (and couldn't) notice the failure. This is normal and, unfortunately, expected behavior. You can configure connections to close after a period of inactivity for exactly this reason. Please see http://relayrides.github.io/pushy/apidocs/0.4/com/relayrides/pushy/apns/ApnsConnectionConfiguration.html for details.

> It seems weird that i get a confirmation that the notification was received, but an exception right after.

I don't mean to be pedantic, but we very carefully avoid ever saying that any notification was received (because we have no way of knowing). What we ARE saying when you see that a connection "successfully wrote notification N" is that we handed it off to the OS-level "things to send" buffer, but we have no way of knowing what happened to it after that.

Cheers!

-Jon

--
Pushy is an open-source Java library for sending APNs (iOS and OS X) push notifications. Pushy is brought to you by the engineers at RelayRides.
---
You received this message because you are subscribed to the Google Groups "pushy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to pushy-apns+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Mathias]

Hey Jon, thanks for a quick response! I understand perfectly your "pedantic" response, i know what you mean.

Regarding the connection settings, more specifically the getCloseAfterInactivityTime and setSendAttemptLimit:

1. inactivitytime - do you recommend anything in particular here? Does Apple care if i have, say, 2 connections and reconnect them every minute? every five minutes?

2. sentAttemptLimit - is there any specific reason why i'd always reconnect after a certain number of notifications? if the connection is bad make sure i never lose too many?

Just hoping for some pointers based on your production experience. My volume will probably be waaaaaay less than yours though.

[Jon Chambers]

> do you recommend anything in particular here? Does Apple care if i have, say, 2 connections and reconnect them every minute? every five minutes?

We have no specific recommendation; an appropriate timeout will depend on your specific use case, but something on the order of single-digit numbers of minutes doesn't seem crazy. Apple does not, as far as we know, have any specifications as to how often "too often" is when it comes to reconnection.

> is there any specific reason why i'd always reconnect after a certain number of notifications?

Connections could, in theory, fail at any time and without any way of detecting the problem. Setting an upper limit on the number of notifications that can be sent through a notification before it closes limits the potential damage (in the form of notifications in an unknown state) done by an unexpectedly closed connection. It's probably reasonable to configure this so it, too, causes connections to close after a single digit number of minutes under load. Again, there is no specific recommendation here and appropriate values will depend on your use case, and Apple offers no guidance with regard to "dead" connections.

-Jon