fosite icon indicating copy to clipboard operation
fosite copied to clipboard

Why using errorsx.WithStack and not errors.WithStack

Open mitar opened this issue 4 years ago • 10 comments
trafficstars

It looks to me that using errorsx.WithStack leads to lose of information: now the only information available as a stack trace is the stack trace of original place of an error and not also stack traces of followup places where errors were processed. I find this lacking when trying to understand and debug the error.

For example, in Python, when you have a chain of exceptions, each exception has its own stack trace. The reason is that catching and (re-)raising an exception or wrapping it into another exception can happen at different places so you want to know which code path also error/exception handling wast traveling before you got to the final place where you are looking into the error.

mitar avatar Apr 08 '21 22:04 mitar

That is what errorsx.WithStack is doing. The original errors.WithStack did not include wrapped stack traces, errorsx does:

  • https://github.com/ory/x/blob/master/errorsx/errors.go#L34
  • https://github.com/pkg/errors/blob/master/errors.go#L145

aeneasr avatar Apr 14 '21 07:04 aeneasr

No? The errors.WithStack includes wrapper stack traces, it adds a stack trace every time, you just have to traverse the chain up and retrieve all of them. If you look only at the latest stack trace then it maybe looks like other stack traces are missing. You just have to walk the chain up.

errorsx.WithStack on the other hand stores and returns only the first stack trace, which then looks more useful at first (because you get the stack trace where the original error happened) but you do not have any other stack trace information available.

I think maybe the answer is that we should have errors.WithStack behavior, but instead of using error.StackTrace() we should have error.FirstStackTrace() method which returns the most inner stack trace and use then error.FirstStackTrace() in most cases when trying to get (only one) stack trace out of it.

mitar avatar Apr 14 '21 07:04 mitar

Could you maybe show an example for both stack trace results and what you would expect?

aeneasr avatar Apr 14 '21 07:04 aeneasr

OK, here is an example Go program:

package main

import (
	"encoding/json"
	"fmt"

	"github.com/ory/x/errorsx"
	"github.com/pkg/errors"
	"github.com/sirupsen/logrus"
)

func a() (error, error) {
	err1, err2 := b()
	if err1 != nil || err2 != nil {
		// Do some handling of the error.
		return c(err1, err2)
	}
	// If no error.
	return nil, nil
}

func b() (error, error) {
	// Somewhere deep there is an error.
	err := fmt.Errorf("error happened")
	// At this point, returned errors are the same.
	return errorsx.WithStack(err), errors.WithStack(err)
}

func c(err1 error, err2 error) (error, error) {
	// We handle the error.	Making sure the stack trace has been returned.
	if 1 == 2 {
		return errorsx.WithStack(err1), errors.WithStack(err2)
	} else {
		// At this point err1 contains only the original stack trace, while err2
		// contains both the original stack trace and the current stack trace.
		// To me this is like re-throwing here. So I would want both stack traces,
		// to know where and how was the error handled. "errorsx.WithStack" optimization
		// is really unnecessary, I think.
		return errorsx.WithStack(err1), errors.WithStack(err2)
	}
}

func makeFieldsFromError(err error) logrus.Fields {
	fields := logrus.Fields{
		"error": err.Error(),
	}

	fields = stacktraceErrRegisterFunc(fields, err)

	return fields
}

type StackTracer interface {
	StackTrace() errors.StackTrace
}

type causer interface {
	Cause() error
}

func stacktraceErrRegisterFunc(fields logrus.Fields, err error) logrus.Fields {
	var causerErr causer
	stackErr, ok := err.(StackTracer)
	if ok {
		fields["stack"] = stackErr.StackTrace()
	}

	causerErr, ok = err.(causer)

	if ok && causerErr.Cause() != nil {
		fields["cause"] = makeFieldsFromError(causerErr.Cause())
	} else {
		// If an error does not implement the causer interface, maybe it
		// implements (just) the standard unwrapping interface.
		wrappedErr, ok := err.(interface {
			Unwrap() error
		})
		if ok && wrappedErr.Unwrap() != nil {
			fields["wrapped"] = makeFieldsFromError(wrappedErr.Unwrap())
		}
	}
	return fields
}

func printError(err error) {
	fields := makeFieldsFromError(err)
	jsonFields, err := json.MarshalIndent(fields, "", "  ")
	if err != nil {
		panic(err)
	}
	fmt.Printf("%s\n", jsonFields)
}

func main() {
	err1, err2 := a()
	if err1 != nil {
		fmt.Printf("Error with errorx\n")
		printError(err1)
	}
	if err2 != nil {
		fmt.Printf("Error with errors\n")
		printError(err2)
	}
}

It is a bit long because I included also part of the logging code we use when logging errors and where we want to log all stack traces. The output of this program for me is:

Error with errorx
{
  "cause": {
    "error": "error happened"
  },
  "error": "error happened",
  "stack": [
    "github.com/ory/x/errorsx.WithStack /home/mitar/go/pkg/mod/github.com/ory/[email protected]/errorsx/errors.go:38",
    "main.b /home/mitar/go-errors/main.go:26",
    "main.a /home/mitar/go-errors/main.go:13",
    "main.main /home/mitar/go-errors/main.go:95",
    "runtime.main /usr/local/go/src/runtime/proc.go:255",
    "runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1581"
  ]
}
Error with errors
{
  "cause": {
    "cause": {
      "error": "error happened"
    },
    "error": "error happened",
    "stack": [
      "main.b /home/mitar/go-errors/main.go:26",
      "main.a /home/mitar/go-errors/main.go:13",
      "main.main /home/mitar/go-errors/main.go:95",
      "runtime.main /usr/local/go/src/runtime/proc.go:255",
      "runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1581"
    ]
  },
  "error": "error happened",
  "stack": [
    "main.c /home/mitar/go-errors/main.go:39",
    "main.a /home/mitar/go-errors/main.go:16",
    "main.main /home/mitar/go-errors/main.go:95",
    "runtime.main /usr/local/go/src/runtime/proc.go:255",
    "runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1581"
  ]
}

I have the following observations:

  • I do not understand why would it be worse to use errors.WithStack over errorsx.WithStack. To me it looks like errors.WithStack always have the same amount of information, but it can have more information.
  • If you are saying that you might lose the original stack trace, this is just because you have not traversed the causation chain of errors.
    • This is similar to me to Python's __cause__ which happens when you do raise Exception("foobar") from error and if you look only at the last stack trace there, it can also looks like original exception's tack trace (of error) is lost (because you see only the stack trace of raise Exception("foobar")). But you can traverse __cause__ attribute to get to the parent error. This can be made easy with utility functions and standard functions like print_exception does that for you.
  • I like more stack traces, so that you can see which is the path error handling took. If you have only the most inner stack trace then you know where the error happened and who called it, but not also how was the error handled.
  • One should probably not use directly errors.WithStack but should always use errors.Wrap instead, which adds not just the stack trace but also the context information. So then it is less confusing which stack trace belongs to where (which one is the inner most where error happened and which ones are then part of the error handling, which is adding more context every time).
  • Using errorsx adds github.com/ory/x/errorsx.WithStack to the stack.
  • Using errorsx.WithStack is very fragile, because it checks only if the latest error has a stack trace or not, and not if any of wrapped errors might have it.

TLDR: I do not see what is broken with errors.WithStack that it would require all codebase to use a custom function. I think a better and more robust solution is to fix how stacktraces are extracted from errors where you want to log them (e.g., find the most inner one) which works across all possible ways/orders to wrap errors.

mitar avatar Nov 11 '21 22:11 mitar

See this example where errorsx.WithStack backfires. You call errors.New which creates an error with a stack trace. And then when you call errorsx.WithStack(ErrNoTransactionOpen) later on, the stack trace is not set, the original one is kept. With errors.WithStack you would set a new stack trace (while keeping the old one).

Probably here one would want errorsx.WithForcedStack or something. Or maybe simple not using errors.New here.

But I am pointing out how this behavior can make some issues because it breaks what one assumes errorsx.WithStack does (wraps current stack trace, and NOT wraps current stack trace unless some other random stack trace exists).

mitar avatar Nov 15 '21 14:11 mitar

@mitar you are right. I noticed that problem also already before, that's why I avoid using errors.New and instead import the standard error package to do stderrors.New.

zepatrik avatar Nov 15 '21 14:11 zepatrik

I think it might be reasonable to introduce something like x.Serror which would be an error with a stack trace and we should set which functions are returning then x.Serror and which are not. Then you know that if you are not getting x.Serror, you should get one by calling errorsx.WithStack. And I would make it also so that if you call errorsx.WithStack on x.Serror it fails.

Because now code is really ugly, we have to call errorsx.WithStack all around, just in case if we are getting an error without a stack trace. And we have to use errorsx.WithStack and not errors.WithStack to prevent double stack traces because we do not know if we are getting an error with a stack trace or not. I think using Go type system here to help us would help a lot.

mitar avatar Nov 16 '21 23:11 mitar

Short demo example:

package main

import (
	"fmt"
	"github.com/ory/kratos/hash"
	"github.com/pkg/errors"
)

func f() error {
	return errors.WithStack(hash.ErrUnknownHashAlgorithm)
}

func main() {
	fmt.Printf("%+v\n", hash.ErrUnknownHashAlgorithm)
	fmt.Println("DOUBLE STACK TRACE:")
	fmt.Printf("%+v\n", f())
}

outputs

unknown hash algorithm
github.com/ory/kratos/hash.init
        /home/patrik/git/kratos/hash/hash_comparator.go:19
runtime.doInit
        /usr/lib/go/src/runtime/proc.go:6498
runtime.doInit
        /usr/lib/go/src/runtime/proc.go:6475
runtime.main
        /usr/lib/go/src/runtime/proc.go:238
runtime.goexit
        /usr/lib/go/src/runtime/asm_amd64.s:1581
DOUBLE STACK TRACE:
unknown hash algorithm
github.com/ory/kratos/hash.init
        /home/patrik/git/kratos/hash/hash_comparator.go:19
runtime.doInit
        /usr/lib/go/src/runtime/proc.go:6498
runtime.doInit
        /usr/lib/go/src/runtime/proc.go:6475
runtime.main
        /usr/lib/go/src/runtime/proc.go:238
runtime.goexit
        /usr/lib/go/src/runtime/asm_amd64.s:1581
main.f
        /home/patrik/git/kratos/demo.go:10
main.main
        /home/patrik/git/kratos/demo.go:16
runtime.main
        /usr/lib/go/src/runtime/proc.go:255
runtime.goexit
        /usr/lib/go/src/runtime/asm_amd64.s:1581

zepatrik avatar Nov 19 '21 13:11 zepatrik

@zepatrik I think this proves my point. Which is, making hash.ErrUnknownHashAlgorithm using errors.New is the source of problems. You do not want that value to have stack trace at all. You want it to be an error so that As and Is finds it, but there is no point in saving the stack trace there in the first place. So using errorsx.WithStack just hides the underlying issue of how are those constant error values made.

BTW, in meantime I decided to make a new package for errors which addresses those issues. I will post it here once I have something to show. It will almost like github.com/pkg/errors but without such surprises.

mitar avatar Nov 19 '21 22:11 mitar

OK, I made the package. Check it out: https://gitlab.com/tozd/go/errors

I think it is perfect reimplementation of the github.com/pkg/errors for modern Go. Feedback welcome. I think it addresses the issue described here and quite few others.

mitar avatar Nov 30 '21 22:11 mitar

Hello contributors!

I am marking this issue as stale as it has not received any engagement from the community or maintainers for a year. That does not imply that the issue has no merit! If you feel strongly about this issue

  • open a PR referencing and resolving the issue;
  • leave a comment on it and discuss ideas on how you could contribute towards resolving it;
  • leave a comment and describe in detail why this issue is critical for your use case;
  • open a new issue with updated details and a plan for resolving the issue.

Throughout its lifetime, Ory has received over 10.000 issues and PRs. To sustain that growth, we need to prioritize and focus on issues that are important to the community. A good indication of importance, and thus priority, is activity on a topic.

Unfortunately, burnout has become a topic of concern amongst open-source projects.

It can lead to severe personal and health issues as well as opening catastrophic attack vectors.

The motivation for this automation is to help prioritize issues in the backlog and not ignore, reject, or belittle anyone.

If this issue was marked as stale erroneously you can exempt it by adding the backlog label, assigning someone, or setting a milestone for it.

Thank you for your understanding and to anyone who participated in the conversation! And as written above, please do participate in the conversation if this topic is important to you!

Thank you 🙏✌️

github-actions[bot] avatar Dec 01 '22 00:12 github-actions[bot]

BTW, https://gitlab.com/tozd/go/errors has proved through time to be a great replacement for github.com/pkg/errors for us, especially now that github.com/pkg/errors is archived. Besides fixing issue with double stack traces, it also supports additional formatting options, sentinel errors, JSON marshaling, and more. @aeneasr @zepatrik I would invite you to check it out.

mitar avatar Oct 12 '23 07:10 mitar

Will do! Looks promising

aeneasr avatar Oct 12 '23 09:10 aeneasr