feat: log connection pool events on log-level=info

CHANGELOG.md

@@ -13,6 +13,7 @@ This project adheres to [Semantic Versioning](http://semver.org/).
  - #3171, #3046, Log schema cache stats to stderr - @steve-chavez
  - #3210, Dump schema cache through admin API - @taimoorzaeem
  - #2676, Performance improvement on bulk json inserts, around 10% increase on requests per second by removing `json_typeof` from write queries - @steve-chavez
+ - #3214, Log connection pool events on log-level=info - @steve-chavez
 
 ### Fixed
 

cabal.project.freeze

@@ -1 +1 @@
-index-state: hackage.haskell.org 2024-03-13T22:43:26Z
+index-state: hackage.haskell.org 2024-04-15T20:28:44Z

nix/overlays/haskell-packages.nix

@@ -35,11 +35,14 @@ let
       # - <subpath> is usually "."
       # - When adding a new library version here, postgrest.cabal and stack.yaml must also be updated
       #
-      # Note:
+      # Notes:
       # - This should NOT be the first place to start managing dependencies. Check postgrest.cabal.
+      # - When adding a new package version here, you have to update stack:
+      #   + For stack.yml add:
+      #   extra-deps:
+      #     - <package>-<ver>
+      #   + For stack.yml.lock, CI should report an error with the correct lock, copy/paste that one into the file
       # - To modify and try packages locally, see "Working with locally modified Haskell packages" in the Nix README.
-      #
-
 
       configurator-pg =
         prev.callHackageDirect
@@ -60,18 +63,26 @@ let
           }
           { };
 
+      hasql-pool =
+        lib.dontCheck (prev.callHackageDirect
+          {
+            pkg = "hasql-pool";
+            ver = "1.0.1";
+            sha256 = "sha256-Hf1f7lX0LWkjrb25SDBovCYPRdmUP1H6pAxzi7kT4Gg=";
+          }
+          { }
+        );
+
       postgresql-libpq = lib.dontCheck
         (prev.postgresql-libpq_0_10_0_0.override {
           postgresql = super.libpq;
         });
 
-      hasql-pool = lib.dontCheck prev.hasql-pool_0_10;
-
       hasql-notifications = lib.dontCheck (prev.callHackageDirect
         {
           pkg = "hasql-notifications";
-          ver = "0.2.1.0";
-          sha256 = "sha256-MEIirDKR81KpiBOnWJbVInWevL6Kdb/XD1Qtd8e6KsQ=";
+          ver = "0.2.1.1";
+          sha256 = "sha256-oPhKA/pSQGJvgQyhsi7CVr9iDT7uWpKUz0iJfXsaxXo=";
         }
         { }
       );

postgrest.cabal

@@ -108,8 +108,8 @@ library
                     , gitrev                    >= 1.2 && < 1.4
                     , hasql                     >= 1.6.1.1 && < 1.7
                     , hasql-dynamic-statements  >= 0.3.1 && < 0.4
-                    , hasql-notifications       >= 0.2.1.0 && < 0.3
-                    , hasql-pool                >= 0.10 && < 0.11
+                    , hasql-notifications       >= 0.2.1.1 && < 0.3
+                    , hasql-pool                >= 1.0.1 && < 1.1
                     , hasql-transaction         >= 1.0.1 && < 1.1
                     , heredoc                   >= 0.2 && < 0.3
                     , http-types                >= 0.12.2 && < 0.13
@@ -254,7 +254,7 @@ test-suite spec
                     , bytestring        >= 0.10.8 && < 0.13
                     , case-insensitive  >= 1.2 && < 1.3
                     , containers        >= 0.5.7 && < 0.7
-                    , hasql-pool        >= 0.10 && < 0.11
+                    , hasql-pool        >= 1.0.1 && < 1.1
                     , hasql-transaction >= 1.0.1 && < 1.1
                     , heredoc           >= 0.2 && < 0.3
                     , hspec             >= 2.3 && < 2.12

src/PostgREST/AppState.hs

@@ -39,6 +39,7 @@ import qualified Data.Text                  as T (unpack)
 import           Hasql.Connection           (acquire)
 import qualified Hasql.Notifications        as SQL
 import qualified Hasql.Pool                 as SQL
+import qualified Hasql.Pool.Config          as SQL
 import qualified Hasql.Session              as SQL
 import qualified Hasql.Transaction.Sessions as SQL
 import qualified Network.HTTP.Types.Status  as HTTP
@@ -122,7 +123,7 @@ init :: AppConfig -> IO AppState
 init conf@AppConfig{configLogLevel} = do
   loggerState <- Logger.init
   let observer = Logger.observationLogger loggerState configLogLevel
-  pool <- initPool conf
+  pool <- initPool conf observer
   (sock, adminSock) <- initSockets conf
   state' <- initWithPool (sock, adminSock) pool conf loggerState observer
   pure state' { stateSocketREST = sock, stateSocketAdmin = adminSock}
@@ -193,14 +194,16 @@ initSockets AppConfig{..} = do
 
   pure (sock, adminSock)
 
-initPool :: AppConfig -> IO SQL.Pool
-initPool AppConfig{..} =
-  SQL.acquire
-    configDbPoolSize
-    (fromIntegral configDbPoolAcquisitionTimeout)
-    (fromIntegral configDbPoolMaxLifetime)
-    (fromIntegral configDbPoolMaxIdletime)
-    (toUtf8 $ addFallbackAppName prettyVersion configDbUri)
+initPool :: AppConfig -> ObservationHandler -> IO SQL.Pool
+initPool AppConfig{..} observer =
+  SQL.acquire $ SQL.settings
+    [ SQL.size configDbPoolSize
+    , SQL.acquisitionTimeout $ fromIntegral configDbPoolAcquisitionTimeout
+    , SQL.agingTimeout $ fromIntegral configDbPoolMaxLifetime
+    , SQL.idlenessTimeout $ fromIntegral configDbPoolMaxIdletime
+    , SQL.staticConnectionSettings (toUtf8 $ addFallbackAppName prettyVersion configDbUri)
+    , SQL.observationHandler $ observer . HasqlPoolObs
+    ]
 
 -- | Run an action with a database connection.
 usePool :: AppState -> SQL.Session a -> IO (Either SQL.UsageError a)

src/PostgREST/Logger.hs

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

src/PostgREST/Observation.hs

@@ -9,14 +9,15 @@ module PostgREST.Observation
   , ObservationHandler
   ) where
 
-import qualified Data.ByteString.Lazy as LBS
-import qualified Data.Text            as T
-import qualified Data.Text.Encoding   as T
-import qualified Hasql.Connection     as SQL
-import qualified Hasql.Pool           as SQL
-import qualified Network.Socket       as NS
-import           Numeric              (showFFloat)
-import qualified PostgREST.Error      as Error
+import qualified Data.ByteString.Lazy   as LBS
+import qualified Data.Text              as T
+import qualified Data.Text.Encoding     as T
+import qualified Hasql.Connection       as SQL
+import qualified Hasql.Pool             as SQL
+import qualified Hasql.Pool.Observation as SQL
+import qualified Network.Socket         as NS
+import           Numeric                (showFFloat)
+import qualified PostgREST.Error        as Error
 
 import Protolude
 import Protolude.Partial (fromJust)
@@ -50,6 +51,7 @@ data Observation
   | QueryRoleSettingsErrorObs SQL.UsageError
   | QueryErrorCodeHighObs SQL.UsageError
   | PoolAcqTimeoutObs SQL.UsageError
+  | HasqlPoolObs SQL.Observation
 
 type ObservationHandler = Observation -> IO ()
 
@@ -111,6 +113,18 @@ observationMessage = \case
      "Config reloaded"
   PoolAcqTimeoutObs usageErr ->
     jsonMessage usageErr
+  HasqlPoolObs (SQL.ConnectionObservation uuid status) ->
+    "Connection " <> show uuid <> (
+      case status of
+        SQL.ConnectingConnectionStatus   -> " is being established"
+        SQL.ReadyForUseConnectionStatus  -> " is available"
+        SQL.InUseConnectionStatus        -> " is used"
+        SQL.TerminatedConnectionStatus reason -> " is terminated due to " <> case reason of
+          SQL.AgingConnectionTerminationReason          -> "max lifetime"
+          SQL.IdlenessConnectionTerminationReason       -> "max idletime"
+          SQL.ReleaseConnectionTerminationReason        -> "release"
+          SQL.NetworkErrorConnectionTerminationReason _ -> "network error" -- usage error is already logged, no need to repeat the same message.
+    )
   where
     showMillis :: Double -> Text
     showMillis x = toS $ showFFloat (Just 1) (x * 1000) ""

stack.yaml

@@ -12,7 +12,7 @@ nix:
 extra-deps:
   - configurator-pg-0.2.7
   - fuzzyset-0.2.4
-  - hasql-notifications-0.2.1.0
-  - hasql-pool-0.10
+  - hasql-notifications-0.2.1.1
+  - hasql-pool-1.0.1
   - megaparsec-9.2.2
   - postgresql-libpq-0.10.0.0

stack.yaml.lock

@@ -19,19 +19,19 @@ packages:
   original:
     hackage: fuzzyset-0.2.4
 - completed:
-    hackage: hasql-notifications-0.2.1.0@sha256:c9c0ba3ac0866142836d2d0a08a0d10a945bcbe1c163ee1ef6aed407d046a24e,2022
+    hackage: hasql-notifications-0.2.1.1@sha256:e4f41f462e96f3af3f088b747daeeb2275ceaebd0e4b0d05187bd10d329afada,2021
     pantry-tree:
-      sha256: 65a646ed0a77ee1dfe902faedc590103ee385eaa78f407c4cf02a1eb5783d464
+      sha256: f9041b1c242436324372f6be9a4f2e5cf70203c3efad36a4e9ea4cca5113a2ec
       size: 452
   original:
-    hackage: hasql-notifications-0.2.1.0
+    hackage: hasql-notifications-0.2.1.1
 - completed:
-    hackage: hasql-pool-0.10@sha256:912197a328acb85505f98bb9700d61f366b87659ca45126c5c2d636687b801c3,2112
+    hackage: hasql-pool-1.0.1@sha256:3cfb4c7153a6c536ac7e126c17723e6d26ee03794954deed2d72bcc826d05a40,2302
     pantry-tree:
-      sha256: b655c540a49764a8d16b62941137e295b936b96edc0785eb9250972f0f92dc47
-      size: 346
+      sha256: d98e1269bdd60989b0eb0b84e1d5357eaa9f92821439d9f206663b7251ee95b2
+      size: 799
   original:
-    hackage: hasql-pool-0.10
+    hackage: hasql-pool-1.0.1
 - completed:
     hackage: megaparsec-9.2.2@sha256:c306a135ec25d91d252032c6128f03598a00e87ea12fcf5fc4878fdffc75c768,3219
     pantry-tree:

test/io/test_io.py

@@ -593,13 +593,13 @@ def test_pool_acquisition_timeout(level, defaultenv, metapostgrest):
         assert data["message"] == "Timed out acquiring connection from connection pool."
 
         # ensure the message appears on the logs as well
-        output = sorted(postgrest.read_stdout(nlines=2))
+        output = sorted(postgrest.read_stdout(nlines=3))
 
         if level == "crit":
             assert len(output) == 0
-        else:
+        elif level == "info":
             assert " 504 " in output[0]
-            assert "Timed out acquiring connection from connection pool." in output[1]
+            assert "Timed out acquiring connection from connection pool." in output[2]
 
 
 def test_change_statement_timeout_held_connection(defaultenv, metapostgrest):
@@ -792,7 +792,7 @@ def test_log_level(level, defaultenv):
         response = postgrest.session.get("/")
         assert response.status_code == 200
 
-        output = sorted(postgrest.read_stdout(nlines=3))
+        output = sorted(postgrest.read_stdout(nlines=7))
 
         if level == "crit":
             assert len(output) == 0
@@ -825,7 +825,11 @@ def test_log_level(level, defaultenv):
                 r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 - "" "python-requests/.+"',
                 output[2],
             )
-            assert len(output) == 3
+            assert "Connection" and "is available" in output[3]
+            assert "Connection" and "is available" in output[4]
+            assert "Connection" and "is used" in output[5]
+            assert "Connection" and "is used" in output[6]
+            assert len(output) == 7
 
 
 def test_no_pool_connection_required_on_bad_http_logic(defaultenv):
@@ -1083,12 +1087,14 @@ def test_get_pgrst_version_with_keyval_connection_string(defaultenv):
 def test_log_postgrest_version(defaultenv):
     "Should show the PostgREST version in the logs"
 
+    env = {**defaultenv, "PGRST_LOG_LEVEL": "crit"}
+
     with run(env=defaultenv, no_startup_stdout=False) as postgrest:
         version = postgrest.session.head("/").headers["Server"].split("/")[1]
 
         output = sorted(postgrest.read_stdout(nlines=5))
 
-        assert "Starting PostgREST %s..." % version in output[3]
+        assert "Starting PostgREST %s..." % version in output[4]
 
 
 def test_succeed_w_role_having_superuser_settings(defaultenv):
@@ -1371,10 +1377,13 @@ def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest):
         assert response.status_code == 500
 
         # ensure the message appears on the logs
-        output = sorted(postgrest.read_stdout(nlines=2))
+        output = sorted(postgrest.read_stdout(nlines=4))
 
         if level == "crit":
             assert len(output) == 0
+        elif level == "info":
+            assert " 500 " in output[0]
+            assert "canceling statement due to statement timeout" in output[3]
         else:
             assert " 500 " in output[0]
             assert "canceling statement due to statement timeout" in output[1]

test/spec/Main.hs

@@ -1,6 +1,7 @@
 module Main where
 
 import qualified Hasql.Pool                 as P
+import qualified Hasql.Pool.Config          as P
 import qualified Hasql.Transaction.Sessions as HT
 
 import Data.Function (id)
@@ -70,7 +71,13 @@ import qualified Feature.RpcPreRequestGucsSpec
 main :: IO ()
 main = do
   let observer = const $ pure ()
-  pool <- P.acquire 3 10 60 60 $ toUtf8 $ configDbUri testCfg
+  pool <- P.acquire $ P.settings
+    [ P.size 3
+    , P.acquisitionTimeout 10
+    , P.agingTimeout 60
+    , P.idlenessTimeout 60
+    , P.staticConnectionSettings (toUtf8 $ configDbUri testCfg)
+    ]
 
   actualPgVersion <- either (panic . show) id <$> P.use pool (queryPgVersion False)