on master help sign in
Working sketch of katip internal queueing
85eb6dcMichael Xavier
katip-elasticsearch/src/Katip/Scribes/ElasticSearch.hs+3−4
@@ -261,8 +261,7 @@ mkEsScribe
261 -> MappingName
261 -> MappingName
262 -> Severity
262 -> Severity
263 -> Verbosity
263 -> Verbosity
264− -> IO (Scribe, IO ())
264+ -> IO Scribe
265− -- ^ Returns a finalizer that will gracefully flush all remaining logs before shutting down workers
266mkEsScribe cfg@EsScribeCfg {..} env ix mapping sev verb = do
265mkEsScribe cfg@EsScribeCfg {..} env ix mapping sev verb = do
267 q <- newTBMQueueIO $ unEsQueueSize essQueueSize
266 q <- newTBMQueueIO $ unEsQueueSize essQueueSize
268 endSig <- newEmptyMVar
267 endSig <- newEmptyMVar
@@ -290,11 +289,11 @@ mkEsScribe cfg@EsScribeCfg {..} env ix mapping sev verb = do
290 mapM_ waitCatch workers
289 mapM_ waitCatch workers
291 putMVar endSig ()
290 putMVar endSig ()
292
291
293− let scribe = Scribe $ \ i ->
292+ let logger i =
294 when (_itemSeverity i >= sev) $
293 when (_itemSeverity i >= sev) $
295 void $ atomically $ tryWriteTBMQueue q (chooseIxn ix essIndexSharding i, itemJson' i)
294 void $ atomically $ tryWriteTBMQueue q (chooseIxn ix essIndexSharding i, itemJson' i)
296 let finalizer = putMVar endSig () >> takeMVar endSig
295 let finalizer = putMVar endSig () >> takeMVar endSig
297− return (scribe, finalizer)
296+ return (Scribe logger finalizer)
298 where
297 where
299 tplName = TemplateName ixn
298 tplName = TemplateName ixn
300 shardingEnabled = case essIndexSharding of
299 shardingEnabled = case essIndexSharding of
katip-elasticsearch/test/Main.hs+11−12
@@ -46,7 +46,7 @@ main = defaultMain $ testGroup "katip-elasticsearch"
46
46
47
47
48-------------------------------------------------------------------------------
48-------------------------------------------------------------------------------
49−setupSearch :: (EsScribeCfg -> EsScribeCfg) -> IO (Scribe, IO ())
49+setupSearch :: (EsScribeCfg -> EsScribeCfg) -> IO Scribe
50setupSearch modScribeCfg = do
50setupSearch modScribeCfg = do
51 bh dropESSchema
51 bh dropESSchema
52 mgr <- newManager defaultManagerSettings
52 mgr <- newManager defaultManagerSettings
@@ -58,22 +58,21 @@ setupSearch modScribeCfg = do
58
58
59
59
60-------------------------------------------------------------------------------
60-------------------------------------------------------------------------------
61−teardownSearch :: (Scribe, IO ()) -> IO ()
61+teardownSearch :: IO ()
62−teardownSearch (_, finalizer) = do
62+teardownSearch = do
63− finalizer
64 bh $ do
63 bh $ do
65 when False $ dropESSchema
64 when False $ dropESSchema
66− when False $ dropESSTemplate --TODO: drop
65+ when False $ dropESSTemplate
67
66
68
67
69-------------------------------------------------------------------------------
68-------------------------------------------------------------------------------
70−withSearch :: (IO (Scribe, IO ()) -> TestTree) -> TestTree
69+withSearch :: (IO Scribe -> TestTree) -> TestTree
71withSearch = withSearch' id
70withSearch = withSearch' id
72
71
73
72
74-------------------------------------------------------------------------------
73-------------------------------------------------------------------------------
75−withSearch' :: (EsScribeCfg -> EsScribeCfg) -> (IO (Scribe, IO ()) -> TestTree) -> TestTree
74+withSearch' :: (EsScribeCfg -> EsScribeCfg) -> (IO Scribe -> TestTree) -> TestTree
76−withSearch' modScribeCfg = withResource (setupSearch modScribeCfg) teardownSearch
75+withSearch' modScribeCfg = withResource (setupSearch modScribeCfg) (const teardownSearch)
77
76
78
77
79-------------------------------------------------------------------------------
78-------------------------------------------------------------------------------
@@ -253,20 +252,20 @@ bh = withBH defaultManagerSettings svr
253
252
254-------------------------------------------------------------------------------
253-------------------------------------------------------------------------------
255withTestLogging
254withTestLogging
256− :: IO (Scribe, IO ()) -> (IO Reply -> KatipT IO b) -> IO b
255+ :: IO Scribe -> (IO Reply -> KatipT IO b) -> IO b
257withTestLogging = withTestLogging' id
256withTestLogging = withTestLogging' id
258
257
259
258
260-------------------------------------------------------------------------------
259-------------------------------------------------------------------------------
261withTestLogging'
260withTestLogging'
262 :: (LogEnv -> LogEnv)
261 :: (LogEnv -> LogEnv)
263− -> IO (Scribe, IO ())
262+ -> IO Scribe
264 -> (IO Reply -> KatipT IO b)
263 -> (IO Reply -> KatipT IO b)
265 -> IO b
264 -> IO b
266withTestLogging' modEnv setup f = do
265withTestLogging' modEnv setup f = do
267− (scr, done) <- setup
266+ scr <- setup
268 le <- modEnv <$> initLogEnv ns env
267 le <- modEnv <$> initLogEnv ns env
269− le' <- registerScribe "es" scr (defaultScribeSettings done) le
268+ le' <- registerScribe "es" scr defaultScribeSettings le
270 let done' = do
269 let done' = do
271 _ <- clearScribes le'
270 _ <- clearScribes le'
272 bh (refreshIndex ixn)
271 bh (refreshIndex ixn)
katip/src/Katip/Core.hs+18−22
@@ -502,26 +502,29 @@ itemJson verb a = toJSON $ a & itemPayload %~ payloadObject verb
502-- down gracefully before returning. This can be hooked into your
502-- down gracefully before returning. This can be hooked into your
503-- application's shutdown routine to ensure you never miss any log
503-- application's shutdown routine to ensure you never miss any log
504-- messages on shutdown.
504-- messages on shutdown.
505−newtype Scribe = Scribe {
505+data Scribe = Scribe {
506 liPush :: forall a. LogItem a => Item a -> IO ()
506 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.
507 }
511 }
508
512
509
513
510instance Semigroup Scribe where
514instance Semigroup Scribe where
511− (Scribe a) <> (Scribe b) = Scribe $ \ item -> do
515+ (Scribe pushA finA) <> (Scribe pushB finB) =
512− a item
516+ Scribe (\item -> pushA item >> pushB item) (finA >> finB)
513− b item
514
517
515
518
516instance Monoid Scribe where
519instance Monoid Scribe where
517− mempty = Scribe $ const $ return ()
520+ mempty = Scribe (const (return ())) (return ())
518 mappend = (<>)
521 mappend = (<>)
519
522
520
523
521-------------------------------------------------------------------------------
524-------------------------------------------------------------------------------
522data ScribeHandle = ScribeHandle {
525data ScribeHandle = ScribeHandle {
523− shFinalizer :: IO ()
526+ shScribe :: Scribe
524− , shChan :: UB.InChan WorkerMessage
527+ , shChan :: UB.InChan WorkerMessage
525 }
528 }
526
529
527
530
@@ -597,16 +600,16 @@ registerScribe nm scribe ScribeSettings {..} le = do
597 void (Async.waitCatch worker)
600 void (Async.waitCatch worker)
598 --TODO: safe exceptions
601 --TODO: safe exceptions
599 -- wait for scribe to finish final write
602 -- wait for scribe to finish final write
600− scribeFinalizer
603+ scribeFinalizer scribe
601
604
602− let sh = ScribeHandle fin inChan
605+ let sh = ScribeHandle (scribe { scribeFinalizer = fin }) inChan
603 return (le & logEnvScribes %~ M.insert nm sh)
606 return (le & logEnvScribes %~ M.insert nm sh)
604
607
605
608
606-------------------------------------------------------------------------------
609-------------------------------------------------------------------------------
607--TODO: should do some reasonable exception handling in the scribe, don't want to crash the loop
610--TODO: should do some reasonable exception handling in the scribe, don't want to crash the loop
608spawnScribeWorker :: Scribe -> UB.OutChan WorkerMessage -> IO (Async.Async ())
611spawnScribeWorker :: Scribe -> UB.OutChan WorkerMessage -> IO (Async.Async ())
609−spawnScribeWorker (Scribe write) outChan = Async.async go
612+spawnScribeWorker (Scribe write _) outChan = Async.async go
610 where
613 where
611 go = do
614 go = do
612 newCmd <- UB.readChan outChan
615 newCmd <- UB.readChan outChan
@@ -619,22 +622,15 @@ spawnScribeWorker (Scribe write) outChan = Async.async go
619
622
620-------------------------------------------------------------------------------
623-------------------------------------------------------------------------------
621data ScribeSettings = ScribeSettings {
624data 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
627 }
626 }
628
627
629
628
630--TODO: standardize on american or british spelling of finali{z,s}er
629--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
632-- size of 4096.
631-- size of 4096.
633−defaultScribeSettings
632+defaultScribeSettings :: ScribeSettings
634− :: IO ()
635− -- ^ Finalizer
636− -> ScribeSettings
637−defaultScribeSettings fin = ScribeSettings fin 4096
633+defaultScribeSettings = ScribeSettings 4096
638
634
639
635
640-------------------------------------------------------------------------------
636-------------------------------------------------------------------------------
@@ -647,7 +643,7 @@ unregisterScribe
647 -> LogEnv
643 -> LogEnv
648 -> IO LogEnv
644 -> IO LogEnv
649unregisterScribe nm le = do
645unregisterScribe nm le = do
650− maybe (return ()) shFinalizer (M.lookup nm (_logEnvScribes le))
646+ maybe (return ()) (scribeFinalizer . shScribe) (M.lookup nm (_logEnvScribes le))
651 return (le & logEnvScribes %~ M.delete nm)
647 return (le & logEnvScribes %~ M.delete nm)
652
648
653
649
katip/src/Katip/Scribes/Handle.hs+18−40
@@ -3,22 +3,21 @@
3module Katip.Scribes.Handle where
3module Katip.Scribes.Handle where
4
4
5-------------------------------------------------------------------------------
5-------------------------------------------------------------------------------
6−import Control.Applicative as A
6+import Control.Applicative as A
7+import Control.Concurrent
8+import Control.Exception (bracket_)
7import Control.Monad
9import Control.Monad
8−import Control.Exception (onException)
9import Data.Aeson
10import Data.Aeson
10−import qualified Data.HashMap.Strict as HM
11+import qualified Data.HashMap.Strict as HM
11import Data.Monoid
12import Data.Monoid
12−import Data.Text (Text)
13+import Data.Text (Text)
13import Data.Text.Lazy.Builder
14import Data.Text.Lazy.Builder
14−import Data.Text.Lazy.IO as T
15+import Data.Text.Lazy.IO as T
15import System.IO
16import System.IO
16−import System.IO.Unsafe (unsafePerformIO)
17+import System.IO.Unsafe (unsafePerformIO)
17−import qualified Control.Concurrent.Chan.Unagi.Bounded as U
18−import Control.Concurrent.Async
19-------------------------------------------------------------------------------
18-------------------------------------------------------------------------------
20import Katip.Core
19import Katip.Core
21−import Katip.Format.Time (formatAsLogTime)
20+import Katip.Format.Time (formatAsLogTime)
22-------------------------------------------------------------------------------
21-------------------------------------------------------------------------------
23
22
24
23
@@ -49,12 +48,6 @@ data ColorStrategy
49 | ColorIfTerminal
48 | ColorIfTerminal
50 -- ^ Color if output is a terminal
49 -- ^ Color if output is a terminal
51
50
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−
58-------------------------------------------------------------------------------
51-------------------------------------------------------------------------------
59-- | Logs to a file handle such as stdout, stderr, or a file. Contexts
52-- | Logs to a file handle such as stdout, stderr, or a file. Contexts
60-- and other information will be flattened out into bracketed
53-- and other information will be flattened out into bracketed
@@ -65,33 +58,18 @@ data WorkerCmd =
65-- > [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
58-- > [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
66--
59--
67-- Returns the newly-created `Scribe` together with a finaliser the user needs to run to perform resource cleanup.
60-- 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
69mkHandleScribe cs h sev verb = do
62mkHandleScribe cs h sev verb = do
70− (inChan, outChan) <- U.newChan 4096
71− worker <- async $ workerLoop outChan
72− flip onException (stopWorker worker inChan) $ do
73 hSetBuffering h LineBuffering
63 hSetBuffering h LineBuffering
74 colorize <- case cs of
64 colorize <- case cs of
75 ColorIfTerminal -> hIsTerminalDevice h
65 ColorIfTerminal -> hIsTerminalDevice h
76− ColorLog b -> return b
66+ ColorLog b -> return b
77− let scribe = Scribe $ \i ->
67+ lock <- newMVar ()
78− when (permitItem sev i) $ void (U.tryWriteChan inChan (HNewItem (formatItem colorize verb i)))
68+ let logger i@Item{..} = do
79− return (scribe, stopWorker worker inChan)
69+ when (permitItem sev i) $ bracket_ (takeMVar lock) (putMVar lock ()) $
80−
70+ T.hPutStrLn h $ toLazyText $ formatItem colorize verb i
81− where
71+ return $ Scribe logger (return ()) --TODO: maybe do a hFlush?
82− stopWorker :: Async () -> U.InChan WorkerCmd -> IO ()
83− stopWorker worker inChan = do
84− U.writeChan inChan HPoisonPill
85− void $ waitCatch worker
86
72
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 ()
95
73
96-------------------------------------------------------------------------------
74-------------------------------------------------------------------------------
97formatItem :: LogItem a => Bool -> Verbosity -> Item a -> Builder
75formatItem :: LogItem a => Bool -> Verbosity -> Item a -> Builder
@@ -114,7 +92,7 @@ formatItem withColor verb Item{..} =
114 CriticalS -> red $ renderSeverity s
92 CriticalS -> red $ renderSeverity s
115 ErrorS -> red $ renderSeverity s
93 ErrorS -> red $ renderSeverity s
116 WarningS -> yellow $ renderSeverity s
94 WarningS -> yellow $ renderSeverity s
117− _ -> renderSeverity s
95+ _ -> renderSeverity s
118 red = colorize "31"
96 red = colorize "31"
119 yellow = colorize "33"
97 yellow = colorize "33"
120 colorize c s
98 colorize c s
@@ -128,8 +106,8 @@ formatItem withColor verb Item{..} =
128_ioLogEnv :: LogEnv
106_ioLogEnv :: LogEnv
129_ioLogEnv = unsafePerformIO $ do
107_ioLogEnv = unsafePerformIO $ do
130 le <- initLogEnv "io" "io"
108 le <- initLogEnv "io" "io"
131− (lh, finalizer) <- mkHandleScribe ColorIfTerminal stdout DebugS V3
109+ lh <- mkHandleScribe ColorIfTerminal stdout DebugS V3
132− registerScribe "stdout" lh (defaultScribeSettings finalizer) le
110+ registerScribe "stdout" lh defaultScribeSettings le
133{-# NOINLINE _ioLogEnv #-}
111{-# NOINLINE _ioLogEnv #-}
134
112
135
113
katip/test/Katip/Tests/Scribes/Handle.hs+2−2
@@ -78,9 +78,9 @@ setup :: IO (FilePath, Handle, IO (), LogEnv)
78setup = do
78setup = do
79 tempDir <- getTemporaryDirectory
79 tempDir <- getTemporaryDirectory
80 (fp, h) <- openTempFile tempDir "katip.log"
80 (fp, h) <- openTempFile tempDir "katip.log"
81− (s, finaliser) <- mkHandleScribe (ColorLog False) h DebugS V3
81+ s <- mkHandleScribe (ColorLog False) h DebugS V3
82 le <- initLogEnv "katip-test" "test"
82 le <- initLogEnv "katip-test" "test"
83− le' <- registerScribe "handle" s (defaultScribeSettings finaliser) le
83+ le' <- registerScribe "handle" s defaultScribeSettings le
84 return (fp, h, void (clearScribes le'), le')
84 return (fp, h, void (clearScribes le'), le')
85
85
86
86