Rocket.chat: Users appear online when logged out or disconnected

[kau210]

EDIT
The bug can be reproduced if rocketchat service is stopped server side.

---

Rocket.Chat Version: 0.54.2
Running Instances: 1
Node Version: 4.5
Server OS: Debian Jessie
Issue: User presence not updated
How to reproduce: Cannot

We have an installation of Rocket chat with ~30 users on a variety of devices and clients (mobile, browser, windows / unix / os x apps) and the online / offline status of users seems to not reflect the user setting, for instance a user might have logged out but they still seem as if they're online.

The issue first appeared a few months ago (ca November) and affected 2 users. We tried monitoring the logs and frontend to observe the user status while the user (a) logged in, (b) logged out, (c) changed status to anything else but online (away, busy, invisible), (d) manually log in and out of all locations known to have logged in, (e) forced 'logging out from other logged in locations' from the option in the user settings and then logged out. For a, b, d and e, in the logs we could see the respective actions (see dump below) however on the frontend the user appeared online. If the user changes their status to busy, away or invisible we can see the change on the frontend. Idle time also works like a charm - we see it in the logs and frontend.

At the moment this affects almost half the users (which happened gradually over time) and we haven't been able to reproduce it. We must be missing something obvious as we can't seem to find others with a similar issue, maybe someone has an idea what to research further?

A log dump from one of the users that has this issue:

log in

#033[34mMeteor ➔ publish#033[39m roles -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m rocketchat_roles Falling back _publishCursor to model with query: undefined
#033[34mMeteor ➔ publish#033[39m meteor_autoupdate_clientVersions -> userId: SOMEID , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: SOMEID , arguments:  { '0': 'updateCustomSound', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: SOMEID , arguments:  { '0': 'deleteCustomSound', '1': false }
#033[34mMeteor ➔ publish#033[39m activeUsers -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: { username: { '$exists': 1 }, status: { '$in': [ 'online', 'away', 'busy' ] } }
#033[34mMeteor ➔ publish#033[39m userData -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: SOMEID
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: SOMEID , arguments:  { '0': 'public-settings-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m null -> userId: SOMEID , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'roles-change', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'updateEmojiCustom', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'deleteEmojiCustom', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'updateAvatar', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'permissions-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/message', '1': false }
#033[34mMeteor ➔ method#033[39m getUserRoles -> userId: SOMEID , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/otr', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/webrtc', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/notification', '1': false }
#033[34mMeteor ➔ publish#033[39m userData -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: SOMEID
#033[34mMeteor ➔ publish#033[39m activeUsers -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: { username: { '$exists': 1 }, status: { '$in': [ 'online', 'away', 'busy' ] } }
#033[34mMeteor ➔ method#033[39m rooms/get -> userId: SOMEID , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/rooms-changed', '1': false }
#033[34mMeteor ➔ method#033[39m subscriptions/get -> userId: SOMEID , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/subscriptions-changed', '1': false }
#033[34mMeteor ➔ method#033[39m permissions/get -> userId: SOMEID , arguments:  {}

change status

#033[34mMeteor ➔ method#033[39m UserPresence:setDefaultStatus -> userId: SOMEID , arguments:  { '0': 'away' }

log out from other logged in locations

#033[34mMeteor ➔ publish#033[39m roles -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m rocketchat_roles Falling back _publishCursor to model with query: undefined
#033[34mMeteor ➔ publish#033[39m meteor_autoupdate_clientVersions -> userId: SOMEID , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: SOMEID , arguments:  { '0': 'updateCustomSound', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: SOMEID , arguments:  { '0': 'deleteCustomSound', '1': false }
#033[34mMeteor ➔ publish#033[39m activeUsers -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: { username: { '$exists': 1 }, status: { '$in': [ 'online', 'away', 'busy' ] } }
#033[34mMeteor ➔ publish#033[39m userData -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: SOMEID
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: SOMEID , arguments:  { '0': 'public-settings-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'updateEmojiCustom', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'deleteEmojiCustom', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'updateAvatar', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'roles-change', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: SOMEID , arguments:  { '0': 'permissions-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/message', '1': false }
#033[34mMeteor ➔ publish#033[39m userData -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: SOMEID
#033[34mMeteor ➔ publish#033[39m activeUsers -> userId: SOMEID , arguments:  {}
#033[34mBaseCache ➔ debug#033[39m users Falling back _publishCursor to model with query: { username: { '$exists': 1 }, status: { '$in': [ 'online', 'away', 'busy' ] } }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/otr', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/webrtc', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/notification', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/rooms-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: SOMEID , arguments:  { '0': 'SOMEID/subscriptions-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m null -> userId: SOMEID , arguments:  {}

log out

#033[34mMeteor ➔ publish#033[39m roles -> userId: null , arguments:  {}
#033[34mMeteor ➔ publish#033[39m meteor_autoupdate_clientVersions -> userId: null , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: null , arguments:  { '0': 'updateCustomSound', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: null , arguments:  { '0': 'deleteCustomSound', '1': false }
#033[34mMeteor ➔ publish#033[39m activeUsers -> userId: null , arguments:  {}
#033[34mMeteor ➔ publish#033[39m userData -> userId: null , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-all -> userId: null , arguments:  { '0': 'public-settings-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: null , arguments:  { '0': 'updateEmojiCustom', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: null , arguments:  { '0': 'deleteEmojiCustom', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: null , arguments:  { '0': 'updateAvatar', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: null , arguments:  { '0': 'SOMEID/message', '1': false }
#033[34mMeteor ➔ publish#033[39m userData -> userId: null , arguments:  {}
#033[34mMeteor ➔ publish#033[39m activeUsers -> userId: null , arguments:  {}
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: null , arguments:  { '0': 'roles-change', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: null , arguments:  { '0': 'SOMEID/otr', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: null , arguments:  { '0': 'SOMEID/webrtc', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: null , arguments:  { '0': 'SOMEID/notification', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: null , arguments:  { '0': 'SOMEID/rooms-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-user -> userId: null , arguments:  { '0': 'SOMEID/subscriptions-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m stream-notify-logged -> userId: null , arguments:  { '0': 'permissions-changed', '1': false }
#033[34mMeteor ➔ publish#033[39m null -> userId: null , arguments:  {}
#033[34mMeteor ➔ method#033[39m logoutCleanUp -> userId: null , arguments:  { '0':
 { _id: 'SOMEID',
 status: 'online',
 utcOffset: 2,
 username: 'SOMEUNAME',
 services: { password: [Object] },
 active: true,
 roles: [ 'SOMEROLE' ],
 name: 'SOMENAME',
 statusConnection: 'online',
 settings: { profile: {}, preferences: [Object] },
 language: 'en',
 statusDefault: 'online',
 emails: [ [Object] ] } }
#033[34mMeteor ➔ method#033[39m UserPresence:online -> userId: null , arguments:  {}

[geekgonecrazy]

Easy way to reproduce this bug.. Connect with mobile phone and then toggle airplane mode on. Some how it seems to never realize that connection is gone.

[JSzaszvari]

+1 - Opposite of the other issue :)

[geekgonecrazy]

You are experiencing this as well? Any triggers you've been able to identify to get it stuck this way?

[JSzaszvari]

@geekgonecrazy - Yes, Ran it up in a test environment and imported my production MongoDB database, then upgraded and there is a bunch of users stuck in a "Online" state as well as some of our Bots

Essentially, the users that were online at the time the server was stopped, then was upgraded are stuck in the Online state.

In the admin are I've got

Inactive Users 2
Online Users 3
Away Users 4

When I am the only user online. No errors in the console that would be of concern

@geekgonecrazy Do you want access to the environment? I can punch .a hole for you to get in, And its a testing/dev one so I'm not concerned about it if you want to have a play

[JSzaszvari]

Just did some testing

If I log in as one of the users that is stuck online and watch with another user their status updates correctly when changed between Busy, Online..etc (when they are online)

Then when the user logs out, their status stays stuck in that state.

So I just logged in as a user thats stuck in the "Away" status and set them to "Busy" and logged out and they are now stuck in the "Busy" status after logging out

If i set the user to "Online" and log out they go back to the "Away" status.

[kau210]

So the issue is that the user status gets "stuck" to what it was when the connection was lost (whether it's stopped server side or client side).

Would there be a way to manually flush the user status? Something like a manual reset of the status of any user (or of all users) to use as a workaround.

[geekgonecrazy]

The only workaround right now is to connect to database and delete that users record from userSessions collection

[kau210]

FWIW, I cannot seem to able to reproduce the bug with the connection stopping client side. It takes a while but the user status is updated with the expected information. Offline if the user logs out, online/away/busy if the user is logged in and then when logged out again the status was updated to offline.

However, being online as a user and shutting down rocketchat service on the _server_ reproduces the bug. The status of the user I tested hasn't been restored and is stuck.

[geekgonecrazy]

So service being abruptly stopped due to a crash or having the service stopped underneath is probably the more common of causes.

I could see something as simple as taking it down during an upgrade potentially causing this.

[fcoppolani]

Hi,

I am just starting to receive complains from users with the same issue. We use 0.56.0 . We may have some crash, I would have to check. Could you provide :
a) a screen in rocket.chat to manage user sessions (and so disconnect them and delete from collection if needed)
b) a 'safe' script to detect and delete stucked userSessions collection (I'm a bit afraid of doing something wrong here)?
Thanks for your help.

[kau210]

b) a 'safe' script to detect and delete stucked userSessions collection (I'm a bit afraid of doing something wrong here)?

No script, but my work around was to log into the machine hosting rocketchat and from the mongo shell list all user sessions and select the ones to remove. You'll also need the user id of each user you wish to remove the session.

Specifically - I'm on a debian machine:

user@host:~$ mongo
> show dbs
local       2.077GB
rocketchat  1.953GB
> use rocketchat
switched to db rocketchat

show all collections

> show collections
...
...
...
users
usersSessions

find all users sessions
> db.usersSessions.find()
[side note, when you list all the user sessions you will see which ones are 'stuck' because they appear to have logged in a few weeks or even months ago]

find a specific user session -- replace the USERID
> db.usersSessions.find( { _id: "USERID" } )

delete a user session
> db.usersSessions.deleteOne( { _id: "USERID" } )

Further info on what you can do with a mongodb collection https://docs.mongodb.com/manual/reference/method/js-collection/

From my experience with being worried of bringing everything offline and doom to my desk, I would encourage you to not worry too much about doing something wrong. The user session gets created instantly when the user is logged in. They can even be logged in while you're removing it, your action will be hardly noticeable. As far as I understand this deletes the active user session and thus restarts the connection. If the user is offline it will show them offline and if online will just continue off where it stopped.

If you want to be sure you can create a test user and remove that session only. And of course having backups of your rocketchat database always helps.

[fcoppolani]

Thanks for your help, indeed it came from a crash. I see that usersSessions are linked to instanceId, a lapsing date on isntance Id and thus to usersSessions should be a good idea.
Anyway here is the command lines I used to clean up the mess :

var bulk = db.usersSessions.initializeUnorderedBulkOp()
bulk.find({"connections._createdAt" : { $lte : new ISODate("2017-07-10T20:00:31Z") }}).remove()
bulk.execute()

[geekgonecrazy]

We are working on improving this. Hopefully the changes will land in 0.59.0

[antgel]

@geekgonecrazy We also see this in 0.59.3. Have the changes landed yet, or are we still waiting for them?

[antgel]

@geekgonecrazy Ping. Will this be fixed in 0.60?

[geekgonecrazy]

@antgel they should be! Please let us know if its not improved. Make sure of course to wipe out sessions and then see if it happens again.

[seanpackham]

Fixed in 0.60.0

[phlegx]

Happening to me still on 0.62.2: One user is shown as always online Restarting the server solves it (for now)

[acflint]

Also having this issue on 0.65.1

[geekgonecrazy]

Please try newer release. Also 0.69.0 will contain more fixes related to this

[phlegx]

Seeing this issue with one user still on 0.68.4. The user is always show as online even if he is away. When the user goes offline the status offline is correctly shown

[geekgonecrazy]

Make sure to have the user go-to settings and check that they have auto away on and set to reasonable time