Hello all, I'm having an issue I'm hoping someone might be able to help with:
We've been using metabase for the last 6 months, now all of a sudden after a server reboot, metabase won't start. The logs show metabase initialization failed java.lang.exception: timed out after 5.0 s
then lower down java.util.concurrent.timeoutexception.
This started happening out of the blue, I haven't made any changes to metabase or the ubuntu server it's running on. I restored a backup of the entire vm from 10 days ago and it's having the same issue.
Any help would be greatly appreciated.
Hi @mti_jason
Too much information is lost in that little screenshot of the log.
It’s most likely not able to connect to the application database, but I cannot say for sure.
Thank you, hopefully these will come over better. That's what it seems like to me as well, like it's timing out connecting to the database, but I'm not sure why all of a sudden, and these logs are from trying to start metabase from a restored VM from when it was running perfectly well.
Here’s the direct text without the screenshot, thank you again for any help you can provide:
01-26 15:22:43 ^[[1mERROR metabase.core^[[0m :: Metabase Initialization FAILED
java.lang.Exception: Timed out after 5.0 s
at metabase.driver.util$can_connect_with_details_QMARK_.invokeStatic(util.clj:40)
at metabase.driver.util$can_connect_with_details_QMARK_.doInvoke(util.clj:23)
at clojure.lang.RestFn.invoke(RestFn.java:442)
at clojure.lang.Var.invoke(Var.java:393)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793$fn__21794.invoke(db.clj:309)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793.invoke(db.clj:308)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21791.invoke(db.clj:303)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$setup_db_BANG__STAR_$fn__21829.invoke(db.clj:345)
at metabase.util$do_with_us_locale.invokeStatic(util.clj:656)
at metabase.util$do_with_us_locale.invoke(util.clj:642)
at metabase.db$setup_db_BANG__STAR_.invokeStatic(db.clj:344)
at metabase.db$setup_db_BANG__STAR_.invoke(db.clj:339)
at metabase.db$setup_db_from_env_BANG_.invokeStatic(db.clj:358)
at metabase.db$setup_db_from_env_BANG_.invoke(db.clj:351)
at metabase.db$setup_db_BANG_$fn__21834.invoke(db.clj:368)
at metabase.db$setup_db_BANG_.invokeStatic(db.clj:366)
at metabase.db$setup_db_BANG_.invoke(db.clj:361)
at metabase.core$init_BANG_.invokeStatic(core.clj:75)
at metabase.util$do_with_us_locale.invokeStatic(util.clj:656)
at metabase.util$do_with_us_locale.invoke(util.clj:642)
at metabase.db$setup_db_BANG__STAR_.invokeStatic(db.clj:344)
at metabase.db$setup_db_BANG__STAR_.invoke(db.clj:339)
at metabase.db$setup_db_from_env_BANG_.invokeStatic(db.clj:358)
at metabase.db$setup_db_from_env_BANG_.invoke(db.clj:351)
at metabase.db$setup_db_BANG_$fn__21834.invoke(db.clj:368)
at metabase.db$setup_db_BANG_.invokeStatic(db.clj:366)
at metabase.db$setup_db_BANG_.invoke(db.clj:361)
at metabase.core$init_BANG_.invokeStatic(core.clj:75)
at metabase.core$init_BANG_.invoke(core.clj:54)
at metabase.core$start_normally.invokeStatic(core.clj:119)
at metabase.core$start_normally.invoke(core.clj:113)
at metabase.core$main.invokeStatic(core.clj:152)
at metabase.core$main.doInvoke(core.clj:146)
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)
01-26 15:22:43 ^[[1mERROR metabase.core^[[0m :: Metabase Initialization FAILED
java.lang.Exception: Timed out after 5.0 s
at metabase.driver.util$can_connect_with_details_QMARK.invokeStatic(util.clj:40)
at metabase.driver.util$can_connect_with_details_QMARK.doInvoke(util.clj:23)
at clojure.lang.RestFn.invoke(RestFn.java:442)
at clojure.lang.Var.invoke(Var.java:393)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793$fn__21794.invoke(db.clj:309)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793.invoke(db.clj:308)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21791.invoke(db.clj:303)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$setup_db_BANG__STAR_$fn__21829.invoke(db.clj:345)
at metabase.util$do_with_us_locale.invokeStatic(util.clj:656)
at metabase.db$setup_db_BANG__STAR_.invokeStatic(db.clj:344)
at metabase.db$setup_db_BANG__STAR_.invoke(db.clj:339)
at metabase.db$setup_db_from_env_BANG_.invokeStatic(db.clj:358)
at metabase.db$setup_db_from_env_BANG_.invoke(db.clj:351)
at metabase.db$setup_db_BANG_$fn__21834.invoke(db.clj:368)
at metabase.db$setup_db_BANG_.invokeStatic(db.clj:366)
at metabase.db$setup_db_BANG_.invoke(db.clj:361)
at metabase.core$init_BANG_.invokeStatic(core.clj:75)
at metabase.core$init_BANG_.invoke(core.clj:54)
at metabase.core$start_normally.invokeStatic(core.clj:119)
at metabase.core$start_normally.invoke(core.clj:113)
at metabase.core$_main.invokeStatic(core.clj:152)
at metabase.core$main.doInvoke(core.clj:146)
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)
Caused by: java.util.concurrent.TimeoutException: Timed out after 5.0 s
at metabase.util$deref_with_timeout.invokeStatic(util.clj:301)
at metabase.util$deref_with_timeout.invoke(util.clj:293)
at metabase.util$do_with_timeout.invokeStatic(util.clj:307)
at metabase.util$do_with_timeout.invoke(util.clj:304)
at metabase.driver.util$can_connect_with_details_QMARK.invokeStatic(util.clj:34)
… 28 more
01-26 15:22:43 ^[[1mINFO metabase.core^[[0m :: Metabase Shutting Down …
01-26 15:22:43 ^[[1mINFO metabase.server^[[0m :: Shutting Down Embedded Jetty Webserver
01-26 15:22:43 ^[[1mINFO metabase.core^[[0m :: Metabase Shutdown COMPLETE
@mti_jason But it’s everything before the timeout that is interesting - the log from startup to shutdown.
My apologies, I misunderstood, here is the complete log:
01-26 15:22:08 ^[[1mINFO metabase.util^[[0m :: Loading Metabase…
01-26 15:22:08 ^[[1mINFO metabase.util^[[0m :: Maximum memory available to JVM: 986.0 MB
01-26 15:22:26 ^[[1mINFO util.encryption^[[0m :: 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
01-26 15:22:36 ^[[1mWARN metabase.core^[[0m :: WARNING: You have enabled namespace tracing, which could log sensitive information like db passwords.
01-26 15:22:36 ^[[1mINFO metabase.core^[[0m :: Starting Metabase in STANDALONE mode
01-26 15:22:36 ^[[1mINFO metabase.server^[[0m :: Launching Embedded Jetty Webserver with config:
{:port 3000, :host “0.0.0.0”}
01-26 15:22:36 ^[[1mINFO metabase.core^[[0m :: Starting Metabase version v0.36.5.1 (a3459e8 release-0.36.x) …
01-26 15:22:36 ^[[1mINFO metabase.core^[[0m :: System info:
{“file.encoding” “UTF-8”,
“java.runtime.name” “OpenJDK Runtime Environment”,
“java.runtime.version” “11.0.8+10”,
“java.vendor” “AdoptOpenJDK”,
“java.vendor.url” “https://adoptopenjdk.net/”,
“java.version” “11.0.8”,
“java.vm.name” “OpenJDK 64-Bit Server VM”,
“java.vm.version” “11.0.8+10”,
“os.name” “Linux”,
“os.version” “5.4.0-59-generic”,
“user.language” “en”,
“user.timezone” “GMT”}
01-26 15:22:36 ^[[1mINFO metabase.plugins^[[0m :: Loading plugins in /plugins…
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :presto…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered abstract driver :sql^[[0m 
^[[32mLoad driver :sql took 201.7 ms^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :presto^[[0m (parents: [:sql])
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :druid…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :druid^[[0m
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: ^[[31mMetabase cannot initialize plugin Metabase Vertica Driver due to required dependencies.^[[0m Metabase requir>
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: Metabase Vertica Driver dependency {:class com.vertica.jdbc.Driver} satisfied? false
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: ^[[33mPlugins with unsatisfied deps: [“Metabase Vertica Driver”]^[[0m
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :sqlserver…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered abstract driver :sql-jdbc^[[0m (parents: [:sql])
^[[32mLoad driver :sql-jdbc took 69.7 ms^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :sqlserver^[[0m (parents: [:sql-jdbc])
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: Plugin ‘Metabase Google Analytics Driver’ depends on plugin ‘Metabase Google Drivers Shared Dependencies’
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? false
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: ^[[33mPlugins with unsatisfied deps: [“Metabase Google Analytics Driver” “Metabase Vertica Driver”]^[[0m
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :snowflake…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :snowflake^[[0m (parents: [:sql-jdbc])
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :google…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered abstract driver :google^[[0m
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
01-26 15:22:37 ^[[1mDEBUG plugins.initialize^[[0m :: ^[[33mDependencies satisfied; these plugins will now be loaded: [“Metabase Google Analytics Driver”]^[[0m
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :googleanalytics…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :googleanalytics^[[0m (parents: [:google])
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :redshift…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :postgres^[[0m (parents: [:sql-jdbc])
^[[32mLoad driver :postgres took 32.2 ms^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :redshift^[[0m (parents: [:postgres])
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :sqlite…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :sqlite^[[0m (parents: [:sql-jdbc])
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :hive-like…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered abstract driver :hive-like^[[0m (parents: [:sql-jdbc])
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :sparksql…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :sparksql^[[0m (parents: [:hive-like])
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: Plugin ‘Metabase BigQuery Driver’ depends on plugin ‘Metabase Google Drivers Shared Dependencies’
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
01-26 15:22:37 ^[[1mWARN plugins.lazy-loaded-driver^[[0m :: ^[[31mWarning: plugin manifest for :bigquery does not include connection properties^[[0m
01-26 15:22:37 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :bigquery…^[[0m
01-26 15:22:37 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :bigquery^[[0m (parents: [:sql :google])
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: ^[[31mMetabase cannot initialize plugin Metabase Oracle Driver due to required dependencies.^[[0m Metabase require>
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: Metabase Oracle Driver dependency {:class oracle.jdbc.OracleDriver} satisfied? false
01-26 15:22:37 ^[[1mINFO plugins.dependencies^[[0m :: ^[[33mPlugins with unsatisfied deps: [“Metabase Vertica Driver” “Metabase Oracle Driver”]^[[0m
01-26 15:22:38 ^[[1mDEBUG plugins.lazy-loaded-driver^[[0m :: ^[[35mRegistering lazy loading driver :mongo…^[[0m
01-26 15:22:38 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :mongo^[[0m
01-26 15:22:38 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :h2^[[0m (parents: [:sql-jdbc])
01-26 15:22:38 ^[[1mINFO driver.impl^[[0m :: ^[[34mRegistered driver :mysql^[[0m (parents: [:sql-jdbc])
01-26 15:22:38 ^[[1mINFO metabase.core^[[0m :: Setting up and migrating Metabase DB. Please sit tight, this may take a minute…
01-26 15:22:38 ^[[1mWARN metabase.db^[[0m :: ^[[31mWARNING: Using Metabase with an H2 application database is not recommended for production deployments. For production>
01-26 15:22:38 ^[[1mINFO metabase.db^[[0m :: ^[[36mVerifying h2 Database Connection …^[[0m
01-26 15:22:38 ^[[1mINFO driver.impl^[[0m :: ^[[33mInitializing driver :sql…^[[0m
01-26 15:22:38 ^[[1mINFO driver.impl^[[0m :: ^[[33mInitializing driver :sql-jdbc…^[[0m
01-26 15:22:38 ^[[1mINFO driver.impl^[[0m :: ^[[33mInitializing driver :h2…^[[0m
01-26 15:22:43 ^[[1mERROR driver.util^[[0m :: Database connection error
java.util.concurrent.TimeoutException: Timed out after 5.0 s
at metabase.util$deref_with_timeout.invokeStatic(util.clj:301)
at metabase.util$deref_with_timeout.invoke(util.clj:293)
at metabase.util$do_with_timeout.invokeStatic(util.clj:307)
at metabase.util$do_with_timeout.invoke(util.clj:304)
at metabase.driver.util$can_connect_with_details_QMARK_.invokeStatic(util.clj:34)
at metabase.driver.util$can_connect_with_details_QMARK_.doInvoke(util.clj:23)
at clojure.lang.RestFn.invoke(RestFn.java:442)
at clojure.lang.Var.invoke(Var.java:393)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793$fn__21794.invoke(db.clj:309)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793.invoke(db.clj:308)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21791.invoke(db.clj:303)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$setup_db_BANG__STAR_$fn__21829.invoke(db.clj:345)
at metabase.util$do_with_us_locale.invokeStatic(util.clj:656)
at metabase.util$do_with_us_locale.invoke(util.clj:642)
at metabase.db$setup_db_BANG__STAR_.invokeStatic(db.clj:344)
at metabase.db$setup_db_BANG__STAR_.invoke(db.clj:339)
at metabase.db$setup_db_from_env_BANG_.invokeStatic(db.clj:358)
at metabase.db$setup_db_from_env_BANG_.invoke(db.clj:351)
at metabase.db$setup_db_BANG_$fn__21834.invoke(db.clj:368)
at metabase.db$setup_db_BANG_.invokeStatic(db.clj:366)
at metabase.db$setup_db_BANG_.invoke(db.clj:361)
at metabase.core$init_BANG_.invokeStatic(core.clj:75)
at metabase.core$init_BANG_.invoke(core.clj:54)
at metabase.core$start_normally.invokeStatic(core.clj:119)
at metabase.core$start_normally.invoke(core.clj:113)
at metabase.core$main.invokeStatic(core.clj:152)
at metabase.core$main.doInvoke(core.clj:146)
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)
01-26 15:22:43 ^[[1mERROR metabase.core^[[0m :: Metabase Initialization FAILED
java.lang.Exception: Timed out after 5.0 s
at metabase.driver.util$can_connect_with_details_QMARK.invokeStatic(util.clj:40)
at metabase.driver.util$can_connect_with_details_QMARK.doInvoke(util.clj:23)
at clojure.lang.RestFn.invoke(RestFn.java:442)
at clojure.lang.Var.invoke(Var.java:393)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793$fn__21794.invoke(db.clj:309)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21793.invoke(db.clj:308)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$fn__21781$verify_db_connection__21790$fn__21791.invoke(db.clj:303)
at metabase.db$fn__21781$verify_db_connection__21790.invoke(db.clj:300)
at metabase.db$setup_db_BANG__STAR_$fn__21829.invoke(db.clj:345)
at metabase.util$do_with_us_locale.invokeStatic(util.clj:656)
at metabase.util$do_with_us_locale.invoke(util.clj:642)
at metabase.db$setup_db_BANG__STAR_.invokeStatic(db.clj:344)
at metabase.db$setup_db_BANG__STAR_.invoke(db.clj:339)
at metabase.db$setup_db_from_env_BANG_.invokeStatic(db.clj:358)
at metabase.db$setup_db_from_env_BANG_.invoke(db.clj:351)
at metabase.db$setup_db_BANG_$fn__21834.invoke(db.clj:368)
at metabase.db$setup_db_BANG_.invokeStatic(db.clj:366)
at metabase.db$setup_db_BANG_.invoke(db.clj:361)
at metabase.core$init_BANG_.invokeStatic(core.clj:75)
at metabase.core$init_BANG_.invoke(core.clj:54)
at metabase.core$start_normally.invokeStatic(core.clj:119)
at metabase.core$start_normally.invoke(core.clj:113)
at metabase.core$_main.invokeStatic(core.clj:152)
at metabase.core$main.doInvoke(core.clj:146)
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)
Caused by: java.util.concurrent.TimeoutException: Timed out after 5.0 s
at metabase.util$deref_with_timeout.invokeStatic(util.clj:301)
at metabase.util$deref_with_timeout.invoke(util.clj:293)
at metabase.util$do_with_timeout.invokeStatic(util.clj:307)
at metabase.util$do_with_timeout.invoke(util.clj:304)
at metabase.driver.util$can_connect_with_details_QMARK.invokeStatic(util.clj:34)
… 28 more
01-26 15:22:43 ^[[1mINFO metabase.core^[[0m :: Metabase Shutting Down …
01-26 15:22:43 ^[[1mINFO metabase.server^[[0m :: Shutting Down Embedded Jetty Webserver
01-26 15:22:43 ^[[1mINFO metabase.core^[[0m :: Metabase Shutdown COMPLETE
@mti_jason It looks like your H2 application database is corrupted (or for some other reason borked).
https://www.metabase.com/docs/latest/troubleshooting-guide/application-database.html
You need to get the H2 into a working state and then migrate away from it:
https://www.metabase.com/docs/latest/operations-guide/migrating-from-h2.html
Latest release is 0.37.7
how would you suggest getting the H2 into a working state?
