Migration failed after upgrading to 0.42

jsacra · April 20, 2022, 6:23pm

Hi!

I'm running Metabase on an Azure App service using a Postgres database. When upgrading from version 0.37.0.2 to 0.42.0.4, I get an exception doing the migration.

Below is excerpt from logs from start until the first error (it then goes on to repeat the same error a million times). I would post the diagnostic but I can't access it without starting the application. For reference, I used FileZilla for both the update and getting the logs.

I don't think there was any changes to the postgres database recently, so it must be related to the update. Is there anything I can do to complete the migration?

2022-04-20T16:00:41.750148813Z _____
2022-04-20T16:00:41.750183913Z / _ \ __________ _________ ____
2022-04-20T16:00:41.750189813Z / /\ ___ / | _ __ _/ __ \
2022-04-20T16:00:41.750193813Z / | / /| | /| | /\ ___/
2022-04-20T16:00:41.750197613Z _| /_____ _/ || __ >
2022-04-20T16:00:41.750201713Z / / /
2022-04-20T16:00:41.750205413Z A P P S E R V I C E O N L I N U X
2022-04-20T16:00:41.750209113Z Documentation: http://aka.ms/webapp-linux
2022-04-20T16:00:41.750212813Z
2022-04-20T16:00:41.750217213Z NOTE: No files or system changes outside of /home will persist beyond your application's current session. /home is your application's persistent storage and is shared across all the server instances.
2022-04-20T16:00:41.750223113Z
2022-04-20T16:00:41.750226713Z
2022-04-20T16:00:41.750920918Z Setup openrc ...
2022-04-20T16:00:41.902879270Z Service machine-id' needs non existent servicedev'
2022-04-20T16:00:41.903899077Z * Caching service dependencies ... [ ok ]
2022-04-20T16:00:41.908262504Z Updating /etc/ssh/sshd_config to use PORT 2222
2022-04-20T16:00:41.911021221Z Starting ssh service...
2022-04-20T16:00:42.202990356Z ssh-keygen: generating new host keys: RSA DSA ECDSA ED25519
2022-04-20T16:00:43.290402287Z * Starting sshd ... [ ok ]
2022-04-20T16:00:43.296606026Z ## Printing build info...
2022-04-20T16:00:43.300022547Z PACKAGE | VERSION | COMMIT
2022-04-20T16:00:43.300040448Z Microsoft.AppService.WebsitesExtensionsJava | 1.0.015010001-alpha-9b3c66d6 | 9b3c66d6
2022-04-20T16:00:43.300055748Z self | 1.0.017140001-alpha-dce9cbe8 | dce9cbe8
2022-04-20T16:00:43.301742858Z ## Done printing build info.
2022-04-20T16:00:43.318547564Z Add public certificates to keystore if exists...
2022-04-20T16:00:43.320055373Z Add private certificates to keystore if exists...
2022-04-20T16:00:43.320461876Z Configuring max heap = 4878 MB
2022-04-20T16:00:43.345112931Z STARTUP_FILE=
2022-04-20T16:00:43.345141431Z STARTUP_COMMAND=java -Xmx5g -Djava.net.preferIPv4Stack=true -jar /home/site/wwwroot/metabase.jar
2022-04-20T16:00:43.345146931Z No STARTUP_FILE available.
2022-04-20T16:00:43.345764135Z Running STARTUP_COMMAND: java -Xmx5g -Djava.net.preferIPv4Stack=true -jar /home/site/wwwroot/metabase.jar
2022-04-20T16:00:43.580842012Z Picked up JAVA_TOOL_OPTIONS: -Xmx4878M -Djava.net.preferIPv4Stack=true
2022-04-20T16:00:46.631674978Z WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
2022-04-20T16:00:48.733124180Z 2022-04-20 16:00:48,731 INFO metabase.util :: Maximum memory available to JVM: 5.0 GB
2022-04-20T16:01:03.627803904Z 2022-04-20 16:01:03,627 INFO util.encryption :: Saved credentials encryption is DISABLED for this Metabase instance.
2022-04-20T16:01:07.745709923Z 2022-04-20 16:01:07,745 INFO driver.impl :: e[34mRegistered abstract driver :sqle[0m
2022-04-20T16:01:07.750854458Z e[36m ⮦ Load driver :sql took 833.0 mse[0m
2022-04-20T16:01:07.760621024Z 2022-04-20 16:01:07,760 INFO driver.impl :: e[34mRegistered abstract driver :sql-jdbce[0m (parents: [:sql])
2022-04-20T16:01:07.766254863Z e[32mLoad driver :sql-jdbc took 853.0 mse[0m
2022-04-20T16:01:07.767388471Z 2022-04-20 16:01:07,766 INFO driver.impl :: e[34mRegistered driver :h2e[0m (parents: [:sql-jdbc])
2022-04-20T16:01:07.803099014Z 2022-04-20 16:01:07,802 INFO driver.impl :: e[34mRegistered driver :mysqle[0m (parents: [:sql-jdbc])
2022-04-20T16:01:07.828136485Z 2022-04-20 16:01:07,827 INFO driver.impl :: e[34mRegistered driver :postgrese[0m (parents: [:sql-jdbc])
2022-04-20T16:01:11.426877956Z 2022-04-20 16:01:11,417 INFO metabase.core ::
2022-04-20T16:01:11.426936457Z Metabase v0.42.4 (7c3ce2d release-x.42.x)
2022-04-20T16:01:11.426944357Z
2022-04-20T16:01:11.426948757Z Copyright © 2022 Metabase, Inc.
2022-04-20T16:01:11.426954057Z
2022-04-20T16:01:11.426958157Z Metabase Enterprise Edition extensions are NOT PRESENT.
2022-04-20T16:01:11.443246268Z 2022-04-20 16:01:11,442 INFO metabase.core :: Starting Metabase in STANDALONE mode
2022-04-20T16:01:11.506587001Z 2022-04-20 16:01:11,505 INFO metabase.server :: Launching Embedded Jetty Webserver with config:
2022-04-20T16:01:11.506680801Z {:port 80}
2022-04-20T16:01:11.506709501Z
2022-04-20T16:01:11.568618224Z 2022-04-20 16:01:11,568 INFO metabase.core :: Starting Metabase version v0.42.4 (7c3ce2d release-x.42.x) ...
2022-04-20T16:01:11.617825360Z 2022-04-20 16:01:11,617 INFO metabase.core :: System info:
2022-04-20T16:01:11.617905761Z {"file.encoding" "UTF-8",
2022-04-20T16:01:11.617911761Z "java.runtime.name" "OpenJDK Runtime Environment",
2022-04-20T16:01:11.617916061Z "java.runtime.version" "11.0.12+7-LTS",
2022-04-20T16:01:11.617920061Z "java.vendor" "Azul Systems, Inc.",
2022-04-20T16:01:11.617927861Z "java.version" "11.0.12",
2022-04-20T16:01:11.617931561Z "java.vm.name" "OpenJDK 64-Bit Server VM",
2022-04-20T16:01:11.617935461Z "java.vm.version" "11.0.12+7-LTS",
2022-04-20T16:01:11.617939161Z "os.name" "Linux",
2022-04-20T16:01:11.617942861Z "os.version" "4.15.0-162-generic",
2022-04-20T16:01:11.617975161Z "user.language" "en",
2022-04-20T16:01:11.617979561Z "user.timezone" "GMT"}
2022-04-20T16:01:11.617983461Z
2022-04-20T16:01:11.619899374Z 2022-04-20 16:01:11,619 INFO metabase.plugins :: Loading plugins in /plugins...
2022-04-20T16:01:11.811096780Z 2022-04-20 16:01:11,808 INFO util.files :: Extract file /modules/sparksql.metabase-driver.jar -> /plugins/sparksql.metabase-driver.jar
2022-04-20T16:01:12.418604928Z 2022-04-20 16:01:12,417 INFO util.files :: Extract file /modules/bigquery.metabase-driver.jar -> /plugins/bigquery.metabase-driver.jar
2022-04-20T16:01:12.427524188Z 2022-04-20 16:01:12,427 INFO util.files :: Extract file /modules/sqlserver.metabase-driver.jar -> /plugins/sqlserver.metabase-driver.jar
2022-04-20T16:01:12.439348169Z 2022-04-20 16:01:12,439 INFO util.files :: Extract file /modules/presto-jdbc.metabase-driver.jar -> /plugins/presto-jdbc.metabase-driver.jar
2022-04-20T16:01:12.515311788Z 2022-04-20 16:01:12,514 INFO util.files :: Extract file /modules/sqlite.metabase-driver.jar -> /plugins/sqlite.metabase-driver.jar
2022-04-20T16:01:12.541608467Z 2022-04-20 16:01:12,541 INFO util.files :: Extract file /modules/vertica.metabase-driver.jar -> /plugins/vertica.metabase-driver.jar
2022-04-20T16:01:12.543257279Z 2022-04-20 16:01:12,542 INFO util.files :: Extract file /modules/redshift.metabase-driver.jar -> /plugins/redshift.metabase-driver.jar
2022-04-20T16:01:12.552670243Z 2022-04-20 16:01:12,552 INFO util.files :: Extract file /modules/presto.metabase-driver.jar -> /plugins/presto.metabase-driver.jar
2022-04-20T16:01:12.554779957Z 2022-04-20 16:01:12,554 INFO util.files :: Extract file /modules/druid.metabase-driver.jar -> /plugins/druid.metabase-driver.jar
2022-04-20T16:01:12.561231201Z 2022-04-20 16:01:12,560 INFO util.files :: Extract file /modules/mongo.metabase-driver.jar -> /plugins/mongo.metabase-driver.jar
2022-04-20T16:01:12.584923663Z 2022-04-20 16:01:12,584 INFO util.files :: Extract file /modules/google.metabase-driver.jar -> /plugins/google.metabase-driver.jar
2022-04-20T16:01:12.597648550Z 2022-04-20 16:01:12,597 INFO util.files :: Extract file /modules/oracle.metabase-driver.jar -> /plugins/oracle.metabase-driver.jar
2022-04-20T16:01:12.599531063Z 2022-04-20 16:01:12,599 INFO util.files :: Extract file /modules/snowflake.metabase-driver.jar -> /plugins/snowflake.metabase-driver.jar
2022-04-20T16:01:12.822452885Z 2022-04-20 16:01:12,821 INFO util.files :: Extract file /modules/googleanalytics.metabase-driver.jar -> /plugins/googleanalytics.metabase-driver.jar
2022-04-20T16:01:12.830886142Z 2022-04-20 16:01:12,828 INFO util.files :: Extract file /modules/bigquery-cloud-sdk.metabase-driver.jar -> /plugins/bigquery-cloud-sdk.metabase-driver.jar
2022-04-20T16:01:12.893979573Z 2022-04-20 16:01:12,893 INFO util.files :: Extract file /modules/presto-common.metabase-driver.jar -> /plugins/presto-common.metabase-driver.jar
2022-04-20T16:01:13.072023289Z 2022-04-20 16:01:13,071 INFO plugins.dependencies :: Plugin 'Metabase BigQuery Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
2022-04-20T16:01:13.074182004Z 2022-04-20 16:01:13,073 INFO plugins.dependencies :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? false
2022-04-20T16:01:13.085805183Z 2022-04-20 16:01:13,085 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase BigQuery Driver"]e[0m
2022-04-20T16:01:13.094321041Z 2022-04-20 16:01:13,092 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :sqlite...e[0m
2022-04-20T16:01:13.102805199Z 2022-04-20 16:01:13,095 INFO driver.impl :: e[34mRegistered driver :sqlitee[0m (parents: [:sql-jdbc])
2022-04-20T16:01:13.108003035Z 2022-04-20 16:01:13,107 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :mongo...e[0m
2022-04-20T16:01:13.108573738Z 2022-04-20 16:01:13,108 INFO driver.impl :: e[34mRegistered driver :mongoe[0m
2022-04-20T16:01:13.113179670Z 2022-04-20 16:01:13,112 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :druid...e[0m
2022-04-20T16:01:13.113845574Z 2022-04-20 16:01:13,113 INFO driver.impl :: e[34mRegistered driver :druide[0m
2022-04-20T16:01:13.119129510Z 2022-04-20 16:01:13,118 INFO plugins.dependencies :: Plugin 'Metabase Google Analytics Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
2022-04-20T16:01:13.119593514Z 2022-04-20 16:01:13,119 INFO plugins.dependencies :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? false
2022-04-20T16:01:13.120214818Z 2022-04-20 16:01:13,119 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase BigQuery Driver" "Metabase Google Analytics Driver"]e[0m
2022-04-20T16:01:13.125735556Z 2022-04-20 16:01:13,125 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :sqlserver...e[0m
2022-04-20T16:01:13.126464461Z 2022-04-20 16:01:13,126 INFO driver.impl :: e[34mRegistered driver :sqlservere[0m (parents: [:sql-jdbc])
2022-04-20T16:01:13.150195723Z 2022-04-20 16:01:13,149 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :snowflake...e[0m
2022-04-20T16:01:13.151084529Z 2022-04-20 16:01:13,150 INFO driver.impl :: e[34mRegistered driver :snowflakee[0m (parents: [:sql-jdbc])
2022-04-20T16:01:13.155474659Z 2022-04-20 16:01:13,155 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :google...e[0m
2022-04-20T16:01:13.158308878Z 2022-04-20 16:01:13,158 INFO driver.impl :: e[34mRegistered abstract driver :googlee[0m
2022-04-20T16:01:13.159235484Z 2022-04-20 16:01:13,158 INFO plugins.dependencies :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
2022-04-20T16:01:13.159936389Z 2022-04-20 16:01:13,159 INFO plugins.dependencies :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
2022-04-20T16:01:13.163423613Z 2022-04-20 16:01:13,163 DEBUG plugins.initialize :: e[33mDependencies satisfied; these plugins will now be loaded: ["Metabase Google Analytics Driver" "Metabase BigQuery Driver"]e[0m
2022-04-20T16:01:13.164715922Z 2022-04-20 16:01:13,164 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :googleanalytics...e[0m
2022-04-20T16:01:13.166071731Z 2022-04-20 16:01:13,164 INFO driver.impl :: e[34mRegistered driver :googleanalyticse[0m (parents: [:google])
2022-04-20T16:01:13.167680442Z 2022-04-20 16:01:13,167 WARN plugins.lazy-loaded-driver :: e[31mWarning: plugin manifest for :bigquery does not include connection propertiese[0m
2022-04-20T16:01:13.168319146Z 2022-04-20 16:01:13,167 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :bigquery...e[0m
2022-04-20T16:01:13.170988365Z 2022-04-20 16:01:13,168 INFO driver.impl :: e[34mRegistered driver :bigquerye[0m (parents: [:sql :google])
2022-04-20T16:01:13.178068713Z 2022-04-20 16:01:13,177 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :redshift...e[0m
2022-04-20T16:01:13.182553444Z 2022-04-20 16:01:13,182 INFO driver.impl :: e[34mRegistered driver :redshifte[0m (parents: [:postgres])
2022-04-20T16:01:13.200282565Z 2022-04-20 16:01:13,194 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :bigquery-cloud-sdk...e[0m
2022-04-20T16:01:13.202080077Z 2022-04-20 16:01:13,201 INFO driver.impl :: e[34mRegistered driver :bigquery-cloud-sdke[0m (parents: [:sql])
2022-04-20T16:01:13.217342681Z 2022-04-20 16:01:13,216 INFO plugins.dependencies :: e[31mMetabase cannot initialize plugin Metabase Vertica Driver due to required dependencies.e[0m 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 url for more details.
2022-04-20T16:01:13.217375881Z
2022-04-20T16:01:13.224008127Z 2022-04-20 16:01:13,223 INFO plugins.dependencies :: Metabase Vertica Driver dependency {:class com.vertica.jdbc.Driver} satisfied? false
2022-04-20T16:01:13.225170134Z 2022-04-20 16:01:13,224 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Vertica Driver"]e[0m
2022-04-20T16:01:13.230186269Z 2022-04-20 16:01:13,229 INFO plugins.dependencies :: Plugin 'Metabase Presto Driver' depends on plugin 'Presto Common Driver'
2022-04-20T16:01:13.235478705Z 2022-04-20 16:01:13,235 INFO plugins.dependencies :: Metabase Presto Driver dependency {:plugin Presto Common Driver} satisfied? false
2022-04-20T16:01:13.238378825Z 2022-04-20 16:01:13,235 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Presto Driver" "Metabase Vertica Driver"]e[0m
2022-04-20T16:01:13.256133846Z 2022-04-20 16:01:13,255 INFO plugins.dependencies :: Plugin 'Metabase Presto JDBC Driver' depends on plugin 'Presto Common Driver'
2022-04-20T16:01:13.256729250Z 2022-04-20 16:01:13,256 INFO plugins.dependencies :: Metabase Presto JDBC Driver dependency {:plugin Presto Common Driver} satisfied? false
2022-04-20T16:01:13.257251354Z 2022-04-20 16:01:13,256 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Presto JDBC Driver" "Metabase Presto Driver" "Metabase Vertica Driver"]e[0m
2022-04-20T16:01:13.260630677Z 2022-04-20 16:01:13,260 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :presto-common...e[0m
2022-04-20T16:01:13.263356395Z 2022-04-20 16:01:13,263 INFO driver.impl :: e[34mRegistered abstract driver :presto-commone[0m
2022-04-20T16:01:13.264478503Z 2022-04-20 16:01:13,264 INFO plugins.dependencies :: Metabase Presto JDBC Driver dependency {:plugin Presto Common Driver} satisfied? true
2022-04-20T16:01:13.265868712Z 2022-04-20 16:01:13,265 INFO plugins.dependencies :: Metabase Presto Driver dependency {:plugin Presto Common Driver} satisfied? true
2022-04-20T16:01:13.271269449Z 2022-04-20 16:01:13,271 DEBUG plugins.initialize :: e[33mDependencies satisfied; these plugins will now be loaded: ["Metabase Presto Driver" "Metabase Presto JDBC Driver"]e[0m
2022-04-20T16:01:13.275959081Z 2022-04-20 16:01:13,275 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :presto...e[0m
2022-04-20T16:01:13.278885201Z 2022-04-20 16:01:13,278 INFO driver.impl :: e[34mRegistered driver :prestoe[0m (parents: [:presto-common])
2022-04-20T16:01:13.282013323Z 2022-04-20 16:01:13,281 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :presto-jdbc...e[0m
2022-04-20T16:01:13.284799442Z 2022-04-20 16:01:13,284 INFO driver.impl :: e[34mRegistered driver :presto-jdbce[0m (parents: [:presto-common])
2022-04-20T16:01:13.290058978Z 2022-04-20 16:01:13,289 INFO plugins.dependencies :: e[31mMetabase cannot initialize plugin Metabase Oracle Driver due to required dependencies.e[0m 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 url for more details.
2022-04-20T16:01:13.290078678Z
2022-04-20T16:01:13.291624088Z 2022-04-20 16:01:13,291 INFO plugins.dependencies :: Metabase Oracle Driver dependency {:class oracle.jdbc.OracleDriver} satisfied? false
2022-04-20T16:01:13.294639509Z 2022-04-20 16:01:13,294 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Oracle Driver" "Metabase Vertica Driver"]e[0m
2022-04-20T16:01:13.445893042Z 2022-04-20 16:01:13,445 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :hive-like...e[0m
2022-04-20T16:01:13.448497459Z 2022-04-20 16:01:13,448 INFO driver.impl :: e[34mRegistered abstract driver :hive-likee[0m (parents: [:sql-jdbc])
2022-04-20T16:01:13.450400272Z 2022-04-20 16:01:13,450 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :sparksql...e[0m
2022-04-20T16:01:13.452280185Z 2022-04-20 16:01:13,452 INFO driver.impl :: e[34mRegistered driver :sparksqle[0m (parents: [:hive-like])
2022-04-20T16:01:13.453513294Z 2022-04-20 16:01:13,453 INFO metabase.core :: Setting up and migrating Metabase DB. Please sit tight, this may take a minute...
2022-04-20T16:01:13.459731136Z 2022-04-20 16:01:13,459 INFO db.setup :: e[36mVerifying postgres Database Connection ...e[0m
2022-04-20T16:01:15.415691767Z 2022-04-20 16:01:15,415 INFO db.setup :: Successfully verified PostgreSQL 10.17 application database connection.
2022-04-20T16:01:15.417162578Z 2022-04-20 16:01:15,416 INFO db.setup :: Running Database Migrations...
2022-04-20T16:01:16.228536325Z 2022-04-20 16:01:16,228 INFO db.setup :: Setting up Liquibase...
2022-04-20T16:01:16.661056289Z 2022-04-20 16:01:16,660 INFO db.setup :: Liquibase is ready.
2022-04-20T16:01:16.661570893Z 2022-04-20 16:01:16,661 INFO db.liquibase :: Checking if Database has unrun migrations...

2022-04-20T16:01:19.979271895Z 2022-04-20T16:01:20.109328617Z 2022-04-20T16:01:20.570502884Z 2022-04-20T16:01:20.570540384Z 2022-04-20T16:01:20.570547384Z 2022-04-20T16:01:20.570552184Z 2022-04-20T16:01:20.570556884Z 2022-04-20T16:01:20.570561484Z 2022-04-20T16:01:20.570566084Z 2022-04-20T16:01:20.570570584Z 2022-04-20T16:01:20.570574984Z 2022-04-20T16:01:20.570579384Z 2022-04-20T16:01:20.570583784Z 2022-04-20T16:01:20.570588284Z 2022-04-20T16:01:20.570592784Z 2022-04-20T16:01:20.570597184Z 2022-04-20T16:01:20.570601484Z 2022-04-20T16:01:20.570605784Z 2022-04-20T16:01:20.570610184Z 2022-04-20T16:01:20.570614585Z 2022-04-20T16:01:20.570618985Z 2022-04-20T16:01:20.570623285Z 2022-04-20T16:01:20.570627785Z 2022-04-20T16:01:20.570632285Z 2022-04-20T16:01:20.652834767Z 2022-04-20T16:01:20.652950768Z 2022-04-20T16:01:20.652956568Z 2022-04-20T16:01:20.652960268Z 2022-04-20T16:01:20.652963668Z 2022-04-20T16:01:20.652967168Z 2022-04-20T16:01:20.652970568Z 2022-04-20T16:01:20.652991668Z 2022-04-20T16:01:20.652995168Z 2022-04-20T16:01:20.652998768Z 2022-04-20T16:01:20.653002168Z 2022-04-20T16:01:20.653005768Z 2022-04-20T16:01:20.653009268Z 2022-04-20T16:01:20.653012668Z 2022-04-20T16:01:20.653016168Z 2022-04-20T16:01:20.653019668Z 2022-04-20T16:01:20.653023068Z 2022-04-20T16:01:20.653026468Z 2022-04-20T16:01:20.653029968Z 2022-04-20T16:01:20.653033368Z 2022-04-20T16:01:20.653037968Z 2022-04-20T16:01:20.653041668Z 2022-04-20T16:01:20.653045268Z 2022-04-20T16:01:21.394800623Z 2022-04-20T16:01:21.394845723Z 2022-04-20T16:01:21.394852223Z 2022-04-20T16:01:21.394856823Z 2022-04-20T16:01:21.394860923Z 2022-04-20T16:01:21.394865023Z 2022-04-20T16:01:21.394869124Z 2022-04-20T16:01:21.394873324Z 2022-04-20T16:01:21.394891224Z 2022-04-20T16:01:21.394895424Z 2022-04-20T16:01:21.394899324Z 2022-04-20T16:01:21.394903424Z 2022-04-20T16:01:21.394907224Z 2022-04-20T16:01:21.394911224Z 2022-04-20T16:01:21.394915024Z 2022-04-20T16:01:21.394918924Z 2022-04-20T16:01:21.394922824Z 2022-04-20T16:01:21.394926724Z 2022-04-20T16:01:21.394930624Z 2022-04-20T16:01:21.394934724Z 2022-04-20T16:01:21.394938824Z 2022-04-20T16:01:21.394942824Z 2022-04-20T16:01:21.474912691Z 2022-04-20T16:01:21.474959791Z 2022-04-20T16:01:21.474965091Z 2022-04-20T16:01:21.474969191Z 2022-04-20T16:01:21.474972991Z 2022-04-20T16:01:21.474976791Z 2022-04-20T16:01:21.474980491Z 2022-04-20T16:01:21.474984091Z 2022-04-20T16:01:21.474987691Z 2022-04-20T16:01:21.474991191Z 2022-04-20T16:01:21.474994791Z 2022-04-20T16:01:21.474998391Z 2022-04-20T16:01:21.475002091Z 2022-04-20T16:01:21.475005591Z 2022-04-20T16:01:21.475009191Z 2022-04-20T16:01:21.475012591Z 2022-04-20T16:01:21.475034891Z 2022-04-20T16:01:21.475039491Z 2022-04-20T16:01:21.475042991Z 2022-04-20T16:01:21.475046591Z 2022-04-20T16:01:21.475049992Z 2022-04-20T16:01:21.475053692Z 2022-04-20T16:01:21.475057292Z 2022-04-20T16:01:22.165402514Z 2022-04-20T16:01:22.165435014Z 2022-04-20T16:01:22.165440814Z 2022-04-20T16:01:22.165444614Z 2022-04-20T16:01:22.165448414Z 2022-04-20T16:01:22.165452114Z 2022-04-20T16:01:22.165455814Z 2022-04-20T16:01:22.165459514Z 2022-04-20T16:01:22.165463014Z 2022-04-20T16:01:22.165466614Z 2022-04-20T16:01:22.165470114Z 2022-04-20T16:01:22.165473814Z 2022-04-20T16:01:22.165477414Z 2022-04-20T16:01:22.165480914Z 2022-04-20T16:01:22.165484314Z 2022-04-20T16:01:22.165487814Z 2022-04-20T16:01:22.165491414Z 2022-04-20T16:01:22.165494914Z 2022-04-20T16:01:22.165498414Z 2022-04-20T16:01:22.165502015Z 2022-04-20T16:01:22.165505615Z 2022-04-20T16:01:22.165509215Z 2022-04-20 16:01:19,978 INFO db.liquibase :: Database has unrun migrations. Waiting for migration lock to be cleared...
2022-04-20 16:01:20,108 INFO db.liquibase :: Migration lock is cleared. Running migrations...
2022-04-20 16:01:20,570 ERROR changelog.ChangeSet :: Change Set migrations/000_migrations.yaml::304::camsaul failed. Error: ERROR: column "semantic_type" does not exist
Position: 1034 [Failed SQL: UPDATE metabase_field SET semantic_type = (CASE semantic_type
WHEN 'avatar' THEN 'type/AvatarURL'
WHEN 'category' THEN 'type/Category'
WHEN 'city' THEN 'type/City'
WHEN 'country' THEN 'type/Country'
WHEN 'desc' THEN 'type/Description'
WHEN 'fk' THEN 'type/FK'
WHEN 'id' THEN 'type/PK'
WHEN 'image' THEN 'type/ImageURL'
WHEN 'json' THEN 'type/SerializedJSON'
WHEN 'latitude' THEN 'type/Latitude'
WHEN 'longitude' THEN 'type/Longitude'
WHEN 'name' THEN 'type/Name'
WHEN 'number' THEN 'type/Number'
WHEN 'state' THEN 'type/State'
WHEN 'url' THEN 'type/URL'
WHEN 'zip_code' THEN 'type/ZipCode'
END)
WHERE semantic_type IN ('avatar', 'category', 'city', 'country', 'desc', 'fk', 'id', 'image',
'json', 'latitude', 'longitude', 'name', 'number', 'state', 'url',
'zip_code')]
2022-04-20 16:01:20,652 WARN metabase.util :: e[31mauto-retry metabase.db.liquibase$migrate_up_if_needed_BANG_$fn__14370@30265f75: Migration failed for change set migrations/000_migrations.yaml::304::camsaul:
Reason: liquibase.exception.DatabaseException: ERROR: column "semantic_type" does not exist
Position: 1034 [Failed SQL: UPDATE metabase_field SET semantic_type = (CASE semantic_type
WHEN 'avatar' THEN 'type/AvatarURL'
WHEN 'category' THEN 'type/Category'
WHEN 'city' THEN 'type/City'
WHEN 'country' THEN 'type/Country'
WHEN 'desc' THEN 'type/Description'
WHEN 'fk' THEN 'type/FK'
WHEN 'id' THEN 'type/PK'
WHEN 'image' THEN 'type/ImageURL'
WHEN 'json' THEN 'type/SerializedJSON'
WHEN 'latitude' THEN 'type/Latitude'
WHEN 'longitude' THEN 'type/Longitude'
WHEN 'name' THEN 'type/Name'
WHEN 'number' THEN 'type/Number'
WHEN 'state' THEN 'type/State'
WHEN 'url' THEN 'type/URL'
WHEN 'zip_code' THEN 'type/ZipCode'
END)
WHERE semantic_type IN ('avatar', 'category', 'city', 'country', 'desc', 'fk', 'id', 'image',
'json', 'latitude', 'longitude', 'name', 'number', 'state', 'url',
'zip_code')]e[0m
2022-04-20 16:01:21,394 ERROR changelog.ChangeSet :: Change Set migrations/000_migrations.yaml::304::camsaul failed. Error: ERROR: column "semantic_type" does not exist
Position: 1034 [Failed SQL: UPDATE metabase_field SET semantic_type = (CASE semantic_type
WHEN 'avatar' THEN 'type/AvatarURL'
WHEN 'category' THEN 'type/Category'
WHEN 'city' THEN 'type/City'
WHEN 'country' THEN 'type/Country'
WHEN 'desc' THEN 'type/Description'
WHEN 'fk' THEN 'type/FK'
WHEN 'id' THEN 'type/PK'
WHEN 'image' THEN 'type/ImageURL'
WHEN 'json' THEN 'type/SerializedJSON'
WHEN 'latitude' THEN 'type/Latitude'
WHEN 'longitude' THEN 'type/Longitude'
WHEN 'name' THEN 'type/Name'
WHEN 'number' THEN 'type/Number'
WHEN 'state' THEN 'type/State'
WHEN 'url' THEN 'type/URL'
WHEN 'zip_code' THEN 'type/ZipCode'
END)
WHERE semantic_type IN ('avatar', 'category', 'city', 'country', 'desc', 'fk', 'id', 'image',
'json', 'latitude', 'longitude', 'name', 'number', 'state', 'url',
'zip_code')]
2022-04-20 16:01:21,474 WARN metabase.util :: e[31mauto-retry metabase.db.liquibase$migrate_up_if_needed_BANG_$fn__14370@30265f75: Migration failed for change set migrations/000_migrations.yaml::304::camsaul:
Reason: liquibase.exception.DatabaseException: ERROR: column "semantic_type" does not exist
Position: 1034 [Failed SQL: UPDATE metabase_field SET semantic_type = (CASE semantic_type
WHEN 'avatar' THEN 'type/AvatarURL'
WHEN 'category' THEN 'type/Category'
WHEN 'city' THEN 'type/City'
WHEN 'country' THEN 'type/Country'
WHEN 'desc' THEN 'type/Description'
WHEN 'fk' THEN 'type/FK'
WHEN 'id' THEN 'type/PK'
WHEN 'image' THEN 'type/ImageURL'
WHEN 'json' THEN 'type/SerializedJSON'
WHEN 'latitude' THEN 'type/Latitude'
WHEN 'longitude' THEN 'type/Longitude'
WHEN 'name' THEN 'type/Name'
WHEN 'number' THEN 'type/Number'
WHEN 'state' THEN 'type/State'
WHEN 'url' THEN 'type/URL'
WHEN 'zip_code' THEN 'type/ZipCode'
END)
WHERE semantic_type IN ('avatar', 'category', 'city', 'country', 'desc', 'fk', 'id', 'image',
'json', 'latitude', 'longitude', 'name', 'number', 'state', 'url',
'zip_code')]e[0m
2022-04-20 16:01:22,161 ERROR changelog.ChangeSet :: Change Set migrations/000_migrations.yaml::304::camsaul failed. Error: ERROR: column "semantic_type" does not exist
Position: 1034 [Failed SQL: UPDATE metabase_field SET semantic_type = (CASE semantic_type
WHEN 'avatar' THEN 'type/AvatarURL'
WHEN 'category' THEN 'type/Category'
WHEN 'city' THEN 'type/City'
WHEN 'country' THEN 'type/Country'
WHEN 'desc' THEN 'type/Description'
WHEN 'fk' THEN 'type/FK'
WHEN 'id' THEN 'type/PK'
WHEN 'image' THEN 'type/ImageURL'
WHEN 'json' THEN 'type/SerializedJSON'
WHEN 'latitude' THEN 'type/Latitude'
WHEN 'longitude' THEN 'type/Longitude'
WHEN 'name' THEN 'type/Name'
WHEN 'number' THEN 'type/Number'
WHEN 'state' THEN 'type/State'
WHEN 'url' THEN 'type/URL'
WHEN 'zip_code' THEN 'type/ZipCode'
END)
WHERE semantic_type IN ('avatar', 'category', 'city', 'country', 'desc', 'fk', 'id', 'image',
'json', 'latitude', 'longitude', 'name', 'number', 'state', 'url',
'zip_code')]`

flamber · April 20, 2022, 6:31pm

Hi @jsacra
I'm guessing that you upgraded to 0.39+ at some point and then downgraded to pre-39 again, which required that you manually had to rename a column to make it work. Correct?
Then manually rename metabase_field.special_type to metabase_field.semantic_type
That will fix your problem.

jsacra · April 20, 2022, 7:33pm

Thank you for your quick reply!

Yes we did upgrade and then revert. I'll try this fix.

jsacra · April 20, 2022, 7:42pm

For reference, could Metabase take longer than 60 minutes to start?

flamber · April 20, 2022, 7:50pm

@jsacra It should take 30-40 seconds to start Metabase, but I don't know where you're stuck - show your logs.
Sounds like you are running out of entropy: https://github.com/metabase/metabase/issues/10175

jsacra · April 20, 2022, 7:57pm

This portion of the logs is repeated every (roughly) 2-3 minutes.

2022-04-20T18:31:19.678967288Z _____
2022-04-20T18:31:19.679082589Z / _ \ __________ _________ ____
2022-04-20T18:31:19.679088489Z / /\ ___ / | _ __ _/ __ \
2022-04-20T18:31:19.679092489Z / | / /| | /| | /\ ___/
2022-04-20T18:31:19.679096189Z _| /_____ _/ || __ >
2022-04-20T18:31:19.679100089Z / / /
2022-04-20T18:31:19.679103689Z A P P S E R V I C E O N L I N U X
2022-04-20T18:31:19.679107289Z Documentation:
2022-04-20T18:31:19.679110789Z
2022-04-20T18:31:19.679114289Z NOTE: No files or system changes outside of /home will persist beyond your application's current session. /home is your application's persistent storage and is shared across all the server instances.
2022-04-20T18:31:19.679120789Z
2022-04-20T18:31:19.679124189Z
2022-04-20T18:31:19.679463892Z Setup openrc ...
2022-04-20T18:31:19.848875057Z Service machine-id' needs non existent servicedev'
2022-04-20T18:31:19.848955258Z * Caching service dependencies ... [ ok ]
2022-04-20T18:31:19.853794697Z Updating /etc/ssh/sshd_config to use PORT 2222
2022-04-20T18:31:19.858992139Z Starting ssh service...
2022-04-20T18:31:20.172345565Z ssh-keygen: generating new host keys: RSA DSA ECDSA ED25519
2022-04-20T18:31:21.215075111Z * Starting sshd ... [ ok ]
2022-04-20T18:31:21.224047384Z ## Printing build info...
2022-04-20T18:31:21.225756598Z PACKAGE | VERSION | COMMIT
2022-04-20T18:31:21.225772698Z Microsoft.AppService.WebsitesExtensionsJava | 1.0.015010001-alpha-9b3c66d6 | 9b3c66d6
2022-04-20T18:31:21.225778398Z self | 1.0.017140001-alpha-dce9cbe8 | dce9cbe8
2022-04-20T18:31:21.226340503Z ## Done printing build info.
2022-04-20T18:31:21.232647154Z Add public certificates to keystore if exists...
2022-04-20T18:31:21.232936856Z Add private certificates to keystore if exists...
2022-04-20T18:31:21.233330859Z Configuring max heap = 4878 MB
2022-04-20T18:31:21.244219048Z STARTUP_FILE=
2022-04-20T18:31:21.244298848Z STARTUP_COMMAND=java -Xmx5g -Djava.net.preferIPv4Stack=true -jar /home/site/wwwroot/metabase.jar
2022-04-20T18:31:21.244309349Z No STARTUP_FILE available.
2022-04-20T18:31:21.244528750Z Running STARTUP_COMMAND: java -Xmx5g -Djava.net.preferIPv4Stack=true -jar /home/site/wwwroot/metabase.jar
2022-04-20T18:31:21.303348528Z Picked up JAVA_TOOL_OPTIONS: -Xmx4878M -Djava.net.preferIPv4Stack=true
2022-04-20T18:31:23.916547629Z WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
2022-04-20T18:31:25.787517009Z 2022-04-20 18:31:25,784 INFO metabase.util :: Maximum memory available to JVM: 5.0 GB
2022-04-20T18:31:39.687044843Z 2022-04-20 18:31:39,686 INFO util.encryption :: Saved credentials encryption is DISABLED for this Metabase instance.
2022-04-20T18:31:39.687104644Z For more information, see
2022-04-20T18:31:43.751272322Z 2022-04-20 18:31:43,750 INFO driver.impl :: e[34mRegistered abstract driver :sqle[0m
2022-04-20T18:31:43.757513074Z e[36m ⮦ Load driver :sql took 851.9 mse[0m
2022-04-20T18:31:43.765284137Z 2022-04-20 18:31:43,765 INFO driver.impl :: e[34mRegistered abstract driver :sql-jdbce[0m (parents: [:sql])
2022-04-20T18:31:43.770843483Z e[32mLoad driver :sql-jdbc took 869.7 mse[0m
2022-04-20T18:31:43.771788591Z 2022-04-20 18:31:43,771 INFO driver.impl :: e[34mRegistered driver :h2e[0m (parents: [:sql-jdbc])
2022-04-20T18:31:43.795589686Z 2022-04-20 18:31:43,795 INFO driver.impl :: e[34mRegistered driver :mysqle[0m (parents: [:sql-jdbc])
2022-04-20T18:31:43.829672866Z 2022-04-20 18:31:43,829 INFO driver.impl :: e[34mRegistered driver :postgrese[0m (parents: [:sql-jdbc])
2022-04-20T18:31:47.589880033Z 2022-04-20 18:31:47,581 INFO metabase.core ::
2022-04-20T18:31:47.589931333Z Metabase v0.42.4 (7c3ce2d release-x.42.x)
2022-04-20T18:31:47.589939833Z
2022-04-20T18:31:47.589944133Z Copyright © 2022 Metabase, Inc.
2022-04-20T18:31:47.589949033Z
2022-04-20T18:31:47.589952933Z Metabase Enterprise Edition extensions are NOT PRESENT.
2022-04-20T18:31:47.593944866Z 2022-04-20 18:31:47,593 INFO metabase.core :: Starting Metabase in STANDALONE mode
2022-04-20T18:31:47.647173999Z 2022-04-20 18:31:47,646 INFO metabase.server :: Launching Embedded Jetty Webserver with config:
2022-04-20T18:31:47.647219899Z {:port 80}
2022-04-20T18:31:47.647227800Z
2022-04-20T18:31:47.718280378Z 2022-04-20 18:31:47,717 INFO metabase.core :: Starting Metabase version v0.42.4 (7c3ce2d release-x.42.x) ...
2022-04-20T18:31:47.771937015Z 2022-04-20 18:31:47,771 INFO metabase.core :: System info:
2022-04-20T18:31:47.771987116Z {"file.encoding" "UTF-8",
2022-04-20T18:31:47.771995016Z "java.runtime.name" "OpenJDK Runtime Environment",
2022-04-20T18:31:47.771999916Z "java.runtime.version" "11.0.12+7-LTS",
2022-04-20T18:31:47.772004416Z "java.vendor" "Azul Systems, Inc.",
2022-04-20T18:31:47.772008916Z "java.vendor.url" "http://www.azul.com/",
2022-04-20T18:31:47.772013216Z "java.version" "11.0.12",
2022-04-20T18:31:47.772017616Z "java.vm.name" "OpenJDK 64-Bit Server VM",
2022-04-20T18:31:47.772021816Z "java.vm.version" "11.0.12+7-LTS",
2022-04-20T18:31:47.772026016Z "os.name" "Linux",
2022-04-20T18:31:47.772030216Z "os.version" "4.15.0-162-generic",
2022-04-20T18:31:47.772048216Z "user.language" "en",
2022-04-20T18:31:47.772053916Z "user.timezone" "GMT"}
2022-04-20T18:31:47.772058316Z
2022-04-20T18:31:47.779592277Z 2022-04-20 18:31:47,779 INFO metabase.plugins :: Loading plugins in /plugins...
2022-04-20T18:31:47.962494467Z 2022-04-20 18:31:47,962 INFO util.files :: Extract file /modules/sparksql.metabase-driver.jar -> /plugins/sparksql.metabase-driver.jar
2022-04-20T18:31:48.414584949Z 2022-04-20 18:31:48,414 INFO util.files :: Extract file /modules/bigquery.metabase-driver.jar -> /plugins/bigquery.metabase-driver.jar
2022-04-20T18:31:48.431027983Z 2022-04-20 18:31:48,430 INFO util.files :: Extract file /modules/sqlserver.metabase-driver.jar -> /plugins/sqlserver.metabase-driver.jar
2022-04-20T18:31:48.444035489Z 2022-04-20 18:31:48,443 INFO util.files :: Extract file /modules/presto-jdbc.metabase-driver.jar -> /plugins/presto-jdbc.metabase-driver.jar
2022-04-20T18:31:48.571324125Z 2022-04-20 18:31:48,570 INFO util.files :: Extract file /modules/sqlite.metabase-driver.jar -> /plugins/sqlite.metabase-driver.jar
2022-04-20T18:31:48.611469252Z 2022-04-20 18:31:48,610 INFO util.files :: Extract file /modules/vertica.metabase-driver.jar -> /plugins/vertica.metabase-driver.jar
2022-04-20T18:31:48.612956864Z 2022-04-20 18:31:48,612 INFO util.files :: Extract file /modules/redshift.metabase-driver.jar -> /plugins/redshift.metabase-driver.jar
2022-04-20T18:31:48.630141604Z 2022-04-20 18:31:48,629 INFO util.files :: Extract file /modules/presto.metabase-driver.jar -> /plugins/presto.metabase-driver.jar
2022-04-20T18:31:48.633310530Z 2022-04-20 18:31:48,633 INFO util.files :: Extract file /modules/druid.metabase-driver.jar -> /plugins/druid.metabase-driver.jar
2022-04-20T18:31:48.638320171Z 2022-04-20 18:31:48,638 INFO util.files :: Extract file /modules/mongo.metabase-driver.jar -> /plugins/mongo.metabase-driver.jar
2022-04-20T18:31:48.676180179Z 2022-04-20 18:31:48,675 INFO util.files :: Extract file /modules/google.metabase-driver.jar -> /plugins/google.metabase-driver.jar
2022-04-20T18:31:48.710822861Z 2022-04-20 18:31:48,710 INFO util.files :: Extract file /modules/oracle.metabase-driver.jar -> /plugins/oracle.metabase-driver.jar
2022-04-20T18:31:48.713688084Z 2022-04-20 18:31:48,713 INFO util.files :: Extract file /modules/snowflake.metabase-driver.jar -> /plugins/snowflake.metabase-driver.jar
2022-04-20T18:31:48.797112064Z 2022-04-20 18:31:48,793 INFO middleware.exceptions :: Request canceled before finishing.
2022-04-20T18:31:49.117438973Z 2022-04-20 18:31:49,116 INFO util.files :: Extract file /modules/googleanalytics.metabase-driver.jar -> /plugins/googleanalytics.metabase-driver.jar
2022-04-20T18:31:49.124815533Z 2022-04-20 18:31:49,124 INFO util.files :: Extract file /modules/bigquery-cloud-sdk.metabase-driver.jar -> /plugins/bigquery-cloud-sdk.metabase-driver.jar
2022-04-20T18:31:49.214965767Z 2022-04-20 18:31:49,214 INFO util.files :: Extract file /modules/presto-common.metabase-driver.jar -> /plugins/presto-common.metabase-driver.jar
2022-04-20T18:31:49.519842350Z 2022-04-20 18:31:49,519 INFO plugins.dependencies :: e[31mMetabase cannot initialize plugin Metabase Oracle Driver due to required dependencies.e[0m 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.
2022-04-20T18:31:49.519894350Z
2022-04-20T18:31:49.523618080Z 2022-04-20 18:31:49,523 INFO plugins.dependencies :: Metabase Oracle Driver dependency {:class oracle.jdbc.OracleDriver} satisfied? false
2022-04-20T18:31:49.538550502Z 2022-04-20 18:31:49,538 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Oracle Driver"]e[0m
2022-04-20T18:31:49.545518559Z 2022-04-20 18:31:49,545 INFO plugins.dependencies :: Plugin 'Metabase Google Analytics Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
2022-04-20T18:31:49.546052063Z 2022-04-20 18:31:49,545 INFO plugins.dependencies :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? false
2022-04-20T18:31:49.546668168Z 2022-04-20 18:31:49,546 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Google Analytics Driver" "Metabase Oracle Driver"]e[0m
2022-04-20T18:31:49.550379398Z 2022-04-20 18:31:49,550 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :presto-common...e[0m
2022-04-20T18:31:49.551136504Z 2022-04-20 18:31:49,550 INFO driver.impl :: e[34mRegistered abstract driver :presto-commone[0m
2022-04-20T18:31:49.665334534Z 2022-04-20 18:31:49,664 INFO plugins.dependencies :: Plugin 'Metabase Presto JDBC Driver' depends on plugin 'Presto Common Driver'
2022-04-20T18:31:49.665903139Z 2022-04-20 18:31:49,665 INFO plugins.dependencies :: Metabase Presto JDBC Driver dependency {:plugin Presto Common Driver} satisfied? true
2022-04-20T18:31:49.667897555Z 2022-04-20 18:31:49,667 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :presto-jdbc...e[0m
2022-04-20T18:31:49.669127365Z 2022-04-20 18:31:49,668 INFO driver.impl :: e[34mRegistered driver :presto-jdbce[0m (parents: [:presto-common])
2022-04-20T18:31:49.688883326Z 2022-04-20 18:31:49,688 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :sqlserver...e[0m
2022-04-20T18:31:49.690044536Z 2022-04-20 18:31:49,689 INFO driver.impl :: e[34mRegistered driver :sqlservere[0m (parents: [:sql-jdbc])
2022-04-20T18:31:49.705194459Z 2022-04-20 18:31:49,704 INFO plugins.dependencies :: Plugin 'Metabase BigQuery Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
2022-04-20T18:31:49.706155267Z 2022-04-20 18:31:49,705 INFO plugins.dependencies :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? false
2022-04-20T18:31:49.709613495Z 2022-04-20 18:31:49,709 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Google Analytics Driver" "Metabase Oracle Driver" "Metabase BigQuery Driver"]e[0m
2022-04-20T18:31:49.719013272Z 2022-04-20 18:31:49,718 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :mongo...e[0m
2022-04-20T18:31:49.736742816Z 2022-04-20 18:31:49,730 INFO driver.impl :: e[34mRegistered driver :mongoe[0m
2022-04-20T18:31:49.742624464Z 2022-04-20 18:31:49,742 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :sqlite...e[0m
2022-04-20T18:31:49.743454371Z 2022-04-20 18:31:49,743 INFO driver.impl :: e[34mRegistered driver :sqlitee[0m (parents: [:sql-jdbc])
2022-04-20T18:31:49.761673719Z 2022-04-20 18:31:49,761 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :bigquery-cloud-sdk...e[0m
2022-04-20T18:31:49.762659127Z 2022-04-20 18:31:49,762 INFO driver.impl :: e[34mRegistered driver :bigquery-cloud-sdke[0m (parents: [:sql])
2022-04-20T18:31:49.810470816Z 2022-04-20 18:31:49,809 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :snowflake...e[0m
2022-04-20T18:31:49.813428440Z 2022-04-20 18:31:49,813 INFO driver.impl :: e[34mRegistered driver :snowflakee[0m (parents: [:sql-jdbc])
2022-04-20T18:31:49.826270045Z 2022-04-20 18:31:49,825 INFO plugins.dependencies :: e[31mMetabase cannot initialize plugin Metabase Vertica Driver due to required dependencies.e[0m 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 url for more details.
2022-04-20T18:31:49.826327946Z
2022-04-20T18:31:49.827246153Z 2022-04-20 18:31:49,826 INFO plugins.dependencies :: Metabase Vertica Driver dependency {:class com.vertica.jdbc.Driver} satisfied? false
2022-04-20T18:31:49.828065660Z 2022-04-20 18:31:49,827 INFO plugins.dependencies :: e[33mPlugins with unsatisfied deps: ["Metabase Google Analytics Driver" "Metabase Oracle Driver" "Metabase Vertica Driver" "Metabase BigQuery Driver"]e[0m
2022-04-20T18:31:49.839835556Z 2022-04-20 18:31:49,839 INFO plugins.dependencies :: Plugin 'Metabase Presto Driver' depends on plugin 'Presto Common Driver'
2022-04-20T18:31:49.843333484Z 2022-04-20 18:31:49,843 INFO plugins.dependencies :: Metabase Presto Driver dependency {:plugin Presto Common Driver} satisfied? true
2022-04-20T18:31:49.849462634Z 2022-04-20 18:31:49,849 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :presto...e[0m
2022-04-20T18:31:49.852902362Z 2022-04-20 18:31:49,852 INFO driver.impl :: e[34mRegistered driver :prestoe[0m (parents: [:presto-common])
2022-04-20T18:31:49.865861567Z 2022-04-20 18:31:49,865 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :druid...e[0m
2022-04-20T18:31:49.868706091Z 2022-04-20 18:31:49,868 INFO driver.impl :: e[34mRegistered driver :druide[0m
2022-04-20T18:31:49.877650763Z 2022-04-20 18:31:49,876 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :google...e[0m
2022-04-20T18:31:49.879404678Z 2022-04-20 18:31:49,879 INFO driver.impl :: e[34mRegistered abstract driver :googlee[0m
2022-04-20T18:31:49.880695888Z 2022-04-20 18:31:49,880 INFO plugins.dependencies :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
2022-04-20T18:31:49.882531603Z 2022-04-20 18:31:49,882 INFO plugins.dependencies :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
2022-04-20T18:31:49.883712113Z 2022-04-20 18:31:49,883 DEBUG plugins.initialize :: e[33mDependencies satisfied; these plugins will now be loaded: ["Metabase BigQuery Driver" "Metabase Google Analytics Driver"]e[0m
2022-04-20T18:31:49.884655221Z 2022-04-20 18:31:49,884 WARN plugins.lazy-loaded-driver :: e[31mWarning: plugin manifest for :bigquery does not include connection propertiese[0m
2022-04-20T18:31:49.885636728Z 2022-04-20 18:31:49,885 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :bigquery...e[0m
2022-04-20T18:31:49.886965139Z 2022-04-20 18:31:49,886 INFO driver.impl :: e[34mRegistered driver :bigquerye[0m (parents: [:sql :google])
2022-04-20T18:31:49.891469276Z 2022-04-20 18:31:49,891 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :googleanalytics...e[0m
2022-04-20T18:31:49.892338083Z 2022-04-20 18:31:49,892 INFO driver.impl :: e[34mRegistered driver :googleanalyticse[0m (parents: [:google])
2022-04-20T18:31:49.909235521Z 2022-04-20 18:31:49,908 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :redshift...e[0m
2022-04-20T18:31:49.913389755Z 2022-04-20 18:31:49,913 INFO driver.impl :: e[34mRegistered driver :redshifte[0m (parents: [:postgres])
2022-04-20T18:31:49.979806595Z 2022-04-20 18:31:49,979 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :hive-like...e[0m
2022-04-20T18:31:50.009897140Z 2022-04-20 18:31:50,009 INFO driver.impl :: e[34mRegistered abstract driver :hive-likee[0m (parents: [:sql-jdbc])
2022-04-20T18:31:50.011214251Z 2022-04-20 18:31:50,010 DEBUG plugins.lazy-loaded-driver :: e[35mRegistering lazy loading driver :sparksql...e[0m
2022-04-20T18:31:50.014491878Z 2022-04-20 18:31:50,014 INFO driver.impl :: e[34mRegistered driver :sparksqle[0m (parents: [:hive-like])
2022-04-20T18:31:50.017891706Z 2022-04-20 18:31:50,017 INFO metabase.core :: Setting up and migrating Metabase DB. Please sit tight, this may take a minute...
2022-04-20T18:31:50.031295815Z 2022-04-20 18:31:50,030 INFO db.setup :: e[36mVerifying postgres Database Connection ...e[0m
2022-04-20T18:31:52.024564947Z 2022-04-20 18:31:52,024 INFO db.setup :: Successfully verified PostgreSQL 10.17 application database connection.
2022-04-20T18:31:52.025784757Z 2022-04-20 18:31:52,025 INFO db.setup :: Running Database Migrations...
2022-04-20T18:31:52.769395012Z 2022-04-20 18:31:52,768 INFO db.setup :: Setting up Liquibase...
2022-04-20T18:31:53.208565686Z 2022-04-20 18:31:53,207 INFO db.setup :: Liquibase is ready.
2022-04-20T18:31:53.209512194Z 2022-04-20 18:31:53,209 INFO db.liquibase :: Checking if Database has unrun migrations...

2022-04-20T18:31:56.161693924Z 2022-04-20 18:31:56,161 INFO db.liquibase :: Database has unrun migrations. Waiting for migration lock to be cleared...
2022-04-20T18:31:58.205166757Z 2022-04-20 18:31:58,204 WARN metabase.util :: e[31mauto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__14367@7c7da6e9: Database has migration lock; cannot run migrations. You can force-release these locks by running java -jar metabase.jar migrate release-locks.e[0m

2022-04-20T18:32:00.247300579Z 2022-04-20 18:32:00,246 WARN metabase.util :: e[31mauto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__14367@7c7da6e9: Database has migration lock; cannot run migrations. You can force-release these locks by running java -jar metabase.jar migrate release-locks.e[0m
2022-04-20T18:32:02.290309094Z 2022-04-20 18:32:02,289 WARN metabase.util :: e[31mauto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__14367@7c7da6e9: Database has migration lock; cannot run migrations. You can force-release these locks by running java -jar metabase.jar migrate release-locks.e[0m

2022-04-20T18:32:04.330355283Z 2022-04-20 18:32:04,329 WARN metabase.util :: e[31mauto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__14367@7c7da6e9: Database has migration lock; cannot run migrations. You can force-release these locks by running java -jar metabase.jar migrate release-locks.e[0m
2022-04-20T18:32:06.370827376Z 2022-04-20 18:32:06,370 WARN metabase.util :: e[31mauto-retry metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__14367@7c7da6e9: Database has migration lock; cannot run migrations. You can force-release these locks by running java -jar metabase.jar migrate release-locks.e[0m
2022-04-20T18:32:08.457501444Z 2022-04-20 18:32:08,450 ERROR metabase.core :: Metabase Initialization FAILED
2022-04-20T18:32:08.457538244Z 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.
2022-04-20T18:32:08.457544644Z at metabase.db.liquibase$wait_for_migration_lock_to_be_cleared$fn__14367.invoke(liquibase.clj:109)
2022-04-20T18:32:08.457549244Z at metabase.util$do_with_auto_retries.invokeStatic(util.clj:478)
2022-04-20T18:32:08.457553445Z at metabase.util$do_with_auto_retries.invoke(util.clj:470)
2022-04-20T18:32:08.457557545Z at metabase.util$do_with_auto_retries.invokeStatic(util.clj:485)
2022-04-20T18:32:08.457561745Z at metabase.util$do_with_auto_retries.invoke(util.clj:470)
2022-04-20T18:32:08.457565445Z at metabase.util$do_with_auto_retries.invokeStatic(util.clj:485)
2022-04-20T18:32:08.457569245Z at metabase.util$do_with_auto_retries.invoke(util.clj:470)
2022-04-20T18:32:08.457573045Z at metabase.util$do_with_auto_retries.invokeStatic(util.clj:485)
2022-04-20T18:32:08.457576945Z at metabase.util$do_with_auto_retries.invoke(util.clj:470)
2022-04-20T18:32:08.457580645Z at metabase.util$do_with_auto_retries.invokeStatic(util.clj:485)
2022-04-20T18:32:08.457584545Z at metabase.util$do_with_auto_retries.invoke(util.clj:470)
2022-04-20T18:32:08.457588345Z at metabase.util$do_with_auto_retries.invokeStatic(util.clj:485)
2022-04-20T18:32:08.457592145Z at metabase.util$do_with_auto_retries.invoke(util.clj:470)
2022-04-20T18:32:08.457595945Z at metabase.db.liquibase$wait_for_migration_lock_to_be_cleared.invokeStatic(liquibase.clj:104)
2022-04-20T18:32:08.457612745Z at metabase.db.liquibase$wait_for_migration_lock_to_be_cleared.invoke(liquibase.clj:100)
2022-04-20T18:32:08.457617345Z at metabase.db.liquibase$migrate_up_if_needed_BANG_.invokeStatic(liquibase.clj:120)
2022-04-20T18:32:08.457621245Z at metabase.db.liquibase$migrate_up_if_needed_BANG_.invoke(liquibase.clj:114)
2022-04-20T18:32:08.457624945Z at metabase.db.setup$migrate_BANG_$fn__34026$fn__34027.invoke(setup.clj:68)
2022-04-20T18:32:08.457628745Z at metabase.db.liquibase$do_with_liquibase.invokeStatic(liquibase.clj:38)
2022-04-20T18:32:08.457632545Z at metabase.db.liquibase$do_with_liquibase.invoke(liquibase.clj:30)
2022-04-20T18:32:08.457636345Z at metabase.db.setup$migrate_BANG_$fn__34026.invoke(setup.clj:63)
2022-04-20T18:32:08.457640045Z at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:807)
2022-04-20T18:32:08.457643945Z at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776)
2022-04-20T18:32:08.457647645Z at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:852)
2022-04-20T18:32:08.457651445Z at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776)
2022-04-20T18:32:08.457656345Z at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:789)
2022-04-20T18:32:08.457660345Z at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776)
2022-04-20T18:32:08.457664145Z at metabase.db.setup$migrate_BANG_.invokeStatic(setup.clj:54)
2022-04-20T18:32:08.457668045Z at metabase.db.setup$migrate_BANG_.invoke(setup.clj:40)
2022-04-20T18:32:08.457671745Z at metabase.db.setup$run_schema_migrations_BANG_.invokeStatic(setup.clj:119)
2022-04-20T18:32:08.457675646Z at metabase.db.setup$run_schema_migrations_BANG_.invoke(setup.clj:115)
2022-04-20T18:32:08.457679846Z at metabase.db.setup$setup_db_BANG_$fn__34077$fn__34078.invoke(setup.clj:143)
2022-04-20T18:32:08.457683746Z at metabase.util$do_with_us_locale.invokeStatic(util.clj:699)
2022-04-20T18:32:08.457687446Z at metabase.util$do_with_us_locale.invoke(util.clj:685)
2022-04-20T18:32:08.457691146Z at metabase.db.setup$setup_db_BANG_$fn__34077.invoke(setup.clj:141)
2022-04-20T18:32:08.457694946Z at metabase.db.setup$setup_db_BANG_.invokeStatic(setup.clj:140)
2022-04-20T18:32:08.457698846Z at metabase.db.setup$setup_db_BANG_.invoke(setup.clj:136)
2022-04-20T18:32:08.457702546Z at metabase.db$setup_db_BANG_$fn__34187.invoke(db.clj:61)
2022-04-20T18:32:08.457706346Z at metabase.db$setup_db_BANG_.invokeStatic(db.clj:56)
2022-04-20T18:32:08.457710046Z at metabase.db$setup_db_BANG_.invoke(db.clj:51)
2022-04-20T18:32:08.457713846Z at metabase.core$init_BANG_.invokeStatic(core.clj:91)
2022-04-20T18:32:08.457717546Z at metabase.core$init_BANG_.invoke(core.clj:74)
2022-04-20T18:32:08.457721346Z at metabase.core$start_normally.invokeStatic(core.clj:132)
2022-04-20T18:32:08.457728546Z at metabase.core$start_normally.invoke(core.clj:126)
2022-04-20T18:32:08.457732746Z at metabase.core$_main.invokeStatic(core.clj:165)
2022-04-20T18:32:08.457736546Z at metabase.core$_main.doInvoke(core.clj:159)
2022-04-20T18:32:08.457740346Z at clojure.lang.RestFn.invoke(RestFn.java:397)
2022-04-20T18:32:08.457744046Z at clojure.lang.AFn.applyToHelper(AFn.java:152)
2022-04-20T18:32:08.457747746Z at clojure.lang.RestFn.applyTo(RestFn.java:132)
2022-04-20T18:32:08.457751546Z at metabase.core.main(Unknown Source)
2022-04-20T18:32:08.460592669Z 2022-04-20 18:32:08,460 INFO metabase.core :: Metabase Shutting Down ...
2022-04-20T18:32:08.460797571Z 2022-04-20 18:32:08,460 INFO metabase.server :: Shutting Down Embedded Jetty Webserver
2022-04-20T18:32:08.470545450Z 2022-04-20 18:32:08,470 INFO metabase.core :: Metabase Shutdown COMPLETE

2022-04-20T18:32:08.833578504Z Finished running startup file 'java -Xmx5g -Djava.net.preferIPv4Stack=true -jar /home/site/wwwroot/metabase.jar'. Exit code: '1'.
2022-04-20T18:32:08.833625504Z Custom startup complete. Now, exiting with exit code '1'

jsacra · April 20, 2022, 8:05pm

As I'm simply placing the jar in the App Service and restarting it, I can't directly run the .jar with the remove-lock command. Is there another I could do this?

flamber · April 20, 2022, 8:07pm

@jsacra Shutdown Metabase. Go to the application database table databasechangeloglock and truncate it or unlock the row and start Metabase again.

jsacra · April 21, 2022, 8:42am

This fixed it. Thank you very much for your help.