diff --git a/CHANGELOG.md b/CHANGELOG.md index cb9bff8e4c..9269d97530 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,10 @@ All notable changes to this project will be documented in this file. From versio ## Unreleased +### Added + +- Log when the pool is released during schema cache reload on `log-level=debug` by @mkleczek in #4668 + ## [14.9] - 2026-04-10 ### Added diff --git a/postgrest.cabal b/postgrest.cabal index 73a6108737..1dc8cc836f 100644 --- a/postgrest.cabal +++ b/postgrest.cabal @@ -304,6 +304,7 @@ test-suite observability other-modules: ObsHelper Observation.JwtCache Observation.MetricsSpec + Observation.SchemaCacheSpec build-depends: base >= 4.9 && < 4.20 , base64-bytestring >= 1 && < 1.3 , bytestring >= 0.10.8 && < 0.13 diff --git a/src/PostgREST/AppState.hs b/src/PostgREST/AppState.hs index a96e49fa22..f265fa7e36 100644 --- a/src/PostgREST/AppState.hs +++ b/src/PostgREST/AppState.hs @@ -219,10 +219,14 @@ usePool AppState{stateObserver=observer, stateMainThreadId=mainThreadId, ..} ses -- | Flush the connection pool so that any future use of the pool will -- use connections freshly established after this call. +-- | Emits PoolFlushed observation flushPool :: AppState -> IO () -flushPool AppState{..} = SQL.release statePool +flushPool AppState{..} = do + SQL.release statePool + stateObserver PoolFlushed -- | Destroy the pool on shutdown. +-- | Differs from flushPool in not emiting PoolFlushed observation. destroyPool :: AppState -> IO () destroyPool AppState{..} = SQL.release statePool diff --git a/src/PostgREST/Logger.hs b/src/PostgREST/Logger.hs index 3b2d933fd6..7a0e160285 100644 --- a/src/PostgREST/Logger.hs +++ b/src/PostgREST/Logger.hs @@ -110,6 +110,9 @@ observationLogger loggerState logLevel obs = case obs of o@PoolRequestFullfilled -> when (logLevel >= LogDebug) $ do logWithZTime loggerState $ observationMessage o + o@PoolFlushed -> + when (logLevel >= LogDebug) $ do + logWithZTime loggerState $ observationMessage o o@JwtCacheEviction -> when (logLevel >= LogDebug) $ do logWithZTime loggerState $ observationMessage o diff --git a/src/PostgREST/Observation.hs b/src/PostgREST/Observation.hs index f8745922ac..99d4506018 100644 --- a/src/PostgREST/Observation.hs +++ b/src/PostgREST/Observation.hs @@ -64,6 +64,7 @@ data Observation | HasqlPoolObs SQL.Observation | PoolRequest | PoolRequestFullfilled + | PoolFlushed | JwtCacheLookup Bool | JwtCacheEviction | TerminationUnixSignalObs Text @@ -161,6 +162,8 @@ observationMessage = \case "Trying to borrow a connection from pool" PoolRequestFullfilled -> "Borrowed a connection from the pool" + PoolFlushed -> + "Database connection pool flushed" JwtCacheLookup _ -> "Looked up a JWT in JWT cache" JwtCacheEviction -> diff --git a/test/observability/Main.hs b/test/observability/Main.hs index 7a38b51c81..416ed70556 100644 --- a/test/observability/Main.hs +++ b/test/observability/Main.hs @@ -17,10 +17,11 @@ import PostgREST.SchemaCache (querySchemaCache) import qualified Observation.JwtCache import qualified Observation.MetricsSpec -import ObsHelper -import PostgREST.Observation (Observation (HasqlPoolObs)) -import Protolude hiding (toList, toS) -import Test.Hspec +import qualified Observation.SchemaCacheSpec +import ObsHelper +import PostgREST.Observation (Observation (HasqlPoolObs)) +import Protolude hiding (toList, toS) +import Test.Hspec main :: IO () main = do @@ -64,6 +65,8 @@ main = do describe "Observation.JwtCacheObs" Observation.JwtCache.spec before (initApp baseSchemaCache testCfg) $ describe "Feature.MetricsSpec" Observation.MetricsSpec.spec + before (initApp baseSchemaCache testCfg) $ + describe "Feature.SchemaCacheSpec" Observation.SchemaCacheSpec.spec where loadSCache pool conf = diff --git a/test/observability/Observation/SchemaCacheSpec.hs b/test/observability/Observation/SchemaCacheSpec.hs new file mode 100644 index 0000000000..e3260271b8 --- /dev/null +++ b/test/observability/Observation/SchemaCacheSpec.hs @@ -0,0 +1,51 @@ +{-# LANGUAGE DataKinds #-} +{-# LANGUAGE MonadComprehensions #-} +{-# LANGUAGE NamedFieldPuns #-} +module Observation.SchemaCacheSpec where + +import Network.Wai (Application) +import ObsHelper +import qualified PostgREST.AppState as AppState +import PostgREST.Config (configDbSchemas) +import PostgREST.Observation +import Protolude +import Test.Hspec (SpecWith, describe, it) +import Test.Hspec.Wai (getState) + +spec :: SpecWith (SpecState, Application) +spec = describe "Server started with metrics enabled" $ do + + it "Should emit PoolFlushed, SchemaCacheQueriedObs and SchemaCacheLoadedObs when schema cache is reloaded" $ do + SpecState{specAppState = appState, specObsChan} <- getState + let waitFor = waitForObs specObsChan + + liftIO $ do + AppState.schemaCacheLoader appState + + waitFor (1 * sec) "PoolFlushed" $ \x -> [ o | o@PoolFlushed <- pure x ] + waitFor (1 * sec) "SchemaCacheQueriedObs" $ \x -> [ o | o@SchemaCacheQueriedObs{} <- pure x ] + waitFor (1 * sec) "SchemaCacheLoadedObs" $ \x -> [ o | o@SchemaCacheLoadedObs{} <- pure x ] + + + it "Should flush pool multiple times when schema reloading retries" $ do + SpecState{specAppState = appState, specObsChan} <- getState + let waitFor = waitForObs specObsChan + + liftIO $ do + AppState.getConfig appState >>= \cfg -> do + AppState.putConfig appState $ cfg { configDbSchemas = pure "bad_schema" } + AppState.schemaCacheLoader appState + + waitFor (1 * sec) "PoolFlushed 1" $ \x -> [ o | o@PoolFlushed <- pure x ] + waitFor (1 * sec) "SchemaCacheErrorObs" $ \x -> [ o | o@SchemaCacheErrorObs{} <- pure x ] + + -- Restore configuration + AppState.putConfig appState cfg + + -- Wait for 2 seconds so that retry can happen + waitFor (2 * sec) "PoolFlushed 2" $ \x -> [ o | o@PoolFlushed <- pure x ] + waitFor (1 * sec) "SchemaCacheQueriedObs" $ \x -> [ o | o@SchemaCacheQueriedObs{} <- pure x ] + waitFor (1 * sec) "SchemaCacheLoadedObs" $ \x -> [ o | o@SchemaCacheLoadedObs{} <- pure x ] + + where + sec = 1000000