diff --git a/CHANGELOG.md b/CHANGELOG.md index 70022f903..737abb4b5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,7 @@ All notable changes to this project will be documented in this file. From versio - Add config `client-error-verbosity` to customize error verbosity by @taimoorzaeem in #4088, #3980, #3824 - Add `Vary` header to responses by @develop7 in #4609 - 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 ### Changed diff --git a/postgrest.cabal b/postgrest.cabal index d88a035db..188653a41 100644 --- a/postgrest.cabal +++ b/postgrest.cabal @@ -308,6 +308,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 44000294b..3f60ef04a 100644 --- a/src/PostgREST/AppState.hs +++ b/src/PostgREST/AppState.hs @@ -225,10 +225,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 bbfcc6a1a..7e1543316 100644 --- a/src/PostgREST/Logger.hs +++ b/src/PostgREST/Logger.hs @@ -111,6 +111,9 @@ observationLogger loggerState logLevel obs = case obs of o@PoolRequestFullfilled -> when (logLevel >= LogDebug) $ do logWithZTime loggerState $ observationMessages o + o@PoolFlushed -> + when (logLevel >= LogDebug) $ do + logWithZTime loggerState $ observationMessages o o@JwtCacheEviction -> when (logLevel >= LogDebug) $ do logWithZTime loggerState $ observationMessages o @@ -224,6 +227,8 @@ observationMessages = \case pure "Trying to borrow a connection from pool" PoolRequestFullfilled -> pure "Borrowed a connection from the pool" + PoolFlushed -> + pure "Database connection pool flushed" JwtCacheLookup _ -> pure "Looked up a JWT in JWT cache" JwtCacheEviction -> diff --git a/src/PostgREST/Observation.hs b/src/PostgREST/Observation.hs index 1c0dd1da9..d781606eb 100644 --- a/src/PostgREST/Observation.hs +++ b/src/PostgREST/Observation.hs @@ -53,6 +53,7 @@ data Observation | HasqlPoolObs SQL.Observation | PoolRequest | PoolRequestFullfilled + | PoolFlushed | JwtCacheLookup Bool | JwtCacheEviction | TerminationUnixSignalObs Text diff --git a/test/observability/Main.hs b/test/observability/Main.hs index 7a38b51c8..416ed7055 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 000000000..e3260271b --- /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