29 Jan 2023

A take on log messages

At $DAYJOB we use structured logging with rather little actual structure, the only rules are

Log to stdout.
Log one JSON object per line.
The only required fields are
- message - a human readable string describing the event
- level - the severity of the event, debug, info, warn, error, or fatal.
- timestamp - the time of the event
- correlation-id - an ID passed between services to allow to find related events

Beyond that pretty much anything goes, any other fields that are useful in that service, or even in that one log message is OK.

My first take was very ad-hoc, mostly becuase there were other parts of the question "How do I write a service in Haskell, actually?" that needed more attention – then I read Announcing monad-logger-aeson: Structured logging in Haskell for cheap. Sure, I'd looked at some of the logging libraries on Hackage but not really found anything that seemed like it would fit very well. Not until monad-logger-aeson, that is. Well, at least until I realised it didn't quite fit the rules we have.

It did give me some ideas of how to structure my current rather simple, but very awkward to use, current loggging code. This is what I came up with, and after using it in a handful services I find it kind of nice to work with. Let me know what you think.

The log message type

I decided that a log message must always contain the text describing the event. It's the one thing that's sure to be known at the point where the developer writes the code to log an event. All the other mandatory parts can, and probably should as far as possible, be added by the logging library itself. So I ended up with this type.

data LogMsg = Text :# [Pair]
    deriving (Eq, Show)

It should however be easy to add custom parts at the point of logging, so I added an operator for that.

(#+) :: LogMsg -> [Pair] -> LogMsg
(#+) (msg :# ps0) ps1 = msg :# (ps0 <> ps1)

The ordering is important, i.e. ps0 <> ps1, as aeson's object function will take the last value for a field and I want to be able to give keys in a log message new values by overwriting them later on.

Instances to use it with fast-logger

The previous logging code used fast-logger and it had worked really well so I decided to stick with it. Making LogMsg and instance of ToLogStr is key, and as the rules require logging of JSON objects it also needs to be an instance of ToJSON.

instance ToJSON LogMsg where
    toJSON (msg :# ps) = object $ ps <> ["message" .= msg]

instance ToLogStr LogMsg where
    toLogStr msg = toLogStr (encode msg) <> "\n"

Instance to make it easy to log a string

It's common to just want to log a single string and nothing else, so it's handy if LogMsg is an instance of IsString.

instance IsString LogMsg where
    fromString msg = pack msg :# []

Combining log messages

When writing the previous logging code I'd regularly felt pain from the lack of a nice way to combine log messages. With the definition of LogMsg above it's not difficult to come up with reasonable instances for both Semigroup and Monoid.

instance Semigroup LogMsg where
    "" :# ps0 <> msg1 :# ps1 = msg1 :# (ps0 <> ps1)
    msg0 :# ps0 <> "" :# ps1 = msg0 :# (ps0 <> ps1)
    msg0 :# ps0 <> msg1 :# ps1 = (msg0 <> " - " <> msg1) :# (ps0 <> ps1)

instance Monoid LogMsg where
    mempty = ""

In closing

What's missing above is the automatic handling of the remaining fields. I'll try to get back to that part soon. For now I'll just say that the log message API above made the implementation nice and straight forward.

Comment here.