RocketChat / RocketChat/Rocket.Chat

Restarting server takes ages and stuck in the past - runs migration for no reason, message logs from two months ago

Open
#24,876 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
TypeScript
Stars
46.1k
Forks
13.9k
Avg merge
3d 3h
Merged PRs (30d)
130

Description

It's been a while, hope everyone is well. Our server may not be...

Description:

Restarting our RC (Docker) server process usually takes around a minute. Suddenly it takes around ten minutes, which is very strange, and there is strange behaviour in the logs, it seems confused about what migration level it's at, and old messages are repeated.

Steps to reproduce:

docker-compose restart

Expected behavior:

Restarts within around a minute, maybe two.

Actual behavior:

See the logs below, restart done on 2022-03-18. After the restart, messages include: Migrating from version 249 -> 252 and there is a slew of messages from 2022-01-24 onwards in date order until it catches up with today.

Server Setup Information:
  • Version of Rocket.Chat Server: 4.3.2
  • Operating System: Ubuntu
  • Deployment Method: Docker
  • Number of Running Instances: 1
  • DB Replicaset Oplog: It's been a must for a while
  • NodeJS Version: 12.22.8
  • MongoDB Version: 4.0.27
Additional context

Let me know if I need to add any more information. Would like to upgrade Mongo and RC but currently not comfortable with trying to upgrade anything.

Relevant logs:
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-03-18T16:54:15.558Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","method":"getRoomRoles","userId":"fzrJwtPJ7GZ3eKeoZ","userAgent":"Mozilla/5.0 (W
indows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.74 Safari/537.36","remoteIP":null,"instanceId":"drMhCaKhj5pGJHGCi"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-03-18T16:54:16.508Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","method":"getMessages","userId":"fzrJwtPJ7GZ3eKeoZ","userAgent":"Mozilla/5.0 (Wi
ndows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.74 Safari/537.36","remoteIP":null,"instanceId":"drMhCaKhj5pGJHGCi"}
Gracefully stopping... (press Ctrl+C again to force)
Stopping rocketchat_rocketchat_1 ... ^M
rocketchat_db_1 is up-to-date
rocketchat_rocketchat_1 is up-to-date
Attaching to rocketchat_rocketchat_1
^[[36mrocketchat_1          |^[[0m LocalStore: store created at
^[[36mrocketchat_1          |^[[0m LocalStore: store created at
^[[36mrocketchat_1          |^[[0m LocalStore: store created at
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:39.438Z","pid":1,"hostname":"d20bb3e2646f","name":"System","msg":"Updating process.env.MAIL_URL"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:39.699Z","pid":1,"hostname":"d20bb3e2646f","name":"System","msg":"Setting default file store to AmazonS3"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:42.160Z","pid":1,"hostname":"d20bb3e2646f","name":"Federation","section":"Setup","msg":"Federation is disabled"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:44.334Z","pid":1,"hostname":"d20bb3e2646f","name":"CAS","msg":"Disabling CAS login service"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:44.641Z","pid":1,"hostname":"d20bb3e2646f","name":"rocketchat:theme","stop_rendering":80}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:45.155Z","pid":1,"hostname":"d20bb3e2646f","name":"Search Logger","msg":"create search provider defaultProvider"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:45.178Z","pid":1,"hostname":"d20bb3e2646f","name":"Search Logger","msg":"create search provider chatpalProvider"}
^[[36mrocketchat_1          |^[[0m {"level":51,"time":"2022-01-24T11:23:45.871Z","pid":1,"hostname":"d20bb3e2646f","name":"Migrations","msg":"Migrating from version 249 -> 252"}
^[[36mrocketchat_1          |^[[0m {"level":51,"time":"2022-01-24T11:23:45.872Z","pid":1,"hostname":"d20bb3e2646f","name":"Migrations","msg":"Running up() on version 250"}
^[[36mrocketchat_1          |^[[0m {"level":51,"time":"2022-01-24T11:23:45.877Z","pid":1,"hostname":"d20bb3e2646f","name":"Migrations","msg":"Running up() on version 251"}
^[[36mrocketchat_1          |^[[0m {"level":51,"time":"2022-01-24T11:23:45.883Z","pid":1,"hostname":"d20bb3e2646f","name":"Migrations","msg":"Running up() on version 252"}
^[[36mrocketchat_1          |^[[0m {"level":51,"time":"2022-01-24T11:23:45.898Z","pid":1,"hostname":"d20bb3e2646f","name":"Migrations","msg":"Finished migrating."}
^[[36mrocketchat_1          |^[[0m ufs: temp directory created at "/tmp/ufs"
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.229Z","pid":1,"hostname":"d20bb3e2646f","name":"SAUMonitor","msg":"[aggregate] - Start Cron."}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.349Z","pid":1,"hostname":"d20bb3e2646f","name":"EmailInbox","msg":"Clearing old email inbox registrations"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.377Z","pid":1,"hostname":"d20bb3e2646f","name":"EmailInbox","msg":"Configured a total of 0 inboxes"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.419Z","pid":1,"hostname":"d20bb3e2646f","name":"CROWD","msg":"Disabling CROWD Background Sync"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.420Z","pid":1,"hostname":"d20bb3e2646f","name":"System","msg":"Using GridFS for custom sounds storage"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.421Z","pid":1,"hostname":"d20bb3e2646f","name":"System","msg":"Using GridFS for custom emoji storage"}
^[[36mrocketchat_1          |^[[0m Loaded the Apps Framework and loaded a total of 2 Apps!
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.832Z","pid":1,"hostname":"d20bb3e2646f","name":"VersionCheck","msg":"Checking for version updates"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.904Z","pid":1,"hostname":"d20bb3e2646f","name":"StreamBroadcast","msg":"startStreamBroadcast"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.912Z","pid":1,"hostname":"d20bb3e2646f","name":"StreamBroadcast","section":"Auth","msg":"prevent self connect","instance":"undefined:300
0"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.913Z","pid":1,"hostname":"d20bb3e2646f","name":"StreamBroadcast","section":"Auth","msg":"prevent self connect","instance":"undefined:300
0"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.949Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"Apps-Engine:check\" next run @Tue Jan 25 2022 04:00:00 GM
T+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.950Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"version_check\" next run @Tue Jan 25 2022 02:00:00 GMT+00
00 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.952Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"Cleanup OEmbed cache\" next run @Tue Jan 25 2022 02:24:00
 GMT+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.954Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"Generate and save statistics\" next run @Mon Jan 24 2022
12:12:00 GMT+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.955Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"NPS\" next run @Tue Jan 25 2022 03:09:00 GMT+0000 (Coordi
nated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.956Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"Cloud Workspace Sync\" next run @Mon Jan 24 2022 12:00:00
 GMT+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.957Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"aggregate-sessions\" next run @Tue Jan 25 2022 02:00:00 G
MT+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.958Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"Generate download files for user data\" next run @Mon Jan
 24 2022 11:24:00 GMT+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.959Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"Remove users from Token Channels\" next run @Mon Jan 24 2
022 12:00:00 GMT+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m {"level":30,"time":"2022-01-24T11:23:46.960Z","pid":1,"hostname":"d20bb3e2646f","name":"SyncedCron","msg":"Scheduled \"Livechat Agent Activity Monitor\" next run @Tue Jan 25 20
22 00:00:00 GMT+0000 (Coordinated Universal Time)"}
^[[36mrocketchat_1          |^[[0m +--------------------------------------------------------+
^[[36mrocketchat_1          |^[[0m |                     SERVER RUNNING                     |
^[[36mrocketchat_1          |^[[0m +--------------------------------------------------------+
^[[36mrocketchat_1          |^[[0m |                                                        |
^[[36mrocketchat_1          |^[[0m |  Rocket.Chat Version: 4.3.2                            |
^[[36mrocketchat_1          |^[[0m |       NodeJS Version: 12.22.8 - x64                    |
^[[36mrocketchat_1          |^[[0m |      MongoDB Version: 4.0.27                           |
^[[36mrocketchat_1          |^[[0m |       MongoDB Engine: mmapv1                           |
^[[36mrocketchat_1          |^[[0m |             Platform: linux                            |
^[[36mrocketchat_1          |^[[0m |         Process Port: 3000                             |
^[[36mrocketchat_1          |^[[0m |             Site URL: MUNGED
^[[36mrocketchat_1          |^[[0m |     ReplicaSet OpLog: Enabled                          |
^[[36mrocketchat_1          |^[[0m |          Commit Hash: 4e8ba1542d                       |
^[[36mrocketchat_1          |^[[0m |        Commit Branch: HEAD                             |
^[[36mrocketchat_1          |^[[0m |                                                        |
^[[36mrocketchat_1          |^[[0m +--------------------------------------------------------+
^[[36mrocketchat_1          |^[[0m +----------------------------------------------------------------------+
^[[36mrocketchat_1          |^[[0m |                              DEPRECATION                             |
^[[36mrocketchat_1          |^[[0m +----------------------------------------------------------------------+
^[[36mrocketchat_1          |^[[0m |                                                                      |
^[[36mrocketchat_1          |^[[0m |  YOUR CURRENT MONGODB VERSION (4.0.27) IS DEPRECATED.                |
^[[36mrocketchat_1          |^[[0m |  IT WILL NOT BE SUPPORTED ON ROCKET.CHAT VERSION 5.0.0 AND GREATER,  |
^[[36mrocketchat_1          |^[[0m |  PLEASE UPGRADE MONGODB TO VERSION 4.2 OR GREATER                    |
^[[36mrocketchat_1          |^[[0m |                                                                      |
^[[36mrocketchat_1          |^[[0m +----------------------------------------------------------------------+
^[[36mrocketchat_1          |^[[0m Warning: language  is not supported in this project, fallback language (en)
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:47.779Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":null,"userAgent":"Mozilla/5.0 (Windows NT 10.0; Win6
4; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:47.808Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":"BWk8jxfcqwTfMK9qc","userAgent":"Mozilla/5.0 (Window
s NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:47.880Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":null,"userAgent":"Mozilla/5.0 (Windows NT 10.0; Win6
4; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:47.909Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":"9WRnddBEpvd3E4pTJ","userAgent":"Mozilla/5.0 (Window
s NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.173Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":null,"userAgent":"Mozilla/5.0 (Windows NT 10.0; Win6
4; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.211Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":"XZEiRdgHgY6oLttoo","userAgent":"Mozilla/5.0 (Window
s NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.338Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","method":"loadMissedMessages","userId":"BWk8jxfcqwTfMK9qc","userAgent":"Mozilla/
5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.455Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","method":"loadMissedMessages","userId":"BWk8jxfcqwTfMK9qc","userAgent":"Mozilla/
5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.477Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","method":"loadMissedMessages","userId":"BWk8jxfcqwTfMK9qc","userAgent":"Mozilla/
5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.482Z","pid":1,"hostname":"d20bb3e2646f","name":"API","method":"GET","url":"/api/v1/me","userId":"BWk8jxfcqwTfMK9qc","userAgent":"Mozilla
/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36","host":"MUNGED","referer":"https://MUNGED/direct/BWk8jxfcqwTfMK9qcqJ
hr9sszFxjsXjdcc/thread","remoteIP":"86.22.248.82","status":200,"responseTime":31}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.505Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":null,"userAgent":"Mozilla/5.0 (Windows NT 10.0; Win6
4; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.539Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","publication":null,"userId":"sQHrBNdnH9r7bHXHy","userAgent":"Mozilla/5.0 (Window
s NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.746Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","method":"loadMissedMessages","userId":"9WRnddBEpvd3E4pTJ","userAgent":"Mozilla/
5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}
^[[36mrocketchat_1          |^[[0m {"level":35,"time":"2022-01-24T11:23:48.763Z","pid":1,"hostname":"d20bb3e2646f","name":"Meteor","method":"loadMissedMessages","userId":"9WRnddBEpvd3E4pTJ","userAgent":"Mozilla/
5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36","remoteIP":null,"instanceId":"X4eMsxrgjYKdrkpf4"}

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by reproducing the issue with docker-compose restart on the reported Rocket.Chat, MongoDB, and Node.js versions, then inspect the startup and migration logs for the old timestamps and migration replay. Done means the server restarts within the expected time without replaying old messages or unnecessarily running migrations.

Written by the indexing model from the issue text.

Assessment

Tech stack
docker, mongodb, node.js
Domain
backend, databases, devops
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.