Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Rocketchatctl fails to detect running rocketchat after today's upgrade to 4.0.0 due to mongod Depreciation message #23358

Closed
corrigac opened this issue Oct 4, 2021 · 6 comments · Fixed by RocketChat/install.sh#49
Closed

Rocketchatctl fails to detect running rocketchat after today's upgrade to 4.0.0 due to mongod Depreciation message #23358

corrigac opened this issue Oct 4, 2021 · 6 comments · Fixed by RocketChat/install.sh#49
Labels
feat: rocketchatctl

Comments

@corrigac
Copy link

corrigac commented Oct 4, 2021 •
edited by sampaiodiego
Loading

Description:

Following this weekend's release of Rocketchat 4.0.0, update from previous release 3.18.1 an upgrade via rocketchatctl update fails to complete with the following output:

sudo rocketchatctl update
......
Waiting up to 60 seconds for RocketChat server to be active ... 54
Waiting up to 60 seconds for RocketChat server to be active ... 56
Waiting up to 60 seconds for RocketChat server to be active ... 58
Waiting up to 60 seconds for RocketChat server to be active ... 60
Error in updated RocketChat server health check, restoring backup.

Even though rocketchat has successfully restarted and had been running

Steps to reproduce:

  1. deploy rocketchat 3.18.1 on Ubuntu 18.04.6 LTS
  2. run rocketchatctl update

Expected behavior:

Expected rocketchat to upgrade to 4.0 without issue

Actual behavior:

Install fails, rocketchat installation left in non-working state, clients report nginx/1.14.0 502 bad gateway error

Server Setup Information:

  • Version of Rocket.Chat Server: 3.18.1 -> 4.0
  • Operating System: Ubuntu 18.4.6 LTS
  • Deployment Method: install via curl from https://releases.rocket.chat/ on EC2 instance
  • Nodes: 1
  • DB Replicaset Oplog: n/a
  • NodeJS Version: v12.18.3
  • MongoDB Version: 4.0.27

Client Setup Information

  • Desktop App or Browser Version: Electron client
  • Operating System: MacOS/Windows

Additional context

Relevant logs:

Client Console log:
chat.scformulae.com/:1 Failed to load resource: the server responded with a status of 502 (Bad Gateway)

Server Syslog:

Oct  4 08:38:43 chat systemd-networkd[3791]: ens5: Configured
Oct  4 08:38:43 chat systemd-timesyncd[3825]: Network configuration changed, trying to establish connection.
Oct  4 08:38:43 chat systemd-timesyncd[3825]: Synchronized to time server 91.189.89.199:123 (ntp.ubuntu.com).
Oct  4 09:08:44 chat systemd-networkd[3791]: ens5: Configured
Oct  4 09:08:44 chat systemd-timesyncd[3825]: Network configuration changed, trying to establish connection.
Oct  4 09:08:44 chat systemd-timesyncd[3825]: Synchronized to time server 91.189.89.199:123 (ntp.ubuntu.com).
Oct  4 09:10:40 chat systemd[1]: Created slice User Slice of ubuntu.
Oct  4 09:10:40 chat systemd[1]: Starting User Manager for UID 1000...
Oct  4 09:10:40 chat systemd[1]: Started Session 830 of user ubuntu.
Oct  4 09:10:40 chat systemd[26606]: Failed to open directory /home/ubuntu/.config/systemd/user, ignoring: Permission denied
Oct  4 09:10:40 chat systemd[26606]: Listening on GnuPG cryptographic agent and passphrase cache.
Oct  4 09:10:40 chat systemd[26606]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Oct  4 09:10:40 chat systemd[26606]: Listening on GnuPG network certificate management daemon.
Oct  4 09:10:40 chat systemd[26606]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Oct  4 09:10:40 chat systemd[26606]: Reached target Paths.
Oct  4 09:10:40 chat systemd[26606]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Oct  4 09:10:40 chat systemd[26606]: Reached target Sockets.
Oct  4 09:10:40 chat systemd[26606]: Reached target Timers.
Oct  4 09:10:40 chat systemd[26606]: Reached target Basic System.
Oct  4 09:10:40 chat systemd[1]: Started User Manager for UID 1000.
Oct  4 09:10:40 chat systemd[26606]: Reached target Default.
Oct  4 09:10:40 chat systemd[26606]: Startup finished in 68ms.
Oct  4 09:16:57 chat systemd[1]: Stopping The Rocket.Chat server...
Oct  4 09:16:57 chat systemd[1]: Stopped The Rocket.Chat server.
Oct  4 09:17:01 chat CRON[26775]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct  4 09:17:15 chat systemd[1]: Starting The Rocket.Chat server...
Oct  4 09:17:35 chat systemd[1]: Started The Rocket.Chat server.
Oct  4 09:17:51 chat rocketchat[26801]: LocalStore: store created at
Oct  4 09:17:51 chat rocketchat[26801]: message repeated 2 times: [ LocalStore: store created at]
Oct  4 09:17:52 chat rocketchat[26801]: Setting default file store to AmazonS3
Oct  4 09:17:59 chat rocketchat[26801]: {"line":"120","file":"migrations.js","message":"Migrations: Not migrating, already at version 231","time":{"$date":1633339079154},"level":"info"}
Oct  4 09:18:01 chat rocketchat[26801]: Configuring Prometheus { port: '9102', enabled: true, resetInterval: 0, collectGC: false }
Oct  4 09:18:01 chat rocketchat[26801]: Using GridFS for custom sounds storage
Oct  4 09:18:01 chat rocketchat[26801]: Using GridFS for custom emoji storage
Oct  4 09:18:01 chat rocketchat[26801]: Updating process.env.MAIL_URL
Oct  4 09:18:02 chat rocketchat[26801]: Loaded the Apps Framework and loaded a total of 5 Apps!
Oct  4 09:18:02 chat rocketchat[26801]: ➔ System ➔ startup
Oct  4 09:18:02 chat rocketchat[26801]: ➔ +----------------------------------------------------+
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |                   SERVER RUNNING                   |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ +----------------------------------------------------+
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |                                                    |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |  Rocket.Chat Version: 4.0.0                        |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |       NodeJS Version: 12.18.3 - x64                |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |      MongoDB Version: 4.0.26                       |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |       MongoDB Engine: mmapv1                       |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |             Platform: linux                        |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |         Process Port: 3000                         |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |             Site URL: https://chat.scformulae.com  |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |     ReplicaSet OpLog: Enabled                      |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |          Commit Hash: 2f33bd7896                   |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |        Commit Branch: develop                      |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ |                                                    |
Oct  4 09:18:02 chat rocketchat[26801]: ➔ +----------------------------------------------------+
Oct  4 09:18:31 chat systemd[1]: Reloading.
Oct  4 09:18:33 chat systemd[1]: message repeated 2 times: [ Reloading.]
Oct  4 09:18:33 chat systemd[1]: Stopping System Logging Service...
Oct  4 09:18:33 chat rsyslogd:  message repeated 30 times: [ [origin software="rsyslogd" swVersion="8.32.0" x-pid="728" x-info="http://www.rsyslog.com"] rsyslogd was HUPed]
Oct  4 09:18:33 chat rsyslogd:  [origin software="rsyslogd" swVersion="8.32.0" x-pid="728" x-info="http://www.rsyslog.com"] exiting on signal 15.
Oct  4 09:18:33 chat systemd[1]: Stopped System Logging Service.
Oct  4 09:18:33 chat systemd[1]: Starting System Logging Service...
Oct  4 09:18:33 chat rsyslogd: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.32.0]
Oct  4 09:18:33 chat systemd[1]: Started System Logging Service.
Oct  4 09:18:33 chat rsyslogd: rsyslogd's groupid changed to 106
Oct  4 09:18:33 chat rsyslogd: rsyslogd's userid changed to 102
Oct  4 09:18:33 chat rsyslogd:  [origin software="rsyslogd" swVersion="8.32.0" x-pid="27783" x-info="http://www.rsyslog.com"] start
Oct  4 09:18:49 chat systemd[1]: Stopping The Rocket.Chat server...
Oct  4 09:18:49 chat systemd[1]: Stopped The Rocket.Chat server.
Oct  4 09:19:30 chat systemd[1]: Starting The Rocket.Chat server...
Oct  4 09:19:50 chat systemd[1]: Started The Rocket.Chat server.
Oct  4 09:20:04 chat rocketchat[28643]: LocalStore: store created at
Oct  4 09:20:07 chat rocketchat[28643]: message repeated 5 times: [ LocalStore: store created at]
Oct  4 09:20:14 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:14.643Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Migrating from version 231 -> 239"}
Oct  4 09:20:14 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:14.645Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 232"}
Oct  4 09:20:14 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:14.691Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 233"}
Oct  4 09:20:14 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:14.711Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 234"}
Oct  4 09:20:14 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:14.773Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 235"}
Oct  4 09:20:14 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:14.953Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 236"}
Oct  4 09:20:14 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:14.962Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 237"}
Oct  4 09:20:15 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:15.079Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 238"}
Oct  4 09:20:15 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:15.495Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Running up() on version 239"}
Oct  4 09:20:15 chat rocketchat[28643]: {"level":51,"time":"2021-10-04T09:20:15.502Z","pid":28643,"hostname":"chat","name":"Migrations","msg":"Finished migrating."}
Oct  4 09:20:18 chat rocketchat[28643]: Loaded the Apps Framework and loaded a total of 5 Apps!
Oct  4 09:20:20 chat rocketchat[28643]: LocalStore: store created at
Oct  4 09:20:20 chat rocketchat[28643]: message repeated 2 times: [ LocalStore: store created at]
Oct  4 09:20:24 chat rocketchat[28643]: +----------------------------------------------------+
Oct  4 09:20:24 chat rocketchat[28643]: |                   SERVER RUNNING                   |
Oct  4 09:20:24 chat rocketchat[28643]: +----------------------------------------------------+
Oct  4 09:20:24 chat rocketchat[28643]: |                                                    |
Oct  4 09:20:24 chat rocketchat[28643]: |  Rocket.Chat Version: 4.0.0                        |
Oct  4 09:20:24 chat rocketchat[28643]: |       NodeJS Version: 12.18.3 - x64                |
Oct  4 09:20:24 chat rocketchat[28643]: |      MongoDB Version: 4.0.26                       |
Oct  4 09:20:24 chat rocketchat[28643]: |       MongoDB Engine: mmapv1                       |
Oct  4 09:20:24 chat rocketchat[28643]: |             Platform: linux                        |
Oct  4 09:20:24 chat rocketchat[28643]: |         Process Port: 3000                         |
Oct  4 09:20:24 chat rocketchat[28643]: |             Site URL: https://chat.scformulae.com  |
Oct  4 09:20:24 chat rocketchat[28643]: |     ReplicaSet OpLog: Enabled                      |
Oct  4 09:20:24 chat rocketchat[28643]: |          Commit Hash: 2ffdd13795                   |
Oct  4 09:20:24 chat rocketchat[28643]: |        Commit Branch: HEAD                         |
Oct  4 09:20:24 chat rocketchat[28643]: |                                                    |
Oct  4 09:20:24 chat rocketchat[28643]: +----------------------------------------------------+
Oct  4 09:20:24 chat rocketchat[28643]: +----------------------------------------------------------------------+
Oct  4 09:20:24 chat rocketchat[28643]: |                              DEPRECATION                             |
Oct  4 09:20:24 chat rocketchat[28643]: +----------------------------------------------------------------------+
Oct  4 09:20:24 chat rocketchat[28643]: |                                                                      |
Oct  4 09:20:24 chat rocketchat[28643]: |  YOUR CURRENT MONGODB VERSION (4.0.26) IS DEPRECATED.                |
Oct  4 09:20:24 chat rocketchat[28643]: |  IT WILL NOT BE SUPPORTED ON ROCKET.CHAT VERSION 5.0.0 AND GREATER,  |
Oct  4 09:20:24 chat rocketchat[28643]: |  PLEASE UPGRADE MONGODB TO VERSION 4.2 OR GREATER                    |
Oct  4 09:20:24 chat rocketchat[28643]: |                                                                      |
Oct  4 09:20:24 chat rocketchat[28643]: +----------------------------------------------------------------------+
Oct  4 09:20:28 chat rocketchat[28643]: (node:28643) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
Oct  4 09:31:51 chat rocketchat[28643]: Exception while invoking method 'createDirectMessage' Error: Match error: Expected string, got null
Oct  4 09:31:51 chat rocketchat[28643]:     at check (packages/check/match.js:36:17)
Oct  4 09:31:51 chat rocketchat[28643]:     at createDirectMessage (server/methods/createDirectMessage.js:12:2)
Oct  4 09:31:51 chat rocketchat[28643]:     at MethodInvocation.createDirectMessage (server/methods/createDirectMessage.js:94:10)
Oct  4 09:31:51 chat rocketchat[28643]:     at MethodInvocation.methodsMap.<computed> (app/lib/server/lib/debug.js:66:34)
Oct  4 09:31:51 chat rocketchat[28643]:     at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1771:12)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:719:19
Oct  4 09:31:51 chat rocketchat[28643]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:717:46
Oct  4 09:31:51 chat rocketchat[28643]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:715:46
Oct  4 09:31:51 chat rocketchat[28643]:     at new Promise (<anonymous>)
Oct  4 09:31:51 chat rocketchat[28643]:     at Session.method (packages/ddp-server/livedata_server.js:689:23)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:559:43
Oct  4 09:31:51 chat rocketchat[28643]: Sanitized and reported to the client as: errorClass [Error]: Match failed [400]
Oct  4 09:31:51 chat rocketchat[28643]:     at errorClass.<anonymous> (packages/check/match.js:91:27)
Oct  4 09:31:51 chat rocketchat[28643]:     at new errorClass (packages/meteor.js:655:17)
Oct  4 09:31:51 chat rocketchat[28643]:     at check (packages/check/match.js:36:17)
Oct  4 09:31:51 chat rocketchat[28643]:     at createDirectMessage (server/methods/createDirectMessage.js:12:2)
Oct  4 09:31:51 chat rocketchat[28643]:     at MethodInvocation.createDirectMessage (server/methods/createDirectMessage.js:94:10)
Oct  4 09:31:51 chat rocketchat[28643]:     at MethodInvocation.methodsMap.<computed> (app/lib/server/lib/debug.js:66:34)
Oct  4 09:31:51 chat rocketchat[28643]:     at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1771:12)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:719:19
Oct  4 09:31:51 chat rocketchat[28643]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:717:46
Oct  4 09:31:51 chat rocketchat[28643]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:715:46
Oct  4 09:31:51 chat rocketchat[28643]:     at new Promise (<anonymous>)
Oct  4 09:31:51 chat rocketchat[28643]:     at Session.method (packages/ddp-server/livedata_server.js:689:23)
Oct  4 09:31:51 chat rocketchat[28643]:     at packages/ddp-server/livedata_server.js:559:43 {
Oct  4 09:31:51 chat rocketchat[28643]:   isClientSafe: true,
Oct  4 09:31:51 chat rocketchat[28643]:   error: 400,
Oct  4 09:31:51 chat rocketchat[28643]:   reason: 'Match failed',
Oct  4 09:31:51 chat rocketchat[28643]:   details: undefined,
Oct  4 09:31:51 chat rocketchat[28643]:   errorType: 'Meteor.Error'
Oct  4 09:31:51 chat rocketchat[28643]: }
Oct  4 09:31:51 chat rocketchat[28643]: undefined undefined
Oct  4 09:38:43 chat systemd-timesyncd[3825]: Network configuration changed, trying to establish connection.
Oct  4 09:38:43 chat systemd-networkd[3791]: ens5: Configured
Oct  4 09:38:43 chat systemd-timesyncd[3825]: Synchronized to time server 91.189.89.199:123 (ntp.ubuntu.com).
Oct  4 09:47:44 chat systemd[1]: Stopping The Rocket.Chat server...
Oct  4 09:47:44 chat systemd[1]: Stopped The Rocket.Chat server.
Oct  4 09:47:44 chat systemd[1]: Starting The Rocket.Chat server...
Oct  4 09:48:04 chat systemd[1]: Started The Rocket.Chat server.
Oct  4 09:48:19 chat rocketchat[29149]: LocalStore: store created at
Oct  4 09:48:21 chat rocketchat[29149]: message repeated 5 times: [ LocalStore: store created at]
Oct  4 09:48:22 chat rocketchat[29149]: Setting default file store to AmazonS3
Oct  4 09:48:30 chat rocketchat[29149]: Exception in callback of async function: errorClass [Error]: [Can't find migration version 239]
Oct  4 09:48:30 chat rocketchat[29149]:     at Object.Migrations._findIndexByVersion (app/migrations/server/migrations.js:403:8)
Oct  4 09:48:30 chat rocketchat[29149]:     at Object.Migrations._migrateTo (app/migrations/server/migrations.js:254:24)
Oct  4 09:48:30 chat rocketchat[29149]:     at Object.Migrations.migrateTo (app/migrations/server/migrations.js:179:20)
Oct  4 09:48:30 chat rocketchat[29149]:     at module (server/startup/migrations/xrun.js:6:13)
Oct  4 09:48:30 chat rocketchat[29149]:     at fileEvaluate (packages/modules-runtime.js:336:7)
Oct  4 09:48:30 chat rocketchat[29149]:     at Module.require (packages/modules-runtime.js:238:14)
Oct  4 09:48:30 chat rocketchat[29149]:     at Module.moduleLink [as link] (/opt/Rocket.Chat/programs/server/npm/node_modules/meteor/modules/node_modules/reify/lib/runtime/index.js:52:22)
Oct  4 09:48:30 chat rocketchat[29149]:     at module (server/startup/migrations/index.js:1:5068)
Oct  4 09:48:30 chat rocketchat[29149]:     at fileEvaluate (packages/modules-runtime.js:336:7)
Oct  4 09:48:30 chat rocketchat[29149]:     at Module.require (packages/modules-runtime.js:238:14)
Oct  4 09:48:30 chat rocketchat[29149]:     at Module.moduleLink [as link] (/opt/Rocket.Chat/programs/server/npm/node_modules/meteor/modules/node_modules/reify/lib/runtime/index.js:52:22)
Oct  4 09:48:30 chat rocketchat[29149]:     at module (server/main.js:1:210)
Oct  4 09:48:30 chat rocketchat[29149]:     at fileEvaluate (packages/modules-runtime.js:336:7)
Oct  4 09:48:30 chat rocketchat[29149]:     at Module.require (packages/modules-runtime.js:238:14)
Oct  4 09:48:30 chat rocketchat[29149]:     at require (packages/modules-runtime.js:258:21)
Oct  4 09:48:30 chat rocketchat[29149]:     at /opt/Rocket.Chat/programs/server/app/app.js:207872:15
Oct  4 09:48:30 chat rocketchat[29149]:     at /opt/Rocket.Chat/programs/server/boot.js:401:38
Oct  4 09:48:30 chat rocketchat[29149]:     at Array.forEach (<anonymous>)
Oct  4 09:48:30 chat rocketchat[29149]:     at /opt/Rocket.Chat/programs/server/boot.js:226:21
Oct  4 09:48:30 chat rocketchat[29149]:     at /opt/Rocket.Chat/programs/server/boot.js:464:7
Oct  4 09:48:30 chat rocketchat[29149]:     at Function.run (/opt/Rocket.Chat/programs/server/profile.js:280:14)
Oct  4 09:48:30 chat rocketchat[29149]:     at /opt/Rocket.Chat/programs/server/boot.js:463:13 {
Oct  4 09:48:30 chat rocketchat[29149]:   isClientSafe: true,
Oct  4 09:48:30 chat rocketchat[29149]:   error: "Can't find migration version 239",
Oct  4 09:48:30 chat rocketchat[29149]:   reason: undefined,
Oct  4 09:48:30 chat rocketchat[29149]:   details: undefined,
Oct  4 09:48:30 chat rocketchat[29149]:   errorType: 'Meteor.Error'
Oct  4 09:48:30 chat rocketchat[29149]: }

Note: https://rocket.chat/docs/contributing/reporting-issues#gathering-logs reports 404.
mongod.log

2021-10-04T08:15:59.672+0000 I COMMAND  [conn59] command rocketchat.rocketchat_message command: find { find: "rocketchat_message", filter: { $text: { $search: "https://app" }, t: { $ne: "rm" }, _hidden: { $ne: true }, rid: "MAEht8hjb74X38iLkum9B4QpXmWL474DmL" }, sort: { ts: -1 }, projection: { score: { $meta: "textScore" } }, limit: 30, returnKey: false, showRecordId: false, lsid: { id: UUID("72cef0c4-0c71-4296-ab5f-4a9d991a7b45") }, $clusterTime: { clusterTime: Timestamp(1633335353, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat", $readPreference: { mode: "secondaryPreferred" } } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:61836 docsExamined:123110 hasSortStage:1 cursorExhausted:1 numYields:964 nreturned:30 reslen:34270 locks:{ Global: { acquireCount: { r: 1932 } }, MMAPV1Journal: { acquireCount: { r: 965 } }, Database: { acquireCount: { r: 966 } }, Collection: { acquireCount: { R: 966 } } } protocol:op_msg 326ms
2021-10-04T09:16:57.752+0000 I NETWORK  [conn49] end connection 127.0.0.1:36234 (14 connections now open)
2021-10-04T09:16:57.752+0000 I NETWORK  [conn58] end connection 127.0.0.1:36272 (12 connections now open)
2021-10-04T09:16:57.752+0000 I NETWORK  [conn53] end connection 127.0.0.1:36246 (11 connections now open)
2021-10-04T09:16:57.752+0000 I NETWORK  [conn48] end connection 127.0.0.1:36232 (13 connections now open)
2021-10-04T09:16:57.752+0000 I NETWORK  [conn56] end connection 127.0.0.1:36266 (9 connections now open)
2021-10-04T09:16:57.752+0000 I NETWORK  [conn61] end connection 127.0.0.1:36278 (8 connections now open)
2021-10-04T09:16:57.752+0000 I NETWORK  [conn51] end connection 127.0.0.1:36242 (7 connections now open)
2021-10-04T09:16:57.753+0000 I NETWORK  [conn55] end connection 127.0.0.1:36264 (6 connections now open)
2021-10-04T09:16:57.753+0000 I NETWORK  [conn60] end connection 127.0.0.1:36276 (5 connections now open)
2021-10-04T09:16:57.753+0000 I NETWORK  [conn57] end connection 127.0.0.1:36268 (4 connections now open)
2021-10-04T09:16:57.753+0000 I NETWORK  [conn59] end connection 127.0.0.1:36274 (10 connections now open)
2021-10-04T09:16:57.753+0000 I NETWORK  [conn50] end connection 127.0.0.1:36240 (3 connections now open)
2021-10-04T09:16:57.858+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:33918 #62 (4 connections now open)
2021-10-04T09:16:57.899+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:33920 #63 (5 connections now open)
2021-10-04T09:16:57.987+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:33926 #64 (6 connections now open)
2021-10-04T09:16:57.989+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:33930 #65 (7 connections now open)
2021-10-04T09:16:57.999+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:33934 #66 (8 connections now open)
2021-10-04T09:16:58.122+0000 I COMMAND  [conn64] command rocketchat.rocketchat_statistics command: find { find: "rocketchat_statistics", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:286822356897 keysExamined:101 docsExamined:101 numYields:93 nreturned:101 reslen:423968 locks:{ Global: { acquireCount: { r: 188 } }, MMAPV1Journal: { acquireCount: { r: 94 } }, Database: { acquireCount: { r: 94 } }, Collection: { acquireCount: { R: 94 } }, Mutex: { acquireCount: { r: 93 } } } protocol:op_query 122ms
2021-10-04T09:16:58.199+0000 I NETWORK  [conn54] end connection 127.0.0.1:36248 (7 connections now open)
2021-10-04T09:16:58.974+0000 I COMMAND  [conn64] command rocketchat.rocketchat_statistics command: getMore { getMore: 286822356897, collection: "rocketchat_statistics", $db: "rocketchat" } originatingCommand: { find: "rocketchat_statistics", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:286822356897 keysExamined:4035 docsExamined:4035 numYields:715 nreturned:4034 reslen:16776505 locks:{ Global: { acquireCount: { r: 1432 } }, MMAPV1Journal: { acquireCount: { r: 716 } }, Database: { acquireCount: { r: 716 } }, Collection: { acquireCount: { R: 716 } }, Mutex: { acquireCount: { r: 715 } } } protocol:op_query 838ms
2021-10-04T09:16:59.042+0000 I COMMAND  [conn65] command rocketchat.rocketchat__trash command: find { find: "rocketchat__trash", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:315205418621 keysExamined:101 docsExamined:101 numYields:59 nreturned:101 reslen:6415469 locks:{ Global: { acquireCount: { r: 120 } }, MMAPV1Journal: { acquireCount: { r: 60 } }, Database: { acquireCount: { r: 60 } }, Collection: { acquireCount: { R: 60 } }, Mutex: { acquireCount: { r: 57 } } } protocol:op_query 139ms
2021-10-04T09:16:59.064+0000 I COMMAND  [conn66] command rocketchat.rocketchat_oembed_cache command: find { find: "rocketchat_oembed_cache", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:318199858488 keysExamined:101 docsExamined:101 numYields:37 nreturned:101 reslen:5197526 locks:{ Global: { acquireCount: { r: 76 } }, MMAPV1Journal: { acquireCount: { r: 38 } }, Database: { acquireCount: { r: 38 } }, Collection: { acquireCount: { R: 38 } }, Mutex: { acquireCount: { r: 37 } } } protocol:op_query 113ms
2021-10-04T09:16:59.335+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:16834 docsExamined:16834 numYields:1039 nreturned:16833 reslen:16777101 locks:{ Global: { acquireCount: { r: 2080 } }, MMAPV1Journal: { acquireCount: { r: 1040 } }, Database: { acquireCount: { r: 1040 } }, Collection: { acquireCount: { R: 1040 } }, Mutex: { acquireCount: { r: 1027 } } } protocol:op_query 1305ms
2021-10-04T09:16:59.577+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:15708 docsExamined:15708 numYields:194 nreturned:15708 reslen:16774453 locks:{ Global: { acquireCount: { r: 390 } }, MMAPV1Journal: { acquireCount: { r: 195 } }, Database: { acquireCount: { r: 195 } }, Collection: { acquireCount: { R: 195 } }, Mutex: { acquireCount: { r: 123 } } } protocol:op_query 206ms
2021-10-04T09:16:59.775+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:16418 docsExamined:16418 numYields:160 nreturned:16418 reslen:16773939 locks:{ Global: { acquireCount: { r: 322 } }, MMAPV1Journal: { acquireCount: { r: 161 } }, Database: { acquireCount: { r: 161 } }, Collection: { acquireCount: { R: 161 } }, Mutex: { acquireCount: { r: 57 } } } protocol:op_query 165ms
2021-10-04T09:17:01.905+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:16001 docsExamined:16001 numYields:143 nreturned:16001 reslen:16776953 locks:{ Global: { acquireCount: { r: 288 } }, MMAPV1Journal: { acquireCount: { r: 144 } }, Database: { acquireCount: { r: 144 } }, Collection: { acquireCount: { R: 144 } }, Mutex: { acquireCount: { r: 37 } } } protocol:op_query 200ms
2021-10-04T09:17:02.946+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:15344 docsExamined:15344 numYields:130 nreturned:15344 reslen:16771079 locks:{ Global: { acquireCount: { r: 262 } }, MMAPV1Journal: { acquireCount: { r: 131 } }, Database: { acquireCount: { r: 131 } }, Collection: { acquireCount: { R: 131 } }, Mutex: { acquireCount: { r: 21 } } } protocol:op_query 119ms
2021-10-04T09:17:03.738+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:15404 docsExamined:15404 numYields:126 nreturned:15404 reslen:16777285 locks:{ Global: { acquireCount: { r: 254 } }, MMAPV1Journal: { acquireCount: { r: 127 } }, Database: { acquireCount: { r: 127 } }, Collection: { acquireCount: { R: 127 } }, Mutex: { acquireCount: { r: 11 } } } protocol:op_query 129ms
2021-10-04T09:17:04.219+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:15719 docsExamined:15719 numYields:129 nreturned:15719 reslen:16736551 locks:{ Global: { acquireCount: { r: 260 } }, MMAPV1Journal: { acquireCount: { r: 130 } }, Database: { acquireCount: { r: 130 } }, Collection: { acquireCount: { R: 130 } }, Mutex: { acquireCount: { r: 14 } } } protocol:op_query 103ms
2021-10-04T09:17:04.895+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:14744 docsExamined:14744 numYields:121 nreturned:14744 reslen:16777066 locks:{ Global: { acquireCount: { r: 244 } }, MMAPV1Journal: { acquireCount: { r: 122 } }, Database: { acquireCount: { r: 122 } }, Collection: { acquireCount: { R: 122 } }, Mutex: { acquireCount: { r: 9 } } } protocol:op_query 107ms
2021-10-04T09:17:05.420+0000 I COMMAND  [conn63] command rocketchat.rocketchat_message command: getMore { getMore: 324700461149, collection: "rocketchat_message", $db: "rocketchat" } originatingCommand: { find: "rocketchat_message", hint: { _id: 1 }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "rocketchat" } planSummary: IXSCAN { _id: 1 } cursorid:324700461149 keysExamined:15492 docsExamined:15492 numYields:124 nreturned:15492 reslen:16776899 locks:{ Global: { acquireCount: { r: 250 } }, MMAPV1Journal: { acquireCount: { r: 125 } }, Database: { acquireCount: { r: 125 } }, Collection: { acquireCount: { R: 125 } }, Mutex: { acquireCount: { r: 6 } } } protocol:op_query 106ms
2021-10-04T09:17:15.604+0000 I NETWORK  [conn63] end connection 127.0.0.1:33920 (5 connections now open)
2021-10-04T09:17:15.604+0000 I NETWORK  [conn62] end connection 127.0.0.1:33918 (6 connections now open)
2021-10-04T09:17:15.605+0000 I NETWORK  [conn64] end connection 127.0.0.1:33926 (4 connections now open)
2021-10-04T09:17:15.605+0000 I NETWORK  [conn65] end connection 127.0.0.1:33930 (3 connections now open)
2021-10-04T09:17:15.605+0000 I NETWORK  [conn66] end connection 127.0.0.1:33934 (2 connections now open)
2021-10-04T09:17:38.187+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34076 #67 (3 connections now open)
2021-10-04T09:17:38.196+0000 I NETWORK  [conn67] received client metadata from 127.0.0.1:34076 conn67: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:38.202+0000 I NETWORK  [conn67] end connection 127.0.0.1:34076 (2 connections now open)
2021-10-04T09:17:38.203+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34078 #68 (3 connections now open)
2021-10-04T09:17:38.204+0000 I NETWORK  [conn68] received client metadata from 127.0.0.1:34078 conn68: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:38.213+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34080 #69 (4 connections now open)
2021-10-04T09:17:38.214+0000 I NETWORK  [conn69] received client metadata from 127.0.0.1:34080 conn69: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:38.751+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34084 #70 (5 connections now open)
2021-10-04T09:17:38.751+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34086 #71 (6 connections now open)
2021-10-04T09:17:38.754+0000 I NETWORK  [conn70] received client metadata from 127.0.0.1:34084 conn70: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:38.754+0000 I NETWORK  [conn71] received client metadata from 127.0.0.1:34086 conn71: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:41.442+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34106 #72 (7 connections now open)
2021-10-04T09:17:41.446+0000 I NETWORK  [conn72] received client metadata from 127.0.0.1:34106 conn72: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:41.452+0000 I NETWORK  [conn72] end connection 127.0.0.1:34106 (6 connections now open)
2021-10-04T09:17:41.453+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34108 #73 (7 connections now open)
2021-10-04T09:17:41.454+0000 I NETWORK  [conn73] received client metadata from 127.0.0.1:34108 conn73: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:41.458+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34110 #74 (8 connections now open)
2021-10-04T09:17:41.459+0000 I NETWORK  [conn74] received client metadata from 127.0.0.1:34110 conn74: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:49.871+0000 I COMMAND  [conn74] command local.oplog.rs command: find { find: "oplog.rs", filter: { ns: /^(?:rocketchat\.|admin\.\$cmd)/, op: { $in: [ "i", "u", "d" ] }, ts: { $gt: Timestamp(1633339058, 1) } }, returnKey: false, showRecordId: false, tailable: true, awaitData: true, lsid: { id: UUID("d99c38ec-629a-4df7-a4d1-63b3db241270") }, $clusterTime: { clusterTime: Timestamp(1633339058, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "local" } planSummary: COLLSCAN cursorid:442661477313 keysExamined:0 docsExamined:2318886 numYields:22051 nreturned:0 reslen:228 locks:{ Global: { acquireCount: { r: 44104 } }, MMAPV1Journal: { acquireCount: { r: 22052 } }, Database: { acquireCount: { r: 22052 } }, Mutex: { acquireCount: { r: 5810 } }, oplog: { acquireCount: { R: 22052 } } } protocol:op_msg 7038ms
2021-10-04T09:17:52.349+0000 I STORAGE  [conn70] createCollection: rocketchat.rocketchat_raw_imports with generated UUID: 8b5e2fdb-af9f-4e08-bcb9-37866e39504d
2021-10-04T09:17:52.371+0000 I INDEX    [conn70] build index on: rocketchat.rocketchat_raw_imports properties: { v: 2, key: { _updatedAt: 1 }, name: "_updatedAt_1", ns: "rocketchat.rocketchat_raw_imports" }
2021-10-04T09:17:52.373+0000 I INDEX    [conn70] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:17:52.375+0000 I INDEX    [conn70] build index done.  scanned 0 total records. 0 secs
2021-10-04T09:17:54.867+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34144 #75 (9 connections now open)
2021-10-04T09:17:54.939+0000 I NETWORK  [conn75] received client metadata from 127.0.0.1:34144 conn75: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:54.943+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34146 #76 (10 connections now open)
2021-10-04T09:17:54.944+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34148 #77 (11 connections now open)
2021-10-04T09:17:54.948+0000 I NETWORK  [conn76] received client metadata from 127.0.0.1:34146 conn76: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:54.948+0000 I NETWORK  [conn77] received client metadata from 127.0.0.1:34148 conn77: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:58.668+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34158 #78 (12 connections now open)
2021-10-04T09:17:58.668+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34160 #79 (13 connections now open)
2021-10-04T09:17:58.668+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34162 #80 (14 connections now open)
2021-10-04T09:17:58.669+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34164 #81 (15 connections now open)
2021-10-04T09:17:58.672+0000 I NETWORK  [conn78] received client metadata from 127.0.0.1:34158 conn78: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:58.672+0000 I NETWORK  [conn79] received client metadata from 127.0.0.1:34160 conn79: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:58.673+0000 I NETWORK  [conn80] received client metadata from 127.0.0.1:34162 conn80: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:17:58.673+0000 I NETWORK  [conn81] received client metadata from 127.0.0.1:34164 conn81: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:18:01.519+0000 I COMMAND  [conn76] CMD: drop rocketchat.rocketchat_raw_imports
2021-10-04T09:18:01.521+0000 I STORAGE  [conn76] dropCollection: rocketchat.rocketchat_raw_imports (8b5e2fdb-af9f-4e08-bcb9-37866e39504d) - renaming to drop-pending collection: rocketchat.system.drop.1633339081i1t73.rocketchat_raw_imports with drop optime { ts: Timestamp(1633339081, 1), t: 73 }
2021-10-04T09:18:01.521+0000 I STORAGE  [conn76] renameCollection: renaming collection 8b5e2fdb-af9f-4e08-bcb9-37866e39504d from rocketchat.rocketchat_raw_imports to rocketchat.system.drop.1633339081i1t73.rocketchat_raw_imports
2021-10-04T09:18:01.547+0000 I REPL     [replication-0] Completing collection drop for rocketchat.system.drop.1633339081i1t73.rocketchat_raw_imports with drop optime { ts: Timestamp(1633339081, 1), t: 73 } (notification optime: { ts: Timestamp(1633339081, 1), t: 73 })
2021-10-04T09:18:01.557+0000 I STORAGE  [replication-0] Finishing collection drop for rocketchat.system.drop.1633339081i1t73.rocketchat_raw_imports (8b5e2fdb-af9f-4e08-bcb9-37866e39504d).
2021-10-04T09:18:49.825+0000 I NETWORK  [conn81] end connection 127.0.0.1:34164 (14 connections now open)
2021-10-04T09:18:49.826+0000 I NETWORK  [conn80] end connection 127.0.0.1:34162 (13 connections now open)
2021-10-04T09:18:49.826+0000 I NETWORK  [conn78] end connection 127.0.0.1:34158 (12 connections now open)
2021-10-04T09:18:49.826+0000 I NETWORK  [conn77] end connection 127.0.0.1:34148 (11 connections now open)
2021-10-04T09:18:49.826+0000 I NETWORK  [conn75] end connection 127.0.0.1:34144 (10 connections now open)
2021-10-04T09:18:49.827+0000 I NETWORK  [conn76] end connection 127.0.0.1:34146 (9 connections now open)
2021-10-04T09:18:49.827+0000 I NETWORK  [conn73] end connection 127.0.0.1:34108 (8 connections now open)
2021-10-04T09:18:49.827+0000 I NETWORK  [conn70] end connection 127.0.0.1:34084 (7 connections now open)
2021-10-04T09:18:49.827+0000 I NETWORK  [conn71] end connection 127.0.0.1:34086 (6 connections now open)
2021-10-04T09:18:49.827+0000 I NETWORK  [conn69] end connection 127.0.0.1:34080 (5 connections now open)
2021-10-04T09:18:49.827+0000 I NETWORK  [conn79] end connection 127.0.0.1:34160 (4 connections now open)
2021-10-04T09:18:49.827+0000 I NETWORK  [conn68] end connection 127.0.0.1:34078 (3 connections now open)
2021-10-04T09:18:50.558+0000 I NETWORK  [conn74] end connection 127.0.0.1:34110 (2 connections now open)
2021-10-04T09:19:52.972+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34540 #82 (3 connections now open)
2021-10-04T09:19:52.978+0000 I NETWORK  [conn82] received client metadata from 127.0.0.1:34540 conn82: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:19:52.984+0000 I NETWORK  [conn82] end connection 127.0.0.1:34540 (2 connections now open)
2021-10-04T09:19:52.985+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34542 #83 (3 connections now open)
2021-10-04T09:19:52.986+0000 I NETWORK  [conn83] received client metadata from 127.0.0.1:34542 conn83: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:19:52.996+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34544 #84 (4 connections now open)
2021-10-04T09:19:52.997+0000 I NETWORK  [conn84] received client metadata from 127.0.0.1:34544 conn84: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:19:53.355+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34546 #85 (5 connections now open)
2021-10-04T09:19:53.355+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34548 #86 (6 connections now open)
2021-10-04T09:19:53.358+0000 I NETWORK  [conn85] received client metadata from 127.0.0.1:34546 conn85: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:19:53.359+0000 I NETWORK  [conn86] received client metadata from 127.0.0.1:34548 conn86: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:19:55.958+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34566 #87 (7 connections now open)
2021-10-04T09:19:55.962+0000 I NETWORK  [conn87] received client metadata from 127.0.0.1:34566 conn87: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:19:55.968+0000 I NETWORK  [conn87] end connection 127.0.0.1:34566 (6 connections now open)
2021-10-04T09:19:55.969+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34568 #88 (7 connections now open)
2021-10-04T09:19:55.970+0000 I NETWORK  [conn88] received client metadata from 127.0.0.1:34568 conn88: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:19:55.975+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34570 #89 (8 connections now open)
2021-10-04T09:19:55.976+0000 I NETWORK  [conn89] received client metadata from 127.0.0.1:34570 conn89: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:04.531+0000 I COMMAND  [conn89] command local.oplog.rs command: find { find: "oplog.rs", filter: { ns: /^(?:rocketchat\.|admin\.\$cmd)/, op: { $in: [ "i", "u", "d" ] }, ts: { $gt: Timestamp(1633339193, 1) } }, returnKey: false, showRecordId: false, tailable: true, awaitData: true, lsid: { id: UUID("a17bb6ae-9d7e-4b21-bc18-00f1c45ca77c") }, $clusterTime: { clusterTime: Timestamp(1633339193, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "local" } planSummary: COLLSCAN cursorid:442482563828 keysExamined:0 docsExamined:2312644 numYields:18182 nreturned:30 reslen:7873 locks:{ Global: { acquireCount: { r: 36366 } }, MMAPV1Journal: { acquireCount: { r: 18208 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 19941 } }, Database: { acquireCount: { r: 18183 } }, Mutex: { acquireCount: { r: 97 } }, oplog: { acquireCount: { R: 18183 }, acquireWaitCount: { R: 25 }, timeAcquiringMicros: { R: 2447 } } } protocol:op_msg 7154ms
2021-10-04T09:20:04.566+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34586 #90 (9 connections now open)
2021-10-04T09:20:04.566+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34588 #91 (10 connections now open)
2021-10-04T09:20:04.566+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34590 #92 (11 connections now open)
2021-10-04T09:20:04.566+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34592 #93 (12 connections now open)
2021-10-04T09:20:04.566+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34594 #94 (13 connections now open)
2021-10-04T09:20:04.566+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34596 #95 (14 connections now open)
2021-10-04T09:20:04.567+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:34598 #96 (15 connections now open)
2021-10-04T09:20:04.573+0000 I NETWORK  [conn90] received client metadata from 127.0.0.1:34586 conn90: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:04.574+0000 I NETWORK  [conn91] received client metadata from 127.0.0.1:34588 conn91: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:04.574+0000 I NETWORK  [conn92] received client metadata from 127.0.0.1:34590 conn92: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:04.575+0000 I NETWORK  [conn93] received client metadata from 127.0.0.1:34592 conn93: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:04.575+0000 I NETWORK  [conn94] received client metadata from 127.0.0.1:34594 conn94: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:04.576+0000 I NETWORK  [conn95] received client metadata from 127.0.0.1:34596 conn95: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:04.576+0000 I NETWORK  [conn96] received client metadata from 127.0.0.1:34598 conn96: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:20:08.033+0000 I STORAGE  [conn85] createCollection: rocketchat.rocketchat_raw_imports with generated UUID: 67a82c48-e2a8-47ec-80cb-19c8fee4da9e
2021-10-04T09:20:08.050+0000 I INDEX    [conn85] build index on: rocketchat.rocketchat_raw_imports properties: { v: 2, key: { _updatedAt: 1 }, name: "_updatedAt_1", ns: "rocketchat.rocketchat_raw_imports" }
2021-10-04T09:20:08.050+0000 I INDEX    [conn85] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:20:08.050+0000 I INDEX    [conn85] build index done.  scanned 0 total records. 0 secs
2021-10-04T09:20:14.395+0000 I INDEX    [conn96] build index on: rocketchat.rocketchat_banner properties: { v: 2, key: { platform: 1, startAt: 1, expireAt: 1, active: 1 }, name: "platform_1_startAt_1_expireAt_1_active_1", ns: "rocketchat.rocketchat_banner" }
2021-10-04T09:20:14.395+0000 I INDEX    [conn96] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:20:14.396+0000 I INDEX    [conn96] build index done.  scanned 0 total records. 0 secs
2021-10-04T09:20:14.941+0000 I COMMAND  [conn86] CMD: dropIndexes rocketchat.rocketchat_subscription
2021-10-04T09:20:15.201+0000 I SHARDING [conn96] Marking collection rocketchat.rocketchat_apps_packages.files as collection version: <unsharded>
2021-10-04T09:20:15.204+0000 I STORAGE  [conn94] createCollection: rocketchat.rocketchat_apps_packages.files with generated UUID: e3f5aa6f-22bd-4211-89f1-2ea5824f82cd
2021-10-04T09:20:15.215+0000 I INDEX    [conn94] build index on: rocketchat.rocketchat_apps_packages.files properties: { v: 2, key: { filename: 1, uploadDate: 1 }, name: "filename_1_uploadDate_1", ns: "rocketchat.rocketchat_apps_packages.files", background: false }
2021-10-04T09:20:15.215+0000 I INDEX    [conn94] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:20:15.215+0000 I INDEX    [conn94] build index done.  scanned 0 total records. 0 secs
2021-10-04T09:20:15.227+0000 I SHARDING [conn91] Marking collection rocketchat.rocketchat_apps_packages.chunks as collection version: <unsharded>
2021-10-04T09:20:15.228+0000 I STORAGE  [conn92] createCollection: rocketchat.rocketchat_apps_packages.chunks with generated UUID: d575f484-c88b-4850-a495-436441c53a44
2021-10-04T09:20:15.233+0000 I INDEX    [conn92] build index on: rocketchat.rocketchat_apps_packages.chunks properties: { v: 2, unique: true, key: { files_id: 1, n: 1 }, name: "files_id_1_n_1", ns: "rocketchat.rocketchat_apps_packages.chunks", background: false }
2021-10-04T09:20:15.234+0000 I INDEX    [conn92] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:20:15.234+0000 I INDEX    [conn92] build index done.  scanned 0 total records. 0 secs
2021-10-04T09:20:15.989+0000 I COMMAND  [conn95] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1633339215, 80), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { tcount: 1, tlm: 1 } keysExamined:367 docsExamined:367 numYields:30 reslen:170 locks:{ Global: { acquireCount: { r: 62 } }, MMAPV1Journal: { acquireCount: { r: 31 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 476 } }, Database: { acquireCount: { r: 31 } }, Collection: { acquireCount: { R: 31 } }, Mutex: { acquireCount: { r: 23 } } } protocol:op_msg 180ms
2021-10-04T09:20:20.491+0000 I COMMAND  [conn93] CMD: dropIndexes rocketchat.rocketchat_apps_logs
2021-10-04T09:20:20.504+0000 I INDEX    [conn92] build index on: rocketchat.rocketchat_apps_logs properties: { v: 2, key: { _updatedAt: 1 }, name: "_updatedAt_1", ns: "rocketchat.rocketchat_apps_logs", expireAfterSeconds: 2592000 }
2021-10-04T09:20:20.504+0000 I INDEX    [conn92] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:20:20.508+0000 I INDEX    [conn92] build index done.  scanned 182 total records. 0 secs
2021-10-04T09:20:21.023+0000 I COMMAND  [conn91] CMD: drop rocketchat.rocketchat_raw_imports
2021-10-04T09:20:21.023+0000 I STORAGE  [conn91] dropCollection: rocketchat.rocketchat_raw_imports (67a82c48-e2a8-47ec-80cb-19c8fee4da9e) - renaming to drop-pending collection: rocketchat.system.drop.1633339221i1t73.rocketchat_raw_imports with drop optime { ts: Timestamp(1633339221, 1), t: 73 }
2021-10-04T09:20:21.023+0000 I STORAGE  [conn91] renameCollection: renaming collection 67a82c48-e2a8-47ec-80cb-19c8fee4da9e from rocketchat.rocketchat_raw_imports to rocketchat.system.drop.1633339221i1t73.rocketchat_raw_imports
2021-10-04T09:20:21.119+0000 I REPL     [replication-0] Completing collection drop for rocketchat.system.drop.1633339221i1t73.rocketchat_raw_imports with drop optime { ts: Timestamp(1633339221, 1), t: 73 } (notification optime: { ts: Timestamp(1633339221, 10), t: 73 })
2021-10-04T09:20:21.125+0000 I STORAGE  [replication-0] Finishing collection drop for rocketchat.system.drop.1633339221i1t73.rocketchat_raw_imports (67a82c48-e2a8-47ec-80cb-19c8fee4da9e).
2021-10-04T09:27:01.784+0000 I QUERY    [clientcursormon] Cursor id 443945274335 timed out, idle since 2021-10-04T09:16:58.199+0000
2021-10-04T09:28:53.800+0000 I QUERY    [clientcursormon] Cursor id 442661477313 timed out, idle since 2021-10-04T09:18:50.558+0000
2021-10-04T09:47:44.910+0000 I NETWORK  [conn95] end connection 127.0.0.1:34596 (14 connections now open)
2021-10-04T09:47:44.911+0000 I NETWORK  [conn94] end connection 127.0.0.1:34594 (13 connections now open)
2021-10-04T09:47:44.911+0000 I NETWORK  [conn91] end connection 127.0.0.1:34588 (12 connections now open)
2021-10-04T09:47:44.911+0000 I NETWORK  [conn96] end connection 127.0.0.1:34598 (11 connections now open)
2021-10-04T09:47:44.912+0000 I NETWORK  [conn85] end connection 127.0.0.1:34546 (10 connections now open)
2021-10-04T09:47:44.912+0000 I NETWORK  [conn93] end connection 127.0.0.1:34592 (9 connections now open)
2021-10-04T09:47:44.912+0000 I NETWORK  [conn92] end connection 127.0.0.1:34590 (8 connections now open)
2021-10-04T09:47:44.912+0000 I NETWORK  [conn88] end connection 127.0.0.1:34568 (7 connections now open)
2021-10-04T09:47:44.912+0000 I NETWORK  [conn84] end connection 127.0.0.1:34544 (6 connections now open)
2021-10-04T09:47:44.913+0000 I NETWORK  [conn83] end connection 127.0.0.1:34542 (5 connections now open)
2021-10-04T09:47:44.913+0000 I NETWORK  [conn90] end connection 127.0.0.1:34586 (4 connections now open)
2021-10-04T09:47:44.913+0000 I NETWORK  [conn86] end connection 127.0.0.1:34548 (3 connections now open)
2021-10-04T09:47:45.594+0000 I NETWORK  [conn89] end connection 127.0.0.1:34570 (2 connections now open)
2021-10-04T09:48:07.362+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36558 #97 (3 connections now open)
2021-10-04T09:48:07.369+0000 I NETWORK  [conn97] received client metadata from 127.0.0.1:36558 conn97: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:07.376+0000 I NETWORK  [conn97] end connection 127.0.0.1:36558 (2 connections now open)
2021-10-04T09:48:07.377+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36560 #98 (3 connections now open)
2021-10-04T09:48:07.378+0000 I NETWORK  [conn98] received client metadata from 127.0.0.1:36560 conn98: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:07.387+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36562 #99 (4 connections now open)
2021-10-04T09:48:07.388+0000 I NETWORK  [conn99] received client metadata from 127.0.0.1:36562 conn99: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:07.932+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36564 #100 (5 connections now open)
2021-10-04T09:48:07.932+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36566 #101 (6 connections now open)
2021-10-04T09:48:07.935+0000 I NETWORK  [conn100] received client metadata from 127.0.0.1:36564 conn100: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:07.935+0000 I NETWORK  [conn101] received client metadata from 127.0.0.1:36566 conn101: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:10.662+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36574 #102 (7 connections now open)
2021-10-04T09:48:10.667+0000 I NETWORK  [conn102] received client metadata from 127.0.0.1:36574 conn102: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:10.673+0000 I NETWORK  [conn102] end connection 127.0.0.1:36574 (6 connections now open)
2021-10-04T09:48:10.674+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36576 #103 (7 connections now open)
2021-10-04T09:48:10.675+0000 I NETWORK  [conn103] received client metadata from 127.0.0.1:36576 conn103: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:10.681+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36578 #104 (8 connections now open)
2021-10-04T09:48:10.682+0000 I NETWORK  [conn104] received client metadata from 127.0.0.1:36578 conn104: { driver: { name: "nodejs", version: "3.6.9" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:10.888+0000 I INDEX    [conn100] build index on: rocketchat.rocketchat_subscription properties: { v: 2, key: { audioNotifications: 1 }, name: "audioNotifications_1", ns: "rocketchat.rocketchat_subscription", sparse: 1 }
2021-10-04T09:48:10.888+0000 I INDEX    [conn100] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:48:10.889+0000 I INDEX    [conn100] build index done.  scanned 529 total records. 0 secs
2021-10-04T09:48:18.955+0000 I COMMAND  [conn104] command local.oplog.rs command: find { find: "oplog.rs", filter: { ns: /^(?:rocketchat\.|admin\.\$cmd)/, op: { $in: [ "i", "u", "d" ] }, ts: { $gt: Timestamp(1633340883, 1) } }, returnKey: false, showRecordId: false, tailable: true, awaitData: true, lsid: { id: UUID("864dcea5-be98-4d83-8b62-7306ab925b49") }, $clusterTime: { clusterTime: Timestamp(1633340883, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "local" } planSummary: COLLSCAN cursorid:443545137430 keysExamined:0 docsExamined:2312266 numYields:18842 nreturned:30 reslen:7873 locks:{ Global: { acquireCount: { r: 37686 } }, MMAPV1Journal: { acquireCount: { r: 18857 } }, Database: { acquireCount: { r: 18843 } }, Mutex: { acquireCount: { r: 1200 } }, oplog: { acquireCount: { R: 18843 }, acquireWaitCount: { R: 14 }, timeAcquiringMicros: { R: 1338 } } } protocol:op_msg 6854ms
2021-10-04T09:48:19.234+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36614 #105 (9 connections now open)
2021-10-04T09:48:19.234+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36616 #106 (10 connections now open)
2021-10-04T09:48:19.234+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36618 #107 (11 connections now open)
2021-10-04T09:48:19.234+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36620 #108 (12 connections now open)
2021-10-04T09:48:19.235+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36622 #109 (13 connections now open)
2021-10-04T09:48:19.235+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36624 #110 (14 connections now open)
2021-10-04T09:48:19.235+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36626 #111 (15 connections now open)
2021-10-04T09:48:19.277+0000 I NETWORK  [conn105] received client metadata from 127.0.0.1:36614 conn105: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:19.277+0000 I NETWORK  [conn106] received client metadata from 127.0.0.1:36616 conn106: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:19.278+0000 I NETWORK  [conn107] received client metadata from 127.0.0.1:36618 conn107: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:19.278+0000 I NETWORK  [conn108] received client metadata from 127.0.0.1:36620 conn108: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:19.279+0000 I NETWORK  [conn109] received client metadata from 127.0.0.1:36622 conn109: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:19.279+0000 I NETWORK  [conn110] received client metadata from 127.0.0.1:36624 conn110: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:19.280+0000 I NETWORK  [conn111] received client metadata from 127.0.0.1:36626 conn111: { driver: { name: "nodejs", version: "3.6.6" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "5.4.0-1055-aws" }, platform: "'Node.js v12.18.3, LE (unified)" }
2021-10-04T09:48:22.747+0000 I STORAGE  [conn111] createCollection: rocketchat.rocketchat_raw_imports with generated UUID: f998a481-4af3-4e63-90d4-efdf38d82070
2021-10-04T09:48:22.752+0000 I INDEX    [conn111] build index on: rocketchat.rocketchat_raw_imports properties: { v: 2, key: { _updatedAt: 1 }, name: "_updatedAt_1", ns: "rocketchat.rocketchat_raw_imports" }
2021-10-04T09:48:22.752+0000 I INDEX    [conn111] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2021-10-04T09:48:22.752+0000 I INDEX    [conn111] build index done.  scanned 0 total records. 0 secs
2021-10-04T09:53:53.877+0000 I COMMAND  [LogicalSessionCacheRefresh] command config.$cmd command: update { update: "system.sessions", ordered: false, allowImplicitCollectionCreation: false, writeConcern: { w: "majority", wtimeout: 15000 }, $db: "config" } numYields:0 reslen:245 locks:{ Global: { acquireCount: { r: 20, w: 20 } }, MMAPV1Journal: { acquireCount: { w: 20 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 166 } }, Database: { acquireCount: { w: 20 } }, Collection: { acquireCount: { W: 10 } }, oplog: { acquireCount: { W: 10 } } } protocol:op_msg 105ms
2021-10-04T09:57:46.040+0000 I QUERY    [clientcursormon] Cursor id 442482563828 timed out, idle since 2021-10-04T09:47:45.594+0000

auth.log:
Oct 4 09:18:35 chat sudo: pam_unix(sudo:session): session closed for user root
Oct 4 09:18:48 chat sudo: ubuntu : TTY=pts/0 ; PWD=/home/ubuntu ; USER=root ; COMMAND=/usr/local/bin/rocketchatctl update
Oct 4 09:18:48 chat sudo: pam_unix(sudo:session): session opened for user root by ubuntu(uid=0)
@erickmff
Copy link

erickmff commented Oct 4, 2021

Same issue here!

@corrigac
Copy link
Author

corrigac commented Oct 4, 2021

Jury Rigged Temporary workaround if you have no backup / rollback path for a simple single server configuration.

  • stub the rocketchatctl so it runs again, (/usr/local/bin/rocketchatctl - get_rocketchat_current_version() substitute steps with current_rocketchat_version=3.0.18 )
  • re-run the rocketchatctl update
  • ^z the installer after you get to the healthcheck phase "Waiting up to...."
  • confirm rocketchat services are running.

@strasharo strasharo mentioned this issue Oct 4, 2021
Closed
@strasharo
Copy link

Thanks @corrigac , this resolved it for me, didn't have to ^z the installer, since it went straight to success:

Waiting up to 5 minutes for RocketChat server to be active ... 2
RocketChat server updated to latest version :)

Now it's running for me, previously it failed with this exception:
#23356

@m4z
Copy link

m4z commented Oct 5, 2021

See also RocketChat/install.sh#48

@sampaiodiego sampaiodiego mentioned this issue Oct 5, 2021
Merged
@geekgonecrazy
Copy link
Contributor

This has now been fixed in update of rocketchatctl. 🙏 should be able to use: rocketchatctl upgrade-rocketchatctl to get latest version of rocketchatctl which should now upgrade properly

@strasharo
Copy link

I confirm this is now resolved for me. 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
feat: rocketchatctl
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix update to Rocket.Chat 4.0 RocketChat/install.sh
6 participants
@geekgonecrazy @m4z @corrigac @strasharo @erickmff @sampaiodiego