The first time I ran into “structured logging” was way, way back when I first started working on kitsune. Back then I went with the approach of using a Logback Formatter (the JacksonJsonFormatter) to log Clojure maps as JSON. This was nice because I didn’t have to do anything to “transform” the logs further, but had the quite significant downside that logs weren’t really human readable anymore. This plus that that log processors like Loki and CloudWatch can easily parse huge amounts of “traditional” text logs made me pretty much forget about structured logging until recently.

That is until in a thread on the clojurians slack about logging someone mentioned mulog, a structured logging library that caught my attention. I guess maybe from a traditional Clojure background it would’ve been natural to end up with taoensso/timbre at this point, but I never did that bit (though I do have it as an indirect dependency).

Working some more on kitsune, I wanted to do what is called “tagged logging” in Rails – add some items to every log line within a context (such as a request or async job ID). At first I hacked around this by using a dynamic var and bindings to wrap various contexts, but I very quickly ran into walls with this. Then I recalled mulog, and decided to give it a try. I haven’t looked back since.

μ/log and μ/trace are very convenient. The library does what it does really well. Its publishers are not difficult to configure and there are tons of options. While I grew to appreciate its flavor of structured logging a lot, I also didn’t want to give up the “old way” with log levels and human readable log lines. Log levels were easy to do with a few macros, but getting human readable logs was a bit more involved.

First the log lines have to be transformed from the Clojure map they are into a readable line. I made a function that takes a log event and prints the “common” bits such as timestamp, level, and trace id. Then I made a multimethod that formats the event specific pieces. At first this feels like a lot more work to do than logging the “old way,” but unless the log line is something super trivial like “Starting server…” it’s not all that different in the end. In text based logging the printf-like formatting is often concealed by concatenation, but it’s there nonetheless. Using :mulog/event-name as the multi’s dispatch-fn also means that adding the formatting for any event is painless.

The only reason I also wrote my own publisher was that the default console publisher uses pr to output, which means quotes. I didn’t want the quotes around my log lines, so I wrote a very basic publisher that printlns every log event instead.

I really appreciate how I don’t need to manually deal with System/nanoTime anymore as μ/trace handles that too. Finding the options to achieve the stuff I wanted wasn’t easy, but once I found them it made stuff like logging requests and async jobs really smooth. Adding context-specific information is really easy (either with with-context or built-in with trace), and contexts having unique flake IDs helps a lot with debugging too.

I don’t know if I’ll ever end up using something like CloudWatch for a personal project, but when/if that happens, mulog having built-in publishers for every major “thing” you might want to send your logs too will come handy for sure. I wonder if I could use it to for example automatically send error events to an error aggregator too… The possibilities feel endless.