diff --git a/postgrest.cabal b/postgrest.cabal index bbf030b61..3d4f76520 100644 --- a/postgrest.cabal +++ b/postgrest.cabal @@ -158,7 +158,7 @@ library , wai-extra >= 3.1.8 && < 3.2 -- We already depend on wai-logger >= 2.3.7 indirectly via wai-extra, -- but we want to depend on 2.4.0 which fixes 'unknownSocket' log output - -- for unix sockets; this is tested in test/io/test_io.py. See + -- for unix sockets; this is tested in test/io/test_log.py. See -- https://github.com/kazu-yamamoto/logger/commit/3a71ca70afdbb93d4ecf0083eeba1fbbbcab3fc3 , wai-logger >= 2.4.0 , warp >= 3.4.14 && < 3.5 diff --git a/test/io/test_io.py b/test/io/test_io.py index 969e20d62..158e05b33 100644 --- a/test/io/test_io.py +++ b/test/io/test_io.py @@ -1,28 +1,16 @@ "Unit tests for Input/Ouput of PostgREST seen as a black box." -import re -import signal import time import pytest -import requests -from config import SECRET from util import ( Thread, - jwtauthheader, - relativeSeconds, - drain_stdout, - match_log, psql_as_superuser, ) from postgrest import ( - Admin, PostgrestTimedOut, freeport, - is_ipv6, - reset_statement_timeout, run, - set_statement_timeout, wait_until_exit, ) @@ -48,24 +36,6 @@ def test_graceful_shutdown_waits_for_in_flight_request(defaultenv): t.join() -def test_termination_unix_signal_logging(defaultenv): - "Server logs when handling termination unix signals." - - with run(env=defaultenv) as postgrest: - postgrest.process.send_signal(signal.SIGTERM) - lines = postgrest.read_stdout(nlines=1) - wait_until_exit(postgrest) - - assert any("SIGTERM" in line for line in lines) - - with run(env=defaultenv) as postgrest: - postgrest.process.send_signal(signal.SIGINT) - lines = postgrest.read_stdout(nlines=1) - wait_until_exit(postgrest) - - assert any("SIGINT" in line for line in lines) - - def test_random_port_bound(defaultenv): "PostgREST should bind to a random port when PGRST_SERVER_PORT is 0." @@ -219,454 +189,6 @@ def test_listener_query_is_visible_in_pg_stat_activity(defaultenv): assert output == 'LISTEN "pgrst"' -@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) -def test_log_level(level, defaultenv): - "log_level should filter request logging" - - env = {**defaultenv, "PGRST_LOG_LEVEL": level} - - # any token to test 500 response for "Server lacks JWT secret" - claim = {"role": "postgrest_test_author"} - headers = jwtauthheader(claim, SECRET) - - with run(env=env) as postgrest: - response = postgrest.session.get("/", headers=headers) - assert response.status_code == 500 - - response = postgrest.session.get("/unknown") - assert response.status_code == 404 - - response = postgrest.session.get("/") - assert response.status_code == 200 - - output = postgrest.read_stdout(nlines=9) - - if level == "crit": - assert len(output) == 0 - elif level == "error": - match_log( - output, - [r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"'], - ) - assert len(output) == 1 - elif level == "warn": - match_log( - output, - [ - r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', - r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', - ], - ) - assert len(output) == 2 - elif level == "info": - match_log( - output, - [ - r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', - r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', - r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', - ], - ) - assert len(output) == 3 - elif level == "debug": - match_log( - output, - [ - r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', - r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', - r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', - ], - ) - assert len(output) == 9 - assert any("Connection" and "is available" in line for line in output) - assert any("Connection" and "is used" in line for line in output) - - -@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) -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": "true", - } - - with run(env=env) as postgrest: - response = postgrest.session.get("/") - assert response.status_code == 200 - - response = postgrest.session.get("/projects") - assert response.status_code == 200 - - response = postgrest.session.get( - "/projects", headers={"Prefer": "count=estimated"} - ) - assert response.status_code == 200 - - response = postgrest.session.get( - "/projects", headers={"Prefer": "count=planned"} - ) - assert response.status_code == 200 - - response = postgrest.session.get("/infinite_recursion") - assert response.status_code == 500 - - get_2xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."projects"\.\* FROM "public"\."projects".+_postgrest_t' - get_2xx_count_regx = ( - r'.+: EXPLAIN \(FORMAT JSON\) SELECT 1 FROM "public"."projects"' - ) - infinite_recursion_5xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."infinite_recursion"\.\* FROM "public"\."infinite_recursion".+_postgrest_t' - 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.+pn\.nspname AS proc_schema.+FROM pg_proc p.+p\.pronamespace = \$1::regnamespace" - root_descr_regx = r".+: SELECT pg_catalog\.obj_description\(\$1::regnamespace, 'pg_namespace'\)" - set_config_regx = ( - r".+: select set_config\('search_path', \$1, true\), set_config\(" - ) - - output = drain_stdout(postgrest) - - project_queries = [line for line in output if re.match(get_2xx_regx, line)] - project_counts = [line for line in output if re.match(get_2xx_count_regx, line)] - infinite_queries = [ - line for line in output if re.match(infinite_recursion_5xx_regx, line) - ] - 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 - assert not root_tables - 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 - assert not root_tables - 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 - assert len(root_tables) == 1 - 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 - assert len(root_tables) == 1 - 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_expired_jwt_log_lacks_role(defaultenv): - "Expired JWT requests are logged without a role." - - env = {**defaultenv, "PGRST_JWT_SECRET": SECRET} - headers = jwtauthheader({"exp": relativeSeconds(-35)}, SECRET) - - with run(env=env) as postgrest: - response = postgrest.session.get("/authors_only", headers=headers) - assert response.status_code == 401 - - output = postgrest.read_stdout(nlines=1) - - assert len(output) == 1 - assert re.match( - r'- - - \[.+\] "GET /authors_only HTTP/1.1" 401 \d+ "" "python-requests/.+"', - output[0], - ) - - -def test_log_lacks_role_with_empty_anon_role(defaultenv): - "Requests are logged without a role when db-anon-role is empty." - - env = { - **defaultenv, - "PGRST_DB_CONFIG": "false", - "PGRST_DB_ANON_ROLE": "", - } - - with run(env=env) as postgrest: - response = postgrest.session.get("/projects") - assert response.status_code == 401 - - output = postgrest.read_stdout(nlines=1) - - assert len(output) == 1 - assert re.match( - r'- - - \[.+\] "GET /projects HTTP/1.1" 401 \d+ "" "python-requests/.+"', - output[0], - ) - - -def test_invalid_rpc_method_log_contains_role(defaultenv): - "Invalid RPC method requests are logged with the anonymous role." - - with run(env=defaultenv) as postgrest: - response = postgrest.session.put("/rpc/sleep") - assert response.status_code == 405 - - output = postgrest.read_stdout(nlines=1) - - assert len(output) == 1 - assert re.match( - r'- - postgrest_test_anonymous \[.+\] "PUT /rpc/sleep HTTP/1.1" 405 \d+ "" "python-requests/.+"', - output[0], - ) - - -def test_empty_schema_cache_log_contains_jwt_role(defaultenv): - "Requests are logged with the role when the schema cache is empty on startup" - - env = { - **defaultenv, - "PGRST_DB_SCHEMAS": "non_existent_schema_aaaa", - "PGRST_JWT_SECRET": SECRET, - } - headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET) - - with run(env=env, wait_for=None) as postgrest: - postgrest.wait_until_scache_starts_loading() - - response = postgrest.session.get("/authors_only", headers=headers) - assert response.status_code == 503 - - output = drain_stdout(postgrest) - - assert any( - re.match( - r'- - postgrest_test_author \[.+\] "GET /authors_only HTTP/1.1" 503 \d+ "" "python-requests/.+"', - line, - ) - for line in output - ) - - -def test_options_request_logs_but_cors_preflight_does_not(defaultenv): - "Plain OPTIONS requests should be logged, but CORS preflight requests should not." - - env = { - **defaultenv, - "PGRST_LOG_LEVEL": "info", - "PGRST_SERVER_CORS_ALLOWED_ORIGINS": "http://example.com", - } - preflight_headers = { - "Origin": "http://example.com", - "Access-Control-Request-Method": "POST", - "Access-Control-Request-Headers": "Content-Type", - } - - with run(env=env) as postgrest: - response = postgrest.session.options("/projects") - assert response.status_code == 200 - - response = postgrest.session.options("/projects", headers=preflight_headers) - assert response.status_code == 200 - assert response.headers["Access-Control-Allow-Origin"] == "http://example.com" - - output = drain_stdout(postgrest) - - assert len(output) == 1 - assert re.match( - r'- - postgrest_test_anonymous \[.+\] "OPTIONS /projects HTTP/1.1" 200 \d+ "" "python-requests/.+"', - output[0], - ) - - -def test_schema_cache_query_sleep_logs(defaultenv): - """Schema cache sleep should be reflected in the logged query duration.""" - - env = { - **defaultenv, - "PGRST_INTERNAL_SCHEMA_CACHE_QUERY_SLEEP": "1000", - } - log_pattern = re.compile(r"Schema cache queried in ([\d.]+) milliseconds") - - with run(env=env, wait_max_seconds=3, no_startup_stdout=False) as postgrest: - observed_ms = None - collected = [] - - lines = postgrest.read_stdout(nlines=10) - collected.extend(lines) - for line in lines: - match = log_pattern.search(line) - if match: - observed_ms = float(match.group(1)) - break - - assert observed_ms is not None - assert 1000 < observed_ms < 2000 - - -@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) -def test_schema_cache_query_timings_log(level, defaultenv): - "Schema cache query timings should be logged on log-level=debug." - - env = { - **defaultenv, - "PGRST_LOG_LEVEL": level, - } - log_pattern = re.compile( - r".+: tables: [\d.]+ ms, keydeps: [\d.]+ ms, rels: [\d.]+ ms, funcs: [\d.]+ ms, comprels: [\d.]+ ms, dreps: [\d.]+ ms, mhandlers: [\d.]+ ms" - ) - - with run(env=env, no_startup_stdout=False) as postgrest: - output = drain_stdout(postgrest) - timing_matches = [ - match for line in output if (match := log_pattern.match(line)) - ] - - if level == "debug": - assert len(timing_matches) == 1 - else: - assert not timing_matches - - -def test_log_postgrest_version(defaultenv): - "Should show the PostgREST version in the logs" - with run(env=defaultenv, no_startup_stdout=False) as postgrest: - version = postgrest.session.head("/").headers["Server"].split("/")[1] - - output = postgrest.read_stdout(nlines=1) - - assert "Starting PostgREST %s..." % version in output[0] - - -@pytest.mark.parametrize( - "host", ["127.0.0.1", "::1", None], ids=["IPv4", "IPv6", "Unix"] -) -def test_log_postgrest_host_and_port(host, defaultenv): - "PostgREST should output the host and port it is bound to." - - # We run postgrest on unix socket when host and port are set to None - is_unix = host is None - port = None if is_unix else freeport() - - with run( - env=defaultenv, host=host, port=port, no_startup_stdout=False - ) as postgrest: - output = postgrest.read_stdout(nlines=11) - - # Cannot assume a particular log entry order - # Listening on a socket happens after schema querying - # but is concurrent to the schema loading process - # and migh happen before or after writing of the - # "Schema cache loaded" log entry - if is_unix: - match_log(output, [r".*API server listening on .*/tmp/.*\.sock"]) - elif is_ipv6(host): - match_log(output, [r".*API server listening on \[.+]:\d+"]) - else: # IPv4 - match_log(output, [r".*API server listening on .+:\d+"]) - - -@pytest.mark.parametrize( - "host", ["127.0.0.1", "::1", None], ids=["IPv4", "IPv6", "Unix"] -) -def test_log_postgrest_admin_server_host_and_port(host, defaultenv): - "PostgREST should log the admin server host and port" - - # We run admin server on unix socket when host and admin_port are set to None - is_unix = host is None - port = None if is_unix else freeport() - admin_port = None if is_unix else freeport(used_ports=[port]) - - with run( - env=defaultenv, - host=host, - port=port, - admin_port=admin_port, - no_startup_stdout=False, - wait_for=Admin.ready, - ) as postgrest: - output = postgrest.read_stdout(nlines=11) - - # Cannot assume a particular log entry order - # Listening on a socket happens after schema querying - # but is concurrent to the schema loading process - # and migh happen before or after writing of the - # "Schema cache loaded" log entry - if is_unix: - match_log(output, [r".*Admin server listening on .*/tmp/.*\.sock"]) - elif is_ipv6(host): - match_log(output, [r".*Admin server listening on \[.+]:\d+"]) - else: # IPv4 - match_log(output, [r".*Admin server listening on .+:\d+"]) - - -@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) -def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest): - "verify that DB errors are logged to stderr" - - role = "timeout_authenticator" - set_statement_timeout(metapostgrest, role, 500) - - env = { - **defaultenv, - "PGUSER": role, - "PGRST_DB_ANON_ROLE": role, - "PGRST_LOG_LEVEL": level, - } - - with run(env=env) as postgrest: - response = postgrest.session.get("/rpc/sleep?seconds=1") - assert response.status_code == 500 - - # ensure the message appears on the logs - output = postgrest.read_stdout(nlines=8) - - if level == "crit": - assert len(output) == 0 - elif level == "debug": - match_log( - output, - [ - r".*canceling statement due to statement timeout.*", - r".*500.*", - ], - ) - else: - assert " 500 " in output[1] - assert "canceling statement due to statement timeout" in output[0] - - reset_statement_timeout(metapostgrest, role) - - def test_schema_cache_startup_load_with_in_db_config(defaultenv, metapostgrest): "verify that the Schema Cache loads correctly at startup, using the in-db `pgrst.db_schemas` config" @@ -684,80 +206,6 @@ def test_schema_cache_startup_load_with_in_db_config(defaultenv, metapostgrest): assert response.status_code == 204 -def test_pgrst_log_503_client_error_to_stderr(defaultenv): - "PostgREST should log 503 errors to stderr" - - env = { - **defaultenv, - "PGAPPNAME": "test-io", - } - - with run(env=env) as postgrest: - - postgrest.session.get("/rpc/terminate_pgrst?appname=test-io") - - output = postgrest.read_stdout(nlines=6) - - log_message = '{"code":"PGRST001","details":"no connection to the server\\n","hint":null,"message":"Database client error. Retrying the connection."}\n' - - assert any(log_message in line for line in output) - - -def test_log_error_when_schema_cache_load_error_on_startup_to_stderr(defaultenv): - "Should log the 503 error message when there is an error loading schema cache on startup" - - env = { - **defaultenv, - "PGRST_INTERNAL_SCHEMA_CACHE_QUERY_SLEEP_BEFORE_QUERIES": "1000", - "PGRST_DB_SCHEMAS": "non_existent_schema_aaaa", - } - - with run(env=env, wait_for=None) as postgrest: - postgrest.wait_until_scache_starts_loading() - - # First call should fail with connection refused - with pytest.raises(requests.ConnectionError): - postgrest.session.get("/projects") - - # Next call should return 503 - time.sleep(1) - response = postgrest.session.get("/projects") - assert response.status_code == 503 - - output_start = postgrest.read_stdout(nlines=10) - - log_err_message = '{"code":"PGRST002","details":null,"hint":null,"message":"Could not query the database for the schema cache. Retrying."}' - - assert any(log_err_message in line for line in output_start) - - -@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) -def test_log_pool_req_observation(level, defaultenv): - "PostgREST should log PoolRequest and PoolRequestFullfilled observation when log-level=debug" - - env = {**defaultenv, "PGRST_LOG_LEVEL": level, "PGRST_JWT_SECRET": SECRET} - - headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET) - - pool_req = r".*Trying to borrow a connection from pool.*" - pool_req_fullfill = r".*Borrowed a connection from the pool.*" - - with run(env=env) as postgrest: - - postgrest.session.get("/authors_only", headers=headers) - - if level == "debug": - output = postgrest.read_stdout(nlines=7) - assert len(output) == 7 - match_log(output, [pool_req, pool_req_fullfill]) - elif level == "info": - output = postgrest.read_stdout(nlines=4) - assert len(output) == 1 - else: - output = postgrest.read_stdout(nlines=4) - assert len(output) == 0 - - def test_allow_configs_to_be_set_to_empty(defaultenv): 'configs that are explicitly set to empty (= "") should not throw parse error' @@ -771,63 +219,6 @@ def test_allow_configs_to_be_set_to_empty(defaultenv): assert response.status_code == 200 -def test_schema_cache_error_observation(defaultenv): - "schema cache error observation should be logged with invalid db-schemas or db-extra-search-path" - - env = { - **defaultenv, - "PGRST_DB_EXTRA_SEARCH_PATH": "x", - } - - with run(env=env, no_startup_stdout=False, wait_for=None) as postgrest: - # TODO: postgrest should exit here, instead it keeps retrying - # exitCode = wait_until_exit(postgrest) - # assert exitCode == 1 - - output = postgrest.read_stdout(nlines=9) - assert ( - "Failed to load the schema cache using db-schemas=public and db-extra-search-path=x" - in output[6] - ) - - -def test_log_listener_connection_errors(defaultenv): - "The logs should show the listener connection error message in a single line" - - env = { - **defaultenv, - "PGHOST": "no_host", - "PGRST_DB_CHANNEL_ENABLED": "true", - } - - with run(env=env, no_startup_stdout=False, wait_for=None) as postgrest: - output = postgrest.read_stdout(nlines=5) - assert any( - 'Failed listening for database notifications on the "pgrst" channel. could not translate host name "no_host" to address:' - in line - for line in output - ) - - -def test_log_listener_connection_start(defaultenv): - "The logs should show the listener connection start message in a single line" - - env = { - **defaultenv, - "PGRST_DB_CHANNEL_ENABLED": "true", - } - - with run(env=env, no_startup_stdout=False, wait_for=Admin.ready) as postgrest: - output = postgrest.read_stdout(nlines=10) - # Check for the listener start message containing host and port - # Do not check if pg version is displayed properly as it is tricky to test it - assert any( - f'"{defaultenv["PGHOST"]}:5432" and listening for database notifications on the "pgrst" channel' - in line - for line in output - ) - - def test_connection_error_message_does_not_claim_retry(defaultenv): "The connection error message should not claim retrying, since PostgREST stops on fatal errors." uri = f'postgresql://?dbname={defaultenv["PGDATABASE"]}&host={defaultenv["PGHOST"]}&user=some_protected_user&password=invalid_pass' diff --git a/test/io/test_log.py b/test/io/test_log.py new file mode 100644 index 000000000..6ef89e492 --- /dev/null +++ b/test/io/test_log.py @@ -0,0 +1,621 @@ +"Test PostgREST logs and observations" + +import re +import signal +import time +import pytest +import requests + +from config import SECRET +from util import ( + jwtauthheader, + relativeSeconds, + drain_stdout, + match_log, +) +from postgrest import ( + Admin, + freeport, + is_ipv6, + reset_statement_timeout, + run, + set_statement_timeout, + wait_until_exit, +) + + +@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) +def test_log_level(level, defaultenv): + "log_level should filter request logging" + + env = {**defaultenv, "PGRST_LOG_LEVEL": level} + + # any token to test 500 response for "Server lacks JWT secret" + claim = {"role": "postgrest_test_author"} + headers = jwtauthheader(claim, SECRET) + + with run(env=env) as postgrest: + response = postgrest.session.get("/", headers=headers) + assert response.status_code == 500 + + response = postgrest.session.get("/unknown") + assert response.status_code == 404 + + response = postgrest.session.get("/") + assert response.status_code == 200 + + output = postgrest.read_stdout(nlines=9) + + if level == "crit": + assert len(output) == 0 + elif level == "error": + match_log( + output, + [r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"'], + ) + assert len(output) == 1 + elif level == "warn": + match_log( + output, + [ + r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', + ], + ) + assert len(output) == 2 + elif level == "info": + match_log( + output, + [ + r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', + ], + ) + assert len(output) == 3 + elif level == "debug": + match_log( + output, + [ + r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', + ], + ) + assert len(output) == 9 + assert any("Connection" and "is available" in line for line in output) + assert any("Connection" and "is used" in line for line in output) + + +@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) +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": "true", + } + + with run(env=env) as postgrest: + response = postgrest.session.get("/") + assert response.status_code == 200 + + response = postgrest.session.get("/projects") + assert response.status_code == 200 + + response = postgrest.session.get( + "/projects", headers={"Prefer": "count=estimated"} + ) + assert response.status_code == 200 + + response = postgrest.session.get( + "/projects", headers={"Prefer": "count=planned"} + ) + assert response.status_code == 200 + + response = postgrest.session.get("/infinite_recursion") + assert response.status_code == 500 + + get_2xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."projects"\.\* FROM "public"\."projects".+_postgrest_t' + get_2xx_count_regx = ( + r'.+: EXPLAIN \(FORMAT JSON\) SELECT 1 FROM "public"."projects"' + ) + infinite_recursion_5xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."infinite_recursion"\.\* FROM "public"\."infinite_recursion".+_postgrest_t' + 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.+pn\.nspname AS proc_schema.+FROM pg_proc p.+p\.pronamespace = \$1::regnamespace" + root_descr_regx = r".+: SELECT pg_catalog\.obj_description\(\$1::regnamespace, 'pg_namespace'\)" + set_config_regx = ( + r".+: select set_config\('search_path', \$1, true\), set_config\(" + ) + + output = drain_stdout(postgrest) + + project_queries = [line for line in output if re.match(get_2xx_regx, line)] + project_counts = [line for line in output if re.match(get_2xx_count_regx, line)] + infinite_queries = [ + line for line in output if re.match(infinite_recursion_5xx_regx, line) + ] + 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 + assert not root_tables + 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 + assert not root_tables + 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 + assert len(root_tables) == 1 + 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 + assert len(root_tables) == 1 + 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_log_lacks_role_with_empty_anon_role(defaultenv): + "Requests are logged without a role when db-anon-role is empty." + + env = { + **defaultenv, + "PGRST_DB_CONFIG": "false", + "PGRST_DB_ANON_ROLE": "", + } + + with run(env=env) as postgrest: + response = postgrest.session.get("/projects") + assert response.status_code == 401 + + output = postgrest.read_stdout(nlines=1) + + assert len(output) == 1 + assert re.match( + r'- - - \[.+\] "GET /projects HTTP/1.1" 401 \d+ "" "python-requests/.+"', + output[0], + ) + + +def test_log_postgrest_version(defaultenv): + "Should show the PostgREST version in the logs" + with run(env=defaultenv, no_startup_stdout=False) as postgrest: + version = postgrest.session.head("/").headers["Server"].split("/")[1] + + output = postgrest.read_stdout(nlines=1) + + assert "Starting PostgREST %s..." % version in output[0] + + +@pytest.mark.parametrize( + "host", ["127.0.0.1", "::1", None], ids=["IPv4", "IPv6", "Unix"] +) +def test_log_postgrest_host_and_port(host, defaultenv): + "PostgREST should output the host and port it is bound to." + + # We run postgrest on unix socket when host and port are set to None + is_unix = host is None + port = None if is_unix else freeport() + + with run( + env=defaultenv, host=host, port=port, no_startup_stdout=False + ) as postgrest: + output = postgrest.read_stdout(nlines=11) + + # Cannot assume a particular log entry order + # Listening on a socket happens after schema querying + # but is concurrent to the schema loading process + # and migh happen before or after writing of the + # "Schema cache loaded" log entry + if is_unix: + match_log(output, [r".*API server listening on .*/tmp/.*\.sock"]) + elif is_ipv6(host): + match_log(output, [r".*API server listening on \[.+]:\d+"]) + else: # IPv4 + match_log(output, [r".*API server listening on .+:\d+"]) + + +@pytest.mark.parametrize( + "host", ["127.0.0.1", "::1", None], ids=["IPv4", "IPv6", "Unix"] +) +def test_log_postgrest_admin_server_host_and_port(host, defaultenv): + "PostgREST should log the admin server host and port" + + # We run admin server on unix socket when host and admin_port are set to None + is_unix = host is None + port = None if is_unix else freeport() + admin_port = None if is_unix else freeport(used_ports=[port]) + + with run( + env=defaultenv, + host=host, + port=port, + admin_port=admin_port, + no_startup_stdout=False, + wait_for=Admin.ready, + ) as postgrest: + output = postgrest.read_stdout(nlines=11) + + # Cannot assume a particular log entry order + # Listening on a socket happens after schema querying + # but is concurrent to the schema loading process + # and migh happen before or after writing of the + # "Schema cache loaded" log entry + if is_unix: + match_log(output, [r".*Admin server listening on .*/tmp/.*\.sock"]) + elif is_ipv6(host): + match_log(output, [r".*Admin server listening on \[.+]:\d+"]) + else: # IPv4 + match_log(output, [r".*Admin server listening on .+:\d+"]) + + +def test_log_error_when_schema_cache_load_error_on_startup_to_stderr(defaultenv): + "Should log the 503 error message when there is an error loading schema cache on startup" + + env = { + **defaultenv, + "PGRST_INTERNAL_SCHEMA_CACHE_QUERY_SLEEP_BEFORE_QUERIES": "1000", + "PGRST_DB_SCHEMAS": "non_existent_schema_aaaa", + } + + with run(env=env, wait_for=None) as postgrest: + postgrest.wait_until_scache_starts_loading() + + # First call should fail with connection refused + with pytest.raises(requests.ConnectionError): + postgrest.session.get("/projects") + + # Next call should return 503 + time.sleep(1) + response = postgrest.session.get("/projects") + assert response.status_code == 503 + + output_start = postgrest.read_stdout(nlines=10) + + log_err_message = '{"code":"PGRST002","details":null,"hint":null,"message":"Could not query the database for the schema cache. Retrying."}' + + assert any(log_err_message in line for line in output_start) + + +@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) +def test_log_pool_req_observation(level, defaultenv): + "PostgREST should log PoolRequest and PoolRequestFullfilled observation when log-level=debug" + + env = {**defaultenv, "PGRST_LOG_LEVEL": level, "PGRST_JWT_SECRET": SECRET} + + headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET) + + pool_req = r".*Trying to borrow a connection from pool.*" + pool_req_fullfill = r".*Borrowed a connection from the pool.*" + + with run(env=env) as postgrest: + + postgrest.session.get("/authors_only", headers=headers) + + if level == "debug": + output = postgrest.read_stdout(nlines=7) + assert len(output) == 7 + match_log(output, [pool_req, pool_req_fullfill]) + elif level == "info": + output = postgrest.read_stdout(nlines=4) + assert len(output) == 1 + else: + output = postgrest.read_stdout(nlines=4) + assert len(output) == 0 + + +def test_log_listener_connection_errors(defaultenv): + "The logs should show the listener connection error message in a single line" + + env = { + **defaultenv, + "PGHOST": "no_host", + "PGRST_DB_CHANNEL_ENABLED": "true", + } + + with run(env=env, no_startup_stdout=False, wait_for=None) as postgrest: + output = postgrest.read_stdout(nlines=5) + assert any( + 'Failed listening for database notifications on the "pgrst" channel. could not translate host name "no_host" to address:' + in line + for line in output + ) + + +def test_log_listener_connection_start(defaultenv): + "The logs should show the listener connection start message in a single line" + + env = { + **defaultenv, + "PGRST_DB_CHANNEL_ENABLED": "true", + } + + with run(env=env, no_startup_stdout=False, wait_for=Admin.ready) as postgrest: + output = postgrest.read_stdout(nlines=10) + # Check for the listener start message containing host and port + # Do not check if pg version is displayed properly as it is tricky to test it + assert any( + f'"{defaultenv["PGHOST"]}:5432" and listening for database notifications on the "pgrst" channel' + in line + for line in output + ) + + +@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) +def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest): + "verify that DB errors are logged to stderr" + + role = "timeout_authenticator" + set_statement_timeout(metapostgrest, role, 500) + + env = { + **defaultenv, + "PGUSER": role, + "PGRST_DB_ANON_ROLE": role, + "PGRST_LOG_LEVEL": level, + } + + with run(env=env) as postgrest: + response = postgrest.session.get("/rpc/sleep?seconds=1") + assert response.status_code == 500 + + # ensure the message appears on the logs + output = postgrest.read_stdout(nlines=8) + + if level == "crit": + assert len(output) == 0 + elif level == "debug": + match_log( + output, + [ + r".*canceling statement due to statement timeout.*", + r".*500.*", + ], + ) + else: + assert " 500 " in output[1] + assert "canceling statement due to statement timeout" in output[0] + + reset_statement_timeout(metapostgrest, role) + + +def test_schema_cache_query_sleep_logs(defaultenv): + """Schema cache sleep should be reflected in the logged query duration.""" + + env = { + **defaultenv, + "PGRST_INTERNAL_SCHEMA_CACHE_QUERY_SLEEP": "1000", + } + log_pattern = re.compile(r"Schema cache queried in ([\d.]+) milliseconds") + + with run(env=env, wait_max_seconds=3, no_startup_stdout=False) as postgrest: + observed_ms = None + collected = [] + + lines = postgrest.read_stdout(nlines=10) + collected.extend(lines) + for line in lines: + match = log_pattern.search(line) + if match: + observed_ms = float(match.group(1)) + break + + assert observed_ms is not None + assert 1000 < observed_ms < 2000 + + +@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) +def test_schema_cache_query_timings_log(level, defaultenv): + "Schema cache query timings should be logged on log-level=debug." + + env = { + **defaultenv, + "PGRST_LOG_LEVEL": level, + } + log_pattern = re.compile( + r".+: tables: [\d.]+ ms, keydeps: [\d.]+ ms, rels: [\d.]+ ms, funcs: [\d.]+ ms, comprels: [\d.]+ ms, dreps: [\d.]+ ms, mhandlers: [\d.]+ ms" + ) + + with run(env=env, no_startup_stdout=False) as postgrest: + output = drain_stdout(postgrest) + timing_matches = [ + match for line in output if (match := log_pattern.match(line)) + ] + + if level == "debug": + assert len(timing_matches) == 1 + else: + assert not timing_matches + + +def test_empty_schema_cache_log_contains_jwt_role(defaultenv): + "Requests are logged with the role when the schema cache is empty on startup" + + env = { + **defaultenv, + "PGRST_DB_SCHEMAS": "non_existent_schema_aaaa", + "PGRST_JWT_SECRET": SECRET, + } + headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET) + + with run(env=env, wait_for=None) as postgrest: + postgrest.wait_until_scache_starts_loading() + + response = postgrest.session.get("/authors_only", headers=headers) + assert response.status_code == 503 + + output = drain_stdout(postgrest) + + assert any( + re.match( + r'- - postgrest_test_author \[.+\] "GET /authors_only HTTP/1.1" 503 \d+ "" "python-requests/.+"', + line, + ) + for line in output + ) + + +def test_expired_jwt_log_lacks_role(defaultenv): + "Expired JWT requests are logged without a role." + + env = {**defaultenv, "PGRST_JWT_SECRET": SECRET} + headers = jwtauthheader({"exp": relativeSeconds(-35)}, SECRET) + + with run(env=env) as postgrest: + response = postgrest.session.get("/authors_only", headers=headers) + assert response.status_code == 401 + + output = postgrest.read_stdout(nlines=1) + + assert len(output) == 1 + assert re.match( + r'- - - \[.+\] "GET /authors_only HTTP/1.1" 401 \d+ "" "python-requests/.+"', + output[0], + ) + + +def test_schema_cache_error_observation(defaultenv): + "schema cache error observation should be logged with invalid db-schemas or db-extra-search-path" + + env = { + **defaultenv, + "PGRST_DB_EXTRA_SEARCH_PATH": "x", + } + + with run(env=env, no_startup_stdout=False, wait_for=None) as postgrest: + # TODO: postgrest should exit here, instead it keeps retrying + # exitCode = wait_until_exit(postgrest) + # assert exitCode == 1 + + output = postgrest.read_stdout(nlines=9) + assert ( + "Failed to load the schema cache using db-schemas=public and db-extra-search-path=x" + in output[6] + ) + + +def test_invalid_rpc_method_log_contains_role(defaultenv): + "Invalid RPC method requests are logged with the anonymous role." + + with run(env=defaultenv) as postgrest: + response = postgrest.session.put("/rpc/sleep") + assert response.status_code == 405 + + output = postgrest.read_stdout(nlines=1) + + assert len(output) == 1 + assert re.match( + r'- - postgrest_test_anonymous \[.+\] "PUT /rpc/sleep HTTP/1.1" 405 \d+ "" "python-requests/.+"', + output[0], + ) + + +def test_pgrst_log_503_client_error_to_stderr(defaultenv): + "PostgREST should log 503 errors to stderr" + + env = { + **defaultenv, + "PGAPPNAME": "test-io", + } + + with run(env=env) as postgrest: + + postgrest.session.get("/rpc/terminate_pgrst?appname=test-io") + + output = postgrest.read_stdout(nlines=6) + + log_message = '{"code":"PGRST001","details":"no connection to the server\\n","hint":null,"message":"Database client error. Retrying the connection."}\n' + + assert any(log_message in line for line in output) + + +def test_termination_unix_signal_logging(defaultenv): + "Server logs when handling termination unix signals." + + with run(env=defaultenv) as postgrest: + postgrest.process.send_signal(signal.SIGTERM) + lines = postgrest.read_stdout(nlines=1) + wait_until_exit(postgrest) + + assert any("SIGTERM" in line for line in lines) + + with run(env=defaultenv) as postgrest: + postgrest.process.send_signal(signal.SIGINT) + lines = postgrest.read_stdout(nlines=1) + wait_until_exit(postgrest) + + assert any("SIGINT" in line for line in lines) + + +def test_options_request_logs_but_cors_preflight_does_not(defaultenv): + "Plain OPTIONS requests should be logged, but CORS preflight requests should not." + + env = { + **defaultenv, + "PGRST_LOG_LEVEL": "info", + "PGRST_SERVER_CORS_ALLOWED_ORIGINS": "http://example.com", + } + preflight_headers = { + "Origin": "http://example.com", + "Access-Control-Request-Method": "POST", + "Access-Control-Request-Headers": "Content-Type", + } + + with run(env=env) as postgrest: + response = postgrest.session.options("/projects") + assert response.status_code == 200 + + response = postgrest.session.options("/projects", headers=preflight_headers) + assert response.status_code == 200 + assert response.headers["Access-Control-Allow-Origin"] == "http://example.com" + + output = drain_stdout(postgrest) + + assert len(output) == 1 + assert re.match( + r'- - postgrest_test_anonymous \[.+\] "OPTIONS /projects HTTP/1.1" 200 \d+ "" "python-requests/.+"', + output[0], + )