How to use pkg/errors to annotate error & pretty print stack trace in golang?

Question

Consider the following code (https://go.dev/play/p/hDOyP3W_lqW)

package main

import (
    "log"

    "github.com/pkg/errors"
)

func myError() error {
    return errors.New("failing unconditionally")
}

func myError1() error {
    return errors.Errorf("annotate with additional debug info: %+v", myError())
}

func myError2() error {
    return errors.Errorf("extra debug info: %+v", myError1())
}

func main() {
    if err := myError2(); err != nil {
        log.Printf("%+v", err)
    }
}

I originate the error with errors.New and annotate it with additional info using errors.Errorf.

It does what I want--record and print the stack trace & line number. However, the problem is that the output of log.Printf("%+v", err) is verbose and repetitive:

2009/11/10 23:00:00 extra debug info: annotate with additional debug info: failing unconditionally
main.myError
    /tmp/sandbox3329712514/prog.go:10
main.myError1
    /tmp/sandbox3329712514/prog.go:14
main.myError2
    /tmp/sandbox3329712514/prog.go:18
main.main
    /tmp/sandbox3329712514/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:250
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1571
main.myError1
    /tmp/sandbox3329712514/prog.go:14
main.myError2
    /tmp/sandbox3329712514/prog.go:18
main.main
    /tmp/sandbox3329712514/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:250
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1571
main.myError2
    /tmp/sandbox3329712514/prog.go:18
main.main
    /tmp/sandbox3329712514/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:250
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1571

iiuc, errors package appends an additional copy of stack trace to the error every time of annotating the error, as can be seen in the below snippet

// repetitive (thrice) error stack
main.myError
    /tmp/sandbox3329712514/prog.go:10
main.myError1
    /tmp/sandbox3329712514/prog.go:14
main.myError2
    /tmp/sandbox3329712514/prog.go:18
main.main
    /tmp/sandbox3329712514/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:250
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1571
main.myError1
    /tmp/sandbox3329712514/prog.go:14
main.myError2
    /tmp/sandbox3329712514/prog.go:18
main.main
    /tmp/sandbox3329712514/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:250
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1571
main.myError2
    /tmp/sandbox3329712514/prog.go:18
main.main
    /tmp/sandbox3329712514/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:250
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1571

My desired output is

// Desired output
2009/11/10 23:00:00 extra debug info: annotate with additional debug info: failing unconditionally
main.myError
    /tmp/sandbox3329712514/prog.go:10
main.myError1
    /tmp/sandbox3329712514/prog.go:14
main.myError2
    /tmp/sandbox3329712514/prog.go:18
main.main
    /tmp/sandbox3329712514/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:250
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1571

One way to achieve that is to only use the errors package to originate the error and then use fmt.Errorf with %+v to add additional info in the call stack (like this https://go.dev/play/p/OrWe6KUIL_m). However, it's error-prone and hard to enforce every developer to use this pattern in a large code base. Developers have to remember to use the errors package to originate the error and use fmt properly with %+v %s to print out the stack trace.

I'm wondering if this is the desired behavior (verbose and repetitive). And is it possible to consistently use the errors package to annotate errors along the call stack without worrying about appending repetitive stack trace copies (e.g., the errors magically knows the error already has a stack trace)?

Answer 1

You could use errors.Wrap() along with errors.Cause() function to retrieve the first cause of error

package main

import (
    "log"

    "github.com/pkg/errors"
)

func myError() error {
    return errors.New("failing unconditionally")
}

func myError1() error {
    return errors.Wrap(myError(), "annotate with additional debug info")
}

func myError2() error {
    return errors.Wrap(myError1(), "extra debug info")
}

func main() {
    if err := myError2(); err != nil {
        log.Println(err)
        log.Printf("%+v", errors.Cause(err))
    }
}

Output:

2009/11/10 23:00:00 extra debug info: annotate with additional debug info: failing unconditionally
2009/11/10 23:00:00 failing unconditionally
main.myError
    /tmp/sandbox3114780755/prog.go:10
main.myError1
    /tmp/sandbox3114780755/prog.go:14
main.myError2
    /tmp/sandbox3114780755/prog.go:18
main.main
    /tmp/sandbox3114780755/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:272
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1700

Link to Go Playground

Answer 2

I made a spiritual successor of github.com/pkg/errors named gitlab.com/tozd/go/errors some time ago which addresses a long list of issues github.com/pkg/errors has. Here are relevant two:

• My errors package records a stack trace only if the error you are wrapping does not already contain it (and there is errors.Wrap if you want to force recording a stack trace again).
• You can use %w format verb in errors.Errorf which wraps original error with standard Go wrapping.

You can use it as mostly drop-in replacement for github.com/pkg/errors. So your example above would just work by changing the import and using %w:

package main

import (
    "log"

    "gitlab.com/tozd/go/errors"
)

func myError() error {
    return errors.New("failing unconditionally")
}

func myError1() error {
    return errors.Errorf("annotate with additional debug info: %w", myError())
}

func myError2() error {
    return errors.Errorf("extra debug info: %w", myError1())
}

func main() {
    if err := myError2(); err != nil {
        log.Printf("%+v", err)
    }
}

Output:

2009/11/10 23:00:00 extra debug info: annotate with additional debug info: failing unconditionally
main.myError
    /tmp/sandbox3373322165/prog.go:10
main.myError1
    /tmp/sandbox3373322165/prog.go:14
main.myError2
    /tmp/sandbox3373322165/prog.go:18
main.main
    /tmp/sandbox3373322165/prog.go:22
runtime.main
    /usr/local/go-faketime/src/runtime/proc.go:267
runtime.goexit
    /usr/local/go-faketime/src/runtime/asm_amd64.s:1650

Answer 3

I don't particularly like github.com/pkg/errors, so I wrote my own package with similar behavior where I can control the format of my stack.

You can find my package in github.com/go-msvc/errors and copy or change it as you like.

It does not have a errors.New(), only errors.Error() which does the same. You can change that in your copy to be consistent with the standard one (I will too).

I also wrap errors with errors.Wrapf(err, "...xxx failed..."). If you just append inside a string like you did, the formatter cannot traverse the layers.

So, when I take your main.go and change:

• New() to Error(),
• Errorf("....: %+v", err) to Wrapf(err, "..."), and
• import github.com/go-msvc/errors, Then it outputs this:

2022/07/14 13:35:33 main.go(18):extra debug info because main.go(14):annotate with additional debug info because main.go(10):failing unconditionally

That works for me and avoids lots of clutter in the stack.

If you want newlines, you can add that too, but I prefer my error messages in my log files not to have newlines.

Code:

package main

import (
    "log"

    "github.com/go-msvc/errors"
)

func myError() error {
    return errors.Error("failing unconditionally")
}

func myError1() error {
    return errors.Wrapf(myError(), "annotate with additional debug info")
}

func myError2() error {
    return errors.Wrapf(myError1(),"extra debug info")
}

func main() {
    if err := myError2(); err != nil {
        log.Printf("%+v", err)
    }
}

Answer 4

there are v format specifiers for printing an error.

%s - print the error. If the error has a Cause it will be printed recursively.

%v – It will print only values. The field name will not be printed. This is the default way of printing a struct when using Println (print the error 👉🏻 If the error has a Cause it will be printed recursively.)

%+v – It will print both field and value. (extended format. Each Frame of the error's StackTrace will be printed in detail.)

In your case:

func myerror() error {
    return errors.New("failing unconditionally") // 1️⃣
}

func myerror1() error {
    return errors.Errorf("annotate with additional debug info: %+v", myerror()) // 2️⃣
}

func myerror2() error {
    return errors.WithStack(myerror1()) // 3️⃣
}

1️⃣ create new error with stack file (errors.New)

2️⃣ create new error with "formatted" message and this error stack (errors.Errorf)

3️⃣ create new error with this error stack (errors.WithStack)

2022/07/13 11:42:03 annotate with additional debug info: failing unconditionally
github.com/kozmod/idea-tests/core/errors.myerror
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:10 // 1️⃣
github.com/kozmod/idea-tests/core/errors.myerror1
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:14
github.com/kozmod/idea-tests/core/errors.myerror2
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:18
github.com/kozmod/idea-tests/core/errors.TestStack.func1
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:35
testing.tRunner
    /Library/GoLang/go1.18.2.darwin-amd64/src/testing/testing.go:1439
runtime.goexit
    /Library/GoLang/go1.18.2.darwin-amd64/src/runtime/asm_amd64.s:1571
github.com/kozmod/idea-tests/core/errors.myerror1
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:14 // 2️⃣
github.com/kozmod/idea-tests/core/errors.myerror2
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:18
github.com/kozmod/idea-tests/core/errors.TestStack.func1
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:35
testing.tRunner
    /Library/GoLang/go1.18.2.darwin-amd64/src/testing/testing.go:1439
runtime.goexit
    /Library/GoLang/go1.18.2.darwin-amd64/src/runtime/asm_amd64.s:1571
github.com/kozmod/idea-tests/core/errors.myerror2
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:18 // 3️⃣
github.com/kozmod/idea-tests/core/errors.TestStack.func1
    /Users/19798572/GolandProjects/idea-tests/core/errors/stack_test.go:35
testing.tRunner
    /Library/GoLang/go1.18.2.darwin-amd64/src/testing/testing.go:1439
runtime.goexit
    /Library/GoLang/go1.18.2.darwin-amd64/src/runtime/asm_amd64.s:1571

1️⃣ start of the first error stack

2️⃣ start of the second error stack

3️⃣ start of the third error stack

You can simply create the "root" error with stack and then add message (wrap) "root" error

func myerror3() error {
    return errors.New("failing unconditionally")
}

func myerror4() error {
    return errors.WithMessage(myerror3(), "annotate with additional debug info")
}

func myerror5() error {
    return errors.WithMessage(myerror4(), "myerror5")
}

func main() {
    if err := myerror5(); err != nil {
        log.Printf("%+v", err)
    }
}

PLAYGROUND

or

func myError() error {
    // create error (github.com/pkg/errors + fmt) with stack (message)
    return fmt.Errorf("%+v", errors.New("failing unconditionally"))
}

func myError1() error {
    return fmt.Errorf("annotate with additional debug info: %v", myError())
}

func myError2() error {
    return fmt.Errorf("extra debug info: %v", myError1())
}

func main() {
    if err := myError2(); err != nil {
        log.Printf("%v", err)
    }
}

PLAYGROUND