Context.Stack() not working

[sylvain101010]

What happened:
Using Context.Stack().Logger() does not work, the stack is not added to each log entries.

What you expected to happen:
The stack field should be added to each log entries

How to reproduce it (as minimally and precisely as possible):

package main

import (
	"github.com/pkg/errors"

	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
	"github.com/rs/zerolog/pkgerrors"
)

func myFunc() {

	err := errors.New("my error")
	err = errors.WithStack(errors.Wrap(err, "something failed"))

	log.Error().Err(err).Msg("hello world")
}

func main() {
	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack

	log.Logger = log.With().Str("my", "field").Stack().Logger()
	myFunc()
}

Anything else we need to know?:

I think it comes from the fact that Context.Stack() setup an Hook which is called after the event is completely built, so Err never see that Stack() was enabled.
We can see it because the following example works as expected:

package main

import (
	"github.com/pkg/errors"

	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
	"github.com/rs/zerolog/pkgerrors"
)

func myFunc() {

	err := errors.New("my error")
	err = errors.WithStack(errors.Wrap(err, "something failed"))

	log.Error().Stack().Err(err).Msg("hello world")
}

func main() {
	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack

	log.Logger = log.With().Str("my", "field").Logger()
	myFunc()
}

I'm not sure how to fix this. One solution could be to add a stack field to Logger which would be transferred to the event in logger.newEvent.

[rs]

What would be a good use-case for putting a stack in a context?

[sylvain101010]

If, for performance reasons, we want to enable stack logging only in precise points of fhe application.

[rs]

I would imagine the use of Stack with error message, so only on events.

[sylvain101010]

+1, so maybe we could remove the Context.Stack() method which is misleading.

[rs]

I would favor that yes. As a non-user of this specific feature, I wanted to understand the use first.

[sylvain101010]

After refactoring, it seems that the good way to achieve what I tried to do (stack trace on events where level >= FatalLevel) is to use a Hook. So no need for Context.Stack().

[rs]

Do you want to update your PR to remove it?

[sylvain101010]

Hi. Sorry my claims were false (because I use a fork of zerolog where it works).

Adding a hook to add stack traces or not, according to the event's level does not work (for the reasons in the first comment).

For instance

package main

import (
	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
	"github.com/rs/zerolog/pkgerrors"

	"github.com/pkg/errors"
)

type stackHook struct{}

func (h stackHook) Run(e *zerolog.Event, level zerolog.Level, msg string) {
	if level >= zerolog.FatalLevel {
		e.Stack()
	}
}

func main() {
	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack

	log.Logger = log.Hook(stackHook{})

	err := errors.New("my error")
	err = errors.WithStack(errors.Wrap(err, "something failed"))

	log.Fatal().Err(err).Msg("unrecoverable")
}

which seems a legitimate use case, does not work. I'm not sure if it's a feature or a bug.

[rs]

The problem is that e.Stack() is adding a hook, and the way we iterate over hooks during write does not take into consideration new hooks added during the hook execution phase. It could easily be fixed by replacing the type of for loop in Event.msg() I think.

[mec07]

I actually made a PR for this very issue, a while ago... #144 (I'm currently using my own fork of pkgerrors https://github.com/mec07/zerolog/tree/multi-stack/pkgerrors until the PR gets merged in)

[sylvain101010]

Hi,
Sorry for the delay...

On my side I step down on this issue as I no longer use Go.

Bets regards,
Sylvain

[joshatintegris]

So my expectation from reading the docs is that by creating a logger with context by calling With().Stack().Logger() I should get a stacktrace when I call log.Err(errors.New("testing 1 2 3")) but that does not happen because when the hooks from the With().Stack() context aren't processed until Msg() is called, which is after the Event.Err() function runs where it's looking for e.stack to be true. Since the logger hook from the context has not been called yet, it's always false. So the only way around it now is to call log.Error().Stack().Err(...) which is not what you necessarily want to do. For example, I only want to enable stacktrace output with errors when a user specifies a --debug flag, so I'd like to create a logger with Stack() context at runtime. I think if you can just update the logic of the Err() function in events.go, that should fix the issue.

[larsla]

I also have this problem and created a PR a while back: #179

[xmlking]

zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack

logr = zerolog.New(l.opts.Out).
			Level(zerolog.InfoLevel).
			With().Timestamp().Stack().Logger()
# not printing Stack
logr.Error().Err(r.err).Msgf(format, args...)
# this will print Stack
logr.Error().Stack().Err(r.err).Msgf(format, args...)

I was expecting Stack hook should automatically enable Stack priniting but looks like I have to still call
logr.Error().Stack().Err(r.err).Msgf(format, args...)

[joshhe]

Thanks for fixing this! Is this fix released? If so, what version?

[bvisness]

It was released in version v1.21.0: https://github.com/rs/zerolog/releases/tag/v1.21.0

However, there have been many versions released since then too.

[gelouko]

Trying on 1.26.1 (Golang 1.18) and this is still not working here :(

Tested the example in readme:

func main() {
	zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack

	err := outer()
	log.Error().Stack().Err(err).Msg("")
}

func inner() error {
	return errors.New("seems we have an error here")
}

func middle() error {
	err := inner()
	if err != nil {
		return err
	}
	return nil
}

func outer() error {
	err := middle()
	if err != nil {
		return err
	}
	return nil
}

It logged

{"level":"error","error":"seems we have an error here","time":1653573551}

[gelouko]

NVM, I was using Go's default error library instead of pkgErrors'

[joshhe]

It actually works for me on 1.26.1. Are you using golang standard errors package? If so, you need to switch to pkg/errors for it to work.

…

On Thu, May 26, 2022 at 4:00 AM Giulio Denardi ***@***.***> wrote: Trying on 1.26.1 and this still is not working here :( Tested the example in readme: func main() { zerolog.TimeFieldFormat = zerolog.TimeFormatUnix zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack err := outer() log.Error().Stack().Err(err).Msg("") } func inner() error { return errors.New("seems we have an error here") } func middle() error { err := inner() if err != nil { return err } return nil } func outer() error { err := middle() if err != nil { return err } return nil } It logged {"level":"error","error":"seems we have an error here","time":1653573551} — Reply to this email directly, view it on GitHub <#129 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAQ45M72GNNNCW2ARCD6TETVL57Y3ANCNFSM4GUT456Q> . You are receiving this because you commented.Message ID: ***@***.***>