diff --git a/CHANGELOG.md b/CHANGELOG.md index b4659f5ab..2a6bc25e3 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/src/PostgREST/App.hs b/src/PostgREST/App.hs index c62a24086..e696929b4 100644 --- a/src/PostgREST/App.hs +++ b/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 diff --git a/src/PostgREST/Logger.hs b/src/PostgREST/Logger.hs index 93d441296..8f6150985 100644 --- a/src/PostgREST/Logger.hs +++ b/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 diff --git a/src/PostgREST/Observation.hs b/src/PostgREST/Observation.hs index 34b11b5e3..42a16c77a 100644 --- a/src/PostgREST/Observation.hs +++ b/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) diff --git a/test/io/test_io.py b/test/io/test_io.py index 5f95d3c43..690430db4 100644 --- a/test/io/test_io.py +++ b/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"