push fails with status 400 and reason BadExpirationDate

[mman]

Issue Description

Upgraded to parse server 2.7.2 and all my pushes are failing with the following error message:

node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device <xxx> with status 400 and reason BadExpirationDate

Upgraded to node 8, upgraded to push-adapter 3.0.0-alpha1 and it is all the same error. No push gets through or very few of them (under 5%).

Removed the expiration_interval: 120 from my cloud code push fragments and pushes seem to go through fine again.

Steps to reproduce

Sending pushes via cloud code with

        Parse.Push.send({
          where: realQuery,
          expiration_interval: 120,
          data: payload
        }, {
          success: function() {
            response.success("OK")
          },
          error: function(error) {
            var msg = "Parse.Push.send() ERROR: " + error.code + " " + error.message;
            console.log(msg);
            response.error(msg);
          },
          useMasterKey: true
        });

The expiration_interval: 120 should indicate that push message is valid for 2 minutes only.

Expected Results

Before upgrading the pushes were working fine, I'm not sure if expiration_interval was taken into account but it definitely never produced any error messages. The pushes were sent.

Actual Outcome

With expiration_interval: 120 no pushes are sent and all attempts produce a BadExpirationTime error.

Environment Setup

parse-server version 2.7.2 with push-adapter 3.0.0-alpha1 and push-adapter 2.0.2

[flovilmart]

if you increase your expiration interval, does it help?

[mman]

Not sure if it matters, but here is an interesting observation:

parse-server/src/Controllers/PushController.js

Line 33 in 8a23c00

body['push_time'] = PushController.formatPushTime(pushTime);

.

The push_time is formatted to ISO string using PushController.formatPushTime.

whereas:

parse-server/src/Controllers/PushController.js

Line 28 in 8a23c00

body.expiration_time = (new Date(now.valueOf() + ttlMs)).valueOf();

The expiration_time is simply set to valueOf given Date which returns milliseconds.

The Apple Guide here (https://developer.apple.com/library/content/documentation/NetworkingInternet/Conceptual/RemoteNotificationsPG/CommunicatingwithAPNs.html#//apple_ref/doc/uid/TP40008194-CH11-SW1) says that apns-expiration is a UNIX epoch date expressed in seconds (UTC).

expiration_time in milliseconds is passed through to the push-adapter and converted back to seconds here: https://github.com/parse-community/parse-server-push-adapter/blob/4d90634d00278886877291fd7ddd405c5320c6c6/src/APNS.js#L212.

Not sure if it rings a bell with somebody, just investigating.

[flovilmart]

So the expiration should be added to the pushTime, instead of the current date

[mman]

I'm using pushTime of none, that is push immediately and used to have expiration_interval: 60.
Increased it to 120 but that did not make change.

I assume it can not take more than 120 seconds for the cloud function to process and schedule the push so that it would potentially send it to the apple server with expiration time in the past. But I need to investigate that route as well.

[flovilmart]

Is the ttl properly converted to milliseconds or just send as is?

From what I can see, the ttl is properly converted to milliseconds, and it seems that the code is 'valid'

> now = new Date(); exp = (new Date(now.valueOf() + ttlMs)).valueOf();
1518126658927
> exp
1518126658927
> now
2018-02-08T21:50:48.927Z

[mman]

Tried increasing the expiration_interval to 300, still no luck, simply mentioning the expiration_interval causes all pushes to receive BadExpirationDate.

[flovilmart]

ARE you able to put a log inside APNS after the payload is generated to see how it looks like? Monkey patching the send method would be easy, I can share a sample it you like

[mman]

Tried once more to increase the expiration_interval to 30000 in case there is some weirdness with secs/millis but no luck. Just putting the parameter there breaks it. Removing it and pushes are getting through.

Will try to experiment with logging inside of APNS or better yet down at node-apn level to see what gets sent, but not today, way too dark here already :)

[flovilmart]

UHM, i’ll Try on our dev infra

[mman]

I have hooked into APNS.js line 214 here: https://github.com/parse-community/parse-server-push-adapter/blob/4d90634d00278886877291fd7ddd405c5320c6c6/src/APNS.js#L214

dumping what notification gets generated there when expiration_interval is specified in Parse.Push.send and when it is not specified. The output is always the same yet presenting expiration_interval makes the send fail.

node-pre-gyp ERR! parse-server-push-adapter APNS APNS: _generateNotification: {"aps":{"alert":{"body":"body","title":"title"},"sound":"sound.wav","category":"mycat","mutable-content":1}}
Feb  9 14:01:55 db1-nyc3 14e07639eeb5[782]: node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device 7937f928c236a264182fb9c22549adbfdab90c30627fa15704e9c4f592308d75 with status 400 and reason BadExpirationDate

[mman]

Here we go boys, I think I got it. The bug is that apns-expiration that gets sent is a fractional number instead of number of seconds as APNS expect:

Feb  9 14:15:40 db1-nyc3 14e07639eeb5[782]: APNS: _generateNotification: {"aps":{"alert":{"body":"body","title":"title"},"category":"default","mutable-content":1}}
Feb  9 14:15:40 db1-nyc3 14e07639eeb5[782]: HEADERS: {"apns-expiration":1518182259.475,"apns-topic":"appid","apns-collapse-id":"30736ed73a3f41f5950f58fa7e264957"}
Feb  9 14:15:40 db1-nyc3 14e07639eeb5[782]: COMPILED: {"aps":{"alert":{"body":"body","title":"title"},"category":"default","mutable-content":1}}
Feb  9 14:15:41 db1-nyc3 14e07639eeb5[782]: node-pre-gyp ERR! parse-server-push-adapter APNS APNS error transmitting to device 4be4c5cb3d032880620d8e76dfe8dc8c8bffd3b81908d60f157df6d36f7f098c with status 400 and reason BadExpirationDate

The HEADERS and COMPILED outputs come straight down from node-apn/lib/notification.js.

[flovilmart]

Is it from node apn or the push Adapter?

[mman]

the debug info is from node-apn and I think the .expiry field gets computed wrong, very probably when being converted from milliseconds to seconds by dividing by 1000. This is where a big integer number gets divided into a float something.something. Need to find out where.

[mman]

I bet it's here, the apn.Notification gets created and it's expiry field is computed by dividing by 1000 producing a floating point number that gets passed down to apn library, apn in turn just passes this field to apns-expiration HTTP/2 header.

https://github.com/parse-community/parse-server-push-adapter/blob/4d90634d00278886877291fd7ddd405c5320c6c6/src/APNS.js#L212

The fix is probably to use someting like

notification.expiry = Math.round(Number(headers.expirationTime / 1000));

[flovilmart]

Can you try it out and open a PR accordingly?