Skip to content

SlogLogger loses error context #1265

@oPOCCOMAXAo

Description

@oPOCCOMAXAo

Describe the bug
In function slogErr errors are converted into string and lose metadata, like stacktrace or extra fields of error structs.

//fxevent/slog.go:270
func slogErr(err error) slog.Attr {
 	return slog.String("error", err.Error())
}

To Reproduce
Example:

package example

import (
	"context"
	"fmt"
	"log/slog"
	"testing"

	"github.com/pkg/errors"
	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"go.uber.org/fx"
	"go.uber.org/fx/fxevent"
)

type TestService struct{}

func NewTestService(
	lc fx.Lifecycle,
) *TestService {
	lc.Append(fx.Hook{
		OnStart: func(context.Context) error {
			return errors.WithStack(assert.AnError)
		},
	})

	return &TestService{}
}

var _ slog.Handler = (*CustomLogger)(nil)

type CustomLogger struct {
	SeenError bool
	Text      string
}

func (c *CustomLogger) Enabled(context.Context, slog.Level) bool { return true }

func (c *CustomLogger) Handle(_ context.Context, rec slog.Record) error {
	rec.Attrs(func(attr slog.Attr) bool {
		if err, ok := attr.Value.Any().(error); ok && err != nil {
			c.SeenError = true
		}

		if attr.Key == "error" {
			c.Text = attr.Value.String()
		}

		return true
	})

	return nil
}

func (c *CustomLogger) WithAttrs([]slog.Attr) slog.Handler { return c }

func (c *CustomLogger) WithGroup(string) slog.Handler { return c }

func TestExample(t *testing.T) {
	slogHandler := CustomLogger{}

	app := fx.New(
		fx.WithLogger(func() fxevent.Logger {
			return &fxevent.SlogLogger{
				Logger: slog.New(&slogHandler),
			}
		}),
		fx.Provide(NewTestService),
		fx.Invoke(func(_ *TestService, sd fx.Shutdowner) {
			sd.Shutdown()
		}),
	)

	err := app.Start(context.Background())
	require.Error(t, err, "test error")

	<-app.Done()

	assert.False(t, slogHandler.SeenError)
	assert.Equal(t, "assert.AnError general error for testing", slogHandler.Text)

	// here partial checks as path is not stable from machine to machine
	fullErrorText := fmt.Sprintf("%+v", err)
	t.Log(fullErrorText)
	assert.Contains(t, fullErrorText, "assert.AnError")
	assert.Contains(t, fullErrorText, "example_test.go:23")
	assert.Contains(t, fullErrorText, "go.uber.org/fx@v1.23.0/internal/lifecycle/lifecycle.go:265")
}

Here slog handler doesn't have access to original error, but receives untraceable string.

Original error has extra data - stacktrace, which could be retrieved in slog handler like this:

	// here partial checks as path is not stable from machine to machine
	fullErrorText := fmt.Sprintf("%+v", err)
	t.Log(fullErrorText)
	assert.Contains(t, fullErrorText, "assert.AnError")
	assert.Contains(t, fullErrorText, "example_test.go:23")
	assert.Contains(t, fullErrorText, "go.uber.org/fx@v1.23.0/internal/lifecycle/lifecycle.go:265")

Also repo with code: https://github.com/oPOCCOMAXAo/fxexample/blob/master/example_test.go

Expected behavior

Custom slog Handler must access to original error value and process it as required by business logic. Like in this example:

func (c *CustomLogger) Handle(_ context.Context, rec slog.Record) error {
	rec.Attrs(func(attr slog.Attr) bool {
		if err, ok := attr.Value.Any().(error); ok && err != nil {
			c.SeenError = true
		}

		if attr.Key == "error" {
			c.Text = attr.Value.String()
		}

		return true
	})

	return nil
}

Additional context

This will fix the issue:

//fxevent/slog.go:270
func slogErr(err error) slog.Attr {
 	return slog.Any("error", err)
}

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions