Client refreshes when opening a saved question or switching to SQL mode with SQL Server DB

bt2016 · November 7, 2016, 5:15pm

I am creating a dashboard based off of a SQL Server DB connection. The first time I create the DB connection, I can make a few questions, save them, add them to the dashboard, and then refresh/modify them. If I close out and come back the following day, whenever I open those saved questions, Metabase displays the ‘Doing Science’ text for about a second, then refreshes completely and takes me back to the main activity log.

This happens for all questions/dashboards I created, and I cannot create a new questions from that DB using the raw SQL editor. I can successfully run a query from the GUI. Other connections (Redshift) work fine. This is on the OSX client, v20.0.

It seems like there is something wrong with re-establishing the connection, but nothing jumped out from the logs. Any suggestions would be very helpful, thanks!

sameer · November 7, 2016, 5:36pm

sounds like the server is crashing.

can you open up the Console app, and capture the logs when this happens?

bt2016 · November 7, 2016, 7:39pm

Here are the system logs when I open a saved question (removed actual query info):

+--------------------------------------------------------------------+
|           Server status has transitioned to: HEALTHY               |
+--------------------------------------------------------------------+

Nov 7 11:32:25 Bretts-MB Metabase[1328]: Connecting to Metabase instance at: http://localhost:13280
Nov 7 11:32:26 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/user/current 200 (6 ms) (1 DB calls)
DEBUG metabase.middleware :: GET /api/session/properties 200 (6 ms) (1 DB calls)
Nov 7 11:32:26 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/dashboard 200 (280 ms) (2 DB calls)
Nov 7 11:32:26 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/activity/recent_views 200 (275 ms) (1 DB calls)
Nov 7 11:32:26 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/activity 200 (348 ms) (6 DB calls)
Nov 7 11:32:26 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/setup/admin_checklist 200 (371 ms) (10 DB calls)
Nov 7 11:32:36 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/database 200 (731 ms) (3 DB calls)
Nov 7 11:32:36 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/card/11 200 (10 ms) (5 DB calls)
Nov 7 11:32:37 Bretts-MB Metabase[1328]: DEBUG metabase.query-processor ::
QUERY:
{:database 6,
type “native”,
native
{:query info, :query-type “native”}}
Nov 7 11:32:37 Bretts-MB Metabase[1328]:
Nov 7 11:32:37 Bretts-MB Metabase[1328]:

+--------------------------------------------------------------------+
|           Server status has transitioned to: NOT HEALTHY           |
+--------------------------------------------------------------------+

Nov 7 11:32:38 Bretts-MB Metabase[1328]:
Nov 7 11:32:40 — last message repeated 1 time —
Nov 7 11:32:40 Bretts-MB Metabase[1328]: DEBUG query-processor.permissions :: Permissions Check : Can User 1 run existing native queries against Database 6 (Client)?
DEBUG query-processor.permissions :: Permissions Check : Yes because User 1 is a member of Group 1 (All Users) which has permissions for ‘/db/6/’
Nov 7 11:32:40 Bretts-MB Metabase[1328]: DEBUG metabase.query-processor :: NATIVE FORM:
{:query info}

DEBUG driver.generic-sql :: Creating new connection pool for database 6 ...

Nov 7 11:32:40 Bretts-MB Metabase[1328]:
Nov 7 11:32:40 Bretts-MB Metabase[1328]:

+--------------------------------------------------------------------+
|           Server status has transitioned to: HEALTHY               |
+--------------------------------------------------------------------+

Nov 7 11:32:40 Bretts-MB Metabase[1328]: Connecting to Metabase instance at: http://localhost:13280
Nov 7 11:32:41 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/user/current 200 (2 ms) (1 DB calls)
Nov 7 11:32:41 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/session/properties 200 (3 ms) (1 DB calls)
Nov 7 11:32:41 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/activity/recent_views 200 (2 ms) (1 DB calls)
DEBUG metabase.middleware :: GET /api/dashboard 200 (3 ms) (2 DB calls)
Nov 7 11:32:41 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/activity 200 (9 ms) (6 DB calls)
Nov 7 11:32:41 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/setup/admin_checklist 200 (43 ms) (10 DB calls)
Nov 7 11:32:42 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/database/6/fields 200 (6 s) (5 DB calls)
Nov 7 11:32:47 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: POST /api/card/11/query 200 (11 s) (8 DB calls)

sameer · November 7, 2016, 7:45pm

Ok, that’s less than awesome.

Whatever native query you’re trying to run is killing the server.

Can you share the query structure and rough table sized? Is it possible that the result is really large?

sameer · November 7, 2016, 7:50pm

also, do you know how long that query takes to run when you run it in other tools?

bt2016 · November 7, 2016, 7:57pm

The final table is only 107 rows x 10 columns, but the query itself is ridiculously long and convoluted to get there, which is why I didn’t paste the whole thing. It has many CTEs and is finally rolled up via a number of window functions, so maybe that is the problem. It is 312 lines long and 9293 characters.

Despite all that, it runs in 7s in SQL Workbench/J.

Also, would this explain why it crashes when creating a new question and switching to SQL mode? I get this when trying the new question route:

Nov 7 11:58:12 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/database 200 (338 ms) (3 DB calls)
Nov 7 11:58:15 Bretts-MB Metabase[1328]:
Nov 7 11:58:15 Bretts-MB Metabase[1328]:

+--------------------------------------------------------------------+
|           Server status has transitioned to: NOT HEALTHY           |
+--------------------------------------------------------------------+

Nov 7 11:58:17 Bretts-MB Metabase[1328]:
Nov 7 11:58:17 Bretts-MB Metabase[1328]:

+--------------------------------------------------------------------+
|           Server status has transitioned to: HEALTHY               |
+--------------------------------------------------------------------+

Nov 7 11:58:17 Bretts-MB Metabase[1328]: Connecting to Metabase instance at: http://localhost:13280
Nov 7 11:58:17 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/user/current 200 (657 µs) (1 DB calls)
Nov 7 11:58:17 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/session/properties 200 (916 µs) (1 DB calls)
Nov 7 11:58:17 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/dashboard 200 (2 ms) (2 DB calls)
Nov 7 11:58:17 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/activity/recent_views 200 (6 ms) (1 DB calls)
DEBUG metabase.middleware :: GET /api/setup/admin_checklist 200 (33 ms) (10 DB calls)
DEBUG metabase.middleware :: GET /api/activity 200 (12 ms) (6 DB calls)
Nov 7 11:58:17 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/database/6/fields 200 (3 s) (5 DB calls)
Nov 7 11:59:49 Bretts-MB Metabase[1328]: DEBUG metabase.middleware :: GET /api/database 200 (263 ms) (3 DB calls)

sameer · November 10, 2016, 1:54am

Huh. We fixed a couple issues that might result in the mac client in 0.20.3.

It definitely shouldn’t crash if you click on new question and enter sql mode. It sounds like something else is killing the server somehow.

I don’t know if the two are connected, but if you can upgrade to 0.20.3, it’ll at least remove those couple bugs from the picture.

bt2016 · November 10, 2016, 9:47pm

Unfortunately that didn’t work, just upgraded and getting the same behavior.