H2 database unable to upgrade v0.40.1

martinnormark · July 30, 2021, 8:03pm

I was stupid enough to upgrade from v0.37 to v0.40.1 without securing a backup of my H2 file.

So now when I start metabase, I get this error: Database has migration lock; cannot run migrations. You can force-release these locks by runningjava -jar metabase.jar migrate release-locks``

Full output:

/app # ./run_metabase.sh
Warning: environ value jdk-11.0.11+9 for key :java-version has been overwritten with 11.0.11
WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
2021-07-30 19:57:28,897 INFO metabase.util :: Maximum memory available to JVM: 3.1 GB
2021-07-30 19:57:37,223 INFO util.encryption :: Saved credentials encryption is DISABLED for this Metabase instance. 🔓
 For more information, see https://metabase.com/docs/latest/operations-guide/encrypting-database-details-at-rest.html
2021-07-30 19:57:42,253 INFO metabase.core ::
Metabase v0.40.1 (ed8f9c8 release-x.40.x)

Copyright © 2021 Metabase, Inc.

Metabase Enterprise Edition extensions are NOT PRESENT.
2021-07-30 19:57:42,263 WARN metabase.core :: WARNING: You have enabled namespace tracing, which could log sensitive information like db passwords.
2021-07-30 19:57:42,263 INFO metabase.core :: Starting Metabase in STANDALONE mode
2021-07-30 19:57:42,317 INFO metabase.server :: Launching Embedded Jetty Webserver with config:
 {:port 3000, :host "0.0.0.0"}

2021-07-30 19:57:42,346 INFO metabase.core :: Starting Metabase version v0.40.1 (ed8f9c8 release-x.40.x) ...
2021-07-30 19:57:42,375 INFO metabase.core :: System info:
 {"file.encoding" "UTF-8",
 "java.runtime.name" "OpenJDK Runtime Environment",
 "java.runtime.version" "11.0.11+9",
 "java.vendor" "AdoptOpenJDK",
 "java.vendor.url" "https://adoptopenjdk.net/",
 "java.version" "11.0.11",
 "java.vm.name" "OpenJDK 64-Bit Server VM",
 "java.vm.version" "11.0.11+9",
 "os.name" "Linux",
 "os.version" "5.10.16.3-microsoft-standard-WSL2",
 "user.language" "en",
 "user.timezone" "GMT"}

2021-07-30 19:57:42,380 WARN metabase.plugins :: Metabase cannot use the plugins directory /app/plugins
 Please make sure the directory exists and that Metabase has permission to write to it. You can change the directory Metabase uses for modules by setting the environment variable MB_PLUGINS_DIR. Falling back to a temporary directory for now.
java.lang.AssertionError: Assert failed: Metabase does not have permissions to write to plugins directory /app/plugins
(Files/isWritable path)
        at metabase.plugins$fn__78716$fn__78717.invoke(plugins.clj:26)
        at clojure.lang.Delay.deref(Delay.java:42)
        at clojure.core$deref.invokeStatic(core.clj:2320)
        at clojure.core$deref.invoke(core.clj:2306)
        at metabase.plugins$plugins_dir.invokeStatic(plugins.clj:48)
        at metabase.plugins$plugins_dir.invoke(plugins.clj:48)
        at metabase.plugins$load_BANG_.invokeStatic(plugins.clj:138)
        at metabase.plugins$load_BANG_.invoke(plugins.clj:137)
        at metabase.plugins$fn__78793$fn__78794.invoke(plugins.clj:145)
        at clojure.lang.Delay.deref(Delay.java:42)
        at clojure.core$deref.invokeStatic(core.clj:2320)
        at clojure.core$deref.invoke(core.clj:2306)
        at metabase.plugins$load_plugins_BANG_.invokeStatic(plugins.clj:147)
        at metabase.plugins$load_plugins_BANG_.invoke(plugins.clj:147)
        at metabase.core$init_BANG_.invokeStatic(core.clj:78)
        at metabase.core$init_BANG_.invoke(core.clj:66)
        at metabase.core$start_normally.invokeStatic(core.clj:131)
        at metabase.core$start_normally.invoke(core.clj:125)
        at metabase.core$_main.invokeStatic(core.clj:164)
        at metabase.core$_main.doInvoke(core.clj:158)
        at clojure.lang.RestFn.invoke(RestFn.java:397)
        at clojure.lang.AFn.applyToHelper(AFn.java:152)
        at clojure.lang.RestFn.applyTo(RestFn.java:132)
        at metabase.core.main(Unknown Source)
2021-07-30 19:57:42,385 INFO metabase.plugins :: Loading plugins in /tmp...
2021-07-30 19:57:42,643 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :google...
2021-07-30 19:57:42,644 INFO driver.impl :: Registered abstract driver :google  🚚
2021-07-30 19:57:42,658 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :mongo...
2021-07-30 19:57:42,659 INFO driver.impl :: Registered driver :mongo  🚚
2021-07-30 19:57:42,664 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :presto...
2021-07-30 19:57:42,764 INFO driver.impl :: Registered abstract driver :sql  🚚
Load driver :sql took 104.5 ms
2021-07-30 19:57:42,776 INFO driver.impl :: Registered driver :presto (parents: [:sql]) 🚚
2021-07-30 19:57:42,780 INFO plugins.dependencies :: Plugin 'Metabase BigQuery Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
2021-07-30 19:57:42,783 INFO plugins.dependencies :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
2021-07-30 19:57:42,784 WARN plugins.lazy-loaded-driver :: Warning: plugin manifest for :bigquery does not include connection properties
2021-07-30 19:57:42,784 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :bigquery...
2021-07-30 19:57:42,785 INFO driver.impl :: Registered driver :bigquery (parents: [:sql :google]) 🚚
2021-07-30 19:57:42,791 INFO plugins.dependencies :: Metabase cannot initialize plugin Metabase Vertica Driver due to required dependencies. Metabase requires the Vertica JDBC driver in order to connect to Vertica databases, but we can't ship it as part of Metabase due to licensing restrictions. See https://metabase.com/docs/latest/administration-guide/databases/vertica.html for more details.

2021-07-30 19:57:42,791 INFO plugins.dependencies :: Metabase Vertica Driver dependency {:class com.vertica.jdbc.Driver} satisfied? false
2021-07-30 19:57:42,792 INFO plugins.dependencies :: Plugins with unsatisfied deps: ["Metabase Vertica Driver"]
2021-07-30 19:57:42,798 INFO plugins.dependencies :: Metabase cannot initialize plugin Metabase Oracle Driver due to required dependencies. Metabase requires the Oracle JDBC driver in order to connect to Oracle databases, but we can't ship it as part of Metabase due to licensing restrictions. See https://metabase.com/docs/latest/administration-guide/databases/oracle.html for more details.

2021-07-30 19:57:42,799 INFO plugins.dependencies :: Metabase Oracle Driver dependency {:class oracle.jdbc.OracleDriver} satisfied? false
2021-07-30 19:57:42,801 INFO plugins.dependencies :: Plugins with unsatisfied deps: ["Metabase Oracle Driver" "Metabase Vertica Driver"]
2021-07-30 19:57:42,808 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :sqlserver...
2021-07-30 19:57:42,871 INFO driver.impl :: Registered abstract driver :sql-jdbc (parents: [:sql]) 🚚
Load driver :sql-jdbc took 67.7 ms
2021-07-30 19:57:42,878 INFO driver.impl :: Registered driver :sqlserver (parents: [:sql-jdbc]) 🚚
2021-07-30 19:57:42,883 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :sqlite...
2021-07-30 19:57:42,884 INFO driver.impl :: Registered driver :sqlite (parents: [:sql-jdbc]) 🚚
2021-07-30 19:57:42,908 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :hive-like...
2021-07-30 19:57:42,909 INFO driver.impl :: Registered abstract driver :hive-like (parents: [:sql-jdbc]) 🚚
2021-07-30 19:57:42,909 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :sparksql...
2021-07-30 19:57:42,910 INFO driver.impl :: Registered driver :sparksql (parents: [:hive-like]) 🚚
2021-07-30 19:57:42,918 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :redshift...
2021-07-30 19:57:42,930 INFO driver.impl :: Registered driver :postgres (parents: [:sql-jdbc]) 🚚
Load driver :postgres took 24.4 ms
2021-07-30 19:57:42,944 INFO driver.impl :: Registered driver :redshift (parents: [:postgres]) 🚚
2021-07-30 19:57:42,948 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :druid...
2021-07-30 19:57:42,948 INFO driver.impl :: Registered driver :druid  🚚
2021-07-30 19:57:42,953 INFO plugins.dependencies :: Plugin 'Metabase Google Analytics Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
2021-07-30 19:57:42,954 INFO plugins.dependencies :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
2021-07-30 19:57:42,955 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :googleanalytics...
2021-07-30 19:57:42,956 INFO driver.impl :: Registered driver :googleanalytics (parents: [:google]) 🚚
2021-07-30 19:57:42,973 DEBUG plugins.lazy-loaded-driver :: Registering lazy loading driver :snowflake...
2021-07-30 19:57:42,974 INFO driver.impl :: Registered driver :snowflake (parents: [:sql-jdbc]) 🚚
2021-07-30 19:57:42,982 INFO driver.impl :: Registered driver :h2 (parents: [:sql-jdbc]) 🚚
2021-07-30 19:57:43,003 INFO driver.impl :: Registered driver :mysql (parents: [:sql-jdbc]) 🚚
2021-07-30 19:57:43,023 INFO metabase.core :: Setting up and migrating Metabase DB. Please sit tight, this may take a minute...
2021-07-30 19:57:43,026 WARN db.env :: WARNING: Using Metabase with an H2 application database is not recommended for production deployments. For production deployments, we highly recommend using Postgres, MySQL, or MariaDB instead. If you decide to continue to use H2, please be sure to back up the database file regularly. For more information, see https://metabase.com/docs/latest/operations-guide/migrating-from-h2.html
2021-07-30 19:57:43,030 INFO db.setup :: Verifying h2 Database Connection ...
2021-07-30 19:57:43,485 INFO db.setup :: Successfully verified H2 1.4.197 (2018-03-18) application database connection. ✅
2021-07-30 19:57:43,486 INFO db.setup :: Running Database Migrations...
2021-07-30 19:57:43,489 INFO db.setup :: Setting up Liquibase...
2021-07-30 19:57:43,542 INFO db.setup :: Liquibase is ready.
2021-07-30 19:57:43,543 INFO db.liquibase :: Checking if Database has unrun migrations...
2021-07-30 19:57:45,331 INFO db.liquibase :: Database has unrun migrations. Waiting for migration lock to be cleared...
2021-07-30 19:57:47,335 WARN metabase.util :: auto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__35455@5fb6b271: Database has migration lock; cannot run migrations. You can force-release these locks by running `java -jar metabase.jar migrate release-locks`.
2021-07-30 19:57:49,337 WARN metabase.util :: auto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__35455@5fb6b271: Database has migration lock; cannot run migrations. You can force-release these locks by running `java -jar metabase.jar migrate release-locks`.
2021-07-30 19:57:51,338 WARN metabase.util :: auto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__35455@5fb6b271: Database has migration lock; cannot run migrations. You can force-release these locks by running `java -jar metabase.jar migrate release-locks`.
2021-07-30 19:57:53,339 WARN metabase.util :: auto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__35455@5fb6b271: Database has migration lock; cannot run migrations. You can force-release these locks by running `java -jar metabase.jar migrate release-locks`.
2021-07-30 19:57:55,341 WARN metabase.util :: auto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__35455@5fb6b271: Database has migration lock; cannot run migrations. You can force-release these locks by running `java -jar metabase.jar migrate release-locks`.
2021-07-30 19:57:57,343 ERROR metabase.core :: Metabase Initialization FAILED
liquibase.exception.LockException: Database has migration lock; cannot run migrations. You can force-release these locks by running `java -jar metabase.jar migrate release-locks`.
        at metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__35455.invoke(liquibase.clj:109)
        at metabase.util$do_with_auto_retries.invokeStatic(util.clj:464)
        at metabase.util$do_with_auto_retries.invoke(util.clj:456)
        at metabase.util$do_with_auto_retries.invokeStatic(util.clj:471)
        at metabase.util$do_with_auto_retries.invoke(util.clj:456)
        at metabase.util$do_with_auto_retries.invokeStatic(util.clj:471)
        at metabase.util$do_with_auto_retries.invoke(util.clj:456)
        at metabase.util$do_with_auto_retries.invokeStatic(util.clj:471)
        at metabase.util$do_with_auto_retries.invoke(util.clj:456)
        at metabase.util$do_with_auto_retries.invokeStatic(util.clj:471)
        at metabase.util$do_with_auto_retries.invoke(util.clj:456)
        at metabase.util$do_with_auto_retries.invokeStatic(util.clj:471)
        at metabase.util$do_with_auto_retries.invoke(util.clj:456)
        at metabase.db.liquibase$wait_for_migration_lock_to_be_cleared.invokeStatic(liquibase.clj:104)
        at metabase.db.liquibase$wait_for_migration_lock_to_be_cleared.invoke(liquibase.clj:100)
        at metabase.db.liquibase$migrate_up_if_needed_BANG_.invokeStatic(liquibase.clj:120)
        at metabase.db.liquibase$migrate_up_if_needed_BANG_.invoke(liquibase.clj:114)
        at metabase.db.setup$migrate_BANG_$fn__35686$fn__35687.invoke(setup.clj:68)
        at metabase.db.liquibase$do_with_liquibase.invokeStatic(liquibase.clj:38)
        at metabase.db.liquibase$do_with_liquibase.invoke(liquibase.clj:30)
        at metabase.db.setup$migrate_BANG_$fn__35686.invoke(setup.clj:63)
        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.db.setup$migrate_BANG_.invokeStatic(setup.clj:54)
        at metabase.db.setup$migrate_BANG_.invoke(setup.clj:40)
        at metabase.db.setup$run_schema_migrations_BANG_.invokeStatic(setup.clj:119)
        at metabase.db.setup$run_schema_migrations_BANG_.invoke(setup.clj:115)
        at metabase.db.setup$setup_db_BANG_$fn__35737$fn__35738.invoke(setup.clj:143)
        at metabase.util$do_with_us_locale.invokeStatic(util.clj:683)
        at metabase.util$do_with_us_locale.invoke(util.clj:669)
        at metabase.db.setup$setup_db_BANG_$fn__35737.invoke(setup.clj:141)
        at metabase.db.setup$setup_db_BANG_.invokeStatic(setup.clj:140)
        at metabase.db.setup$setup_db_BANG_.invoke(setup.clj:136)
        at metabase.db$setup_db_BANG_$fn__35751.invoke(db.clj:61)
        at metabase.db$setup_db_BANG_.invokeStatic(db.clj:56)
        at metabase.db$setup_db_BANG_.invoke(db.clj:51)
        at metabase.core$init_BANG_.invokeStatic(core.clj:87)
        at metabase.core$init_BANG_.invoke(core.clj:66)
        at metabase.core$start_normally.invokeStatic(core.clj:131)
        at metabase.core$start_normally.invoke(core.clj:125)
        at metabase.core$_main.invokeStatic(core.clj:164)
        at metabase.core$_main.doInvoke(core.clj:158)
        at clojure.lang.RestFn.invoke(RestFn.java:397)
        at clojure.lang.AFn.applyToHelper(AFn.java:152)
        at clojure.lang.RestFn.applyTo(RestFn.java:132)
        at metabase.core.main(Unknown Source)
2021-07-30 19:57:57,347 INFO metabase.core :: Metabase Shutting Down ...
2021-07-30 19:57:57,351 INFO metabase.server :: Shutting Down Embedded Jetty Webserver
2021-07-30 19:57:57,366 INFO metabase.core :: Metabase Shutdown COMPLETE
/app #

When I run the release-locks command, it doesn't seem to fail. But running metabase again produces the same error as above.

Output from release-locks

/app # java -jar metabase.jar migrate release-locks
Warning: environ value jdk-11.0.11+9 for key :java-version has been overwritten with 11.0.11
WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
2021-07-30 19:58:26,678 INFO metabase.util :: Maximum memory available to JVM: 3.1 GB
2021-07-30 19:58:35,747 INFO util.encryption :: Saved credentials encryption is DISABLED for this Metabase instance. 🔓
 For more information, see https://metabase.com/docs/latest/operations-guide/encrypting-database-details-at-rest.html
2021-07-30 19:58:40,815 INFO metabase.core ::
Metabase v0.40.1 (ed8f9c8 release-x.40.x)

Copyright © 2021 Metabase, Inc.

Metabase Enterprise Edition extensions are NOT PRESENT.
2021-07-30 19:58:40,826 WARN metabase.core :: WARNING: You have enabled namespace tracing, which could log sensitive information like db passwords.
2021-07-30 19:58:40,845 WARN db.env :: WARNING: Using Metabase with an H2 application database is not recommended for production deployments. For production deployments, we highly recommend using Postgres, MySQL, or MariaDB instead. If you decide to continue to use H2, please be sure to back up the database file regularly. For more information, see https://metabase.com/docs/latest/operations-guide/migrating-from-h2.html
2021-07-30 19:58:41,005 INFO db.setup :: Setting up Liquibase...
2021-07-30 19:58:41,077 INFO db.setup :: Liquibase is ready.

flamber · July 30, 2021, 8:16pm

Hi @martinnormark
How big is the H2?
Something makes me think that you tried to start 0.40.1 and then you stopped it at some point, and then you tried starting it again, which then has the migration locks on. Could that be correct?

martinnormark · July 30, 2021, 9:05pm

The H2 is 18MB

That could’ve been the case. I tried to access the UI after several hours and there was a progress bar at the bottom with some chart illustrations cycling across the screen.

I waited even more hours, refreshed the browser many times but it never seemed to complete.

I looked at the logs and this error came up.

I then tried downloading the H2 file to try it locally in Docker, where I grabbed the above logs from.

flamber · July 31, 2021, 9:13am

@martinnormark Okay, so the log from 2021-07-30 19:57 shows it trying to startup and shutting down.
Sounds like the H2 has become corrupted. Try removing the row in the table DATABASECHANGELOGLOCK. You can use something like DBeaver.io to view H2 database, just remember to use the same driver as Metabase, which is currently 1.4.197

But once you have gotten it working, then migrate away from H2, which is not recommended in production:
https://www.metabase.com/docs/latest/operations-guide/migrating-from-h2.html

martinnormark · July 31, 2021, 10:08am

Will give it a try, thanks a lot for the help so far!

I actually tried to migrate to Postgres as a way out but the un-run migrations and locks won’t let me, of course.

Will migrate if I get it fixed

martinnormark · August 2, 2021, 9:21am

When I open my metabase.db folder in DBeaver, using driver version 1.4.197, it opens successfully but it doesn't show any tables. Running a query like SELECT * FROM DATABASECHANGELOGLOCK fails with message indicating the table does not exist.

Could there be an older driver version I should try? My H2 database was created with metabase v0.39.1-3 as far as I recall.

flamber · August 2, 2021, 9:50am

@martinnormark Metabase has used 1.4.197 for several years. So either you're pointing DBeaver to the wrong location or your H2 is completely corrupted, but then you should see errors.

leccine · August 3, 2021, 6:20pm

@martinnormark so there is this weird thing going on with h2. When you open a DB you should never specify the whole filename and just remove the mv.db suffix yourself.

Example:

You have a file called hello.mv.db. Your JDBC string must be jdbc:h2:hello. Same goes to DBeaver or other tools.

You can use java -cp h2-1.4.197.jar org.h2.tools.Shell to open a h2 database on the command line.

Example:

 java -cp h2-1.4.197.jar org.h2.tools.Shell

Welcome to H2 Shell 1.4.197 (2018-03-18)
Exit with Ctrl+C
[Enter]   jdbc:h2:~/test
URL       jdbc:h2:/opt/metabase/metabase.db
[Enter]   org.h2.Driver
Driver
[Enter]
User
[Enter]   Hide
Password
Password

martinnormark · August 3, 2021, 8:31pm

@leccine Oh yeah, that did the trick. I thought I tried any possible combination for the path in DBeaver, but the extra .db in mine must have fooled me.

So it was called metabase.db.mv.db so the path metabase.db opened successfully.

Now I'm back in business, got the H2 running again and have migrated to Postgres.

Thanks a lot for the help, both @leccine and @flamber!

leccine · August 4, 2021, 2:23pm

@martinnormark I am glad I could help.