ctxslog

Updated 2023-07-14: Replaced all -Ctx to -Context as the rename happened on go 1.21rc3

With the release of the first RC of go 1.21 earlier this week, I’m polishing my ctxslog package I’ve been using with my Google Cloud Run services, and preparing for a v1.0.0 release with stable APIs (it’s currently at v1.0.0-beta.1).

First, some background

Logging should be easy. It is also more or less easy if you are writing everything yourself. But it’s not so easy when third-party libraries are involved.

First of all, Principle #1: If you are writing a library, you should avoid logging and communicate the info to your user by other means (return values, etc.).

But principle is just… a principle. We are living in a non-ideal world and shit happens. There are certain cases there’s no (easy) way to communicate back the errors to your user, especially the cases that those happen in the background. For example, thrift.TSimpleServer runs a background goroutine to accept new client connections, and there’s no easy way to communicate network errors back to the user when those errors happen outside of a request cycle, so it does some logging.

So here comes Principle #2: If you are writing a library and some logging cannot be avoided, then you should give your user control on how those logging should happen.

But here comes the hard problem: it’s very hard to make everyone (this includes every third party library author) to agree to a common logging interface.

There is something in go’s stdlib: log. There were some ecosystem around it in third-party libraries world to bring bells and whistles, the most popular/successful one is probably logrus. So some third-party libraries that cannot avoid logging would just use the APIs around stdlib log to do the logging.

Later people start to realize the limitation of stdlib log, especially on the performance side. A new flock of highly-efficient, structured (JSON native) third-party logging libraries start to become mainstream, with the most popular/successful one being zap.

But those logging libraries achieved their high efficiency by jumping out of the limitations set by the APIs of stdlib log, so they are no longer compatible with log (zap does provide a wrapper to stdlib log, but it’s also limited by the API of log), so those other third-party libraries using stdlib log to do logging can no longer take full advantage of it. It’s not uncommon that a go service uses zap to do logging, but it also uses (several) third-party libraries do logging with stdlib log, so in the end it ends up with mixed logs.

To handle the fragmentation issue, I advocated for a “common denomination” logger interface to be used by third-party libraries and it’s adopted by both Thrift go library and Reddit’s open sourced version of Baseplate.go. The interface is simple: just a lambda accepting a single string arg (Baseplate.go’s version has an additional ctx arg as it’s very important to Baseplate.go’s other libraries).

Because lambdas are first-class citizens in go, it’s very easy to wrap whatever logging library you are using into this “common ground”. For example, if you are using zap, you can call thrift.TSimpleServer.SetLogger simply as:

server.SetLogger(func(msg string) {
  zap.S().Infow(msg, "from", "thrift")
})

This is where slog comes in

slog, which is currently provided as an experimental third-party library but will be part of go stdlib as log/slog starting at go 1.21, is go team’s retake of stdlib logging. It took a lot of inspiration from zap and co, but also made a lot of improvements on top of them (for example, the LogValuer interface is very nice to handle uncertainty of expensive calculations needed by logging).

I’m really excited about it, because my hope is that in the near future, slog would become the new logging standard that all/most go third-party libraries could agree on, thus resolve the fragmentation problem we are facing today. At that time, when a third party library need to do some unavoidable logging, they would be simply using slog:

slog.ErrorContext(ctx, "Some error happened in the background", "err", err)

And this is where ctxslog comes in

Although slog designed its API around context, the 2 Handler implementations provided out of the box, the JSON and text handlers, both ignore the ctx arg passed in. (This is actually totally fine, I’m not bashing the Go team for ignoring it, because at slog level those handlers really have no special thing to do with the ctx arg.)

This is where ctxslog comes in: it handles those contexts.

At the time of writing, there are 3 different contexts ctxslog can handle:

1. The logger (kv pairs) attached to a context: This is useful to attach request level info to a context to be automatically logged in every log within this request. For example, a trace id, or some http request details.
2. Override the minimal level of logs to keep: This is useful when a third-party library you use does use slog to do logging, but uses the levels “inappropriately” (not consistent with the levels used elsewhere in your code).
3. Override the minimal level to add callstack info: Similar to 2.

So if you are writing some go code, you can use ctxslog to setup the global logger used by slog in your main, then prepare context accordingly before passing them to third-party libraries that use slog for logging. So that if they use slog.ErrorContext(ctx, "Some error happened in the background", "err", err) the log will have trace id/other per request info attached to the log automatically. If you don’t agree with their usage of levels or think they are too spammy, you can also raise the minimal level used by them. I provided some example code in the package example.