chvanikoff / apns4ex

APNS for Elixir
MIT License
70 stars 23 forks source link

Push stops working after a few hours on Google Compute Engine #50

Open dvcrn opened 7 years ago

dvcrn commented 7 years ago

Hello,

I noticed a problem in that push notifications strangely stop working after a few hours after server restart on Google Compute Engine. I was using Heroku before and didn't notice this problem but since migrating to google, it started popping up. (Not completely ruling out it didn't happen with Heroku as well)

I enabled full debug output to get an idea of what's going on but still can't figure out why the push notifications never make it to the device. After server restart it again works for a few hours.

This is probably a problem with Google. If you have any idea what could be causing this (since you implemented apns4ex), it would help us a lot.

My first thought was that a long-lasting connection got terminated so I adjusted expiry, timeout and feedback_interval but no luck.

Here is some debug output when sending a notification:

01:41:14.820 request_id=fecds3h3s1so2825c44qfestvvvpv707 [debug] [APNS] #PID<0.20135.97> 23303051:1ad798 sending in poolboy transaction :myapp
01:41:14.821 request_id=fecds3h3s1so2825c44qfestvvvpv707 [debug] [APNS] #PID<0.20135.97> 23303051:1ad798 sending message
01:41:14.821 request_id=fecds3h3s1so2825c44qfestvvvpv707 [debug] [APNS] #PID<0.20135.97> 62064556:b12e98 sending in poolboy transaction :myapp
01:41:14.821 [debug] [APNS] #PID<0.349.0> 23303051:1ad798 handling cast :send
01:41:14.821 [debug] [APNS] #PID<0.349.0> 23303051:1ad798 message's payload looks good
01:41:14.821 request_id=fecds3h3s1so2825c44qfestvvvpv707 [debug] [APNS] #PID<0.20135.97> 62064556:b12e98 sending message
01:41:14.821 request_id=fecds3h3s1so2825c44qfestvvvpv707 [debug] [APNS] #PID<0.20135.97> 19048099:b3ed8e sending in poolboy transaction :myapp
01:41:14.822 [debug] [APNS] #PID<0.349.0> success sending ssl package
01:41:14.822 [debug] [APNS] #PID<0.349.0> 23303051:1ad798 success sending
01:41:14.822 [debug] [APNS] #PID<0.349.0> 23303051:1ad798 handle call :send received :ok
01:41:14.822 [debug] [APNS] #PID<0.348.0> 62064556:b12e98 handling cast :send
01:41:14.822 [debug] [APNS] #PID<0.348.0> 62064556:b12e98 message's payload looks good
01:41:14.823 request_id=fecds3h3s1so2825c44qfestvvvpv707 [debug] [APNS] #PID<0.20135.97> 19048099:b3ed8e sending message
01:41:14.823 request_id=fecds3h3s1so2825c44qfestvvvpv707 [info] Sent 200 in 22ms
01:41:14.823 [debug] [APNS] #PID<0.348.0> success sending ssl package
01:41:14.823 [debug] [APNS] #PID<0.348.0> 62064556:b12e98 success sending
01:41:14.823 [debug] [APNS] #PID<0.348.0> 62064556:b12e98 handle call :send received :ok
01:41:14.823 [debug] [APNS] #PID<0.347.0> 19048099:b3ed8e handling cast :send
01:41:14.824 [debug] [APNS] #PID<0.347.0> 19048099:b3ed8e message's payload looks good
01:41:14.824 [debug] [APNS] #PID<0.347.0> success sending ssl package
01:41:14.824 [debug] [APNS] #PID<0.347.0> 19048099:b3ed8e success sending
01:41:14.824 [debug] [APNS] #PID<0.347.0> 19048099:b3ed8e handle call :send received :ok
01:41:15.027 [debug] [APNS] #PID<0.348.0> ssl socket closed, returning :connect
01:41:15.029 [debug] [APNS] #PID<0.347.0> ssl socket closed, returning :connect
01:41:15.043 [debug] [APNS] #PID<0.349.0> ssl socket closed, returning :connect
01:41:15.207 [debug] [APNS] #PID<0.348.0> successfully connected to gateway.push.apple.com:2195
01:41:15.207 [debug] [APNS] #PID<0.348.0> successfully connected to socket
01:41:15.209 [debug] [APNS] #PID<0.347.0> successfully connected to gateway.push.apple.com:2195
01:41:15.209 [debug] [APNS] #PID<0.347.0> successfully connected to socket
01:41:15.214 [debug] [APNS] #PID<0.349.0> successfully connected to gateway.push.apple.com:2195
01:41:15.214 [debug] [APNS] #PID<0.349.0> successfully connected to socket
dvcrn commented 7 years ago

I debugged this a bit and noticed that in the case where the push notification doesn't work, it will:

  1. Attempt to send the message
  2. Report "success sending"
  3. Then receive a ssl socket close
  4. Reconnect to gateway.push.apple.com

Always in this pattern. On the other hand, on successful push the 2 last points don't occur.

Could it be that the library thinks it sent the push correctly only to receive the callback that the SSL socket got closed?

zepplock commented 7 years ago

This might be similar to https://github.com/chvanikoff/apns4ex/issues/52

The way it works on Apple side is that any push is successful as long as they receive it. Then they either deliver it to the device or send you error/feedback on a separate connection, which happens later. In any case SSL socket close is not good but I'm not sure how I can help in this case. I do not see this happening on my production setup.