The Grumpy Troll

Ramblings of a grumpy troll.

Go error construction loop

One of the really nice things about the Go programming language is that you have the complete source to the compiler and the standard library, as very readable code which can be used to investigate problems.

When merging a feature branch in a git repo I, of course, rebuilt my test frontend server to be sure everything still worked, as a check before committing. So I found that a client call was never returning, while my program was now chewing a whole CPU. (MacOS top(1) will sort by CPU usage; type ‘o’, then “-cpu” and Enter).

The first easiest pass to figure out what's going on does not even involve opening a debugger. Programs written in Go will dump out a stack trace for all Go-routines (on the way to exiting) when the program receives a SIGQUIT. The “stty -a” command will show the terminal settings for sending the signal, but it's normally control-backslash.

In one of the routines, I saw this repeated a lot (sorry for the long lines wrapping in this blog post, I only edited for names, not to re-layout):

fmt.Sprintf(0x24e08c, 0x656d614e00000012, 0xe12a4208, 0x100000001, 0xf87b255d20, ...)
  /usr/local/go/src/pkg/fmt/print.go:228 +0x5d$employer/$repo/storage.NameNotFound.Error(0xf848d0afb8, 0x4, 0x1c3530, 0xf87b25b6e0, 0x32692, ...)
  /Users/$grumpytroll/src/go/src/$employer/$repo/storage/storage.go:60 +0x9f$employer/$repo/storage.(*NameNotFound).Error(0xf87b255d00, 0x1eaa78, 0xf87b255d00, 0xf800000073)
  /Users/$grumpytroll/src/go/src/$employer/$repo/storage/storage.go:0 +0x6d
fmt.(*pp).handleMethods(0xf87b25c840, 0x73, 0x0, 0xf87b250100, 0x0, ...)
  /usr/local/go/src/pkg/fmt/print.go:698 +0x33a
fmt.(*pp).printField(0xf87b25c840, 0x1eaa78, 0xf87b255d00, 0x73, 0x0, ...)
  /usr/local/go/src/pkg/fmt/print.go:737 +0x275
fmt.(*pp).doPrintf(0xf87b25c840, 0x24e08c, 0x12, 0xe12a46b8, 0x100000001, ...)
  /usr/local/go/src/pkg/fmt/print.go:1078 +0x10ae
fmt.Sprintf(0x24e08c, 0x656d614e00000012, 0xe12a46b8, 0x100000001, 0xf87b255d00, ...)
  /usr/local/go/src/pkg/fmt/print.go:228 +0x5d$employer/$repo/storage.NameNotFound.Error(0xf848d0afb8, 0x4, 0x1c3530, 0xf87b25b690, 0x32692, ...)
  /Users/$grumpytroll/src/go/src/$employer/$repo/storage/storage.go:60 +0x9f$employer/$repo/storage.(*NameNotFound).Error(0xf87b255ce0, 0x1eaa78, 0xf87b255ce0, 0xf800000073)
  /Users/$grumpytroll/src/go/src/$employer/$repo/storage/storage.go:0 +0x6d

This is clearly a recursion loop. Note though the standard library errors refer to the source files on disk for the standard library. This meant that I could go read the source for the fmt package and understand why the loop was happening.

src/pkg/fmt/print.go in handleMethods() looks to see if a type matches the Error interface, before it checks if it's a string, and calls Error() to get the value, so an Error() method which calls fmt.Sprintf() with itself as a parameter to a %s expansion item will enter a recursion loop.

In this case the code, which had been merged to master but which my code was exercising, was:

type NameNotFound string
func (n NameNotFound) Error() string {
  return fmt.Sprintf("Name not found: %s", n)

The simplest fix for the merge was to use ‘string(n)” instead of “n” for the parameter.

-The Grumpy Troll
Categories: git debugging golang