Ghost migration fails

Hi

I updated my ghost instance and the migration failed. There were multiple problems and I updated my node version in the mean time.

Previous version: 4.22.1

Update to 4.40

I had been using v14.17.3

Current instance uses v16.14.2

ghosthost@vm:/var/www/tafkasworld$ nvm --version
0.39.1
ghosthost@vm:/var/www/tafkasworld$ npm --version
8.5.0
ghosthost@vm:/var/www/tafkasworld$ node --version
v16.14.2

ghosthost@vm/var/www/tafkasworld$ ghost update --rollback --verbose
[11:57:30] Checking for Ghost-CLI updates [started]
[11:57:30] Checking for Ghost-CLI updates [completed]
[11:57:30] Ensuring correct ~/.config folder ownership [started]
[11:57:30] Ensuring correct ~/.config folder ownership [completed]

Love open source? We’re hiring Node.js Engineers to work on Ghost full-time.
https://careers.ghost.org/product-engineer-node-js

+ sudo systemctl is-active ghost_tafka-net
[11:57:30] Checking system Node.js version [started]
[11:57:30] Checking system Node.js version - found v16.14.2 [title changed]
[11:57:30] Checking system Node.js version - found v16.14.2 [completed]
[11:57:30] Ensuring user is not logged in as ghost user [started]
[11:57:30] Ensuring user is not logged in as ghost user [completed]
[11:57:30] Checking if logged in user is directory owner [started]
[11:57:30] Checking if logged in user is directory owner [completed]
[11:57:30] Checking current folder permissions [started]
[11:57:30] Checking current folder permissions [completed]
[11:57:30] Checking folder permissions [started]
[11:57:30] Checking folder permissions [completed]
[11:57:30] Checking file permissions [started]
[11:57:31] Checking file permissions [completed]
[11:57:31] Checking content folder ownership [started]
[11:57:31] Checking content folder ownership [completed]
[11:57:31] Checking memory availability [started]
[11:57:31] Checking memory availability [completed]
[11:57:31] Checking free space [started]
[11:57:31] Checking free space [completed]
βœ” Checking for available migrations
βœ” Checking for latest Ghost version
[11:57:31] Fetching release notes [started]
[11:57:31] Fetched release notes [title changed]

# 4.40.0

* πŸ› Fixed member "last seen at" data not being returned in the API - Kevin Ansfield
* πŸ› Fixed post access in the get helper (#14282) - Fabien 'egg' O'Carroll
* πŸ› Fixed duplicate email open rate column when filtering members by open rate - Kevin Ansfield
* πŸ› Fixed slow loading and high memory usage of members list screen - Kevin Ansfield
* πŸ› Fixed scheduled date/time inputs not being focusable when used from post preview modal - Kevin Ansfield

---

View the changelogs for full details:
* Ghost - https://github.com/tryghost/ghost/compare/v4.39.1...v4.40.0
* Admin - https://github.com/tryghost/admin/compare/v4.39.1...v4.40.0

πŸͺ„ Love open source? We're hiring [Node.js Engineers](https://careers.ghost.org/product-engineer-node-js) to work on Ghost full-time

[11:57:31] Fetched release notes [completed]
[11:57:31] Downloading and updating Ghost [started]
[11:57:31] Downloading and updating Ghost [skipped]
[11:57:31] Rolling back database migrations [started]
+ sudo /var/www/tafkasworld/current/node_modules/.bin/knex-migrator-rollback --force --v 4.40.0 --mgpath /var/www/tafkasworld/current
[11:57:31] Rolling back database migrations [failed]
[11:57:31] β†’ The database migration in Ghost encountered an error.
A ProcessError occurred.

Message: The database migration in Ghost encountered an error.
Help: https://ghost.org/docs/faq/
Suggestion: ghost update --rollback
--------------- stderr ---------------
/usr/bin/env: β€˜node’: No such file or directory


Debug Information:
    OS: Ubuntu, v20.04.4 LTS
    Node Version: v16.14.2
    Ghost Version: 4.40.0
    Ghost-CLI Version: 1.18.2
    Environment: production
    Command: 'ghost update --rollback --verbose'

journalctl -u ghost_deployment.service

I tried this fix on the database side: Migration failed in latest version Β· Issue #288 Β· docker-library/ghost Β· GitHub

SET PERSIST default_collation_for_utf8mb4 = utf8mb4_general_ci;

Even though i read this is necessary if mysql version is 5!
But my mysql version is mysql Ver 8.0.28-0ubuntu0.20.04.3 for Linux on x86_64 ((Ubuntu))

Mar 18 16:58:56  systemd[1]: Started Ghost systemd service for blog: .
Mar 18 16:58:57  node[18073]: - Inspecting operating system
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] INFO Ghost is running in production...
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] INFO Your site is now available on https:///
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] INFO Ctrl+C to shut down
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Tries: 0
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Retrying...
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Tries: 1
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Retrying...
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Tries: 2
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Retrying...
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:58:58  node[18102]: [2022-03-18 16:58:58] INFO Ghost server started in 1.192s
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Database state requires migration.
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Creating database backup
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Database backup written to: /var/www/tafkasworld/content/data/tafkasworld.ghost.2022-03-18-16-58-59.json
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Running migrations.
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN No Offers found needing truncation
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Adding products.type column
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Adding tier "Free"
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Looking for duplicate offer redemptions.
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO No duplicate offer redemptions found.
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Adding products.active column
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Adding products.welcome_page_url column
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Adding table: posts_products
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Rolling back: alter table `posts_products` add constraint `posts_products_post_id_foreign` foreign key (`post_id`) references `posts` (`id`) on delete CASCADE - Referencing colu>
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Dropping table: posts_products
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Removing products.welcome_page_url column
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Removing products.active column
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Not recreating duplicate offer redemptions
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Removing free tier
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Removing products.type column
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] INFO Rollback was successful.
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] ERROR alter table `posts_products` add constraint `posts_products_post_id_foreign` foreign key (`post_id`) references `posts` (`id`) on delete CASCADE - Referencing column 'post_id' >
Mar 18 16:58:59  node[18102]: 
Mar 18 16:58:59  node[18102]: alter table `posts_products` add constraint `posts_products_post_id_foreign` foreign key (`post_id`) references `posts` (`id`) on delete CASCADE - Referencing column 'post_id' and referenced column 'id' i>
Mar 18 16:58:59  node[18102]: {"config":{"transaction":false},"name":"2022-01-20-05-55-add-post-products-table.js"}
Mar 18 16:58:59  node[18102]: "Error occurred while executing the following migration: 2022-01-20-05-55-add-post-products-table.js"
Mar 18 16:58:59  node[18102]: Error ID:
Mar 18 16:58:59  node[18102]:     300
Mar 18 16:58:59  node[18102]: ----------------------------------------
Mar 18 16:58:59  node[18102]: MigrationScriptError: alter table `posts_products` add constraint `posts_products_post_id_foreign` foreign key (`post_id`) references `posts` (`id`) on delete CASCADE - Referencing column 'post_id' and re>
Mar 18 16:58:59  node[18102]:     at DatabaseStateManager.makeReady (/var/www/tafkasworld/versions/4.40.0/core/server/data/db/state-manager.js:95:32)
Mar 18 16:58:59  node[18102]:     at MigrationScriptError.KnexMigrateError (/var/www/tafkasworld/versions/4.40.0/node_modules/knex-migrator/lib/errors.js:7:26)
Mar 18 16:58:59  node[18102]:     at new MigrationScriptError (/var/www/tafkasworld/versions/4.40.0/node_modules/knex-migrator/lib/errors.js:25:26)
Mar 18 16:58:59  node[18102]:     at /var/www/tafkasworld/versions/4.40.0/node_modules/knex-migrator/lib/index.js:1032:19
Mar 18 16:58:59  node[18102]:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
Mar 18 16:58:59  node[18102]: Error: alter table `posts_products` add constraint `posts_products_post_id_foreign` foreign key (`post_id`) references `posts` (`id`) on delete CASCADE - Referencing column 'post_id' and referenced column>
Mar 18 16:58:59  node[18102]:     at Packet.asError (/var/www/tafkasworld/versions/4.40.0/node_modules/mysql2/lib/packets/packet.js:728:17)
Mar 18 16:58:59  node[18102]:     at Query.execute (/var/www/tafkasworld/versions/4.40.0/node_modules/mysql2/lib/commands/command.js:29:26)
Mar 18 16:58:59  node[18102]:     at Connection.handlePacket (/var/www/tafkasworld/versions/4.40.0/node_modules/mysql2/lib/connection.js:456:32)
Mar 18 16:58:59  node[18102]:     at PacketParser.onPacket (/var/www/tafkasworld/versions/4.40.0/node_modules/mysql2/lib/connection.js:85:12)
Mar 18 16:58:59  node[18102]:     at PacketParser.executeStart (/var/www/tafkasworld/versions/4.40.0/node_modules/mysql2/lib/packet_parser.js:75:16)
Mar 18 16:58:59  node[18102]:     at Socket.<anonymous> (/var/www/tafkasworld/versions/4.40.0/node_modules/mysql2/lib/connection.js:92:25)
Mar 18 16:58:59  node[18102]:     at Socket.emit (node:events:526:28)
Mar 18 16:58:59  node[18102]:     at addChunk (node:internal/streams/readable:315:12)
Mar 18 16:58:59  node[18102]:     at readableAddChunk (node:internal/streams/readable:289:9)
Mar 18 16:58:59  node[18102]:     at Socket.Readable.push (node:internal/streams/readable:228:10)
Mar 18 16:58:59  node[18102]:     at TCP.onStreamRead (node:internal/stream_base_commons:190:23)
Mar 18 16:58:59  node[18102]: 
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Ghost is shutting down
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Tries: 0
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Retrying...
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Ghost has shut down
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Your site is now offline
Mar 18 16:58:59  node[18102]: [2022-03-18 16:58:59] WARN Ghost was running for a few seconds
Mar 18 16:59:00  node[18073]: /usr/lib/node_modules/ghost-cli/lib/process-manager.js:46
Mar 18 16:59:00  node[18073]:         throw error;
Mar 18 16:59:00  node[18073]:         ^
Mar 18 16:59:00  node[18073]: {
Mar 18 16:59:00  node[18073]:   message: "Ghost was able to start, but errored during boot with: alter table `posts_products` add constraint `posts_products_post_id_foreign` foreign key (`post_id`) references `posts` (`id`) on delete >
Mar 18 16:59:00  node[18073]: }
Mar 18 16:59:00  systemd[1]: ghost_.service: Main process exited, code=exited, status=1/FAILURE
Mar 18 16:59:00  systemd[1]: ghost_.service: Failed with result 'exit-code'.
Mar 18 16:59:01  systemd[1]: ghost_.service: Scheduled restart job, restart counter is at 34.
Mar 18 16:59:01  systemd[1]: Stopped Ghost systemd service for blog: .
Mar 18 16:59:01  systemd[1]: Started Ghost systemd service for blog: .
Mar 18 16:59:01  node[18127]: - Inspecting operating system
Mar 18 16:59:02  node[18156]: [2022-03-18 16:59:02] INFO Ghost is running in production...
Mar 18 16:59:02  node[18156]: [2022-03-18 16:59:02] INFO Your site is now available on https:///
Mar 18 16:59:02  node[18156]: [2022-03-18 16:59:02] INFO Ctrl+C to shut down
Mar 18 16:59:02  node[18156]: [2022-03-18 16:59:02] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:59:02  node[18156]: [2022-03-18 16:59:02] WARN Tries: 0
Mar 18 16:59:02  node[18156]: [2022-03-18 16:59:02] WARN Retrying...
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Tries: 1
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Retrying...
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Tries: 2
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Retrying...
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] INFO Ghost server started in 1.417s
Mar 18 16:59:03  node[18156]: [2022-03-18 16:59:03] WARN Database state requires migration.
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Creating database backup
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Database backup written to: /var/www/tafkasworld/content/data/tafkasworld.ghost.2022-03-18-16-59-04.json
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Running migrations.
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] WARN No Offers found needing truncation
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Adding products.type column
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Adding tier "Free"
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Looking for duplicate offer redemptions.
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO No duplicate offer redemptions found.
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Adding products.active column
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Adding products.welcome_page_url column
Mar 18 16:59:04  systemd[1]: Stopping Ghost systemd service for blog: ...
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] WARN Ghost is shutting down
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] WARN Ghost has shut down
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] WARN Your site is now offline
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] WARN Ghost was running for a few seconds
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Adding table: posts_products
Mar 18 16:59:04  node[18156]: [2022-03-18 16:59:04] INFO Rolling back: alter table `posts_products` add constraint `posts_products_post_id_foreign` foreign key (`post_id`) references `posts` (`id`) on delete CASCADE - Referencing colu>
Mar 18 16:59:04  systemd[1]: ghost_.service: Succeeded.
Mar 18 16:59:04  systemd[1]: Stopped Ghost systemd service for blog: .
Mar 18 17:02:30  systemd[1]: Started Ghost systemd service for blog: .
Mar 18 17:02:31  node[18291]: - Inspecting operating system
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] INFO Ghost is running in production...
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] INFO Your site is now available on https:///
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] INFO Ctrl+C to shut down
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Tries: 0
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Retrying...
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Tries: 1
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Retrying...
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Tries: 2
Mar 18 17:02:32  node[18330]: [2022-03-18 17:02:32] WARN Retrying...
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] INFO Ghost server started in 1.493s
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] ERROR Migration lock was never released or currently a migration is running.
Mar 18 17:02:33  node[18330]: 
Mar 18 17:02:33  node[18330]: Migration lock was never released or currently a migration is running.
Mar 18 17:02:33  node[18330]: "If you are sure no migration is running, check your data and if your database is in a broken state, you could run `knex-migrator rollback`."
Mar 18 17:02:33  node[18330]: Error ID:
Mar 18 17:02:33  node[18330]:     500
Mar 18 17:02:33  node[18330]: ----------------------------------------
Mar 18 17:02:33  node[18330]: MigrationsAreLockedError: Migration lock was never released or currently a migration is running.
Mar 18 17:02:33  node[18330]:     at DatabaseStateManager.getState (/var/www/tafkasworld/versions/4.40.0/core/server/data/db/state-manager.js:64:32)
Mar 18 17:02:33  node[18330]:     at MigrationsAreLockedError.KnexMigrateError (/var/www/tafkasworld/versions/4.40.0/node_modules/knex-migrator/lib/errors.js:7:26)
Mar 18 17:02:33  node[18330]:     at new MigrationsAreLockedError (/var/www/tafkasworld/versions/4.40.0/node_modules/knex-migrator/lib/errors.js:37:26)
Mar 18 17:02:33  node[18330]:     at /var/www/tafkasworld/versions/4.40.0/node_modules/knex-migrator/lib/locking.js:62:23
Mar 18 17:02:33  node[18330]:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
Mar 18 17:02:33  node[18330]:     at async DatabaseStateManager.getState (/var/www/tafkasworld/versions/4.40.0/core/server/data/db/state-manager.js:40:13)
Mar 18 17:02:33  node[18330]:     at async DatabaseStateManager.makeReady (/var/www/tafkasworld/versions/4.40.0/core/server/data/db/state-manager.js:73:25)
Mar 18 17:02:33  node[18330]:     at async initDatabase (/var/www/tafkasworld/versions/4.40.0/core/boot.js:60:5)
Mar 18 17:02:33  node[18330]:     at async bootGhost (/var/www/tafkasworld/versions/4.40.0/core/boot.js:394:9)
Mar 18 17:02:33  node[18330]: 
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Ghost is shutting down
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Can't connect to the bootstrap socket (localhost 8000) ECONNREFUSED.
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Tries: 0
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Retrying...
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Ghost has shut down
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Your site is now offline
Mar 18 17:02:33  node[18330]: [2022-03-18 17:02:33] WARN Ghost was running for a few seconds
Mar 18 17:02:34  node[18291]: /usr/lib/node_modules/ghost-cli/lib/process-manager.js:46
Mar 18 17:02:34  node[18291]:         throw error;
Mar 18 17:02:34  node[18291]:         ^
Mar 18 17:02:34  node[18291]: {
Mar 18 17:02:34  node[18291]:   message: 'Ghost was able to start, but errored during boot with: Migration lock was never released or currently a migration is running.'
Mar 18 17:02:34  node[18291]: }
Mar 18 17:02:34  systemd[1]: ghost_.service: Main process exited, code=exited, status=1/FAILURE
Mar 18 17:02:34  systemd[1]: ghost_.service: Failed with result 'exit-code'.
Mar 18 17:02:34  systemd[1]: ghost_.service: Scheduled restart job, restart counter is at 1.