diff --git a/CHANGELOG.md b/CHANGELOG.md index 6b3416e34..8e0f77d62 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ This project adheres to [Semantic Versioning](http://semver.org/). - Fix not logging OpenAPI queries when `log-query=main-query` is enabled by @steve-chavez in #4226 - Fix not logging explain query when `log-query=main-query` is enabled by @steve-chavez in #4319 +- Fix not logging transaction variables and db-pre-request function when `log-query=main-query` is enabled by @steve-chavez in #3934 ### Added diff --git a/src/PostgREST/Logger.hs b/src/PostgREST/Logger.hs index c091b8026..93d441296 100644 --- a/src/PostgREST/Logger.hs +++ b/src/PostgREST/Logger.hs @@ -123,7 +123,7 @@ logWithZTime loggerState txt = do logMainQ :: LoggerState -> MainQuery -> IO () logMainQ loggerState MainQuery{mqOpenAPI=(x, y, z),..} = - let snipts = renderSnippet <$> [mqMain, x, y, z, fromMaybe mempty mqExplain] + let snipts = renderSnippet <$> [mqTxVars, fromMaybe mempty mqPreReq, mqMain, x, y, z, fromMaybe mempty mqExplain] -- Does not log SQL when it's empty (happens on OPTIONS requests and when the openapi queries are not generated) logQ q = when (q /= mempty) $ logWithZTime loggerState $ showOnSingleLine '\n' $ T.decodeUtf8 q in mapM_ logQ snipts diff --git a/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml b/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml index 55ed52b7f..ff0102673 100644 --- a/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml +++ b/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml @@ -196,6 +196,23 @@ pdSchema: public pdVolatility: Volatile +- - qiName: do_nothing + qiSchema: public + - - pdDescription: null + pdFuncSettings: [] + pdHasVariadic: false + pdName: do_nothing + pdParams: [] + pdReturnType: + contents: + contents: + qiName: void + qiSchema: pg_catalog + tag: Scalar + tag: Single + pdSchema: public + pdVolatility: Volatile + - - qiName: get_guc_value qiSchema: public - - pdDescription: null diff --git a/test/io/fixtures.sql b/test/io/fixtures.sql index c50f15e7f..0aeeb1a3c 100644 --- a/test/io/fixtures.sql +++ b/test/io/fixtures.sql @@ -95,6 +95,9 @@ create function notify_do_nothing() returns void as $_$ notify pgrst, 'nothing'; $_$ language sql; +create function do_nothing() returns void as $_$ +$_$ language sql; + create function reset_invalid_role_claim_key() returns void as $_$ begin alter role postgrest_test_authenticator reset pgrst.jwt_role_claim_key; diff --git a/test/io/test_io.py b/test/io/test_io.py index 2b4c2ba99..a7f0bf70d 100644 --- a/test/io/test_io.py +++ b/test/io/test_io.py @@ -1003,7 +1003,20 @@ def test_log_level(level, defaultenv): def test_log_query(level, defaultenv): "log_query=true should log the SQL query according to the log_level" - env = {**defaultenv, "PGRST_LOG_LEVEL": level, "PGRST_LOG_QUERY": "main-query"} + def drain_stdout(proc): + lines = [] + while True: + chunk = proc.read_stdout(nlines=20) + if not chunk: + break + lines.extend(chunk) + return lines + + env = { + **defaultenv, + "PGRST_LOG_LEVEL": level, + "PGRST_LOG_QUERY": "main-query", + } with run(env=env) as postgrest: response = postgrest.session.get("/") @@ -1033,15 +1046,9 @@ def test_log_query(level, defaultenv): root_tables_regx = r".+: SELECT n.nspname AS table_schema, .+ FROM pg_class c .+ ORDER BY table_schema, table_name" root_procs_regx = r".+: WITH base_types AS \(.+\) SELECT pn.nspname AS proc_schema, .+ FROM pg_proc p.+AND p.pronamespace = \$1::regnamespace" root_descr_regx = r".+: SELECT pg_catalog\.obj_description\(\$1::regnamespace, 'pg_namespace'\)" - - def drain_stdout(proc): - lines = [] - while True: - chunk = proc.read_stdout(nlines=20) - if not chunk: - break - lines.extend(chunk) - return lines + set_config_regx = ( + r".+: select set_config\('search_path', \$1, true\), set_config\(" + ) output = drain_stdout(postgrest) @@ -1053,8 +1060,10 @@ def test_log_query(level, defaultenv): root_tables = [line for line in output if re.match(root_tables_regx, line)] root_procs = [line for line in output if re.match(root_procs_regx, line)] root_descr = [line for line in output if re.match(root_descr_regx, line)] + set_configs = [line for line in output if re.match(set_config_regx, line)] if level == "crit": + assert not set_configs assert not project_queries assert not project_counts assert not infinite_queries @@ -1062,6 +1071,7 @@ def test_log_query(level, defaultenv): assert not root_procs assert not root_descr elif level in {"error", "warn"}: + assert len(set_configs) == 1 assert len(infinite_queries) == 1 assert not project_queries assert not project_counts @@ -1069,6 +1079,7 @@ def test_log_query(level, defaultenv): assert not root_procs assert not root_descr elif level == "info": + assert len(set_configs) == 5 assert len(project_queries) == 3 assert len(project_counts) == 2 assert len(infinite_queries) == 1 @@ -1076,6 +1087,7 @@ def test_log_query(level, defaultenv): assert len(root_procs) == 1 assert len(root_descr) == 1 elif level == "debug": + assert len(set_configs) == 5 assert len(project_queries) == 3 assert len(project_counts) == 2 assert len(infinite_queries) == 1 @@ -1083,6 +1095,29 @@ def test_log_query(level, defaultenv): assert len(root_procs) == 1 assert len(root_descr) == 1 + pre_req_env = { + **env, + "PGRST_DB_PRE_REQUEST": "do_nothing", + } + + with run(env=pre_req_env) as postgrest: + response = postgrest.session.get("/projects") + assert response.status_code == 200 + + output = drain_stdout(postgrest) + + pre_request_regx = r'.+: select "do_nothing"()' + pre_reqs = [line for line in output if re.match(pre_request_regx, line)] + + if level == "crit": + assert not pre_reqs + elif level in {"error", "warn"}: + assert not pre_reqs + elif level == "info": + assert len(pre_reqs) == 1 + elif level == "debug": + assert len(pre_reqs) == 1 + def test_no_pool_connection_required_on_bad_http_logic(defaultenv): "no pool connection should be consumed for failing on invalid http logic" diff --git a/test/spec/fixtures/schema.sql b/test/spec/fixtures/schema.sql index e9e1e70ac..19167867b 100644 --- a/test/spec/fixtures/schema.sql +++ b/test/spec/fixtures/schema.sql @@ -3843,3 +3843,6 @@ $$ language sql; create or replace function test.delete_items_returns_void() returns void as $$ delete from items; $$ language sql; + +create function do_nothing() returns void as $_$ +$_$ language sql;