Michal KleczekandGitHub
77ff11de95
Changes: 1. Refactoring and some cleanup of JWT handling code: * Instead of caching AuthResult cache decoded claims (which signature was verified). Validating claims and determining role is done after cache lookup * Cleaned up API so that usage of it is simplified: lookupJwtCache cache key >>= parseClaims configJwtAud time * Handling of JwtCacheState initialization and updates of configuration is encapsulated in Auth.JwtCache module 2. Generic high performance (hopefully) scalable, dynamically resizeable cache implementation based on stm, stm-hamt and sieve algorithm. It also integrates with PostgREST measurements infrastructure providing usage stats (ie. hit ratio, evictions count)
116 lines
4.2 KiB
Haskell
116 lines
4.2 KiB
Haskell
{-|
|
|
Module : PostgREST.Logger
|
|
Description : Logging based on the Observation.hs module. Access logs get sent to stdout and server diagnostic get sent to stderr.
|
|
-}
|
|
-- TODO log with buffering enabled to not lose throughput on logging levels higher than LogError
|
|
module PostgREST.Logger
|
|
( middleware
|
|
, observationLogger
|
|
, init
|
|
, LoggerState
|
|
) where
|
|
|
|
import Control.AutoUpdate (defaultUpdateSettings,
|
|
mkAutoUpdate, updateAction)
|
|
import Control.Debounce
|
|
import qualified Data.ByteString.Char8 as BS
|
|
|
|
import Data.Time (ZonedTime, defaultTimeLocale, formatTime,
|
|
getZonedTime)
|
|
|
|
import qualified Network.Wai as Wai
|
|
import qualified Network.Wai.Middleware.RequestLogger as Wai
|
|
|
|
import Network.HTTP.Types.Status (Status, status400, status500)
|
|
import System.IO.Unsafe (unsafePerformIO)
|
|
|
|
import PostgREST.Config (LogLevel (..))
|
|
import PostgREST.Observation
|
|
|
|
import Protolude
|
|
|
|
data LoggerState = LoggerState
|
|
{ stateGetZTime :: IO ZonedTime -- ^ Time with time zone used for logs
|
|
, stateLogDebouncePoolTimeout :: MVar (IO ()) -- ^ Logs with a debounce
|
|
}
|
|
|
|
init :: IO LoggerState
|
|
init = do
|
|
zTime <- mkAutoUpdate defaultUpdateSettings { updateAction = getZonedTime }
|
|
LoggerState zTime <$> newEmptyMVar
|
|
|
|
logWithDebounce :: LoggerState -> IO () -> IO ()
|
|
logWithDebounce loggerState action = do
|
|
debouncer <- tryReadMVar $ stateLogDebouncePoolTimeout loggerState
|
|
case debouncer of
|
|
Just d -> d
|
|
Nothing -> do
|
|
newDebouncer <-
|
|
let oneSecond = 1000000 in
|
|
mkDebounce defaultDebounceSettings
|
|
{ debounceAction = action
|
|
, debounceFreq = 5*oneSecond
|
|
, debounceEdge = leadingEdge -- logs at the start and the end
|
|
}
|
|
putMVar (stateLogDebouncePoolTimeout loggerState) newDebouncer
|
|
newDebouncer
|
|
|
|
-- TODO stop using this middleware to reuse the same "observer" pattern for all our logs
|
|
middleware :: LogLevel -> (Wai.Request -> Maybe BS.ByteString) -> Wai.Middleware
|
|
middleware logLevel getAuthRole =
|
|
unsafePerformIO $
|
|
Wai.mkRequestLogger Wai.defaultRequestLoggerSettings
|
|
{ Wai.outputFormat =
|
|
Wai.ApacheWithSettings $
|
|
Wai.defaultApacheSettings &
|
|
Wai.setApacheRequestFilter (\_ res -> shouldLogResponse logLevel $ Wai.responseStatus res) &
|
|
Wai.setApacheUserGetter getAuthRole
|
|
, Wai.autoFlush = True
|
|
, Wai.destination = Wai.Handle stdout
|
|
}
|
|
|
|
shouldLogResponse :: LogLevel -> Status -> Bool
|
|
shouldLogResponse logLevel = case logLevel of
|
|
LogCrit -> const False
|
|
LogError -> (>= status500)
|
|
LogWarn -> (>= status400)
|
|
LogInfo -> const True
|
|
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
|
|
o@(PoolAcqTimeoutObs _) -> do
|
|
when (logLevel >= LogError) $ do
|
|
logWithDebounce loggerState $
|
|
logWithZTime loggerState $ observationMessage o
|
|
o@(QueryErrorCodeHighObs _) -> do
|
|
when (logLevel >= LogError) $ do
|
|
logWithZTime loggerState $ observationMessage o
|
|
o@(HasqlPoolObs _) -> do
|
|
when (logLevel >= LogDebug) $ do
|
|
logWithZTime loggerState $ observationMessage o
|
|
o@(DBQuery sql status) -> do
|
|
-- Does not log SQL when it's empty (for OPTIONS requests or for the default OpenAPI output)
|
|
when (sql /= mempty && shouldLogResponse logLevel status) $ do
|
|
logWithZTime loggerState $ observationMessage o
|
|
o@PoolRequest ->
|
|
when (logLevel >= LogDebug) $ do
|
|
logWithZTime loggerState $ observationMessage o
|
|
o@PoolRequestFullfilled ->
|
|
when (logLevel >= LogDebug) $ do
|
|
logWithZTime loggerState $ observationMessage o
|
|
o@JwtCacheEviction ->
|
|
when (logLevel >= LogDebug) $ do
|
|
logWithZTime loggerState $ observationMessage o
|
|
o@(JwtCacheLookup _) ->
|
|
when (logLevel >= LogDebug) $ do
|
|
logWithZTime loggerState $ observationMessage o
|
|
o ->
|
|
logWithZTime loggerState $ observationMessage o
|
|
|
|
logWithZTime :: LoggerState -> Text -> IO ()
|
|
logWithZTime loggerState txt = do
|
|
zTime <- stateGetZTime loggerState
|
|
hPutStrLn stderr $ toS (formatTime defaultTimeLocale "%d/%b/%Y:%T %z: " zTime) <> txt
|