on master help sign in
Define exception behavior in finalizers

Before we were swallowing exceptions in the finalizer wrapper. Instead, we let closeScribe throw, and we let closeScribes run all finalizer before rethrowing the first error. The idea is that if the user is closing a single scribe, they should be able to react if there's an issue. If they're closing all scribes, we should make sure resources are freed but then let them respond. I suppose the other way would be to catch and return a list of exceptions associated with the finalizer. I could be convinced of that API too.

commit2f4deaf960a7430a428347233e9956cd3f33213e authorMichael Xavier <michael@michaelxavier.net> dateTue 4 Apr 2017, 09:48 (10 years ago) parentf8bc783
3 files changed+96−7
katip/katip.cabal+3 katip/src/Katip/Core.hs+12−6 katip/test/Katip/Tests.hs+81−1
katip/katip.cabal+3
@@ -117,6 +117,9 @@ test-suite test
117117 , regex-tdfa
118118 , unordered-containers
119119 , microlens
120+ , containers
121+ , stm
122+ , safe-exceptions
120123 ghc-options: -Wall
121124 if flag(lib-Werror)
122125 ghc-options: -Werror
katip/src/Katip/Core.hs+12−6
@@ -600,7 +600,7 @@ registerScribe nm scribe ScribeSettings {..} le = do
600600 -- wait for our worker to finish final write
601601 void (Async.waitCatch worker)
602602 -- wait for scribe to finish final write
603− void (tryAny (scribeFinalizer scribe))
603+ void (scribeFinalizer scribe)
604604
605605 let sh = ScribeHandle (scribe { scribeFinalizer = fin }) queue
606606 return (le & logEnvScribes %~ M.insert nm sh)
@@ -661,7 +661,9 @@ clearScribes = logEnvScribes .~ mempty
661661
662662-------------------------------------------------------------------------------
663663-- | Finalize a scribe. The scribe is removed from the environment,
664−-- its finalizer is called and it can never be written to again.
664+-- its finalizer is called and it can never be written to again. Note
665+-- that this will throw any exceptions yoru finalizer will throw, and
666+-- that LogEnv is immutable, so it will not be removed in that case.
665667closeScribe
666668 :: Text
667669 -- ^ Name of the scribe
@@ -676,12 +678,17 @@ closeScribe nm le = do
676678-- | Call this at the end of your program. This is a blocking call
677679-- that stop writing to a scribe's queue, waits for the queue to
678680-- empty, finalizes each scribe in the log environment and then
679−-- removes it.
681+-- removes it. Finalizers are all run even if one of them throws, but
682+-- the exception will be re-thrown at the end.
680683closeScribes
681684 :: LogEnv
682685 -> IO LogEnv
683−closeScribes le =
684− foldrM closeScribe le (M.keys (_logEnvScribes le))
686+closeScribes le = do
687+ -- We want to run every finalizer here so we'll not save
688+ -- intermediate logenvs and just clear scribes at the end.
689+ let actions = [void (closeScribe k le) | k <- M.keys (_logEnvScribes le)]
690+ foldr finally (return ()) actions
691+ return (le & logEnvScribes .~ mempty)
685692
686693
687694-------------------------------------------------------------------------------
@@ -781,7 +788,6 @@ logItem a ns loc sev msg = do
781788 <*> pure (_logEnvApp <> ns)
782789 <*> pure loc
783790 FT.forM_ (M.elems _logEnvScribes) $ \ ScribeHandle {..} -> atomically (tryWriteTBQueue shChan (NewItem item))
784− --TODO: if we use tbqueue, write an atomic tryWriteTBQueue
785791
786792
787793-------------------------------------------------------------------------------
katip/test/Katip/Tests.hs+81−1
@@ -11,9 +11,12 @@ module Katip.Tests
1111
1212
1313-------------------------------------------------------------------------------
14−import Control.Applicative as A
14+import Control.Applicative as A
15+import Control.Concurrent.STM
16+import Control.Exception.Safe
1517import Data.Aeson
1618import qualified Data.HashMap.Strict as HM
19+import qualified Data.Map.Strict as M
1720import Data.Monoid
1821import Data.Text (Text)
1922import qualified Data.Text.Lazy.Builder as B
@@ -43,6 +46,8 @@ tests = testGroup "Katip"
4346 , testCase "processIDToText is just the number" $ do
4447 processIDToText 123 @?= "123"
4548 , logContextsTests
49+ , closeScribeTests
50+ , closeScribesTests
4651 ]
4752
4853
@@ -65,6 +70,81 @@ logContextsTests = testGroup "logContexts"
6570 ]
6671
6772
73+-------------------------------------------------------------------------------
74+closeScribeTests :: TestTree
75+closeScribeTests = testGroup "closeScribe"
76+ [ testCase "removes the specified scribe" $ do
77+ (scr, finalizerCalled) <- trivialScribe
78+ le <- registerScribe "trivial" scr defaultScribeSettings =<< initLogEnv "ns" "test"
79+ le' <- closeScribe "trivial" le
80+ closed <- atomically (readTVar finalizerCalled)
81+ assertBool "finalizer called" closed
82+ assertBool "should not have trivial key in scribes" (not (M.member "trivial" (_logEnvScribes le')))
83+ , testCase "does nothing for a missing scribe" $ do
84+ le <- initLogEnv "ns" "test"
85+ le' <- closeScribe "nah" le
86+ assertBool "does not affect scribes" (M.null (_logEnvScribes le'))
87+ , testCase "re-throws finalizer exceptions" $ do
88+ (scr, finalizerCalled) <- brokenScribe 1
89+ le <- registerScribe "broken" scr defaultScribeSettings =<< initLogEnv "ns" "test"
90+ res <- try (closeScribe "broken" le)
91+ closed <- atomically (readTVar finalizerCalled)
92+ assertBool "finalizer called" closed
93+ case res of
94+ Left (ScribeBroken scribeNo) -> scribeNo @?= 1
95+ Right _ -> assertFailure "Expected to throw a ScribeBroken but it did not"
96+ ]
97+
98+
99+-------------------------------------------------------------------------------
100+trivialScribe :: IO (Scribe, TVar Bool)
101+trivialScribe = do
102+ finalizerCalled <- newTVarIO False
103+ let finalizer = atomically (writeTVar finalizerCalled True)
104+ return (Scribe (const (return ())) finalizer, finalizerCalled)
105+
106+
107+-------------------------------------------------------------------------------
108+brokenScribe :: Int -> IO (Scribe, TVar Bool)
109+brokenScribe scribeNum = do
110+ finalizerCalled <- newTVarIO False
111+ let finalizer = do
112+ atomically (writeTVar finalizerCalled True)
113+ throw (ScribeBroken scribeNum)
114+ return (Scribe (const (return ())) finalizer, finalizerCalled)
115+
116+
117+-------------------------------------------------------------------------------
118+data BrokenScribeError = ScribeBroken Int deriving (Show)
119+
120+
121+instance Exception BrokenScribeError
122+
123+-------------------------------------------------------------------------------
124+closeScribesTests :: TestTree
125+closeScribesTests = testGroup "closeScribes"
126+ [ testCase "returns a log env with no scribes" $ do
127+ (scr, finalizerCalled) <- trivialScribe
128+ le <- registerScribe "trivial" scr defaultScribeSettings =<< initLogEnv "ns" "test"
129+ le' <- closeScribes le
130+ closed <- atomically (readTVar finalizerCalled)
131+ assertBool "finalizer called" closed
132+ assertBool "remvoes all scribes" (M.null (_logEnvScribes le'))
133+ , testCase "throws the first exception encountered after closing all scribes" $ do
134+ (scr1, finalizerCalled1) <- brokenScribe 1
135+ (scr2, finalizerCalled2) <- brokenScribe 2
136+ le <- registerScribe "broken2" scr2 defaultScribeSettings =<< registerScribe "broken1" scr1 defaultScribeSettings =<< initLogEnv "ns" "test"
137+ res <- try (closeScribes le)
138+ closed1 <- atomically (readTVar finalizerCalled1)
139+ assertBool "finalizer 1 called" closed1
140+ closed2 <- atomically (readTVar finalizerCalled2)
141+ assertBool "finalizer 2 called" closed2
142+ case res of
143+ Left (ScribeBroken scribeNo) -> scribeNo @?= 1
144+ Right _ -> assertFailure "Expected to throw a ScribeBroken but it did not"
145+ ]
146+
147+
68148-------------------------------------------------------------------------------
69149data ConservativePayload = ConservativePayload {
70150 oftenShown :: Text