Unable to run migrations when upgrading from 0.8.2 to 0.9.0 on PostgreSQL

[blazejpawlak]

Describe the bug I'm trying to upgrade our LHCI server from 0.8.2 to 0.9.0 and when I'm starting the new docker container I am getting the following messages and the server just stops:

2022-04-13T19:59:30.495Z lhci:server:sql [createApp] initializing storage method 2022-04-13T19:59:30.652Z lhci:server:sql [initialize] initializing database connection 2022-04-13T19:59:30.705Z sequelize:pool pool created with max/min: 5/0, no replication 2022-04-13T19:59:30.738Z lhci:server:sql [initialize] defining models 2022-04-13T19:59:30.762Z lhci:server:sql [initialize] running migrations

Lighthouse is connecting to PostgreSQL 12.7 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4), 64-bit. Unfortunately no more logs are being output in spite of the DEBUG=* being set.

I also tried setting the LHCI_STORAGE__SQL_MIGRATION_OPTIONS__TABLE_NAME property to sequelize_meta to no avail. Still migrations fail. When I restore my database to a backup that was used by the 0.8.2 version, run the 0.8.2 that works fine, and then change the Docker image to 0.9.0 and run it it fails as outlined above. When trying to run the 0.8.2 image I'm getting the following output:

> [email protected] start /usr/src/lhci
> lhci server --config=./lighthouserc.json

2022-04-13T19:33:49.516Z lhci:server:sql [createApp] initializing storage method
2022-04-13T19:33:49.673Z lhci:server:sql [initialize] initializing database connection
2022-04-13T19:33:49.720Z sequelize:pool pool created with max/min: 5/0, no replication
2022-04-13T19:33:49.793Z lhci:server:sql [initialize] defining models
2022-04-13T19:33:49.808Z lhci:server:sql [initialize] running migrations
(node:27) DeprecationWarning: Implicit disabling of certificate verification is deprecated and will be removed in pg 8. Specify `rejectUnauthorized: true` to require a valid CA or `rejectUnauthorized: false` to explicitly opt out of MITM protection.
2022-04-13T19:33:49.941Z sequelize:connection:pg connection acquired
2022-04-13T19:33:49.952Z sequelize:sql:pg executing(default) : SHOW SERVER_VERSION
2022-04-13T19:33:49.954Z sequelize:sql:pg executed(default) : SHOW SERVER_VERSION
2022-04-13T19:33:49.960Z sequelize:connection:pg connection timeout
2022-04-13T19:33:50.022Z sequelize:connection:pg connection acquired
2022-04-13T19:33:50.042Z sequelize:pool connection acquired
2022-04-13T19:33:50.043Z lhci:server:sql:verbose [sequelize] Executing (default): CREATE TABLE IF NOT EXISTS "sequelize_meta" ("name" VARCHAR(255) NOT NULL UNIQUE , PRIMARY KEY ("name"));
2022-04-13T19:33:50.043Z sequelize:sql:pg executing(default) : CREATE TABLE IF NOT EXISTS "sequelize_meta" ("name" VARCHAR(255) NOT NULL UNIQUE , PRIMARY KEY ("name"));
2022-04-13T19:33:50.045Z sequelize:sql:pg executed(default) : CREATE TABLE IF NOT EXISTS "sequelize_meta" ("name" VARCHAR(255) NOT NULL UNIQUE , PRIMARY KEY ("name"));
2022-04-13T19:33:50.046Z sequelize:pool connection released
2022-04-13T19:33:50.047Z sequelize:pool connection acquired
2022-04-13T19:33:50.048Z lhci:server:sql:verbose [sequelize] Executing (default): SELECT i.relname AS name, ix.indisprimary AS primary, ix.indisunique AS unique, ix.indkey AS indkey, array_agg(a.attnum) as column_indexes, array_agg(a.attname) AS column_names, pg_get_indexdef(ix.indexrelid) AS definition FROM pg_class t, pg_class i, pg_index ix, pg_attribute a WHERE t.oid = ix.indrelid AND i.oid = ix.indexrelid AND a.attrelid = t.oid AND t.relkind = 'r' and t.relname = 'sequelize_meta' GROUP BY i.relname, ix.indexrelid, ix.indisprimary, ix.indisunique, ix.indkey ORDER BY i.relname;
2022-04-13T19:33:50.048Z sequelize:sql:pg executing(default) : SELECT i.relname AS name, ix.indisprimary AS primary, ix.indisunique AS unique, ix.indkey AS indkey, array_agg(a.attnum) as column_indexes, array_agg(a.attname) AS column_names, pg_get_indexdef(ix.indexrelid) AS definition FROM pg_class t, pg_class i, pg_index ix, pg_attribute a WHERE t.oid = ix.indrelid AND i.oid = ix.indexrelid AND a.attrelid = t.oid AND t.relkind = 'r' and t.relname = 'sequelize_meta' GROUP BY i.relname, ix.indexrelid, ix.indisprimary, ix.indisunique, ix.indkey ORDER BY i.relname;
2022-04-13T19:33:50.060Z sequelize:sql:pg executed(default) : SELECT i.relname AS name, ix.indisprimary AS primary, ix.indisunique AS unique, ix.indkey AS indkey, array_agg(a.attnum) as column_indexes, array_agg(a.attname) AS column_names, pg_get_indexdef(ix.indexrelid) AS definition FROM pg_class t, pg_class i, pg_index ix, pg_attribute a WHERE t.oid = ix.indrelid AND i.oid = ix.indexrelid AND a.attrelid = t.oid AND t.relkind = 'r' and t.relname = 'sequelize_meta' GROUP BY i.relname, ix.indexrelid, ix.indisprimary, ix.indisunique, ix.indkey ORDER BY i.relname;
2022-04-13T19:33:50.062Z sequelize:pool connection released
2022-04-13T19:33:50.073Z sequelize:pool connection acquired
2022-04-13T19:33:50.073Z lhci:server:sql:verbose [sequelize] Executing (default): SELECT "name" FROM "sequelize_meta" AS "SequelizeMeta" ORDER BY "SequelizeMeta"."name" ASC;
2022-04-13T19:33:50.073Z sequelize:sql:pg executing(default) : SELECT "name" FROM "sequelize_meta" AS "SequelizeMeta" ORDER BY "SequelizeMeta"."name" ASC;
2022-04-13T19:33:50.076Z sequelize:sql:pg executed(default) : SELECT "name" FROM "sequelize_meta" AS "SequelizeMeta" ORDER BY "SequelizeMeta"."name" ASC;
2022-04-13T19:33:50.078Z sequelize:pool connection released
2022-04-13T19:33:50.087Z sequelize:pool connection acquired
2022-04-13T19:33:50.087Z lhci:server:sql:verbose [sequelize] Executing (default): CREATE TABLE IF NOT EXISTS "sequelize_meta" ("name" VARCHAR(255) NOT NULL UNIQUE , PRIMARY KEY ("name"));
2022-04-13T19:33:50.087Z sequelize:sql:pg executing(default) : CREATE TABLE IF NOT EXISTS "sequelize_meta" ("name" VARCHAR(255) NOT NULL UNIQUE , PRIMARY KEY ("name"));
2022-04-13T19:33:50.090Z sequelize:sql:pg executed(default) : CREATE TABLE IF NOT EXISTS "sequelize_meta" ("name" VARCHAR(255) NOT NULL UNIQUE , PRIMARY KEY ("name"));
2022-04-13T19:33:50.090Z sequelize:pool connection released
2022-04-13T19:33:50.090Z sequelize:pool connection acquired
2022-04-13T19:33:50.091Z lhci:server:sql:verbose [sequelize] Executing (default): SELECT i.relname AS name, ix.indisprimary AS primary, ix.indisunique AS unique, ix.indkey AS indkey, array_agg(a.attnum) as column_indexes, array_agg(a.attname) AS column_names, pg_get_indexdef(ix.indexrelid) AS definition FROM pg_class t, pg_class i, pg_index ix, pg_attribute a WHERE t.oid = ix.indrelid AND i.oid = ix.indexrelid AND a.attrelid = t.oid AND t.relkind = 'r' and t.relname = 'sequelize_meta' GROUP BY i.relname, ix.indexrelid, ix.indisprimary, ix.indisunique, ix.indkey ORDER BY i.relname;
2022-04-13T19:33:50.091Z sequelize:sql:pg executing(default) : SELECT i.relname AS name, ix.indisprimary AS primary, ix.indisunique AS unique, ix.indkey AS indkey, array_agg(a.attnum) as column_indexes, array_agg(a.attname) AS column_names, pg_get_indexdef(ix.indexrelid) AS definition FROM pg_class t, pg_class i, pg_index ix, pg_attribute a WHERE t.oid = ix.indrelid AND i.oid = ix.indexrelid AND a.attrelid = t.oid AND t.relkind = 'r' and t.relname = 'sequelize_meta' GROUP BY i.relname, ix.indexrelid, ix.indisprimary, ix.indisunique, ix.indkey ORDER BY i.relname;
2022-04-13T19:33:50.096Z sequelize:sql:pg executed(default) : SELECT i.relname AS name, ix.indisprimary AS primary, ix.indisunique AS unique, ix.indkey AS indkey, array_agg(a.attnum) as column_indexes, array_agg(a.attname) AS column_names, pg_get_indexdef(ix.indexrelid) AS definition FROM pg_class t, pg_class i, pg_index ix, pg_attribute a WHERE t.oid = ix.indrelid AND i.oid = ix.indexrelid AND a.attrelid = t.oid AND t.relkind = 'r' and t.relname = 'sequelize_meta' GROUP BY i.relname, ix.indexrelid, ix.indisprimary, ix.indisunique, ix.indkey ORDER BY i.relname;
2022-04-13T19:33:50.096Z sequelize:pool connection released
2022-04-13T19:33:50.097Z sequelize:pool connection acquired
2022-04-13T19:33:50.097Z lhci:server:sql:verbose [sequelize] Executing (default): SELECT "name" FROM "sequelize_meta" AS "SequelizeMeta" ORDER BY "SequelizeMeta"."name" ASC;
2022-04-13T19:33:50.098Z sequelize:sql:pg executing(default) : SELECT "name" FROM "sequelize_meta" AS "SequelizeMeta" ORDER BY "SequelizeMeta"."name" ASC;
2022-04-13T19:33:50.141Z sequelize:sql:pg executed(default) : SELECT "name" FROM "sequelize_meta" AS "SequelizeMeta" ORDER BY "SequelizeMeta"."name" ASC;
2022-04-13T19:33:50.142Z sequelize:pool connection released
2022-04-13T19:33:50.144Z lhci:server:sql:verbose [umzug] == 20191009-project-token: migrating =======
2022-04-13T19:33:50.147Z sequelize:pool connection acquired
2022-04-13T19:33:50.147Z lhci:server:sql:verbose [sequelize] Executing (default): ALTER TABLE "public"."projects" ADD COLUMN "token" UUID;
2022-04-13T19:33:50.147Z sequelize:sql:pg executing(default) : ALTER TABLE "public"."projects" ADD COLUMN "token" UUID;
2022-04-13T19:33:50.177Z sequelize:pool connection released
Wed, 13 Apr 2022 19:33:50 GMT retry-as-promised:error SequelizeDatabaseError: column "token" of relation "projects" already exists
SequelizeDatabaseError: column "token" of relation "projects" already exists
    at Query.formatError (/usr/src/lhci/node_modules/sequelize/lib/dialects/postgres/query.js:363:16)
    at /usr/src/lhci/node_modules/sequelize/lib/dialects/postgres/query.js:86:18
    at tryCatcher (/usr/src/lhci/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/usr/src/lhci/node_modules/bluebird/js/release/promise.js:547:31)
    at Promise._settlePromise (/usr/src/lhci/node_modules/bluebird/js/release/promise.js:604:18)
    at Promise._settlePromise0 (/usr/src/lhci/node_modules/bluebird/js/release/promise.js:649:10)
    at Promise._settlePromises (/usr/src/lhci/node_modules/bluebird/js/release/promise.js:725:18)
    at _drainQueueStep (/usr/src/lhci/node_modules/bluebird/js/release/async.js:93:12)
    at _drainQueue (/usr/src/lhci/node_modules/bluebird/js/release/async.js:86:9)
    at Async._drainQueues (/usr/src/lhci/node_modules/bluebird/js/release/async.js:102:5)
    at Immediate.Async.drainQueues [as _onImmediate] (/usr/src/lhci/node_modules/bluebird/js/release/async.js:15:14)
    at processImmediate (internal/timers.js:456:21)npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] start: `lhci server --config=./lighthouserc.json`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the [email protected] start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2022-04-13T19_33_50_196Z-debug.log

Then I have to drop the database, and restore it to run again the 0.8.2 image. I tried setting up 0.9.0 against an empty database with the same result. The startup stops at [initialize] running migrations and no tables / entries at all created in the database.

Ideas on why migrations in 0.9.0 don't do their thing? I can debug it further if anyone can give me some pointers how to approach it.

To Reproduce Steps to reproduce the behavior:

1. Have LHCI in 0.8.2 deployed and running against a Postgres DB v12
2. Upgrade to 0.9.0 and start it with DEBUG=* set.
3. Observe the LHCI log.

Expected behavior A migration task should be run resulting in complete upgrade to 0.9.0 that runs.

Logs/Screenshots n/a

Environment (please complete the following information):

• OS: Docker v20.10.13 running images provided by patrickhulce/lhci-server at https://hub.docker.com/r/patrickhulce/lhci-server
• DB: PostgreSQL 12.7 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4), 64-bit.
• Version: 0.8.2 and 0.9.0

Additional context Add any other context about the problem here.

[blazejpawlak]

Hi, any ideas how do debug this situation? I'd like to upgrade our LHCI server but cannot, since we're using Postgres for data storage, so I'm stuck at 0.8.2.

Any help at all appreciated. Thanks!