on master help sign in
Working sketch of katip internal queueing
commit85eb6dc61618822be529b116860a4bb3acdcd7a8 authorMichael Xavier <michael@michaelxavier.net> dateTue 21 Feb 2017, 10:21 (10 years ago) parent875f475
5 files changed+52−80
katip-elasticsearch/src/Katip/Scribes/ElasticSearch.hs+3−4 katip-elasticsearch/test/Main.hs+11−12 katip/src/Katip/Core.hs+18−22 katip/src/Katip/Scribes/Handle.hs+18−40 katip/test/Katip/Tests/Scribes/Handle.hs+2−2
katip-elasticsearch/src/Katip/Scribes/ElasticSearch.hs+3−4
@@ -261,8 +261,7 @@ mkEsScribe
261261 -> MappingName
262262 -> Severity
263263 -> Verbosity
264− -> IO (Scribe, IO ())
265− -- ^ Returns a finalizer that will gracefully flush all remaining logs before shutting down workers
264+ -> IO Scribe
266265mkEsScribe cfg@EsScribeCfg {..} env ix mapping sev verb = do
267266 q <- newTBMQueueIO $ unEsQueueSize essQueueSize
268267 endSig <- newEmptyMVar
@@ -290,11 +289,11 @@ mkEsScribe cfg@EsScribeCfg {..} env ix mapping sev verb = do
290289 mapM_ waitCatch workers
291290 putMVar endSig ()
292291
293− let scribe = Scribe $ \ i ->
292+ let logger i =
294293 when (_itemSeverity i >= sev) $
295294 void $ atomically $ tryWriteTBMQueue q (chooseIxn ix essIndexSharding i, itemJson' i)
296295 let finalizer = putMVar endSig () >> takeMVar endSig
297− return (scribe, finalizer)
296+ return (Scribe logger finalizer)
298297 where
299298 tplName = TemplateName ixn
300299 shardingEnabled = case essIndexSharding of
katip-elasticsearch/test/Main.hs+11−12
@@ -46,7 +46,7 @@ main = defaultMain $ testGroup "katip-elasticsearch"
4646
4747
4848-------------------------------------------------------------------------------
49−setupSearch :: (EsScribeCfg -> EsScribeCfg) -> IO (Scribe, IO ())
49+setupSearch :: (EsScribeCfg -> EsScribeCfg) -> IO Scribe
5050setupSearch modScribeCfg = do
5151 bh dropESSchema
5252 mgr <- newManager defaultManagerSettings
@@ -58,22 +58,21 @@ setupSearch modScribeCfg = do
5858
5959
6060-------------------------------------------------------------------------------
61−teardownSearch :: (Scribe, IO ()) -> IO ()
62−teardownSearch (_, finalizer) = do
63− finalizer
61+teardownSearch :: IO ()
62+teardownSearch = do
6463 bh $ do
6564 when False $ dropESSchema
66− when False $ dropESSTemplate --TODO: drop
65+ when False $ dropESSTemplate
6766
6867
6968-------------------------------------------------------------------------------
70−withSearch :: (IO (Scribe, IO ()) -> TestTree) -> TestTree
69+withSearch :: (IO Scribe -> TestTree) -> TestTree
7170withSearch = withSearch' id
7271
7372
7473-------------------------------------------------------------------------------
75−withSearch' :: (EsScribeCfg -> EsScribeCfg) -> (IO (Scribe, IO ()) -> TestTree) -> TestTree
76−withSearch' modScribeCfg = withResource (setupSearch modScribeCfg) teardownSearch
74+withSearch' :: (EsScribeCfg -> EsScribeCfg) -> (IO Scribe -> TestTree) -> TestTree
75+withSearch' modScribeCfg = withResource (setupSearch modScribeCfg) (const teardownSearch)
7776
7877
7978-------------------------------------------------------------------------------
@@ -253,20 +252,20 @@ bh = withBH defaultManagerSettings svr
253252
254253-------------------------------------------------------------------------------
255254withTestLogging
256− :: IO (Scribe, IO ()) -> (IO Reply -> KatipT IO b) -> IO b
255+ :: IO Scribe -> (IO Reply -> KatipT IO b) -> IO b
257256withTestLogging = withTestLogging' id
258257
259258
260259-------------------------------------------------------------------------------
261260withTestLogging'
262261 :: (LogEnv -> LogEnv)
263− -> IO (Scribe, IO ())
262+ -> IO Scribe
264263 -> (IO Reply -> KatipT IO b)
265264 -> IO b
266265withTestLogging' modEnv setup f = do
267− (scr, done) <- setup
266+ scr <- setup
268267 le <- modEnv <$> initLogEnv ns env
269− le' <- registerScribe "es" scr (defaultScribeSettings done) le
268+ le' <- registerScribe "es" scr defaultScribeSettings le
270269 let done' = do
271270 _ <- clearScribes le'
272271 bh (refreshIndex ixn)
katip/src/Katip/Core.hs+18−22
@@ -502,26 +502,29 @@ itemJson verb a = toJSON $ a & itemPayload %~ payloadObject verb
502502-- down gracefully before returning. This can be hooked into your
503503-- application's shutdown routine to ensure you never miss any log
504504-- messages on shutdown.
505−newtype Scribe = Scribe {
505+data Scribe = Scribe {
506506 liPush :: forall a. LogItem a => Item a -> IO ()
507+ , scribeFinalizer :: IO ()
508+ -- ^ Provide a *blocking* finalizer to call when your scribe is
509+ -- removed. If this is not relevant to your scribe, return () is
510+ -- fine.
507511 }
508512
509513
510514instance Semigroup Scribe where
511− (Scribe a) <> (Scribe b) = Scribe $ \ item -> do
512− a item
513− b item
515+ (Scribe pushA finA) <> (Scribe pushB finB) =
516+ Scribe (\item -> pushA item >> pushB item) (finA >> finB)
514517
515518
516519instance Monoid Scribe where
517− mempty = Scribe $ const $ return ()
520+ mempty = Scribe (const (return ())) (return ())
518521 mappend = (<>)
519522
520523
521524-------------------------------------------------------------------------------
522525data ScribeHandle = ScribeHandle {
523− shFinalizer :: IO ()
524− , shChan :: UB.InChan WorkerMessage
526+ shScribe :: Scribe
527+ , shChan :: UB.InChan WorkerMessage
525528 }
526529
527530
@@ -597,16 +600,16 @@ registerScribe nm scribe ScribeSettings {..} le = do
597600 void (Async.waitCatch worker)
598601 --TODO: safe exceptions
599602 -- wait for scribe to finish final write
600− scribeFinalizer
603+ scribeFinalizer scribe
601604
602− let sh = ScribeHandle fin inChan
605+ let sh = ScribeHandle (scribe { scribeFinalizer = fin }) inChan
603606 return (le & logEnvScribes %~ M.insert nm sh)
604607
605608
606609-------------------------------------------------------------------------------
607610--TODO: should do some reasonable exception handling in the scribe, don't want to crash the loop
608611spawnScribeWorker :: Scribe -> UB.OutChan WorkerMessage -> IO (Async.Async ())
609−spawnScribeWorker (Scribe write) outChan = Async.async go
612+spawnScribeWorker (Scribe write _) outChan = Async.async go
610613 where
611614 go = do
612615 newCmd <- UB.readChan outChan
@@ -619,22 +622,15 @@ spawnScribeWorker (Scribe write) outChan = Async.async go
619622
620623-------------------------------------------------------------------------------
621624data ScribeSettings = ScribeSettings {
622− scribeFinalizer :: IO ()
623− -- ^ Provide a *blocking* finalizer to call when your scribe is
624− -- removed. If this is not relevant to your scribe, return () is
625− -- fine.
626− , scribeBufferSize :: Int
625+ scribeBufferSize :: Int
627626 }
628627
629628
630629--TODO: standardize on american or british spelling of finali{z,s}er
631−-- | Reasonable defaults for a scribe. No-op finalizer and a buffer
630+-- | Reasonable defaults for a scribe. Buffer
632631-- size of 4096.
633−defaultScribeSettings
634− :: IO ()
635− -- ^ Finalizer
636− -> ScribeSettings
637−defaultScribeSettings fin = ScribeSettings fin 4096
632+defaultScribeSettings :: ScribeSettings
633+defaultScribeSettings = ScribeSettings 4096
638634
639635
640636-------------------------------------------------------------------------------
@@ -647,7 +643,7 @@ unregisterScribe
647643 -> LogEnv
648644 -> IO LogEnv
649645unregisterScribe nm le = do
650− maybe (return ()) shFinalizer (M.lookup nm (_logEnvScribes le))
646+ maybe (return ()) (scribeFinalizer . shScribe) (M.lookup nm (_logEnvScribes le))
651647 return (le & logEnvScribes %~ M.delete nm)
652648
653649
katip/src/Katip/Scribes/Handle.hs+18−40
@@ -3,22 +3,21 @@
33module Katip.Scribes.Handle where
44
55-------------------------------------------------------------------------------
6−import Control.Applicative as A
6+import Control.Applicative as A
7+import Control.Concurrent
8+import Control.Exception (bracket_)
79import Control.Monad
8−import Control.Exception (onException)
910import Data.Aeson
10−import qualified Data.HashMap.Strict as HM
11+import qualified Data.HashMap.Strict as HM
1112import Data.Monoid
12−import Data.Text (Text)
13+import Data.Text (Text)
1314import Data.Text.Lazy.Builder
14−import Data.Text.Lazy.IO as T
15+import Data.Text.Lazy.IO as T
1516import System.IO
16−import System.IO.Unsafe (unsafePerformIO)
17−import qualified Control.Concurrent.Chan.Unagi.Bounded as U
18−import Control.Concurrent.Async
17+import System.IO.Unsafe (unsafePerformIO)
1918-------------------------------------------------------------------------------
2019import Katip.Core
21−import Katip.Format.Time (formatAsLogTime)
20+import Katip.Format.Time (formatAsLogTime)
2221-------------------------------------------------------------------------------
2322
2423
@@ -49,12 +48,6 @@ data ColorStrategy
4948 | ColorIfTerminal
5049 -- ^ Color if output is a terminal
5150
52−-------------------------------------------------------------------------------
53−--TODO: probably drop this stuff since katip does buffering and this isn't doing concurrent writer workers?
54−data WorkerCmd =
55− HNewItem Builder
56− | HPoisonPill
57−
5851-------------------------------------------------------------------------------
5952-- | Logs to a file handle such as stdout, stderr, or a file. Contexts
6053-- and other information will be flattened out into bracketed
@@ -65,33 +58,18 @@ data WorkerCmd =
6558-- > [2016-05-11 21:01:15][MyApp][Info][myhost.example.com][1724][ThreadId 1154][main:Helpers.Logging Helpers/Logging.hs:43:7] Namespace and context are back to normal
6659--
6760-- Returns the newly-created `Scribe` together with a finaliser the user needs to run to perform resource cleanup.
68−mkHandleScribe :: ColorStrategy -> Handle -> Severity -> Verbosity -> IO (Scribe, IO ())
61+mkHandleScribe :: ColorStrategy -> Handle -> Severity -> Verbosity -> IO Scribe
6962mkHandleScribe cs h sev verb = do
70− (inChan, outChan) <- U.newChan 4096
71− worker <- async $ workerLoop outChan
72− flip onException (stopWorker worker inChan) $ do
7363 hSetBuffering h LineBuffering
7464 colorize <- case cs of
7565 ColorIfTerminal -> hIsTerminalDevice h
76− ColorLog b -> return b
77− let scribe = Scribe $ \i ->
78− when (permitItem sev i) $ void (U.tryWriteChan inChan (HNewItem (formatItem colorize verb i)))
79− return (scribe, stopWorker worker inChan)
80−
81− where
82− stopWorker :: Async () -> U.InChan WorkerCmd -> IO ()
83− stopWorker worker inChan = do
84− U.writeChan inChan HPoisonPill
85− void $ waitCatch worker
66+ ColorLog b -> return b
67+ lock <- newMVar ()
68+ let logger i@Item{..} = do
69+ when (permitItem sev i) $ bracket_ (takeMVar lock) (putMVar lock ()) $
70+ T.hPutStrLn h $ toLazyText $ formatItem colorize verb i
71+ return $ Scribe logger (return ()) --TODO: maybe do a hFlush?
8672
87− workerLoop :: U.OutChan WorkerCmd -> IO ()
88− workerLoop outChan = do
89− newCmd <- U.readChan outChan
90− case newCmd of
91− HNewItem b -> do
92− T.hPutStrLn h $ toLazyText b
93− workerLoop outChan
94− HPoisonPill -> return ()
9573
9674-------------------------------------------------------------------------------
9775formatItem :: LogItem a => Bool -> Verbosity -> Item a -> Builder
@@ -114,7 +92,7 @@ formatItem withColor verb Item{..} =
11492 CriticalS -> red $ renderSeverity s
11593 ErrorS -> red $ renderSeverity s
11694 WarningS -> yellow $ renderSeverity s
117− _ -> renderSeverity s
95+ _ -> renderSeverity s
11896 red = colorize "31"
11997 yellow = colorize "33"
12098 colorize c s
@@ -128,8 +106,8 @@ formatItem withColor verb Item{..} =
128106_ioLogEnv :: LogEnv
129107_ioLogEnv = unsafePerformIO $ do
130108 le <- initLogEnv "io" "io"
131− (lh, finalizer) <- mkHandleScribe ColorIfTerminal stdout DebugS V3
132− registerScribe "stdout" lh (defaultScribeSettings finalizer) le
109+ lh <- mkHandleScribe ColorIfTerminal stdout DebugS V3
110+ registerScribe "stdout" lh defaultScribeSettings le
133111{-# NOINLINE _ioLogEnv #-}
134112
135113
katip/test/Katip/Tests/Scribes/Handle.hs+2−2
@@ -78,9 +78,9 @@ setup :: IO (FilePath, Handle, IO (), LogEnv)
7878setup = do
7979 tempDir <- getTemporaryDirectory
8080 (fp, h) <- openTempFile tempDir "katip.log"
81− (s, finaliser) <- mkHandleScribe (ColorLog False) h DebugS V3
81+ s <- mkHandleScribe (ColorLog False) h DebugS V3
8282 le <- initLogEnv "katip-test" "test"
83− le' <- registerScribe "handle" s (defaultScribeSettings finaliser) le
83+ le' <- registerScribe "handle" s defaultScribeSettings le
8484 return (fp, h, void (clearScribes le'), le')
8585
8686