Friday, February 21, 2014

Logging flow activity

Foreword

Everyone needs to log things in a program. Have you already wondered what kind of logs you were dealing with? I don’t mean debug, warning or error logs. I mean semantic here.
Basically, I’ll put apart two concepts:
  • tracing an algorithm’s behavior
  • tracing a flow activity
Tracing an algorithm’s behavior is something we often do in Haskell with the Writer or WriterT monads. Those are very convenient because they allow the use of a monoid along with your computation. You can then compute things while mappending a monoidal value. Once the algorithm is done, you get a pair of values: the value from your computation, and the monoidal log. This is great when you want to launch something and analyze trace later.
This Writer stuff doesn’t fit flow activity. Why? Because tracing an algorithm’s behavior is what we could call deferred log handling whereas the later is on-the-fly log handling. There could be a lot of reasons for prefering on-the-fly over deferred:
  • if you’re planning to log in a function that may take long time to run (you’d like the logs as soon as possible, not in an hour)
  • if you’re planning to log a lot (you don’t want your application to poorly crash because your system runs out of memory due to the huge and nasty accumulating monoid memory print)
  • you have a reactive ecosystem to logs
  • and so on…
You still can do on-the-fly log handling with Writer. There are two functions called listen and listens that will grant you access to the monoidal value of a sub Writer. Then you can do something like that:
runWriterT $ do
(_,w) <- listen $ do
tell "Hello, this is dawg!"
return 314
liftIO (print w) -- print it out here
But all of this has a huge and important drawback: because the call to listen runs in Writer or WriterT, its monoid will be accumulated in its parent. So we can treat stuff on the fly, but we can’t purge logs. Imagine what happens if your application logs intensively and runs for a long time. Bam! :)

Tracing flow activity

We want to easily accumulate monoidal values. We also want to have a solution to access the monoid and do something with it – for instance print it out on screen or in the terminal. Finally we want to clear the monoid – the purge thing.

MonadJournal

Here MonadJournal comes. I’ve chosen the term journal because it’s straight-forward and a lot of applications call that that way (look at systemd’s journalctl program for instance). Let’s have a look:
class (Monoid w, Monad m) => MonadJournal w m | m -> w where
journal :: w -> m ()
history :: m w
clear :: m ()
And these useful functions:
sink :: (MonadJournal w m, MonadIO m) => (w -> IO ()) -> m ()
absorb :: (Monadjournal w m) => (a,w) -> m a
The MonadJournal typeclass defines three functions. journal, history and clear. The former is used to trace activity. It’s quite the same thing as tell, but in MonadJournal. history is used to retrieve the history of logs. The latter is used to clear the history.
sink is a log handler. It takes a function that takes the monoid – i.e. the logs history – and does something with it in IO, and purge the history. The simpliest thing you can do with logs is print them out! And this is quite ultra simple to do. If your monoid is also in the Show class, you can simply print them all with this:
sink print
absorb is to MonadJournal what writer is to MonadWriter. It takes a value with a monoid, absorbs the monoid, and pass the value around.

JournalT

The problem with that is that it’s a typeclass, not something directly usable. There’s no implementation of journal nor sink anywhere yet. That’s why a JournalT monad transformer was introduced. This is its type:
JournalT w m a
It’s then the monad transformer version of MonadJournal, just as WriterT is the monad transformer version of MonadWriter. It has a function to run it:
runJournalT :: JournalT w m a -> m (a,w)
Now we can write a complete example:
main :: IO ()
main = do
void . runJournalT $ do
-- here we are tracing IO flow activity
journal ["hello!"]
v <- maybe (return 0) absorb . runJournalT $ test
journal ["just read " ++ show v]
sink print
-- and here we are tracing Maybe flow activity, which is pure
test :: JournalT [String] Maybe Int
test = do
journal ["lol"]
return 314
See how it’s unified thank to the typeclass!

Conclusion

I’ve been wandering around logging in Haskell for a while now. I’ve been using Writer, WriterT, passing logging action (like a function foo :: (Errorable e, MonadIO m) => (e -> IO ()) -> a -> b -> … -> m ()) and so on. I came up with the MonadJournal solution recently while working on my 3D engine, and it’s quite nice. It’s already in hackage, so give it a try, and leave your feedback! :)
If you think some combinators are missing, please let me know! :)

2 comments:

  1. Can you show an example of it being used with something that would normally take a long time to complete? Do you need to put `sink print` calls in the middle of your algorithm?

    ReplyDelete
  2. Well I guess it depends on your algorithm. If your stuff isn’t in`(MonadIO m) => m, the issue is the same for`MonadWriter and MonadJournal. If you’re in (MonadIO m) => m, you can indeed sink logs. A more correct phrase I could have used would have been “something that takes a long time in IO”. If you put such a function in WriterT w IO, you’ll have to wait for the whole function – and nested calls – to complete and the function exits to access the logs. It’s not the case with MonadJournal, where you can access them whenever you want.

    ReplyDelete