rocketchat update to 6.5.3 fails on first run (migration step 303 to 304)

[rgoerner]

A strange error happened when migration is done from 6.4 latest branch to 6.5.3,

First start, migrations stucks on step 303 to 304:

Feb 4 08:33:28 rocketchat rocketchat[239232]: {"level":51,"time":"2024-02-04T07:33:28.150Z","pid":239232,"hostname":"rocketchat","name":"Migrations","msg":"Migrating from version 303 -> 304"}
Feb 4 08:33:28 rocketchat rocketchat[239232]: {"level":51,"time":"2024-02-04T07:33:28.150Z","pid":239232,"hostname":"rocketchat","name":"Migrations","msg":"Running up() on version 304(Drop wrong index from analytics collection)"}
Feb 4 08:33:28 rocketchat rocketchat[239232]: +----------------------------------------------------------------------+
Feb 4 08:33:28 rocketchat rocketchat[239232]: | ERROR! SERVER STOPPED |
Feb 4 08:33:28 rocketchat rocketchat[239232]: +----------------------------------------------------------------------+
Feb 4 08:33:28 rocketchat rocketchat[239232]: | |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Your database migration failed: |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Cannot read property 'finally' of undefined |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Please make sure you are running the latest version and try again. |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | If the problem persists, please contact support. |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | This Rocket.Chat version: 6.5.3 |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Database locked at version: 303 |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Database target version: 304 |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Commit: 726574c |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Date: Thu Jan 18 12:57:31 2024 +0000 |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Branch: HEAD |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | Tag: 6.5.3 |
Feb 4 08:33:28 rocketchat rocketchat[239232]: | |
Feb 4 08:33:28 rocketchat rocketchat[239232]: +----------------------------------------------------------------------+

After a full stop, and restart:

04T07:35:47.058Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 0/30. Trying again in 10 seconds."}
Feb 4 08:35:57 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:35:57.065Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 1/30. Trying again in 10 seconds."}
Feb 4 08:36:07 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:36:07.075Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 2/30. Trying again in 10 seconds."}
Feb 4 08:36:17 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:36:17.086Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 3/30. Trying again in 10 seconds."}
Feb 4 08:36:27 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:36:27.096Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 4/30. Trying again in 10 seconds."}
Feb 4 08:36:37 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:36:37.107Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 5/30. Trying again in 10 seconds."}
Feb 4 08:36:47 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:36:47.114Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 6/30. Trying again in 10 seconds."}
Feb 4 08:36:57 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:36:57.126Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 7/30. Trying again in 10 seconds."}
Feb 4 08:37:07 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:37:07.137Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 8/30. Trying again in 10 seconds."}
Feb 4 08:37:17 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:37:17.147Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 9/30. Trying again in 10 seconds."}
Feb 4 08:37:27 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:37:27.157Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 10/30. Trying again in 10 seconds."}
Feb 4 08:37:37 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:37:37.167Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 11/30. Trying again in 10 seconds."}
Feb 4 08:37:47 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:37:47.186Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 12/30. Trying again in 10 seconds."}
Feb 4 08:37:57 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:37:57.196Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 13/30. Trying again in 10 seconds."}
Feb 4 08:38:07 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:38:07.202Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 14/30. Trying again in 10 seconds."}
Feb 4 08:38:17 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:38:17.212Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 15/30. Trying again in 10 seconds."}
Feb 4 08:38:27 rocketchat rocketchat[239280]: {"level":40,"time":"2024-02-04T07:38:27.222Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Not migrating, control is locked. Attempt 16/30. Trying again in 10 seconds."}
Feb 4 08:38:37 rocketchat rocketchat[239280]: {"level":51,"time":"2024-02-04T07:38:37.234Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Migrating from version 303 -> 304"}
Feb 4 08:38:37 rocketchat rocketchat[239280]: {"level":51,"time":"2024-02-04T07:38:37.234Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Running up() on version 304(Drop wrong index from analytics collection)"}
Feb 4 08:38:37 rocketchat rocketchat[239280]: {"level":51,"time":"2024-02-04T07:38:37.243Z","pid":239280,"hostname":"rocketchat","name":"Migrations","msg":"Finished migrating."}

For me, this seems to be a kind of timeout, or some simular issue, on the migration script maybe. We never had such an issue before and I am wondering, if anyone else can confirm this.

[pbirkants]

Just encountered the same scenario. Stack trace for the failure:

TypeError: Cannot read property 'finally' of undefined
    at server/models/raw/BaseRaw.ts:96:29
    at /opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40
 => awaited here:
    at Function.Promise.await (/opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)
    at server/startup/migrations/v304.ts:20:3
    at /opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40
 => awaited here:
    at Function.Promise.await (/opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)
    at server/lib/migrations.ts:151:2
    at /opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40
 => awaited here:
    at Function.Promise.await (/opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)
    at server/lib/migrations.ts:257:6
    at /opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40
 => awaited here:
    at Function.Promise.await (/opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)
    at server/lib/migrations.ts:276:4
    at /opt/rocketchat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40

[santos525]

same problem here, after trying to upgrade from 6.4.8 to 6.5.3.

[janmuennich]

Encountered the same problem on three instances too.

[robinreinhardt]

Encountered the same problem

[ziorufus]

Any news about that? I have the same issue (anyway, I managed to update it after a couple of attempts).

[haary]

Same here when upgrading from 6.4 to 6.6.0, using Docker.

[bleomycin]

This is a real problem especially with RC complaining they will be dropping support for 6.4.x soon. What are we supposed to do?

[santos525]

I managed to upgrade my installation. I simply dropped the index of rocketchat_analytics. the error above indicates that "Running up() on version 304(Drop wrong index from analytics collection)"}
connect to mongodb
use rocketchat
db.rocketchat_analytics.dropIndexes()

then start rocketchat. The Index gets regenerated at startup.

[pjv]

I am running RC via docker. I tried updating from 6.4.9 directly to 6.5.3 and had the same problem. I just stopped the docker containers, changed my compose file to instead update to 6.5.0, brought the stack up which updated fine to 6.5.0, then immediately updated again to 6.5.3 which worked fine from 6.5.0.

The level of support from RC developers demonstrated in the responses in this issue is why I will soon be updating from RC 6.X to another open source group chat. Can’t wait to get that done.

[DRKMDMZ]

I am running RC via docker. I tried updating from 6.4.9 directly to 6.5.3 and had the same problem. I just stopped the docker containers, changed my compose file to instead update to 6.5.0, brought the stack up which updated fine to 6.5.0, then immediately updated again to 6.5.3 which worked fine from 6.5.0.

Thanks for this! Worked here too.

[TBG-FR]

I am running RC via docker. I tried updating from 6.4.9 directly to 6.5.3 and had the same problem. I just stopped the docker containers, changed my compose file to instead update to 6.5.0, brought the stack up which updated fine to 6.5.0, then immediately updated again to 6.5.3 which worked fine from 6.5.0.

The level of support from RC developers demonstrated in the responses in this issue is why I will soon be updating from RC 6.X to another open source group chat. Can’t wait to get that done.

Same here, migration from 6.4.7 to 6.6.1, using the 6.5.0 as intermediate solved it.

I totally agree with you, and I will also add that the choices made by the team (pushing everyone to cloud subscriptions) these last months are pushing a lot of people towards alternatives to RocketChat !

[pjv]

I totally agree with you, and I will also add that the choices made by the team (pushing everyone to cloud subscriptions) these last months are pushing a lot of people towards alternatives to RocketChat !

I get paid to write code. I have nothing whatsoever against getting paid for writing or maintaining code. I am totally grateful that I can get paid to write code and I have nothing but positive feelings about people getting paid to write code. I specifically disagree with people who think all software should be “free” - as in nobody gets paid to write it.

It’s 100% OK with me if someone wants to create a commercial product and sell licenses / subscriptions / etc. to customers for its use. It’s also 100% OK with me if someone wants to create an open source project and find a way to monetize their contributions and consulting for its use. There are plenty of examples out there.

What is absolutely not OK with me, and why I am currently trialing solutions other than RC and will be moving away from it ASAP, is taking an open source project that many people have invested in creating solutions around, and that many people have contributed bug reports and patches to, and then suddenly changing the rules of its usage by arbitrarily deciding what constitutes “value added” services that were once freely bundled with the project and without which the project is not a viable solution and limiting the usability of those “value added” services to some “commercial trial” number of seats.

That’s just not OK and I can’t trust a development team who makes those kind of choices.

[ggazzo]

sorry the delay folks. plz try 6.5.5 or 6.6.6