fix: not logging the JSON message on a PGRST002 error

It happens right after the configuration is loaded and before
the schema cache is queried.

CHANGELOG.md

@@ -11,6 +11,7 @@ This project adheres to [Semantic Versioning](http://semver.org/).
 - 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
 - Fix loading utf-8 config files with `ASCII` locale set in #4386
+- Fix not logging the JSON message to stderr on a `PGRST002` error by @laurenceisla in #4129
 
 ### Added
 

src/PostgREST/App.hs

@@ -126,11 +126,14 @@ postgrestResponse
   -> Wai.Request
   -> Handler IO Wai.Response
 postgrestResponse appState conf@AppConfig{..} maybeSchemaCache authResult@AuthResult{..} req = do
+  let observer = AppState.getObserver appState
+
   sCache <-
     case maybeSchemaCache of
       Just sCache ->
         return sCache
-      Nothing ->
+      Nothing -> do
+        lift $ observer SchemaCacheEmptyObs
         throwError Error.NoSchemaCacheError
 
   body <- lift $ Wai.strictRequestBody req
@@ -144,7 +147,6 @@ postgrestResponse appState conf@AppConfig{..} maybeSchemaCache authResult@AuthRe
 
   let mainQ = Query.mainQuery plan conf apiReq authResult configDbPreRequest
       tx = MainTx.mainTx mainQ conf authResult apiReq plan sCache
-      observer = AppState.getObserver appState
       obsQuery s = when configLogQuery $ observer $ QueryObs mainQ s
 
   (txTime, txResult) <- withTiming $ do

src/PostgREST/Logger.hs

@@ -95,6 +95,9 @@ observationLogger loggerState logLevel obs = case obs of
   o@(QueryErrorCodeHighObs _) -> do
     when (logLevel >= LogError) $ do
       logWithZTime loggerState $ observationMessage o
+  o@SchemaCacheEmptyObs ->
+    when (logLevel >= LogError) $ do
+    logWithZTime loggerState $ observationMessage o
   o@(HasqlPoolObs _) -> do
     when (logLevel >= LogDebug) $ do
       logWithZTime loggerState $ observationMessage o

src/PostgREST/Observation.hs

@@ -37,6 +37,7 @@ data Observation
   | ExitDBNoRecoveryObs
   | ExitDBFatalError ObsFatalError SQL.UsageError
   | DBConnectedObs Text
+  | SchemaCacheEmptyObs
   | SchemaCacheErrorObs (NonEmpty Text) [Text] SQL.UsageError
   | SchemaCacheQueriedObs Double
   | SchemaCacheSummaryObs Text
@@ -88,6 +89,8 @@ observationMessage = \case
     "If you are using connection poolers in transaction mode, try setting db-prepared-statements to false. " <> jsonMessage usageErr
   ExitDBFatalError ServerError08P01 usageErr ->
     "Connection poolers in statement mode are not supported." <> jsonMessage usageErr
+  SchemaCacheEmptyObs ->
+    T.decodeUtf8 . LBS.toStrict . Error.errorPayload $ Error.NoSchemaCacheError
   SchemaCacheErrorObs dbSchemas extraPaths usageErr ->
     "Failed to load the schema cache using "
       <> "db-schemas=" <> T.intercalate "," (toList dbSchemas)

test/io/test_io.py

@@ -1871,6 +1871,27 @@ 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"
+
+    env = {
+        **defaultenv,
+        "PGRST_INTERNAL_SCHEMA_CACHE_QUERY_SLEEP": "300",
+    }
+
+    with run(env=env, wait_for_readiness=False) as postgrest:
+        postgrest.wait_until_scache_starts_loading()
+
+        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"