Push token from android updates wrong userid in rocket chat #13101

pkolmann · 2019-01-09T09:16:57Z

Description:

On our production instance of rocket.chat I have an issue with the android app of rocket chat (3.1.1): It can't receive Push notifications.

I have now enabled push debug and I see the following for my user:

Jan 09 09:50:16 web-d-1 RocketChat[14287]: Push: Got push token from app: { id: '9C2N2wcPo95Ch5zEn',
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   token:
Jan 09 09:50:16 web-d-1 RocketChat[14287]:    { gcm: 'eiDGfCByqJMxxx' },
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   appName: 'Main',
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   userId: 'EeRmbSNepikkwy7mp' }
Jan 09 09:50:16 web-d-1 RocketChat[14287]: Push: updated { _id: '5GfLokDpjGf3hFZL9',
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   token:
Jan 09 09:50:16 web-d-1 RocketChat[14287]:    { gcm: 'eiDGfCByqJMxxx' },
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   appName: 'Main',
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   userId: '7smTD8QANZFowxbx9',
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   enabled: true,
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   createdAt: 2018-10-12T16:15:08.879Z,
Jan 09 09:50:16 web-d-1 RocketChat[14287]:   updatedAt: 2019-01-09T08:48:08.330Z }

The userId received is my proper userid:

      {
         "_id" : "EeRmbSNepikkwy7mp",
         "active" : true,
         "language" : "en",
         "name" : "Philipp Kolmann",
         "status" : "online",
         "type" : "user",
         "username" : "philipp.kolmann",
         "utcOffset" : 1
      },

The userId in the push token (7smTD8QANZFowxbx9) is not found in the Users REST....

When I try to test the push notification, I receive the error:

"ERROR: There are no tokens for this user"

Steps to reproduce:

use rocket chat on android, and login
use a web session with admin rights and the same user and try push notification
receive error

Expected behavior:

push notification works

Actual behavior:

push notification fails, because there is no push token for the user available.

Server Setup Information:

Version of Rocket.Chat Server: 0.73.1
Operating System: Linux web-d-1 4.9.0-8-amd64 Refactored and reorganised entire css/less files and logic. #1 SMP Debian 4.9.110-3+deb9u6 (2018-10-08) x86_64 GNU/Linux
Deployment Method: local build
Number of Running Instances: 8
DB Replicaset Oplog: yes
NodeJS Version: 8.12.0-1nodesource1 (deb package)
MongoDB Version: 3.2.11-2+deb9u1

Additional context

Relevant logs:


�[34mI20190109-09:36:02.941(1) Updating process.env.MAIL_URL 
�[34mI20190109-09:36:03.473(1) Starting Email Intercepter... 
�[34mI20190109-09:36:03.530(1) LocalStore: store created at  
�[34mI20190109-09:36:03.530(1) LocalStore: store created at  
�[34mI20190109-09:36:03.530(1) LocalStore: store created at  
�[34mI20190109-09:36:04.069(1) Setting default file store to GridFS 
�[34mI20190109-09:36:07.840(1) (migrations.js:121) Migrations: Not migrating, already at version 136
�[34mI20190109-09:36:08.204(1) Using GridFS for custom sounds storage 
�[34mI20190109-09:36:08.209(1) Using GridFS for custom emoji storage 
�[34mI20190109-09:36:08.454(1) Updating process.env.MAIL_URL 
�[34mI20190109-09:36:08.604(1) Loaded the Apps Framework and loaded a total of 0 Apps! 
�[34mI20190109-09:36:09.268(1) Push: configuring... 
�[34mI20190109-09:36:09.269(1) Push.Configure { sendTimeout: 60000,   apn: undefined,   gcm: undefined,   production: true,   sendInterval: 5000,   sendBatchSize: 10 } 
�[34mI20190109-09:36:09.271(1) Push: Send worker started, using interval: 5000 
�[34mI20190109-09:36:09.503(1) ➔ System ➔ startup 
�[34mI20190109-09:36:09.503(1) ➔ +--------------------------------------------------+ 
�[34mI20190109-09:36:09.503(1) ➔ |                  SERVER RUNNING                  | 
�[34mI20190109-09:36:09.503(1) ➔ +--------------------------------------------------+ 
�[34mI20190109-09:36:09.503(1) ➔ |                                                  | 
�[34mI20190109-09:36:09.504(1) ➔ |  Rocket.Chat Version: 0.73.1                     | 
�[34mI20190109-09:36:09.504(1) ➔ |       NodeJS Version: 8.12.0 - x64               | 
�[34mI20190109-09:36:09.504(1) ➔ |             Platform: linux                      | 
�[34mI20190109-09:36:09.504(1) ➔ |         Process Port: 8080                       | 
�[34mI20190109-09:36:09.504(1) ➔ |             Site URL: https://chat.tuwien.ac.at  | 
�[34mI20190109-09:36:09.504(1) ➔ |     ReplicaSet OpLog: Enabled                    | 
�[34mI20190109-09:36:09.504(1) ➔ |                                                  | 
�[34mI20190109-09:36:09.504(1) ➔ +--------------------------------------------------+ 
�[34mI20190109-09:48:08.326(1) Push: Got push token from app: { id: 'w7KZeEpBzeR8G8mDC',   token:     { gcm: 'xxx' },   appName: 'Main',   userId: 'EeRmbSNepikkwy7mp' } 
�[34mI20190109-09:48:08.335(1) Push: updated { _id: '5GfLokDpjGf3hFZL9',   token:     { gcm: 'xxx' },   appName: 'Main',   userId: '7smTD8QANZFowxbx9',   enabled: true,   createdAt: 2018-10-12T16:15:08.879Z,   updatedAt: 2019-01-09T06:41:25.186Z } 
�[34mI20190109-09:50:16.914(1) Push: Got push token from app: { id: '9C2N2wcPo95Ch5zEn',   token:     { gcm: 'xxx' },   appName: 'Main',   userId: 'EeRmbSNepikkwy7mp' } 
�[34mI20190109-09:50:16.927(1) Push: updated { _id: '5GfLokDpjGf3hFZL9',   token:     { gcm: 'xxx' },   appName: 'Main',   userId: '7smTD8QANZFowxbx9',   enabled: true,   createdAt: 2018-10-12T16:15:08.879Z,   updatedAt: 2019-01-09T08:48:08.330Z } 
�[34mI20190109-09:54:32.887(1) Push: Got push token from app: { id: 'APxZtDoBq2SQ3dNvD',   token:     { gcm: 'xxx' },   appName: 'Main',   userId: '4hbbGaoa9TLk9bNBm' } 
�[34mI20190109-09:54:32.892(1) Push: updated { _id: 'SQHh7AwrPqrqavS7T',   token:     { gcm: 'xxx' },   appName: 'Main',   userId: '4hbbGaoa9TLk9bNBm',   enabled: true,   createdAt: 2018-11-23T08:21:52.838Z,   updatedAt: 2019-01-09T08:20:03.761Z }

The text was updated successfully, but these errors were encountered:

geekgonecrazy · 2019-01-10T02:18:41Z

Its unclear here. Are you using push gateway or your own? A self built app or our official app?

Also self built Rocket.Chat or an official build?

pkolmann · 2019-01-10T13:04:33Z

I am using the provided gateway and regular rocket chat app from google play store.

pkolmann · 2019-01-10T13:05:52Z

I have a self-built rocket chat because I need additional SAML attributes. (see #12347)

geekgonecrazy · 2019-01-10T20:46:42Z

if you completely close the android app. Making sure its killed from background too. Then start it up again it should register the push token again.

Using your steps to reproduce unfortunately are basically the normal flow we would use and I can't reproduce. So lets see if we can get your tokens loaded back up.

Also in mongo if you run:

db.rocketchat_settings.find().forEach(function(s) {
    if (!s._id.match(/^Assets/) && !s._id.match(/^Layout/) && s._id !== 'css' && s.value !== s.packageValue) {
        print(s._id + ' - ' + s.value);
    }
});

Might help us identify a setting related cause. Of course censor any setting values that are sensitive.

I'm suspecting push gateway maybe with gcm information still being provided? We should be ignoring if gateway is provided... but i'm not certain we are. Your logs kind of make me think this is happening.

pkolmann · 2019-01-11T07:55:56Z

Hi @geekgonecrazy

thanks for your hints. I stopped the app via the settings and started it up again.

I saw in the logfile the registration of my token again:

Jan 11 08:49:42 web-d-1 RocketChat[14598]: The endpoint "permissions" is deprecated and will be removed after version v0.69
Jan 11 08:49:42 web-d-1 RocketChat[14598]: Push: Got push token from app: { id: 'Yxn8Gd77AQeqrSypc',
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   token:
Jan 11 08:49:42 web-d-1 RocketChat[14598]:    { gcm: 'xxx' },
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   appName: 'Main',
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   userId: 'EeRmbSNepikkwy7mp' }
Jan 11 08:49:42 web-d-1 RocketChat[14598]: Push: updated { _id: '5GfLokDpjGf3hFZL9',
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   token:
Jan 11 08:49:42 web-d-1 RocketChat[14598]:    { gcm: 'xxx' },
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   appName: 'Main',
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   userId: '7smTD8QANZFowxbx9',
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   enabled: true,
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   createdAt: 2018-10-12T16:15:08.879Z,
Jan 11 08:49:42 web-d-1 RocketChat[14598]:   updatedAt: 2019-01-10T17:09:27.213Z }

If you check closely the userid in the received JSON is different to the userid in the updated JSON array. For other users I see the same userid in both JSON arrays.

I also only have this problem in our production environment. In our other two setups, everything is working as expected :(

MongoDB Settings:

Accounts_AllowPasswordChange - false
Accounts_ShowFormLogin - false
Accounts_RegistrationForm_SecretURL - XXXXXX
Show_Setup_Wizard - completed
Site_Name - TUchat
Language - de
Push_debug - true
UI_Use_Real_Name - true
Organization_Type - nonprofit
Organization_Name - TU Wien
Industry - education
Size - 7
Country - austria
Website - https://www.tuwien.ac.at/
Server_Type - privateTeam
Allow_Marketing_Emails - false
SAML_Custom_Default - true
SAML_Custom_Default_provider - chat
SAML_Custom_Default_entry_point - https://idp.zid.tuwien.ac.at/simplesaml/saml2/idp/SSOService.php
SAML_Custom_Default_idp_slo_redirect_url - https://idp.zid.tuwien.ac.at/simplesaml/saml2/idp/SingleLogoutService.php
SAML_Custom_Default_issuer - https://chat.tuwien.ac.at/_saml/metadata/chat
SAML_Custom_Default_cert - XXX
SAML_Custom_Default_public_cert - XXX
SAML_Custom_Default_private_key - XXX
SAML_Custom_Default_button_label_text - TU Login

geekgonecrazy · 2019-01-24T05:14:24Z

@rodrigok do you have any ideas on this one?

pkolmann · 2019-04-09T13:50:43Z

I was able to fix this issue with removing the wrong entry in the mongodb:

Look for the wrong token in the database:
db.getCollection('_raix_push_app_tokens').find({"userId":"WRONG-UserId"})
Logout from Device.
Delete the entry from the database:
db.getCollection('_raix_push_app_tokens').remove({"userId":"WRONG-UserId"}) WriteResult({ "nRemoved" : 1 })
Login from device into Rocket.Chat and I saw that the new entry is now with the proper userId.

It seems that there was an old userId still registered in the android app but the user was not available on the database (was probably from testing). This issue has never occured since and I hope that this was a one-time thing. Closing issue.

pkolmann closed this as completed Apr 9, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Push token from android updates wrong userid in rocket chat #13101

Push token from android updates wrong userid in rocket chat #13101

pkolmann commented Jan 9, 2019 •

edited

Loading

geekgonecrazy commented Jan 10, 2019

pkolmann commented Jan 10, 2019

pkolmann commented Jan 10, 2019

geekgonecrazy commented Jan 10, 2019 •

edited

Loading

pkolmann commented Jan 11, 2019

geekgonecrazy commented Jan 24, 2019

pkolmann commented Apr 9, 2019

Push token from android updates wrong userid in rocket chat #13101

Push token from android updates wrong userid in rocket chat #13101

Comments

pkolmann commented Jan 9, 2019 • edited Loading

Description:

Steps to reproduce:

Expected behavior:

Actual behavior:

Server Setup Information:

Additional context

Relevant logs:

geekgonecrazy commented Jan 10, 2019

pkolmann commented Jan 10, 2019

pkolmann commented Jan 10, 2019

geekgonecrazy commented Jan 10, 2019 • edited Loading

pkolmann commented Jan 11, 2019

geekgonecrazy commented Jan 24, 2019

pkolmann commented Apr 9, 2019

pkolmann commented Jan 9, 2019 •

edited

Loading

geekgonecrazy commented Jan 10, 2019 •

edited

Loading