search

metabase / metabase

The simplest, fastest way to get business intelligence and analytics to everyone in your company :yum:
https://metabase.com
Other
38.66k stars 5.14k forks source link

Connections can not be acquired from the underlying database! #7700

Closed VikramTiwari closed 3 years ago

VikramTiwari commented 6 years ago 
05-23 09:46:30 WARN server.HttpChannel :: /
java.sql.SQLException: Connections could not be acquired from the underlying database!
        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:118)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:529)
        at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
        at clojure.java.jdbc$get_connection.invokeStatic(jdbc.clj:310)
        at clojure.java.jdbc$get_connection.invoke(jdbc.clj:226)
        at clojure.java.jdbc$db_query_with_resultset_STAR_.invokeStatic(jdbc.clj:1014)
        at clojure.java.jdbc$db_query_with_resultset_STAR_.invoke(jdbc.clj:996)
        at clojure.java.jdbc$query.invokeStatic(jdbc.clj:1090)
        at clojure.java.jdbc$query.invoke(jdbc.clj:1047)
        at toucan.db$query.invokeStatic(db.clj:278)
        at toucan.db$query.doInvoke(db.clj:274)
        at clojure.lang.RestFn.invoke(RestFn.java:410)
        at toucan.db$simple_select.invokeStatic(db.clj:383)
        at toucan.db$simple_select.invoke(db.clj:372)
        at toucan.db$simple_select_one.invokeStatic(db.clj:409)
        at toucan.db$simple_select_one.invoke(db.clj:398)
        at toucan.db$select_one.invokeStatic(db.clj:605)
        at toucan.db$select_one.doInvoke(db.clj:598)
        at clojure.lang.RestFn.invoke(RestFn.java:423)
        at toucan.db$exists_QMARK_.invokeStatic(db.clj:709)
        at toucan.db$exists_QMARK_.doInvoke(db.clj:703)
        at clojure.lang.RestFn.invoke(RestFn.java:439)
        at metabase.public_settings$public_settings.invokeStatic(public_settings.clj:165)
        at metabase.public_settings$public_settings.invoke(public_settings.clj:150)
        at metabase.routes$entrypoint.invokeStatic(routes.clj:57)
        at metabase.routes$entrypoint.invoke(routes.clj:52)
        at clojure.core$partial$fn__4761.invoke(core.clj:2522)
        at compojure.response$fn__18172.invokeStatic(response.clj:33)
        at compojure.response$fn__18172.invoke(response.clj:21)
        at compojure.response$fn__18145$G__18140__18152.invoke(response.clj:6)
        at compojure.core$make_route$fn__19320.invoke(core.clj:135)
        at compojure.core$wrap_route_middleware$fn__19313.invoke(core.clj:122)
        at compojure.core$wrap_route_info$fn__19317.invoke(core.clj:126)
        at compojure.core$if_route$fn__19275.invoke(core.clj:45)
        at compojure.core$if_method$fn__19265.invoke(core.clj:27)
        at compojure.core$routing$fn__19327.invoke(core.clj:151)
        at clojure.core$some.invokeStatic(core.clj:2592)
        at clojure.core$some.invoke(core.clj:2583)
        at compojure.core$routing.invokeStatic(core.clj:151)
        at compojure.core$routing.doInvoke(core.clj:148)
        at clojure.lang.RestFn.applyTo(RestFn.java:139)
        at clojure.core$apply.invokeStatic(core.clj:648)
        at clojure.core$apply.invoke(core.clj:641)
        at compojure.core$routes$fn__19331.invoke(core.clj:156)
        at clojure.lang.Var.invoke(Var.java:379)
        at metabase.middleware$log_api_call$fn__42291.invoke(middleware.clj:353)
        at metabase.middleware$add_security_headers$fn__42241.invoke(middleware.clj:258)
        at ring.middleware.json$wrap_json_body$fn__48535.invoke(json.clj:46)
        at metabase.core$wrap_streamed_json_response$fn__48732.invoke(core.clj:67)
        at ring.middleware.keyword_params$wrap_keyword_params$fn__48580.invoke(keyword_params.clj:36)
        at ring.middleware.params$wrap_params$fn__48628.invoke(params.clj:67)
        at metabase.middleware$bind_current_user$fn__42196.invoke(middleware.clj:139)
        at clojure.core$comp$fn__4727.invoke(core.clj:2460)
        at clojure.core$comp$fn__4727.invoke(core.clj:2460)
        at clojure.core$comp$fn__4727.invoke(core.clj:2460)
        at metabase.middleware$maybe_set_site_url$fn__42245.invoke(middleware.clj:282)
        at puppetlabs.i18n.core$locale_negotiator$fn__124.invoke(core.clj:357)
        at ring.middleware.cookies$wrap_cookies$fn__48478.invoke(cookies.clj:175)
        at ring.middleware.session$wrap_session$fn__48719.invoke(session.clj:108)
        at ring.middleware.gzip$wrap_gzip$fn__48509.invoke(gzip.clj:65)
        at ring.adapter.jetty$proxy_handler$fn__48355.invoke(jetty.clj:25)
        at ring.adapter.jetty.proxy$org.eclipse.jetty.server.handler.AbstractHandler$ff19274a.handle(Unknown Source)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
        at org.eclipse.jetty.server.Server.handle(Server.java:499)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
        at java.lang.Thread.run(Thread.java:745)
Caused by: com.mchange.v2.resourcepool.CannotAcquireResourceException: A ResourcePool could not acquire a resource from its primary factory or source.
        at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1319)
        at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
        at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
        ... 68 more
salsakran commented 6 years ago

does this go away on a restart?

this sounds like an issue connecting with the application database

VikramTiwari commented 6 years ago

Should have provided more details. This doesn't happen during start, it just happens randomly. It also auto fixes itself. I haven't looked into it since but I will add more details this weekend if I see it still happening.

ashwini0529 commented 6 years ago

Same thing happened with me as well. Suddenly it threw Connections could not be acquired from the underlying database! I'm running Metabase on a linux server with a Docker Container.

jornh commented 6 years ago

Could you guys just be experiencing fallacy number 1. in https://www.infoworld.com/article/3114195/system-management/the-8-fallacies-of-distributed-computing-are-becoming-irrelevant.html ⬅️ (But they’re not gone in all environments)

;) Yes I know, a bit cheeky response, apologies! To try to be constructive:

Overbryd commented 6 years ago

Same problem here. What can I do about it?

I am running 0.25.1 here, against a PostgreSQL RDS instance.

Oct 19 11:39:37 18.207.193.200 metabase:  :cause A ResourcePool could not acquire a resource from its primary factory or source.
Oct 19 11:39:37 18.207.193.200 metabase:  :via
Oct 19 11:39:37 18.207.193.200 metabase:  [{:type java.sql.SQLException
Oct 19 11:39:37 18.207.193.200 metabase:    :message Connections could not be acquired from the underlying database!
Oct 19 11:39:37 18.207.193.200 metabase:    :at [com.mchange.v2.sql.SqlUtils toSQLException SqlUtils.java 118]}
Oct 19 11:39:37 18.207.193.200 metabase:   {:type com.mchange.v2.resourcepool.CannotAcquireResourceException
Oct 19 11:39:37 18.207.193.200 metabase:    :message A ResourcePool could not acquire a resource from its primary factory or source.
Oct 19 11:39:37 18.207.193.200 metabase:    :at [com.mchange.v2.resourcepool.BasicResourcePool awaitAvailable BasicResourcePool.java 1319]}]
Oct 19 11:39:37 18.207.193.200 metabase:  :trace
Oct 19 11:39:37 18.207.193.200 metabase:  [[com.mchange.v2.resourcepool.BasicResourcePool awaitAvailable BasicResourcePool.java 1319]
Oct 19 11:39:37 18.207.193.200 metabase:   [com.mchange.v2.resourcepool.BasicResourcePool prelimCheckoutResource BasicResourcePool.java 557]
Oct 19 11:39:37 18.207.193.200 metabase:   [com.mchange.v2.resourcepool.BasicResourcePool checkoutResource BasicResourcePool.java 477]
Oct 19 11:39:37 18.207.193.200 metabase:   [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool checkoutPooledConnection C3P0PooledConnectionPool.java 525]
Oct 19 11:39:37 18.207.193.200 metabase:   [com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getConnection AbstractPoolBackedDataSource.java 128]
Oct 19 11:39:37 18.207.193.200 metabase:   [clojure.java.jdbc$get_connection invokeStatic jdbc.clj 298]
Oct 19 11:39:37 18.207.193.200 metabase:   [clojure.java.jdbc$get_connection invoke jdbc.clj 193]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.driver.generic_sql$describe_database invokeStatic generic_sql.clj 412]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.driver.generic_sql$describe_database invoke generic_sql.clj 409]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.driver$fn__22486$G__22452__22493 invoke driver.clj 45]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database.introspect$db__GT_tables invokeStatic introspect.clj 188]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database.introspect$db__GT_tables invoke introspect.clj 187]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database.introspect$introspect_database_and_update_raw_tables_BANG_ invokeStatic introspect.clj 204]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database.introspect$introspect_database_and_update_raw_tables_BANG_ invoke introspect.clj 198]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database$sync_database_with_tracking_BANG_$fn__30875 invoke sync_database.clj 78]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database$sync_database_with_tracking_BANG_ invokeStatic sync_database.clj 75]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database$sync_database_with_tracking_BANG_ invoke sync_database.clj 69]
Oct 19 11:39:37 18.207.193.200 metabase:   [clojure.core$partial$fn__4763 invoke core.clj 2528]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.driver$fn__22710 invokeStatic driver.clj 252]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.driver$fn__22710 invoke driver.clj 252]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.driver$fn__22659$G__22442__22668 invoke driver.clj 45]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database$sync_database_BANG_ invokeStatic sync_database.clj 44]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.sync_database$sync_database_BANG_ doInvoke sync_database.clj 25]
Oct 19 11:39:37 18.207.193.200 metabase:   [clojure.lang.RestFn invoke RestFn.java 410]
Oct 19 11:39:37 18.207.193.200 metabase:   [metabase.events.sync_database$process_sync_database_event$fn__45970 invoke sync_database.clj 31]
Oct 19 11:39:37 18.207.193.200 metabase:   [clojure.core$binding_conveyor_fn$fn__4676 invoke core.clj 1938]
Oct 19 11:39:37 18.207.193.200 metabase:   [clojure.lang.AFn call AFn.java 18]
Oct 19 11:39:37 18.207.193.200 metabase:   [java.util.concurrent.FutureTask run FutureTask.java 266]
Oct 19 11:39:37 18.207.193.200 metabase:   [java.util.concurrent.ThreadPoolExecutor runWorker ThreadPoolExecutor.java 1142]
Oct 19 11:39:37 18.207.193.200 metabase:   [java.util.concurrent.ThreadPoolExecutor$Worker run ThreadPoolExecutor.java 617]
Oct 19 11:39:37 18.207.193.200 metabase:   [java.lang.Thread run Thread.java 745]]}
viluon commented 5 years ago

Still an issue with v0.31.0-snapshot

SQLException:
 Message: Connections could not be acquired from the underlying database!
 SQLState: null
 Error Code: 0
03-06 11:56:32 ERROR generic-sql.query-processor :: nil
flamber commented 5 years ago

Hi @viluon Try 0.31.2 - and which database are you using for Metabase internal? Do you see anything on the log of your database? Have you tried to follow the troubleshooting guide? https://metabase.com/docs/latest/troubleshooting-guide/datawarehouse.html

viluon commented 5 years ago

Hi @flamber. I'm now on v0.31.3 and the issue is still present. I'll get back to you as soon as I determine which database connection is the problematic one, there are quite a few DBs connected to this Metabase instance. The weirdest thing is the lack of a stack trace or other detailed listing of the error, despite a DEBUG log level:

03-06 18:19:31 DEBUG metabase.middleware :: POST /api/card/6/query 200 (86 ms) (10 DB calls). Jetty threads: 8/50 (4 busy, 6 idle, 0 queued)
SQLException:
 Message: Connections could not be acquired from the underlying database!
 SQLState: null
 Error Code: 0
03-06 18:19:34 ERROR generic-sql.query-processor :: nil
03-06 18:19:39 INFO api.card :: Card results metadata passed in to API is VALID. Thanks!
03-06 18:19:39 DEBUG metabase.middleware :: PUT /api/card/6 200 (14 ms) (10 DB calls). Jetty threads: 8/50 (4 busy, 6 idle, 0 queued)

I'm not aware of any configuration changes which could cause this behaviour.

flamber commented 5 years ago

@viluon I'm not talking about datasources - I was asking what database you use for Metabase's internal structure. It's H2 by default, which is not recommended for production use. You should be using Postgres or MySQL/MariaDB for the internal database. If you're using non-H2, then you should be able to see failed connections or queries on your database log.

viluon commented 5 years ago

@flamber Ah, I see, no, the instance uses PostgreSQL. EDIT: it seems that the issue either isn't with the Metabase database (on PostgreSQL) or that Metabase can't connect at all, there are no mentions of connections to the MB database in the server log (it is set to warning+ level). It is important to note that one can log into this Metabase instance, therefore the connection to the underlying DB is at least partially working.

flamber commented 5 years ago

@viluon Is Metabase and Postgres on the same server - otherwise it could be blocked by some firewall or DoS protection, or simply just a bad connection between the two. You could use tcpdump to see all the network activity between the two.

viluon commented 5 years ago

@flamber it's definitely not that. Not only did it work before and the firewall would have to somehow be picky about which packets to let through and which ones to block (since logging in, viewing questions, dashboards, etc. works normally), there have been no changes to the network configuration that could cause this behaviour and, above all, they are both on the same server.

viluon commented 5 years ago

@flamber just got a word from a user of the instance, the weird behaviour started after adding a connection to a MySQL database. By weird behaviour I mean the errors, but also complete blackouts of the instance, where after a couple of these errors the server just stopped responding entirely, the logs went black, and the instance had to be restarted to work again. This was on the aforementioned v0.31.0-snapshot however, it is possible that the changes introduced by upgrading to v0.31.3 fixed these crashes.

mezod commented 5 years ago

happening here on v0.32.8. Just upgraded and now getting this error from the web version. I'm using Metabase from Mac to make queries to an Amazon RDS (I can connect via mysqlpro without issues)

camsaul commented 5 years ago

@viluon upgrading to 0.32.8 will fix you server hanging issues. In older versions queries that were waiting for connections could exhaust all available threads and the server would be unable to handle new requests.

Sharom commented 5 years ago

I have updated Metabase from 0.30.4 to 0.32.8 and got this issue, using MySQL.

mezod commented 5 years ago

had this issue yesterday when upgrading from 0.30.* to 0.32.8 and fixed it by adding

trustServerCertificate=true

to Additional JDBC connection string options: for the database.

Sharom commented 5 years ago

had this issue yesterday when upgrading from 0.30.* to 0.32.8 and fixed it by adding

trustServerCertificate=true

to Additional JDBC connection string options: for the database.

It works, thank you!

beastoin commented 5 years ago

Try to check the connection from metabase server(docker: using cmd docker inspect --format '{{ .NetworkSettings.IPAddress }}' <your_docker_container>) to your database application server(including with application port, e.g 3306, 5432...). Sometime the issue just because the firewall block the connection from another.

officeutils commented 4 years ago

had this issue yesterday when upgrading from 0.30.* to 0.32.8 and fixed it by adding

trustServerCertificate=true

to Additional JDBC connection string options: for the database.

I added this option - It works! Then I removed this option - I works again! I think any change of jdbc options reset connection and can help to resolve this problem. But manual actions are required always.

camsaul commented 3 years ago

This was fixed by #11771 -- the issue was we didn't check whether existing Connections were still valid before using them, so after a while the connection pool could get filled with invalid connections.