fix: remove red herring warp logs on default log-level

The logs added on e95e815483 are red
herrings under normal operation.

This moves them to `log-level=debug` and removes "error" from the
message prefix.

Fixes https://github.com/PostgREST/postgrest/issues/4799

CHANGELOG.md

@@ -16,6 +16,10 @@ All notable changes to this project will be documented in this file. From versio
 - Add config `db-timezone-enabled` for optional querying of timezones by @taimoorzaeem in #4751
 - Log when the pool is released during schema cache reload on `log-level=debug` by @mkleczek in #4668
 
+### Fixed
+
+- Remove red herring warp logs on default log-level, only emit them on `log-level=debug` by @steve-chavez in #4799
+
 ### Changed
 
 - All responses now include a `Vary` header by @develop7 in #4609

src/PostgREST/App.hs

@@ -99,7 +99,7 @@ run appState = do
     onWarpException :: Maybe Wai.Request -> SomeException -> IO ()
     onWarpException _ ex =
       when (shouldDisplayException ex) $
-        observer $ WarpErrorObs $ show ex
+        observer $ WarpServerObs $ show ex
 
     -- Similar to wai defaultShouldDisplayException in
     -- https://github.com/yesodweb/wai//blob/8c3882c60f6abe043889fc20c7efd3fa9747fa4a/warp/Network/Wai/Handler/Warp/Settings.hs#L251-L258

src/PostgREST/Logger.hs

@@ -120,6 +120,9 @@ observationLogger loggerState logLevel obs = case obs of
   o@(JwtCacheLookup _) ->
     when (logLevel >= LogDebug) $ do
       logWithZTime loggerState $ observationMessages o
+  o@(WarpServerObs _) ->
+    when (logLevel >= LogDebug) $ do
+      logWithZTime loggerState $ observationMessages o
   o ->
     logWithZTime loggerState $ observationMessages o
 
@@ -235,8 +238,8 @@ observationMessages = \case
     pure "Evicted entry from JWT cache"
   TerminationUnixSignalObs signal ->
     pure $ "Received termination unix signal " <> signal
-  WarpErrorObs txt ->
-    pure $ "Warp server error: " <> txt
+  WarpServerObs txt ->
+    pure $ "Warp server: " <> txt
   where
     showMillis :: Double -> Text
     showMillis x = toS $ showFFloat (Just 1) x ""

src/PostgREST/Observation.hs

@@ -57,7 +57,7 @@ data Observation
   | JwtCacheLookup Bool
   | JwtCacheEviction
   | TerminationUnixSignalObs Text
-  | WarpErrorObs Text
+  | WarpServerObs Text
   deriving (Generic)
 
 data ObsFatalError = ServerAuthError | ServerPgrstBug | ServerError42P05 | ServerError08P01

test/io/test_big_schema.py

@@ -57,13 +57,15 @@ def test_openapi_in_big_schema(defaultenv):
         assert response.status_code == 200
 
 
-def test_stackoverflow_is_logged(defaultenv):
-    "Stack overflow errors should be logged with the Warp error message"
+@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"])
+def test_stackoverflow_is_logged(level, defaultenv):
+    "Stack overflow should be logged with the Warp message only on log-level=debug"
 
     env = {
         **defaultenv,
         "PGRST_DB_SCHEMAS": "apflora",
         "PGRST_DB_ANON_ROLE": "postgrest_test_anonymous",
+        "PGRST_LOG_LEVEL": level,
     }
 
     with run(env=env, wait_max_seconds=30, no_startup_stdout=False) as postgrest:
@@ -71,9 +73,15 @@ def test_stackoverflow_is_logged(defaultenv):
             postgrest.session.get("/")
 
         output = postgrest.read_stdout(nlines=10)
-        output.extend(postgrest.read_stdout(nlines=10))
+        for _ in range(3):
+            output.extend(postgrest.read_stdout(nlines=10))
 
-        assert any("Warp server error: stack overflow" in line for line in output)
+        found = any("Warp server: stack overflow" in line for line in output)
+
+        if level == "debug":
+            assert found
+        else:
+            assert not found
 
 
 # See: https://github.com/PostgREST/postgrest/issues/3329