test(io): move logs and observations tests to test_log.py

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>

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

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 (= "<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'

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],
+    )