Rocket.chat: [CRITICAL BUG] Rocket.Chat Stability problem

Created on 29 Apr 2020  ·  34Comments  ·  Source: RocketChat/Rocket.Chat

Description:

This is continue of https://github.com/RocketChat/Rocket.Chat/issues/17310 and it is definitely related to https://github.com/RocketChat/Rocket.Chat/issues/16851 and maybe with this https://github.com/RocketChat/Rocket.Chat/issues/17100 and this https://github.com/RocketChat/Rocket.Chat/issues/17397 but I start that issue to consolidate all my (and not only my) performance and stability problems in one thread.

@sampaiodiego @rodrigok @rsjr please take a look at that issue.

Our deployment is
3 CentOS7 VM (12vCPU, 16Gb vRAM) with 4 Docker container of Rocket Chat on each, and 1 Nginx container to handle web requests on each VM in front of Rocket Chat servers.
MongoDB is running on separate VM in Docker (10vCPU, 12Gb vRAM)

Recently we upgraded to Rocket Chat version 3.1.1 and installed a great RC monitoring system Rocket.Chat.Metrics https://github.com/RocketChat/Rocket.Chat.Metrics from @frdmn
And I enabled DDP Rate Limiter (which previously was disabled for the reason described here https://github.com/RocketChat/Rocket.Chat/issues/16851)
And after that I thought that all problems are gone, but they not.
I can say, that general performance with DDP Rate Limiter was better, CPU load was less then usual, but with peaks on DDP Rate Limiter works. But one working day went good - no any issue. First @bbrauns advised me at open.rocket.chat to enable DDP to avoid performance issues made by clients. Thank him for hi advice!
But tomorrow, near 15.00 Moscow time we had an catastrophic issue again.

Steps to reproduce:

  1. Start Rocket.Chat servers and keep them working for a while
  2. Enable DDP Rate Limiter
  3. Wait for server crash or stop responding

Expected behavior:

Rocket Chat as a organizations main messaging system should works 24\7 365

Actual behavior:

I think, that all start at 14.56 with this DDP Rate Limiter
image
By the way, @frdmn on a screenshot you can see, that all requests was from user ASfqPs4Hw7u7QRM2q but actually it is not true.
Here you can see different userId in logs
image
image
And different method loadMissedMessages
image
So, I think something could be done to improve your great monitoring system.
And stream-notify-room made not majority of load, but maybe start issue itself
image

Then we see CPU load growth on one of 3 VM:
image
I think that clients with DDP flood was on second sever.

At 15.20 all 3 servers was on high load - CPU, network bandwidth, web requests (we think clients try to create new websocket session), RAM
image
image
image
image
Increased Query Rate in MongoDB, but CPU was OK
image

And at 15.24 we first see TIMEOUT QUERY OPERATION in logs. That a sign, that users have a problems to send messages - they appears grey.
image
Here is Node.js in that time. Heap is growing, handles are crazy
image
image
DDP Rate Limiter see only LoadMissedMessages, but in logs there others too
image
Oplog growing high with users/update and rocketchat_sessions/update and rocketchat_sessions/insert
image
Methods time increased
image
Stream:notify-logged on top
image
Stream apps time growth with amount of value
image
image
2FA callback gone crazy
image
Three hooks growth onValidateLogin, beforeValidateLogin and afterValidateLoginwith same graph
image
REST API time increased
image
With me and users.presence
image

And at 15.37 we rebooted all our 3 servers (VM).
After that we stop Nginx on each server to give Rocket Chat servers to start and warm up.
And if you don't give a chance them to warm up, that reboot could be useless, because CPU load could be catastrophic again right after reboot ( #17397)
CPU
image
DB
image
Network
image

But one of my main think is - with DDP Rate Limiter reboot is a bit easy to handle.
Yesterday one of our two big offices was already out of working hours, and that mitigate problem a little.

Server Setup Information:

  • Version of Rocket.Chat Server: 3.1.1
  • Operating System: CentOS7
  • Deployment Method: docker
  • Number of Running Instances: 12
  • DB Replicaset Oplog: Enabled
  • NodeJS Version: v12.16.1
  • MongoDB Version: 4.0.17

Client Setup Information

  • Desktop App or Browser Version: 2.17.7, Google Chrome 81, a lot of RC-RN 4.6.0
  • Operating System: Windows 10, Linux, Android, iOS

Additional context

My thoughts about that and my questions.
I think, that DDP Rate Limiter in Rocket Chat to handle some architectural issues in Meteor or in Rocket Chat itself (or in variety of it clients).
But DDP Rate Limiter itself consume a lot of server resources and floods logs.
Server restart - is't pain, because of high load on server start.
We actually don't know what is the real cause of all that stability problems. I don't know who can tell.

To core team: What wee need to do, to solve that stability issues? We running latest stable RC version, resources are enough, we monitoring it, but anyway it crashed.
How we can minimize performance impact of DDP Rate Limiter? (I suggest reduce logs entries https://github.com/RocketChat/Rocket.Chat/issues/16851#issuecomment-620406397)

Relevant logs:

    April 28th 2020, 15:24:35.700   s-rc-srv-02 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    April 28th 2020, 15:24:35.700   s-rc-srv-03 rocketchat_rocketchat_2_1   "numInvocationsLeft": 0,
    April 28th 2020, 15:24:35.700   s-rc-srv-02 rocketchat_rocketchat_1_1   "broadcastAuth": false
    April 28th 2020, 15:24:35.700   s-rc-srv-02 rocketchat_rocketchat_1_1   "name": "loadMissedMessages",
    April 28th 2020, 15:24:35.701   s-rc-srv-03 rocketchat_rocketchat_2_1   "userId": "Q4tLegZQhdNy7jtDP",
    April 28th 2020, 15:24:35.701   s-rc-srv-03 rocketchat_rocketchat_2_1   "clientAddress": "37.194.74.35",
    April 28th 2020, 15:24:35.701   s-rc-srv-03 rocketchat_rocketchat_2_1   "type": "subscription",
    April 28th 2020, 15:24:35.702   s-rc-srv-03 rocketchat_rocketchat_2_1   "name": "stream-notify-user",
    April 28th 2020, 15:24:35.702   s-rc-srv-03 rocketchat_rocketchat_2_1   "connectionId": "ZWxRRk4kcRMXcGeAh",
    April 28th 2020, 15:24:35.702   s-rc-srv-03 rocketchat_rocketchat_2_1   "broadcastAuth": false
    April 28th 2020, 15:24:35.702   s-rc-srv-02 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    April 28th 2020, 15:24:35.703   s-rc-srv-03 rocketchat_rocketchat_2_1   }
    April 28th 2020, 15:24:35.703   s-rc-srv-03 rocketchat_rocketchat_2_1   RateLimiter ➔ info {
    April 28th 2020, 15:24:35.703   s-rc-srv-03 rocketchat_rocketchat_2_1   RateLimiter ➔ info DDP RATE LIMIT: limit by userId per method
    April 28th 2020, 15:24:35.704   s-rc-srv-03 rocketchat_rocketchat_2_1   "allowed": false,
    April 28th 2020, 15:24:35.705   s-rc-srv-02 rocketchat_rocketchat_1_1   RateLimiter ➔ info DDP RATE LIMIT: limit by connectionId per method
    April 28th 2020, 15:24:35.705   s-rc-srv-02 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"saSTLFt6rCd33zzkt","services.resume.loginTokens.hashedToken":"A8EiZEhMX2MmmAkqM+qiYNtog1tIepF/xp0vGHqkF3U="},"options":{"transform":null,"fields":{"_id":1}}}',
    April 28th 2020, 15:24:35.705   s-rc-srv-02 rocketchat_rocketchat_1_1   }
    April 28th 2020, 15:24:35.705   s-rc-srv-02 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    April 28th 2020, 15:24:35.705   s-rc-srv-03 rocketchat_rocketchat_2_1   "timeToReset": 6543,
    April 28th 2020, 15:24:35.706   s-rc-srv-02 rocketchat_rocketchat_2_1   }
    April 28th 2020, 15:24:35.706   s-rc-srv-02 rocketchat_rocketchat_1_1   "allowed": false,
    April 28th 2020, 15:24:35.706   s-rc-srv-02 rocketchat_rocketchat_1_1   RateLimiter ➔ info {
    April 28th 2020, 15:24:35.706   s-rc-srv-02 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"saSTLFt6rCd33zzkt","services.resume.loginTokens.hashedToken":"A8EiZEhMX2MmmAkqM+qiYNtog1tIepF/xp0vGHqkF3U="},"options":{"transform":null,"fields":{"_id":1}}}'
    April 28th 2020, 15:24:35.706   s-rc-srv-02 rocketchat_rocketchat_1_1   "timeToReset": 846,
    April 28th 2020, 15:24:35.707   s-rc-srv-03 rocketchat_rocketchat_2_1   "numInvocationsLeft": 0,
    April 28th 2020, 15:24:35.707   s-rc-srv-03 rocketchat_rocketchat_2_1   "userId": "Q4tLegZQhdNy7jtDP",
    April 28th 2020, 15:24:35.707   s-rc-srv-03 rocketchat_rocketchat_2_1   "clientAddress": "37.194.74.35",
    April 28th 2020, 15:24:35.707   s-rc-srv-02 rocketchat_rocketchat_1_1   "numInvocationsLeft": 0,
    April 28th 2020, 15:24:35.708   s-rc-srv-03 rocketchat_rocketchat_2_1   "type": "subscription",
    April 28th 2020, 15:24:35.708   s-rc-srv-03 rocketchat_rocketchat_2_1   "name": "stream-notify-user",
    April 28th 2020, 15:24:35.708   s-rc-srv-03 rocketchat_rocketchat_2_1   "connectionId": "ZWxRRk4kcRMXcGeAh",
    April 28th 2020, 15:24:35.709   s-rc-srv-03 rocketchat_rocketchat_2_1   "broadcastAuth": false

performance
Source
picture ankar84
👍2 ❤1

Most helpful comment

At that moment issue solved with:

  1. Proper server and instances sizing. 25 instances for about 3K connected users peak
  2. Weekly instance restart (late night, one-by-one without service downtime)
  3. Sticky sessions with IP_HASH (Nginx). We plan to migrate to HAProxy
  4. Maybe DISABLE_PRESENCE_MONITOR=yes helped a bit (I'm not sure about that really)
  5. Maybe 1 reverse proxy instead of 3 reverse proxies (I'm not sure about that)

Some issues are still in place, but with all that workarounds and technics Rocket Chat looks stable and with pretty good performance for us and our users.

picture ankar84 on 21 Jul 2020
👍5 ❤2

All 34 comments

@ankar84 First of all: impressive, top-notch monitoring! :+1:

Do you use the HAProxy configuration that @bbrauns shared with you (if he did)? At that time there was a mistake and it didn't have session stickiness configured. :disappointed:

Would you mind sharing your webserver configuration here as well?

benedikt-wegmann picture benedikt-wegmann on 29 Apr 2020

For perspective: we operate Rocket.Chat version 3.1.1 on a simgle VM with 64 CPUs and 128GB RAM, a Docker (Compose) setup with 26 instances running, MongoDB 3.4 in a single container and haproxy in a container.

And since updating 12 days ago we have a smooth operation with about 2400 incoming connections peak, ~40 req/s and sub 10ms latency from HAProxy to Rocket.Chat containers.
Subjectively, using the service is fast and reliable, sending messages is almost instantaneous and loading channels or searching messages is quite quick.

It would be interesting to see how many peak users your service is serving when it seems to hit a problem (I might have missed it in the monitoring data).

benedikt-wegmann picture benedikt-wegmann on 29 Apr 2020

@ankar84 First of all: impressive, top-notch monitoring!

Thanks a lot! But we all should say thanks to @frdmn for that impressive monitoring!

Do you use the HAProxy configuration that @bbrauns shared with you (if he did)?

Yes, hi did share his HAProxy config, but we don't use that. We user only 3 Nginx servers.

Would you mind sharing your webserver configuration here as well?

Sure, no problem

worker_processes auto;
error_log /dev/stderr warn;
pid        /var/run/nginx.pid;

events {
    worker_connections  10240;
    }
http {
    include       /etc/nginx/mime.types;
    default_type  application/octet-stream;

    log_format gelf_json escape=json '{ "timestamp": "$time_iso8601", '
         '"remote_addr": "$remote_addr", '
         '"connection": "$connection", '
         '"connection_requests": $connection_requests, '
         '"pipe": "$pipe", '
         '"body_bytes_sent": $body_bytes_sent, '
         '"request_length": $request_length, '
         '"request_time": $request_time, '
         '"response_status": $status, '
         '"request": "$request", '
         '"request_method": "$request_method", '
         '"host": "$host", '
         '"upstream_cache_status": "$upstream_cache_status", '
         '"upstream_addr": "$upstream_addr", '
         '"http_x_forwarded_for": "$http_x_forwarded_for", '
         '"http_referrer": "$http_referer", '
         '"http_user_agent": "$http_user_agent", '
         '"http_version": "$server_protocol", '
         '"remote_user": "$remote_user", '
         '"http_x_forwarded_proto": "$http_x_forwarded_proto", '
         '"upstream_response_time": "$upstream_response_time", '
         '"nginx_access": true }';

    access_log    /dev/stdout gelf_json;
    sendfile        on;
    keepalive_timeout  65;

    # Upstreams
    upstream backend {
        server rocketchat_1:3000;
        server rocketchat_2:3001;
        server rocketchat_3:3002;
        server rocketchat_4:3003;
    }


    server {
        listen 80;
        location = /basic_status {
        stub_status;
        allow x.x.x.x/32;
        deny all;
        }
    }

    # HTTPS Server


    server {
        listen 443 ssl;

        set_real_ip_from xxxxxx/32;
        set_real_ip_from xxxxxx/32;
        set_real_ip_from xxxxxx/32;
        real_ip_header X-Forwarded-For;

        # You can increase the limit if your need to.
        client_max_body_size 200M;

        ssl_certificate /etc/nginx/certificate.crt;
        ssl_certificate_key /etc/nginx/certificate.key;
        ssl_protocols TLSv1 TLSv1.1 TLSv1.2; # don’t use SSLv3 ref: POODLE

        server_tokens off;
        add_header 'Access-Control-Allow-Origin' '*.company.ru';
        add_header X-Frame-Options SAMEORIGIN;
        add_header X-XSS-Protection "1; mode=block";
        add_header X-Content-Type-Options nosniff;
        add_header Strict-Transport-Security 'max-age=31536000; includeSubDomains; preload' always;

        location / {
            proxy_pass http://backend/;
            proxy_http_version 1.1;
            proxy_set_header Upgrade $http_upgrade;
            proxy_set_header Connection "upgrade";
            proxy_set_header Host $http_host;

            proxy_set_header X-Real-IP $remote_addr;
            proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
            proxy_set_header X-Forward-Proto http;
            proxy_set_header X-Nginx-Proxy true;

            proxy_redirect off;
            proxy_buffering off;
        }

    }
}

For perspective: we operate Rocket.Chat version 3.1.1 on a simgle VM with 64 CPUs and 128GB RAM, a Docker (Compose) setup with 26 instances running, MongoDB 3.4 in a single container and haproxy in a container.

Very good server you have

And since updating 12 days ago we have a smooth operation with about 2400 incoming connections peak, ~40 req/s and sub 10ms latency from HAProxy to Rocket.Chat containers

We have a very similar load with about 3000 connected users peak
@benedikt-wegmann tell me please, do you have DDP Rate Limits executions in your environment?
How often? Is it consume CPU? Is it floods log for you?
What are your limits?

It would be interesting to see how many peak users your service is serving when it seems to hit a problem (I might have missed it in the monitoring data).

Yesterday crash was when one of two main headquarters office was out of working hours, so daily peak was behind. In that moment was about 2600 connected users.
image

ankar84 picture ankar84 on 29 Apr 2020

Are these issues present on RocketChat Server 3.2?

nofikoff picture nofikoff on 29 Apr 2020

Are these issues present on RocketChat Server 3.2?

We did not try it yet, but definitely we will upgrade to 3.2.X because of better push notifications work.

ankar84 picture ankar84 on 29 Apr 2020

@ankar84 I just noticed: neither in your Nginx config nor in the example of the Rocket.Chat documentation (https://rocket.chat/docs/installation/manual-installation/multiple-instances-to-improve-performance/#update-your-nginx-proxy-config) I can find session stickiness configured, but for the Apache config below it is.

I think session stickiness for Nginx should look like this:
https://docs.nginx.com/nginx/admin-guide/load-balancer/http-load-balancer/#enabling-session-persistence

benedikt-wegmann picture benedikt-wegmann on 29 Apr 2020

I think session stickiness for Nginx should look like this

Thanks! We will check it out.

@benedikt-wegmann tell me please, do you have DDP Rate Limits executions in your environment?
How often? Is it consume CPU?
Is it floods log for you?
What are your limits?

ankar84 picture ankar84 on 29 Apr 2020

@ankar84 You are asking the right questions, but my monitoring is sub-par compared to yours, I don't have all the details. But going through yesterdays log (24h period) i counted a few specific log messages with the following results:

rate limits by types (occurences)
    440 info DDP RATE LIMIT: limit by connectionId
   1319 info DDP RATE LIMIT: limit by connectionId per method
   1873 info DDP RATE LIMIT: limit by userId per method

top 10 users who tripped rate limiting (my understanding is that only 4 users were affected yesterday. the 'null' must be an error while searching through the file):
     28  "userId": "GzvsSnXWtBRu2XXXX",
     51  "userId": null,
    232  "userId": "Hb9awZAThicicXXXX",
   1349  "userId": "A5p8PSbrXiYa6XXXX",
   1971  "userId": "AKyz5pF9pidnAXXXX",

So, flooding the logs is relative, but we do encounter occurrences of the limits being hit, yes.

Our API Rate Limiter is set to defaults, our DDP rate limiters are enabled except for "by IP" (to avoid impacting users behind NAT). The DDP Limits are at Defaults except for "Limit by User per Method: requests: 30" and "Limit by Connection per Method: requests: 50". I adjusted those by the seat of my pants while eyeballing the logs during an upgrade process some weeks ago, that's it.
I hope this data is useful for you.

benedikt-wegmann picture benedikt-wegmann on 29 Apr 2020
👍1

My colleague @bbrauns investigated regarding sticky sessions and Meteor (on which Rocket.Chat is build) and the documentation regards it as "critical":

It's critical that your load balancer has ''sticky sessions'' (aka session affinity) to work properly with your Meteor App
http://www.meteorpedia.com/read/Scaling_your_Meteor_App

Rocket.Chat doesn't break obviously without it as I had our service accidentally run it without for a few days but I assume your service would benefit from configuring sticky sessions by cookie in Nginx. Worth a shot at least.

benedikt-wegmann picture benedikt-wegmann on 29 Apr 2020
👍1

Our API Rate Limiter is set to defaults, our DDP rate limiters are enabled except for "by IP" (to avoid impacting users behind NAT). The DDP Limits are at Defaults except for "Limit by User per Method: requests: 30" and "Limit by Connection per Method: requests: 50". I adjusted those by the seat of my pants while eyeballing the logs during an upgrade process some weeks ago, that's it.
I hope this data is useful for you.

Thanks a lot! It is really very useful information for me!

ankar84 picture ankar84 on 29 Apr 2020

Yesterday we had very similar crash, so now we decided to disable DDP Rate Limits (2 days of performance issue one by one)
image

@benedikt-wegmann could you tell me, do you have public channels for all your users? It's like news or announcements channels. We have 2 of such channels. And I think that it could be the root cause of problem. Actually users status notifications.

ankar84 picture ankar84 on 30 Apr 2020

Yesterday crash graphs
Node.js
image
image
image
image
DDP rate limiter
image
Oplog
image
image
image
image
image
image
image
image
image
image
Notifications
image
image
Methods
image
image
image
Subscriptions
image
image
image
Callbacks
image
image
Hooks
image
image
REST API
image
image
Network, RAM, CPU
image
DB
image
Users and messages
image

ankar84 picture ankar84 on 30 Apr 2020

Yesterday we had very similar crash, so now we decided to disable DDP Rate Limits (2 days of performance issue one by one)
image

@benedikt-wegmann could you tell me, do you have public channels for all your users? It's like news or announcements channels. We have 2 of such channels. And I think that it could be the root cause of problem. Actually users status notifications.

As I said before I would not recommend disabling the rate limiter. Your image "DDP rate limiter" - "limit by userId" looks like a single user is causing trouble. Have you considered looking up who that is and talking about his/her general rc usage behavior like: which browser/client in version x, etc.?

bbrauns picture bbrauns on 30 Apr 2020

As I said before I would not recommend disabling the rate limiter. Your image "DDP rate limiter" - "limit by userId" looks like a single user is causing trouble. Have you considered looking up who that is and talking about his/her general rc usage behavior like: which browser/client in version x, etc.?

Hi @bbrauns
Yes,I know, that DDP Rate Limiter recommended to be enabled, but in our case we have no choice and must disabled it. I hope temporary, before we will find root cause of problem.
And about 1 user on graph, as I already mention in first message, DDP Rate Limiter graphs do not show every DDP record that we see in logs. And @frdmn should do something with that issue. Actually there are a lot of different userId's and connections in DDP records.

ankar84 picture ankar84 on 30 Apr 2020

If you want to investigate a (few) potential users, I can give you my script that produced the coarse statistics mentioned earlier. I have the Rocket.Chat logs directed to syslog and filtered into its own logfile, so the script expects syslog syntax like this:

Apr 30 06:25:17 chat rocketchat_app_scale_26[3963]: server.js:204 LDAPHandler ➔ info Init LDAP login [email protected]
Apr 30 06:25:17 chat rocketchat_app_scale_26[3963]: server.js:204 LDAP ➔ Connection.info Init setup
Apr 30 06:25:17 chat rocketchat_app_scale_26[3963]: server.js:204 LDAP ➔ Connection.info Connecting ldaps://ldap1.xxxx.de:636
Apr 30 06:25:17 chat rocketchat_app_scale_26[3963]: server.js:204 LDAP ➔ Connection.info LDAP connected
Apr 30 06:25:17 chat rocketchat_app_scale_26[3963]: server.js:204 LDAP ➔ Bind.info Binding UserDN cn=xxxxxx
Apr 30 06:25:17 chat rocketchat_app_scale_26[3963]: server.js:204 LDAP ➔ Search.info Searching user [email protected]
Apr 30 06:25:17 chat rocketchat_app_scale_26[3963]: server.js:204 LDAP ➔ Search.info Search result count 1

(the file ist .txt because of GitHub upload restrictions)

rc-log-report.txt

benedikt-wegmann picture benedikt-wegmann on 30 Apr 2020
👍1

Experiencing quite the same across the board as @ankar84.
12 instances, 2 Mongo DB Replica sets.
Version 3.2.X

DBs wont settle down, and keep going through periods of unavailability. Working on implementing Grafana metrics

Beeez picture Beeez on 7 May 2020
👍1

@ankar84 I am curious in your screenshots, how are you monitoring multiple instances on a single server? I see you're running 4 instances on each s-rc-srv-0X with metrics on different ports for each.

Does it increment up from 9458 by default per instance? I would just need to open those firewall ports if so. I am just curious if you have to make a separate configuration.

Beeez picture Beeez on 7 May 2020

Here is a bit of a dump of info:
As i had said, we are seeing very similar problems here. The app servers themselves are fine, but the MongoDBs are very much not.

First image shows the very high usage that makes RocketChat completely unusable during this time. It seems quite random.

One thing I'd like to mention is we previously were using readPrefernce in out MongoURL as we used to have these problems with performance. It helped to no longer cause outtages, but it also created a problem with users not getting notifications. We removed this settings when we went to 3.2.X in hopes that there were some performance fixes, but it seems to still cause issues. Not sure if it makes more sense to have users not be notified of messages sometimes, or have the server down a few times a day....

image
image
image
image
image
image
image
image

Another Interesting thing. We have User Data downloads Disabled and they seem to still be running jobs frequently?
image

MongoDb Faults:
image

Beeez picture Beeez on 7 May 2020

Hello, @Beeez

Another Interesting thing. We have User Data downloads Disabled and they seem to still be running jobs frequently?

We had same problem, and I asked about that on open.rocket.chat.
I have a workaround - you need to enable it, set big Processing Frequency (Minutes) and then disable it again:
image
I don't know why cron task remain active after feature disabled.

MongoDb Faults:

I think that this could be you main problem. You need stabilize your MongDB deployment.
Here in my active DB page faults graph
image

First image shows the very high usage that makes RocketChat completely unusable during this time. It seems quite random.

Amounts of values not so high, IMHO.
Now in normal load we have such Oplog graph:
image

ankar84 picture ankar84 on 8 May 2020

@Beeez

One thing I'd like to mention is we previously were using readPrefernce in out MongoURL as we used to have these problems with performance. It helped to no longer cause outtages, but it also created a problem with users not getting notifications.

That is very disappointing. Due to performance issues in the past we plan to deploy a similar setup with multiple read replicas and readPreference=nearest. That means you would not recommend that kind of setup and you are back to write and read to the primary mongodb member?

bbrauns picture bbrauns on 8 May 2020

@Beeez

One thing I'd like to mention is we previously were using readPrefernce in out MongoURL as we used to have these problems with performance. It helped to no longer cause outtages, but it also created a problem with users not getting notifications.
@bbrauns
That is very disappointing. Due to performance issues in the past we plan to deploy a similar setup with multiple read replicas and readPreference=nearest. That means you would not recommend that kind of setup and you are back to write and read to the primary mongodb member?

I would recommend it for the better performance. We had initially configured that option _because_ of the problems that are occurring in this Github issue - it allowed us to mitigate the performance problems.

It wasn't notification issues with mobile or anything, but more with the highlighting of unread messages. They just wouldn't show up, so users would be required to refresh their page every so often for them to show up on the side. Perhaps it is due to system time on the DBs as they are maybe 1 second out of sync at times.

I can't say you will have this exact issue though, and i think it is worth a shot.

We made many changes last night to try and remedy some of the things posted here including the page faults, so we will see how things go today. We did however add back in the readpreference along with all the changes we did, since missing message notifications is a bit better than a non-functioning chat server.

Beeez picture Beeez on 8 May 2020

To resolve that issue we:

  • Disabled DDP Rate Limits
  • Implement sticky sessions in Nginx

But anyway, yesterday we had a crash again!
This time I think I know what was a trigger to that crash - migration of 1 of 3 servers in VMware virtual infrastructure. During that migration 2 of 4 instances of third server was "lost" for few seconds on a network. And that increased load on all other instances immediately.
But again - why so short unavailability of 2 of 12 instances did crash all Rocket.chat service?
Here is a lot of graph again.
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
image
Resources:
image
image
image
image
image
Logs:

    May 12th 2020, 16:17:45.753 s-rc-srv-01 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3001
    May 12th 2020, 16:17:45.757 s-rc-srv-01 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3001
    May 12th 2020, 16:17:45.759 s-rc-srv-02 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3001
    May 12th 2020, 16:17:45.762 s-rc-srv-01 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3001
    May 12th 2020, 16:17:45.764 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3001
    May 12th 2020, 16:17:45.766 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3001
    May 12th 2020, 16:17:45.931 s-rc-srv-01 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:45.933 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:45.933 s-rc-srv-01 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:45.934 s-rc-srv-01 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:45.935 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:45.944 s-rc-srv-02 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:45.997 s-rc-srv-01 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3003
    May 12th 2020, 16:17:45.999 s-rc-srv-02 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3003
    May 12th 2020, 16:17:45.999 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3003
    May 12th 2020, 16:17:46.000 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3003
    May 12th 2020, 16:17:46.032 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3003
    May 12th 2020, 16:17:46.043 s-rc-srv-01 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3000
    May 12th 2020, 16:17:46.043 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3000
    May 12th 2020, 16:17:46.044 s-rc-srv-01 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3000
    May 12th 2020, 16:17:46.046 s-rc-srv-02 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3000
    May 12th 2020, 16:17:46.046 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3000
    May 12th 2020, 16:17:46.052 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3000
    May 12th 2020, 16:17:46.606 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3001
    May 12th 2020, 16:17:46.693 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:46.989 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3001
    May 12th 2020, 16:17:47.002 s-rc-srv-02 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3002
    May 12th 2020, 16:17:47.011 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3003
    May 12th 2020, 16:17:47.017 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3001
    May 12th 2020, 16:17:47.020 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3000
    May 12th 2020, 16:17:47.033 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3000
    May 12th 2020, 16:17:47.043 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3002
    May 12th 2020, 16:17:47.043 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3002
    May 12th 2020, 16:17:47.044 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3003
    May 12th 2020, 16:17:47.585 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3003
    May 12th 2020, 16:17:47.597 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3003
    May 12th 2020, 16:17:47.610 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3001
    May 12th 2020, 16:17:47.645 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3000
    May 12th 2020, 16:17:47.650 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3002
    May 12th 2020, 16:17:47.659 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3002
    May 12th 2020, 16:17:47.710 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3001
    May 12th 2020, 16:17:47.779 s-rc-srv-02 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.162:3003
    May 12th 2020, 16:17:48.056 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3000
    May 12th 2020, 16:17:48.877 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3003
    May 12th 2020, 16:17:48.903 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3001
    May 12th 2020, 16:17:48.914 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3002
    May 12th 2020, 16:17:48.986 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3000
    May 12th 2020, 16:17:49.005 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3002
    May 12th 2020, 16:17:49.019 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3000
    May 12th 2020, 16:17:49.033 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3001
    May 12th 2020, 16:17:49.067 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3003
    May 12th 2020, 16:17:49.616 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3001
    May 12th 2020, 16:17:49.641 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3003
    May 12th 2020, 16:17:49.655 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3001
    May 12th 2020, 16:17:49.672 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3000 true
    May 12th 2020, 16:17:49.698 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3002
    May 12th 2020, 16:17:49.716 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3003
    May 12th 2020, 16:17:50.006 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3002
    May 12th 2020, 16:17:50.053 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3000
    May 12th 2020, 16:17:50.089 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3000
    May 12th 2020, 16:17:50.467 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3000 true
    May 12th 2020, 16:17:50.556 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3003 true
    May 12th 2020, 16:17:50.557 s-rc-srv-03 rocketchat_rocketchat_4_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3003' to '172.18.106.161:3003' with name notify-room not authorized
    May 12th 2020, 16:17:50.587 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3003
    May 12th 2020, 16:17:50.589 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3003 true
    May 12th 2020, 16:17:50.616 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3000 true
    May 12th 2020, 16:17:50.677 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3001 true
    May 12th 2020, 16:17:50.678 s-rc-srv-03 rocketchat_rocketchat_4_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3003' to '172.18.106.161:3000' with name notify-room not authorized
    May 12th 2020, 16:17:50.683 s-rc-srv-03 rocketchat_rocketchat_4_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3003' to '172.18.106.160:3002' with name notify-room not authorized
    May 12th 2020, 16:17:50.690 s-rc-srv-03 rocketchat_rocketchat_4_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3003' to '172.18.106.161:3002' with name notify-room not authorized
    May 12th 2020, 16:17:50.707 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3000
    May 12th 2020, 16:17:50.709 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3000 true
    May 12th 2020, 16:17:50.716 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3002
    May 12th 2020, 16:17:50.739 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3002 true
    May 12th 2020, 16:17:50.748 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3002
    May 12th 2020, 16:17:50.751 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3002 true
    May 12th 2020, 16:17:50.763 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3001 true
    May 12th 2020, 16:17:50.765 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3003 true
    May 12th 2020, 16:17:50.766 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3002 true
    May 12th 2020, 16:17:50.982 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3001 true
    May 12th 2020, 16:17:50.992 s-rc-srv-03 rocketchat_rocketchat_4_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3003' to '172.18.106.160:3000' with name notify-room not authorized
    May 12th 2020, 16:17:51.009 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.160:3000
    May 12th 2020, 16:17:51.011 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3000 true
    May 12th 2020, 16:17:51.337 s-rc-srv-02 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3003 true
    May 12th 2020, 16:17:51.575 s-rc-srv-02 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3000 true
    May 12th 2020, 16:17:51.877 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3003 true
    May 12th 2020, 16:17:52.214 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3003 true
    May 12th 2020, 16:17:52.400 s-rc-srv-02 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3003 true
    May 12th 2020, 16:17:52.545 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:17:52.850 s-rc-srv-02 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:17:53.248 s-rc-srv-02 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:17:53.447 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3001 true
    May 12th 2020, 16:17:53.448 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3003 true
    May 12th 2020, 16:17:53.450 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3000 true
    May 12th 2020, 16:17:53.501 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3000 true
    May 12th 2020, 16:17:53.503 s-rc-srv-03 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3002 true
    May 12th 2020, 16:17:54.040 s-rc-srv-01 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3003 true
    May 12th 2020, 16:17:54.354 s-rc-srv-01 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3000 true
    May 12th 2020, 16:17:54.425 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:17:54.616 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3003 true
    May 12th 2020, 16:17:55.066 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3000 true
    May 12th 2020, 16:17:57.545 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3003 true
    May 12th 2020, 16:17:59.310 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3002 true
    May 12th 2020, 16:17:59.314 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3001 true
    May 12th 2020, 16:17:59.726 s-rc-srv-03 rocketchat_rocketchat_1_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3000' to '172.18.106.161:3003' with name notify-logged not authorized
    May 12th 2020, 16:17:59.730 s-rc-srv-03 rocketchat_rocketchat_1_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3000' to '172.18.106.161:3001' with name notify-logged not authorized
    May 12th 2020, 16:17:59.785 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3001
    May 12th 2020, 16:17:59.788 s-rc-srv-03 rocketchat_rocketchat_1_1   server.js:204 StreamBroadcast ➔ Stream.error Stream broadcast from '172.18.106.162:3000' to '172.18.106.161:3001' with name notify-room not authorized
    May 12th 2020, 16:17:59.798 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3003
    May 12th 2020, 16:17:59.798 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3003 true
    May 12th 2020, 16:17:59.842 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info Authorizing with 172.18.106.161:3001
    May 12th 2020, 16:17:59.845 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3001 true
    May 12th 2020, 16:18:00.360 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3002 true
    May 12th 2020, 16:18:00.362 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3000 true
    May 12th 2020, 16:18:00.518 s-rc-srv-01 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:18:02.348 s-rc-srv-01 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:18:03.115 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:18:06.421 s-rc-srv-01 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3000 true
    May 12th 2020, 16:18:06.869 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3003 true
    May 12th 2020, 16:18:06.871 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3001 true
    May 12th 2020, 16:18:07.124 s-rc-srv-03 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3001 true
    May 12th 2020, 16:18:09.702 s-rc-srv-02 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3001 true
    May 12th 2020, 16:18:11.924 s-rc-srv-02 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3001 true
    May 12th 2020, 16:18:11.930 s-rc-srv-01 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3002 true
    May 12th 2020, 16:18:13.377 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3003 true
    May 12th 2020, 16:18:13.395 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3002 true
    May 12th 2020, 16:18:13.448 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3000 true
    May 12th 2020, 16:18:13.918 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3002 true
    May 12th 2020, 16:18:14.348 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3002 true
    May 12th 2020, 16:18:14.351 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3001 true
    May 12th 2020, 16:18:14.354 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3003 true
    May 12th 2020, 16:18:14.355 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3001 true
    May 12th 2020, 16:18:14.358 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3003 true
    May 12th 2020, 16:18:14.434 s-rc-srv-03 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3000 true
    May 12th 2020, 16:18:15.497 s-rc-srv-02 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3001 true
    May 12th 2020, 16:18:21.342 s-rc-srv-01 rocketchat_rocketchat_3_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3001 true
    May 12th 2020, 16:18:21.958 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.160:3000 true
    May 12th 2020, 16:18:21.961 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3002 true
    May 12th 2020, 16:18:21.967 s-rc-srv-03 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.161:3000 true
    May 12th 2020, 16:18:29.507 s-rc-srv-01 rocketchat_rocketchat_4_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3001 true
    May 12th 2020, 16:18:31.299 s-rc-srv-01 rocketchat_rocketchat_2_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3001 true
    May 12th 2020, 16:18:59.510 s-rc-srv-01 rocketchat_rocketchat_1_1   StreamBroadcast ➔ Auth.info broadcastAuth with 172.18.106.162:3001 true
    May 12th 2020, 16:20:45.331 s-rc-srv-03 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:20:45.331 s-rc-srv-03 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"Yt6FLteovaGMzXSy5"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:20:45.332 s-rc-srv-03 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:20:45.332 s-rc-srv-03 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"Yt6FLteovaGMzXSy5"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:20:45.332 s-rc-srv-03 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:20:45.342 s-rc-srv-03 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:20:45.750 s-rc-srv-03 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:20:45.750 s-rc-srv-03 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"ivf4hyPuasq6fTwp7","services.resume.loginTokens.hashedToken":"ImaJnUd7PBfuWQt9DO2wSd7CAvdUhTDwc5cp6A8EhYU="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:20:45.750 s-rc-srv-03 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:20:45.750 s-rc-srv-03 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"ivf4hyPuasq6fTwp7","services.resume.loginTokens.hashedToken":"ImaJnUd7PBfuWQt9DO2wSd7CAvdUhTDwc5cp6A8EhYU="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:20:45.751 s-rc-srv-03 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:20:45.759 s-rc-srv-03 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:21:21.649 s-rc-srv-02 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:21:21.651 s-rc-srv-02 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"kZkfQqkyr69taNAdo"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:21:21.651 s-rc-srv-02 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:21:21.651 s-rc-srv-02 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"kZkfQqkyr69taNAdo"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:21:21.652 s-rc-srv-02 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:21:21.656 s-rc-srv-02 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:21:28.870 s-rc-srv-02 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:21:28.870 s-rc-srv-02 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:21:28.871 s-rc-srv-02 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:21:28.871 s-rc-srv-02 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:21:28.871 s-rc-srv-02 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:21:28.879 s-rc-srv-02 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:21:45.340 s-rc-srv-03 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:21:45.341 s-rc-srv-03 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:21:45.341 s-rc-srv-03 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:21:45.342 s-rc-srv-03 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:21:45.342 s-rc-srv-03 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:21:45.342 s-rc-srv-03 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:21:45.675 s-rc-srv-03 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:21:45.675 s-rc-srv-03 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"GTdhv2HTgc9JRmTvs","services.resume.loginTokens.hashedToken":"PKMXXw94xCtbrU2uBGtEdHzCec2OXhQHxF1RpCyJLr0="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:21:45.676 s-rc-srv-03 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:21:45.676 s-rc-srv-03 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"GTdhv2HTgc9JRmTvs","services.resume.loginTokens.hashedToken":"PKMXXw94xCtbrU2uBGtEdHzCec2OXhQHxF1RpCyJLr0="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:21:45.680 s-rc-srv-03 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:21:45.686 s-rc-srv-03 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:21:45.745 s-rc-srv-03 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"j2nWBBfRkBjLx9HiY"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:21:45.745 s-rc-srv-03 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:21:45.745 s-rc-srv-03 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:21:45.746 s-rc-srv-03 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"j2nWBBfRkBjLx9HiY"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:21:45.746 s-rc-srv-03 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:21:45.746 s-rc-srv-03 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:22:17.120 s-rc-srv-01 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:17.120 s-rc-srv-01 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:17.120 s-rc-srv-01 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"aPRjEiLAEYS8muWd7"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:17.121 s-rc-srv-01 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:22:17.121 s-rc-srv-01 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"aPRjEiLAEYS8muWd7"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:17.129 s-rc-srv-01 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:21.660 s-rc-srv-02 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:21.660 s-rc-srv-02 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"g68W5K3Q5FwuyQnw8"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:21.660 s-rc-srv-02 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:21.661 s-rc-srv-02 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"g68W5K3Q5FwuyQnw8"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:21.661 s-rc-srv-02 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:21.661 s-rc-srv-02 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:22:23.231 s-rc-srv-01 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:23.232 s-rc-srv-01 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"L8ACjgDD2veASFXtf"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:23.233 s-rc-srv-01 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:23.233 s-rc-srv-01 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"L8ACjgDD2veASFXtf"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:23.233 s-rc-srv-01 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:22:23.240 s-rc-srv-01 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:23.688 s-rc-srv-02 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:23.689 s-rc-srv-02 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"6ydg24dsw9J26qSQB"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:23.689 s-rc-srv-02 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"6ydg24dsw9J26qSQB"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:23.689 s-rc-srv-02 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:22:23.689 s-rc-srv-02 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:23.701 s-rc-srv-02 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:23.845 s-rc-srv-02 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:23.845 s-rc-srv-02 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"fadoBdC762qkfovku"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:23.846 s-rc-srv-02 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:23.846 s-rc-srv-02 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"fadoBdC762qkfovku"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:23.846 s-rc-srv-02 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:22:23.858 s-rc-srv-02 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:28.893 s-rc-srv-02 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:28.894 s-rc-srv-02 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA","services.resume.loginTokens.hashedToken":"Gywf83hG4ISAxOVq7dHhpPqZHafbRsoOKPfla0b/b6w="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:22:28.894 s-rc-srv-02 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:28.894 s-rc-srv-02 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:28.898 s-rc-srv-02 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA","services.resume.loginTokens.hashedToken":"Gywf83hG4ISAxOVq7dHhpPqZHafbRsoOKPfla0b/b6w="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:22:28.898 s-rc-srv-02 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:22:29.989 s-rc-srv-01 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"98W6NgPBSeop2hBLb"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:29.989 s-rc-srv-01 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:29.989 s-rc-srv-01 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:29.991 s-rc-srv-01 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"98W6NgPBSeop2hBLb"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:29.992 s-rc-srv-01 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:29.992 s-rc-srv-01 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:22:45.350 s-rc-srv-03 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:45.350 s-rc-srv-03 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:45.350 s-rc-srv-03 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw","services.resume.loginTokens.hashedToken":"aeyFomNlNNmDAhlNHKLfn2yo2L+uOG/YUgsONl1u/OY="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:22:45.351 s-rc-srv-03 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:45.351 s-rc-srv-03 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw","services.resume.loginTokens.hashedToken":"aeyFomNlNNmDAhlNHKLfn2yo2L+uOG/YUgsONl1u/OY="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:22:45.351 s-rc-srv-03 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:22:45.685 s-rc-srv-03 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:45.686 s-rc-srv-03 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:22:45.686 s-rc-srv-03 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"y8BLGgdTpDR2NG4wf"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:45.686 s-rc-srv-03 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:45.686 s-rc-srv-03 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"y8BLGgdTpDR2NG4wf"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:45.686 s-rc-srv-03 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:45.758 s-rc-srv-03 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:45.758 s-rc-srv-03 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"krtSHRmbAHvGRA779"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:22:45.760 s-rc-srv-03 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:45.760 s-rc-srv-03 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:22:45.764 s-rc-srv-03 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"krtSHRmbAHvGRA779"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:22:45.764 s-rc-srv-03 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:22:45.803 s-rc-srv-03 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:22:45.803 s-rc-srv-03 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:22:45.803 s-rc-srv-03 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"hEo3WwtG4e3n4wW6j","services.resume.loginTokens.hashedToken":"9ZhsBZh5jV4mHAX5acPPf8XAGPFJJFSW9IF7EqaFKck="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:22:45.803 s-rc-srv-03 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"hEo3WwtG4e3n4wW6j","services.resume.loginTokens.hashedToken":"9ZhsBZh5jV4mHAX5acPPf8XAGPFJJFSW9IF7EqaFKck="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:22:45.804 s-rc-srv-03 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:22:45.820 s-rc-srv-03 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:17.117 s-rc-srv-01 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:17.117 s-rc-srv-01 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:17.118 s-rc-srv-01 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:23:17.118 s-rc-srv-01 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"HSzZdmzkMHAHBG5hu","services.resume.loginTokens.hashedToken":"0LTmQRZdkIILMw9EYZ5r2PYHv9VU2vh/Wql6l2gTMDk="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:23:17.118 s-rc-srv-01 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:17.118 s-rc-srv-01 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"HSzZdmzkMHAHBG5hu","services.resume.loginTokens.hashedToken":"0LTmQRZdkIILMw9EYZ5r2PYHv9VU2vh/Wql6l2gTMDk="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:23:21.666 s-rc-srv-02 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"g68W5K3Q5FwuyQnw8","services.resume.loginTokens.hashedToken":"jxmytHybakLnVNtgu7ycBRaH+SPhX2rj7h/gBEknS+8="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:23:21.666 s-rc-srv-02 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:21.666 s-rc-srv-02 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:21.667 s-rc-srv-02 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:21.669 s-rc-srv-02 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"g68W5K3Q5FwuyQnw8","services.resume.loginTokens.hashedToken":"jxmytHybakLnVNtgu7ycBRaH+SPhX2rj7h/gBEknS+8="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:23:21.671 s-rc-srv-02 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:23:23.241 s-rc-srv-01 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:23.241 s-rc-srv-01 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:23.241 s-rc-srv-01 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"At2dzfc7YS4yg3ojs"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:23:23.241 s-rc-srv-01 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:23.242 s-rc-srv-01 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"At2dzfc7YS4yg3ojs"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:23:23.243 s-rc-srv-01 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:23:23.693 s-rc-srv-02 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:23.694 s-rc-srv-02 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:23.696 s-rc-srv-02 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"6ydg24dsw9J26qSQB","services.resume.loginTokens.hashedToken":"PsBiNfaUg34NRarMG9ycEUVPYBcCv0g7oCV0WwIplqg="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:23:23.697 s-rc-srv-02 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:23.697 s-rc-srv-02 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:23:23.697 s-rc-srv-02 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"6ydg24dsw9J26qSQB","services.resume.loginTokens.hashedToken":"PsBiNfaUg34NRarMG9ycEUVPYBcCv0g7oCV0WwIplqg="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:23:23.845 s-rc-srv-02 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"XuMfSDvsWxTQ9KvmE","services.resume.loginTokens.hashedToken":"DBFYPROmYUIppvfQ/ySBgW0k1AdRn+7CqInfIKvKLzE="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:23:23.845 s-rc-srv-02 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:23.846 s-rc-srv-02 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:23.846 s-rc-srv-02 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:23.846 s-rc-srv-02 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"XuMfSDvsWxTQ9KvmE","services.resume.loginTokens.hashedToken":"DBFYPROmYUIppvfQ/ySBgW0k1AdRn+7CqInfIKvKLzE="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:23:23.846 s-rc-srv-02 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:23:28.909 s-rc-srv-02 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:28.909 s-rc-srv-02 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:28.914 s-rc-srv-02 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:23:28.917 s-rc-srv-02 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:28.918 s-rc-srv-02 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:23:28.918 s-rc-srv-02 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:23:29.991 s-rc-srv-01 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:29.991 s-rc-srv-01 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"kRTqFuXe8PBi7h9CE"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:23:29.991 s-rc-srv-01 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:29.991 s-rc-srv-01 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:29.992 s-rc-srv-01 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"kRTqFuXe8PBi7h9CE"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:23:29.995 s-rc-srv-01 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:23:45.376 s-rc-srv-03 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:45.376 s-rc-srv-03 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:45.376 s-rc-srv-03 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:23:45.377 s-rc-srv-03 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:45.377 s-rc-srv-03 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:23:45.379 s-rc-srv-03 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:23:45.705 s-rc-srv-03 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"yrnZXA2GmMs9mB35Y"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:23:45.705 s-rc-srv-03 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:45.705 s-rc-srv-03 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:45.705 s-rc-srv-03 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:45.706 s-rc-srv-03 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:23:45.706 s-rc-srv-03 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"yrnZXA2GmMs9mB35Y"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:23:45.775 s-rc-srv-03 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:45.775 s-rc-srv-03 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"krtSHRmbAHvGRA779","services.resume.loginTokens.hashedToken":"DgCaKH1FmZ1hdiEWPnmYDDX0H0ZU/YK7+adlUnZv0AU="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:23:45.776 s-rc-srv-03 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:45.776 s-rc-srv-03 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:23:45.783 s-rc-srv-03 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"krtSHRmbAHvGRA779","services.resume.loginTokens.hashedToken":"DgCaKH1FmZ1hdiEWPnmYDDX0H0ZU/YK7+adlUnZv0AU="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:23:45.784 s-rc-srv-03 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:23:45.817 s-rc-srv-03 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"hEo3WwtG4e3n4wW6j"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:23:45.817 s-rc-srv-03 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:23:45.817 s-rc-srv-03 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:23:45.821 s-rc-srv-03 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"hEo3WwtG4e3n4wW6j"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:23:45.821 s-rc-srv-03 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:23:45.821 s-rc-srv-03 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:17.127 s-rc-srv-01 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"SwtHndeXWFkYStap8"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:17.127 s-rc-srv-01 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:24:17.127 s-rc-srv-01 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:17.127 s-rc-srv-01 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"SwtHndeXWFkYStap8"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:17.127 s-rc-srv-01 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:17.127 s-rc-srv-01 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:21.677 s-rc-srv-02 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:21.678 s-rc-srv-02 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:21.678 s-rc-srv-02 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:24:21.678 s-rc-srv-02 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"DNnQ9SYvyXWSD6WtM"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:21.678 s-rc-srv-02 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:21.678 s-rc-srv-02 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"DNnQ9SYvyXWSD6WtM"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:23.250 s-rc-srv-01 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:23.250 s-rc-srv-01 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"p9gMXDfcJRBGwsqfi"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:23.251 s-rc-srv-01 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:23.258 s-rc-srv-01 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:23.259 s-rc-srv-01 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"p9gMXDfcJRBGwsqfi"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:23.259 s-rc-srv-01 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:24:23.722 s-rc-srv-02 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"bggjeMqXBoNo75z57"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:23.722 s-rc-srv-02 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:23.722 s-rc-srv-02 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:23.727 s-rc-srv-02 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:23.727 s-rc-srv-02 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:24:23.727 s-rc-srv-02 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"bggjeMqXBoNo75z57"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:23.853 s-rc-srv-02 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:23.856 s-rc-srv-02 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:23.856 s-rc-srv-02 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"dczqjZRRsbbtmAtSP"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:23.857 s-rc-srv-02 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:23.857 s-rc-srv-02 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"dczqjZRRsbbtmAtSP"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:23.857 s-rc-srv-02 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:24:28.947 s-rc-srv-02 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA","services.resume.loginTokens.hashedToken":"Gywf83hG4ISAxOVq7dHhpPqZHafbRsoOKPfla0b/b6w="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:24:28.947 s-rc-srv-02 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:28.948 s-rc-srv-02 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:24:28.948 s-rc-srv-02 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:28.948 s-rc-srv-02 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"xBQnPDwZAbcjsmrgA","services.resume.loginTokens.hashedToken":"Gywf83hG4ISAxOVq7dHhpPqZHafbRsoOKPfla0b/b6w="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:24:28.948 s-rc-srv-02 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:30.011 s-rc-srv-01 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"PHb6TjN9cDaY7QfnK"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:30.011 s-rc-srv-01 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:30.011 s-rc-srv-01 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:30.011 s-rc-srv-01 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:30.013 s-rc-srv-01 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"PHb6TjN9cDaY7QfnK"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:30.014 s-rc-srv-01 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:24:45.390 s-rc-srv-03 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:45.390 s-rc-srv-03 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:45.390 s-rc-srv-03 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw","services.resume.loginTokens.hashedToken":"aeyFomNlNNmDAhlNHKLfn2yo2L+uOG/YUgsONl1u/OY="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:24:45.390 s-rc-srv-03 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:45.391 s-rc-srv-03 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"nECKmxu9bf6fzJ3Bw","services.resume.loginTokens.hashedToken":"aeyFomNlNNmDAhlNHKLfn2yo2L+uOG/YUgsONl1u/OY="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:24:45.391 s-rc-srv-03 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:24:45.722 s-rc-srv-03 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:45.724 s-rc-srv-03 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"o3M8xGgKpi7PhdDpd"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:45.724 s-rc-srv-03 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:45.726 s-rc-srv-03 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:45.726 s-rc-srv-03 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"o3M8xGgKpi7PhdDpd"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:45.727 s-rc-srv-03 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:24:45.774 s-rc-srv-03 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:45.775 s-rc-srv-03 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:45.775 s-rc-srv-03 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"tT9BD9L79S9RcGAm5"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:24:45.779 s-rc-srv-03 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:24:45.779 s-rc-srv-03 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:45.779 s-rc-srv-03 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"tT9BD9L79S9RcGAm5"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:24:45.843 s-rc-srv-03 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:24:45.843 s-rc-srv-03 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:24:45.843 s-rc-srv-03 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"hEo3WwtG4e3n4wW6j","services.resume.loginTokens.hashedToken":"9ZhsBZh5jV4mHAX5acPPf8XAGPFJJFSW9IF7EqaFKck="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:24:45.844 s-rc-srv-03 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:24:45.844 s-rc-srv-03 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"hEo3WwtG4e3n4wW6j","services.resume.loginTokens.hashedToken":"9ZhsBZh5jV4mHAX5acPPf8XAGPFJJFSW9IF7EqaFKck="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:24:45.844 s-rc-srv-03 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:25:17.146 s-rc-srv-01 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:25:17.147 s-rc-srv-01 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"SbcETbW6e7aG2EYG8"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:25:17.147 s-rc-srv-01 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:25:17.147 s-rc-srv-01 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:25:17.147 s-rc-srv-01 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"SbcETbW6e7aG2EYG8"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:25:17.147 s-rc-srv-01 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:25:21.699 s-rc-srv-02 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:25:21.699 s-rc-srv-02 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:25:21.702 s-rc-srv-02 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"YCB3oqZ6LYh6tXuJY"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:25:21.702 s-rc-srv-02 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"YCB3oqZ6LYh6tXuJY"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:25:21.702 s-rc-srv-02 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:25:21.703 s-rc-srv-02 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:25:23.256 s-rc-srv-01 rocketchat_rocketchat_4_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:25:23.256 s-rc-srv-01 rocketchat_rocketchat_4_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"yvb7uuQYerYhG2cE7"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:25:23.256 s-rc-srv-01 rocketchat_rocketchat_4_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:25:23.256 s-rc-srv-01 rocketchat_rocketchat_4_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:25:23.256 s-rc-srv-01 rocketchat_rocketchat_4_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"yvb7uuQYerYhG2cE7"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:25:23.257 s-rc-srv-01 rocketchat_rocketchat_4_1   }
    May 12th 2020, 16:25:23.722 s-rc-srv-02 rocketchat_rocketchat_3_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:25:23.722 s-rc-srv-02 rocketchat_rocketchat_3_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:25:23.722 s-rc-srv-02 rocketchat_rocketchat_3_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"bggjeMqXBoNo75z57","services.resume.loginTokens.hashedToken":"7EQrDHVE0sHfriQe1lv84oP8XvLK6LRElPaa06IMPc0="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:25:23.722 s-rc-srv-02 rocketchat_rocketchat_3_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:25:23.723 s-rc-srv-02 rocketchat_rocketchat_3_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"bggjeMqXBoNo75z57","services.resume.loginTokens.hashedToken":"7EQrDHVE0sHfriQe1lv84oP8XvLK6LRElPaa06IMPc0="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:25:23.723 s-rc-srv-02 rocketchat_rocketchat_3_1   }
    May 12th 2020, 16:25:23.864 s-rc-srv-02 rocketchat_rocketchat_2_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:25:23.864 s-rc-srv-02 rocketchat_rocketchat_2_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"dczqjZRRsbbtmAtSP","services.resume.loginTokens.hashedToken":"62eq+Ou/y+G42BIonypXV75Anuhs/5wor95wIcOjdUE="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:25:23.865 s-rc-srv-02 rocketchat_rocketchat_2_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:25:23.865 s-rc-srv-02 rocketchat_rocketchat_2_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:25:23.872 s-rc-srv-02 rocketchat_rocketchat_2_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"dczqjZRRsbbtmAtSP","services.resume.loginTokens.hashedToken":"62eq+Ou/y+G42BIonypXV75Anuhs/5wor95wIcOjdUE="},"options":{"transform":null,"fields":{"_id":1}}}'
    May 12th 2020, 16:25:23.874 s-rc-srv-02 rocketchat_rocketchat_2_1   }
    May 12th 2020, 16:25:28.980 s-rc-srv-02 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"iG2DZ2GF7qhvsJahB"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}',
    May 12th 2020, 16:25:28.980 s-rc-srv-02 rocketchat_rocketchat_1_1   TIMEOUT QUERY OPERATION {
    May 12th 2020, 16:25:28.981 s-rc-srv-02 rocketchat_rocketchat_1_1   writesToCommitWhenWeReachSteadyLength: 0,
    May 12th 2020, 16:25:28.981 s-rc-srv-02 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}
    May 12th 2020, 16:25:28.981 s-rc-srv-02 rocketchat_rocketchat_1_1   cursorDescription: '{"collectionName":"users","selector":{"_id":"iG2DZ2GF7qhvsJahB"},"options":{"transform":null,"fields":{"profile":1,"username":1,"emails":1}}}'
    May 12th 2020, 16:25:28.985 s-rc-srv-02 rocketchat_rocketchat_1_1   }
    May 12th 2020, 16:25:30.032 s-rc-srv-01 rocketchat_rocketchat_1_1   observeKey: '{"ordered":false,"collectionName":"users","selector":{"_id":"wxqhYwrrNSH3yyaYN","services.resume.loginTokens.hashedToken":"LUixSxIyCJagMGAPP/rz203yo809tIYZ9lCDcCC4c7A="},"options":{"transform":null,"fields":{"_id":1}}}',
    May 12th 2020, 16:25:30.032 s-rc-srv-01 rocketchat_rocketchat_1_1   Exception in setInterval callback: SwitchedToQuery {}

ankar84 picture ankar84 on 13 May 2020

And yesterday again.. two times... without users load...
Nginx requests
image
Network
image
RAM
image
CPU
image
DB
image
NodeJS
image
image
image
image
OpLog
image
Methods
image
Subscriptions
image
Callbacks (why disabled 2fa so much?)
image
Hooks
image
REST API Calls
image

These two options helping a lot on reboot:
image
That settings disables stream-notify-logged witch amount consume resources a lot.
But in crash moment Admin UI is not usable, so we decided to set that options in DB with:

db.rocketchat_settings.update({"_id":"Troubleshoot_Disable_Notifications"},{$set:{"value":true}})
db.rocketchat_settings.update({"_id":"Troubleshoot_Disable_Presence_Broadcast"},{$set:{"value":true}})

But I see that it doesn't work well. Rocket Chat instances do not re-read that settings from DB, so Admin UI manipulations are only one guaranteed way to turn that options on.

@sampaiodiego how we can apply that two settings from DB (without unreliable in crash moments Admin UI)?

ankar84 picture ankar84 on 15 May 2020

Have you considered that perhaps someone malicious is targeting your instance? nginx req/s is really high. You could analyze the access logs for common patterns.

bbrauns picture bbrauns on 15 May 2020

Have you considered that perhaps someone malicious is targeting your instance? nginx req/s is really high. You could analyze the access logs for common patterns.

That high Nginx requests amount is a symptom for Rocket Chat unavailability - clients are downgraded to SockJS and do a lot of POST requests like described here https://github.com/RocketChat/Rocket.Chat/issues/17559
But what caused that unavailability with high resources load - that is the question!

ankar84 picture ankar84 on 15 May 2020

That weekend we reconfigured our deployment a bit.
Now we have 25 instances in docker on 5 CentOS7 servers with one nginx with IP_HASH for sticky sessions on separate server.
And I configured DISABLE_PRESENCE_MONITOR=no only on first instance on first server, the others have DISABLE_PRESENCE_MONITOR=yes
And before any instance reboot or other maintenance I enable option Troubleshoot_Disable_Presence_Broadcast and all goes rather easy and faster.
Will see...

ankar84 picture ankar84 on 18 May 2020

Any news ?
Looks like RocketChat continues to be developed without considering this bug ._.
How to know if we can make the update to 3.x ?

Kayoku picture Kayoku on 21 May 2020

Any news ?

Hi @Kayoku
After that changes and for now all seem to be stable. No any sporadic peaks in resource load.
Today I noticed, that Poll application is disabled again. And I think that Poll app can be somehow the reason for all that crashed.
But not poll app itself but apps-engine.
That issue can clarify my thoughts.
Tomorrow I will enable Poll app again and will check system stability.
@benedikt-wegmann @bbrauns do you use Poll app or any other app in your deployment?

ankar84 picture ankar84 on 21 May 2020

@ankar84 I had to check but we have poll bot.js (https://gist.github.com/sampaiodiego/db4b60717e7ac0051024dde23c6a902e) enabled in our service but hardly anybody seems to use it. The list of Apps in the Admin UI is empty though. :monocle_face:

benedikt-wegmann picture benedikt-wegmann on 22 May 2020
👍1

Now we have 25 instances in docker on 5 CentOS7 servers with one nginx with IP_HASH for sticky sessions on separate server.
And I configured DISABLE_PRESENCE_MONITOR=no only on first instance on first server, the others have DISABLE_PRESENCE_MONITOR=yes
And before any instance reboot or other maintenance I enable option Troubleshoot_Disable_Presence_Broadcast and all goes rather easy and faster.

After these changes I can say that we have 2 weeks of stability and good performance of service.
One thing - Memory leak problem (#16586 and #13602 ) caused us to restart every of 25 instances at sunday night in 5 minuted interval for each.
image
I'm not sure that DISABLE_PRESENCE_MONITOR increased stability in our case. I think that amount of instances did. Now each instance serves less users and that is good for our stability and performance.

ankar84 picture ankar84 on 1 Jun 2020

@ankar84 First of all: impressive, top-notch monitoring! 👍

Do you use the HAProxy configuration that @bbrauns shared with you (if he did)? At that time there was a mistake and it didn't have session stickiness configured. 😞

Would you mind sharing your webserver configuration here as well?

Hi @bbrauns, could you share yours HAproxy config. We also think about HAproxy and working config can be helpful

emikolajczak picture emikolajczak on 10 Jun 2020

@emikolajczak This is our Haproxy Config, serving 26 Rocket.Chat Docker instances on one large host. Haproxy itself is also in Docker.

haproxy.cfg.txt

benedikt-wegmann picture benedikt-wegmann on 10 Jun 2020
👍2

At that moment issue solved with:

  1. Proper server and instances sizing. 25 instances for about 3K connected users peak
  2. Weekly instance restart (late night, one-by-one without service downtime)
  3. Sticky sessions with IP_HASH (Nginx). We plan to migrate to HAProxy
  4. Maybe DISABLE_PRESENCE_MONITOR=yes helped a bit (I'm not sure about that really)
  5. Maybe 1 reverse proxy instead of 3 reverse proxies (I'm not sure about that)

Some issues are still in place, but with all that workarounds and technics Rocket Chat looks stable and with pretty good performance for us and our users.

ankar84 picture ankar84 on 21 Jul 2020
👍5 ❤2

that's good to hear, thanks for letting us know @ankar84 .. having to restart the instances due the memory leak is something we know about and hopefully we'll have something in place to fix it in the near future.

sampaiodiego picture sampaiodiego on 21 Jul 2020
👍2
Was this page helpful?
0 / 5 - 0 ratings

Related issues

antn89 picture antn89  ·  3Comments
sta-szek picture sta-szek  ·  3Comments
mattlin picture mattlin  ·  3Comments
neha1deshmukh picture neha1deshmukh  ·  3Comments
engelgabriel picture engelgabriel  ·  3Comments