APNS push fails after inactive period

[Uscher1]

Uniqush is a great project - thank you!
Currently in version 1.5.1 we observe for APNS following reliability issue.

When Uniqush is inactive within 2 hours (i.e. does no push) APNS server seems to close the connection. The next push request will then fail. The subcriber is missing and the delivery point is unknown. Also the retries will fail. The retry after 20 s fails due to i/o timeout. And then the sleep time seems to be calculated wrong. Two more tries happen immediately.

After that the next push request succeeds again.

This is the logging of the scenario descibed above:

[Push][Info] 2014/06/04 11:11:19 RequestId=538ee2b7-m67KDaMlSzW8k7nEhwhCXA== From=127.0.0.1:52617 Service=ajoy Subscribers="[41786377584]"

[Push][Info] 2014/06/04 11:11:19 RequestID=538ee2b7-m67KDaMlSzW8k7nEhwhCXA== Service=ajoy Subscriber=41786377584 PushServiceProvider=apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7 DeliveryPoint=apns:98e33a0cad66bc695e9ba781efa48a4252eb70ba MsgId=apns:apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7-56 Success!


[Push][Info] 2014/06/04 13:11:19 Connection closed by APNS: EOF

[Push][Info] 2014/06/04 13:42:35 RequestId=538f062b-dsI1O6Q5RvBfVW2uWABqyw== From=127.0.0.1:55461 Service=ajoy Subscribers="[41786377584]"

[Push][Error] 2014/06/04 13:42:35 RequestID=538f062b-dsI1O6Q5RvBfVW2uWABqyw== Service=ajoy Subscriber= PushServiceProvider=apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7 DeliveryPoint=Unknown Failed: error on connection with 17.149.34.189:2195: EOF. Will retry within 20s

[Push][Error] 2014/06/04 13:42:56 Error: error on connection with 17.172.232.46:2195: write tcp 17.172.232.46:2195: i/o timeout. Will retry within -1618991h33m41.610135552s

[Push][Info] 2014/06/04 13:42:56 Connection closed by APNS: read tcp 17.172.232.46:2195: use of closed network connection
[Push][Error] 2014/06/04 13:42:56 Error: error on connection with 17.172.232.45:2195: write tcp 17.172.232.45:2195: i/o timeout. Will retry within -1934822h49m41.49584896s

[Push][Info] 2014/06/04 13:42:56 Connection closed by APNS: read tcp 17.172.232.45:2195: use of closed network connection

[Push][Info] 2014/06/04 13:42:57 Connection closed by APNS: read tcp 17.172.232.18:2195: use of closed network connection


[Push][Info] 2014/06/04 13:43:15 RequestId=538f0653--PVGYfvtdivXRJKHu5LEnQ== From=127.0.0.1:55461 Service=ajoy Subscribers="[41786377584]"

[Push][Info] 2014/06/04 13:43:16 RequestID=538f0653--PVGYfvtdivXRJKHu5LEnQ== Service=ajoy Subscriber=41786377584 PushServiceProvider=apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7 DeliveryPoint=apns:98e33a0cad66bc695e9ba781efa48a4252eb70ba MsgId=apns:apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7-58 Success! 

[monnand]

I think I could fix this bug by changing the connection pool library. I will give you a new build by this Sunday.

[Uscher1]

I am looking forward to testing your next build. 👍

[monnand]

Hi @Uscher1,

Please try this build. Before running it, please make sure it's the right version:

 % ./uniqush-push -version
uniqush-push 1.5.2a4

[Uscher1]

Hi monnand
Thank you for the build.

I installed the build 1.5.2a4 but push fails due to missing Subscriber/DeliveryPoint problem:

[Subscribe][Info] 2014/06/22 16:25:07 From=127.0.0.1:39926 Service=ajoy Subscriber=41786377584 PushServiceProvider=apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7 DeliveryPoint=apns:98e33a0cad66bc695e9ba781efa48a4252eb70ba Success!
[Push][Info] 2014/06/22 16:26:23 RequestId=53a6e78f-GvIEfCSvWC-Zyf6dYTJ4xw== From=127.0.0.1:55331 Service=ajoy NrSubscribers=1 Subscribers="[41786377584]"
[Push][Error] 2014/06/22 16:26:23 RequestID=53a6e78f-GvIEfCSvWC-Zyf6dYTJ4xw== Service=ajoy Subscriber= PushServiceProvider=apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7 DeliveryPoint=Unknown Failed: tls: either ServerName or InsecureSkipVerify must be specified in the tls.Config

Are there more steps to do than just installing the binary? Is the existing data still available and compatible?

[monnand]

@Uscher1 Sorry, I do not have my APNS certificate and key with me. The most recent Go TLS library changed its behaviour. But it's an easy fix. You could try this new build. Sorry about that.

[Uscher1]

Is there anything wrong with the archive?

tar zxvf uniqush-push_1.5.2a5_x86_64.tar.gz
tar: This does not look like a tar archive
tar: Skipping to next header
tar: Exiting with failure status due to previous errors

[monnand]

Well.. It works for me:

$ wget http://uniqush.org/downloads/uniqush-push_1.5.2a5_x86_64.tar.gz
--2014-06-23 17:33:13--  http://uniqush.org/downloads/uniqush-push_1.5.2a5_x86_64.tar.gz
Resolving uniqush.org (uniqush.org)... 108.162.199.101, 108.162.198.101
Connecting to uniqush.org (uniqush.org)|108.162.199.101|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2119678 (2.0M) [application/octet-stream]
Saving to: ‘uniqush-push_1.5.2a5_x86_64.tar.gz’

100%[===========================================================================================================================================================================>] 2,119,678   3.68MB/s   in 0.5s   

2014-06-23 17:33:14 (3.68 MB/s) - ‘uniqush-push_1.5.2a5_x86_64.tar.gz’ saved [2119678/2119678]
$ tar zxvf uniqush-push_1.5.2a5_x86_64.tar.gz 
uniqush-push_1.5.2a5_x86_64/
uniqush-push_1.5.2a5_x86_64/Apache-2.0
uniqush-push_1.5.2a5_x86_64/uniqush-push.conf
uniqush-push_1.5.2a5_x86_64/uniqush-push
uniqush-push_1.5.2a5_x86_64/install.sh
$ sha256sum uniqush-push_1.5.2a5_x86_64.tar.gz 
ef16990ffdc5364c418e23a53eeadb14a0588c06578b15f60271410f87de69a6  uniqush-push_1.5.2a5_x86_64.tar.gz

Here is the SHA256 of the file: ef16990ffdc5364c418e23a53eeadb14a0588c06578b15f60271410f87de69a6

[Uscher1]

OK, thank you, I was able to download your latest build now. It works for APNS, but not for GCM (see second push):

[Push][Info] 2014/06/24 11:43:13 RequestId=53a94831-A7dvHqDFfhAmutaCUdWbgg== From=127.0.0.1:44237 Service=ajoy NrSubscribers=1 Subscribers="[41786377584]"
[Push][Info] 2014/06/24 11:43:14 RequestID=53a94831-A7dvHqDFfhAmutaCUdWbgg== Service=ajoy Subscriber=41786377584 PushServiceProvider=apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7 DeliveryPoint=apns:98e33a0cad66bc695e9ba781efa48a4252eb70ba MsgId=apns:apns:85532e46d56583e1d66a0c07be4eb27a4d325ef7-1 Success!
[Push][Info] 2014/06/24 11:44:06 RequestId=53a94866-_81J73FxLWCue1tO3g6eAw== From=127.0.0.1:44237 Service=ajoy NrSubscribers=1 Subscribers="[41791336366]"
[Push][Error] 2014/06/24 11:44:06 RequestID=53a94866-_81J73FxLWCue1tO3g6eAw== Service=ajoy Subscriber=41791336366 Failed: No device
uniqush

Do you have an idea whats going wrong?

[monnand]

@Uscher1 The error shown above suggests that uniqush cannot find any device under the subscriber "41791336366". Do you have same error when you use the old version with same subscriber? Also, you could use redis-cli to check if there's any device under this subscriber. Here's how to do it:

• Use redis-cli to connect to your redis server
• In the redis client, run this command: KEYS srv.sub-2-dp:ajoy:41791336366. If it returns empty, then there's no device under the subscriber. Otherwise, move on to next step.
• In the redis client, run this command: SMEMBERS srv.sub-2-dp:ajoy:41791336366. Again, If it returns empty, then there's no device under the subscriber. Otherwise, this would be a bug.

I checked my commits. There's no change on GCM part. The error suggests that it did not even reach any GCM-specific code. This error message means uniqush-push tried to retrieve data from redis but found nothing. The database code is not change for a long time, like almost a year.

[Uscher1]

Hi Monnand, for some reason this device number was not stored anymore in redis, even though unsubscribe is not implemented at all. Additionally the uniqush process was stopped over night for unknown reason.

However, everything works fine now and I start doing some long term tests.

Thank you so much for your excellent support and patience!
Uscher

[monnand]

Uniqush will automatically remove devices when the push service provider
says the device should be removed. This is usually happen when user removed
your app. You could find the unsubscription event in the log. Thank you for
your feedback. Have fun!
On Jun 25, 2014 1:23 AM, "Urs Steger" notifications@github.com wrote:

Hi Monnand, for some reason this device number was not stored anymore in
redis, even though unsubscribe is not implemented at all. Additionally the
uniqush process was stopped over night for unknown reason.

However, everything works fine now and I start doing some long term tests.

Thank you so much for your excellent support and patience!
Uscher

—
Reply to this email directly or view it on GitHub
#47 (comment).