From 2944cf94c7cd78ea8ab691b1b6f1bdff7be25503 Mon Sep 17 00:00:00 2001 From: Steve Chavez Date: Sat, 19 Jun 2021 15:55:18 -0500 Subject: [PATCH] feat: Add time to startup/worker logs (#1872) BREAKING CHANGE Sends startup/worker logs to stderr to differentiate them from access logs, which go to stdout --- main/Main.hs | 3 +- src/PostgREST/App.hs | 5 ++-- src/PostgREST/AppState.hs | 17 +++++++++-- src/PostgREST/Config/Database.hs | 19 ++++-------- src/PostgREST/Unix.hs | 1 - src/PostgREST/Workers.hs | 51 ++++++++++++++++++-------------- test/io-tests/test_io.py | 4 +++ 7 files changed, 57 insertions(+), 43 deletions(-) diff --git a/main/Main.hs b/main/Main.hs index 15abf009c..d9d39373a 100644 --- a/main/Main.hs +++ b/main/Main.hs @@ -44,5 +44,4 @@ setBuffering = do -- output, the buffer overflows, a hFlush is issued or the handle is closed hSetBuffering stdout LineBuffering hSetBuffering stdin LineBuffering - -- NoBuffering: output is written immediately and never stored in the buffer - hSetBuffering stderr NoBuffering + hSetBuffering stderr LineBuffering diff --git a/src/PostgREST/App.hs b/src/PostgREST/App.hs index 74ca6168c..87b82c5ee 100644 --- a/src/PostgREST/App.hs +++ b/src/PostgREST/App.hs @@ -116,13 +116,14 @@ run installHandlers maybeRunWithSocket appState = do Just socket -> -- run the postgrest application with user defined socket. Only for UNIX systems case maybeRunWithSocket of - Just runWithSocket -> + Just runWithSocket -> do + AppState.logWithZTime appState $ "Listening on unix socket " <> show socket runWithSocket (serverSettings conf) app configServerUnixSocketMode socket Nothing -> panic "Cannot run with socket on non-unix plattforms." Nothing -> do - putStrLn $ ("Listening on port " :: Text) <> show configServerPort + AppState.logWithZTime appState $ "Listening on port " <> show configServerPort Warp.runSettings (serverSettings conf) app serverSettings :: AppConfig -> Warp.Settings diff --git a/src/PostgREST/AppState.hs b/src/PostgREST/AppState.hs index fa021dd28..bc9da187e 100644 --- a/src/PostgREST/AppState.hs +++ b/src/PostgREST/AppState.hs @@ -12,6 +12,7 @@ module PostgREST.AppState , getTime , init , initWithPool + , logWithZTime , putConfig , putDbStructure , putIsWorkerOn @@ -28,6 +29,8 @@ import Control.AutoUpdate (defaultUpdateSettings, mkAutoUpdate, updateAction) import Data.IORef (IORef, atomicWriteIORef, newIORef, readIORef) +import Data.Time (ZonedTime, defaultTimeLocale, formatTime, + getZonedTime) import Data.Time.Clock (UTCTime, getCurrentTime) import PostgREST.Config (AppConfig (..)) @@ -51,7 +54,11 @@ data AppState = AppState , stateListener :: MVar () -- | Config that can change at runtime , stateConf :: IORef AppConfig + -- | Time used for verifying JWT expiration , stateGetTime :: IO UTCTime + -- | Time with time zone used for worker logs + , stateGetZTime :: IO ZonedTime + -- | Used for killing the main thread in case a subthread fails , stateMainThreadId :: ThreadId } @@ -63,14 +70,14 @@ init conf = do initWithPool :: P.Pool -> AppConfig -> IO AppState initWithPool newPool conf = AppState newPool - -- assume we're in a supported version when starting, this will be corrected on a later step - <$> newIORef minimumPgVersion + <$> newIORef minimumPgVersion -- assume we're in a supported version when starting, this will be corrected on a later step <*> newIORef Nothing <*> newIORef mempty <*> newIORef False <*> newEmptyMVar <*> newIORef conf <*> mkAutoUpdate defaultUpdateSettings { updateAction = getCurrentTime } + <*> mkAutoUpdate defaultUpdateSettings { updateAction = getZonedTime } <*> myThreadId initPool :: AppConfig -> IO P.Pool @@ -117,6 +124,12 @@ putConfig = atomicWriteIORef . stateConf getTime :: AppState -> IO UTCTime getTime = stateGetTime +-- | Log to stderr with local time +logWithZTime :: AppState -> Text -> IO () +logWithZTime appState txt = do + zTime <- stateGetZTime appState + hPutStrLn stderr $ toS (formatTime defaultTimeLocale "%d/%b/%Y:%T %z: " zTime) <> txt + getMainThreadId :: AppState -> ThreadId getMainThreadId = stateMainThreadId diff --git a/src/PostgREST/Config/Database.hs b/src/PostgREST/Config/Database.hs index 5cb208760..24cc3d47a 100644 --- a/src/PostgREST/Config/Database.hs +++ b/src/PostgREST/Config/Database.hs @@ -15,10 +15,9 @@ import qualified Hasql.Statement as H import qualified Hasql.Transaction as HT import qualified Hasql.Transaction.Sessions as HT -import Data.Text.IO (hPutStrLn) import Text.InterpolatedString.Perl6 (q) -import Protolude hiding (hPutStrLn) +import Protolude queryPgVersion :: H.Session PgVersion queryPgVersion = H.statement mempty $ H.Statement sql HE.noParams versionRow False @@ -26,18 +25,10 @@ queryPgVersion = H.statement mempty $ H.Statement sql HE.noParams versionRow Fal sql = "SELECT current_setting('server_version_num')::integer, current_setting('server_version')" versionRow = HD.singleRow $ PgVersion <$> column HD.int4 <*> column HD.text -queryDbSettings :: P.Pool -> IO [(Text, Text)] -queryDbSettings pool = do - result <- - P.use pool . HT.transaction HT.ReadCommitted HT.Read $ - HT.statement mempty dbSettingsStatement - case result of - Left e -> do - hPutStrLn stderr $ - "An error ocurred when trying to query database settings for the config parameters:\n" - <> show e - pure [] - Right x -> pure x +queryDbSettings :: P.Pool -> IO (Either P.UsageError [(Text, Text)]) +queryDbSettings pool = + P.use pool . HT.transaction HT.ReadCommitted HT.Read $ + HT.statement mempty dbSettingsStatement -- | Get db settings from the connection role. Global settings will be overridden by database specific settings. dbSettingsStatement :: H.Statement () [(Text, Text)] diff --git a/src/PostgREST/Unix.hs b/src/PostgREST/Unix.hs index 86d42bacc..e003ccb24 100644 --- a/src/PostgREST/Unix.hs +++ b/src/PostgREST/Unix.hs @@ -23,7 +23,6 @@ import Protolude runAppWithSocket :: Warp.Settings -> Application -> FileMode -> FilePath -> IO () runAppWithSocket settings app socketFileMode socketFilePath = bracket createAndBindSocket Socket.close $ \socket -> do - putStrLn $ ("Listening on unix socket " :: Text) <> show socketFilePath Socket.listen socket Socket.maxListenQueue Warp.runSettingsSocket settings socket app where diff --git a/src/PostgREST/Workers.hs b/src/PostgREST/Workers.hs index cae6e8b37..a298244fe 100644 --- a/src/PostgREST/Workers.hs +++ b/src/PostgREST/Workers.hs @@ -16,7 +16,6 @@ import qualified Hasql.Transaction.Sessions as HT import Control.Retry (RetryStatus, capDelay, exponentialBackoff, retrying, rsPreviousDelay) -import Data.Text.IO (hPutStrLn) import PostgREST.AppState (AppState) import PostgREST.Config (AppConfig (..), readAppConfig) @@ -28,7 +27,7 @@ import PostgREST.Error (PgError (PgError), checkIsFatal, import qualified PostgREST.AppState as AppState -import Protolude hiding (hPutStrLn, head, toS) +import Protolude hiding (head, toS) import Protolude.Conv (toS) @@ -67,12 +66,12 @@ connectionWorker appState = do where work = do AppConfig{..} <- AppState.getConfig appState - putStrLn ("Attempting to connect to the database..." :: Text) - connected <- connectionStatus $ AppState.getPool appState + AppState.logWithZTime appState "Attempting to connect to the database..." + connected <- connectionStatus appState case connected of FatalConnectionError reason -> -- Fatal error when connecting - hPutStrLn stderr reason >> killThread (AppState.getMainThreadId appState) + AppState.logWithZTime appState reason >> killThread (AppState.getMainThreadId appState) NotConnected -> -- Unreachable because connectionStatus will keep trying to connect return () @@ -81,7 +80,7 @@ connectionWorker appState = do AppState.putPgVersion appState actualPgVersion when configDbChannelEnabled $ AppState.signalListener appState - putStrLn ("Connection successful" :: Text) + AppState.logWithZTime appState "Connection successful" -- this could be fail because the connection drops, but the -- loadSchemaCache will pick the error and retry again when configDbConfig $ reReadConfig False appState @@ -106,11 +105,12 @@ connectionWorker appState = do -- -- The connection tries are capped, but if the connection times out no error is -- thrown, just 'False' is returned. -connectionStatus :: P.Pool -> IO ConnectionStatus -connectionStatus pool = +connectionStatus :: AppState -> IO ConnectionStatus +connectionStatus appState = retrying retrySettings shouldRetry $ const $ P.release pool >> getConnectionStatus where + pool = AppState.getPool appState retrySettings = capDelay delayMicroseconds $ exponentialBackoff backoffMicroseconds delayMicroseconds = 32000000 -- 32 seconds backoffMicroseconds = 1000000 -- 1 second @@ -121,7 +121,7 @@ connectionStatus pool = case pgVersion of Left e -> do let err = PgError False e - hPutStrLn stderr . toS $ errorPayload err + AppState.logWithZTime appState . toS $ errorPayload err case checkIsFatal err of Just reason -> return $ FatalConnectionError reason @@ -140,7 +140,7 @@ connectionStatus pool = let delay = fromMaybe 0 (rsPreviousDelay rs) `div` backoffMicroseconds itShould = NotConnected == isConnSucc - when itShould . putStrLn $ + when itShould . AppState.logWithZTime appState $ "Attempting to reconnect to the database in " <> (show delay::Text) <> " seconds..." @@ -157,17 +157,17 @@ loadSchemaCache appState = do Left e -> do let err = PgError False e - putErr = hPutStrLn stderr . toS . errorPayload $ err + putErr = AppState.logWithZTime appState . toS $ errorPayload err case checkIsFatal err of Just _ -> do - hPutStrLn stderr "A fatal error ocurred when loading the schema cache" + AppState.logWithZTime appState "A fatal error ocurred when loading the schema cache" putErr - hPutStrLn stderr $ + AppState.logWithZTime appState $ "This is probably a bug in PostgREST, please report it at " <> "https://github.com/PostgREST/postgrest/issues" return SCFatalFail Nothing -> do - hPutStrLn stderr "An error ocurred when loading the schema cache" + AppState.logWithZTime appState "An error ocurred when loading the schema cache" putErr return SCOnRetry @@ -175,7 +175,7 @@ loadSchemaCache appState = do AppState.putDbStructure appState dbStructure when (isJust configDbRootSpec) $ AppState.putJsonDbS appState $ toS $ JSON.encode dbStructure - putStrLn ("Schema cache loaded" :: Text) + AppState.logWithZTime appState "Schema cache loaded" return SCLoaded -- | Starts a dedicated pg connection to LISTEN for notifications. When a @@ -189,7 +189,7 @@ listener appState = do -- The listener has to wait for a signal from the connectionWorker. -- This is because when the connection to the db is lost, the listener also -- tries to recover the connection, but not with the same pace as the connectionWorker. - -- Not waiting makes stdout quickly fill with connection retries messages from the listener. + -- Not waiting makes stderr quickly fill with connection retries messages from the listener. AppState.waitListener appState -- forkFinally allows to detect if the thread dies @@ -197,7 +197,7 @@ listener appState = do dbOrError <- C.acquire $ toS configDbUri case dbOrError of Right db -> do - putStrLn $ "Listening for notifications on the " <> dbChannel <> " channel" + AppState.logWithZTime appState $ "Listening for notifications on the " <> dbChannel <> " channel" N.listen db $ N.toPgIdentifier dbChannel N.waitForNotifications handleNotification db _ -> @@ -205,7 +205,7 @@ listener appState = do where handleFinally dbChannel _ = do -- if the thread dies, we try to recover - putStrLn $ "Retrying listening for notifications on the " <> dbChannel <> " channel.." + AppState.logWithZTime appState $ "Retrying listening for notifications on the " <> dbChannel <> " channel.." -- assume the pool connection was also lost, call the connection worker connectionWorker appState -- retry the listener @@ -228,8 +228,15 @@ reReadConfig :: Bool -> AppState -> IO () reReadConfig startingUp appState = do AppConfig{..} <- AppState.getConfig appState dbSettings <- - if configDbConfig then - queryDbSettings (AppState.getPool appState) + if configDbConfig then do + qDbSettings <- queryDbSettings $ AppState.getPool appState + case qDbSettings of + Left e -> do + AppState.logWithZTime appState $ + "An error ocurred when trying to query database settings for the config parameters:\n" + <> show e + pure [] + Right x -> pure x else pure mempty readAppConfig dbSettings configFilePath (Just configDbUri) >>= \case @@ -237,10 +244,10 @@ reReadConfig startingUp appState = do if startingUp then panic err -- die on invalid config if the program is starting up else - hPutStrLn stderr $ "Failed re-loading config: " <> err + AppState.logWithZTime appState $ "Failed re-loading config: " <> err Right newConf -> do AppState.putConfig appState newConf if startingUp then pass else - putStrLn ("Config re-loaded" :: Text) + AppState.logWithZTime appState "Config re-loaded" diff --git a/test/io-tests/test_io.py b/test/io-tests/test_io.py index 5aa18b436..15be81b08 100644 --- a/test/io-tests/test_io.py +++ b/test/io-tests/test_io.py @@ -684,6 +684,10 @@ def test_invalid_role_claim_key_notify_reload(defaultenv): with run(env=env) as postgrest: postgrest.session.post("/rpc/invalid_role_claim_key_reload") + # skips the first lines from stderr, the "Attempting to connect to database", "Connection successful", etc. + # this is a hack to avoid readline() from locking up the test + for _ in range(6): + postgrest.process.stderr.readline() assert "failed to parse role-claim-key value" in str( postgrest.process.stderr.readline() )