fix: Flush pool as late as possible during schema cache reloading

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

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

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)

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