Logging is a fundamental tool to monitor and debug a running system. Even if we can use logs to gather metrics about our system, these are often written with the assumption that humans are going to consume them, which make it hard to extract meaning information from log messages.
Log messages are rarely consistent or even meaningful if read few days after writing them during your emergency debug session. Writing good log messages is hard! Almost as hard as naming things and cache invalidation.
Another overlooked problem is that often logs are are context less, what can we infer by a message like "Failed to process user payment" if we don't know what triggered the payment process, the affected user or product?
Structured logging aims to provide query-able, consistent, information rich logs that can be used for:
mulog is a Clojure library, developed by Bruno Bonacci, that can be used to replace your text based logs with content rich events, enabling a large set of analytics for the data produced by your system. I highly suggest to read the motivation behind this library to understand the author's vision but, for the impatient, it can be summarized as following:
Without further ado, lets jump to some examples!
We can either create a new project adding mulog to the dependencies or start a REPL with support to clojure.repl.deps/add-lib and download the lib dynamically to our session [older post with add-lib].
New project
$ clj -X:new-app :name mulog-example.main
$ cd mulog-main
The :new-app alias is defined in my $HOME/.clojure/deps.edn, using the handy clj-new tool by Sean Corfield; the project is well documented and the README is a great place to get you up and running, in case you are interested to try it out. It is also possible to start from scratch with a basic deps.edn file like the following:
{:paths ["src"]
:deps {org.clojure/clojure {:mvn/version "1.11.1"}
com.brunobonacci/mulog {:mvn/version "0.9.0"}}}
Assuming a fully functional project/REPL/whatever setup with mulog available to you it is time to write our first log:
(require '[com.brunobonacci.mulog :as u])
(u/log ::my-first-event :message "a log, wow!")
I want to point out few things:
mulog make it possible to send events to different publishers which will take care of delivering the events to the right destinations. Out of the box mulog supports console and file publishers but there are my others available to be plugged in. It is also possible to write your own publisher if your target tools is not supported yet. A list of currently supported publishers is available here.
For the sake of this example we can enable the console publisher
(u/start-publisher! {:type :console}) ;; good enough for development
After evaluating it, we will be able to see the event logged to our REPL. By default an event will look like the following map:
{:mulog/trace-id #mulog/flake "4q6x5wlEnU0WNV5fV0HTvJ32Lz3b4GvV"
:mulog/timestamp 1684906031447
:mulog/event-name :your-ns/my-first-event
:mulog/namespace "your-ns"
:message "a log, wow!"}
Keys in the mulog namespace are automatically added by the library, the rest is whatever we have provided as extra parameters in the call.
Enriching our logs with custom data is the first step towards our goal to improve the observability of our systems. Another key factor is the consistency of the data collected with logs.
As systems grow in size and complexity it might be hard and tedious to maintain the same set of keys across all functions and entry points.
Assuming that we are writing a web application we may want to keep a standard set of key across all event generate by all handlers, for example user id, ip, endpoint path or name and so on.
mulog events are logged within a context and we have already seen it in action in our first log, and it was represented by the keys in mulog namespace.
It is possible to add more data to the logging context using:
;; (u/set-global-contex! {:key1 val1 … keyN valN}) alters the global context, may be used at application start for example
;; (u/with-context {:keyN valN} body) macro that will wrap the body in a new, temporary context; more context can be chained together
(u/with-context {:username "foo"
:handler :some-endpoint}
(u/log ::business-logic :message "User did something"))
;; will log something look this
{:username "foo"
:handler :some-endpoint
:mulog/trace-id #mulog/flake "4q6yXTTvky4yTeHENi8UcRNPpjJrPpPq"
:mulog/timestamp 1684907603865
:mulog/event-name :user/business-logic
:mulog/namespace "user"
:message "User did something"}
As we have seen in the example, the event has been created with the extra information set in the call to u/with-context. This is very handy and makes it easier to have consistent logs across our code.
As we add more context in our call chain we will end up with extremely rich logs that can be used for analytics. Taking again the example of a web app we can potentially understand how different parts of our business are being used by users with different devices using the request user agent or how many users we have for each country using the request ip, in order to scale up or down our clusters in those regions.
On top of the logging facility, mulog u/trace macro make it possible to measure the time spent by any part of code wrapped by it, here is its signature:
(u/trace event-name [:keyN value1N] body)
Like u/log it can leverage nested context data but on top of that it is possible to introduce new context data that will be captured by the current and nested u/trace calls but not by nested calls to u/log.
The body parameter is the code that we want to trace. Here is an example call and the resulting event:
(u/trace :calling-api [:extra "content"] (post-to-external-api payload))
;; example event logged by the trace call
{:mulog/duration 250362049
:mulog/namespace "user"
:mulog/outcome :ok
:extra "content" ;; <- here is the extra content provided by trace
:mulog/parent-trace nil
:mulog/root-trace #mulog/flake "4q73JVUr9GK_PBOhs6p3NJfnYhqps7Tp"
:mulog/timestamp 1684953980473
:mulog/trace-id #mulog/flake "4q73JVUr9GK_PBOhs6p3NJfnYhqps7Tp"
:mulog/event-name :calling-api}
The example shown here traces within the boundaries of the running process but mulog can be instrumented to work with distributed tracing systems; for more details refer to the documentation.
When starting a publisher it is possible to specify a transformation function that will take a sequence of events to be modified or even evicted, and returns the new sequence of events. Thanks Bruno for your review!
This approach can be useful to remove sensible data before it is sent to a log collector, for example user tokens, passwords, API keys and so on. While we may want to retain this kind of information when developing, and using a console logger, it is mandatory to remove it while in production when working with real business data. Another use case is to completely evict events that we don't want to send to a specific collector, for example we may have a collector interested in metrics to scale a cluster and another one dedicated to business logic, the possibilities are endless!
Having the possibility to specify a transformation function at the publisher level make it easy to configure our systems based on the environment they are running on.
While it looks simple on the surface, mulog is a powerful library that helps you to get useful insights about your running system. Fortunately it does not require a lot of ceremony to get started and can be bent to meet your specific use cases if needed.
This post is just a brief introduction to the topic of structured logging, viewed with the lenses of mulog. I highly suggest to dig deeper in its documentation and watch Bruno's talk "u/log and the next 100 logging systems".