Mysterious disconnect

[alleus]

Hi,

I encountered this weird disconnection this morning on the v50 branch. 5 pushes was suppose to be sent out, but it resulted in none at all. When I tried again 45 minutes later with a single different token, it worked all right. Now, a few hours later, returning to the problem and trying to reproduce with the same 5 tokens, everything seems to work fine...

This is the log from this morning, with a disconnect problem Connection to the other side was lost in a non-clean fashion.

2013-09-04 05:31:36+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 05:31:36+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
2013-09-04 05:31:36+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x17b5050> will retry in 2 seconds
2013-09-04 05:31:36+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x17b0e18>
2013-09-04 05:31:38+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x17b0e18>
2013-09-04 05:31:38+0000 [-] APNSClientFactory startedConnecting
2013-09-04 05:31:39+0000 [Uninitialized] APNSProtocol connectionMade
2013-09-04 06:00:37+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 06:00:37+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
2013-09-04 06:00:37+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x18275f0> will retry in 2 seconds
2013-09-04 06:00:37+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 06:00:39+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 06:00:39+0000 [-] APNSClientFactory startedConnecting
2013-09-04 06:00:39+0000 [Uninitialized] APNSProtocol connectionMade
2013-09-04 09:01:02+0000 [HTTPChannel,20,127.0.0.1] APNSProtocol sendMessage msg=01000000010000000000***
2013-09-04 09:01:02+0000 [HTTPChannel,20,127.0.0.1] 127.0.0.1 - - [04/Sep/2013:09:01:01 +0000] "POST /apps/***/production/notifications HTTP/1.1" 201 29 "-" "-"
2013-09-04 09:01:02+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 09:01:02+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion.
    ]
2013-09-04 09:01:02+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x18275f0> will retry in 2 seconds
2013-09-04 09:01:02+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 09:01:05+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 09:01:05+0000 [-] APNSClientFactory startedConnecting
2013-09-04 09:01:05+0000 [Uninitialized] APNSProtocol connectionMade
2013-09-04 09:45:03+0000 [HTTPChannel,21,127.0.0.1] APNSProtocol sendMessage msg=01000000010000000000***
2013-09-04 09:45:03+0000 [HTTPChannel,21,127.0.0.1] 127.0.0.1 - - [04/Sep/2013:09:45:03 +0000] "POST /apps/***/production/notifications HTTP/1.1" 201 29 "-" "-"

I now tried the disconnections and feedback services, but nothing:

curl http://localhost:23480/apps/***/production/disconnections
{"code": 200, "response": []}

curl http://localhost:23480/apps/***/production/feedback
{"code": 200, "response": []}

Looking at my log from earlier, there is a lot of disconnections at what it seems like somewhat regular intervals (at least even-ish 30 minutes).

2013-09-04 00:00:26+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 00:00:26+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
2013-09-04 00:00:26+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x18275f0> will retry in 2 seconds
2013-09-04 00:00:26+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 00:00:29+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 00:00:29+0000 [-] APNSClientFactory startedConnecting
2013-09-04 00:00:29+0000 [Uninitialized] APNSProtocol connectionMade
2013-09-04 01:31:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 01:31:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
2013-09-04 01:31:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x17b5050> will retry in 2 seconds
2013-09-04 01:31:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x17b0e18>
2013-09-04 01:31:32+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x17b0e18>
2013-09-04 01:31:32+0000 [-] APNSClientFactory startedConnecting
2013-09-04 01:31:32+0000 [Uninitialized] APNSProtocol connectionMade
2013-09-04 02:00:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 02:00:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
2013-09-04 02:00:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x18275f0> will retry in 2 seconds
2013-09-04 02:00:30+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 02:00:33+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 02:00:33+0000 [-] APNSClientFactory startedConnecting
2013-09-04 02:00:33+0000 [Uninitialized] APNSProtocol connectionMade
2013-09-04 03:31:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 03:31:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
2013-09-04 03:31:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x17b5050> will retry in 2 seconds
2013-09-04 03:31:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x17b0e18>
2013-09-04 03:31:35+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x17b0e18>
2013-09-04 03:31:35+0000 [-] APNSClientFactory startedConnecting
2013-09-04 03:31:35+0000 [Uninitialized] APNSProtocol connectionMade
2013-09-04 04:00:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSProtocol connectionLost
2013-09-04 04:00:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] APNSClientFactory clientConnectionLost reason=[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
2013-09-04 04:00:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] <twisted.internet.tcp.Connector instance at 0x18275f0> will retry in 2 seconds
2013-09-04 04:00:33+0000 [APNSProtocol (TLSMemoryBIOProtocol),client] Stopping factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 04:00:36+0000 [-] Starting factory <pyapns.server.APNSClientFactory instance at 0x18274d0>
2013-09-04 04:00:36+0000 [-] APNSClientFactory startedConnecting
2013-09-04 04:00:36+0000 [Uninitialized] APNSProtocol connectionMade

I'm running via twistd, making sure it's alive via crontab:

*/5 * * * * ~/bin/twistd -y ~/pyapns/pyapns.tac

Looking at my processes, this is shown:

    PID USER      PRI  NI  VIRT   RES   SHR S CPU% MEM%   TIME+  Command
 879769 ***        20   0  283M 14628  2688 S  0.0  0.1  0:00.06 /usr/local/bin/python2.7 /home/***/bin/twistd -y /home/***/pyapns/pyapns.tac
 797678 ***        20   0  283M 14628  2688 S  0.0  0.1  0:00.00 /usr/local/bin/python2.7 /home/***/bin/twistd -y /home/***/pyapns/pyapns.tac
 865573 ***        20   0  283M 14628  2688 S  0.0  0.1  5:26.57 /usr/local/bin/python2.7 /home/***/bin/twistd -y /home/***/pyapns/pyapns.tac

Am I doing stuff right? Do my setup or logs look weird in any way?

[alleus]

It seems this is caused by a, to me, new status code from Apple:

Status code	Description
10	Shutdown

A status code of 10 indicates that the APNs server closed the connection (for example, to perform maintenance). The notification identifier in the error response indicates the last notification that was successfully sent. Any notifications you sent after it have been discarded and must be resent. When you receive this status code, stop using this connection and open a new connection.

https://developer.apple.com/library/ios/documentation/NetworkingInternet/Conceptual/RemoteNotificationsPG/Chapters/CommunicatingWIthAPS.html

It seems like I need an alternative to pyapns that supports caching sent payloads and resend on errors instead of discarding (I encounter this problem quite a lot since our service at the moment sends out very few pushes). My temporary workaround for this is currently to keep the socket busy by sending scheduled dummy pushes now and then.

So: Not a mystery anymore, closing this ticket.