Structured Logging with Blammo!

Notice: This website has moved to a new URL. Please visit us at Renaissance Learning R&D.

Structured Logging with Blammo!

by @pbrisbin on August 04, 2022

It’s better than bad, it’s good!

A few weeks ago, we at Freckle noticed the release of monad-logger-aeson, a library that made it easy to add Structured Logging to a Haskell application using the familiar MonadLogger interface. We were extremely excited about this library and immediately set to work integrating it into our apps. The result is a higher-level, batteries-included library of our own called Blammo, which we’re announcing here today.

Structured Logging 101

In case you’re not familiar, Structured Logging is what it sounds like: giving your typically-textual logs some structure, usually JSON:

logInfo "Hi"
-- => { message: { text: "Hi" } }

Once you’ve gone structured, you can begin to write richer messages too:

logInfo $ "Authenticating" :# ["user" .= user]
-- => { message: { text: Authenticating, meta: { user: { id: ..., ... } } } }

Logs with structure are particularly valuable when shipped to a centralized log aggregator that understands them, such as Datadog. You can now do very targeted searches like,

user.id:99

And not be buried in false-positives, or miss results because some places logged “User Id 99” and others “user_id=99”.

You can also do searches that treat data like data,

http.method:patch http.duration:>2000

Which you can’t do on free-text logs.

Structured Logging is useful for more than just searching. Datadog supports top-lists and pie charts by the fields in your logs, and its “Watchdog” automatic analysis has become much more useful as we make richer data available to it. We’ll see some examples of this later.

Why Create Blammo?

The main motivation for wrapping monad-logger-aeson up in another library was to make something opinionated and zero configuration. At Freckle, we don’t believe in top-down mandates of patterns or libraries. Instead, we build things that are compelling, and let the best option gain adoption across all teams organically. And the best chance at getting Engineers to do your thing is to make it the easiest thing.

If all of our Engineers adopt Blammo in all their apps, we’ll end up with all logs in a consistent format, and supporting the same sort of analyses. This increases the effectiveness of whatever work we put into Datadog in the form of facets, views, and alerts.

A ubiquitous trace_id, for example, allows us to tail logs of some request across service boundaries:

> env:prod @context.trace_id:abc123
=> { env: prod, context: { service: api, trace_id: abc123 }, message: { text: "Enqueued DeleteTeacher", ...
=> { env: prod, context: { service: api, trace_id: abc123 }, message: { meta: { method: "DELETE", status: 200, ...
=> { env: prod, context: { service: jobs, job: DeleteTeacher, trace_id: abc123 }, source: "SQL", message: { text: "SqlError", ...
=> { env: prod, context: { service: jobs, job: DeleteTeacher, trace_id: abc123 }, message: { text: "Job failed", ...

In support of this goal, Blammo aims to:

Be easy to use in simple Apps, with a single runSimpleLoggingT function
Be easy to use in complex Apps, assuming they use MonadLogger
Have ergonomic and efficient JSON logs in production
Integrate smoothly with other libraries that log

Thanks to libraries like monad-logger-aeson and fast-logger, we were able to meet these and then some.

Oh, and we have a beautiful console format¹ for development:

Getting Started

Converting an existing application to Blammo will go smoothest if you’re already using the ReaderT-IO pattern and MonadLogger constraints throughout. That means you should have actions with constraints like,

something
  :: (MonadIO m, MonadLogger m, MonadReader env m, HasThis env, HasThat env)
  => ...

And a main function such as,

main :: IO ()
main = do
  app <- loadApp
  runSomethingLoggingT $ runReaderT ... app

Given this, the following steps should get you rolling down stairs (sorry):

Replace all imports of Control.Monad.Logger with Blammo.Logging
Implement HasLogger for your App

This typically involves a Logger set as a field. For that, the easiest way is through LogSettings.Env.

Update main:

 main = do
   app <- loadApp
-  runSomethingLoggingT $ runReaderT ... app
+  runLoggerLoggingT app $ runReaderT ... app

Address compilation errors related to Text vs Message arguments

Something like the following will be fine, since OverloadedStrings keeps it working as Text or Message:
```
logInfo "Some message"
```
The problem is if you’re doing “interpolation”, like:
```
logInfo $ "Some message for user " <> userId user
```
But these are exactly the places you want structure, so addressing the compilation errors also automatically gets you taking advantage:
```
logInfo $ "Some message" :# ["user" .= user]
```

Why Use Blammo?

Blammo is just one piece of the puzzle, and a lot of the benefits we’re seeing since using Blammo aren’t uniquely provided by this library. They come from fully buying into Structured Logging as an approach, and leveraging Datadog to maximize the value of those logs. That said, we went a long time without any of this, until Blammo made it easy.

Thread Context

We have a Background Jobs service implemented by a forever-fetch-handle loop. By establishing a thread context for the overall handle portion of this loop, all logs from any code called in handling a Job include details about that Job in the context.job field:

Similarly, Blammo includes a WAI Middleware for establishing the thread context when handling an HTTP Request. Again, this means that all logging, even when happening within dependencies of dependencies of our Yesod App, will receive context that includes the Route, etc.

The above is an exception logged from our API. The trace_id means we can trivially correlate it with the full request details (and any other logging from any other services handling that request):

Insights

Getting structure on log messages opens up all sorts of ways to slice and present logs. For example, here’s a day’s worth of API timeouts, presented by Route:

Datadog’s actual Insights have also gotten much more useful:

In a previous blog post, I mentioned how we’re re-organizing into persona-focused teams, with each team owning delivery to a persona (e.g. Educator, Student) from top to bottom. By adding a team context to all logs, we’re now getting insights that we can funnel directly to the appropriate team. 🤯

Interested?

If you find Structured Logging interesting, and our implementation via Blammo compelling, please try it out and get involved via Issues or Pull Requests.

And, as always, if you’re interested in working for a company that uses Haskell, has a great mission, and gets to do cool Open Source work with Ren & Stimpy inspired names, check out the Job postings in the footer .

This format is a shameless copy of how Python’s structlog does it. ↩