How to put the "real" stack trace under the "stacktrace" key, instead of the "msg" key?

Question

Given the following code (copied from here):

     1  package main
     2  
     3  import (
     4      "fmt"
     5  
     6      "github.com/pkg/errors"
     7  
     8      "go.uber.org/zap"
     9  )
    10  
    11  func main() {
    12      logger, _ := zap.NewProduction()
    13      defer logger.Sync()
    14  
    15      sugar := logger.Sugar()
    16      result, err := caller1()
    17      if err != nil {
    18          sugar.Error(err)
    19          return
    20      }
    21      fmt.Println("Result: ", result)
    22  }
    23  
    24  func caller1() (int, error) {
    25      err := caller2()
    26      if err != nil {
    27          return 0, err
    28      }
    29      return 1, nil
    30  }
    31  
    32  func caller2() error {
    33      doSomething()
    34      return caller3()
    35  }
    36  
    37  func caller3() error {
    38      return errors.New("failed")
    39  }
    40  
    41  func doSomething() {}

Since we are using github.com/pkg/errors package, I know that to log the stack trace, just use sugar.Errorf("%+v", err):

$ go run stacktrace.go 2>&1 | jq
{
  "level": "error",
  "ts": 1606501191.539652,
  "caller": "zap/stacktrace.go:18",
  "msg": "failed\nmain.caller3\n\t/Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:38\nmain.caller2\n\t/Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:34\nmain.caller1\n\t/Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:25\nmain.main\n\t/Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:16\nruntime.main\n\t/usr/local/Cellar/go/1.15.2/libexec/src/runtime/proc.go:204\nruntime.goexit\n\t/usr/local/Cellar/go/1.15.2/libexec/src/runtime/asm_amd64.s:1374",
  "stacktrace": "main.main\n\t/Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:18\nruntime.main\n\t/usr/local/Cellar/go/1.15.2/libexec/src/runtime/proc.go:204"
}

The thing is the stack trace is put under the msg key and the one under the stacktrace is the stack trace of the logging line:

main.main
    /Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:18
runtime.main
    /usr/local/Cellar/go/1.15.2/libexec/src/runtime/proc.go:204

not the stack trace of the error:

main.caller3
    /Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:38
main.caller2
    /Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:34
main.caller1
    /Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:25
main.main
    /Users/quanta/go/src/github.com/quantonganh/zap/stacktrace.go:16
runtime.main
    /usr/local/Cellar/go/1.15.2/libexec/src/runtime/proc.go:204
runtime.goexit
    /usr/local/Cellar/go/1.15.2/libexec/src/runtime/asm_amd64.s:1374

Question: how can I log the "real" stack trace under the stacktrace key?

Answer 1

I have looked into the source code and I think we cannot do that.

Log messages are formatted and put under the msg key.

The stack trace is taken from runtime.CallersFrames at the time of logging.

The reason I asked this question is before using %+v to get the complete call stack, I just looked at the "stacktrace" value and wondering:

• Why it is missing?
• Why it just point to the logging line instead of pointing to the actual error?

Answer 2

You should instead use sugar.Errorw("Error", "error", err) to log the error. zap extracts the stack trace from the error and stores it under errorVerbose key. Example (demo):

package main

import (
    "fmt"

    "github.com/pkg/errors"

    "go.uber.org/zap"
)

func main() {
    logger, _ := zap.NewProduction()
    defer logger.Sync()

    sugar := logger.Sugar()
    result, err := caller1()
    if err != nil {
        sugar.Errorw("Error", "error", err)
        return
    }
    fmt.Println("Result: ", result)
}

func caller1() (int, error) {
    err := caller2()
    if err != nil {
        return 0, err
    }
    return 1, nil
}

func caller2() error {
    doSomething()
    return caller3()
}

func caller3() error {
    return errors.New("failed")
}

func doSomething() {}

It is not really under the stacktrace field, but it is close enough I think. (stacktrace field can then be used by zap itself.)

If you dislike that errors' stack traces are all cramped into one string inside JSON with newlines and tabs and are hard to read, then you are right. So instead of deprecated github.com/pkg/errors you can use gitlab.com/tozd/go/errors instead, which works as drop-in replacement. (Disclaimer: I am its maintainer.) Then you can do (demo):

package main

import (
    "encoding/json"
    "fmt"

    "gitlab.com/tozd/go/errors"
    "go.uber.org/zap"
)

func main() {
    logger, _ := zap.NewProduction()
    defer logger.Sync()

    sugar := logger.Sugar()
    result, err := caller1()
    if err != nil {
        e, _ := json.Marshal(err)
        sugar.Errorw("Error", "error", json.RawMessage(e))
        return
    }
    fmt.Println("Result: ", result)
}

func caller1() (int, error) {
    err := caller2()
    if err != nil {
        return 0, err
    }
    return 1, nil
}

func caller2() error {
    doSomething()
    return caller3()
}

func caller3() error {
    return errors.New("failed")
}

func doSomething() {}

This encodes the error as JSON and stack trace is also a JSON array of objects. Output (rewrapped):

{
  "level": "error",
  "ts": 1257894000,
  "caller": "sandbox818275646/prog.go:19",
  "msg": "Error",
  "error": {
    "error": "failed",
    "stack": [
      {
        "name": "main.caller3",
        "file": "/tmp/sandbox818275646/prog.go",
        "line": 39
      },
      {
        "name": "main.caller2",
        "file": "/tmp/sandbox818275646/prog.go",
        "line": 35
      },
      {
        "name": "main.caller1",
        "file": "/tmp/sandbox818275646/prog.go",
        "line": 26
      },
      {
        "name": "main.main",
        "file": "/tmp/sandbox818275646/prog.go",
        "line": 16
      },
      {
        "name": "runtime.main",
        "file": "/usr/local/go-faketime/src/runtime/proc.go",
        "line": 267
      },
      {
        "name": "runtime.goexit",
        "file": "/usr/local/go-faketime/src/runtime/asm_amd64.s",
        "line": 1650
      }
    ]
  },
  "stacktrace": "main.main\n\t/tmp/sandbox818275646/prog.go:19\nruntime.main\n\t/usr/local/go-faketime/src/runtime/proc.go:267"
}

Errors made with gitlab.com/tozd/go/errors can be converted to JSON, which we use here.