How to Test Logging in Go

Google’s Go language has a very rich and at times utterly infuriating standard library. One of the things it includes is Logging. Since there are six million ways to log (choose one!) we shouldn’t get too worked up about the ways in which the log package doesn’t log the right way for, well probably for anyone outside of Google. That’s not the point.

The point, and it’s a happy one today, is that a mere ounce of prevention will get you easily testable logging with Go’s standard log package. Caveat lector: I have no idea whether this works with Go prior to version 1.5.

Your Ounce of Prevention

Especially when hacking together quick utilities or packages, it’s always tempting to do this:

package logdemo

import "log"

func Log() {
    log.Println("woo hoo")
}

However, that will be very hard to test. Take the time to set up a logger, and expose it. Ideally you can do this with a struct:

package logdemo

import "log"

type LoggingThing struct {
    Logger *log.Logger
}
func New(name string) *LoggingThing {
    prefix := "thing-" + name + " "
    flags := log.Ldate | log.Ltime | log.Lmicroseconds
    return &LoggingThing{Logger: log.New(os.Stdout, prefix, flags)}
}
func (lt *LoggingThing) Log(msg string) {
    lt.Logger.Print(msg)
}

Now you have something that can be messed with in your unit tests, and is also much easier to debug should the need arise.

But if you really can’t deal in structs, at least set up a package variable for the logger. This too can be manipulated.

package logdemo

import "log"

var logger_prefix = "global "
var logger_flags = log.Ldate | log.Ltime | log.Lmicroseconds
var Logger = log.New(os.Stdout, logger_prefix, logger_flags)

func Log(msg string) {
    Logger.Print(msg)
}

Your Pound Sterling of Cure

Now that we have an exposes Logger (two, really), we only need to know one thing: that a Logger can have its Output set after the fact, and that the Output needs only to be an io.Writer, which as you may recall simply requires that it implement this:

type Writer interface {
        Write(p []byte) (n int, err error)
}

In our test package, we can set up a simple struct to catch logs instead of writing them:

type LogCatcher struct {
    Logs []string
    Last string
}

func (lc *LogCatcher) Write(p []byte) (n int, err error) {
    s := string(p)
    lc.Logs = append(lc.Logs, s)
    lc.Last = s
    return len(p), nil
}

That will give us raw logs, but they may include prefixes and timestamps. Prefixes, if they are used at all, are quite useful; but timestamps are very hard to test for, since you then have to match log entries with regular expressions instead of simple strings.

Fortunately, that too can be overridden. Our overrides then look something like this:

thing := logdemo.New("one")

catcher := &LogCatcher{}
thing.Logger.SetOutput(catcher)

// If you want to test the prefix and output format you can of course
// do that separately.  For testing the written logs it's asking a
// lot, but we can override!
thing.Logger.SetFlags(0)
thing.Logger.SetPrefix("")

// Here we log, and catch it!
thing.Log("here")
assert.Equal("here\n", catcher.Last, "caught first log")

Note that I am using the excellent assert package in order to make unit testing sane. (Again with the rich but infuriating standard library…)

If you’ve read this far and you aren’t totally lost then you can imagine how this continues. But you don’t have to imagine, because the code is there for you on GitHub under biztos/go-demos, specifically as
logdemo.go and logdemo_test.go.

Congratulations, now your logging will not prevent you from achieving the coveted (and utterly spurious) 100% code-coverage metric!