At part ' Migration lock is cleared. Running migrations... '
The file has grown at least 3x in size and keeps growing, the upgrade process has been running for over an hour. Should I be worried or is this typical?
I'm at Java 11 and going from from v0.38.3 to v0.45 - H2.
Hi @Su33nf
It can take a very long time with H2, but you should not even be running H2 in production.
https://www.metabase.com/docs/latest/installation-and-operation/migrating-from-h2
Thanks for the reply.
I do not want to be using H2, but when I try to migrate towards postgres, the migration always fails, so I'm hoping once I update Metabase to the latest version, I might have better luck with migrating the h2 to postgres.
[root@esm app]# /usr/bin/java -jar /home/appmgr/metabase.jar load-from-h2 /home/appmgr/metabase.db
WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
2022-12-06 14:31:06,919 INFO metabase.util :: Maximum memory available to JVM: 3.7 GB
2022-12-06 14:31:39,485 INFO util.encryption :: Saved credentials encryption is DISABLED for this Metabase instance. ð
For more information, see Redirecting…
2022-12-06 14:32:11,860 INFO metabase.core ::
Metabase v0.38.3 (8332830 release-x.38.x)
Copyright © 2022 Metabase, Inc.
Metabase Enterprise Edition extensions are NOT PRESENT.
2022-12-06 14:32:11,892 WARN metabase.core :: WARNING: You have enabled namespace tracing, which could log sensitive information like db passwords.
2022-12-06 14:32:12,051 INFO cmd.copy :: Set up h2 source database and run migrations...
2022-12-06 14:32:12,053 INFO db.setup :: Verifying h2 Database Connection ...
2022-12-06 14:32:14,287 INFO db.setup :: Successfully verified H2 1.4.197 (2018-03-18) application database connection. â
2022-12-06 14:32:14,287 INFO db.setup :: Running Database Migrations...
2022-12-06 14:32:14,290 INFO db.setup :: Setting up Liquibase...
2022-12-06 14:32:14,442 INFO db.setup :: Liquibase is ready.
2022-12-06 14:32:14,442 INFO db.liquibase :: Checking if Database has unrun migrations...
2022-12-06 14:32:20,020 INFO db.setup :: Database Migrations Current ... â
2022-12-06 14:32:20,021 INFO db.data-migrations :: Running all necessary data migrations, this may take a minute.
2022-12-06 14:32:20,056 INFO db.data-migrations :: Finished running data migrations.
Database setup took 8.0 s
2022-12-06 14:32:20,057 INFO cmd.copy :: [OK]
2022-12-06 14:32:20,057 INFO cmd.copy :: Set up postgres target database and run migrations...
2022-12-06 14:32:20,058 INFO db.setup :: Verifying postgres Database Connection ...
2022-12-06 14:32:20,574 INFO db.setup :: Successfully verified PostgreSQL 13.2 application database connection. â
2022-12-06 14:32:20,577 INFO db.setup :: Running Database Migrations...
2022-12-06 14:32:20,749 INFO db.setup :: Setting up Liquibase...
2022-12-06 14:32:20,996 INFO db.setup :: Liquibase is ready.
2022-12-06 14:32:20,997 INFO db.liquibase :: Checking if Database has unrun migrations...
2022-12-06 14:32:22,865 INFO db.liquibase :: Database has unrun migrations. Waiting for migration lock to be cleared...
2022-12-06 14:32:23,146 INFO db.liquibase :: Migration lock is cleared. Running migrations...
2022-12-06 14:32:48,540 INFO db.setup :: Database Migrations Current ... â
Database setup took 28.5 s
2022-12-06 14:32:48,540 INFO cmd.copy :: [OK]
2022-12-06 14:32:48,541 INFO cmd.copy :: Testing if target postgres database is already populated...
2022-12-06 14:32:48,654 INFO cmd.copy :: [OK]
2022-12-06 14:32:48,724 INFO cmd.copy :: Temporarily disabling DB constraints...
2022-12-06 14:32:48,816 INFO cmd.copy :: [OK]
2022-12-06 14:32:48,823 INFO cmd.copy :: Copying instances of Database...
2022-12-06 14:32:48,854 INFO cmd.copy :: copied 3 instances.
2022-12-06 14:32:48,855 INFO cmd.copy :: Copying instances of User...
2022-12-06 14:32:48,890 INFO cmd.copy :: copied 5 instances.
2022-12-06 14:32:48,960 INFO cmd.copy :: Copying instances of Setting...
2022-12-06 14:32:49,021 INFO cmd.copy :: copied 20 instances.
2022-12-06 14:32:49,679 INFO cmd.copy :: Copying instances of Table...
2022-12-06 14:32:52,261 INFO cmd.copy :: copied 8,279 instances.
2022-12-06 14:33:00,781 INFO cmd.copy :: Copying instances of Field...
2022-12-06 14:33:01,023 ERROR cmd.copy :: BatchUpdateException:
Message: Batch entry 88 INSERT INTO metabase_field ( "description", "database_type", "table_id", "special_type", "name", "fingerprint_version", "has_field_values", "settings", "caveats", "fk_target_field_id", "updated_at", "custom_position", "active", "parent_id", "id", "last_analyzed", "position", "visibility_type", "preview_display", "display_name", "database_position", "fingerprint", "created_at", "base_type", "points_of_interest" ) VALUES ( NULL, 'RAW', 1529, 'type/FK', 'BLACKOUT_GUID', 0, NULL, NULL, NULL, 18882, '2021-04-25 21:06:18.947-04', 0, 'TRUE', NULL, 15281, NULL, 2, 'normal', 'TRUE', 'Blackout GUID', 2, NULL, '2020-11-12 14:31:04.309-05', 'type/*', NULL ) was aborted: ERROR: duplicate key value violates unique constraint "idx_uniq_field_table_id_parent_id_name_2col"
Detail: Key (table_id, name)=(1529, BLACKOUT_GUID) already exists. Call getNextException to see other errors in the batch.
SQLState: 23505
Error Code: 0
PSQLException:
Message: ERROR: duplicate key value violates unique constraint "idx_uniq_field_table_id_parent_id_name_2col"
Detail: Key (table_id, name)=(1529, BLACKOUT_GUID) already exists.
SQLState: 23505
Error Code: 0
2022-12-06 14:33:01,025 INFO cmd.copy :: Re-enabling DB constraints...
2022-12-06 14:33:01,025 INFO cmd.copy :: [OK]
clojure.lang.ExceptionInfo: Error copying instances of Field {:entity "Field"}
at metabase.cmd.copy$copy_data_BANG_$fn__74861$fn__74862.invoke(copy.clj:143)
at metabase.cmd.copy$copy_data_BANG_$fn__74861.invoke(copy.clj:140)
at clojure.core$partition_all$fn__8535$fn__8536.invoke(core.clj:7264)
at clojure.java.jdbc$init_reduce_rs.invokeStatic(jdbc.clj:1205)
at clojure.java.jdbc$init_reduce_rs.invoke(jdbc.clj:1197)
at clojure.java.jdbc$reducible_result_set_STAR_$reify__27256.reduce(jdbc.clj:1227)
at clojure.core$reduce.invokeStatic(core.clj:6827)
at clojure.core$reduce.invoke(core.clj:6810)
at clojure.java.jdbc$query_reducer$fn__27262$fn__27265.invoke(jdbc.clj:1262)
at clojure.java.jdbc$execute_query_with_params.invokeStatic(jdbc.clj:1091)
at clojure.java.jdbc$execute_query_with_params.invoke(jdbc.clj:1084)
at clojure.java.jdbc$db_query_with_resultset_STAR_.invokeStatic(jdbc.clj:1106)
at clojure.java.jdbc$db_query_with_resultset_STAR_.invoke(jdbc.clj:1093)
at clojure.java.jdbc$reducible_query$reify__27279.reduce(jdbc.clj:1357)
at clojure.core$transduce.invokeStatic(core.clj:6883)
at clojure.core$transduce.invoke(core.clj:6870)
at metabase.cmd.copy$copy_data_BANG_.invokeStatic(copy.clj:128)
at metabase.cmd.copy$copy_data_BANG_.invoke(copy.clj:120)
at metabase.cmd.copy$fn__74955$copy_BANG___74960$fn__74961$fn__74968$fn__74969$fn__74970.invoke(copy.clj:280)
at metabase.cmd.copy$do_with_disabled_db_constraints.invokeStatic(copy.clj:220)
at metabase.cmd.copy$do_with_disabled_db_constraints.invoke(copy.clj:216)
at metabase.cmd.copy$fn__74955$copy_BANG___74960$fn__74961$fn__74968$fn__74969.invoke(copy.clj:279)
at metabase.cmd.copy$do_with_connection_rollback_only.invokeStatic(copy.clj:162)
at metabase.cmd.copy$do_with_connection_rollback_only.invoke(copy.clj:160)
at metabase.cmd.copy$fn__74955$copy_BANG___74960$fn__74961$fn__74968.invoke(copy.clj:277)
at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:807)
at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776)
at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:852)
at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776)
at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:789)
at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776)
at metabase.cmd.copy$fn__74955$copy_BANG___74960$fn__74961.invoke(copy.clj:274)
at metabase.cmd.copy$fn__74955$copy_BANG___74960.invoke(copy.clj:255)
at metabase.cmd.load_from_h2$load_from_h2_BANG_.invokeStatic(load_from_h2.clj:35)
at metabase.cmd.load_from_h2$load_from_h2_BANG_.invoke(load_from_h2.clj:25)
at clojure.lang.Var.invoke(Var.java:384)
at metabase.cmd$load_from_h2.invokeStatic(cmd.clj:45)
at metabase.cmd$load_from_h2.invoke(cmd.clj:39)
at clojure.lang.AFn.applyToHelper(AFn.java:154)
at clojure.lang.AFn.applyTo(AFn.java:144)
at clojure.core$apply.invokeStatic(core.clj:665)
at clojure.core$apply.invoke(core.clj:660)
at metabase.cmd$run_cmd$fn__74462.invoke(cmd.clj:191)
at metabase.cmd$run_cmd.invokeStatic(cmd.clj:191)
at metabase.cmd$run_cmd.invoke(cmd.clj:187)
at clojure.lang.Var.invoke(Var.java:388)
at metabase.core$run_cmd.invokeStatic(core.clj:148)
at metabase.core$run_cmd.invoke(core.clj:146)
at metabase.core$main.invokeStatic(core.clj:170)
at metabase.core$main.doInvoke(core.clj:165)
at clojure.lang.RestFn.applyTo(RestFn.java:137)
at metabase.core.main(Unknown Source)
Caused by: java.sql.BatchUpdateException: Batch entry 88 INSERT INTO metabase_field ( "description", "database_type", "table_id", "special_type", "name", "fingerprint_version", "has_field_values", "settings", "caveats", "fk_target_field_id", "updated_at", "custom_position", "active", "parent_id", "id", "last_analyzed", "position", "visibility_type", "preview_display", "display_name", "database_position", "fingerprint", "created_at", "base_type", "points_of_interest" ) VALUES ( NULL, 'RAW', 1529, 'type/FK', 'BLACKOUT_GUID', 0, NULL, NULL, NULL, 18882, '2021-04-25 21:06:18.947-04', 0, 'TRUE', NULL, 15281, NULL, 2, 'normal', 'TRUE', 'Blackout GUID', 2, NULL, '2020-11-12 14:31:04.309-05', 'type/*', NULL ) was aborted: ERROR: duplicate key value violates unique constraint "idx_uniq_field_table_id_parent_id_name_2col"
Detail: Key (table_id, name)=(1529, BLACKOUT_GUID) already exists. Call getNextException to see other errors in the batch.
at org.postgresql.jdbc.BatchResultHandler.handleError(BatchResultHandler.java:169)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2286)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:521)
at org.postgresql.jdbc.PgStatement.internalExecuteBatch(PgStatement.java:870)
at org.postgresql.jdbc.PgStatement.executeBatch(PgStatement.java:893)
at org.postgresql.jdbc.PgPreparedStatement.executeBatch(PgPreparedStatement.java:1644)
at clojure.java.jdbc$execute_batch.invokeStatic(jdbc.clj:598)
at clojure.java.jdbc$execute_batch.invoke(jdbc.clj:591)
at clojure.java.jdbc$db_do_execute_prepared_statement.invokeStatic(jdbc.clj:1058)
at clojure.java.jdbc$db_do_execute_prepared_statement.invoke(jdbc.clj:1042)
at clojure.java.jdbc$db_do_prepared.invokeStatic(jdbc.clj:1080)
at clojure.java.jdbc$db_do_prepared.invoke(jdbc.clj:1060)
at clojure.java.jdbc$insert_cols_BANG.invokeStatic(jdbc.clj:1594)
at clojure.java.jdbc$insert_cols_BANG.invoke(jdbc.clj:1585)
at clojure.java.jdbc$insert_multi_BANG_.invokeStatic(jdbc.clj:1653)
at clojure.java.jdbc$insert_multi_BANG_.invoke(jdbc.clj:1619)
at metabase.cmd.copy$insert_chunk_BANG_.invokeStatic(copy.clj:112)
at metabase.cmd.copy$insert_chunk_BANG_.invoke(copy.clj:106)
at metabase.cmd.copy$copy_data_BANG_$fn__74861$fn__74862.invoke(copy.clj:141)
... 51 more
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "idx_uniq_field_table_id_parent_id_name_2col"
Detail: Key (table_id, name)=(1529, BLACKOUT_GUID) already exists.
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
... 68 more
Command failed with exception: Error copying instances of Field
@Su33nf Have a look here: https://github.com/metabase/metabase/issues/10087
Make sure you read everything.
You'll have to fix your H2 by connecting with something like DBeaver.io - make sure to use H2 driver 1.4.197, which is what your version of Metabase also uses.
I appreciate everything so much!
Should I let the upgrade complete, or go back to the old version that I'm having an issue with migrating, and then try to upgrade it?
@Su33nf Stop the upgrade. Fix your H2, then migrate to Postgres, then upgrade. Make sure you have plenty of backups before doing anything, since you can easily end up corrupting or destroying even more.
I ended up waiting out the upgrade. It took roughly four hours for the upgrade to complete and then when I went to migrate over to Postgres after going to 0.45 there was no issue.
After the upgrade was finished, the H2 database file shrunk roughly close to what it was.
But, I'm really glad that I'm both upgraded to 0.45 and off of H2.