Reports timing out

efrederick · May 3, 2021, 3:32pm

After several tests I am able to reproduce this issue consistently. If you'd like to setup a remote troubleshooting session so I can reproduce the issue for you in real time, I'd be happy to do so. Steps to reproduce:

Login as a user with the client permissions
Click on the top 3 reports that the user sees when logged in
By the time you go to run the third report, it hangs. I've been able to recreate this 5x now. After each test I've rebooted the docker container
One thing to note: when logged in as the admin, I cannot recreate this issue.

Below are the logs and screenshot of the session status. The logs start after the container finished starting.

The line in the log that starts with "GET /api/dashboard/61" is the call to the third report.

[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:20-04:00 INFO metabase.driver.impl Registered driver :sqlserver (parents: [:sql-jdbc]) 🚚
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:21-04:00 DEBUG metabase.plugins.jdbc-proxy Registering JDBC proxy driver for com.microsoft.sqlserver.jdbc.SQLServerDriver...
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/968/query 202 [ASYNC: completed] 3.9 s (12 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (161 total active threads) Queries in flight: 39 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/989/query 202 [ASYNC: completed] 3.5 s (12 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (161 total active threads) Queries in flight: 38 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/990/query 202 [ASYNC: completed] 3.7 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 38 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/982/query 202 [ASYNC: completed] 3.9 s (12 DB calls) App DB connections: 7/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 37 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/256/query 202 [ASYNC: completed] 4.2 s (12 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 36 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/984/query 202 [ASYNC: completed] 3.7 s (12 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 35 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/976/query 202 [ASYNC: completed] 4.0 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 34 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/974/query 202 [ASYNC: completed] 3.8 s (12 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 33 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/970/query 202 [ASYNC: completed] 3.7 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 32 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/992/query 202 [ASYNC: completed] 3.7 s (12 DB calls) App DB connections: 3/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 32 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/959/query 202 [ASYNC: completed] 4.2 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 31 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/975/query 202 [ASYNC: completed] 3.9 s (12 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 30 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/979/query 202 [ASYNC: completed] 3.9 s (12 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 29 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/418/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 3/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 27 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/417/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 3/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 25 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/981/query 202 [ASYNC: completed] 3.9 s (12 DB calls) App DB connections: 3/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 24 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/960/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 24 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/967/query 202 [ASYNC: completed] 4.2 s (12 DB calls) App DB connections: 3/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 22 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:23-04:00 DEBUG metabase.server.middleware.log POST /api/card/972/query 202 [ASYNC: completed] 4.0 s (12 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 21 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/983/query 202 [ASYNC: completed] 4.1 s (12 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 21 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/986/query 202 [ASYNC: completed] 3.9 s (12 DB calls) App DB connections: 2/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 19 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/988/query 202 [ASYNC: completed] 3.9 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 19 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/971/query 202 [ASYNC: completed] 4.0 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 18 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/964/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 17 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/961/query 202 [ASYNC: completed] 4.2 s (12 DB calls) App DB connections: 7/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 17 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/980/query 202 [ASYNC: completed] 4.2 s (12 DB calls) App DB connections: 6/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 17 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/978/query 202 [ASYNC: completed] 4.2 s (12 DB calls) App DB connections: 6/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 17 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/965/query 202 [ASYNC: completed] 4.4 s (12 DB calls) App DB connections: 7/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 15 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/991/query 202 [ASYNC: completed] 4.2 s (12 DB calls) App DB connections: 7/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 15 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/969/query 202 [ASYNC: completed] 4.1 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 14 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/963/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 3/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 12 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/985/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 10 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/977/query 202 [ASYNC: completed] 4.4 s (12 DB calls) App DB connections: 6/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 10 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/966/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 10 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/987/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 4/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 10 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/958/query 202 [ASYNC: completed] 4.7 s (12 DB calls) App DB connections: 3/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 4 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/973/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 2/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 3 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/962/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 2/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 2 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/957/query 202 [ASYNC: completed] 4.7 s (12 DB calls) App DB connections: 2/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 1 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:24-04:00 DEBUG metabase.server.middleware.log POST /api/card/993/query 202 [ASYNC: completed] 4.3 s (12 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 0 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:31-04:00 DEBUG metabase.server.middleware.log GET /api/collection/7 200 7.5 ms (3 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (163 total active threads) Queries in flight: 0 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:32-04:00 DEBUG metabase.server.middleware.log GET /api/dashboard/46 200 152.4 ms (37 DB calls) App DB connections: 1/15 Jetty threads: 3/50 (25 idle, 0 queued) (163 total active threads) Queries in flight: 0 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:33-04:00 DEBUG metabase.server.middleware.log POST /api/card/924/query 202 [ASYNC: completed] 697.8 ms (17 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 19 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:34-04:00 DEBUG metabase.server.middleware.log POST /api/card/490/query 202 [ASYNC: completed] 1.0 s (16 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 18 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:34-04:00 DEBUG metabase.server.middleware.log POST /api/card/391/query 202 [ASYNC: completed] 1.1 s (12 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 17 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:34-04:00 DEBUG metabase.server.middleware.log POST /api/card/390/query 202 [ASYNC: completed] 1.1 s (12 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 16 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:34-04:00 DEBUG metabase.server.middleware.log POST /api/card/489/query 202 [ASYNC: completed] 1.3 s (16 DB calls) App DB connections: 1/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 15 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:37-04:00 DEBUG metabase.server.middleware.log GET /api/collection/7 200 6.2 ms (3 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 15 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1015/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 14 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1034/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 13 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1038/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 12 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1040/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 11 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1036/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 11 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1032/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 11 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1017/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 8 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1031/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 7 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1039/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 6 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1030/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 4/50 (25 idle, 0 queued) (173 total active threads) Queries in flight: 6 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1045/query 202 [ASYNC: canceled] 6.1 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 5 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/926/query 202 [ASYNC: canceled] 6.2 s (22 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 3 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1016/query 202 [ASYNC: canceled] 6.2 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 1 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1037/query 202 [ASYNC: canceled] 6.1 s (22 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 2 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:39-04:00 DEBUG metabase.server.middleware.log POST /api/card/pivot/1033/query 202 [ASYNC: canceled] 6.2 s (21 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 1 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:40-04:00 DEBUG metabase.server.middleware.log GET /api/dashboard/61 200 146.7 ms (43 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (25 idle, 0 queued) (173 total active threads) Queries in flight: 0 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:43-04:00 DEBUG metabase.server.middleware.log GET /api/database/2/schemas 200 20.7 ms (5 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 23 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:52-04:00 DEBUG metabase.server.middleware.log GET /api/collection/7 200 5.6 ms (3 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 23 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/923/query 202 [ASYNC: canceled] 14.0 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 23 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/606/query 202 [ASYNC: canceled] 14.0 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 22 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/911/query 202 [ASYNC: canceled] 14.0 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 21 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/609/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 19 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/392/query 202 [ASYNC: canceled] 14.1 s (7 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 16 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/900/query 202 [ASYNC: canceled] 14.1 s (8 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 16 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/908/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (25 idle, 0 queued) (173 total active threads) Queries in flight: 15 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/920/query 202 [ASYNC: canceled] 14.1 s (8 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 16 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/1043/query 202 [ASYNC: canceled] 14.1 s (7 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 14 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/610/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 13 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/591/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 12 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/910/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (25 idle, 0 queued) (173 total active threads) Queries in flight: 11 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/1042/query 202 [ASYNC: canceled] 14.1 s (7 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 10 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/613/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 9 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/909/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 8 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/605/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 7 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/608/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 6 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/907/query 202 [ASYNC: canceled] 14.1 s (11 DB calls) App DB connections: 0/15 Jetty threads: 4/50 (25 idle, 0 queued) (173 total active threads) Queries in flight: 5 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/1044/query 202 [ASYNC: canceled] 14.1 s (7 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 4 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/921/query 202 [ASYNC: canceled] 14.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 3 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/607/query 202 [ASYNC: canceled] 14.2 s (11 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 3 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/922/query 202 [ASYNC: canceled] 14.0 s (7 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 1 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:54-04:00 DEBUG metabase.server.middleware.log POST /api/card/590/query 202 [ASYNC: canceled] 14.2 s (9 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (173 total active threads) Queries in flight: 0 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:21:55-04:00 DEBUG metabase.server.middleware.log GET /api/dashboard/63 200 111.0 ms (26 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (25 idle, 0 queued) (173 total active threads) Queries in flight: 0 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:22:19-04:00 DEBUG metabase.server.middleware.log GET /api/collection/7 200 4.9 ms (3 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (26 idle, 0 queued) (184 total active threads) Queries in flight: 13 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:22:20-04:00 DEBUG metabase.server.middleware.log POST /api/card/913/query 202 [ASYNC: canceled] 25.0 s (11 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (26 idle, 0 queued) (184 total active threads) Queries in flight: 13 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:22:20-04:00 DEBUG metabase.server.middleware.log POST /api/card/912/query 202 [ASYNC: canceled] 25.0 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (25 idle, 0 queued) (183 total active threads) Queries in flight: 11 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:22:20-04:00 DEBUG metabase.server.middleware.log POST /api/card/914/query 202 [ASYNC: canceled] 25.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (25 idle, 0 queued) (183 total active threads) Queries in flight: 9 (0 queued)
[eef4bde8-ab42-4b64-bf73-2fac6d7aed11] 2021-05-03T11:22:20-04:00 DEBUG metabase.server.middleware.log POST /api/card/417/query 202 [ASYNC: canceled] 25.1 s (9 DB calls) App DB connections: 0/15 Jetty threads: 2/50 (25 idle, 0 queued) (183 total active threads) Queries in flight: 9 (0 queued)

flamber · May 3, 2021, 5:36pm

@efrederick I've been trying to reproduce with your details for two hours on several different setups - and I find point 4 very interesting, so I mainly only tested with that scenario.
But there must be something specific to your setup/environment, which makes me unable to trigger this.
Would really love to figure this out, so we can reproduce, test and fix locally.
Currently it looks like we have to have you test with one of our builds.

It is expected that it will use up to 15 connections for the database, and after they have been idle for 5/15 minutes, then those should be closed. The status you show, only lists connections idle for ~2 minutes.

But it seems like the problem is that the internal connection pool/queue in Metabase (c3p0) doesn't understand that the connection is idle, so it never closes the connection, but it also means that it cannot use the connection for new queries, which leads to the lockup you're seeing.

I also find it interesting, that you weren't able to make new queries, when you killed some of the connections on the database, but last time it was showing several "Queries in flight", so if you closed a connection, then one of those "in flight" might have taken up that connection right away.

efrederick · May 3, 2021, 7:28pm

Ok. How would I obtain one of your builds for further testing?

flamber · May 3, 2021, 7:39pm

@efrederick We're working on adding some debug info specific to SQL Server connection right now.
https://github.com/metabase/metabase/pull/15908

We should be able to have something later today/tomorrow.

Though, the build is currently based on the upcoming v40, so you'll need to backup your application database, run the build and test, and then revert to your backup to get back to 39.1 state.

efrederick · May 4, 2021, 7:04pm

So we have found a workaround for our issue. After playing around with some settings in AWS I found that the issue went away when I didn't route the traffic to the server through our application load balancer. We have an Nginx server setup already so I just routed traffic through that instead. Since doing that we've not been able to recreate the issue after several attempts.

So in summary, our issue arises when we run reports as non-admins, through an AWS ALB, if that helps you out

flamber · May 4, 2021, 7:11pm

@efrederick Awesome! Thank you for the input - it was exactly what I thought was the problem, which is why I have been testing so many combinations of proxying locally to try to reproduce what ALB is doing, since it's probably not the only load-balancer that can cause interesting stuff like that.