Postgres syntax error when asking a new question

Hey there,

I've been using Metabase at my small company for about 2 months. I've been able to build and run native SQL queries just fine, but whenever I try to use the querybuilder features the Metabase server crashes with a Postgres syntax error.

Specifically, when I go to 'Ask a question' -> 'Custom' -> I select a table to start, the client sends an AJAX request that gets a 500 response. The URL of the request is 'https://my-metabase-deployment.herokuapp.com/api/automagic-dashboards/database/2/candidates' and it returns the following:

{"message":"ERROR: syntax error at or near \"NULL\"\n  Position: 84","type":"class org.postgresql.util.PSQLException","stacktrace":["org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2433)","org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2178)","org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)","org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)","org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)","org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)","org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:118)","com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:353)","clojure.java.jdbc$execute_query_with_params.invokeStatic(jdbc.clj:1002)","clojure.java.jdbc$execute_query_with_params.invoke(jdbc.clj:996)","clojure.java.jdbc$db_query_with_resultset_STAR_.invokeStatic(jdbc.clj:1025)","clojure.java.jdbc$db_query_with_resultset_STAR_.invoke(jdbc.clj:1005)","clojure.java.jdbc$query.invokeStatic(jdbc.clj:1099)","clojure.java.jdbc$query.invoke(jdbc.clj:1056)","toucan.db$query.invokeStatic(db.clj:275)","toucan.db$query.doInvoke(db.clj:271)","clojure.lang.RestFn.invoke(RestFn.java:410)","--> automagic_dashboards.core$enhance_table_stats.invokeStatic(core.clj:1231)","automagic_dashboards.core$enhance_table_stats.invoke(core.clj:1209)","automagic_dashboards.core$candidate_tables.invokeStatic(core.clj:1270)","automagic_dashboards.core$candidate_tables.invoke(core.clj:1250)","automagic_dashboards.core$candidate_tables.invokeStatic(core.clj:1260)","automagic_dashboards.core$candidate_tables.invoke(core.clj:1250)","api.automagic_dashboards$fn__46725.invokeStatic(automagic_dashboards.clj:59)","api.automagic_dashboards$fn__46725.invoke(automagic_dashboards.clj:56)","middleware$enforce_authentication$fn__56174.invoke(middleware.clj:113)","api.routes$fn__56318.invokeStatic(routes.clj:61)","api.routes$fn__56318.invoke(routes.clj:61)","routes$fn__56409$fn__56410.doInvoke(routes.clj:108)","routes$fn__56409.invokeStatic(routes.clj:103)","routes$fn__56409.invoke(routes.clj:103)","middleware$catch_api_exceptions$fn__56309.invoke(middleware.clj:436)","middleware$log_api_call$fn__56287$fn__56289.invoke(middleware.clj:364)","middleware$log_api_call$fn__56287.invoke(middleware.clj:363)","middleware$add_security_headers$fn__56229.invoke(middleware.clj:252)","core$wrap_streamed_json_response$fn__62673.invoke(core.clj:67)","middleware$bind_current_user$fn__56179.invoke(middleware.clj:137)","middleware$maybe_set_site_url$fn__56239.invoke(middleware.clj:290)","middleware$add_content_type$fn__56232.invoke(middleware.clj:262)"],"sql-exception-chain":["PSQLException:","Message: ERROR: syntax error at or near \"NULL\"","Position: 84","SQLState: 42601","Error Code: 0"]}

I can see a similar error message in the server logs. Once this happens, no columns show up in UI to build the query with:

I'm running Metabase 0.31.2 on Heroku. I just upgraded from 0.31.1, but I was having this problem before upgrading. For the database itself, I'm running Postgres 9.6.6 on AWS RDS.

As an update - I can also reproduce this by trying to analyze a native query.

Anyone have any thoughts?

@lionel

Does Metabase crash (so you have to restart the service) or just respond with the error?

I don’t see any calls to /api/automagic-dashboards/ when using Query Builder and selecting a table. There’s calls to /api/table/

Do you have sync disabled? How about x-rays?

Hey Flamber,

Sorry for being unclear - the Metabase server does not crash, it just returns a 500 response. I have both X-rays and sync enabled and have resynced both field names and values just now without seeing a change in behavior.

After playing around with this more, I think it might be that trying to create a new question like I said is not triggering the broken API call - it might be the 'Try these X-Rays' suggestion area in the home page. When I navigate to the home page, I can see repeatedly making failing requests:

Another symptom, which think may be related as it seems like the error is that Metabase is unable to effectively pull the schema from the database, is that in the Admin panel I am unable to see any columns on any tables in the Data Model pane:

Do you know a way to get Metabase to print the query it's trying to run that is resulting in this error?

Aha, an additional symptom which might be causing these problems:

When I try to re-sync the fields in the admin panel, I see errors in the logs such as:

2019-01-14T22:01:02.950494+00:00 app[web.1]: Jan 14, 2019 10:01:02 PM org.postgresql.core.v3.ConnectionFactoryImpl log                                
2019-01-14T22:01:02.950516+00:00 app[web.1]: WARNING: IOException occurred while connecting to <my database>
2019-01-14T22:01:02.950518+00:00 app[web.1]: java.net.SocketTimeoutException: connect timed out                                   
2019-01-14T22:01:02.950520+00:00 app[web.1]: at java.net.PlainSocketImpl.socketConnect(Native Method)                                    
2019-01-14T22:01:02.950522+00:00 app[web.1]: at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)     
2019-01-14T22:01:02.950523+00:00 app[web.1]: at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)                       

... later ...

2019-01-14T22:01:02.958436+00:00 app[web.1]: at java.lang.Thread.run(Thread.java:748)                                                 
2019-01-14T22:01:02.958438+00:00 app[web.1]: Caused by: java.net.SocketTimeoutException: connect timed out
2019-01-14T22:01:02.958439+00:00 app[web.1]: at java.net.PlainSocketImpl.socketConnect(Native Method)
2019-01-14T22:01:02.958441+00:00 app[web.1]: at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)                                           
2019-01-14T22:01:02.958442+00:00 app[web.1]: at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)                                   
2019-01-14T22:01:02.958444+00:00 app[web.1]: at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
2019-01-14T22:01:02.958445+00:00 app[web.1]: at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
2019-01-14T22:01:02.958447+00:00 app[web.1]: at java.net.Socket.connect(Socket.java:589)
2019-01-14T22:01:02.958448+00:00 app[web.1]: at org.postgresql.core.PGStream.<init>(PGStream.java:69)                                     
2019-01-14T22:01:02.958450+00:00 app[web.1]: at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:156)
2019-01-14T22:01:02.958452+00:00 app[web.1]: ... 81 more                                                                   
2019-01-14T22:01:02.958453+00:00 app[web.1]:                                                                        
2019-01-14T22:01:03.137779+00:00 app[web.1]: 01-14 22:01:03 ERROR sync.util :: Error syncing fields for Table 47 'public.my_table': The connection attempt failed.
2019-01-14T22:01:03.137782+00:00 app[web.1]: ("org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:257)"
2019-01-14T22:01:03.137783+00:00 app[web.1]: "org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49)"   
2019-01-14T22:01:03.137785+00:00 app[web.1]: "org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:195)"                                     
2019-01-14T22:01:03.137786+00:00 app[web.1]: "org.postgresql.Driver.makeConnection(Driver.java:452)"                  
2019-01-14T22:01:03.137788+00:00 app[web.1]: "org.postgresql.Driver.connect(Driver.java:254)"                  

I’ll play around with my database connection and see resolving these connection errors fixes things. The strange thing is that everything does work for natively written SQL queries, so some Metabase queries must be getting through to the database just fine…

Looks like something is bad in the sync. And without that data, Metabase cannot work with Query Browser (and probably X-Ray and some other features too).
Not sure if it would help to flush it or if there’s some special structure in the database that makes Metabase hick-up. The log should tell you more…

Native SQL queries will work, since they don’t require to know anything about the database. I use SQL to run some procedures and functions, which Metabase has no knowledge of, but it will happily send the query to the database and just give me the return.

As another update, I’ve reproduced the issue and think it has something to do with the ssh tunnel I’m using. My setup is that the RDS database is IP whitelisted, and Metabase connects to it through a bastion host.

I installed Metabase on my laptop and added the production database directly, without ssh tunneling. Everything worked fine.

Then I added the production database again to my laptop’s Metabase, this time going through the same ssh tunnel as the Heroku deployment, and I immediately ran into the same issue I have on Heroku.

My new theory is that something is interacting badly between Metabase, the ssh tunnel with the bastion host, and connecting to RDS.