java.lang.Exception: Timed out after 5,000 milliseconds

We are running a metabase instance v0.32.9 on AWS using elastic beanstalk. The instance has been running great for about two weeks. All of a sudden things stopped responding, so I pulled the logs. Unfortunately the metabase error message is not very helpful and I’m not sure exactly where to debug. The main error message is java.lang.Exception: Timed out after 5,000 milliseconds. and it seems tto be related to loading a driver. Nothing has changed from our deployment and we use the elastic beanstalk deployment file from https://downloads.metabase.com/v0.32.9/metabase-aws-eb.zip

Here’s the full log output:

07-15 09:08:26 e[1mDEBUG plugins.classloadere[0m :: Using NEWLY CREATED classloader as shared context classloader: clojure.lang.DynamicClassLoader@ceb4bd2
07-15 09:08:26 e[1mDEBUG plugins.classloadere[0m :: Setting current thread context classloader to shared classloader clojure.lang.DynamicClassLoader@ceb4bd2...
07-15 09:08:27 e[1mINFO metabase.utile[0m :: Loading Metabase...
07-15 09:08:27 e[1mINFO metabase.utile[0m :: Maximum memory available to JVM: 483.4 MB
07-15 09:08:39 e[1mINFO util.encryptione[0m :: Saved credentials encryption is ENABLED for this Metabase instance. πŸ” 
 For more information, see https://metabase.com/docs/latest/operations-guide/start.html#encrypting-your-database-connection-details-at-rest
07-15 09:08:47 e[1mINFO metabase.drivere[0m :: e[34mRegistered abstract driver :sqle[0m  🚚
07-15 09:08:55 e[1mINFO metabase.coree[0m :: Starting Metabase in STANDALONE mode
07-15 09:08:55 e[1mINFO metabase.servere[0m :: Launching Embedded Jetty Webserver with config: 
 {:port 3000, :host "0.0.0.0"}

07-15 09:08:55 e[1mINFO metabase.coree[0m :: Starting Metabase version v0.32.9 (8f933a1 release-0.32.x) ...
07-15 09:08:55 e[1mINFO metabase.coree[0m :: System timezone is 'US/Pacific' ...
07-15 09:08:55 e[1mINFO metabase.pluginse[0m :: e[35mLoading plugins in /plugins...e[0m
e[32mExtract file /modules/vertica.metabase-driver.jar -> /plugins/vertica.metabase-driver.jar took 4 mse[0m
e[32mExtract file /modules/sqlserver.metabase-driver.jar -> /plugins/sqlserver.metabase-driver.jar took 47 mse[0m
e[32mExtract file /modules/sqlite.metabase-driver.jar -> /plugins/sqlite.metabase-driver.jar took 46 mse[0m
e[32mExtract file /modules/sparksql.metabase-driver.jar -> /plugins/sparksql.metabase-driver.jar took 673 mse[0m
e[32mExtract file /modules/snowflake.metabase-driver.jar -> /plugins/snowflake.metabase-driver.jar took 187 mse[0m
e[32mExtract file /modules/redshift.metabase-driver.jar -> /plugins/redshift.metabase-driver.jar took 27 mse[0m
e[32mExtract file /modules/presto.metabase-driver.jar -> /plugins/presto.metabase-driver.jar took 2 mse[0m
e[32mExtract file /modules/oracle.metabase-driver.jar -> /plugins/oracle.metabase-driver.jar took 538 Β΅se[0m
e[32mExtract file /modules/mongo.metabase-driver.jar -> /plugins/mongo.metabase-driver.jar took 45 mse[0m
e[32mExtract file /modules/googleanalytics.metabase-driver.jar -> /plugins/googleanalytics.metabase-driver.jar took 4 mse[0m
e[32mExtract file /modules/google.metabase-driver.jar -> /plugins/google.metabase-driver.jar took 22 mse[0m
e[32mExtract file /modules/druid.metabase-driver.jar -> /plugins/druid.metabase-driver.jar took 6 mse[0m
e[32mExtract file /modules/bigquery.metabase-driver.jar -> /plugins/bigquery.metabase-driver.jar took 4 mse[0m
07-15 09:08:57 e[1mINFO plugins.dependenciese[0m :: Plugin 'Metabase Google Analytics Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
07-15 09:08:57 e[1mINFO plugins.dependenciese[0m :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? false
07-15 09:08:57 e[1mINFO plugins.dependenciese[0m :: e[33mPlugins with unsatisfied deps: ["Metabase Google Analytics Driver"]e[0m
07-15 09:08:57 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :hive-like...e[0m
07-15 09:08:57 e[1mINFO metabase.drivere[0m :: e[34mRegistered abstract driver :sql-jdbce[0m (parents: :sql) 🚚
e[32mLoad driver :sql-jdbc took 675 mse[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered abstract driver :hive-likee[0m (parents: #{:sql-jdbc}) 🚚
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :sparksql...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :sparksqle[0m (parents: #{:hive-like}) 🚚
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: Plugin 'Metabase BigQuery Driver' depends on plugin 'Metabase Google Drivers Shared Dependencies'
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? false
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: e[33mPlugins with unsatisfied deps: ["Metabase BigQuery Driver" "Metabase Google Analytics Driver"]e[0m
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :snowflake...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :snowflakee[0m (parents: #{:sql-jdbc}) 🚚
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :druid...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :druide[0m  🚚
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :sqlserver...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :sqlservere[0m (parents: #{:sql-jdbc}) 🚚
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: 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.

07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: Metabase Oracle Driver dependency {:class oracle.jdbc.OracleDriver} satisfied? false
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: e[33mPlugins with unsatisfied deps: ["Metabase Oracle Driver" "Metabase BigQuery Driver" "Metabase Google Analytics Driver"]e[0m
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :mongo...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :mongoe[0m  🚚
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :redshift...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :postgrese[0m (parents: :sql-jdbc) 🚚
e[32mLoad driver :postgres took 45 mse[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :redshifte[0m (parents: #{:postgres}) 🚚
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: 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 https://metabase.com/docs/latest/administration-guide/databases/vertica.html for more details.

07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: Metabase Vertica Driver dependency {:class com.vertica.jdbc.Driver} satisfied? false
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: e[33mPlugins with unsatisfied deps: ["Metabase Oracle Driver" "Metabase BigQuery Driver" "Metabase Google Analytics Driver" "Metabase Vertica Driver"]e[0m
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :sqlite...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :sqlitee[0m (parents: #{:sql-jdbc}) 🚚
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :google...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered abstract driver :googlee[0m  🚚
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: Metabase BigQuery Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
07-15 09:08:58 e[1mINFO plugins.dependenciese[0m :: Metabase Google Analytics Driver dependency {:plugin Metabase Google Drivers Shared Dependencies} satisfied? true
07-15 09:08:58 e[1mDEBUG plugins.initializee[0m :: e[33mDependencies satisfied; these plugins will now be loaded: ["Metabase Google Analytics Driver" "Metabase BigQuery Driver"]e[0m
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :googleanalytics...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :googleanalyticse[0m (parents: #{:google}) 🚚
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :bigquery...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :bigquerye[0m (parents: #{:sql :google}) 🚚
07-15 09:08:58 e[1mINFO plugins.lazy-loaded-drivere[0m :: e[35mRegistering lazy loading driver :presto...e[0m
07-15 09:08:58 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :prestoe[0m (parents: #{:sql}) 🚚
07-15 09:08:59 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :h2e[0m (parents: :sql-jdbc) 🚚
e[32mLoad driver :h2 took 37 mse[0m
07-15 09:08:59 e[1mINFO metabase.drivere[0m :: e[34mRegistered driver :mysqle[0m (parents: :sql-jdbc) 🚚
e[32mLoad driver :mysql took 45 mse[0m
07-15 09:08:59 e[1mINFO metabase.coree[0m :: Setting up and migrating Metabase DB. Please sit tight, this may take a minute...
07-15 09:08:59 e[1mINFO metabase.dbe[0m :: e[36mVerifying postgres Database Connection ...e[0m
07-15 09:08:59 e[1mINFO metabase.drivere[0m :: e[33mInitializing driver :sql...e[0m
07-15 09:08:59 e[1mINFO metabase.drivere[0m :: e[33mInitializing driver :sql-jdbc...e[0m
07-15 09:08:59 e[1mINFO metabase.drivere[0m :: e[33mInitializing driver :postgres...e[0m
07-15 09:09:04 e[1mERROR metabase.coree[0m :: Metabase Initialization FAILED
java.lang.Exception: Timed out after 5,000 milliseconds.
	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:18)
	at clojure.lang.RestFn.invoke(RestFn.java:442)
	at clojure.lang.Var.invoke(Var.java:393)
	at metabase.db$fn__17576$verify_db_connection__17585$fn__17588$fn__17589.invoke(db.clj:405)
	at metabase.db$fn__17576$verify_db_connection__17585$fn__17588.invoke(db.clj:403)
	at metabase.db$fn__17576$verify_db_connection__17585.invoke(db.clj:396)
	at metabase.db$fn__17576$verify_db_connection__17585$fn__17586.invoke(db.clj:399)
	at metabase.db$fn__17576$verify_db_connection__17585.invoke(db.clj:396)
	at metabase.db$setup_db_BANG__STAR_$fn__17621.invoke(db.clj:468)
	at metabase.util$do_with_us_locale.invokeStatic(util.clj:666)
	at metabase.util$do_with_us_locale.invoke(util.clj:652)
	at metabase.db$setup_db_BANG__STAR_.invokeStatic(db.clj:467)
	at metabase.db$setup_db_BANG__STAR_.invoke(db.clj:463)
	at metabase.db$fn__17625$fn__17626.invoke(db.clj:478)
	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 clojure.core$partial$fn__5824.invoke(core.clj:2623)
	at metabase.core$init_BANG_.invokeStatic(core.clj:76)
	at metabase.core$init_BANG_.invoke(core.clj:55)
	at metabase.core$start_normally.invokeStatic(core.clj:122)
	at metabase.core$start_normally.invoke(core.clj:116)
	at metabase.core$_main.invokeStatic(core.clj:142)
	at metabase.core$_main.doInvoke(core.clj:137)
	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,000 milliseconds.
	at metabase.util$deref_with_timeout.invokeStatic(util.clj:322)
	at metabase.util$deref_with_timeout.invoke(util.clj:314)
	at metabase.driver.util$can_connect_with_details_QMARK_.invokeStatic(util.clj:29)
	... 28 more
07-15 09:09:04 e[1mINFO metabase.coree[0m :: Metabase Shutting Down ...
07-15 09:09:04 e[1mINFO metabase.servere[0m :: Shutting Down Embedded Jetty Webserver
07-15 09:09:04 e[1mINFO metabase.coree[0m :: Metabase Shutdown COMPLETE

Any help would be greatly appreciated!

Actually the error message is helpful and I wasn’t reading it carefully enough. It turns out it was an issue with security group settings and the database connection wasn’t being established. Which is exactly what the first line of the stack trace said!

1 Like