Error on querys with many parameters in Presto

[rubenssoto]

Describe the bug We realized in query in PrestoDB with many parameters we had the generic error: Error Executing the query. Logs

[32d0140e-2127-47d2-9324-92a82ad4798c] 2023-01-19T09:57:51-03:00 ERROR metabase.query-processor.middleware.catch-exceptions Erro ao processar a consulta: Error executing query {:database_id 5, :started_at #t "2023-01-19T12:57:50.974596Z[GMT]", :via [{:status :failed, :class java.sql.SQLException, :error "Error executing query", :stacktrace ["com.facebook.presto.jdbc.PrestoStatement.internalExecute(PrestoStatement.java:307)" "com.facebook.presto.jdbc.PrestoStatement.execute(PrestoStatement.java:230)" "com.facebook.presto.jdbc.PrestoPreparedStatement.(PrestoPreparedStatement.java:84)" "com.facebook.presto.jdbc.PrestoConnection.prepareStatement(PrestoConnection.java:142)" "com.facebook.presto.jdbc.PrestoConnection.prepareStatement(PrestoConnection.java:329)" "com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:385)" "--> driver.presto_jdbc$fn91607.invokeStatic(presto_jdbc.clj:393)" "driver.presto_jdbc$fn91607.invoke(presto_jdbc.clj:389)" "driver.sql_jdbc.execute$prepared_statementSTAR.invokeStatic(execute.clj:335)" "driver.sql_jdbc.execute$prepared_statementSTAR.invoke(execute.clj:332)" "driver.sql_jdbc.execute$statement_or_prepared_statement.invokeStatic(execute.clj:359)" "driver.sql_jdbc.execute$statement_or_prepared_statement.invoke(execute.clj:356)" "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:498)" "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:486)" "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:494)" "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:486)" "driver.sql_jdbc$fn86209.invokeStatic(sql_jdbc.clj:54)" "driver.sql_jdbc$fn86209.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:67)" "query_processor.context.default$default_runf.invoke(default.clj:65)" "query_processor.context$runf.invokeStatic(context.clj:45)" "query_processor.context$runf.invoke(context.clj:39)" "query_processor.reducible$identity_qp.invokeStatic(reducible.clj:12)" "query_processor.reducible$identity_qp.invoke(reducible.clj:9)" "query_processor.middleware.cache$run_query_with_cache.invokeStatic(cache.clj:193)" "query_processor.middleware.cache$run_query_with_cache.invoke(cache.clj:178)" "query_processor.middleware.cache$maybe_return_cached_results$maybe_return_cached_results_STAR_52623.invoke(cache.clj:219)" "query_processor.middleware.permissions$check_query_permissions$fn48144.invoke(permissions.clj:109)" "query_processor.middleware.mbql_to_native$mbqlGT_native$fn__51568.invoke(mbql_to_native.clj:23)" "query_processor$fn54099$combined_post_process54104$combined_post_processSTAR54105.invoke(query_processor.clj:212)" "query_processor$fn54099$combined_pre_process54100$combined_pre_process_STAR_54101.invoke(query_processor.clj:209)" "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn52544$fn52549.invoke(resolve_database_and_driver.clj:35)" "driver$do_with_driver.invokeStatic(driver.clj:75)" "driver$do_with_driver.invoke(driver.clj:71)" "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn52544.invoke(resolve_database_and_driver.clj:34)" "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn48579.invoke(fetch_source_query.clj:353)" "query_processor.middleware.store$initialize_store$fn48767$fn48768.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$fn48767.invoke(store.clj:10)" "query_processor.middleware.normalize_query$normalize$fn52816.invoke(normalize_query.clj:22)" "query_processor.middleware.constraints$add_default_userland_constraints$fn49849.invoke(constraints.clj:53)" "query_processor.middleware.process_userland_query$process_userland_query$fn52755.invoke(process_userland_query.clj:145)" "query_processor.middleware.catch_exceptions$catch_exceptions$fn__53127.invoke(catch_exceptions.clj:167)" "query_processor.reducible$async_qp$qpSTAR44982$thunk44984.invoke(reducible.clj:100)" "query_processor.reducible$async_qp$qpSTAR44982$fn44986.invoke(reducible.clj:105)"], :state nil}], :json_query {:constraints {:max-results 10000, :max-results-bare-rows 2000}, :type :native, :middleware {:js-int-to-string? true, :ignore-cached-results? false, :process-viz-settings? false}, :native {:template-tags {"dt_range_start" {:id "fc6819d0-3e3f-bba9-3065-b3c35d316be6", :name "dt_range_start", :display-name "Data de início", :type :date, :required true}, "dt_range_end" {:id "ff5de2f3-1db7-c6cd-cb67-f53d033b8e93", :name "dt_range_end", :display-name "Data de fim", :type :date, :required true}, "poc_category" {:id "044a7515-d7de-6d76-59fa-cb1f1dce39cb", :name "poc_category", :display-name "Categoria do poc", :type :dimension, :dimension [:field 26431 nil], :widget-type :string/=, :default nil}, "poc_id" {:id "90e77ef1-503c-4f80-fd92-f8598cfecbc1", :name "poc_id", :display-name "ID do poc", :type :dimension, :dimension [:field 26426 nil], :widget-type :number/=}, "poc_name" {:id "26b9cc0d-a218-b149-f21f-46027d22215c", :name "poc_name", :display-name "Poc name", :type :dimension, :dimension [:field 26437 nil], :widget-type :string/contains}}, :query "WITH\r\n\r\nbd as(\r\n SELECT\r\n fo.poc_id,\r\n dim_poc.city_name,\r\n dim_poc.state_uf,\r\n dim_poc.poc_name,\r\n --poc.poc_timezone,\r\n fo.order_number,\r\n droh.state AS status,\r\n droh.state,\r\n droh.created_at,\r\n droh.correct_location,\r\n droh.route_id,\r\n droh.created_by as deliveryman_email,\r\n ROW_NUMBER() OVER (PARTITION BY fo.order_number ORDER BY droh.created_at DESC) AS row\r\n \r\n FROM fact_order fo\r\n JOIN sensitive_raw_courier_api.deliveryman_route_order_history droh\r\n ON fo.order_number = droh.order_number\r\n JOIN dim_poc\r\n ON dim_poc.poc_id = fo.poc_id\r\n --LEFT JOIN poc\r\n --ON poc.id = fo.poc_id\r\n \r\n \r\n WHERE \r\n (\r\n droh.created_at BETWEEN date_add('day', -1, cast(concat(cast({{dt_range_start}} as varchar), ' 00:00:00.000 ', 'America/Sao_Paulo') as timestamp) AT TIME ZONE 'UTC' )\r\n AND date_add('day', 1, cast(concat(cast({{dt_range_end}} as varchar), ' 23:59:59.997 ', 'America/Sao_Paulo') as timestamp) AT TIME ZONE 'UTC' )\r\n \r\n \r\n )\r\n \r\n --and droh.state in ('DELIVERED', 'DM_CANCELLATION_REQUEST') \r\n [[AND {{ poc_name }}]]\r\n [[AND {{ poc_id }}]]\r\n [[AND {{ poc_category }}]]\r\n),\r\n\r\nt1 as(\r\n select\r\n bd.poc_id,\r\n bd.city_name,\r\n bd.state_uf,\r\n bd.poc_name,\r\n --bd.poc_timezone,\r\n bd.order_number,\r\n bd.state AS status,\r\n CASE WHEN bd.state in ('DELIVERED', 'DM_CANCELLATION_REQUEST') THEN cast(date_format(bd.created_at at TIME ZONE 'America/Sao_Paulo', '%Y-%m-%d %H:%i:%s') as timestamp)\r\n ELSE cast(date_format(droh2.created_at at TIME ZONE 'America/Sao_Paulo', '%Y-%m-%d %H:%i:%s') as timestamp) END as created_date_time,\r\n CASE WHEN (bd.state in ('DELIVERED', 'DM_CANCELLATION_REQUEST') OR droh2.correct_location IS NULL) THEN bd.correct_location ELSE droh2.correct_location END as status_correct_location,\r\n bd.route_id,\r\n bd.deliveryman_email,\r\n droh2.created_by,\r\n ROW_NUMBER() OVER (PARTITION BY droh2.order_number ORDER BY droh2.created_at DESC) AS rn\r\n \r\n from bd\r\n LEFT JOIN deliveryman_route_order_history as droh2\r\n on bd.order_number = droh2.order_number\r\n \r\n where\r\n bd.row = 1\r\n and droh2.state in ('DELIVERED', 'DM_CANCELLATION_REQUEST')\r\n AND\r\n (\r\n droh2.created_at IS NULL\r\n OR \r\n droh2.created_at BETWEEN date_add('day', -1, cast(concat(cast({{dt_range_start}} as varchar), ' 00:00:00.000 ', 'America/Sao_Paulo') as timestamp) AT TIME ZONE 'UTC' )\r\n AND date_add('day', 1, cast(concat(cast({{dt_range_end}} as varchar), ' 23:59:59.997 ', 'America/Sao_Paulo') as timestamp) AT TIME ZONE 'UTC' )\r\n )\r\n),\r\n\r\nstatus_history as(\r\n select\r\n t1.order_number,\r\n droh.state as status,\r\n droh.correct_location,\r\n droh.created_at,\r\n ROW_NUMBER() OVER (PARTITION BY t1.order_number ORDER BY droh.created_at DESC) AS rn\r\n \r\n from t1\r\n join deliveryman_route_order_history droh\r\n on t1.order_number = droh.order_number\r\n where t1.rn = 1\r\n),\r\n\r\nvalid_last_status as(\r\n select\r\n order_number,\r\n status,\r\n correct_location,\r\n ROW_NUMBER() OVER (PARTITION BY order_number ORDER BY created_at DESC) AS rn\r\n \r\n from (select from status_history where status in ('DELIVERED', 'DM_CANCELLATION_REQUEST') )\r\n),\r\n\r\ndrops as(\r\n\r\n select\r\n route_id,\r\n count() as numero_de_drops\r\n \r\n from t1\r\n where t1.rn = 1\r\n group by 1\r\n),\r\n\r\nlast_order_of_the_route as(\r\n select\r\n t1.route_id,\r\n --t1.poc_timezone,\r\n cast(date_format(max( droh.created_at) at TIME ZONE 'America/Sao_Paulo', '%Y-%m-%d %H:%i:%s') as timestamp) as last_order_of_the_route_delivered_date\r\n \r\n from t1\r\n left join deliveryman_route_order_history droh\r\n on t1.route_id = droh.route_id\r\n \r\n where droh.state in ('DELIVERED', 'DM_CANCELLATION_REQUEST')\r\n and t1.rn = 1\r\n \r\n group by 1--,2\r\n),\r\n\r\nresult as(\r\nSELECT\r\ncast(date_format(t1.created_date_time, '%Y-%m-%d %H:%i:%s') as varchar) AS order_datetime,\r\ncast(date_format(lo.last_order_of_the_route_delivered_date, '%Y-%m-%d %H:%i:%s') as varchar) AS last_order_of_the_route_datetime,\r\n--TO_CHAR(rd.created_date_time, 'YYYY-MM-DD HH24:MI:SS') AS route_datetime, \r\ncast(lo.last_order_of_the_route_delivered_date as date) as last_order_of_the_route_day,\r\nEXTRACT(HOUR FROM lo.last_order_of_the_route_delivered_date) AS last_order_of_the_route_hour,\r\nextract(week from lo.last_order_of_the_route_delivered_date) AS last_order_of_the_route_week,\r\nt1.poc_id,\r\nt1.poc_name,\r\nt1.city_name,\r\nt1.state_uf,\r\nt1.order_number,\r\nls.status as last_status,\r\nvls.status as previous_status,\r\nvls.correct_location,\r\nt1.route_id,\r\nCASE WHEN deliveryman_email != 'ze' THEN deliveryman_email ELSE created_by END as deliveryman_email,\r\nCASE WHEN\r\n (\r\n vls.status = 'DELIVERED'\r\n --OR (ls.status = 'CANCELLED' AND t1.correct_location = 'true')\r\n --OR (vls.status = 'DM_CANCELLATION_REQUEST' AND vls.correct_location = 'true')\r\n )\r\n THEN 'PAGAR' ELSE 'NÃO_PAGAR' END as recebe_pgto,\r\nd.numero_de_drops\r\n \r\nFROM t1\r\n--LEFT JOIN (select id, CONVERT_TIMEZONE('BRA', finished_at) AS created_date_time FROM raw_courier_api.deliveryman_route) rd\r\n-- ON rd.id = t1.route_id\r\nLEFT JOIN drops d\r\n ON t1.route_id = d.route_id\r\nLEFT JOIN (select from status_history where rn = 1) ls --last_status\r\n ON t1.order_number = ls.order_number\r\nLEFT JOIN (select from valid_last_status where rn = 1) vls --valid_last_status\r\n ON t1.order_number = vls.order_number \r\nLEFT JOIN last_order_of_the_route lo\r\n ON t1.route_id = lo.route_id\r\n\r\nWHERE t1.rn = 1\r\nAND lo.last_order_of_the_route_delivered_date BETWEEN {{ dt_range_start }} AND DATE_ADD('day', 1, {{ dt_range_end }})\r\n\r\n\r\nORDER BY 2, 1\r\n)\r\n\r\nselect * from result"}, :database 5, :parameters [{:type "date/single", :value "2022-12-26", :target ["variable" ["template-tag" "dt_range_start"]], :id "fc6819d0-3e3f-bba9-3065-b3c35d316be6"} {:type "date/single", :value "2023-01-01", :target ["variable" ["template-tag" "dt_range_end"]], :id "ff5de2f3-1db7-c6cd-cb67-f53d033b8e93"} {:type "number/=", :value [4176 40557 19176 19859 20012 18914 49020 58019 68731 71920 15126 12395 32535 74794 74791 74478 74806 74485 74804 26540 74801 74807 74481 74800], :target ["dimension" ["template-tag" "poc_id"]], :id "90e77ef1-503c-4f80-fd92-f8598cfecbc1"}], :async? true, :cache-ttl 11}, :status :failed, :class java.lang.RuntimeException, :stacktrace ["com.facebook.presto.jdbc.internal.client.StatementClientV1.requestFailedException(StatementClientV1.java:497)" "com.facebook.presto.jdbc.internal.client.StatementClientV1.(StatementClientV1.java:138)" "com.facebook.presto.jdbc.internal.client.StatementClientFactory.newStatementClient(StatementClientFactory.java:24)" "com.facebook.presto.jdbc.QueryExecutor.startQuery(QueryExecutor.java:46)" "com.facebook.presto.jdbc.PrestoConnection.startQuery(PrestoConnection.java:768)" "com.facebook.presto.jdbc.PrestoStatement.internalExecute(PrestoStatement.java:263)" "com.facebook.presto.jdbc.PrestoStatement.execute(PrestoStatement.java:230)" "com.facebook.presto.jdbc.PrestoPreparedStatement.(PrestoPreparedStatement.java:84)" "com.facebook.presto.jdbc.PrestoConnection.prepareStatement(PrestoConnection.java:142)" "com.facebook.presto.jdbc.PrestoConnection.prepareStatement(PrestoConnection.java:329)" "com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:385)" "--> driver.presto_jdbc$fn91607.invokeStatic(presto_jdbc.clj:393)" "driver.presto_jdbc$fn91607.invoke(presto_jdbc.clj:389)" "driver.sql_jdbc.execute$prepared_statementSTAR.invokeStatic(execute.clj:335)" "driver.sql_jdbc.execute$prepared_statementSTAR.invoke(execute.clj:332)" "driver.sql_jdbc.execute$statement_or_prepared_statement.invokeStatic(execute.clj:359)" "driver.sql_jdbc.execute$statement_or_prepared_statement.invoke(execute.clj:356)" "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:498)" "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:486)" "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:494)" "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:486)" "driver.sql_jdbc$fn86209.invokeStatic(sql_jdbc.clj:54)" "driver.sql_jdbc$fn86209.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:67)" "query_processor.context.default$default_runf.invoke(default.clj:65)" "query_processor.context$runf.invokeStatic(context.clj:45)" "query_processor.context$runf.invoke(context.clj:39)" "query_processor.reducible$identity_qp.invokeStatic(reducible.clj:12)" "query_processor.reducible$identity_qp.invoke(reducible.clj:9)" "query_processor.middleware.cache$run_query_with_cache.invokeStatic(cache.clj:193)" "query_processor.middleware.cache$run_query_with_cache.invoke(cache.clj:178)" "query_processor.middleware.cache$maybe_return_cached_results$maybe_return_cached_resultsSTAR52623.invoke(cache.clj:219)" "query_processor.middleware.permissions$check_query_permissions$fn48144.invoke(permissions.clj:109)" "query_processor.middleware.mbql_to_native$mbql__GT_native$fn51568.invoke(mbql_to_native.clj:23)" "query_processor$fn54099$combined_post_process54104$combined_post_process_STAR_54105.invoke(query_processor.clj:212)" "query_processor$fn54099$combined_pre_process54100$combined_pre_process_STAR_54101.invoke(query_processor.clj:209)" "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn52544$fn52549.invoke(resolve_database_and_driver.clj:35)" "driver$do_with_driver.invokeStatic(driver.clj:75)" "driver$do_with_driver.invoke(driver.clj:71)" "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn52544.invoke(resolve_database_and_driver.clj:34)" "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn48579.invoke(fetch_source_query.clj:353)" "query_processor.middleware.store$initialize_store$fn48767$fn48768.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$fn48767.invoke(store.clj:10)" "query_processor.middleware.normalize_query$normalize$fn__52816.invoke(normalize_query.clj:22)" "query_processor.middleware.constraints$add_default_userland_constraints$fn49849.invoke(constraints.clj:53)" "query_processor.middleware.process_userland_query$process_userland_query$fn52755.invoke(process_userland_query.clj:145)" "query_processor.middleware.catch_exceptions$catch_exceptions$fn__53127.invoke(catch_exceptions.clj:167)" "query_processor.reducible$async_qp$qpSTAR44982$thunk44984.invoke(reducible.clj:100)" "query_processor.reducible$async_qp$qpSTAR44982$fn__44986.invoke(reducible.clj:105)"], :card_id 6108, :context :question, :error "Error executing query", :row_count 0, :running_time 0, :data {:rows [], :cols []}}

To Reproduce Create a query with one parameter and put more than 40 values, for example:

select count(1) from refined_dw.fact_order join refined_dw.dim_poc on refined_dw.fact_order.poc_id = refined_dw.dim_poc.poc_id where 1=1 [[AND {{ poc_id }}]]

[paoliniluis]

Hi @rubenssoto, can you provide some information? 1) diagnostic info 2) if you run with 39 parameters it works?

[rubenssoto]

@paoliniluis I'm really confused with this problem, sometimes works, sometimes don't, that error means something to you? I'm having some difficult to debug because the error is generic.

[paoliniluis]

There’s no error that we can work on unfortunately here. To start debugging we’ll need a consistent reproduction of the bug

[rubenssoto]

@paoliniluis its hard to create a situation, do you suggest me a dataset that you have access and I can try to simulate.

I think the problem is something related to the size of query + parameters

I was seeing this msg on Presto Log org.eclipse.jetty.http.HttpParser Header is too large 8193>8192

I increase MB_JETTY_REQUEST_HEADER_SIZE to 32k, the warning msg was gone but I realize the metabase is only executing the PREPARE statement.

[rubenssoto]

@paoliniluis