diff --git a/CHANGELOG.md b/CHANGELOG.md index 70022f903c..737abb4b50 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 d88a035db2..188653a410 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 44000294be..3f60ef04a6 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 bbfcc6a1a7..7e15433163 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 1c0dd1da91..d781606eb3 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/io/test_io.py b/test/io/test_io.py index 6dc81845c8..392aa9b5c2 100644 --- a/test/io/test_io.py +++ b/test/io/test_io.py @@ -21,6 +21,19 @@ ) +def match_log(output, matchers): + ito = iter(output) + itm = iter(matchers) + nextMatcher = next(itm, None) + while nextMatcher is not None and (line := next(ito, None)) is not None: + if re.match(nextMatcher, line) is not None: + nextMatcher = next(itm, None) + if nextMatcher is not None: + raise AssertionError( + f"Expected log line matching {nextMatcher} not found in output" + ) + + def test_connect_with_dburi(dburi, defaultenv): "Connecting with db-uri instead of LIPQ* environment variables should work." defaultenv_without_libpq = { @@ -768,54 +781,44 @@ def test_log_level(level, defaultenv): response = postgrest.session.get("/") assert response.status_code == 200 - output = sorted(postgrest.read_stdout(nlines=7)) + output = postgrest.read_stdout(nlines=7) if level == "crit": assert len(output) == 0 elif level == "error": - assert re.match( - r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', - output[0], + match_log( + output, + [r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"'], ) assert len(output) == 1 elif level == "warn": - assert re.match( - r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', - output[0], - ) - assert re.match( - r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', - output[1], + match_log( + output, + [ + r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', + ], ) assert len(output) == 2 elif level == "info": - assert re.match( - r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', - output[0], - ) - assert re.match( - r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', - output[1], - ) - assert re.match( - r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', - output[2], + match_log( + output, + [ + r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', + ], ) assert len(output) == 3 elif level == "debug": - assert re.match( - r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', - output[0], + match_log( + output, + [ + r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', + r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', + ], ) - assert re.match( - r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', - output[1], - ) - assert re.match( - r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"', - output[2], - ) - assert len(output) == 7 assert any("Connection" and "is available" in line for line in output) assert any("Connection" and "is used" in line for line in output) @@ -1453,16 +1456,21 @@ 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=6)) + output = postgrest.read_stdout(nlines=6) if level == "crit": assert len(output) == 0 elif level == "debug": - assert " 500 " in output[0] - assert "canceling statement due to statement timeout" in output[5] + match_log( + output, + [ + r".*canceling statement due to statement timeout.*", + r".*500.*", + ], + ) else: - assert " 500 " in output[0] - assert "canceling statement due to statement timeout" in output[1] + assert " 500 " in output[1] + assert "canceling statement due to statement timeout" in output[0] reset_statement_timeout(metapostgrest, role) @@ -1656,18 +1664,17 @@ def test_log_pool_req_observation(level, defaultenv): headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET) - pool_req = "Trying to borrow a connection from pool" - pool_req_fullfill = "Borrowed a connection from the pool" + pool_req = r".*Trying to borrow a connection from pool.*" + pool_req_fullfill = r".*Borrowed a connection from the pool.*" with run(env=env) as postgrest: postgrest.session.get("/authors_only", headers=headers) if level == "debug": - output = postgrest.read_stdout(nlines=5) - assert pool_req in output[1] - assert pool_req_fullfill in output[4] - assert len(output) == 5 + output = postgrest.read_stdout(nlines=7) + assert len(output) == 6 + match_log(output, [pool_req, pool_req_fullfill]) elif level == "info": output = postgrest.read_stdout(nlines=4) assert len(output) == 1 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