Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SQL Server - There was a problem displaying this chart. #9989

Open
rylonian opened this issue May 16, 2019 · 9 comments

Comments

Projects
None yet
9 participants
@rylonian
Copy link

commented May 16, 2019

We love Metabase!

I've looked for more information on this issue, but can't seem to find anything.

Browsers: Chrome 74 and IE 11
Client OS: Windows 10
Database: SQL Server 14
Metabase Version 0.32.7
Metabase Hosting Environment: Running directly on Ubuntu 18.04
Metabase Internal Database: MySQL 5.7.26
Metabase is behind an Apache2 Reverse Proxy running SSL.

Every morning when the first user opens a dashboard in Metabase, some of the questions return "There was a problem displaying this chart." Once the user refreshes the dashboard, the questions that failed to load initially will load. (These are usually very quick running queries. Less than a second.) The log that was associated with the issue this morning has this error message:

ERROR metabase.middleware.log :: POST /api/card/450/query 500 27 ms (2 DB calls)
{:message "(conn=7) Broken pipe (Write failed)",
:type java.sql.SQLNonTransientConnectionException,
:stacktrace
("org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.get(ExceptionMapper.java:234)"
"org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getException(ExceptionMapper.java:165)"
"org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:238)"
"org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:232)"
"org.mariadb.jdbc.MariaDbPreparedStatementClient.execute(MariaDbPreparedStatementClient.java:159)"
"org.mariadb.jdbc.MariaDbPreparedStatementClient.executeQuery(MariaDbPreparedStatementClient.java:174)"
"com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:379)"
"clojure.java.jdbc$execute_query_with_params.invokeStatic(jdbc.clj:1072)"
"clojure.java.jdbc$execute_query_with_params.invoke(jdbc.clj:1066)"
"clojure.java.jdbc$db_query_with_resultset_STAR_.invokeStatic(jdbc.clj:1095)"
"clojure.java.jdbc$db_query_with_resultset_STAR_.invoke(jdbc.clj:1075)"
"clojure.java.jdbc$query.invokeStatic(jdbc.clj:1164)"
"clojure.java.jdbc$query.invoke(jdbc.clj:1126)"
"toucan.db$query.invokeStatic(db.clj:274)"
"toucan.db$query.doInvoke(db.clj:270)"
"clojure.lang.RestFn.invoke(RestFn.java:410)"
"toucan.db$simple_select.invokeStatic(db.clj:378)"
"toucan.db$simple_select.invoke(db.clj:367)"
"toucan.db$select.invokeStatic(db.clj:646)"
"toucan.db$select.doInvoke(db.clj:640)"
"clojure.lang.RestFn.applyTo(RestFn.java:139)"
"clojure.core$apply.invokeStatic(core.clj:667)"
"clojure.core$apply.invoke(core.clj:660)"
"toucan.db$select_field.invokeStatic(db.clj:669)"
"toucan.db$select_field.doInvoke(db.clj:661)"
"clojure.lang.RestFn.applyTo(RestFn.java:142)"
"clojure.core$apply.invokeStatic(core.clj:669)"
"clojure.core$apply.invoke(core.clj:660)"
"toucan.db$select_ids.invokeStatic(db.clj:679)"
"toucan.db$select_ids.doInvoke(db.clj:672)"
"clojure.lang.RestFn.invoke(RestFn.java:439)"
"--> models.collection$fn__28837$descendant_ids__28842$fn__28843.invoke(collection.clj:428)"
"models.collection$fn__28837$descendant_ids__28842.invoke(collection.clj:425)"
"models.collection$fn__29638$user__GT_personal_collection_and_descendant_ids__29643$fn__29644.invoke(collection.clj:1062)"
"models.collection$fn__29638$user__GT_personal_collection_and_descendant_ids__29643.invoke(collection.clj:1052)"
"models.user$permissions_set.invokeStatic(user.clj:278)"
"models.user$permissions_set.invoke(user.clj:272)"
"middleware.session$do_with_current_user$fn__58584.invoke(session.clj:175)"
"models.interface$current_user_permissions_set.invokeStatic(interface.clj:234)"
"models.interface$current_user_permissions_set.invoke(interface.clj:234)"
"models.interface$make_perms_check_fn$_has_perms_QMARK___24078.invoke(interface.clj:249)"
"models.interface$make_perms_check_fn$_has_perms_QMARK___24078.invoke(interface.clj:247)"
"models.interface$fn__24013$G__24004__24022.invoke(interface.clj:181)"
"api.common$read_check.invokeStatic(common.clj:367)"
"api.common$read_check.invoke(common.clj:360)"
"api.card$run_query_for_card_async.invokeStatic(card.clj:618)"
"api.card$run_query_for_card_async.doInvoke(card.clj:610)"
"api.card$fn__44653$fn__44656.invoke(card.clj:632)"
"api.card$fn__44653.invokeStatic(card.clj:631)"
"api.card$fn__44653.invoke(card.clj:627)"
"middleware.auth$enforce_authentication$fn__59881.invoke(auth.clj:14)"
"routes$fn__61038$fn__61039.doInvoke(routes.clj:56)"
"middleware.exceptions$catch_uncaught_exceptions$fn__59972.invoke(exceptions.clj:104)"
"middleware.exceptions$catch_api_exceptions$fn__59969.invoke(exceptions.clj:92)"
"middleware.log$log_api_call$fn__61412$fn__61413.invoke(log.clj:170)"
"middleware.log$log_api_call$fn__61412.invoke(log.clj:164)"
"middleware.security$add_security_headers$fn__59935.invoke(security.clj:105)"
"middleware.json$wrap_json_body$fn__61117.invoke(json.clj:61)"
"middleware.json$wrap_streamed_json_response$fn__61135.invoke(json.clj:97)"
"middleware.session$bind_current_user$fn__58589$fn__58590.invoke(session.clj:193)"
"middleware.session$do_with_current_user.invokeStatic(session.clj:176)"
"middleware.session$do_with_current_user.invoke(session.clj:170)"
"middleware.session$bind_current_user$fn__58589.invoke(session.clj:192)"
"middleware.session$wrap_current_user_id$fn__58578.invoke(session.clj:161)"
"middleware.session$wrap_session_id$fn__58563.invoke(session.clj:123)"
"middleware.auth$wrap_api_key$fn__59889.invoke(auth.clj:27)"
"middleware.misc$maybe_set_site_url$fn__61477.invoke(misc.clj:58)"
"middleware.misc$bind_user_locale$fn__61480.invoke(misc.clj:74)"
"middleware.misc$add_content_type$fn__61465.invoke(misc.clj:30)"
"middleware.misc$disable_streaming_buffering$fn__61502.invoke(misc.clj:119)"
"middleware.misc$wrap_gzip$fn__61495.invoke(misc.clj:101)"),
:sql-exception-chain ["SQLNonTransientConnectionException:" "Message: (conn=7) Broken pipe (Write failed)" "SQLState: 08" "Error Code: 0"]}

This happened a few minutes later with a segment as well.

I assume this is unrelated, but there is a timezone error as well during the hourly synchronization.
ERROR metabase.driver.sql-jdbc.execute :: Failed to set timezone:
SQLException:
Message: (conn=12) Unknown or incorrect time zone: 'US/Eastern'
SQLState: HY000
Error Code: 1298

It seems as though once that first user connects, everything seems okay for a while.

One other note, we were running Metabase version 31.2 and we never experienced this problem. It wasn't until we updated to version 32.5 and 32.7 that this problem began. I believe it was worse on 32.5.

Please let me know if more information is needed. Thanks!

@flamber

This comment has been minimized.

Copy link
Contributor

commented May 16, 2019

@camsaul

05-16 16:36:38 DEBUG middleware.log :: POST /api/card/36/query 200 [ASYNC: completed] 3 s (14 DB calls) Jetty threads: 3/50 (8 idle, 0 queued) (61 total active threads) Queries in flight: 2
05-16 16:36:38 WARN middleware.process-userland-query :: Query failure {:status :failed,
 :class java.lang.IllegalArgumentException,
 :error "No method in multimethod 'date' for dispatch value: [:sqlserver :day]",
 :stacktrace
 ("clojure.lang.MultiFn.getFn(MultiFn.java:156)"
  "clojure.lang.MultiFn.invoke(MultiFn.java:238)"
  "--> query_processor.middleware.parameters.sql$fn__36568$field__GT_identifier__36573$fn__36574.invoke(sql.clj:372)"
  "query_processor.middleware.parameters.sql$fn__36568$field__GT_identifier__36573.invoke(sql.clj:365)"
  "query_processor.middleware.parameters.sql$fn__36629.invokeStatic(sql.clj:449)"
  "query_processor.middleware.parameters.sql$fn__36629.invoke(sql.clj:392)"
  "query_processor.middleware.parameters.sql$fn__36428$G__36423__36433.invoke(sql.clj:314)"
  "query_processor.middleware.parameters.sql$fn__36734$token__GT_param__36739$fn__36740.invoke(sql.clj:511)"
  "query_processor.middleware.parameters.sql$fn__36734$token__GT_param__36739.invoke(sql.clj:506)"
  "query_processor.middleware.parameters.sql$fn__36759$parse_params__36764$fn__36765$fn__36768.invoke(sql.clj:526)"
  "query_processor.middleware.parameters.sql$fn__36759$parse_params__36764$fn__36765.invoke(sql.clj:523)"
  "query_processor.middleware.parameters.sql$fn__36759$parse_params__36764.invoke(sql.clj:518)"
  "query_processor.middleware.parameters.sql$fn__36814$parse_optional__36819$fn__36820$iter__36822__36826$fn__36827$fn__36828.invoke(sql.clj:551)"
  "query_processor.middleware.parameters.sql$fn__36814$parse_optional__36819$fn__36820$iter__36822__36826$fn__36827.invoke(sql.clj:550)"
  "query_processor.middleware.parameters.sql$fn__36814$parse_optional__36819$fn__36820.invoke(sql.clj:549)"
  "query_processor.middleware.parameters.sql$fn__36814$parse_optional__36819.invoke(sql.clj:544)"
  "query_processor.middleware.parameters.sql$fn__36855$parse_template__36860$fn__36861.invoke(sql.clj:559)"
  "query_processor.middleware.parameters.sql$fn__36855$parse_template__36860.invoke(sql.clj:556)"
  "query_processor.middleware.parameters.sql$fn__36879$expand_query_params__36884$fn__36888.invoke(sql.clj:569)"
  "query_processor.middleware.parameters.sql$fn__36879$expand_query_params__36884.invoke(sql.clj:567)"
  "query_processor.middleware.parameters.sql$expand.invokeStatic(sql.clj:585)"
  "query_processor.middleware.parameters.sql$expand.invoke(sql.clj:580)"
  "query_processor.middleware.parameters$expand_parameters_STAR_.invokeStatic(parameters.clj:21)"
  "query_processor.middleware.parameters$expand_parameters_STAR_.invoke(parameters.clj:14)"
  "query_processor.middleware.parameters$expand_parameters.invokeStatic(parameters.clj:43)"
  "query_processor.middleware.parameters$expand_parameters.invoke(parameters.clj:40)"
  "query_processor.middleware.parameters$substitute_parameters_STAR_.invokeStatic(parameters.clj:49)"
  "query_processor.middleware.parameters$substitute_parameters_STAR_.invoke(parameters.clj:46)"
  "query_processor.middleware.driver_specific$process_query_in_context$fn__34386.invoke(driver_specific.clj:12)"
  "query_processor.middleware.resolve_driver$resolve_driver$fn__37215.invoke(resolve_driver.clj:15)"
  "query_processor.middleware.bind_effective_timezone$bind_effective_timezone$fn__33550$fn__33551.invoke(bind_effective_timezone.clj:9)"
  "util.date$call_with_effective_timezone.invokeStatic(date.clj:88)"
  "util.date$call_with_effective_timezone.invoke(date.clj:77)"
  "query_processor.middleware.bind_effective_timezone$bind_effective_timezone$fn__33550.invoke(bind_effective_timezone.clj:8)"
  "query_processor.middleware.store$initialize_store$fn__40274$fn__40275.invoke(store.clj:11)"
  "query_processor.store$do_with_new_store.invokeStatic(store.clj:35)"
  "query_processor.store$do_with_new_store.invoke(store.clj:31)"
  "query_processor.middleware.store$initialize_store$fn__40274.invoke(store.clj:10)"
  "query_processor.middleware.async$async__GT_sync$fn__33146.invoke(async.clj:19)"
  "query_processor.middleware.async_wait$runnable$fn__33277.invoke(async_wait.clj:71)"),
 :query
 {:constraints {:max-results 10000, :max-results-bare-rows 2000},
  :type :native,
  :middleware {:userland-query? true},
  :native
  {:template-tags
   {"clinica" {:id "37630506-1b84-bb89-8014-71ff4a7fd937", :name "clinica", :display-name "Clinica", :type :dimension, :required false, :dimension [:field-id 2853], :widget-type :id},
    "fecha"
    {:id "829f4912-a41d-13a9-6e53-abfb5dd0e160",
     :name "fecha",
     :display-name "Fecha",
     :type :dimension,
     :dimension [:field-id 2856],
     :widget-type :date/all-options,
     :required false,
     :default "thisday"}},
   :query
   "..."},
  :info
  {:executed-by 1,
   :context :question,
   :card-id 38,
   :dashboard-id nil,
   :query-hash [62, 57, -12, 12, 16, 89, 114, -87, -20, 109, 90, -62, -10, -20, -3, -3, -122, 58, 108, 85, -97, 7, -97, -12, 111, 10, 126, 78, 58, -32, 5, -51]},
  :parameters [],
  :async? true,
  :cache-ttl 29}}

05-16 16:36:38 DEBUG middleware.log :: POST /api/card/38/query 200 [ASYNC: completed] 3 s (14 DB calls) Jetty threads: 3/50 (8 idle, 0 queued) (61 total active threads) Queries in flight: 1
05-16 16:36:39 DEBUG middleware.log :: GET /api/database/2/metadata 200 4 s (9 DB calls) Jetty threads: 3/50 (8 idle, 0 queued) (61 total active threads) Queries in flight: 1
05-16 16:36:39 ERROR middleware.results-metadata :: Error recording results metadata for query: 
 clojure.lang.ExceptionInfo Output of stored-column-metadata->result-column-metadata does not match schema: 

	   {:name (not ("Non-blank string" "")), :display_name (not ("Non-blank string" ""))}  

 
 ("--> sync.analyze.query_results$fn__40184$stored_column_metadata__GT_result_column_metadata__40189.invoke(query_results.clj:50)"
 "sync.analyze.query_results$results__GT_column_metadata$iter__40202__40206$fn__40207.invoke(query_results.clj:69)"
 "sync.analyze.query_results$results__GT_column_metadata$iter__40215__40219$fn__40220.invoke(query_results.clj:73)"
 "sync.analyze.query_results$results__GT_column_metadata.invokeStatic(query_results.clj:73)"
 "sync.analyze.query_results$results__GT_column_metadata.invoke(query_results.clj:63)"
 "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__40249.invoke(results_metadata.clj:90)"
 "query_processor.middleware.format_rows$format_rows$fn__34625.invoke(format_rows.clj:26)"
 "query_processor.middleware.add_dimension_projections$add_remapping$fn__31752.invoke(add_dimension_projections.clj:234)"
 "query_processor.middleware.add_row_count_and_status$add_row_count_and_status$fn__32146.invoke(add_row_count_and_status.clj:16)"
 "query_processor.middleware.driver_specific$process_query_in_context$fn__34386.invoke(driver_specific.clj:12)"
 "query_processor.middleware.resolve_driver$resolve_driver$fn__37215.invoke(resolve_driver.clj:15)"
 "query_processor.middleware.bind_effective_timezone$bind_effective_timezone$fn__33550$fn__33551.invoke(bind_effective_timezone.clj:9)"
 "util.date$call_with_effective_timezone.invokeStatic(date.clj:88)"
 "util.date$call_with_effective_timezone.invoke(date.clj:77)"
 "query_processor.middleware.bind_effective_timezone$bind_effective_timezone$fn__33550.invoke(bind_effective_timezone.clj:8)"
 "query_processor.middleware.store$initialize_store$fn__40274$fn__40275.invoke(store.clj:11)"
 "query_processor.store$do_with_new_store.invokeStatic(store.clj:35)"
 "query_processor.store$do_with_new_store.invoke(store.clj:31)"
 "query_processor.middleware.store$initialize_store$fn__40274.invoke(store.clj:10)"
 "query_processor.middleware.async$async__GT_sync$fn__33146.invoke(async.clj:19)"
 "query_processor.middleware.async_wait$runnable$fn__33277.invoke(async_wait.clj:71)")

05-16 16:36:39 INFO middleware.cache :: Query took 4382 ms to run; miminum for cache eligibility is 1000 ms
05-16 16:36:39 INFO middleware.cache :: Caching results for next time for query 
05-16 16:36:40 DEBUG middleware.log :: POST /api/card/40/query 200 [ASYNC: completed] 5 s (15 DB calls) Jetty threads: 3/50 (8 idle, 0 queued) (61 total active threads) Queries in flight: 0
05-16 16:36:42 DEBUG middleware.log :: GET /api/field/2183/values 200 82 ms (5 DB calls) Jetty threads: 4/50 (7 idle, 0 queued) (61 total active threads) Queries in flight: 0
05-16 16:36:42 DEBUG middleware.log :: GET /api/field/2183 200 90 ms (7 DB calls) Jetty threads: 3/50 (8 idle, 0 queued) (61 total active threads) Queries in flight: 0

@contradironee

This comment has been minimized.

Copy link

commented May 17, 2019

Similar problem with chart displays in dashboards showing errors, seen on same versions (incl 32.8 now)

Browsers: Chrome 74
Client OS: Windows 10
Database: Redshift
Metabase Version 0.32.8
Metabase Hosting Environment: Heroku
Metabase Internal Database: Postgres 11.2

But also noticing syncing metadata errors in logs, unsure if related or not but some of the graphs that didn't work had error message relation with OID XXXX does not exist so I tried some syncs hoping to fix the problem and found:

May 17 09:18:32 ERROR metabase.sync.util :: Error running sync step: ERROR: type "e" does not exist
("org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440)"
"org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183)"
"org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308)"
"org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)"
"org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)"
"org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:307)"
"org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:293)"
"org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:270)"
"org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:224)"
"org.postgresql.jdbc.PgDatabaseMetaData.getTables(PgDatabaseMetaData.java:1316)"
"com.mchange.v2.c3p0.impl.NewProxyDatabaseMetaData.getTables(NewProxyDatabaseMetaData.java:2938)"
"--> driver.sql_jdbc.sync$get_tables.invokeStatic(sync.clj:90)"
"driver.sql_jdbc.sync$get_tables.invoke(sync.clj:86)"
"driver.sql_jdbc.sync$fast_active_tables$iter__62217__62223$fn__62224.invoke(sync.clj:106)"
"driver.sql_jdbc.sync$fast_active_tables.invokeStatic(sync.clj:105)"
"driver.sql_jdbc.sync$fast_active_tables.doInvoke(sync.clj:94)"
"driver.sql_jdbc.sync$fn__62172.invokeStatic(sync.clj:35)"
"driver.sql_jdbc.sync$fn__62172.invoke(sync.clj:34)"
"driver.sql_jdbc.sync$describe_database.invokeStatic(sync.clj:189)"
"driver.sql_jdbc.sync$describe_database.invoke(sync.clj:185)"
"driver.sql_jdbc$fn__62849.invokeStatic(sql_jdbc.clj:54)"
"driver.sql_jdbc$fn__62849.invoke(sql_jdbc.clj:53)"
"sync.fetch_metadata$fn__45913$db_metadata__45918$fn__45919.invoke(fetch_metadata.clj:13)"
"sync.fetch_metadata$fn__45913$db_metadata__45918.invoke(fetch_metadata.clj:10)"
"sync.sync_metadata.tables$fn__47381$db_metadata__47386$fn__47387.invoke(tables.clj:144)"
"sync.sync_metadata.tables$fn__47381$db_metadata__47386.invoke(tables.clj:141)"
"sync.sync_metadata.tables$fn__47442$sync_tables_BANG___47447$fn__47448.invoke(tables.clj:161)"
"sync.sync_metadata.tables$fn__47442$sync_tables_BANG___47447.invoke(tables.clj:156)"
"sync.util$fn__37761$run_step_with_metadata__37766$fn__37770$fn__37772.invoke(util.clj:356)"
"sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invokeStatic(util.clj:104)"
"sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invoke(util.clj:98)"
"sync.util$with_start_and_finish_debug_logging.invokeStatic(util.clj:121)"
"sync.util$with_start_and_finish_debug_logging.invoke(util.clj:118)"
"sync.util$fn__37761$run_step_with_metadata__37766$fn__37770.invoke(util.clj:353)"
"sync.util$fn__37761$run_step_with_metadata__37766.invoke(util.clj:348)"
"sync.util$fn__37953$run_sync_operation__37958$fn__37959$fn__37960.invoke(util.clj:441)"
"sync.util$fn__37953$run_sync_operation__37958$fn__37959.invoke(util.clj:441)"
"sync.util$fn__37953$run_sync_operation__37958.invoke(util.clj:435)"
"sync.sync_metadata$fn__47495$sync_db_metadata_BANG___47500$fn__47501$fn__47502.invoke(sync_metadata.clj:51)"
"sync.util$do_with_error_handling.invokeStatic(util.clj:149)"
"sync.util$do_with_error_handling.invoke(util.clj:144)"
"sync.util$do_with_error_handling.invokeStatic(util.clj:147)"
"sync.util$do_with_error_handling.invoke(util.clj:144)"
"driver$fn__18010.invokeStatic(driver.clj:646)"
"driver$fn__18010.invoke(driver.clj:646)"
"sync.util$sync_in_context$fn__37667.invoke(util.clj:140)"
"sync.util$with_db_logging_disabled$fn__37664.invoke(util.clj:131)"
"sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invokeStatic(util.clj:104)"
"sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invoke(util.clj:98)"
"sync.util$with_start_and_finish_logging$fn__37653.invoke(util.clj:116)"
"sync.util$with_sync_events$fn__37648.invoke(util.clj:90)"
"sync.util$with_duplicate_ops_prevented$fn__37639.invoke(util.clj:69)"
"sync.util$do_sync_operation.invokeStatic(util.clj:168)"
"sync.util$do_sync_operation.invoke(util.clj:165)"
"sync.sync_metadata$fn__47495$sync_db_metadata_BANG___47500$fn__47501.invoke(sync_metadata.clj:50)"
"sync.sync_metadata$fn__47495$sync_db_metadata_BANG___47500.invoke(sync_metadata.clj:47)"
"api.database$fn__48163$fn__48164.invoke(database.clj:511)")

@n0rritt

This comment has been minimized.

Copy link

commented May 22, 2019

We are experiencing similar problems lately. It is really annoying that some dashboard charts load and some don't, even after multiple refreshes. Does anyone have an idea what could be causing this?

Browsers: Firefox 66.0.5
Client OS: Ubuntu 18.04
Database: Redshift
Metabase Version 0.32.8
Metabase Hosting Environment: AWS EBS
Metabase Internal Database: Postgres 10.6

May 22 09:41:36 WARN metabase.query-processor.middleware.process-userland-query :: Query failure {:status :failed, :class java.sql.SQLNonTransientException, :error "[Amazon][JDBC](10900) Not all parameters have been populated.", :stacktrace ("com.amazon.exceptions.ExceptionConverter.toSQLException(Unknown Source)" "com.amazon.jdbc.common.SPreparedStatement.executeQuery(Unknown Source)" "com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:379)" "clojure.java.jdbc$execute_query_with_params.invokeStatic(jdbc.clj:1072)" "clojure.java.jdbc$execute_query_with_params.invoke(jdbc.clj:1066)" "clojure.java.jdbc$db_query_with_resultset_STAR_.invokeStatic(jdbc.clj:1081)" "clojure.java.jdbc$db_query_with_resultset_STAR_.invoke(jdbc.clj:1075)" "clojure.java.jdbc$query.invokeStatic(jdbc.clj:1164)" "clojure.java.jdbc$query.invoke(jdbc.clj:1126)" "--> driver.sql_jdbc.execute$cancelable_run_query$fn__62557.invoke(execute.clj:177)" "driver.sql_jdbc.execute$do_with_ensured_connection.invokeStatic(execute.clj:154)" "driver.sql_jdbc.execute$do_with_ensured_connection.invoke(execute.clj:152)" "driver.sql_jdbc.execute$cancelable_run_query.invokeStatic(execute.clj:169)" "driver.sql_jdbc.execute$cancelable_run_query.invoke(execute.clj:165)" "driver.sql_jdbc.execute$run_query.invokeStatic(execute.clj:189)" "driver.sql_jdbc.execute$run_query.invoke(execute.clj:185)" "driver.sql_jdbc.execute$do_with_auto_commit_disabled.invokeStatic(execute.clj:236)" "driver.sql_jdbc.execute$do_with_auto_commit_disabled.invoke(execute.clj:224)" "driver.sql_jdbc.execute$do_in_transaction$fn__62576.invoke(execute.clj:241)" "driver.sql_jdbc.execute$do_in_transaction.invokeStatic(execute.clj:240)" "driver.sql_jdbc.execute$do_in_transaction.invoke(execute.clj:239)" "driver.sql_jdbc.execute$run_query_without_timezone.invokeStatic(execute.clj:258)" "driver.sql_jdbc.execute$run_query_without_timezone.invoke(execute.clj:257)" "driver.sql_jdbc.execute$execute_query$fn__62602.invoke(execute.clj:287)" "driver.sql_jdbc.execute$do_with_try_catch.invokeStatic(execute.clj:216)" "driver.sql_jdbc.execute$do_with_try_catch.invoke(execute.clj:210)" "driver.sql_jdbc.execute$execute_query.invokeStatic(execute.clj:284)" "driver.sql_jdbc.execute$execute_query.invoke(execute.clj:278)" "driver.sql_jdbc$fn__62845.invokeStatic(sql_jdbc.clj:48)" "driver.sql_jdbc$fn__62845.invoke(sql_jdbc.clj:47)" "query_processor$fn__40384$execute_query__40389$fn__40390.invoke(query_processor.clj:61)" "query_processor$fn__40384$execute_query__40389.invoke(query_processor.clj:55)" "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__34664.invoke(mbql_to_native.clj:36)" "query_processor.middleware.annotate$result_rows_maps__GT_vectors$fn__32695.invoke(annotate.clj:368)" "query_processor.middleware.annotate$add_column_info$fn__32600.invoke(annotate.clj:303)" "query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__34144.invoke(cumulative_aggregations.clj:57)" "query_processor.middleware.limit$limit$fn__34637.invoke(limit.clj:19)" "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__40249.invoke(results_metadata.clj:86)" "query_processor.middleware.format_rows$format_rows$fn__34625.invoke(format_rows.clj:26)" "query_processor.middleware.add_dimension_projections$add_remapping$fn__31752.invoke(add_dimension_projections.clj:234)" "query_processor.middleware.add_row_count_and_status$add_row_count_and_status$fn__32146.invoke(add_row_count_and_status.clj:16)" "query_processor.middleware.driver_specific$process_query_in_context$fn__34386.invoke(driver_specific.clj:12)" "query_processor.middleware.resolve_driver$resolve_driver$fn__37215.invoke(resolve_driver.clj:15)" "query_processor.middleware.bind_effective_timezone$bind_effective_timezone$fn__33550$fn__33551.invoke(bind_effective_timezone.clj:9)" "util.date$call_with_effective_timezone.invokeStatic(date.clj:88)" "util.date$call_with_effective_timezone.invoke(date.clj:77)" "query_processor.middleware.bind_effective_timezone$bind_effective_timezone$fn__33550.invoke(bind_effective_timezone.clj:8)" "query_processor.middleware.store$initialize_store$fn__40274$fn__40275.invoke(store.clj:11)" "query_processor.store$do_with_new_store.invokeStatic(store.clj:35)" "query_processor.store$do_with_new_store.invoke(store.clj:31)" "query_processor.middleware.store$initialize_store$fn__40274.invoke(store.clj:10)" "query_processor.middleware.async$async__GT_sync$fn__33146.invoke(async.clj:19)" "query_processor.middleware.async_wait$runnable$fn__33277.invoke(async_wait.clj:71)"), :query {:constraints {:max-results 10000, :max-results-bare-rows 2000}, :type :native, :middleware {:userland-query? true}, :native {:query "...", :template-tags {"start_date" {:id "bad28336-fc4b-741c-131e-6e0bfc34e2f6", :name "start_date", :display-name "start_date", :type :date}, "end_date" {:id "670cc506-9ec0-bac8-15ea-c986aa3c190a", :name "end_date", :display-name "end_date", :type :date}}}, :info {:executed-by 38, :context :question, :card-id 538, :dashboard-id nil, :query-hash [97, 96, -38, -44, 42, -20, 124, -32, -1, 53, 73, -75, -11, 44, -9, -15, 71, -103, -109, 92, -26, -18, 21, 58, -125, -91, 5, -9, -81, 52, -107, -73]}, :parameters [{:type "date/single", :target ["variable" ["template-tag" "start_date"]], :value "2019-05-16"} {:type "date/single", :target ["variable" ["template-tag" "end_date"]], :value "2020-12-31"}], :async? true, :cache-ttl 2}}

@flamber

This comment has been minimized.

Copy link
Contributor

commented May 22, 2019

Hi @n0rritt I think you're seeing issue #9955 - you might also be experiencing this issue, but I'm not sure.

@RMMSecurity

This comment has been minimized.

Copy link

commented Jun 3, 2019

Same issue on SQL Server database. It's like the connection isn't being properly kept alive by the pool.

At the very least it would be great if the pool by default would try and test it has a working connection and the socket wasn't closed before running a query.

@pulponair

This comment has been minimized.

Copy link

commented Jun 18, 2019

Same issue on SQL Server database. It's like the connection isn't being properly kept alive by the pool.

At the very least it would be great if the pool by default would try and test it has a working connection and the socket wasn't closed before running a query.

Indeed: that is partly related to this: #10063 i did some research on this. See my comments.

sidenote:
It even gets worse if you connect to the DB using an ssh tunnel cause without "keep alive traffic" not only the DB connections gets closed but also gets the ssh tunnel (which is not reopend by a simple "refresh"). see: #10081

@kelsen

This comment has been minimized.

Copy link

commented Jun 18, 2019

it is difficult to explain to your boss, in the middle of a presentation of results, that the system has a problem that does not load the graph and you have to reload the page constantly to make it work.
This needs to be resolved as soon as possible otherwise discontent will not be justified to the point of maintaining the metabase as a BI solution.

@pulponair

This comment has been minimized.

Copy link

commented Jun 18, 2019

This needs to be resolved as soon as possible otherwise discontent will not be justified to the point of maintaining the metabase as a BI solution.

Indeed. By now the only thing you can do (at least for mysql/maria) is setting the wait_timeout very high e.g: &sessionVariables=wait_timeout=28800 for 8 hours and cross fingers that within 8hours there is some action on that particular connection to keep it alive ;>

Another thing you can try is setting the wait_timeout just sighly higher than an hour since metabase itself is syncing meta data for each db every hour if you r lucky that is enough to keep the connection alive on the server side for most of the time.

@kelsen

This comment has been minimized.

Copy link

commented Jun 19, 2019

Indeed. By now the only thing you can do (at least for mysql/maria) is setting the wait_timeout very high e.g: &sessionVariables=wait_timeout=28800 for 8 hours and cross fingers that within 8hours there is some action on that particular connection to keep it alive ;>

Another thing you can try is setting the wait_timeout just sighly higher than an hour since metabase itself is syncing meta data for each db every hour if you r lucky that is enough to keep the connection alive on the server side for most of the time.

I'm a bit confused, you mean setting this parameters on both metabase connection and mysql server?
wait_timeout=28800 is default.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.