fix: Start listening after schema cache load

This change ensures PostgREST starts listening on a server socket only after it loaded the schema cache and is ready to handle requests. It is no longer going to return 503 errors during startup until the schema cache is loaded.

test/io/test_io.py

@@ -6,6 +6,7 @@ import signal
 import subprocess
 import time
 import pytest
+import requests
 
 from config import CONFIGSDIR, FIXTURES, SECRET
 from util import (
@@ -1090,7 +1091,7 @@ def test_empty_schema_cache_log_contains_jwt_role(defaultenv):
 
     env = {
         **defaultenv,
-        "PGRST_INTERNAL_SCHEMA_CACHE_QUERY_SLEEP": "1000",
+        "PGRST_DB_SCHEMAS": "non_existent_schema_aaaa",
         "PGRST_JWT_SECRET": SECRET,
     }
     headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET)
@@ -1543,14 +1544,19 @@ def test_log_postgrest_host_and_port(host, defaultenv):
     with run(
         env=defaultenv, host=host, port=port, no_startup_stdout=False
     ) as postgrest:
-        output = postgrest.read_stdout(nlines=10)
+        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:
-            re.match(r'API server listening on "/tmp/.*\.sock"', output[2])
+            match_log(output, [r".*API server listening on .*/tmp/.*\.sock"])
         elif is_ipv6(host):
-            assert f"API server listening on [{host}]:{port}" in output[2]
+            match_log(output, [r".*API server listening on \[.+]:\d+"])
         else:  # IPv4
-            assert f"API server listening on {host}:{port}" in output[2]
+            match_log(output, [r".*API server listening on .+:\d+"])
 
 
 def test_succeed_w_role_having_superuser_settings(defaultenv):
@@ -1818,17 +1824,24 @@ def test_pgrst_log_503_client_error_to_stderr(defaultenv):
         assert any(log_message in line for line in output)
 
 
-def test_log_error_when_empty_schema_cache_on_startup_to_stderr(defaultenv):
-    "Should log the 503 error message when there is an empty schema cache on startup"
+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": "300",
+        "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
 
@@ -1840,7 +1853,7 @@ def test_log_error_when_empty_schema_cache_on_startup_to_stderr(defaultenv):
 
 
 def test_no_double_schema_cache_reload_on_empty_schema(defaultenv):
-    "Should only load the schema cache once on a 503 error when there's an empty schema cache on startup"
+    "Should only load the schema cache once when there's an empty schema cache on startup"
 
     env = {
         **defaultenv,
@@ -1850,12 +1863,15 @@ def test_no_double_schema_cache_reload_on_empty_schema(defaultenv):
     with run(env=env, wait_for=None) as postgrest:
         postgrest.wait_until_scache_starts_loading()
 
-        response = postgrest.session.get("/projects")
-        assert response.status_code == 503
+        with pytest.raises(requests.ConnectionError):
+            postgrest.session.get("/projects")
 
         # Should wait enough time to load the schema cache twice to guarantee that the test is valid
         time.sleep(1)
 
+        response = postgrest.session.get("/projects")
+        assert response.status_code == 200
+
         response = postgrest.admin.get("/metrics")
         assert response.status_code == 200
         assert 'pgrst_schema_cache_loads_total{status="SUCCESS"} 1.0' in response.text
@@ -1937,7 +1953,7 @@ def test_schema_cache_error_observation(defaultenv):
         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[7]
+            in output[6]
         )
 
 

test/observability/ObsHelper.hs

@@ -119,7 +119,8 @@ baseCfg = let secret = encodeUtf8 "reallyreallyreallyreallyverysafe" in
   , configAdminServerUnixSocketMode = 432
   , configRoleSettings              = mempty
   , configRoleIsoLvl                = mempty
-  , configInternalSCQuerySleep      = Nothing
+  , configInternalSCQuerySleepFst   = Nothing
+  , configInternalSCQuerySleepSnd   = Nothing
   , configServerTimingEnabled       = True
   }
 

test/spec/SpecHelper.hs

@@ -160,7 +160,8 @@ baseCfg = let secret = encodeUtf8 "reallyreallyreallyreallyverysafe" in
   , configAdminServerUnixSocketMode = 432
   , configRoleSettings              = mempty
   , configRoleIsoLvl                = mempty
-  , configInternalSCQuerySleep      = Nothing
+  , configInternalSCQuerySleepFst   = Nothing
+  , configInternalSCQuerySleepSnd   = Nothing
   , configServerTimingEnabled       = True
   }