diff --git a/CHANGELOG.md b/CHANGELOG.md index ea36f2edb2..43807eb014 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,10 @@ All notable changes to this project will be documented in this file. From versio - 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 +### Fixed + +- Fix unnecessary connection pool flushes during schema cache reloading by @mkleczek in #4645 + ### Changed - All responses now include a `Vary` header by @develop7 in #4609 diff --git a/src/PostgREST/AppState.hs b/src/PostgREST/AppState.hs index e8424fb728..55ee2de1db 100644 --- a/src/PostgREST/AppState.hs +++ b/src/PostgREST/AppState.hs @@ -302,8 +302,6 @@ retryingSchemaCacheLoad appState@AppState{stateObserver=observer, stateMainThrea let delay = fromMaybe 0 rsPreviousDelay `div` oneSecondInUs observer $ ConnectionRetryObs delay - flushPool appState - (,) <$> qPgVersion <*> (qInDbConfig *> qSchemaCache) ) where @@ -352,6 +350,10 @@ retryingSchemaCacheLoad appState@AppState{stateObserver=observer, stateMainThrea -- IORef on putSchemaCache. This is why schema cache status is marked as pending here to signal the Admin server (using isPending) that we're on a recovery state. markSchemaCachePending appState putSchemaCache appState $ Just sCache + -- Flush the pool after loading the schema cache to reset any stale session cache entries + -- We do it after successfully querying the schema cache (because this can fail and during retries we would flush the pool repeatedly unnecessarily) + -- and after marking sCacheStatus as pending, + flushPool appState observer $ SchemaCacheQueriedObs resultTime observer . uncurry SchemaCacheLoadedObs =<< timeItT (evaluate $ showSummary sCache) markSchemaCacheLoaded appState diff --git a/test/io/test_io.py b/test/io/test_io.py index 86310cd4be..b0f4aef583 100644 --- a/test/io/test_io.py +++ b/test/io/test_io.py @@ -841,7 +841,7 @@ def test_log_level(level, defaultenv): response = postgrest.session.get("/") assert response.status_code == 200 - output = postgrest.read_stdout(nlines=7) + output = postgrest.read_stdout(nlines=9) if level == "crit": assert len(output) == 0 @@ -879,7 +879,7 @@ def test_log_level(level, defaultenv): r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', ], ) - assert len(output) == 7 + assert len(output) == 9 assert any("Connection" and "is available" in line for line in output) assert any("Connection" and "is used" in line for line in output) @@ -1507,7 +1507,7 @@ def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest): assert response.status_code == 500 # ensure the message appears on the logs - output = postgrest.read_stdout(nlines=6) + output = postgrest.read_stdout(nlines=8) if level == "crit": assert len(output) == 0 @@ -1724,7 +1724,7 @@ def test_log_pool_req_observation(level, defaultenv): if level == "debug": output = postgrest.read_stdout(nlines=7) - assert len(output) == 6 + assert len(output) == 7 match_log(output, [pool_req, pool_req_fullfill]) elif level == "info": output = postgrest.read_stdout(nlines=4) diff --git a/test/observability/Observation/SchemaCacheSpec.hs b/test/observability/Observation/SchemaCacheSpec.hs index e3260271b8..318c2dba6b 100644 --- a/test/observability/Observation/SchemaCacheSpec.hs +++ b/test/observability/Observation/SchemaCacheSpec.hs @@ -27,7 +27,7 @@ spec = describe "Server started with metrics enabled" $ do waitFor (1 * sec) "SchemaCacheLoadedObs" $ \x -> [ o | o@SchemaCacheLoadedObs{} <- pure x ] - it "Should flush pool multiple times when schema reloading retries" $ do + it "Should flush pool once when schema reloading retries" $ do SpecState{specAppState = appState, specObsChan} <- getState let waitFor = waitForObs specObsChan @@ -36,16 +36,14 @@ spec = describe "Server started with metrics enabled" $ 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 (2 * 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 ] - where sec = 1000000