Snowflake Connection Timed Out

ajb · March 4, 2020, 6:11pm

Hi,

We setup an initial connection to Snowflake on the latest version of Metabase (v0.34.3), but now any time we try to change the connection we get this error and it is not clear what the issue is. Any help debugging would be appreciated.

03-04 18:08:18 ERROR driver.util :: Database connection error
java.util.concurrent.TimeoutException: Timed out after 5.0 s
	at metabase.util$deref_with_timeout.invokeStatic(util.clj:292)
	at metabase.util$deref_with_timeout.invoke(util.clj:284)
	at metabase.util$do_with_timeout.invokeStatic(util.clj:298)
	at metabase.util$do_with_timeout.invoke(util.clj:295)
	at metabase.driver.util$can_connect_with_details_QMARK_.invokeStatic(util.clj:31)
	at metabase.driver.util$can_connect_with_details_QMARK_.doInvoke(util.clj:20)
	at clojure.lang.RestFn.invoke(RestFn.java:442)
	at metabase.api.database$test_database_connection.invokeStatic(database.clj:319)
	at metabase.api.database$test_database_connection.doInvoke(database.clj:308)
	at clojure.lang.RestFn.invoke(RestFn.java:425)
	at metabase.api.database$fn__54061.invokeStatic(database.clj:454)
	at metabase.api.database$fn__54061.invoke(database.clj:437)
	at compojure.core$wrap_response$fn__1971.invoke(core.clj:160)
	at compojure.core$wrap_route_middleware$fn__1955.invoke(core.clj:132)
	at compojure.core$wrap_route_info$fn__1960.invoke(core.clj:139)
	at compojure.core$wrap_route_matches$fn__1964.invoke(core.clj:151)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$wrap_route_matches$fn__1964.invoke(core.clj:153)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983.invoke(core.clj:200)
	at metabase.middleware.auth$enforce_authentication$fn__66187.invoke(auth.clj:14)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983.invoke(core.clj:200)
	at compojure.core$make_context$handler__2011.invoke(core.clj:287)
	at compojure.core$make_context$fn__2013.invoke(core.clj:296)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$make_context$fn__2013.invoke(core.clj:297)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$make_context$fn__2013.invoke(core.clj:297)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$make_context$fn__2013.invoke(core.clj:297)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$make_context$fn__2013.invoke(core.clj:297)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$make_context$fn__2013.invoke(core.clj:297)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$make_context$fn__2013.invoke(core.clj:297)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983.invoke(core.clj:200)
	at clojure.lang.AFn.applyToHelper(AFn.java:160)
	at clojure.lang.AFn.applyTo(AFn.java:144)
	at clojure.core$apply.invokeStatic(core.clj:665)
	at clojure.core$apply.invoke(core.clj:660)
	at metabase.routes$fn__67541$fn__67542.doInvoke(routes.clj:56)
	at clojure.lang.RestFn.invoke(RestFn.java:436)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983.invoke(core.clj:200)
	at compojure.core$make_context$handler__2011.invoke(core.clj:287)
	at compojure.core$make_context$fn__2013.invoke(core.clj:296)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$wrap_route_matches$fn__1964.invoke(core.clj:153)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$wrap_route_matches$fn__1964.invoke(core.clj:153)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983$f__1984$respond_SINGLEQUOTE___1985.invoke(core.clj:197)
	at compojure.core$wrap_route_matches$fn__1964.invoke(core.clj:153)
	at compojure.core$routes$fn__1983$f__1984.invoke(core.clj:198)
	at compojure.core$routes$fn__1983.invoke(core.clj:200)
	at metabase.middleware.exceptions$catch_uncaught_exceptions$fn__66286.invoke(exceptions.clj:97)
	at metabase.middleware.exceptions$catch_api_exceptions$fn__66283.invoke(exceptions.clj:85)
	at metabase.middleware.log$log_api_call$fn__67917$fn__67918.invoke(log.clj:178)
	at toucan.db$_do_with_call_counting.invokeStatic(db.clj:213)
	at toucan.db$_do_with_call_counting.invoke(db.clj:206)
	at metabase.middleware.log$log_api_call$fn__67917.invoke(log.clj:172)
	at metabase.middleware.security$add_security_headers$fn__66249.invoke(security.clj:121)
	at metabase.middleware.json$wrap_json_body$fn__67622.invoke(json.clj:64)
	at metabase.middleware.json$wrap_streamed_json_response$fn__67640.invoke(json.clj:100)
	at ring.middleware.keyword_params$wrap_keyword_params$fn__68152.invoke(keyword_params.clj:55)
	at ring.middleware.params$wrap_params$fn__68200.invoke(params.clj:69)
	at metabase.middleware.misc$maybe_set_site_url$fn__67946.invoke(misc.clj:58)
	at metabase.middleware.session$bind_current_user$fn__62772$fn__62773.invoke(session.clj:209)
	at metabase.middleware.session$do_with_current_user.invokeStatic(session.clj:184)
	at metabase.middleware.session$do_with_current_user.invoke(session.clj:177)
	at metabase.middleware.session$bind_current_user$fn__62772.invoke(session.clj:208)
	at metabase.middleware.session$wrap_current_user_id$fn__62757.invoke(session.clj:161)
	at metabase.middleware.session$wrap_session_id$fn__62701.invoke(session.clj:125)
	at metabase.middleware.auth$wrap_api_key$fn__66195.invoke(auth.clj:27)
	at metabase.middleware.misc$bind_user_locale$fn__67949.invoke(misc.clj:74)
	at ring.middleware.cookies$wrap_cookies$fn__68072.invoke(cookies.clj:177)
	at metabase.middleware.misc$add_content_type$fn__67932.invoke(misc.clj:29)
	at metabase.middleware.misc$disable_streaming_buffering$fn__67957.invoke(misc.clj:89)
	at ring.middleware.gzip$wrap_gzip$fn__68114.invoke(gzip.clj:86)
	at ring.adapter.jetty$async_proxy_handler$fn__67718.invoke(jetty.clj:35)
	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:132)
	at org.eclipse.jetty.server.Server.handle(Server.java:502)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
	at java.base/java.lang.Thread.run(Unknown Source)
03-04 18:08:18 DEBUG middleware.log :: PUT /api/database/3 400 5.0 s (1 DB calls)
{:valid false, :dbname "Timed out after 5.0 s", :message "Timed out after 5.0 s"}

flamber · March 4, 2020, 9:00pm

Hi @ajb
Every time you’re saving a database, it will validate the connection before saving the information.
So it looks like the hostname or port is probably incorrect, since it gives you a timeout.

ajb · March 4, 2020, 9:14pm

@flamber - There is no port in the Snowflake connection and even if I put the same exact values as the existing connection I get the same error.

ajb · March 4, 2020, 9:19pm

Is there anyway to see the connection string that is being generated?

flamber · March 4, 2020, 9:56pm

@ajb
Make sure that you don’t have a firewall/antivirus blocking the connection - and that the DNS resolves.
If you’re using Docker, then connect to Bash and make the test from there.
I don’t remember if the full connection string is printed if you enable debug logging:
https://www.metabase.com/docs/latest/operations-guide/log-configuration.html
I would recommend using tcpdump/wireshark to see why the packets are not going through.

reebajose · March 21, 2020, 5:45am

Not able to connect to snowflake Database from Metabase, getting “Timed out after 5.0 s” when try to connect. Tried different combibations of account and region ID and also with upper / lower case, none of them seems to be working. please help.

3-21 00:33:17 e[1mDEBUG middleware.loge[0m :: POST /api/database 400 5.0 s (0 DB calls)
{:valid false, :dbname “Timed out after 5.0 s”, :message “Timed out after 5.0 s”}

03-21 00:33:17 e[1mDEBUG middleware.loge[0m :: GET /api/database 200 2.3 ms (3 DB calls) Jetty threads: 5/50 (4 idle, 0 queued) (43 total active threads) Queries in flight: 0
Mar 21, 2020 12:34:22 AM net.snowflake.client.jdbc.RestRequest execute
SEVERE: Stop retrying since elapsed time due to network issues has reached timeout. Elapsed: 70,171(ms), timeout: 60,000(ms)
03-21 00:34:44 e[1mDEBUG middleware.loge[0m :: GET /api/user/current 200 1.9 ms (3 DB calls) Jetty threads: 6/50 (2 idle, 0 queued) (41 total active threads) Queries in flight: 0
03-21 00:34:44 e[1mDEBUG middleware.loge[0m :: GET /api/session/properties 200 4.2 ms (1 DB calls) Jetty threads: 5/50 (2 idle, 0 queued) (42 total active thr

fima · May 10, 2021, 3:27am

I'm having the same issue, were you able to resolve this?

flamber · May 10, 2021, 8:19am

@fima Make sure that Metabase can connect to the database. Use ping or telnet from where Metabase is running. That eliminates incorrect hostname or port, and checks DNS and firewalls.
If there is a slow initial connection, then the timeout can be changed from 5 seconds to something higher:
https://www.metabase.com/docs/latest/operations-guide/environment-variables.html#mb_db_connection_timeout_ms

fima · May 10, 2021, 12:24pm

Thank you! We are using the cloud hosted version so I don’t believe I have access to perform this type of troubleshooting, or do I? Thank you for the help

flamber · May 10, 2021, 12:28pm

@fima
There shouldn't be any problems connecting to Snowflake through Metabase Cloud.
Could it be that you're not allowing Metabase Cloud to connect because of a firewall?
You'll need to add the following to your allow-list: IP to whitelist for Metabase Cloud instances

fima · May 10, 2021, 1:40pm

I appreciate your responses, do you work for Metabase? Thank you for the assistance!

Our Snowflake setup is cloud hosted as well and has no IP ACL firewall restrictions.

From reading other posts here it seems the 5s timeout message is misleading. I suspect Metabase isn’t liking my Snowflake region / account details but have no way to confirm this (we’re on AWS US West (Oregon): us-west-2)

Any other ideas of how to troubleshoot this further?

flamber · May 10, 2021, 1:45pm

@fima Yes: https://github.com/orgs/metabase/people
Check Admin > Troubleshooting > Logs, since there might be more details in the stacktrace.
I have a feeling that you're hitting a known issue:
https://github.com/metabase/metabase/issues/10142

fima · May 10, 2021, 3:38pm

Yes!! You nailed it

I removed the region_id and was able to complete setup. Thank you!

flamber · May 10, 2021, 3:49pm

@fima So it now only errors with a timeout? And even the stacktrace also only reports it as a timeout?
It might be caused by a change at Snowflake, or perhaps the upstream driver. We definitely need to update the input form (while keeping backward compatibility), but we also need to figure out how we can get better error messages from the driver.

fima · May 11, 2021, 1:56am

Yes, exactly right. That was the only kind of error I was able to see. Unfortunately, I no longer have logs available to me from when it occurred but no, the logs did not show a timeout. Let me know if you'd like me to try to reproduce this again. Happy to help