Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Suddenly not recieving notifications #1

Open
NicolaiSchnack opened this issue Aug 28, 2013 · 17 comments
Open

Suddenly not recieving notifications #1

NicolaiSchnack opened this issue Aug 28, 2013 · 17 comments

Comments

@NicolaiSchnack
Copy link

I'm not retrieving any error messages, but after the server has been running for some time, notifications no longer shows up on the devices ?

When i restart the server everything works again :S

I'm running production mode, any thoughts ?

@logicalparadox
Copy link
Owner

My first two thoughts are a memory leak or a connection timeout that is not being handled correctly. I haven't run into this yet, but it is not outside the realm of possibility. I'll try to simulate what I can but it would be helpful it you could help narrow it down.

  • how often does this happen? ... every day, once a week, etc.
  • what kind of volume are you sending? .... 1k/hour, 1k/day, etc. (approximation is fine)
  • if it happens again can you check memory usage and the processes uptime and let me know.

Thanks!

@logicalparadox
Copy link
Owner

Closing this as there has been no follow up. Please reopen with more details if/when you get them.

@netlogic
Copy link

First thank you for the package. It is very well thought out. I am experiencing the same issue when running.
The app starts fine. I can trigger a system level messages via a post call (you will see it in the log below) and then messages are sent. After a while though when I call my api function no messages go through (send message callback will return though with no error, this is why my log says message sent to pan). If I restart my server I can send several messages without a problem. I have attached the log from my app. The sendSystemMessage is the command I send to the server to trigger the send call for the devices I have registered. Please let me know how I can help figure this out. I am running my app on nodejitsu.

[11/13 18:01:49 EST][err] apnagent:agent-live 2ms write: 0
[11/13 18:01:49 EST][err] apnagent:agent-live 301ms connected - gateway.push.apple.com:2195
[11/13 18:01:49 EST][err] apnagent:cache 4ms push: 0
[11/13 18:01:49 EST][out] msg sent
[11/13 18:01:49 EST][err] apnagent:agent-base 2ms drain
[11/13 18:01:49 EST][err] apnagent:agent-live 0ms push: 0
[11/13 18:01:49 EST][out] [] apn agent running
[11/13 18:01:51 EST][out] trying to connect to database
[11/13 18:01:51 EST][out] Succeeded connecting to database
[11/13 18:01:51 EST][out] - calling mongoose.connect
[11/13 18:04:29 EST][err] apnagent:agent-base 3ms iterate
[11/13 18:04:29 EST][err] apnagent:agent-live 1ms push: 1
[11/13 18:04:29 EST][out] sysmsg message sent to apn
[11/13 18:04:29 EST][out] https
[11/13 18:04:29 EST][err] apnagent:agent-live 0ms write: 2
[11/13 18:04:29 EST][err] apnagent:cache 3ms push: 4
[11/13 18:04:29 EST][err] apnagent:agent-base 0ms push: 4
[11/13 18:04:29 EST][err] apnagent:agent-base 1ms push: 3
[11/13 18:04:29 EST][out] sysmsg message sent to apn
[11/13 18:04:29 EST][err] apnagent:agent-live 3ms data: 6 bytes
[11/13 18:04:29 EST][err] apnagent:agent-live 159959ms write: 1
[11/13 18:04:29 EST][err] apnagent:cache 159961ms push: 1
[11/13 18:04:29 EST][err] apnagent:agent-base 5ms iterate
[11/13 18:04:29 EST][err] apnagent:agent-base 1ms iterate
[11/13 18:04:29 EST][err] apnagent:agent-live 0ms push: 3
[11/13 18:04:29 EST][err] apnagent:cache 7ms pause
[11/13 18:04:29 EST][err] apnagent:agent-live 1ms write: 3
[11/13 18:04:29 EST][err] apnagent:agent-base 5ms error: Invalid token
[11/13 18:04:29 EST][err] apnagent:agent-live 1ms write: 1
[11/13 18:04:29 EST][err] apnagent:cache 1ms push: 3
[11/13 18:04:29 EST][out] [message:error] other error: Invalid token , device = 0396b9aaedf3752b2070a164944ffb9afaa071f5796eaf7cdc720dc2a06d0fc8
[11/13 18:04:29 EST][err] apnagent:agent-base 2ms iterate
[11/13 18:04:29 EST][out] remove device <0396b9aa edf3752b 2070a164 944ffb9a faa071f5 796eaf7c dc720dc2 a06d0fc8>
[11/13 18:04:29 EST][err] apnagent:agent-live 2ms write: 4
[11/13 18:04:29 EST][err] apnagent:agent-base 3ms drain
[11/13 18:04:29 EST][err] apnagent:agent-live 2ms write: 2
[11/13 18:04:29 EST][err] apnagent:agent-live 1ms push: 4
[11/13 18:04:29 EST][out] removed device id <0396b9aa edf3752b 2070a164 944ffb9a faa071f5 796eaf7c dc720dc2 a06d0fc8> from database
[11/13 18:04:29 EST][err] apnagent:agent-base 0ms push: 2
[11/13 18:04:29 EST][err] apnagent:cache 3ms push: 2
[11/13 18:04:29 EST][err] apnagent:agent-base 3ms drain
[11/13 18:04:29 EST][out] 10.112.36.47 - - [Wed, 13 Nov 2013 23:04:29 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "mibi/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/13 18:04:29 EST][err] apnagent:agent-live 0ms write: 3
[11/13 18:04:29 EST][err] apnagent:agent-base 159953ms push: 1
[11/13 18:04:29 EST][err] apnagent:agent-live 1ms push: 2
[11/13 18:04:29 EST][out] sysmsg message sent to apn
[11/13 18:04:29 EST][out] sysmsg message sent to apn
[11/13 18:04:29 EST][err] apnagent:agent-live 0ms write: 4
[11/13 18:04:29 EST][err] apnagent:agent-live 5ms disconnected - gateway.push.apple.com:2195
[11/13 18:04:30 EST][err] apnagent:agent-live 1008ms since: 1
[11/13 18:04:30 EST][err] apnagent:agent-live 0ms push: 2
[11/13 18:04:30 EST][err] apnagent:cache 1009ms flush
[11/13 18:04:30 EST][err] apnagent:agent-live 0ms reconnecting
[11/13 18:04:30 EST][err] apnagent:agent-live 0ms connecting - gateway.push.apple.com:2195
[11/13 18:04:30 EST][err] apnagent:agent-live 0ms push: 4
[11/13 18:04:30 EST][err] apnagent:agent-live 1ms push: 3
[11/13 18:04:31 EST][err] apnagent:agent-base 1ms iterate
[11/13 18:04:31 EST][err] apnagent:agent-live 0ms write: 2
[11/13 18:04:31 EST][err] apnagent:cache 375ms resume
[11/13 18:04:31 EST][err] apnagent:cache 0ms clean older than 1800000ms
[11/13 18:04:31 EST][err] apnagent:cache 1ms flush
[11/13 18:04:31 EST][err] apnagent:agent-live 374ms connected - gateway.push.apple.com:2195
[11/13 18:04:31 EST][err] apnagent:agent-live 1ms reconnected
[11/13 18:04:31 EST][err] apnagent:agent-base 1384ms iterate
[11/13 18:04:31 EST][err] apnagent:cache 0ms push: 3
[11/13 18:04:31 EST][err] apnagent:agent-live 0ms write: 2
[11/13 18:04:31 EST][err] apnagent:cache 1ms push: 2
[11/13 18:04:31 EST][err] apnagent:agent-live 0ms push: 2
[11/13 18:04:31 EST][err] apnagent:agent-live 0ms push: 3
[11/13 18:04:31 EST][err] apnagent:agent-live 0ms write: 3
[11/13 18:04:31 EST][err] apnagent:agent-live 1ms write: 3
[11/13 18:04:31 EST][err] apnagent:agent-live 0ms write: 4
[11/13 18:04:31 EST][err] apnagent:agent-base 0ms iterate
[11/13 18:04:31 EST][err] apnagent:agent-live 4ms write: 4
[11/13 18:04:31 EST][err] apnagent:agent-base 5ms drain
[11/13 18:04:31 EST][err] apnagent:cache 5ms push: 4
[11/13 18:04:31 EST][err] apnagent:agent-live 0ms push: 4
[11/13 18:08:12 EST][out] https
[11/13 18:08:12 EST][err] apnagent:agent-base 1ms push: 6
[11/13 18:08:12 EST][err] apnagent:agent-base 221510ms push: 5
[11/13 18:08:12 EST][err] apnagent:agent-base 0ms push: 7
[11/13 18:08:12 EST][err] apnagent:agent-live 221514ms write: 5
[11/13 18:08:12 EST][err] apnagent:agent-base 2ms iterate
[11/13 18:08:12 EST][err] apnagent:agent-live 1ms write: 5
[11/13 18:08:12 EST][err] apnagent:agent-live 0ms push: 5
[11/13 18:08:12 EST][err] apnagent:cache 221514ms push: 5
[11/13 18:08:12 EST][err] apnagent:agent-live 1ms write: 6
[11/13 18:08:12 EST][err] apnagent:agent-live 1ms write: 6
[11/13 18:08:12 EST][err] apnagent:agent-live 2ms push: 6
[11/13 18:08:12 EST][err] apnagent:agent-live 0ms write: 7
[11/13 18:08:12 EST][out] sysmsg message sent to apn
[11/13 18:08:12 EST][err] apnagent:agent-base 3ms iterate
[11/13 18:08:12 EST][err] apnagent:cache 4ms push: 6
[11/13 18:08:12 EST][err] apnagent:cache 1ms push: 7
[11/13 18:08:12 EST][err] apnagent:agent-live 1ms push: 7
[11/13 18:08:12 EST][err] apnagent:agent-base 1ms drain
[11/13 18:08:12 EST][out] sysmsg message sent to apn
[11/13 18:08:12 EST][out] 10.112.36.47 - - [Wed, 13 Nov 2013 23:08:12 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "mibi/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/13 18:08:12 EST][err] apnagent:agent-live 0ms write: 7
[11/13 18:08:12 EST][out] sysmsg message sent to apn
[11/13 18:08:12 EST][err] apnagent:agent-base 2ms iterate
[11/13 18:34:04 EST][out] https
[11/13 18:34:04 EST][err] apnagent:agent-base 1551650ms push: 8
[11/13 18:34:04 EST][out] 10.112.36.42 - - [Wed, 13 Nov 2013 23:34:04 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "mibi/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/13 18:34:04 EST][err] apnagent:agent-base 0ms push: 9
[11/13 18:34:04 EST][err] apnagent:agent-live 1551651ms write: 8
[11/13 18:34:04 EST][err] apnagent:agent-live 0ms push: 8
[11/13 18:34:04 EST][out] sysmsg message sent to apn
[11/13 18:34:04 EST][err] apnagent:agent-live 0ms write: 9
[11/13 18:34:04 EST][err] apnagent:agent-base 2ms iterate
[11/13 18:34:04 EST][err] apnagent:agent-base 0ms push: 10
[11/13 18:34:04 EST][err] apnagent:agent-live 0ms push: 9
[11/13 18:34:04 EST][out] sysmsg message sent to apn
[11/13 18:34:04 EST][out] sysmsg message sent to apn
[11/13 18:34:04 EST][err] apnagent:cache 1ms push: 9
[11/13 18:34:04 EST][err] apnagent:agent-base 1ms iterate
[11/13 18:34:04 EST][err] apnagent:agent-live 1ms write: 10
[11/13 18:34:04 EST][err] apnagent:agent-live 0ms push: 10
[11/13 18:34:04 EST][err] apnagent:agent-base 1ms iterate
[11/13 18:34:04 EST][err] apnagent:agent-live 0ms write: 10
[11/13 18:34:04 EST][err] apnagent:agent-live 1ms write: 9
[11/13 18:34:04 EST][err] apnagent:cache 1551652ms push: 8
[11/13 18:34:04 EST][err] apnagent:agent-base 0ms drain
[11/13 18:34:04 EST][err] apnagent:agent-live 1ms write: 8
[11/13 18:34:04 EST][err] apnagent:cache 1ms push: 10
[11/13 18:34:31 EST][err] apnagent:cache 26821ms clean older than 1800000ms
[11/13 18:34:31 EST][err] apnagent:cache 0ms flush
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 4
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 5
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 3
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 7
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 2
[11/13 18:34:31 EST][err] apnagent:cache 1ms push: 6
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 8
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 9
[11/13 18:34:31 EST][err] apnagent:cache 0ms push: 10
[11/13 19:04:31 EST][err] apnagent:cache 1800001ms clean older than 1800000ms
[11/13 19:04:31 EST][err] apnagent:cache 1ms flush
[11/13 19:34:31 EST][err] apnagent:cache 1800001ms clean older than 1800000ms
[11/13 19:34:31 EST][err] apnagent:cache 0ms flush
[11/13 19:39:26 EST][err] apnagent:agent-base 3922131ms push: 11
[11/13 19:39:26 EST][err] apnagent:agent-base 0ms push: 13
[11/13 19:39:26 EST][err] apnagent:agent-base 0ms push: 12
[11/13 19:39:26 EST][out] 10.112.36.44 - - [Thu, 14 Nov 2013 00:39:26 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "mibi/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/13 19:39:26 EST][err] apnagent:agent-live 3922132ms write: 11
[11/13 19:39:26 EST][err] apnagent:agent-live 0ms write: 11
[11/13 19:39:26 EST][err] apnagent:agent-live 1ms push: 11
[11/13 19:39:26 EST][err] apnagent:cache 295308ms push: 11
[11/13 19:39:26 EST][err] apnagent:agent-base 1ms iterate
[11/13 19:39:26 EST][out] sysmsg message sent to apn
[11/13 19:39:26 EST][err] apnagent:agent-base 2ms iterate
[11/13 19:39:26 EST][err] apnagent:agent-live 0ms write: 12
[11/13 19:39:26 EST][err] apnagent:agent-base 0ms iterate
[11/13 19:39:26 EST][out] sysmsg message sent to apn
[11/13 19:39:26 EST][err] apnagent:cache 1ms push: 12
[11/13 19:39:26 EST][err] apnagent:agent-live 0ms write: 13
[11/13 19:39:26 EST][out] https
[11/13 19:39:26 EST][err] apnagent:agent-live 1ms write: 13
[11/13 19:39:26 EST][err] apnagent:agent-live 0ms push: 12
[11/13 19:39:26 EST][err] apnagent:agent-base 1ms drain
[11/13 19:39:26 EST][out] sysmsg message sent to apn
[11/13 19:39:26 EST][err] apnagent:cache 1ms push: 13
[11/13 19:39:26 EST][err] apnagent:agent-live 0ms push: 13
[11/13 19:39:26 EST][err] apnagent:agent-live 1ms write: 12
[11/13 19:44:36 EST][err] apnagent:agent-live 310083ms error: read ETIMEDOUT

@NicolaiSchnack
Copy link
Author

I don't know why, but I haven't observed the problem since! but maybe you should look at the cache settings?
I use :
agent.set('reconnect delay', '1s');
agent.set('cache ttl','30m');

@netlogic
Copy link

First with the cache ttl settings I had the 30m for the
// common settings
agent
.set('expires', '1d')
.set('reconnect delay', '1s')
.set('cache ttl', '30m');

With the response related to the error. Yes I could ,on error, close the gateway and restart a new one (same idea as restarting server) but for the community is this the desired behavior or just a work around? Work around is fine as long as we document the behavior. Also as my error relates to a timeout it might be better to reduce the cache ttl.

@netlogic
Copy link

I put in reconnect logic in the message error handle. But for the following error:

apnagent:agent-live 81004ms error: read ETIMEDOUT

My error callback is not getting called. I have no others errors as my tokens are valid and the send function completes without errors.

So my handler for:
agent.on('message:error', function (err, msg) {

Is never called.

Also I get valid callbacks for the sends. But nothing is sent and then later ETIMEDOUT error appears.

So the question is how can I catch the gateway error? And what do I do about the messages that are seem to send correctly but then never go anywhere?

Sorry if this is not that clear.

@netlogic
Copy link

So I added a handler for the gateway error and it works great.
Gateway error happens, close the connection, and then I can resend a message.
But it doesn't solve the problem that messages stop sending after awhile and I do not know if a message was really sent or not. Any ideas?

For others here is my reconnect logic handler for the gateway error.

agent.on('gateway:error', function(err) {
console.log("apgn gateway error " + err.message );
if ( _bConnectedToAPNSGateway ) {
/* we will now close the gateway on error as per discussion and then reopen _/
console.log("closing connection to APNS gateway");
bConnectedToAPNSGateway = false;
process.nextTick( function() {
agent.close( function() {
/
* then we will try to reopen the connection */
agent.connect( function(err) {
console.log("Connection to APNS gateway reopened");
_bConnectedToAPNSGateway = true;
});
});
} );
}
} );

@netlogic
Copy link

First thanks for everyone's help so far.
I send a message.
Works great.
Wait 30 minutes.
Send a message.
Nothing gets sent.
No errors reported.
A while later I get a timeout message.
I reconnect successfully and then the same loop.
Log below, any other ideas welcomed.

[11/14 15:21:14 EST][out] 10.112.36.49 - - [Thu, 14 Nov 2013 20:21:14 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/14 15:21:14 EST][err] apnagent:agent-live 3ms write: 12
[11/14 15:21:14 EST][err] apnagent:agent-live 0ms push: 11
[11/14 15:14:19 EST][err] apnagent:agent-live 4871250ms write: 7
[11/14 15:19:37 EST][err] apnagent:cache 1ms pause
[11/14 15:19:37 EST][err] apnagent:cache 0ms push: 9
[11/14 15:21:14 EST][err] apnagent:agent-base 1ms iterate
[11/14 15:49:15 EST][out] https
[11/14 15:49:15 EST][err] apnagent:agent-live 0ms write: 14
[11/14 15:49:15 EST][err] apnagent:agent-base 1680453ms push: 13
[11/14 15:49:15 EST][out] sysmsg message sent to apn
[11/14 15:49:15 EST][err] apnagent:cache 1680456ms push: 13
[11/14 15:49:15 EST][err] apnagent:agent-base 2ms drain
[11/14 15:49:15 EST][err] apnagent:agent-base 0ms push: 14
[11/14 15:49:15 EST][out] sysmsg message sent to apn
[11/14 15:49:15 EST][err] apnagent:agent-live 0ms push: 14
[11/14 15:49:15 EST][err] apnagent:agent-base 0ms push: 15
[11/14 15:49:15 EST][err] apnagent:agent-base 0ms iterate
[11/14 15:49:15 EST][err] apnagent:agent-live 0ms push: 13
[11/14 15:49:15 EST][out] sysmsg message sent to apn
[11/14 15:49:15 EST][err] apnagent:agent-base 1ms iterate
[11/14 15:49:15 EST][err] apnagent:agent-live 1ms write: 14
[11/14 15:49:15 EST][err] apnagent:cache 0ms push: 14
[11/14 15:49:15 EST][err] apnagent:agent-live 0ms write: 13
[11/14 15:49:15 EST][err] apnagent:cache 2ms push: 15
[11/14 15:49:15 EST][err] apnagent:agent-base 1ms iterate
[11/14 15:49:15 EST][err] apnagent:agent-live 0ms write: 15
[11/14 15:49:15 EST][err] apnagent:agent-live 1680455ms write: 13
[11/14 15:49:15 EST][err] apnagent:agent-live 0ms push: 15
[11/14 15:49:15 EST][out] 10.112.36.46 - - [Thu, 14 Nov 2013 20:49:15 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/14 15:49:15 EST][err] apnagent:agent-live 1ms write: 15
[11/14 15:49:37 EST][err] apnagent:cache 22201ms clean older than 1800000ms
[11/14 15:49:37 EST][err] apnagent:cache 0ms push: 11
[11/14 15:49:37 EST][err] apnagent:cache 0ms push: 12
[11/14 15:49:37 EST][err] apnagent:cache 0ms push: 13
[11/14 15:49:37 EST][err] apnagent:cache 0ms flush
[11/14 15:49:37 EST][err] apnagent:cache 0ms push: 10
[11/14 15:49:37 EST][err] apnagent:cache 1ms push: 15
[11/14 15:49:37 EST][err] apnagent:cache 0ms push: 14
[11/14 16:19:37 EST][err] apnagent:cache 0ms flush
[11/14 16:19:37 EST][err] apnagent:cache 1800008ms clean older than 1800000ms
[11/14 16:49:37 EST][err] apnagent:cache 1800008ms clean older than 1800000ms
[11/14 16:49:37 EST][err] apnagent:cache 0ms flush
[11/14 17:01:57 EST][err] apnagent:agent-live 0ms push: 16
[11/14 17:01:57 EST][out] sysmsg message sent to apn
[11/14 17:01:57 EST][out] sysmsg message sent to apn
[11/14 17:01:57 EST][err] apnagent:cache 740417ms push: 16
[11/14 17:01:57 EST][err] apnagent:agent-base 1ms drain
[11/14 17:01:57 EST][err] apnagent:agent-base 1ms iterate
[11/14 17:01:57 EST][err] apnagent:agent-base 1ms iterate
[11/14 17:01:57 EST][err] apnagent:agent-live 1ms write: 18
[11/14 17:01:57 EST][err] apnagent:agent-live 0ms write: 16
[11/14 17:01:57 EST][err] apnagent:cache 1ms push: 18
[11/14 17:01:57 EST][err] apnagent:agent-live 4362636ms write: 16
[11/14 17:01:57 EST][err] apnagent:agent-live 0ms push: 18
[11/14 17:01:57 EST][out] 10.112.36.42 - - [Thu, 14 Nov 2013 22:01:57 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/14 17:01:57 EST][err] apnagent:agent-live 0ms write: 18
[11/14 17:01:57 EST][err] apnagent:agent-base 4362632ms push: 16
[11/14 17:01:57 EST][err] apnagent:cache 1ms push: 17
[11/14 17:01:57 EST][err] apnagent:agent-base 0ms push: 18
[11/14 17:01:57 EST][err] apnagent:agent-base 0ms iterate
[11/14 17:01:57 EST][err] apnagent:agent-live 0ms push: 17
[11/14 17:01:57 EST][err] apnagent:agent-base 2ms push: 17
[11/14 17:01:57 EST][out] sysmsg message sent to apn
[11/14 17:01:57 EST][out] https
[11/14 17:01:57 EST][err] apnagent:agent-live 1ms write: 17
[11/14 17:01:57 EST][err] apnagent:agent-live 0ms write: 17
[11/14 17:03:42 EST][err] apnagent:agent-base 104997ms push: 19
[11/14 17:03:42 EST][err] apnagent:agent-live 0ms write: 20
[11/14 17:03:42 EST][out] sysmsg message sent to apn
[11/14 17:03:42 EST][err] apnagent:agent-base 1ms drain
[11/14 17:03:42 EST][err] apnagent:cache 105000ms push: 19
[11/14 17:03:42 EST][err] apnagent:agent-base 1ms push: 20
[11/14 17:03:42 EST][out] https
[11/14 17:03:42 EST][err] apnagent:agent-live 1ms push: 20
[11/14 17:03:42 EST][out] 10.112.36.42 - - [Thu, 14 Nov 2013 22:03:42 GMT] "POST /api/sendSystemMessage HTTP/1.1" 200 16 "-" "/1.061 (iPhone Simulator; iOS 7.0.3; Scale/2.00)"
[11/14 17:03:42 EST][err] apnagent:agent-base 1ms iterate
[11/14 17:03:42 EST][err] apnagent:agent-base 0ms push: 21
[11/14 17:03:42 EST][out] sysmsg message sent to apn
[11/14 17:03:42 EST][err] apnagent:agent-base 1ms iterate
[11/14 17:03:42 EST][err] apnagent:agent-live 0ms write: 21
[11/14 17:03:42 EST][err] apnagent:agent-live 104999ms write: 19
[11/14 17:03:42 EST][err] apnagent:agent-live 1ms write: 21
[11/14 17:03:42 EST][err] apnagent:agent-live 1ms write: 20
[11/14 17:03:42 EST][out] sysmsg message sent to apn
[11/14 17:03:42 EST][err] apnagent:cache 2ms push: 20
[11/14 17:03:42 EST][err] apnagent:agent-live 0ms push: 19
[11/14 17:03:42 EST][err] apnagent:cache 1ms push: 21
[11/14 17:03:42 EST][err] apnagent:agent-base 2ms iterate
[11/14 17:03:42 EST][err] apnagent:agent-live 1ms write: 19
[11/14 17:03:42 EST][err] apnagent:agent-live 0ms push: 21
[11/14 17:07:28 EST][err] apnagent:agent-live 0ms connecting - gateway.push.apple.com:2195
[11/14 17:07:28 EST][err] apnagent:cache 225581ms pause
[11/14 17:07:28 EST][err] apnagent:cache 1ms pause
[11/14 17:07:28 EST][out] closing connection to APNS gateway
[11/14 17:07:28 EST][err] apnagent:agent-live 1ms closed - gateway.push.apple.com:2195
[11/14 17:07:28 EST][err] apnagent:agent-base 225594ms drain
[11/14 17:07:28 EST][err] apnagent:cache 0ms push: 21
[11/14 17:07:28 EST][err] apnagent:agent-live 241ms connected - gateway.push.apple.com:2195
[11/14 17:07:28 EST][err] apnagent:cache 0ms push: 18
[11/14 17:07:28 EST][err] apnagent:cache 0ms push: 20
[11/14 17:07:28 EST][err] apnagent:cache 0ms push: 17
[11/14 17:07:28 EST][err] apnagent:cache 0ms flush
[11/14 17:07:28 EST][err] apnagent:cache 0ms push: 16
[11/14 17:07:28 EST][err] apnagent:cache 0ms push: 19
[11/14 17:07:28 EST][err] apnagent:agent-live 0ms disconnecting
[11/14 17:07:28 EST][err] apnagent:cache 241ms resume
[11/14 17:07:28 EST][err] apnagent:cache 0ms clean older than 1800000ms
[11/14 17:07:28 EST][out] apgn gateway error read ETIMEDOUT
[11/14 17:07:28 EST][out] Connection to APNS gateway reopened
[11/14 17:07:28 EST][err] apnagent:agent-live 225581ms error: read ETIMEDOUT

@logicalparadox
Copy link
Owner

@netlogic I did a little research into your problem and it seems that it may also be some issue on Apple's side. Whether its a bug or if they consider it a feature is unknown, but either way it is problematic and not isolated to apnagent as far as I can tell (Node.js net/tls sockets do not have a timeout by default).

The solution that keeps coming up is "resetting" the connection every 10 minutes or so to always ensure an active connection. Try this out and see if it works and if it does I will bake it into apnagent.

var reset = setInterval(function() {
  agent.close(function() {
    agent.connect(function(err) {
      if (err) {
        clearInterval(reset);
        console.error('Error resetting apnagent:', err.message);
        return;
      }

      console.log('timeout averted');
    });
  });
}, 10 * 60 * 100);

Let me know if this works out; also, you may need to adjust the timing a bit but I would start with 10 mins.

@netlogic
Copy link

Thank you for all the hard work. It is very much appreciated.
Will try it out and report back any problems if they occur.

@logicalparadox
Copy link
Owner

Wanted to check back and see if the interval reset has solved connection timeout issue. Any news?

@yujinlim
Copy link

same thing happened here. Is there any solution yet?

@gakshay
Copy link

gakshay commented Aug 27, 2014

Receiving the same error when trying to connect. Output with with debug on

apnagent:agent-live 0ms (gateway) connecting - gateway.sandbox.push.apple.com:2195
apnagent:agent-base 0ms (queue) push: 0
apnagent:agent-base 2ms (queue) drain
apnagent:agent-live 75558ms (gateway) error: connect ETIMEDOUT
apnagent:cache 75565ms (timer) pause
apnagent:agent-live 1ms (gateway) closed - gateway.sandbox.push.apple.com:2195
apnagent:agent-base 75538ms (queue) drain

Not sure what to do next.

@gakshay
Copy link

gakshay commented Aug 27, 2014

Worked, finally I figured out that company network was blocking connection to Apple Sandbox server.

@varsha123
Copy link

I have stuck in "MAKING THE CONNECTION" steps in "Delivering iOS Push Notifications with Node.js"
I am using windows 7 to send ios push notfication using node.js..
After executing "node agent/_header.js"

getting error "Error apgn gateway error 1860:error:14094416:SSL routines:SSL3READBYTES:sslv3 a lert certificate unknown:openssl\ssl\s3_pkt.c:1256:SSL alert number 46"

Kindly help to resolve this issue..I am new to node.js....
Same ios certificate and device token working using java..

@countravioli
Copy link

IIRC our key generated from Apple was due to expire at the end of this month and we implemented new ones about a month ago. Maybe a similar issue there.

@jmdiego
Copy link

jmdiego commented Oct 31, 2014

Well, the thing is tha apple changed some things regarding protocols, the request were compatible with SSL 3.0 and TLS, but since they found a "security leak" in SSL 3.0, they stopped the support, so you have to work with TLS since Aug 29th.

Now my problem is something similar though, since that support change, my pushes never respond, I can't open the apnagent's documentation to verify it connects through TLS (seems to be offline), and I've checked the library files and it seems that it ONLY works with TLS, or at least as a default I guess, so I should have not that problem, right?

There is no error logged, there is no apparent cause to this issue, it just that the "send" command, never executes it's callback.

ExploreMqt pushed a commit that referenced this issue Jan 25, 2017
…(issue #1) (#40)

* Revert "Added device to metadata of mock error message"

This reverts commit 6023638.

* Enable tcp keepalive for early detection of severed tcp connections (issue #1)

* Reapply "Added device to metadata of mock error message"

This reverts commit c5da91a.

* Made TCP keepalive delay configurable

* Added naive test for TCP keepalive enabled/disabled
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

8 participants