parse-community/parse-server-push-adapter

APNS VError: apn write failed: Not receiving Ping response after 150000 ms

funkenstrahlen opened this issue Β· 40 comments

I run parse server 2.5.3 with push adapter 2.0.0.

After a lot of errors in the console APNS error transmitting to device XXXXXXXXXXXXXX with status 400 and reason BadDeviceToken I see APNS connection failing.

Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS VError: apn write failed: Not receiving Ping response after 150000 ms 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.stream.on.err (/app/node_modules/apn/lib/client.js:105:21) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:115:13) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.emit (events.js:210:7) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at _connection._streamIds.forEach (/app/node_modules/apn/lib/protocol/endpoint.js:155:16) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at Array.forEach (native) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at Endpoint.close [as _close] (/app/node_modules/apn/lib/protocol/endpoint.js:139:33) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:120:20) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at TLSSocket.emit (events.js:210:7) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at _handle.close (net.js:549:12) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS     at TCP.done [as _onclose] (_tls_wrap.js:350:7) 
Jul 20 11:03:31 parse-server app/web.1: node-pre-gyp ERR! parse-server-push-adapter APNS  APNS error transmitting to device %s with error %s

This causes push notifications to not be delivered.

Seems to be an issue of node-apn node-apn/node-apn#583

Had to downgrade to parse server 2.4.2 to fix this in production for now.

You can always downgrade 'just' the push adapter and provide the custom adapter at startup time.

@funkenstrahlen thanks for referencing the node-apn I didn't notice any issue on our production apps yet.

@funkenstrahlen we had this same error on our production server (parse-server 2.5.3 and parse-server-push-adapter 2.0.0), after some investigation we found out it always happened when sending push notifications to one particular user with over 100 installations. We deleted all the outdated installations and haven't gotten this error message since.

This is only a short term solution, but we haven't found the root cause of the error yet.

after some investigation we found out it always happened when sending push notifications to one particular user with over 100 installations. We deleted all the outdated installations and haven't gotten this error message since.

I have no user with over 100 installations in my database and the error occurred.

We are seeing this, too on our production server with 72k installations. Only a fraction of our iOS users currently receive push messages. I just deleted around 2000 installations (i.e., wrote a script to extract the reported tokens from pm2 error logs, then deleted corresponding installations from mongodb) with bad device tokens and hope that fixes things...

Edit: the amount of sent pushes is back to normal after deleting these tokens

@kontextbewusst For me this looks like bad device tokens are causing a lot of retries sending the push notification and finally APNS is blocking the connection?

I am worried nothing is happening in the node-apn issue thread: node-apn/node-apn#583

hopye commented

Any fix for this ? it is happening to me on my production server ? only fix is to downgrade ?

@hopye, no, the fix is to provided it on node-apn. Which is open source as well. Anyone could work out a fix.

@funkenstrahlen any chance you’d be able to check it on node-apn side?

@flovilmart I am sorry but I currently do not have sufficient knowledge to work on the node-apn module. This would require me to spend many hours just to understand how it works before I can even start thinking about the bug.

@funkenstrahlen All good ! no problem!

hopye commented

Please guys πŸ™πŸ™πŸ™πŸ™πŸ™πŸ™πŸ™πŸ™

@funkenstrahlen, does the error prevent any further notification being sent or will the connection be re established at one point?

Asking that as we do not notice it and we’ee Sending an honorable volume daily

hopye commented

@flovimart it does come back at one point.. i think i can help you with logs and testing.....

hopye commented

Ill be at home in 30 minutes or less.. i could do some live testing to produce the error and send you logs if you need them

hopye commented

@flovilmart @funkenstrahlen i just updated to latest parse-server, did some test and havent seem the error again.. even thought i have several bad attempts to send because of bad tokens.. after sending to an ios audience of 2,500.. Push is sending fine and havent seem the time out.. ill be making some more tests on it... For now.. looks Good with parse server 2.6.1

node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device bcc47a9ee3bdcfb86b50ad7adab4feedb949d7766392ab9b97c4
11d7b38d3ec2 with status 400 and reason BadDeviceToken
node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device 7db7d42e97e4800b5a1c7ada64b900b740bc7b82bb1a281071be
78123636dfd2 with status 400 and reason BadDeviceToken
node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device 1b8468c7624a953f71a3f612cefd7e06bea30e2169184c5deacd
761cf432eae3 with status 400 and reason BadDeviceToken
node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device 2af4542c6b414979f3a0fc558db73026079ad2e610cf64fdaf07
2805eade026e with status 400 and reason BadDeviceToken
node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device 
hopye commented

Hi guys @flovilmart @funkenstrahlen , just wanted to update. After seeing bunch of bad tokens in the log.. the same is happening..

at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/client.js:105:21)\n    at emitOne (events.js:96:13)\n  
  at Stream.emit (events.js:188:7)\n    at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/protoc
ol/endpoint.js:155:16)\n    at Array.forEach (native)\n    at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_mod
ules/apn/lib/protocol/endpoint.js:139:33)\n    at emitOne (events.js:101:20)\n    at TLSSocket.emit (events.js:188:7)\n    at _handle
.close (net.js:497:12)\n    at TCP.done [as _onclose] (_tls_wrap.js:332:7)' }
node-pre-gyp ERR! parse-server-push-adapter APNS VError: apn write failed: Not receiving Ping response after 150000 ms
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/cli
ent.js:105:21)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:96:13)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:155:16)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Array.forEach (native)
node-pre-gyp ERR! parse-server-push-adapter APNS     at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:139:33)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:101:20)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TLSSocket.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _handle.close (net.js:497:12)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TCP.done [as _onclose] (_tls_wrap.js:332:7)
node-pre-gyp ERR! parse-server-push-adapter APNS  APNS error transmitting to device %s with error %s 7445700394b0dffb3353ac89fab809a3
68121c5f79ae7f3a172dcfa4cf3674f7 { VError: apn write failed: Not receiving Ping response after 150000 ms
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/cli
ent.js:105:21)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:96:13)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:155:16)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Array.forEach (native)
node-pre-gyp ERR! parse-server-push-adapter APNS     at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:139:33)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:101:20)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TLSSocket.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _handle.close (net.js:497:12)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TCP.done [as _onclose] (_tls_wrap.js:332:7)
node-pre-gyp ERR! parse-server-push-adapter APNS   jse_shortmsg: 'apn write failed: Not receiving Ping response after 150000 ms',
node-pre-gyp ERR! parse-server-push-adapter APNS   jse_info: {},
node-pre-gyp ERR! parse-server-push-adapter APNS   message: 'apn write failed: Not receiving Ping response after 150000 ms',
node-pre-gyp ERR! parse-server-push-adapter APNS   stack: 'VError: apn write failed: Not receiving Ping response after 150000 ms\n   
 at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/client.js:105:21)\n    at emitOne (events.js:96:13)\n  
  at Stream.emit (events.js:188:7)\n    at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/protoc
ol/endpoint.js:155:16)\n    at Array.forEach (native)\n    at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_mod
ules/apn/lib/protocol/endpoint.js:139:33)\n    at emitOne (events.js:101:20)\n    at TLSSocket.emit (events.js:188:7)\n    at _handle
.close (net.js:497:12)\n    at TCP.done [as _onclose] (_tls_wrap.js:332:7)' }
node-pre-gyp ERR! parse-server-push-adapter APNS VError: apn write failed: Not receiving Ping response after 150000 ms
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/cli
ent.js:105:21)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:96:13)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:155:16)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Array.forEach (native)
node-pre-gyp ERR! parse-server-push-adapter APNS     at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:139:33)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:101:20)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TLSSocket.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _handle.close (net.js:497:12)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TCP.done [as _onclose] (_tls_wrap.js:332:7)
node-pre-gyp ERR! parse-server-push-adapter APNS  APNS error transmitting to device %s with error %s 96bc6bd6f9278e0de0bb1cab9e9ad2c7
ebc6ff7fd5721ec47a353137c7576261 { VError: apn write failed: Not receiving Ping response after 150000 ms
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/cli
ent.js:105:21)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:96:13)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:155:16)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Array.forEach (native)
node-pre-gyp ERR! parse-server-push-adapter APNS     at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:139:33)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:101:20)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TLSSocket.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _handle.close (net.js:497:12)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TCP.done [as _onclose] (_tls_wrap.js:332:7)
node-pre-gyp ERR! parse-server-push-adapter APNS   jse_shortmsg: 'apn write failed: Not receiving Ping response after 150000 ms',
node-pre-gyp ERR! parse-server-push-adapter APNS   jse_info: {},
node-pre-gyp ERR! parse-server-push-adapter APNS   message: 'apn write failed: Not receiving Ping response after 150000 ms',
node-pre-gyp ERR! parse-server-push-adapter APNS   stack: 'VError: apn write failed: Not receiving Ping response after 150000 ms\n   
 at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/client.js:105:21)\n    at emitOne (events.js:96:13)\n  
  at Stream.emit (events.js:188:7)\n    at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/protoc
ol/endpoint.js:155:16)\n    at Array.forEach (native)\n    at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_mod
ules/apn/lib/protocol/endpoint.js:139:33)\n    at emitOne (events.js:101:20)\n    at TLSSocket.emit (events.js:188:7)\n    at _handle
.close (net.js:497:12)\n    at TCP.done [as _onclose] (_tls_wrap.js:332:7)' }
node-pre-gyp ERR! parse-server-push-adapter APNS VError: apn write failed: Not receiving Ping response after 150000 ms
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/cli
ent.js:105:21)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:96:13)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:155:16)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Array.forEach (native)
node-pre-gyp ERR! parse-server-push-adapter APNS     at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:139:33)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:101:20)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TLSSocket.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _handle.close (net.js:497:12)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TCP.done [as _onclose] (_tls_wrap.js:332:7)
node-pre-gyp ERR! parse-server-push-adapter APNS  APNS error transmitting to device %s with error %s ea1bda936fd93f96015f814d34349606
27afaa5b6146954fe2cdbb27c7b0b134 { VError: apn write failed: Not receiving Ping response after 150000 ms
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/cli
ent.js:105:21)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:96:13)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Stream.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:155:16)
node-pre-gyp ERR! parse-server-push-adapter APNS     at Array.forEach (native)
node-pre-gyp ERR! parse-server-push-adapter APNS     at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_modules/a
pn/lib/protocol/endpoint.js:139:33)
node-pre-gyp ERR! parse-server-push-adapter APNS     at emitOne (events.js:101:20)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TLSSocket.emit (events.js:188:7)
node-pre-gyp ERR! parse-server-push-adapter APNS     at _handle.close (net.js:497:12)
node-pre-gyp ERR! parse-server-push-adapter APNS     at TCP.done [as _onclose] (_tls_wrap.js:332:7)
node-pre-gyp ERR! parse-server-push-adapter APNS   jse_shortmsg: 'apn write failed: Not receiving Ping response after 150000 ms',
node-pre-gyp ERR! parse-server-push-adapter APNS   jse_info: {},
node-pre-gyp ERR! parse-server-push-adapter APNS   message: 'apn write failed: Not receiving Ping response after 150000 ms',
node-pre-gyp ERR! parse-server-push-adapter APNS   stack: 'VError: apn write failed: Not receiving Ping response after 150000 ms\n   
 at Stream.stream.on.err (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/client.js:105:21)\n    at emitOne (events.js:96:13)\n  
  at Stream.emit (events.js:188:7)\n    at _connection._streamIds.forEach (/opt/bitnami/apps/parse/htdocs/node_modules/apn/lib/protoc
ol/endpoint.js:155:16)\n    at Array.forEach (native)\n    at EventEmitter.close [as _close] (/opt/bitnami/apps/parse/htdocs/node_mod
ules/apn/lib/protocol/endpoint.js:139:33)\n    at emitOne (events.js:101:20)\n    at TLSSocket.emit (events.js:188:7)\n    at _handle
.close (net.js:497:12)\n    at TCP.done [as _onclose] (_tls_wrap.js:332:7)' }
bruun commented

@hopye 2.6.2 has a new feature for removing invalid device tokens, could you try turning that on and see if that helps in any way?

2.6.2 feature to remove invalid device tokens only check for error "Unregistered", not "BadDeviceToken"

Sure! I'll open a PR

I have similar error as @hopye, any solution so far? Or should I use Alternative Services instead?

hopye commented

hey @bivisss @flovilmart , do i have to enable the feature to remove the BadDeviceTokens or it does it automatically ?? i was reading the changelog on parseserver 2.6.2 , i saw some kind of a variable for setting " PARSE_SERVER_CLEANUP_INVALID_INSTALLATIONS=1 " , where should i set this ?

you should set this in your environment variables, when starting your server. We'll make it the default on the next release.

I appreciate there is a way to delete invalid device tokens now. It does only clear the deviceToken database field right?

How does this affect the bug I reported way above with the no ping response error? Looks like there is no node-apn fix yet: node-apn/node-apn#583

Yes, it only removed the deviceToken from the DB, keeping the installations intact. As for the ping error, I’m not sure.

As we haven't seen much activity on node-apn and the never version is being actively worked upon, I tried a workaround (re-generate the provider at every calls) this may incur additional issues, but feel free to test it out. (#104)

node-apn in version 3.0 looks promising but is still in alpha right now: node-apn/node-apn#583

I’ll make a release of the push adapter with the alpha version of apn as well as instructions to provide a custom push adapter

@flovilmart Do you think it is a good idea to make a release with an alpha version?

@funkenstrahlen I'll make an alpha release of the adapter

@flovilmart First tests with the alpha release look good. I do not have enough clients on my testing backend to reliable reproduce the ping error though.

I did not test PARSE_SERVER_CLEANUP_INVALID_INSTALLATIONS setting. Is this enabled by default in 3.0.0-alpha1? Because I saw some logs that indicate device tokens got reset?

Just a suggestion: I think PARSE_SERVER_CLEANUP_INVALID_INSTALLATIONS should better be named PARSE_SERVER_CLEANUP_INVALID_DEVICE_TOKENS because it does not actually cleanup installations.

it's not enabled by default, yes we could rename it, but it seems there's some issues with it, cleaning up still valid tokens: #87 (comment)

I can confirm it is not enabled by default. I forgot I had set PARSE_SERVER_CLEANUP_INVALID_INSTALLATIONS=1 some time ago. That's why it was enabled for me.

@funkenstrahlen did you find a solution to this issue?

My logs are 95% full of these APNS errors, but if I set PARSE_SERVER_CLEANUP_INVALID_INSTALLATIONS=1 I lose valid iOS installations

@funkenstrahlen @flovilmart still experiencing this issue with 3k installation audience.
Should I try the PARSE_SERVER_CLEANUP_INVALID_INSTALLATIONS=1 solution?

Should I try the PARSE_SERVER_CLEANUP_INVALID_INSTALLATIONS=1 solution?

No. It’s not ready for use yet.

@hopye i am having the same issue as yours. Every time i send a notification i get the same log. Any fix?