RocketChat / Rocket.Chat

The communications platform that puts data protection first.
https://rocket.chat/
Other
40.64k stars 10.64k forks source link

iOS Test Push Notification: Could not send notification id: \"undefined\", Error: Cannot read property 'send' of undefined #23567

Open Zeromax opened 3 years ago

Zeromax commented 3 years ago

Description:

I have a own RocketChat server running. Therefore I configured Push notifications with own Google Firebase Cloud Messaging.
For Android it works fine.
For iOS not.

Steps to reproduce:

Prerequisit: Proper setup for Cloud Messaging in Google console. I only configured APN/Apple for Production. No need for develop.

  1. Go to Admin Settings Push Notifications
  2. Enable push notification
  3. Disable Gateway
  4. Enable Production
  5. Insert APN-Passphrase
  6. Insert APN-Key
  7. Insert APN-Cert
  8. Leave APN Dev settings empty
  9. Insert GCM-API-Key
  10. Insert GCM-Projectnumber
  11. Save Settings (maybe insert Password if requested)
  12. Restart Rocketchat
  13. Login on a Android Device (as same admin uer which is logged currently)
  14. Login on a iOS Device (as same admin uer which is logged currently)
  15. Click on "Send test push notification"
  16. You will not recieve any Push notification

Expected behavior:

I expected that a Test Push notification was send to my iOS phone and on my Android phone.
Even if sending push notification to iOS fails, I expected, that Android will still get Notifications.

Actual behavior:

Even on iOS or Android this admin user will not get any Push notification.
Others with only Android will still recieve Notifications.

Also when getting normal messages, this user will not get any notification on iOS or Android.

Server Setup Information:

Client Setup Information

Additional context

If I remove the APN tokens in Database from this User directly in MongoDB:

// take care: Will remove ALL iOS tokens.
db.getCollection('_raix_push_app_tokens').deleteMany({ appName: "IOS_APP_NAME" })

db.getCollection('_raix_push_app_tokens').find()

db.getCollection('_raix_push_app_tokens').find({userId: "USER_ID"})

Then this admin user can recieve push notifications again on Android

Relevant logs:

rocketchat_1          | {"level":35,"time":"2021-10-26T17:58:08.118Z","pid":12,"hostname":"b5f052d979d3","name":"Meteor","method":"push_test","userId":"USER_ID","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:93.0) Gecko/20100101 Firefox/93.0","referer":"https://DOMAIN_NAME/admin/Push","remoteIP":"SERVER_IP","instanceId":"ixSWZfkv4kdtLyC4A"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.125Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"Sending notification {\"createdAt\":\"2021-10-26T17:58:08.125Z\",\"createdBy\":\"<SERVER>\",\"sent\":false,\"sending\":0,\"from\":\"push\",\"title\":\"@USER_NAME\",\"text\":\"This is a push test message\",\"userId\":\"USER_ID\",\"sound\":\"default\",\"apn\":{\"text\":\"@USER_NAME:\
This is a push test message\"}}"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.126Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"send message \"@USER_NAME\" to userId 'USER_ID'"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.128Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"send to token {\"gcm\":\"TOKEN_1\"}"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.128Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"send to token {\"gcm\":\"TOKEN_1\"}"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.129Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"sendGCM [\"TOKEN_1\"] {\"createdAt\":\"2021-10-26T17:58:08.125Z\",\"createdBy\":\"<SERVER>\",\"sent\":false,\"sending\":0,\"from\":\"push\",\"title\":\"@USER_NAME\",\"text\":\"This is a push test message\",\"userId\":\"USER_ID\",\"sound\":\"default\",\"apn\":{\"text\":\"@USER_NAME:\
This is a push test message\"}}"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.129Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"For devices running Android 8.0 or later you are required to provide an android_channel_id. See https://github.com/raix/push/issues/341 for more info"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.129Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"Create GCM Sender using \"GCM_TOKEN\""}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.129Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"A:Send message to: TOKEN_1"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.130Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"send to token {\"apn\":\"APPLE_TOKEN_1\"}"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.130Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"send to token {\"apn\":\"APPLE_TOKEN_1\"}"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.131Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"Could not send notification id: \"undefined\", Error: Cannot read property 'send' of undefined"}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.135Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"TypeError: Cannot read property 'send' of undefined
    at sendAPN (app/push/server/apn.js:48:16)
    at PushClass.sendNotificationNative (app/push/server/push.js:87:5)
    at app/push/server/push.js:208:16
    at SynchronousCursor.forEach (packages/mongo/mongo_driver.js:1141:16)
    at Cursor.<computed> [as forEach] (packages/mongo/mongo_driver.js:920:44)
    at PushClass.sendNotification (app/push/server/push.js:201:35)
    at PushClass.send (app/push/server/push.js:325:9)
    at MethodInvocation.push_test (server/lib/pushConfig.js:56:8)
    at MethodInvocation.methodsMap.<computed> (app/lib/server/lib/debug.js:66:34)
    at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1771:12)
    at packages/ddp-server/livedata_server.js:1689:15
    at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
    at packages/ddp-server/livedata_server.js:1687:36
    at new Promise (<anonymous>)
    at Server.applyAsync (packages/ddp-server/livedata_server.js:1686:12)
    at Server.apply (packages/ddp-server/livedata_server.js:1625:26)
    at Server.call (packages/ddp-server/livedata_server.js:1607:17)
    at Object.post (app/api/server/v1/misc.js:240:26)
    at app/api/server/api.js:406:82
    at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
    at Object._internalRouteActionHandler [as action] (app/api/server/api.js:406:39)
    at Route.share.Route.Route._callEndpoint (packages/nimble_restivus/lib/route.coffee:150:32)"}
rocketchat_1          | {"level":35,"time":"2021-10-26T17:58:08.136Z","pid":12,"hostname":"b5f052d979d3","name":"API","method":"POST","url":"/api/v1/method.call/push_test","userId":"USER_ID","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:93.0) Gecko/20100101 Firefox/93.0","length":"87","host":"DOMAIN_NAME","referer":"https://DOMAIN_NAME/admin/Push","remoteIP":"SERVER_IP","status":200,"responseTime":18}
rocketchat_1          | {"level":20,"time":"2021-10-26T17:58:08.237Z","pid":12,"hostname":"b5f052d979d3","name":"Push","msg":"ANDROID: Result of sender","result":{"multicast_id":3915736355400703500,"success":1,"failure":0,"canonical_ids":0,"results":[{"message_id":"0:1635271088214377%cfce24ca0034af1a"}]}}
Zeromax commented 3 years ago

Finally I found the root cause of this error. In this case Rocket Chat is not really good in explaining it in documentation and showingg where to find the Issues. I will try to help improve the docs if i find the time.

So the root cause can only be found when watching the logs before rocket chat is started up. To keep things short: I checked out the repo and run latest master build and did the same configuration as on my prod server for debuging and adding additional logs if needed.

I found this log (before the server was ready to use):

I20211031-10:10:51.362(1)? [2021-10-31T09:10:51.358Z] DEBUG (Push/1101 on MAC-C02D41CXMD6M): APN configured
I20211031-10:10:51.363(1)? [2021-10-31T09:10:51.358Z] WARN (Push/1101 on MAC-C02D41CXMD6M): WARNING: Push APN is configured to production mode - but server is running from localhost
I20211031-10:10:51.363(1)? [2021-10-31T09:10:51.359Z] ERROR (Push/1101 on MAC-C02D41CXMD6M): Error trying to initialize APN
I20211031-10:10:51.363(1)? [2021-10-31T09:10:51.359Z] ERROR (Push/1101 on MAC-C02D41CXMD6M): ENAMETOOLONG: name too long, open 'XXXKey starts here'

I configured the APN certs like described in the doc, by putting in the content of it into those fields. At the end of apn.js there is this code:

try {
    apnConnection = new apn.Provider(options.apn);
} catch (e) {
    logger.error('Error trying to initialize APN');
    logger.error(e);
}

So in my case apnConnection will be undefined, because during creating the provider the error ENAMETOOLONG: name too long, open 'XXXKey starts here occures.

That means later, when sending the test push notification the Error TypeError: Cannot read property 'send' of undefined at sendAPN (app/push/server/apn.js:48:16) makes sence, because apnConnection is undefined and calling apnConnection.send() will lead to this error.

So this is why this error happens. IMO Rocket chat should try to reinitialize apn connection when sending the test push, if apnConnection is undefined. Also: It would be important to change the note in the beginning to: Any change on this setting page requires a server restart, this was also not clear to me.

Solution

I came up with a solution for this. Instead of paste the cert and key content of the APN connection, I used the file path for it:

Bildschirmfoto 2021-10-31 um 10 31 03

And added the files to a folder and link them to the container:

volumes:
      - ./certs:/app/apn-certs

After restarting the server, APN push notification works.

conclusion

I hope this helps to understand the pain of configuring a whitelabel server with APN.

IMO only docs and error output of rocket chat needs to be improved, as it is a real problem to understand what goes wrong and what to change.