Query times out on metabase but runs on mysql directly

Get Help
1

Hi,

While running the MySQL query from Metabase it always times out giving a "Your question took too long" result. While the same query when run through MySQL client directly or through MySQL workbench, it works fine and completes under ~30 secs. Any idea what could be wrong?

I am running Metabase on an OpenStack instance but it times out when run locally on my Mac as well.

Metabase log:

Dec 28 07:51:35 metabase: 2021-12-28 07:51:35,852 ERROR middleware.catch-exceptions :: Error processing query: null
Dec 28 07:51:35 metabase: {:database_id 5,
Dec 28 07:51:35 metabase: :started_at #t "2021-12-28T07:50:30.108Z[UTC]",
Dec 28 07:51:35 metabase: :via
Dec 28 07:51:35 metabase: [{:status :failed,
Dec 28 07:51:35 metabase: :class clojure.lang.ExceptionInfo,
Dec 28 07:51:35 metabase: :error "Error executing query",
Dec 28 07:51:35 metabase: :stacktrace
Dec 28 07:51:35 metabase: ["--> driver.sql_jdbc.execute$execute_reducible_query$fn__52491.invoke(execute.clj:504)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:501)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:496)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc$fn__85172.invokeStatic(sql_jdbc.clj:54)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc$fn__85172.invoke(sql_jdbc.clj:52)"
Dec 28 07:51:35 metabase: "query_processor.context$executef.invokeStatic(context.clj:59)"
Dec 28 07:51:35 metabase: "query_processor.context$executef.invoke(context.clj:48)"
Dec 28 07:51:35 metabase: "query_processor.context.default$default_runf.invokeStatic(default.clj:68)"
Dec 28 07:51:35 metabase: "query_processor.context.default$default_runf.invoke(default.clj:66)"
Dec 28 07:51:35 metabase: "query_processor.context$runf.invokeStatic(context.clj:45)"
Dec 28 07:51:35 metabase: "query_processor.context$runf.invoke(context.clj:39)"
Dec 28 07:51:35 metabase: "query_processor.reducible$pivot.invokeStatic(reducible.clj:34)"
Dec 28 07:51:35 metabase: "query_processor.reducible$pivot.invoke(reducible.clj:31)"
Dec 28 07:51:35 metabase: "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__49144.invoke(mbql_to_native.clj:25)"
Dec 28 07:51:35 metabase: "query_processor.middleware.check_features$check_features$fn__49630.invoke(check_features.clj:39)"
Dec 28 07:51:35 metabase: "query_processor.middleware.limit$limit$fn__47517.invoke(limit.clj:37)"
Dec 28 07:51:35 metabase: "query_processor.middleware.cache$maybe_return_cached_results$fn__50004.invoke(cache.clj:204)"
Dec 28 07:51:35 metabase: "query_processor.middleware.optimize_temporal_filters$optimize_temporal_filters$fn__50997.invoke(optimize_temporal_filters.clj:204)"
Dec 28 07:51:35 metabase: "query_processor.middleware.validate_temporal_bucketing$validate_temporal_bucketing$fn__51041.invoke(validate_temporal_bucketing.clj:50)"
Dec 28 07:51:35 metabase: "query_processor.middleware.auto_parse_filter_values$auto_parse_filter_values$fn__49201.invoke(auto_parse_filter_values.clj:43)"
Dec 28 07:51:35 metabase: "query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__39249.invoke(wrap_value_literals.clj:161)"
Dec 28 07:51:35 metabase: "query_processor.middleware.annotate$add_column_info$fn__43680.invoke(annotate.clj:620)"
Dec 28 07:51:35 metabase: "query_processor.middleware.permissions$check_query_permissions$fn__45618.invoke(permissions.clj:108)"
Dec 28 07:51:35 metabase: "query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__50181.invoke(pre_alias_aggregations.clj:40)"
Dec 28 07:51:35 metabase: "query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__46016.invoke(cumulative_aggregations.clj:60)"
Dec 28 07:51:35 metabase: "query_processor.middleware.visualization_settings$update_viz_settings$fn__45954.invoke(visualization_settings.clj:63)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_joined_fields$resolve_joined_fields$fn__47115.invoke(resolve_joined_fields.clj:102)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_joins$resolve_joins$fn__50767.invoke(resolve_joins.clj:171)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__50303.invoke(add_implicit_joins.clj:190)"
Dec 28 07:51:35 metabase: "query_processor.middleware.large_int_id$convert_id_to_string$fn__47134.invoke(large_int_id.clj:59)"
Dec 28 07:51:35 metabase: "query_processor.middleware.format_rows$format_rows$fn__50355.invoke(format_rows.clj:74)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_default_temporal_unit$add_default_temporal_unit$fn__46506.invoke(add_default_temporal_unit.clj:23)"
Dec 28 07:51:35 metabase: "query_processor.middleware.desugar$desugar$fn__45927.invoke(desugar.clj:21)"
Dec 28 07:51:35 metabase: "query_processor.middleware.binning$update_binning_strategy$fn__39149.invoke(binning.clj:229)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_fields$resolve_fields$fn__45261.invoke(resolve_fields.clj:34)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_dimension_projections$add_remapping$fn__49556.invoke(add_dimension_projections.clj:312)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__49853.invoke(add_implicit_clauses.clj:147)"
Dec 28 07:51:35 metabase: "query_processor.middleware.upgrade_field_literals$upgrade_field_literals$fn__47502.invoke(upgrade_field_literals.clj:40)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__46883.invoke(add_source_metadata.clj:123)"
Dec 28 07:51:35 metabase: "query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__50103.invoke(reconcile_breakout_and_order_by_bucketing.clj:100)"
Dec 28 07:51:35 metabase: "query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__48453.invoke(auto_bucket_datetimes.clj:147)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_source_table$resolve_source_tables$fn__45242.invoke(resolve_source_table.clj:45)"
Dec 28 07:51:35 metabase: "query_processor.middleware.parameters$substitute_parameters$fn__48107.invoke(parameters.clj:111)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__45315.invoke(resolve_referenced.clj:79)"
Dec 28 07:51:35 metabase: "query_processor.middleware.expand_macros$expand_macros$fn__51425.invoke(expand_macros.clj:184)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_timezone_info$add_timezone_info$fn__47886.invoke(add_timezone_info.clj:15)"
Dec 28 07:51:35 metabase: "query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__50370.invoke(splice_params_in_response.clj:32)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864$fn__49868.invoke(resolve_database_and_driver.clj:31)"
Dec 28 07:51:35 metabase: "driver$do_with_driver.invokeStatic(driver.clj:60)"
Dec 28 07:51:35 metabase: "driver$do_with_driver.invoke(driver.clj:56)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864.invoke(resolve_database_and_driver.clj:25)"
Dec 28 07:51:35 metabase: "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__45865.invoke(fetch_source_query.clj:274)"
Dec 28 07:51:35 metabase: "query_processor.middleware.store$initialize_store$fn__46053$fn__46054.invoke(store.clj:11)"
Dec 28 07:51:35 metabase: "query_processor.store$do_with_store.invokeStatic(store.clj:44)"
Dec 28 07:51:35 metabase: "query_processor.store$do_with_store.invoke(store.clj:38)"
Dec 28 07:51:35 metabase: "query_processor.middleware.store$initialize_store$fn__46053.invoke(store.clj:10)"
Dec 28 07:51:35 metabase: "query_processor.middleware.validate$validate_query$fn__50153.invoke(validate.clj:10)"
Dec 28 07:51:35 metabase: "query_processor.middleware.normalize_query$normalize$fn__50160.invoke(normalize_query.clj:22)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__47832.invoke(add_rows_truncated.clj:35)"
Dec 28 07:51:35 metabase: "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__49130.invoke(results_metadata.clj:147)"
Dec 28 07:51:35 metabase: "query_processor.middleware.constraints$add_default_userland_constraints$fn__47850.invoke(constraints.clj:42)"
Dec 28 07:51:35 metabase: "query_processor.middleware.process_userland_query$process_userland_query$fn__50139.invoke(process_userland_query.clj:146)"
Dec 28 07:51:35 metabase: "query_processor.middleware.catch_exceptions$catch_exceptions$fn__50450.invoke(catch_exceptions.clj:169)"
Dec 28 07:51:35 metabase: "query_processor.reducible$async_qp$qp_STAR___42500$thunk__42501.invoke(reducible.clj:103)"
Dec 28 07:51:35 metabase: "query_processor.reducible$async_qp$qp_STAR___42500.invoke(reducible.clj:109)"
Dec 28 07:51:35 metabase: "query_processor.reducible$sync_qp$qp_STAR___42509$fn__42512.invoke(reducible.clj:135)"
Dec 28 07:51:35 metabase: "query_processor.reducible$sync_qp$qp_STAR___42509.invoke(reducible.clj:134)"
Dec 28 07:51:35 metabase: "query_processor$process_userland_query.invokeStatic(query_processor.clj:243)"
Dec 28 07:51:35 metabase: "query_processor$process_userland_query.doInvoke(query_processor.clj:239)"
Dec 28 07:51:35 metabase: "query_processor$fn__51473$process_query_and_save_execution_BANG___51482$fn__51485.invoke(query_processor.clj:255)"
Dec 28 07:51:35 metabase: "query_processor$fn__51473$process_query_and_save_execution_BANG___51482.invoke(query_processor.clj:247)"
Dec 28 07:51:35 metabase: "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526$fn__51529.invoke(query_processor.clj:267)"
Dec 28 07:51:35 metabase: "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526.invoke(query_processor.clj:260)"
Dec 28 07:51:35 metabase: "api.dataset$run_query_async$fn__57865.invoke(dataset.clj:64)"
Dec 28 07:51:35 metabase: "query_processor.streaming$streaming_response_STAR_$fn__38058$fn__38059.invoke(streaming.clj:148)"
Dec 28 07:51:35 metabase: "query_processor.streaming$streaming_response_STAR_$fn__38058.invoke(streaming.clj:147)"
Dec 28 07:51:35 metabase: "async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:65)"
Dec 28 07:51:35 metabase: "async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:63)"
Dec 28 07:51:35 metabase: "async.streaming_response$do_f_async$fn__25229.invoke(streaming_response.clj:84)"],
Dec 28 07:51:35 metabase: :error_type :invalid-query,
Dec 28 07:51:35 metabase: :ex-data
Dec 28 07:51:35 metabase: {:sql
Dec 28 07:51:35 metabase: "-- Metabase:: userID: 14 queryType: native queryHash: 27ea8902a2704d1c7aee1e9a950094073ce4bf7ccbfca074c1f44c0dbaf43481\nSELECT `cdreport`.`in_trunkgroup` AS `in_trunkgroup`, count(*) AS `count`\nFROM `cdreport`\nWHERE (`cdreport`.`start` >= convert_tz('2021-11-18 00:00:00.000', 'UTC', @@session.time_zone)\n   AND `cdreport`.`start` < convert_tz('2021-11-19 00:00:00.000', 'UTC', @@session.time_zone) AND (lower(`cdreport`.`gwname`) like 'sbcso%'))\nGROUP BY `cdreport`.`in_trunkgroup`\nORDER BY `cdreport`.`in_trunkgroup` ASC",
Dec 28 07:51:35 metabase: :params nil,
Dec 28 07:51:35 metabase: :type :invalid-query}}],
Dec 28 07:51:35 metabase: :state "70100",
Dec 28 07:51:35 metabase: :error_type :invalid-query,
Dec 28 07:51:35 metabase: :json_query
Dec 28 07:51:35 metabase: {:type "native",
Dec 28 07:51:35 metabase: :native
Dec 28 07:51:35 metabase: {:query
Dec 28 07:51:35 metabase: "SELECT `cdreport`.`in_trunkgroup` AS `in_trunkgroup`, count(*) AS `count`\nFROM `cdreport`\nWHERE (`cdreport`.`start` >= convert_tz('2021-11-18 00:00:00.000', 'UTC', @@session.time_zone)\n   AND `cdreport`.`start` < convert_tz('2021-11-19 00:00:00.000', 'UTC', @@session.time_zone) AND (lower(`cdreport`.`gwname`) like 'sbcso%'))\nGROUP BY `cdreport`.`in_trunkgroup`\nORDER BY `cdreport`.`in_trunkgroup` ASC"},
Dec 28 07:51:35 metabase: :database 5,
Dec 28 07:51:35 metabase: :parameters [],
Dec 28 07:51:35 metabase: :middleware {:js-int-to-string? true, :add-default-userland-constraints? true}},
Dec 28 07:51:35 metabase: :status :failed,
Dec 28 07:51:35 metabase: :class java.sql.SQLTimeoutException,
Dec 28 07:51:35 metabase: :stacktrace
Dec 28 07:51:35 metabase: ["org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.createException(ExceptionFactory.java:47)"
Dec 28 07:51:35 metabase: "org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.create(ExceptionFactory.java:153)"
Dec 28 07:51:35 metabase: "org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:274)"
Dec 28 07:51:35 metabase: "org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:363)"
Dec 28 07:51:35 metabase: "org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:501)"
Dec 28 07:51:35 metabase: "com.mchange.v2.c3p0.impl.NewProxyStatement.execute(NewProxyStatement.java:75)"
Dec 28 07:51:35 metabase: "--> driver.sql_jdbc.execute$fn__52411.invokeStatic(execute.clj:368)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$fn__52411.invoke(execute.clj:366)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_statement_or_prepared_statement_BANG_.invokeStatic(execute.clj:376)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_statement_or_prepared_statement_BANG_.invoke(execute.clj:373)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query$fn__52491.invoke(execute.clj:502)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:501)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:496)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc$fn__85172.invokeStatic(sql_jdbc.clj:54)"
Dec 28 07:51:35 metabase: "driver.sql_jdbc$fn__85172.invoke(sql_jdbc.clj:52)"
Dec 28 07:51:35 metabase: "query_processor.context$executef.invokeStatic(context.clj:59)"
Dec 28 07:51:35 metabase: "query_processor.context$executef.invoke(context.clj:48)"
Dec 28 07:51:35 metabase: "query_processor.context.default$default_runf.invokeStatic(default.clj:68)"
Dec 28 07:51:35 metabase: "query_processor.context.default$default_runf.invoke(default.clj:66)"
Dec 28 07:51:35 metabase: "query_processor.context$runf.invokeStatic(context.clj:45)"
Dec 28 07:51:35 metabase: "query_processor.context$runf.invoke(context.clj:39)"
Dec 28 07:51:35 metabase: "query_processor.reducible$pivot.invokeStatic(reducible.clj:34)"
Dec 28 07:51:35 metabase: "query_processor.reducible$pivot.invoke(reducible.clj:31)"
Dec 28 07:51:35 metabase: "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__49144.invoke(mbql_to_native.clj:25)"
Dec 28 07:51:35 metabase: "query_processor.middleware.check_features$check_features$fn__49630.invoke(check_features.clj:39)"
Dec 28 07:51:35 metabase: "query_processor.middleware.limit$limit$fn__47517.invoke(limit.clj:37)"
Dec 28 07:51:35 metabase: "query_processor.middleware.cache$maybe_return_cached_results$fn__50004.invoke(cache.clj:204)"
Dec 28 07:51:35 metabase: "query_processor.middleware.optimize_temporal_filters$optimize_temporal_filters$fn__50997.invoke(optimize_temporal_filters.clj:204)"
Dec 28 07:51:35 metabase: "query_processor.middleware.validate_temporal_bucketing$validate_temporal_bucketing$fn__51041.invoke(validate_temporal_bucketing.clj:50)"
Dec 28 07:51:35 metabase: "query_processor.middleware.auto_parse_filter_values$auto_parse_filter_values$fn__49201.invoke(auto_parse_filter_values.clj:43)"
Dec 28 07:51:35 metabase: "query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__39249.invoke(wrap_value_literals.clj:161)"
Dec 28 07:51:35 metabase: "query_processor.middleware.annotate$add_column_info$fn__43680.invoke(annotate.clj:620)"
Dec 28 07:51:35 metabase: "query_processor.middleware.permissions$check_query_permissions$fn__45618.invoke(permissions.clj:108)"
Dec 28 07:51:35 metabase: "query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__50181.invoke(pre_alias_aggregations.clj:40)"
Dec 28 07:51:35 metabase: "query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__46016.invoke(cumulative_aggregations.clj:60)"
Dec 28 07:51:35 metabase: "query_processor.middleware.visualization_settings$update_viz_settings$fn__45954.invoke(visualization_settings.clj:63)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_joined_fields$resolve_joined_fields$fn__47115.invoke(resolve_joined_fields.clj:102)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_joins$resolve_joins$fn__50767.invoke(resolve_joins.clj:171)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__50303.invoke(add_implicit_joins.clj:190)"
Dec 28 07:51:35 metabase: "query_processor.middleware.large_int_id$convert_id_to_string$fn__47134.invoke(large_int_id.clj:59)"
Dec 28 07:51:35 metabase: "query_processor.middleware.format_rows$format_rows$fn__50355.invoke(format_rows.clj:74)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_default_temporal_unit$add_default_temporal_unit$fn__46506.invoke(add_default_temporal_unit.clj:23)"
Dec 28 07:51:35 metabase: "query_processor.middleware.desugar$desugar$fn__45927.invoke(desugar.clj:21)"
Dec 28 07:51:35 metabase: "query_processor.middleware.binning$update_binning_strategy$fn__39149.invoke(binning.clj:229)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_fields$resolve_fields$fn__45261.invoke(resolve_fields.clj:34)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_dimension_projections$add_remapping$fn__49556.invoke(add_dimension_projections.clj:312)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__49853.invoke(add_implicit_clauses.clj:147)"
Dec 28 07:51:35 metabase: "query_processor.middleware.upgrade_field_literals$upgrade_field_literals$fn__47502.invoke(upgrade_field_literals.clj:40)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__46883.invoke(add_source_metadata.clj:123)"
Dec 28 07:51:35 metabase: "query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__50103.invoke(reconcile_breakout_and_order_by_bucketing.clj:100)"
Dec 28 07:51:35 metabase: "query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__48453.invoke(auto_bucket_datetimes.clj:147)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_source_table$resolve_source_tables$fn__45242.invoke(resolve_source_table.clj:45)"
Dec 28 07:51:35 metabase: "query_processor.middleware.parameters$substitute_parameters$fn__48107.invoke(parameters.clj:111)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__45315.invoke(resolve_referenced.clj:79)"
Dec 28 07:51:35 metabase: "query_processor.middleware.expand_macros$expand_macros$fn__51425.invoke(expand_macros.clj:184)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_timezone_info$add_timezone_info$fn__47886.invoke(add_timezone_info.clj:15)"
Dec 28 07:51:35 metabase: "query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__50370.invoke(splice_params_in_response.clj:32)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864$fn__49868.invoke(resolve_database_and_driver.clj:31)"
Dec 28 07:51:35 metabase: "driver$do_with_driver.invokeStatic(driver.clj:60)"
Dec 28 07:51:35 metabase: "driver$do_with_driver.invoke(driver.clj:56)"
Dec 28 07:51:35 metabase: "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864.invoke(resolve_database_and_driver.clj:25)"
Dec 28 07:51:35 metabase: "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__45865.invoke(fetch_source_query.clj:274)"
Dec 28 07:51:35 metabase: "query_processor.middleware.store$initialize_store$fn__46053$fn__46054.invoke(store.clj:11)"
Dec 28 07:51:35 metabase: "query_processor.store$do_with_store.invokeStatic(store.clj:44)"
Dec 28 07:51:35 metabase: "query_processor.store$do_with_store.invoke(store.clj:38)"
Dec 28 07:51:35 metabase: "query_processor.middleware.store$initialize_store$fn__46053.invoke(store.clj:10)"
Dec 28 07:51:35 metabase: "query_processor.middleware.validate$validate_query$fn__50153.invoke(validate.clj:10)"
Dec 28 07:51:35 metabase: "query_processor.middleware.normalize_query$normalize$fn__50160.invoke(normalize_query.clj:22)"
Dec 28 07:51:35 metabase: "query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__47832.invoke(add_rows_truncated.clj:35)"
Dec 28 07:51:35 metabase: "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__49130.invoke(results_metadata.clj:147)"
Dec 28 07:51:35 metabase: "query_processor.middleware.constraints$add_default_userland_constraints$fn__47850.invoke(constraints.clj:42)"
Dec 28 07:51:35 metabase: "query_processor.middleware.process_userland_query$process_userland_query$fn__50139.invoke(process_userland_query.clj:146)"
Dec 28 07:51:35 metabase: "query_processor.middleware.catch_exceptions$catch_exceptions$fn__50450.invoke(catch_exceptions.clj:169)"
Dec 28 07:51:35 metabase: "query_processor.reducible$async_qp$qp_STAR___42500$thunk__42501.invoke(reducible.clj:103)"
Dec 28 07:51:35 metabase: "query_processor.reducible$async_qp$qp_STAR___42500.invoke(reducible.clj:109)"
Dec 28 07:51:35 metabase: "query_processor.reducible$sync_qp$qp_STAR___42509$fn__42512.invoke(reducible.clj:135)"
Dec 28 07:51:35 metabase: "query_processor.reducible$sync_qp$qp_STAR___42509.invoke(reducible.clj:134)"
Dec 28 07:51:35 metabase: "query_processor$process_userland_query.invokeStatic(query_processor.clj:243)"
Dec 28 07:51:35 metabase: "query_processor$process_userland_query.doInvoke(query_processor.clj:239)"
Dec 28 07:51:35 metabase: "query_processor$fn__51473$process_query_and_save_execution_BANG___51482$fn__51485.invoke(query_processor.clj:255)"
Dec 28 07:51:35 metabase: "query_processor$fn__51473$process_query_and_save_execution_BANG___51482.invoke(query_processor.clj:247)"
Dec 28 07:51:35 metabase: "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526$fn__51529.invoke(query_processor.clj:267)"
Dec 28 07:51:35 metabase: "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526.invoke(query_processor.clj:260)"
Dec 28 07:51:35 metabase: "api.dataset$run_query_async$fn__57865.invoke(dataset.clj:64)"
Dec 28 07:51:35 metabase: "query_processor.streaming$streaming_response_STAR_$fn__38058$fn__38059.invoke(streaming.clj:148)"
Dec 28 07:51:35 metabase: "query_processor.streaming$streaming_response_STAR_$fn__38058.invoke(streaming.clj:147)"
Dec 28 07:51:35 metabase: "async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:65)"
Dec 28 07:51:35 metabase: "async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:63)"
Dec 28 07:51:35 metabase: "async.streaming_response$do_f_async$fn__25229.invoke(streaming_response.clj:84)"],
Dec 28 07:51:35 metabase: :card_id nil,
Dec 28 07:51:35 metabase: :context :ad-hoc,
Dec 28 07:51:35 metabase: :error "(conn=55833) Query execution was interrupted",
Dec 28 07:51:35 metabase: :row_count 0,
Dec 28 07:51:35 metabase: :running_time 0,
Dec 28 07:51:35 metabase: :data {:rows [], :cols []}}
Dec 28 07:51:35 metabase: 2021-12-28 07:51:35,855 DEBUG middleware.log :: #033[32mPOST /api/dataset 202 [ASYNC: canceled] 1.1 mins (5 DB calls) App DB connections: 1/4 Jetty threads: 4/50 (4 idle, 0 queued) (78 total active threads) Queries in flight: 0 (0 queued); mysql DB 5 connections: 0/1 (0 threads blocked)

{
  "browser-info": {
    "language": "en-US",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36",
    "vendor": "Google Inc."
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "1.8.0_252-b09",
    "java.vendor": "Oracle Corporation",
    "java.vendor.url": "http://java.oracle.com/",
    "java.version": "1.8.0_252",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "25.252-b09",
    "os.name": "Linux",
    "os.version": "3.10.0-1062.18.1.el7.x86_64",
    "user.language": "en",
    "user.timezone": "UTC"
  },
  "metabase-info": {
    "databases": [
      "h2",
      "mysql"
    ],
    "hosting-env": "unknown",
    "application-database": "mysql",
    "application-database-details": {
      "database": {
        "name": "MySQL",
        "version": "5.7.33-log"
      },
      "jdbc-driver": {
        "name": "MariaDB Connector/J",
        "version": "2.6.2"
      }
    },
    "run-mode": "prod",
    "version": {
      "tag": "v0.41.5",
      "date": "2021-12-16",
      "branch": "release-x.41.x",
      "hash": "fbfffc6"
    },
    "settings": {
      "report-timezone": "UTC"
    }
  }
}
2

Hi @rameshraithatha
From the log, is looks like you have a reverse-proxy that is closing the connection after ~60 seconds.
You should upgrade to Java 11: https://www.metabase.com/docs/latest/operations-guide/java-versions.html

3

Hi @flamber,

Thank you for replying. The actual query on the MySQL client takes less than 30 seconds so I believe reverse-proxy might not be an issue since it is set to close the connection after 60 seconds. Anyhow, I tried increasing the proxy_read_timeout to 1800 seconds but it still times out in Metabase.

Thanks

4

@rameshraithatha

  1. Your stacktrace says the connection between the browser and Metabase was broken, which is either you closing the browser window, bad internet or a reverse-proxy.
  2. Test with this select sleep(120); executed from MySQL, which run a query that sleeps for 2 minutes. If it fails, then the problem is elsewhere (reverse-proxy, etc).
  3. Did you actually test with the query generated from Metabase or just something similar? You can only see what is actually being executed in your database query log.
  4. Upgrade to Java 11.
5

@flamber

  • Test with select sleep(120); works fine through MySQL client and through Metabase SQL editor as well.
  • Yes, I tested with the query generated from Metabase. I got the query from SHOW FULL PROCESSLIST and also from the SQL editor in Metabase.
  • Upgraded to Java 11 :white_check_mark:
6

@rameshraithatha If it works through Metabase, then you have fixed your reverse-proxy, so it should work now. Otherwise post "Diagnostic Info" from Admin > Troubleshooting, and the full stacktrace (including a couple of lines before and after the stacktrace) from Admin > Troubleshooting > Logs.

7

@flamber Yeah it is still not working after fixing the reverse-proxy. please find below the full stacktrace and the diagnostic info.

Stack trace:

[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:01+05:30 DEBUG metabase.server.middleware.log GET /api/session/properties 200 75.5 ms (2 DB calls) App DB connections: 0/4 Jetty threads: 6/50 (1 idle, 0 queued) (41 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:01+05:30 DEBUG metabase.server.middleware.log GET /api/user/current 200 333.5 ms (3 DB calls) App DB connections: 0/4 Jetty threads: 5/50 (2 idle, 0 queued) (42 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:02+05:30 DEBUG metabase.server.middleware.log GET /api/database 200 159.0 ms (4 DB calls) App DB connections: 0/4 Jetty threads: 5/50 (2 idle, 0 queued) (42 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:17+05:30 DEBUG metabase.server.middleware.log GET /api/user/current 200 86.0 ms (3 DB calls) App DB connections: 1/4 Jetty threads: 6/50 (1 idle, 0 queued) (43 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:17+05:30 DEBUG metabase.server.middleware.log GET /api/session/properties 200 73.5 ms (2 DB calls) App DB connections: 0/4 Jetty threads: 5/50 (1 idle, 0 queued) (43 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:18+05:30 DEBUG metabase.server.middleware.log GET /api/database 200 95.2 ms (3 DB calls) App DB connections: 0/4 Jetty threads: 6/50 (1 idle, 0 queued) (43 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:18+05:30 WARN metabase.models.field Invalid Field :semantic_type :type/Number: falling back to null
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:36:18+05:30 DEBUG metabase.server.middleware.log GET /api/table/20/query_metadata 200 459.7 ms (9 DB calls) App DB connections: 0/4 Jetty threads: 5/50 (1 idle, 0 queued) (43 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:41:25+05:30 ERROR metabase.query-processor.middleware.catch-exceptions Error processing query: null
{:database_id 5,
 :started_at #t "2021-12-28T14:06:19.424612Z[UTC]",
 :via
 [{:status :failed,
   :class clojure.lang.ExceptionInfo,
   :error "Error executing query",
   :stacktrace
   ["--> driver.sql_jdbc.execute$execute_reducible_query$fn__52491.invoke(execute.clj:504)"
    "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:501)"
    "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
    "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:496)"
    "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
    "driver.sql_jdbc$fn__85172.invokeStatic(sql_jdbc.clj:54)"
    "driver.sql_jdbc$fn__85172.invoke(sql_jdbc.clj:52)"
    "query_processor.context$executef.invokeStatic(context.clj:59)"
    "query_processor.context$executef.invoke(context.clj:48)"
    "query_processor.context.default$default_runf.invokeStatic(default.clj:68)"
    "query_processor.context.default$default_runf.invoke(default.clj:66)"
    "query_processor.context$runf.invokeStatic(context.clj:45)"
    "query_processor.context$runf.invoke(context.clj:39)"
    "query_processor.reducible$pivot.invokeStatic(reducible.clj:34)"
    "query_processor.reducible$pivot.invoke(reducible.clj:31)"
    "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__49144.invoke(mbql_to_native.clj:25)"
    "query_processor.middleware.check_features$check_features$fn__49630.invoke(check_features.clj:39)"
    "query_processor.middleware.limit$limit$fn__47517.invoke(limit.clj:37)"
    "query_processor.middleware.cache$maybe_return_cached_results$fn__50004.invoke(cache.clj:204)"
    "query_processor.middleware.optimize_temporal_filters$optimize_temporal_filters$fn__50997.invoke(optimize_temporal_filters.clj:204)"
    "query_processor.middleware.validate_temporal_bucketing$validate_temporal_bucketing$fn__51041.invoke(validate_temporal_bucketing.clj:50)"
    "query_processor.middleware.auto_parse_filter_values$auto_parse_filter_values$fn__49201.invoke(auto_parse_filter_values.clj:43)"
    "query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__39249.invoke(wrap_value_literals.clj:161)"
    "query_processor.middleware.annotate$add_column_info$fn__43680.invoke(annotate.clj:620)"
    "query_processor.middleware.permissions$check_query_permissions$fn__45618.invoke(permissions.clj:108)"
    "query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__50181.invoke(pre_alias_aggregations.clj:40)"
    "query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__46016.invoke(cumulative_aggregations.clj:60)"
    "query_processor.middleware.visualization_settings$update_viz_settings$fn__45954.invoke(visualization_settings.clj:63)"
    "query_processor.middleware.resolve_joined_fields$resolve_joined_fields$fn__47115.invoke(resolve_joined_fields.clj:102)"
    "query_processor.middleware.resolve_joins$resolve_joins$fn__50767.invoke(resolve_joins.clj:171)"
    "query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__50303.invoke(add_implicit_joins.clj:190)"
    "query_processor.middleware.large_int_id$convert_id_to_string$fn__47134.invoke(large_int_id.clj:59)"
    "query_processor.middleware.format_rows$format_rows$fn__50355.invoke(format_rows.clj:74)"
    "query_processor.middleware.add_default_temporal_unit$add_default_temporal_unit$fn__46506.invoke(add_default_temporal_unit.clj:23)"
    "query_processor.middleware.desugar$desugar$fn__45927.invoke(desugar.clj:21)"
    "query_processor.middleware.binning$update_binning_strategy$fn__39149.invoke(binning.clj:229)"
    "query_processor.middleware.resolve_fields$resolve_fields$fn__45261.invoke(resolve_fields.clj:34)"
    "query_processor.middleware.add_dimension_projections$add_remapping$fn__49556.invoke(add_dimension_projections.clj:314)"
    "query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__49853.invoke(add_implicit_clauses.clj:147)"
    "query_processor.middleware.upgrade_field_literals$upgrade_field_literals$fn__47502.invoke(upgrade_field_literals.clj:40)"
    "query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__46883.invoke(add_source_metadata.clj:123)"
    "query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__50103.invoke(reconcile_breakout_and_order_by_bucketing.clj:100)"
    "query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__48453.invoke(auto_bucket_datetimes.clj:147)"
    "query_processor.middleware.resolve_source_table$resolve_source_tables$fn__45242.invoke(resolve_source_table.clj:45)"
    "query_processor.middleware.parameters$substitute_parameters$fn__48107.invoke(parameters.clj:111)"
    "query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__45315.invoke(resolve_referenced.clj:79)"
    "query_processor.middleware.expand_macros$expand_macros$fn__51425.invoke(expand_macros.clj:184)"
    "query_processor.middleware.add_timezone_info$add_timezone_info$fn__47886.invoke(add_timezone_info.clj:15)"
    "query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__50370.invoke(splice_params_in_response.clj:32)"
    "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864$fn__49868.invoke(resolve_database_and_driver.clj:31)"
    "driver$do_with_driver.invokeStatic(driver.clj:60)"
    "driver$do_with_driver.invoke(driver.clj:56)"
    "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864.invoke(resolve_database_and_driver.clj:25)"
    "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__45865.invoke(fetch_source_query.clj:274)"
    "query_processor.middleware.store$initialize_store$fn__46053$fn__46054.invoke(store.clj:11)"
    "query_processor.store$do_with_store.invokeStatic(store.clj:44)"
    "query_processor.store$do_with_store.invoke(store.clj:38)"
    "query_processor.middleware.store$initialize_store$fn__46053.invoke(store.clj:10)"
    "query_processor.middleware.validate$validate_query$fn__50153.invoke(validate.clj:10)"
    "query_processor.middleware.normalize_query$normalize$fn__50160.invoke(normalize_query.clj:22)"
    "query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__47832.invoke(add_rows_truncated.clj:35)"
    "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__49130.invoke(results_metadata.clj:147)"
    "query_processor.middleware.constraints$add_default_userland_constraints$fn__47850.invoke(constraints.clj:42)"
    "query_processor.middleware.process_userland_query$process_userland_query$fn__50139.invoke(process_userland_query.clj:146)"
    "query_processor.middleware.catch_exceptions$catch_exceptions$fn__50450.invoke(catch_exceptions.clj:169)"
    "query_processor.reducible$async_qp$qp_STAR___42500$thunk__42501.invoke(reducible.clj:103)"
    "query_processor.reducible$async_qp$qp_STAR___42500.invoke(reducible.clj:109)"
    "query_processor.reducible$sync_qp$qp_STAR___42509$fn__42512.invoke(reducible.clj:135)"
    "query_processor.reducible$sync_qp$qp_STAR___42509.invoke(reducible.clj:134)"
    "query_processor$process_userland_query.invokeStatic(query_processor.clj:243)"
    "query_processor$process_userland_query.doInvoke(query_processor.clj:239)"
    "query_processor$fn__51473$process_query_and_save_execution_BANG___51482$fn__51485.invoke(query_processor.clj:255)"
    "query_processor$fn__51473$process_query_and_save_execution_BANG___51482.invoke(query_processor.clj:247)"
    "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526$fn__51529.invoke(query_processor.clj:267)"
    "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526.invoke(query_processor.clj:260)"
    "api.dataset$run_query_async$fn__57865.invoke(dataset.clj:64)"
    "query_processor.streaming$streaming_response_STAR_$fn__38058$fn__38059.invoke(streaming.clj:148)"
    "query_processor.streaming$streaming_response_STAR_$fn__38058.invoke(streaming.clj:147)"
    "async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:65)"
    "async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:63)"
    "async.streaming_response$do_f_async$fn__25229.invoke(streaming_response.clj:84)"],
   :error_type :invalid-query,
   :ex-data
   {:sql
    "-- Metabase:: userID: 14 queryType: MBQL queryHash: bbf88a99a0b3538a5e7c989746ce8652be4501310540cdab674839fa903dd6e8\nSELECT `cdreport`.`in_trunkgroup` AS `in_trunkgroup`, count(*) AS `count` FROM `cdreport` WHERE (`cdreport`.`start` >= ? AND `cdreport`.`start` < ? AND (lower(`cdreport`.`gwname`) like ?)) GROUP BY `cdreport`.`in_trunkgroup` ORDER BY `cdreport`.`in_trunkgroup` ASC",
    :params (#t "2021-11-18T00:00Z[UTC]" #t "2021-11-19T00:00Z[UTC]" "sbcso%"),
    :type :invalid-query}}],
 :state "70100",
 :error_type :invalid-query,
 :json_query
 {:type "query",
  :query
  {:source-table 20,
   :filter
   ["and" ["=" ["field" 196 nil] "2021-11-18"] ["starts-with" ["field" 190 nil] "sbcso" {:case-sensitive false}]],
   :aggregation [["count"]],
   :breakout [["field" 191 nil]]},
  :database 5,
  :parameters [],
  :middleware {:js-int-to-string? true, :add-default-userland-constraints? true}},
 :native
 {:query
  "SELECT `cdreport`.`in_trunkgroup` AS `in_trunkgroup`, count(*) AS `count` FROM `cdreport` WHERE (`cdreport`.`start` >= ? AND `cdreport`.`start` < ? AND (lower(`cdreport`.`gwname`) like ?)) GROUP BY `cdreport`.`in_trunkgroup` ORDER BY `cdreport`.`in_trunkgroup` ASC",
  :params (#t "2021-11-18T00:00Z[UTC]" #t "2021-11-19T00:00Z[UTC]" "sbcso%")},
 :status :failed,
 :class java.sql.SQLTimeoutException,
 :stacktrace
 ["org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.createException(ExceptionFactory.java:47)"
  "org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.create(ExceptionFactory.java:153)"
  "org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:274)"
  "org.mariadb.jdbc.ClientSidePreparedStatement.executeInternal(ClientSidePreparedStatement.java:229)"
  "org.mariadb.jdbc.ClientSidePreparedStatement.execute(ClientSidePreparedStatement.java:149)"
  "org.mariadb.jdbc.ClientSidePreparedStatement.executeQuery(ClientSidePreparedStatement.java:163)"
  "com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:431)"
  "--> driver.sql_jdbc.execute$fn__52409.invokeStatic(execute.clj:364)"
  "driver.sql_jdbc.execute$fn__52409.invoke(execute.clj:362)"
  "driver.sql_jdbc.execute$execute_statement_or_prepared_statement_BANG_.invokeStatic(execute.clj:377)"
  "driver.sql_jdbc.execute$execute_statement_or_prepared_statement_BANG_.invoke(execute.clj:373)"
  "driver.sql_jdbc.execute$execute_reducible_query$fn__52491.invoke(execute.clj:502)"
  "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:501)"
  "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
  "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:496)"
  "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:487)"
  "driver.sql_jdbc$fn__85172.invokeStatic(sql_jdbc.clj:54)"
  "driver.sql_jdbc$fn__85172.invoke(sql_jdbc.clj:52)"
  "query_processor.context$executef.invokeStatic(context.clj:59)"
  "query_processor.context$executef.invoke(context.clj:48)"
  "query_processor.context.default$default_runf.invokeStatic(default.clj:68)"
  "query_processor.context.default$default_runf.invoke(default.clj:66)"
  "query_processor.context$runf.invokeStatic(context.clj:45)"
  "query_processor.context$runf.invoke(context.clj:39)"
  "query_processor.reducible$pivot.invokeStatic(reducible.clj:34)"
  "query_processor.reducible$pivot.invoke(reducible.clj:31)"
  "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__49144.invoke(mbql_to_native.clj:25)"
  "query_processor.middleware.check_features$check_features$fn__49630.invoke(check_features.clj:39)"
  "query_processor.middleware.limit$limit$fn__47517.invoke(limit.clj:37)"
  "query_processor.middleware.cache$maybe_return_cached_results$fn__50004.invoke(cache.clj:204)"
  "query_processor.middleware.optimize_temporal_filters$optimize_temporal_filters$fn__50997.invoke(optimize_temporal_filters.clj:204)"
  "query_processor.middleware.validate_temporal_bucketing$validate_temporal_bucketing$fn__51041.invoke(validate_temporal_bucketing.clj:50)"
  "query_processor.middleware.auto_parse_filter_values$auto_parse_filter_values$fn__49201.invoke(auto_parse_filter_values.clj:43)"
  "query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__39249.invoke(wrap_value_literals.clj:161)"
  "query_processor.middleware.annotate$add_column_info$fn__43680.invoke(annotate.clj:620)"
  "query_processor.middleware.permissions$check_query_permissions$fn__45618.invoke(permissions.clj:108)"
  "query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__50181.invoke(pre_alias_aggregations.clj:40)"
  "query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__46016.invoke(cumulative_aggregations.clj:60)"
  "query_processor.middleware.visualization_settings$update_viz_settings$fn__45954.invoke(visualization_settings.clj:63)"
  "query_processor.middleware.resolve_joined_fields$resolve_joined_fields$fn__47115.invoke(resolve_joined_fields.clj:102)"
  "query_processor.middleware.resolve_joins$resolve_joins$fn__50767.invoke(resolve_joins.clj:171)"
  "query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__50303.invoke(add_implicit_joins.clj:190)"
  "query_processor.middleware.large_int_id$convert_id_to_string$fn__47134.invoke(large_int_id.clj:59)"
  "query_processor.middleware.format_rows$format_rows$fn__50355.invoke(format_rows.clj:74)"
  "query_processor.middleware.add_default_temporal_unit$add_default_temporal_unit$fn__46506.invoke(add_default_temporal_unit.clj:23)"
  "query_processor.middleware.desugar$desugar$fn__45927.invoke(desugar.clj:21)"
  "query_processor.middleware.binning$update_binning_strategy$fn__39149.invoke(binning.clj:229)"
  "query_processor.middleware.resolve_fields$resolve_fields$fn__45261.invoke(resolve_fields.clj:34)"
  "query_processor.middleware.add_dimension_projections$add_remapping$fn__49556.invoke(add_dimension_projections.clj:314)"
  "query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__49853.invoke(add_implicit_clauses.clj:147)"
  "query_processor.middleware.upgrade_field_literals$upgrade_field_literals$fn__47502.invoke(upgrade_field_literals.clj:40)"
  "query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__46883.invoke(add_source_metadata.clj:123)"
  "query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__50103.invoke(reconcile_breakout_and_order_by_bucketing.clj:100)"
  "query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__48453.invoke(auto_bucket_datetimes.clj:147)"
  "query_processor.middleware.resolve_source_table$resolve_source_tables$fn__45242.invoke(resolve_source_table.clj:45)"
  "query_processor.middleware.parameters$substitute_parameters$fn__48107.invoke(parameters.clj:111)"
  "query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__45315.invoke(resolve_referenced.clj:79)"
  "query_processor.middleware.expand_macros$expand_macros$fn__51425.invoke(expand_macros.clj:184)"
  "query_processor.middleware.add_timezone_info$add_timezone_info$fn__47886.invoke(add_timezone_info.clj:15)"
  "query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__50370.invoke(splice_params_in_response.clj:32)"
  "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864$fn__49868.invoke(resolve_database_and_driver.clj:31)"
  "driver$do_with_driver.invokeStatic(driver.clj:60)"
  "driver$do_with_driver.invoke(driver.clj:56)"
  "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__49864.invoke(resolve_database_and_driver.clj:25)"
  "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__45865.invoke(fetch_source_query.clj:274)"
  "query_processor.middleware.store$initialize_store$fn__46053$fn__46054.invoke(store.clj:11)"
  "query_processor.store$do_with_store.invokeStatic(store.clj:44)"
  "query_processor.store$do_with_store.invoke(store.clj:38)"
  "query_processor.middleware.store$initialize_store$fn__46053.invoke(store.clj:10)"
  "query_processor.middleware.validate$validate_query$fn__50153.invoke(validate.clj:10)"
  "query_processor.middleware.normalize_query$normalize$fn__50160.invoke(normalize_query.clj:22)"
  "query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__47832.invoke(add_rows_truncated.clj:35)"
  "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__49130.invoke(results_metadata.clj:147)"
  "query_processor.middleware.constraints$add_default_userland_constraints$fn__47850.invoke(constraints.clj:42)"
  "query_processor.middleware.process_userland_query$process_userland_query$fn__50139.invoke(process_userland_query.clj:146)"
  "query_processor.middleware.catch_exceptions$catch_exceptions$fn__50450.invoke(catch_exceptions.clj:169)"
  "query_processor.reducible$async_qp$qp_STAR___42500$thunk__42501.invoke(reducible.clj:103)"
  "query_processor.reducible$async_qp$qp_STAR___42500.invoke(reducible.clj:109)"
  "query_processor.reducible$sync_qp$qp_STAR___42509$fn__42512.invoke(reducible.clj:135)"
  "query_processor.reducible$sync_qp$qp_STAR___42509.invoke(reducible.clj:134)"
  "query_processor$process_userland_query.invokeStatic(query_processor.clj:243)"
  "query_processor$process_userland_query.doInvoke(query_processor.clj:239)"
  "query_processor$fn__51473$process_query_and_save_execution_BANG___51482$fn__51485.invoke(query_processor.clj:255)"
  "query_processor$fn__51473$process_query_and_save_execution_BANG___51482.invoke(query_processor.clj:247)"
  "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526$fn__51529.invoke(query_processor.clj:267)"
  "query_processor$fn__51517$process_query_and_save_with_max_results_constraints_BANG___51526.invoke(query_processor.clj:260)"
  "api.dataset$run_query_async$fn__57865.invoke(dataset.clj:64)"
  "query_processor.streaming$streaming_response_STAR_$fn__38058$fn__38059.invoke(streaming.clj:148)"
  "query_processor.streaming$streaming_response_STAR_$fn__38058.invoke(streaming.clj:147)"
  "async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:65)"
  "async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:63)"
  "async.streaming_response$do_f_async$fn__25229.invoke(streaming_response.clj:84)"],
 :card_id nil,
 :context :ad-hoc,
 :error "(conn=56006) Query execution was interrupted",
 :row_count 0,
 :running_time 0,
 :preprocessed
 {:type :query,
  :query
  {:source-table 20,
   :filter
   [:and
    [:>= [:field 196 {:temporal-unit :default}] [:absolute-datetime #t "2021-11-18T00:00Z[UTC]" :default]]
    [:< [:field 196 {:temporal-unit :default}] [:absolute-datetime #t "2021-11-19T00:00Z[UTC]" :default]]
    [:starts-with
     [:field 190 nil]
     [:value
      "sbcso"
      {:base_type :type/Text,
       :effective_type :type/Text,
       :coercion_strategy nil,
       :semantic_type :type/Category,
       :database_type "VARCHAR",
       :name "gwname"}]
     {:case-sensitive false}]],
   :aggregation [[:aggregation-options [:count] {:name "count"}]],
   :breakout [[:field 191 nil]],
   :order-by [[:asc [:field 191 nil]]]},
  :database 5,
  :middleware {:js-int-to-string? true, :add-default-userland-constraints? true},
  :info
  {:executed-by 14,
   :context :ad-hoc,
   :nested? false,
   :query-hash
   [-69, -8, -118, -103, -96, -77, 83, -118, 94, 124, -104, -105, 70, -50, -122, 82, -66, 69, 1, 49, 5, 64, -51, -85,
    103, 72, 57, -6, -112, 61, -42, -24]},
  :constraints {:max-results 10000, :max-results-bare-rows 2000}},
 :data {:rows [], :cols []}}

[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:41:25+05:30 DEBUG metabase.server.middleware.log POST /api/dataset 202 [ASYNC: canceled] 5.1 mins (10 DB calls) App DB connections: 1/4 Jetty threads: 4/50 (3 idle, 0 queued) (50 total active threads) Queries in flight: 0 (0 queued); mysql DB 5 connections: 0/0 (0 threads blocked)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:43:10+05:30 DEBUG metabase.server.middleware.log GET /api/user/current 200 86.0 ms (3 DB calls) App DB connections: 0/4 Jetty threads: 5/50 (2 idle, 0 queued) (49 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:43:10+05:30 DEBUG metabase.server.middleware.log GET /api/session/properties 200 62.4 ms (2 DB calls) App DB connections: 0/4 Jetty threads: 5/50 (2 idle, 0 queued) (49 total active threads) Queries in flight: 0 (0 queued)
[0d6ad048-7306-46d6-93d8-4bbacf4948dc] 2021-12-28T19:43:11+05:30 DEBUG metabase.server.middleware.log GET /api/database 200 98.8 ms (3 DB calls) App DB connections: 0/4 Jetty threads: 5/50 (1 idle, 0 queued) (49 total active threads) Queries in flight: 0 (0 queued)

Diagnostic info:

{
  "browser-info": {
    "language": "en-US",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36",
    "vendor": "Google Inc."
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.13+8-LTS",
    "java.vendor": "Red Hat, Inc.",
    "java.vendor.url": "https://www.redhat.com/",
    "java.version": "11.0.13",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.13+8-LTS",
    "os.name": "Linux",
    "os.version": "3.10.0-1062.18.1.el7.x86_64",
    "user.language": "en",
    "user.timezone": "UTC"
  },
  "metabase-info": {
    "databases": [
      "h2",
      "mysql"
    ],
    "hosting-env": "unknown",
    "application-database": "mysql",
    "application-database-details": {
      "database": {
        "name": "MySQL",
        "version": "5.7.33-log"
      },
      "jdbc-driver": {
        "name": "MariaDB Connector/J",
        "version": "2.6.2"
      }
    },
    "run-mode": "prod",
    "version": {
      "date": "2021-12-16",
      "tag": "v0.41.5",
      "branch": "release-x.41.x",
      "hash": "fbfffc6"
    },
    "settings": {
      "report-timezone": "UTC"
    }
  }
}
8

@rameshraithatha The query was cancelled by MySQL after after 5.1 minutes. I cannot tell exactly why it's being cancelled, but likely too large packet:
https://stackoverflow.com/questions/49734913/query-execution-was-interrupted-error-1317-70100

9

Thank you for a prompt reply @flamber. Appreciate it!

The query was cancelled after 5 minutes due to the timeout set in Nginx. I tried with a higher timeout value as well but that did not helped.

The packet should not be large as the query returns just 133 rows.

The Metabase question works just fine if I remove the group by count (Summarize by) from the question. Anything to do with the summarize?

10

@rameshraithatha That would be impossible to say for sure without access to your data. Try running EXPLAIN ANALYZE to understand what your database is doing.
I cannot tell you why it's not working, but I would recommend enabling debug logging on your database to understand fully what it's doing.

And you said you had set the Nginx to 1800 seconds, which is 30 minutes, so not sure why it's timing out after 5.1 minutes.
Again, it's impossible to know your setup.

11

@flamber sure, I will try that out. Thanks for helping.

On the Nginx timeout, I later changed it to 5 minutes so that I do not have to wait so long for the timeout

12

@flamber After some googling and consulting the database engineer, it looks like there are some timeouts other than the proxy timeout causing this issue. Are there any timeouts set in Metabase internally that could be causing the query failure?

Is there a way to configure jetty.http.idleTimeout in Metabase? Looks like the default http idle timeout is set to 30 seconds.

13

@rameshraithatha Please try running Metabase locally on your computer. Metabase is being used by thousands of organizations. There's not a timeout after 30 seconds. Something in your network is closing the connection.
Please read this: https://www.metabase.com/docs/latest/troubleshooting-guide/proxies.html