3.8.0: invoking method loadMissedMessages Error: Invalid user [error-invalid-user]

[deogracia]

Description:

Following an upgrade from 3.1.14 to 3.8.0,i n rocket log, lots of Exception while invoking method loadMissedMessages. I don't understand what generates them
I don't see yet any malfunction in rocket.

Steps to reproduce:

1. upgrade from 3.1.14 to 3.8.0
2. go to rocket's logs

Expected behavior:

no exception

Actual behavior:

Nov 27 22:34:10 chat RocketChat[22572]: Exception while invoking method loadMissedMessages Error: Invalid user [error-invalid-user]

Server Setup Information:

• Version of Rocket.Chat Server: 3.8.0
• Operating System: debian 9
• Deployment Method: tar
• Number of Running Instances: 1
• DB Replicaset Oplog: ok
• NodeJS Version: v12.18.4
• MongoDB Version: 6.14.8

Client Setup Information

non relevant

Additional context

• exception apears just after upgrade from 3.1.14 to 3.8.0
• loadMissedMessages fails on a fresh server #18917 has the same error but with a different context

Relevant logs:

Nov 27 22:34:10 chat RocketChat[22572]: Exception while invoking method loadMissedMessages Error: Invalid user [error-invalid-user]
Nov 27 22:34:10 chat RocketChat[22572]:     at MethodInvocation.loadMissedMessages (server/methods/loadMissedMessages.js:13:10)
Nov 27 22:34:10 chat RocketChat[22572]:     at MethodInvocation.methodsMap.<computed> (app/lib/server/lib/debug.js:76:34)
Nov 27 22:34:10 chat RocketChat[22572]:     at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1771:12)
Nov 27 22:34:10 chat RocketChat[22572]:     at packages/ddp-server/livedata_server.js:1689:15
Nov 27 22:34:10 chat RocketChat[22572]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Nov 27 22:34:10 chat RocketChat[22572]:     at packages/ddp-server/livedata_server.js:1687:36
Nov 27 22:34:10 chat RocketChat[22572]:     at new Promise (<anonymous>)
Nov 27 22:34:10 chat RocketChat[22572]:     at Server.applyAsync (packages/ddp-server/livedata_server.js:1686:12)
Nov 27 22:34:10 chat RocketChat[22572]:     at Server.apply (packages/ddp-server/livedata_server.js:1625:26)
Nov 27 22:34:10 chat RocketChat[22572]:     at Server.call (packages/ddp-server/livedata_server.js:1607:17)
Nov 27 22:34:10 chat RocketChat[22572]:     at Object.post (app/api/server/v1/misc.js:262:26)
Nov 27 22:34:10 chat RocketChat[22572]:     at app/api/server/api.js:394:82
Nov 27 22:34:10 chat RocketChat[22572]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Nov 27 22:34:10 chat RocketChat[22572]:     at Object._internalRouteActionHandler [as action] (app/api/server/api.js:394:39)
Nov 27 22:34:10 chat RocketChat[22572]:     at Route.share.Route.Route._callEndpoint (packages/nimble_restivus/lib/route.coffee:150:32)
Nov 27 22:34:10 chat RocketChat[22572]:     at packages/nimble_restivus/lib/route.coffee:59:33
Nov 27 22:34:10 chat RocketChat[22572]:     at packages/simple_json-routes.js:98:9
Nov 27 22:34:10 chat RocketChat[22572]:  => awaited here:
Nov 27 22:34:10 chat RocketChat[22572]:     at Promise.await (/home/rocketchat/3.8.0/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:60:12)
Nov 27 22:34:10 chat RocketChat[22572]:     at Server.apply (packages/ddp-server/livedata_server.js:1638:22)
Nov 27 22:34:10 chat RocketChat[22572]:     at Server.call (packages/ddp-server/livedata_server.js:1607:17)
Nov 27 22:34:10 chat RocketChat[22572]:     at Object.post (app/api/server/v1/misc.js:262:26)
Nov 27 22:34:10 chat RocketChat[22572]:     at app/api/server/api.js:394:82
Nov 27 22:34:10 chat RocketChat[22572]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Nov 27 22:34:10 chat RocketChat[22572]:     at Object._internalRouteActionHandler [as action] (app/api/server/api.js:394:39)
Nov 27 22:34:10 chat RocketChat[22572]:     at Route.share.Route.Route._callEndpoint (packages/nimble_restivus/lib/route.coffee:150:32)
Nov 27 22:34:10 chat RocketChat[22572]:     at packages/nimble_restivus/lib/route.coffee:59:33
Nov 27 22:34:10 chat RocketChat[22572]:     at packages/simple_json-routes.js:98:9

[psoares]

Same issue in Rocket chat 3.7.1 without any upgrades...

[dkoo761]

I'm on 3.7.4 and just got this error after restarting my RC server (without upgrading) and then opening the web version of RC in Chrome on my Android phone.

I was already logged into RC on Android Chrome but it seems like after restarting the server, I got logged out and then saw an "Invalid user" error appear on the Android Chrome screen. When I logged back in, it got stuck on the white screen with the 3 loading dots (aka. the loading throbber). After I closed (not minimized) Android Chrome and reopened it again, everything was working fine. This has happened more than once but not every time I reboot the server.

Hope this helps with some debugging.

[apaarfus]

We're getting the same error on 3.12.0 -- I've been doing some experimenting to see which user is causing that issue. Looking at the permissions, I saw that Rocket.Cat does not have access to view direct messages and a few other room-related settings.

In a testing environment, I adjusted the following perms for the bot role:

• ✔ View public channel
• ✔ View Direct Messages
• ✔ View Outside Room
• ❌ View Private Room

Unsure if these are the root cause of the issue at this time; but it is at least some kind of progress in tracking the root case down...

Edit: Planning to migrate to 3.12.2+ in the coming weeks -- will report back after seeing how the above changes work out over the course of the week...and after the upgrade.

Edit: The above changes have not resolved the error

[dkoo761]

I solved this a little while ago. Sorry I didn't post the update here earlier.

Here's a link to my forum post which explains everything and includes a work-around: https://forums.rocket.chat/t/user-is-sometimes-logged-out-right-after-reconnecting-to-the-rc-server/10671