fix: Flush pool as late as possible during schema cache reloading (#4645)

retryingSchemaCacheLoad flushes the pool upon every retry before it starts reloading the schema. This is too early as schema reloading might take some time during which new connections might be acquired. The consequence is that:
* upon successful schema cache reload we might have some connections created with the old schema cache
* we close connections upon each retry and under load we will keep closing and re-opening connections until schema cache load succeeds

This change is to make sure we flush the pool only after successful schema cache querying but before loading (so that connections acquired during loading wait for it and do not interfere with timing the loading process).
This commit is contained in:
Michal Kleczek
2026-04-16 11:55:43 +05:00
committed by Taimoor Zaeem
parent df87ce46ed
commit abd76ca8ac
4 changed files with 14 additions and 10 deletions
+4
View File
@@ -8,6 +8,10 @@ All notable changes to this project will be documented in this file. From versio
- Log when the pool is released during schema cache reload on `log-level=debug` by @mkleczek in #4668 - 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
## [14.9] - 2026-04-10 ## [14.9] - 2026-04-10
### Added ### Added
+4 -2
View File
@@ -313,8 +313,6 @@ retryingSchemaCacheLoad appState@AppState{stateObserver=observer, stateMainThrea
observer $ ConnectionRetryObs delay observer $ ConnectionRetryObs delay
putNextListenerDelay appState delay putNextListenerDelay appState delay
flushPool appState
(,) <$> qPgVersion <*> (qInDbConfig *> qSchemaCache) (,) <$> qPgVersion <*> (qInDbConfig *> qSchemaCache)
) )
where where
@@ -363,6 +361,10 @@ retryingSchemaCacheLoad appState@AppState{stateObserver=observer, stateMainThrea
-- IORef on putSchemaCache. This is why SCacheStatus is put at SCPending here to signal the Admin server (using isPending) that we're on a recovery state. -- IORef on putSchemaCache. This is why SCacheStatus is put at SCPending here to signal the Admin server (using isPending) that we're on a recovery state.
putSCacheStatus appState SCPending putSCacheStatus appState SCPending
putSchemaCache appState $ Just sCache 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 $ SchemaCacheQueriedObs resultTime
(t, _) <- timeItT $ observer $ SchemaCacheSummaryObs $ showSummary sCache (t, _) <- timeItT $ observer $ SchemaCacheSummaryObs $ showSummary sCache
observer $ SchemaCacheLoadedObs t observer $ SchemaCacheLoadedObs t
+4 -4
View File
@@ -692,7 +692,7 @@ def test_log_level(level, defaultenv):
response = postgrest.session.get("/") response = postgrest.session.get("/")
assert response.status_code == 200 assert response.status_code == 200
output = postgrest.read_stdout(nlines=7) output = postgrest.read_stdout(nlines=9)
if level == "crit": if level == "crit":
assert len(output) == 0 assert len(output) == 0
@@ -730,7 +730,7 @@ def test_log_level(level, defaultenv):
r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"', 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 available" in line for line in output)
assert any("Connection" and "is used" in line for line in output) assert any("Connection" and "is used" in line for line in output)
@@ -1367,7 +1367,7 @@ def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest):
assert response.status_code == 500 assert response.status_code == 500
# ensure the message appears on the logs # ensure the message appears on the logs
output = postgrest.read_stdout(nlines=6) output = postgrest.read_stdout(nlines=8)
if level == "crit": if level == "crit":
assert len(output) == 0 assert len(output) == 0
@@ -1584,7 +1584,7 @@ def test_log_pool_req_observation(level, defaultenv):
if level == "debug": if level == "debug":
output = postgrest.read_stdout(nlines=7) output = postgrest.read_stdout(nlines=7)
assert len(output) == 6 assert len(output) == 7
match_log(output, [pool_req, pool_req_fullfill]) match_log(output, [pool_req, pool_req_fullfill])
elif level == "info": elif level == "info":
output = postgrest.read_stdout(nlines=4) output = postgrest.read_stdout(nlines=4)
@@ -27,7 +27,7 @@ spec = describe "Server started with metrics enabled" $ do
waitFor (1 * sec) "SchemaCacheLoadedObs" $ \x -> [ o | o@SchemaCacheLoadedObs{} <- pure x ] 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 SpecState{specAppState = appState, specObsChan} <- getState
let waitFor = waitForObs specObsChan 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.putConfig appState $ cfg { configDbSchemas = pure "bad_schema" }
AppState.schemaCacheLoader appState AppState.schemaCacheLoader appState
waitFor (1 * sec) "PoolFlushed 1" $ \x -> [ o | o@PoolFlushed <- pure x ]
waitFor (1 * sec) "SchemaCacheErrorObs" $ \x -> [ o | o@SchemaCacheErrorObs{} <- pure x ] waitFor (1 * sec) "SchemaCacheErrorObs" $ \x -> [ o | o@SchemaCacheErrorObs{} <- pure x ]
-- Restore configuration -- Restore configuration
AppState.putConfig appState cfg AppState.putConfig appState cfg
-- Wait for 2 seconds so that retry can happen -- 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) "SchemaCacheQueriedObs" $ \x -> [ o | o@SchemaCacheQueriedObs{} <- pure x ]
waitFor (1 * sec) "SchemaCacheLoadedObs" $ \x -> [ o | o@SchemaCacheLoadedObs{} <- pure x ] waitFor (1 * sec) "SchemaCacheLoadedObs" $ \x -> [ o | o@SchemaCacheLoadedObs{} <- pure x ]
where where
sec = 1000000 sec = 1000000