I am running Metabase inside a GKE cluster using the official Docker image and am running into an error with a question on BigQuery taking too long to load. The ingress for the pod is an nginx reverse proxy and a global external application load balancer on GCP, both of which have already been configured to have 300 second timeouts (proxy_connect_timeout, proxy_send_timeout, and proxy_read_timeout for nginx; network endpoint group timeout on the load balancer). The logs in the nginx reverse proxy are showing an error code of 499. The web client does not appear to ever receive a response so there is no error code in the network tab. The query has been tested on BigQuery itself and takes about 50 seconds to run, far shorter than I would expect this issue to happen for.
Log excerpt:
[d4186a3a-8312-4d11-9c14-0d636b459902] 2024-06-21T12:25:55-05:00 ERROR metabase.query-processor.streaming Client closed connection prematurely
org.eclipse.jetty.io.EofException
at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:116 undefined)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422 undefined)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:275 undefined)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:254 undefined)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:386 undefined)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:832 undefined)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:243 undefined)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224 undefined)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:589 undefined)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:1051 undefined)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:1123 undefined)
at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:270 undefined)
at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:254 undefined)
at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:736 undefined)
at java.base/java.util.zip.DeflaterOutputStream.flush(Unknown Source)
at metabase.async.streaming_response$delay_output_stream$fn__52170.invoke(streaming_response.clj:122 undefined)
at metabase.async.streaming_response.proxy$java.io.OutputStream$ff19274a.flush(Unknown Source)
at java.base/sun.nio.cs.StreamEncoder.implFlush(Unknown Source)
at java.base/sun.nio.cs.StreamEncoder.flush(Unknown Source)
at java.base/java.io.OutputStreamWriter.flush(Unknown Source)
at java.base/java.io.BufferedWriter.flush(Unknown Source)
at metabase.query_processor.streaming.json$fn$reify__67245.finish_BANG_(json.clj:115 undefined)
at metabase.query_processor.streaming$streaming_result_fn$result__68031$fn__68032.invoke(streaming.clj:144 undefined)
at metabase.query_processor.streaming$streaming_result_fn$result__68031.invoke(streaming.clj:143 undefined)
at metabase.query_processor.pipeline$_STAR_reduce_STAR_.invokeStatic(pipeline.clj:72 undefined)
at metabase.query_processor.pipeline$_STAR_reduce_STAR_.invoke(pipeline.clj:49 undefined)
at metabase.query_processor.pipeline$_STAR_run_STAR_$respond__56626.invoke(pipeline.clj:86 undefined)
at metabase.driver.bigquery_cloud_sdk$post_process_native.invokeStatic(bigquery_cloud_sdk.clj:425 undefined)
at metabase.driver.bigquery_cloud_sdk$post_process_native.invoke(bigquery_cloud_sdk.clj:408 undefined)
at metabase.driver.bigquery_cloud_sdk$_STAR_process_native_STAR_$thunk__123670.invoke(bigquery_cloud_sdk.clj:441 undefined)
at metabase.driver.bigquery_cloud_sdk$_STAR_process_native_STAR_.invokeStatic(bigquery_cloud_sdk.clj:450 undefined)
at metabase.driver.bigquery_cloud_sdk$_STAR_process_native_STAR_.invoke(bigquery_cloud_sdk.clj:430 undefined)
at metabase.driver.bigquery_cloud_sdk$fn__123677.invokeStatic(bigquery_cloud_sdk.clj:471 undefined)
at metabase.driver.bigquery_cloud_sdk$fn__123677.invoke(bigquery_cloud_sdk.clj:463 undefined)
at clojure.lang.MultiFn.invoke(MultiFn.java:244 undefined)
at metabase.query_processor.pipeline$_STAR_execute_STAR_.invokeStatic(pipeline.clj:47 undefined)
at metabase.query_processor.pipeline$_STAR_execute_STAR_.invoke(pipeline.clj:34 undefined)
at metabase.query_processor.pipeline$_STAR_run_STAR_.invokeStatic(pipeline.clj:88 undefined)
at metabase.query_processor.pipeline$_STAR_run_STAR_.invoke(pipeline.clj:81 undefined)
at metabase.query_processor.execute$run.invokeStatic(execute.clj:60 undefined)
at metabase.query_processor.execute$run.invoke(execute.clj:54 undefined)
at metabase.query_processor.middleware.update_used_cards$update_used_cards_BANG_$fn__69571.invoke(update_used_cards.clj:40 undefined)
at metabase.query_processor.execute$add_native_form_to_result_metadata$fn__69580.invoke(execute.clj:23 undefined)
at metabase.query_processor.execute$add_preprocessed_query_to_result_metadata_for_userland_query$fn__69585.invoke(execute.clj:34 undefined)
at metabase.query_processor.middleware.cache$maybe_return_cached_results$maybe_return_cached_results_STAR___69557.invoke(cache.clj:242 undefined)
at metabase.query_processor.middleware.permissions$check_query_permissions$fn__63714.invoke(permissions.clj:118 undefined)
at metabase.query_processor.middleware.enterprise$check_download_permissions_middleware$fn__64290.invoke(enterprise.clj:51 undefined)
at metabase.query_processor.middleware.enterprise$maybe_apply_column_level_perms_check_middleware$fn__64300.invoke(enterprise.clj:64 undefined)
at metabase.query_processor.execute$execute$fn__69612.invoke(execute.clj:92 undefined)
at metabase.query_processor.setup$do_with_qp_setup.invokeStatic(setup.clj:225 undefined)
at metabase.query_processor.setup$do_with_qp_setup.invoke(setup.clj:216 undefined)
at metabase.query_processor.execute$execute.invokeStatic(execute.clj:91 undefined)
at metabase.query_processor.execute$execute.invoke(execute.clj:87 undefined)
at metabase.query_processor$process_query_STAR__STAR_.invokeStatic(query_processor.clj:47 undefined)
at metabase.query_processor$process_query_STAR__STAR_.invoke(query_processor.clj:43 undefined)
at metabase.query_processor.middleware.enterprise$fn__64317$handle_audit_app_internal_queries__64318$fn__64320.invoke(enterprise.clj:96 undefined)
at metabase.query_processor.middleware.enterprise$handle_audit_app_internal_queries_middleware$fn__64328.invoke(enterprise.clj:103 undefined)
at metabase.query_processor.middleware.process_userland_query$process_userland_query_middleware$fn__75430.invoke(process_userland_query.clj:182 undefined)
at metabase.query_processor.middleware.catch_exceptions$catch_exceptions$fn__75499.invoke(catch_exceptions.clj:128 undefined)
at metabase.query_processor$process_query$fn__75536.invoke(query_processor.clj:78 undefined)
at metabase.query_processor.setup$do_with_canceled_chan$fn__64732.invoke(setup.clj:189 undefined)
at metabase.query_processor.setup$do_with_database_local_settings$fn__64727.invoke(setup.clj:181 undefined)
at metabase.query_processor.setup$do_with_driver$fn__64722$fn__64723.invoke(setup.clj:166 undefined)
at metabase.driver$do_with_driver.invokeStatic(driver.clj:104 undefined)
at metabase.driver$do_with_driver.invoke(driver.clj:99 undefined)
at metabase.query_processor.setup$do_with_driver$fn__64722.invoke(setup.clj:165 undefined)
at metabase.query_processor.setup$do_with_metadata_provider$fn__64715$fn__64718.invoke(setup.clj:151 undefined)
at metabase.query_processor.store$do_with_metadata_provider.invokeStatic(store.clj:171 undefined)
at metabase.query_processor.store$do_with_metadata_provider.invoke(store.clj:151 undefined)
at metabase.query_processor.store$do_with_metadata_provider.invokeStatic(store.clj:160 undefined)
at metabase.query_processor.store$do_with_metadata_provider.invoke(store.clj:151 undefined)
at metabase.query_processor.setup$do_with_metadata_provider$fn__64715.invoke(setup.clj:150 undefined)
at metabase.query_processor.setup$do_with_resolved_database$fn__64709.invoke(setup.clj:128 undefined)
at metabase.query_processor.setup$do_with_qp_setup.invokeStatic(setup.clj:232 undefined)
at metabase.query_processor.setup$do_with_qp_setup.invoke(setup.clj:216 undefined)
at metabase.query_processor$process_query.invokeStatic(query_processor.clj:76 undefined)
at metabase.query_processor$process_query.invoke(query_processor.clj:69 undefined)
at metabase.query_processor.card$process_query_for_card_default_qp.invokeStatic(card.clj:170 undefined)
at metabase.query_processor.card$process_query_for_card_default_qp.invoke(card.clj:166 undefined)
at metabase.query_processor.card$process_query_for_card_default_run_fn$fn__81495$fn__81496.invoke(card.clj:177 undefined)
at metabase.query_processor.streaming$_streaming_response$fn__68043$fn__68044$fn__68045.invoke(streaming.clj:175 undefined)
at metabase.query_processor.streaming$_streaming_response$fn__68043$fn__68044.invoke(streaming.clj:174 undefined)
at metabase.query_processor.streaming$do_with_streaming_rff.invokeStatic(streaming.clj:165 undefined)
at metabase.query_processor.streaming$do_with_streaming_rff.invoke(streaming.clj:152 undefined)
at metabase.query_processor.streaming$_streaming_response$fn__68043.invoke(streaming.clj:171 undefined)
at clojure.lang.AFn.applyToHelper(AFn.java:156 undefined)
at clojure.lang.AFn.applyTo(AFn.java:144 undefined)
at clojure.core$apply.invokeStatic(core.clj:667 undefined)
at clojure.core$with_bindings_STAR_.invokeStatic(core.clj:1990 undefined)
at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1990 undefined)
at clojure.lang.RestFn.applyTo(RestFn.java:142 undefined)
at clojure.core$apply.invokeStatic(core.clj:671 undefined)
at clojure.core$bound_fn_STAR_$fn__5818.doInvoke(core.clj:2020 undefined)
at clojure.lang.RestFn.invoke(RestFn.java:421 undefined)
at metabase.async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:68 undefined)
at metabase.async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:66 undefined)
at metabase.async.streaming_response$do_f_async$task__52153.invoke(streaming_response.clj:87 undefined)
at clojure.lang.AFn.run(AFn.java:22 undefined)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: Broken pipe,
at java.base/sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
at java.base/sun.nio.ch.SocketDispatcher.writev(Unknown Source)
at java.base/sun.nio.ch.IOUtil.write(Unknown Source)
at java.base/sun.nio.ch.IOUtil.write(Unknown Source)
at java.base/sun.nio.ch.SocketChannelImpl.write(Unknown Source)
at java.base/java.nio.channels.SocketChannel.write(Unknown Source)
at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:110 undefined)
... 102 more
[d4186a3a-8312-4d11-9c14-0d636b459902] 2024-06-21T12:25:55-05:00 DEBUG metabase.server.middleware.log POST /api/card/2/query 202 [ASYNC: canceled] 59.3 s (26 DB calls) App DB connections: 1/13 Jetty threads: 2/50 (5 idle, 0 queued) (72 total active threads) Queries in flight: 0 (0 queued) {:metabase-user-id 11}
Diagnostic Info:
{
"browser-info": {
"language": "en-US",
"platform": "Linux x86_64",
"userAgent": "Mozilla/5.0 (X11; Linux x86_64; rv:128.0) Gecko/20100101 Firefox/128.0",
"vendor": ""
},
"system-info": {
"file.encoding": "UTF-8",
"java.runtime.name": "OpenJDK Runtime Environment",
"java.runtime.version": "11.0.23+9",
"java.vendor": "Eclipse Adoptium",
"java.vendor.url": "https://adoptium.net/",
"java.version": "11.0.23",
"java.vm.name": "OpenJDK 64-Bit Server VM",
"java.vm.version": "11.0.23+9",
"os.name": "Linux",
"os.version": "5.15.146+",
"user.language": "en",
"user.timezone": "GMT"
},
"metabase-info": {
"databases": [
"h2",
"bigquery-cloud-sdk"
],
"hosting-env": "unknown",
"application-database": "mysql",
"application-database-details": {
"database": {
"name": "MySQL",
"version": "8.0.31-google"
},
"jdbc-driver": {
"name": "MariaDB Connector/J",
"version": "2.7.10"
}
},
"run-mode": "prod",
"version": {
"date": "2024-06-19",
"tag": "v0.50.6",
"hash": "a5fbebf"
},
"settings": {
"report-timezone": null
}
}
}
EDIT: Formatted log excerpt for easier viewing