feat: log all internal database errors to stderr

CHANGELOG.md

@@ -23,6 +23,7 @@ This project adheres to [Semantic Versioning](http://semver.org/).
  - #915, Add support for aggregate functions - @timabdulla
     + The aggregate functions SUM(), MAX(), MIN(), AVG(), and COUNT() are now supported.
     + It's disabled by default, you can enable it with `db-aggregates-enabled`.
+ - #3057, Log all internal database errors to stderr - @laurenceisla
 
 ### Fixed
 

src/PostgREST/AppState.hs

@@ -42,6 +42,7 @@ import qualified Hasql.Notifications        as SQL
 import qualified Hasql.Pool                 as SQL
 import qualified Hasql.Session              as SQL
 import qualified Hasql.Transaction.Sessions as SQL
+import qualified Network.HTTP.Types.Status  as HTTP
 import qualified Network.Socket             as NS
 import qualified PostgREST.Error            as Error
 import           PostgREST.Version          (prettyVersion)
@@ -205,11 +206,16 @@ initPool AppConfig{..} =
 
 -- | Run an action with a database connection.
 usePool :: AppState -> SQL.Session a -> IO (Either SQL.UsageError a)
-usePool AppState{..} x = do
+usePool appState@AppState{..} x = do
   res <- SQL.use statePool x
+
   whenLeft res (\case
     SQL.AcquisitionTimeoutUsageError -> debounceLogAcquisitionTimeout -- this can happen rapidly for many requests, so we debounce
-    _                                -> pure ())
+    error
+      -- TODO We're using the 500 HTTP status for getting all internal db errors but there's no response here. We need a new intermediate type to not rely on the HTTP status.
+      | Error.status (Error.PgError False error) >= HTTP.status500 -> logPgrstError appState error
+      | otherwise -> pure ())
+
   return res
 
 -- | Flush the connection pool so that any future use of the pool will

src/PostgREST/Error.hs

@@ -11,6 +11,7 @@ module PostgREST.Error
   , PgError(..)
   , Error(..)
   , errorPayload
+  , status
   ) where
 
 import qualified Data.Aeson                as JSON

test/io/test_io.py

@@ -1341,3 +1341,25 @@ def test_passes_with_3_sec_statement_and_4_sec_statement_timeout(defaultenv):
         response = postgrest.session.post("/rpc/four_sec_timeout")
 
         assert response.status_code == 204
+
+
+def test_db_error_logging_to_stderr(defaultenv, metapostgrest):
+    "verify that DB errors are logged to stderr"
+
+    role = "timeout_authenticator"
+    set_statement_timeout(metapostgrest, role, 1000)
+
+    env = {
+        **defaultenv,
+        "PGUSER": role,
+        "PGRST_DB_ANON_ROLE": role,
+    }
+
+    with run(env=env) as postgrest:
+        response = postgrest.session.get("/rpc/sleep?seconds=1.5")
+        assert response.status_code == 500
+
+        # ensure the message appears on the logs
+        output = sorted(postgrest.read_stdout(nlines=2))
+        assert " 500 " in output[0]
+        assert "canceling statement due to statement timeout" in output[1]