feat: log SQL query commands to stderr

[laurenceisla]

WIP

Resolves #1578.

Implements what was mentioned in #1578 (comment)

In summary:

• Adds a log-query boolean configuration value
• When activated, it logs the SQL query to stderr only at the log-level specified.
• For example: log-level=warn and log-query=true will log a 400 HTTP error and also the SQL query. But a 200 HTTP response will not log neither the request nor the SQL query.

Example

http 'localhost:3000/clients' "Accept: application/vnd.pgrst.object" <<JSON
{"id": 7, "name": "asdf"}
JSON

$ PGRST_LOG_LEVEL=info PGRST_LOG_QUERY=true postgrest-with-postgresql-16  -f test/spec/fixtures/load.sql postgrest-run

18/Feb/2025:14:21:55 -0500: Starting PostgREST 12.3 (pre-release)...
...

18/Feb/2025:14:22:04 -0500: WITH pgrst_source AS (INSERT INTO "test"."clients"("id", "name") SELECT "pgrst_body"."id", "pgrst_body"."name" FROM (SELECT $1 AS json_data) pgrst_payload, LATE
RAL (SELECT "id", "name" FROM json_to_record(pgrst_payload.json_data) AS _("id" integer, "name" text) ) pgrst_body  RETURNING 1) SELECT '' AS total_result_set, pg_catalog.count(_postgrest_
t) AS page_total, array[]::text[] AS header, ''::text AS body, nullif(current_setting('response.headers', true), '') AS response_headers, nullif(current_setting('response.status', true), '
') AS response_status, '' AS response_inserted FROM (SELECT * FROM pgrst_source) _postgrest_t
127.0.0.1 - postgrest_test_anonymous [18/Feb/2025:14:22:04 -0500] "POST /clients HTTP/1.1" 201 - "" "HTTPie/3.2.2"

[steve-chavez]

Could you explain how you obtain the SQL? Did you had to convert Snippet to ByteString as mentioned on #1578 (comment)?

[steve-chavez]

Ah, I see now that when using dynamicallyParameterized that already outputs the generated sql as part of the Statement.

[steve-chavez]

Feature looks great, very useful even for us when developing.

But looking at the code, it doesn't look like it's left in a good state.

prepareRead, prepareCall, etc now return the SQL, this goes through actionQuery which also has to bubble it to the top level. Looks like this also generates an empty code path, that needs to be patched with a mempty.

I wonder if this could look better with an additional step in App.postgrestResponse, one where a Statement is generated, so the generated SQL is now available at the top. This would avoid the need to bubble up the sql.

[laurenceisla]

I wonder if this could look better with an additional step in App.postgrestResponse, one where a Statement is generated, so the generated SQL is now available at the top. This would avoid the need to bubble up the sql.

That was my idea initially, but I found out that I cannot make it further above the (planTime, plan) assignment, since the Statement generation needs that plan. So this is the declaration I went for:

postgrest/src/PostgREST/App.hs

Lines 148 to 151 in 498b4fd

	(planTime, plan) <- withTiming $ liftEither $ Plan.actionPlan iAction conf apiReq sCache
	let query = Query.query conf authResult apiReq plan sCache pgVer
	logSQL = lift . AppState.getObserver appState . DBQuery (Query.getSQLQuery query)

A single declaration for query and logSQL which are available for both the (queryTime, queryResult) and (respTime, resp) generation.

prepareRead, prepareCall, etc now return the SQL, this goes through actionQuery which also has to bubble it to the top level

This can also be done directly in actionQuery, I just didn't want to import Hasql.Statement in Query.hs since it made more sense in Statement.hs. It would still pass it to the top, but one bubble would be popped.

Looks like this also generates an empty code path, that needs to be patched with a mempty.

I think the SQL as mempty is necessary because neither OPTIONS nor OpenAPI (without db-root-spec) have SQL queries. Or perhaps it's better to convert it to a Maybe? It could make more sense that way.

[steve-chavez]

since the Statement generation needs that plan

Hm, so it seems to me the above is not an issue. I was thinking that the way to do this is to split the Query module into Statements and Query (or another name) so you would have the Statement generation at the top level, this receives the plan and generates the SQL, which can then be logged. The Query module can run the statement and do the additional logic we do like failNotSingular.

If it's too much work now, maybe it can be commented as TODO.

[laurenceisla]

I was thinking that the way to do this is to split the Query module into Statements and Query (or another name)

Oh, I think I understand. I was trying to do something similar but, had problems with the pattern matching leaving unreachable paths fot the OpenAPI case. Although, It should be possible once postgrest-openapi is merged, so I added a TODO mentioning that.

[steve-chavez]

This doesn't generate the EXPLAIN queries we run internally when Prefer: count=estimated is done right?

I think some other extra queries we run for the fail... functions are missing too.

[steve-chavez]

It also doesn't log our transactional variables. The bunch of set_config.

[steve-chavez]

So it only logs the Main query, which is really the most important part. I think most admins will only want to look at that.

Now I'm thinking if we should have different values of log-query, like log-query = full|main-query|disabled. This to make it easier to introduce the other SQL parts if there's demand.

Otherwise I think it's gonna require a major refactor to truly log all the SQL.