Go has some tricks up its logging sleeve

The Go programming language has some subtle capabilities that make it possible to take logging, and therefore tracing and debugging, further than most other languages.

Go has some tricks up its logging sleeve

Since it's more or less TDOV (IYKYK...), I'm going to talk about logging instead.

Logging isn't exactly the most shiny or in-your-face thing that coders tend to think about, but it really can make or break large systems. Throwing in a few print statements (or fmt.Printf, or whatever) only scratches the surface.

I'm mostly talking about my own logging library here. If there's interest, I'd consider releasing it as open source, but it's currently a bit of a moving target. Feel free to comment if you think you'd find it useful, and I'll try to find the time to split it out from the Euravox codebase and put it on GitHub.

The Go programming language ships with logging capabilities in the standard library, found in the log package. If you don't have any better alternatives, using that package rather than raw fmt.Printf is far preferable.

My own logging package is a bit nicer. It's not my first – one of my first jobs working in financial markets data systems back in the 90s was the logging subsystem for the Reuter Workstation, and there is some influence from that 30-odd years later in my library.

Log Levels

One of the first things I always recommend is breaking out log messages by log level. I currently define the following:

  1. SPM -- Spam messages. Very verbose logging, not something you'd normally use, but the kind of thing that makes all the difference doing detailed debugging.
  2. INF -- Information messages. These are intended to be low volume, used to help trace what systems are doing, but not actually representing a an error (i.e., they explicitly are used to log normal behaviour)
  3. WRN -- Warning messages. What it says on the tin. Something is possibly wonky, but not bad enough to be an actual error. Real production systems should have as close to zero of these things as possible -- samething should either be normal (INF) or an actual error (ERR).
  4. ERR -- Error messages. This represents recoverable errors. Something bad happened, but the code can keep running without risk.
  5. FTL -- Fatal errors. These errors show that something very bad has happened, and that the code must abort immediately. There are two cases where this is appropriate. One is when something catastrophic has happened -- system has run out of handles, process is OOMing, etc. The second is where a serious logic bug has been detected. Though in some cases ERR can be OK for this, aborting makes it easier to spot that processes in production are badly broken (e.g., after a bad push), and need to be rolled back.

It's possible to set a configuration parameter that limits logging at a particular level. This makes it possible to crank logging all the way up for tests, but dial it down for production without changing the code or having to introduce if/then guards around the logging. It was a finding back in the 90s that systems would sometimes break when you took the logging out – this isn't something that's normally a problem with Go, because idiomatic code doesn't tend to have too many side-effects, but it was quite noticeable with C++. Of course, the library doesn't do the string formatting if the level is disabled, but any parameters are still evaluated, which tends to be a less risky approach.

Log Destinations

It's common to send log messages to stdout or stderr. There's nothing fundamentally wrong with this, but I find it useful to have deeper capabilities than this. My own library has three options, which can be used together (and with different log levels):

  1. stdout. Nothing special here, but I do have the option to send colour control codes for terminals that support it, which makes logs much more readable.
  2. Files. This is similar to piping the process through the tee command, but has the advantage that things like log rotation can be built in. I need to get around to supporting log rotation, but file output works now.
  3. Circular buffer. This is the one you don't see often. The idea here is you maintain an in-RAM circular buffer of N lines (say about 5000), which can be exposed via code. I use this to provide an HTTP/HTML interface that makes it possible to watch log output on a process via a web browser. This is a godsend when you have a large number of processes running across multiple VMs and/or physical machines.

File names and line numbers

Any good logging solution should be able to include file name and line number information in log output. Using an IDE like vscode, this allows control/command-clicking a log entry and immediately seeing the code that generated it.

C and C++ support this via some fancy #define stunts. Go lacks this kind of preprocessor, but actually has something far better: the runtime.Caller() library function. This makes it possible to pull back the file name and line number (and program counter if you care) anywhere up the call stack.

Example runtime.Caller usage

This code fragment comes from my logging function. The argument to Caller is typically 2, because this code is called from one of many convenience functions for syntactic sugar. Typical log commands look something like this:


lg.SPM("Just about to do the thing at byte offset %d", offset)

err := SomethingThatCanBreak()
if err != nil {
   lg.ERR("Something broke: %v", err)
}

if CheckForOOM() {
   lg.FTL("Ran out of memory, shutting down.")
}

The logging library will automatically pick up the file paths and line numbers where the log commands are located. However, this isn't always useful, and sometimes can be a complete nightmare. Here's a small example:


func DoTheThing(disk_offset uint64) error {
   lg.INF("DoTheThing at disk_offset %d", disk_offset)
   
   ...
   
   return nil
}

In this case, the file name and line number that will be logged will be where the lg.INF command is located. This can be absolutely maddening if DoTheThing() has many call sites, because they will look exactly the same in the log.

My logging library has a small tweak that I've not seen elsewhere – I'm not claiming invention or ownership, because it's so obviously useful that I'd be shocked if nobody else has ever done it. It's just I've not personally seen it. Anyway, here goes:


func DoTheThing(disk_offset uint64) error {
   lg.INFr(1, "DoTheThing at disk_offset %d", disk_offset)
   
   ...
   
   return nil
}

In this case, lg.INFr works similarly to lg.INF, but it takes an extra parameter at the start, which represents how many extra stack frames to look through to find the filename and line number. The 1 parameter returns the filename and line number of the immediate caller, so the thing that makes its way into the log is the location of the DoTheThing calls, not the logging calls themselves. This might seem to be a subtle difference, but the practical consequences are huge – get this right, and logs become useful traces of activity that make it possible to look backwards in time to see when particular data items have been acted upon, and exactly by what code. Almost as good as single-stepping with a debugger, but can be done after the fact.

Anyway, in conclusion, trans women are women, trans men are men, nonbinary and all other variant identities are valid. And fuck fascism.

Subscribe to Taranis

Don’t miss out on the latest issues. Sign up now to get access to the library of members-only issues.
jamie@example.com
Subscribe