add: make config log-level reloadable

Closes #5113.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>

CHANGELOG.md

@@ -16,6 +16,7 @@ All notable changes to this project will be documented in this file. From versio
 - Add GHC runtime metrics to the metrics endpoint by @mkleczek in #4862
 - Support running the admin server on a unix socket by @wolfgangwalther in #5003
 - Add config `server-reuseport` to allow starting multiple PostgREST instances using the same port on supported platforms by @mkleczek in #4703, #4694
+- Make config `log-level` reloadable by @taimoorzaeem in #5113
 
 ### Fixed
 

docs/references/configuration.rst

@@ -767,7 +767,7 @@ log-level
   =============== =================================
   **Type**        String
   **Default**     error
-  **Reloadable**  N
+  **Reloadable**  Y
   **Environment** PGRST_LOG_LEVEL
   **In-Database** `n/a`
   =============== =================================

src/library/PostgREST/AppState.hs

@@ -39,7 +39,7 @@ import           PostgREST.Version       (prettyVersion)
 import Control.AutoUpdate         (defaultUpdateSettings, mkAutoUpdate,
                                    updateAction)
 import Control.Concurrent.STM     (newEmptyTMVarIO)
-import Data.IORef                 (newIORef, readIORef)
+import Data.IORef                 (IORef, newIORef, readIORef)
 import Data.Time.Clock            (getCurrentTime)
 import PostgREST.AppState.Pool    (destroy, initPool, usePool)
 import PostgREST.AppState.Reload  (isSchemaCacheLoaded, readInDbConfig,
@@ -54,26 +54,29 @@ import PostgREST.Debounce         (makeDebouncer)
 import Protolude
 
 init :: AppConfig -> IO () -> IO AppState
-init conf@AppConfig{configLogLevel, configDbPoolSize} appKiller = do
-  loggerState  <- Logger.init
+init conf@AppConfig{configDbPoolSize} appKiller = do
+  -- We need to create IORef first, so we can make its read action part of
+  -- loggerState. This is needed for log-level config reloading.
+  confRef <- newIORef conf
+  loggerState  <- Logger.init (configLogLevel <$> readIORef confRef)
   metricsState <- Metrics.init configDbPoolSize
-  let observer = liftA2 (>>) (Logger.observationLogger loggerState configLogLevel) (Metrics.observationMetrics metricsState)
+  let observer = liftA2 (>>) (Logger.observationLogger loggerState) (Metrics.observationMetrics metricsState)
 
   observer $ AppStartObs prettyVersion
 
   pool <- initPool conf observer
-  initWithPool pool conf loggerState metricsState observer appKiller
-
-initWithPool :: SQL.Pool -> AppConfig -> Logger.LoggerState -> Metrics.MetricsState -> ObservationHandler -> IO () -> IO AppState
-initWithPool pool conf loggerState metricsState observer appKiller = mdo
+  initWithPool pool confRef loggerState metricsState observer appKiller
 
+initWithPool :: SQL.Pool -> IORef AppConfig -> Logger.LoggerState -> Metrics.MetricsState -> ObservationHandler -> IO () -> IO AppState
+initWithPool pool confRef loggerState metricsState observer appKiller = mdo
+  conf <- readIORef confRef
   appState <- AppState pool
     <$> newIORef minimumPgVersion -- assume we're in a supported version when starting, this will be corrected on a later step
     <*> newIORef Nothing
     <*> newSchemaCacheStatus
     <*> newIORef False
     <*> makeDebouncer (retryingSchemaCacheLoad appState *> threadDelay 100000)  -- 100ms cooldown
-    <*> newIORef conf
+    <*> pure confRef
     <*> mkAutoUpdate defaultUpdateSettings { updateAction = getCurrentTime }
     <*> pure appKiller
     <*> newIORef 0

src/library/PostgREST/Logger.hs

@@ -45,13 +45,14 @@ import           Protolude
 data LoggerState = LoggerState
   { stateGetZTime               :: IO ZonedTime  -- ^ Time with time zone used for logs
   , stateLogDebouncePoolTimeout :: IO ()         -- ^ Logs with a debounce
+  , getLogLevel                 :: IO LogLevel   -- ^ Get LogLevel from Config
   }
 
-init :: IO LoggerState
-init = mdo
+init :: IO LogLevel -> IO LoggerState
+init getLogLvl = mdo
   let
     oneSecond = 1_000_000
-    loggerState = LoggerState zTime debouncePoolTimeout
+    loggerState = LoggerState zTime debouncePoolTimeout getLogLvl
   zTime <- mkAutoUpdate defaultUpdateSettings { updateAction = getZonedTime }
   debouncePoolTimeout <- makeDebouncer $
     logWithZTime loggerState (observationMessages PoolAcqTimeoutObs) *> threadDelay (5 * oneSecond)
@@ -66,47 +67,49 @@ shouldLogResponse logLevel = case logLevel of
   LogDebug -> const True
 
 -- All observations are logged except some that depend on the log-level
-observationLogger :: LoggerState -> LogLevel -> ObservationHandler
-observationLogger loggerState logLevel obs = case obs of
-  PoolAcqTimeoutObs -> do
-    when (logLevel >= LogError) $
-      stateLogDebouncePoolTimeout loggerState
-  o@(QueryErrorCodeHighObs _) -> do
-    when (logLevel >= LogError) $ do
+observationLogger :: LoggerState -> ObservationHandler
+observationLogger loggerState obs = do
+  logLevel <- getLogLevel loggerState -- We need to do the IO action to read the "log-level" config value because it can be reloaded
+  case obs of
+    PoolAcqTimeoutObs -> do
+      when (logLevel >= LogError) $
+        stateLogDebouncePoolTimeout loggerState
+    o@(QueryErrorCodeHighObs _) -> do
+      when (logLevel >= LogError) $ do
+        logWithZTime loggerState $ observationMessages o
+    o@SchemaCacheEmptyObs ->
+      when (logLevel >= LogError) $ do
       logWithZTime loggerState $ observationMessages o
-  o@SchemaCacheEmptyObs ->
-    when (logLevel >= LogError) $ do
-    logWithZTime loggerState $ observationMessages o
-  o@(HasqlPoolObs _) -> do
-    when (logLevel >= LogDebug) $ do
+    o@(HasqlPoolObs _) -> do
+      when (logLevel >= LogDebug) $ do
+        logWithZTime loggerState $ observationMessages o
+    o@(QueryObs _ status) -> do
+      when (shouldLogResponse logLevel status) $
+        logWithZTime loggerState $ observationMessages o
+    o@PoolRequest ->
+      when (logLevel >= LogDebug) $ do
+        logWithZTime loggerState $ observationMessages o
+    o@PoolRequestFullfilled ->
+      when (logLevel >= LogDebug) $ do
+        logWithZTime loggerState $ observationMessages o
+    ResponseObs maybeRole req status contentLen ->
+      when (shouldLogResponse logLevel status) $ do
+        zTime <- stateGetZTime loggerState
+        putStr $ apacheFormat maybeRole (BS.pack $ formatZonedTime zTime) req status contentLen -- putStr prints to stdout
+    o@PoolFlushed ->
+      when (logLevel >= LogDebug) $ do
+        logWithZTime loggerState $ observationMessages o
+    o@JwtCacheEviction ->
+      when (logLevel >= LogDebug) $ do
+        logWithZTime loggerState $ observationMessages o
+    o@(JwtCacheLookup _) ->
+      when (logLevel >= LogDebug) $ do
+        logWithZTime loggerState $ observationMessages o
+    o@(WarpServerObs _) ->
+      when (logLevel >= LogDebug) $ do
+        logWithZTime loggerState $ observationMessages o
+    o ->
       logWithZTime loggerState $ observationMessages o
-  o@(QueryObs _ status) -> do
-    when (shouldLogResponse logLevel status) $
-      logWithZTime loggerState $ observationMessages o
-  o@PoolRequest ->
-    when (logLevel >= LogDebug) $ do
-      logWithZTime loggerState $ observationMessages o
-  o@PoolRequestFullfilled ->
-    when (logLevel >= LogDebug) $ do
-      logWithZTime loggerState $ observationMessages o
-  ResponseObs maybeRole req status contentLen ->
-    when (shouldLogResponse logLevel status) $ do
-      zTime <- stateGetZTime loggerState
-      putStr $ apacheFormat maybeRole (BS.pack $ formatZonedTime zTime) req status contentLen -- putStr prints to stdout
-  o@PoolFlushed ->
-    when (logLevel >= LogDebug) $ do
-      logWithZTime loggerState $ observationMessages o
-  o@JwtCacheEviction ->
-    when (logLevel >= LogDebug) $ do
-      logWithZTime loggerState $ observationMessages o
-  o@(JwtCacheLookup _) ->
-    when (logLevel >= LogDebug) $ do
-      logWithZTime loggerState $ observationMessages o
-  o@(WarpServerObs _) ->
-    when (logLevel >= LogDebug) $ do
-      logWithZTime loggerState $ observationMessages o
-  o ->
-    logWithZTime loggerState $ observationMessages o
 
 logWithZTime :: LoggerState -> [Text] -> IO ()
 logWithZTime loggerState txts = do

test/io/configs/sigusr2-settings.config

@@ -3,3 +3,6 @@ db-schemas = "public"
 
 app.settings.name_var = "John"
 jwt-secret = "invalidinvalidinvalidinvalidinvalid"
+
+# will be replaced in test
+log-level = "error"

test/io/test_io.py

@@ -1931,3 +1931,40 @@ def test_use_legacy_target_names(enabled, defaultenv):
         else:
             assert response.status_code == 400
             assert not has_warning_log and not has_hint_log
+
+
+def test_config_log_level_is_reloadable(tmp_path, defaultenv):
+    "Config log-level should be reloadable on SIGUSR2"
+
+    config = (CONFIGSDIR / "sigusr2-settings.config").read_text()
+    configfile = tmp_path / "test.config"
+    configfile.write_text(config)
+
+    # Delete the env variable for "log-level" so the config file value isn't overridden
+    del defaultenv["PGRST_LOG_LEVEL"]
+
+    with run(configfile, env=defaultenv) as postgrest:
+        response = postgrest.session.get("/projects")
+        assert response.status_code == 200
+        output = postgrest.read_stdout(nlines=5)
+
+        # log-level = error, so this log line shouldn't be logged
+        assert not any(
+            "Trying to borrow a connection from pool" in line for line in output
+        )
+
+        # change setting
+        configfile.write_text(
+            config.replace('log-level = "error"', 'log-level = "debug"')
+        )
+        # reload
+        postgrest.process.send_signal(signal.SIGUSR2)
+
+        sleep_until_postgrest_config_reload()
+
+        response = postgrest.session.get("/projects")
+        assert response.status_code == 200
+        output = postgrest.read_stdout(nlines=5)
+
+        # log-level = debug now, so this log line must be logged
+        assert any("Trying to borrow a connection from pool" in line for line in output)

test/observability/Main.hs

@@ -5,6 +5,7 @@ import qualified Hasql.Pool.Config          as P
 import qualified Hasql.Transaction.Sessions as HT
 
 import Data.Function (id)
+import Data.IORef    (newIORef, readIORef)
 
 import           PostgREST.App             (postgrest)
 import qualified PostgREST.AppState        as AppState
@@ -48,14 +49,15 @@ main = do
 
   -- cached schema cache so most tests run fast
   baseSchemaCache <- loadSCache pool testCfg
-  loggerState <- Logger.init
 
   let
     initApp sCache config = do
       -- duplicate poolChan as a starting point
+      confRef <- newIORef config
+      loggerState <- Logger.init (configLogLevel <$> readIORef confRef)
       obsChan <- dupChan poolChan
       stateObsChan <- newObsChan obsChan
-      appState <- AppState.initWithPool pool config loggerState metricsState (Metrics.observationMetrics metricsState <> writeChan obsChan) mempty
+      appState <- AppState.initWithPool pool confRef loggerState metricsState (Metrics.observationMetrics metricsState <> writeChan obsChan) mempty
       AppState.putPgVersion appState actualPgVersion
       AppState.putSchemaCache appState (Just sCache)
       return (SpecState appState metricsState stateObsChan, postgrest appState (pure ()))

test/spec/Main.hs

@@ -5,6 +5,7 @@ import qualified Hasql.Pool.Config          as P
 import qualified Hasql.Transaction.Sessions as HT
 
 import Data.Function (id)
+import Data.IORef    (newIORef, readIORef)
 
 import Test.Hspec
 
@@ -88,12 +89,13 @@ main = do
 
   -- cached schema cache so most tests run fast
   baseSchemaCache <- loadSCache pool baseCfg
-  loggerState <- Logger.init
   metricsState <- Metrics.init (configDbPoolSize baseCfg)
 
   let
     initApp sCache config = do
-      appState <- AppState.initWithPool pool config loggerState metricsState (Metrics.observationMetrics metricsState) mempty
+      confRef <- newIORef config
+      loggerState <- Logger.init (configLogLevel <$> readIORef confRef)
+      appState <- AppState.initWithPool pool confRef loggerState metricsState (Metrics.observationMetrics metricsState) mempty
       AppState.putPgVersion appState actualPgVersion
       AppState.putSchemaCache appState (Just sCache)
       return ((), postgrest appState (pure ()))