Handling errors only once and logging them with full context in Golang

Imagine having a call stack like

main()
    f1()
        f2()

where an error happens in f2() and f2() doesn’t know how to handle it. It will then return it to its caller, f1(). Assume also that f1() doesn’t know how to handle it, and so it returns it to its caller, main(). Finally main() handles it one way or the other. As part of the handling, it also logs it.

To avoid confusion, we want also to log the error only at the place of handling: if each function seeing the error were to log it, we would have in this example 3 log entries referring to the same error and it would be non-evident that actually there is only 1 error.

The simplest possible code is:

func main() {
	if err := f1(); err != nil {
		fmt.Printf("main: f1 failed: error: %v\n", err)
	}
}

func f1() error {
	connID := 123
	fmt.Printf("f1: inside connID=%d\n", connID)
	if err := f2(); err != nil {
		return fmt.Errorf("f2 failed: %v connID=%v", err, connID)
	}
	return nil
}

func f2() error {
	sessID := 456
	fmt.Printf("f2: inside sessID=%d\n", sessID)
	if _, err := os.Open("/non-existent"); err != nil {
		return fmt.Errorf("open failed: %w: sessID=%v", err, sessID)
	}
	return nil
}

Which generates the output (long lines wrapped for readability):

1  f1: inside connID=123
2  f2: inside sessID=456
3  main: f1 failed: error: f2 failed: open failed: open /non-existent: no such file or directory: sessID=456 connID=123

Note that:

We had to explicitly log the context (connID and sessID), which is boring and error-prone.
In log line 2 we miss the value of connID.

Structured logging

Structured logging allows to better search the logs for patterns, both by hand with tools like jq and systematically with log aggregation systems like Grafana Loki.

For this article we use the go-hclog structured logging library, but many other exists. We also use the nice feature Logger.With(), which gives back another logger that will automatically print all the passed key/value pairs, allowing us to avoid boredom and forgetfulness.

The code becomes:

func main() {
	log := hclog.New(&hclog.LoggerOptions{JSONFormat: true})
	if err := f1(log); err != nil {
		log.Error("main: f1 failed", "error", err)
	}
}

func f1(log hclog.Logger) error {
	connID := 123
	connLog := log.With("connID", connID)
	connLog.Info("f1: inside")
	if err := f2(connLog); err != nil {
		return fmt.Errorf("f2 failed: %v connID=%v", err, connID)
	}
	return nil
}

func f2(log hclog.Logger) error {
	sessID := 456
	sessLog := log.With("sessID", sessID)
	sessLog.Info("f2: inside")
	if _, err := os.Open("/non-existent"); err != nil {
		return fmt.Errorf("open failed: %w: sessID=%v", err, sessID)
	}
	return nil
}

Let’s run it and pass the output to jq for pretty-printing:

$ ./bin/ex02 2>| jq .

{
  "@level": "info",
  "@message": "f1: inside",
  "connID": 123
}
{
  "@level": "info",
  "@message": "f2: inside",
  "connID": 123,
  "sessID": 456
}
{
  "@level": "error",
  "@message": "main: f1 failed",
  "error": "f2 failed: open failed: open /non-existent: no such file or directory: sessID=456 connID=123"
}

Compared to the first example, the second log entry ("f2: inside") now reports also the connID value. allowing to better correlate events.

On the other hand, although we follow the best practice of using fmt.Errorf(), the most important log event, the one with the error, has swallowed and thus blurred the pairs connID and sessID into the error message. We cannot use jq or more advanced tooling to correlate. We are back to grepping the log output.

Can we do better, and at the same time log the error only once?

Wrapping the error with the log pairs

Thinking about it, we would like a way to encode in a more structured way (not in the error string!) the pairs from the log context into the error, and then extract the pairs from the error when we are handling it.

We can obtain the pairs from go-hclog with the function

// ImpliedArgs returns With key/value pairs
Logger.ImpliedArgs() []interface{}

We can take the Go idea of error wrapping and extend it to transport the log pairs as follows:

type logWrapError struct {
	msg   string
	err   error
	pairs []interface{}

Let’s add the classic methods to make this struct a proper error:

// Implement the error interface.
func (e logWrapError) Error() string {
	return e.msg
}

// Implement the wrap/unwrap error interface.
func (e logWrapError) Unwrap() error {
	return e.err
}

Now we only need a method to wrap the error (conceptually, like using fmt.Errorf() with the w verb):

// Err creates a wrapped error containing a list of key/value pairs from your
// structured logging library. Use Pairs to get the list back.
func Err(reason string, err error, pairs []interface{}) error {
	return &logWrapError{
		msg:   fmt.Sprintf("%s: %v", reason, err),
		err:   err,
		pairs: pairs,
	}
}

And a way to extract the innermost list of pairs:

// Pairs returns the list of key/value pairs of the innermost error in the chain, or
// returns the pair ["error"/err] if the chain is not of type lograpError. This means that
// in both cases it can be passed, without conditional logic, to a structured logger
// expecting a list of key/value pairs and it will do the right thing.
func Pairs(err error) []interface{} {
	prev, ok := err.(*logWrapError)
	if !ok {
		return []interface{}{"error", err}
	}
	for {
		next, ok := prev.err.(*logWrapError)
		if !ok {
			return append([]interface{}{"error", err}, prev.pairs...)
		}
		prev = next
	}
}

Armed with this simple wrapper, we can rewrite the example:

func main() {
	log := hclog.New(&hclog.LoggerOptions{JSONFormat: true})
	if err := g1(log); err != nil {
		log.Error("main: g1 failed", logwrap.Pairs(err)...)  // <= changed
	}
}

func g1(log hclog.Logger) error {
	connID := 123
	connLog := log.With("connID", connID)
	connLog.Info("g1: inside")
	if err := g2(connLog); err != nil {
		return logwrap.Err("g2 failed", err, connLog.ImpliedArgs())  // <= changed
	}
	return nil
}

func g2(log hclog.Logger) error {
	sessID := 456
	sessLog := log.With("sessID", sessID)
	sessLog.Info("g2: inside")
	if _, err := os.Open("/non-existent"); err != nil {
		return logwrap.Err("open failed", err, sessLog.ImpliedArgs()) // <= changed
	}
	return nil
}

Let’s run it and pass the output to jq for pretty-printing:

{
  "@level": "info",
  "@message": "g1: inside",
  "connID": 123
}
{
  "@level": "info",
  "@message": "g2: inside",
  "connID": 123,
  "sessID": 456
}
{
  "@level": "error",
  "@message": "main: g1 failed",
  "error": "g2 failed: open failed: open /non-existent: no such file or directory",
  "connID": 123, <== visible and searchable!
  "sessID": 456  <== visible and searchable!
}

:-)

Conclusions

Note that this wrapper is independent from the logging package, as long as said package:

has a function to return the key/value pairs as a []interface{}.
has at least one generic logging function that accepts a variadic list of arguments, along the lines of
```
Level(msg string, args ...interface{})
```

I created a small package, called logwrap, that contains the code explained here and some tests, but the code is so short that you may want to follow the Go proverb A little copying is better than a little dependency and just copy and paste it into your code.

The code in this article is released under the MIT license.

#go #golang #best practices #structured logging #error handling