Go 1.21 slog plans (standard-lib Structured Logger)

[protolambda]

Go introduces log/slog in v1.21, a structured logger very similar to the go-ethereum log package.
Rather than ignoring the standard-lib, I think it would be nice to create compatibility, and interop more easily with any other Go projects that use the same slog interfaces.

Slog introduction

See https://go.dev/blog/slog (22 Aug 2023) for context from the Go maintainers.

Quick summary of slog functionality to compare it to Geth:

package ethereum

import (
	"context"
	"errors"
	"io"
	"log/slog"
	"os"
	"testing"
	"testing/slogtest"
)

func TestSLog(t *testing.T) {
	// slog.Level - int level, *with room between levels*.
	// Can add "notice" (google, nimbus) or "crit" and "trace" (geth today) levels

	// slog.Attr - simple Key-Value struct

	// slog.Handler interface:
	// Enabled(context.Context, Level) bool    - check if lvl is enabled
	// Handle(context.Context, Record) error   - process record
	// WithAttrs(attrs []Attr) Handler         - extend with context attributes
	// WithGroup(name string) Handler          - extend and group next attributes

	// there are a two default handlers:
	_ = slog.NewTextHandler(io.Discard, &slog.HandlerOptions{
		AddSource:   false, // with source-code position
		Level:       nil,   // log-level filterer (that can change its level dynamically)
		ReplaceAttr: nil,   // func to replace context attributes (e.g. hide secrets from logs)
	})
	h := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})

	// the handler processes records;
	// slog.Record - like log.Record

	//
	logger := slog.New(h)
	logger.Handler() // can retrieve the handler
	// simple logging:
	logger.Warn("fire", "err", errors.New("oh no"))
	logger.Warn("hello", "a", 123)
	logger.Info("world", "b", "foo")
	logger.Debug("test", "a", "A", "B", "b")
	// with context:
	// (to provide context values for handler to add to record, not necessarily to time out, no error returned)
	ctx := context.Background()
	logger.WarnContext(ctx, "fire", "err", errors.New("oh no"))
	logger.DebugContext(ctx, "hello", "a", 123)
	logger.InfoContext(ctx, "world", "b", "foo")
	logger.WarnContext(ctx, "test", "a", "A", "B", "b")
	// can log custom levels like: (there's room between each standard log level for exactly this)
	logger.Log(ctx, slog.LevelDebug+1, "custom trace", "attribute-context", "example")

	// can check if a log level is enabled
	logger.Enabled(context.Background(), slog.LevelDebug)
	// Explicit attribute typing and K/V pairing, for efficiency
	logger.LogAttrs(ctx, slog.LevelDebug+1, "hello", slog.Attr{Key: "foobar", Value: slog.Int64Value(1234)})
	logger.With("outside", 123).WithGroup("inside").With("inner-attribute", "42").Info("group test")

	// global logger logs to Default(), similar to geth log.Root()
	// But it would be better not to use this as much as possible, for testing readability.
	slog.Log(context.Background(), slog.LevelDebug, "hello world")

	{
		// slogtest is a handler-implementation tester, returning the joined error,
		// not a test-logger like you may expect
		h := slog.NewJSONHandler(io.Discard, nil)
		err := slogtest.TestHandler(h, func() []map[string]any {
			return nil // return expected structured log (would need to parse from the now discarded data)
		})
		if err != nil { // expected, test is not complete
			t.Logf("slogtest error: %v", err)
		}
	}
}

slog Support

To support slog I would suggest to:

• Deprecate geth SetHandler(h) on log.Logger;
  completely swapping the handler dynamically is not necessary, and not supported by slog.
• Implement the Geth log.Logger interface with a new slog.Logger wrapper,
  to pass an slog.Logger into any existing Geth code.
• Above wrapper can be compatible with both log.Logger and slog.Logger interfaces,
  so Geth can pass its logger into dependencies that do leveled logging.
• slog.Handler interface implemented by wrapper around log.Handler,
  to direct any slog records to existing geth log handlers. (since Geth has many log handlers that we probably want to keep supporting)
• Add a SlogLevel() method to Geth log.Lvl type, to translate it easily.
• Define slog.Level "crit" and "trace" constant ints.

Additional logging improvements

Happy to split these up in different issues, but if we're making some changes to logging then I think these will be relatively low lift to support as well:

Avoid global logger

• When writing integration tests, adding context attributes to a logger is very valuable.
  E.g. distinguishing node A and node B in a test. This does not work with global logging.
• When running many tests in parallel,
  the test-logger ensures the different log-data is not scrambled as much across tests,
  like what would happen with std-out.
• Changing the global logger to a test-logger in a test is a no-no,
  as a test fails if a test-logger is written to after test-completion.

Geth testlog improvements

• Expose testlog as public-facing package: everyone who builds on top of Geth likes to test with this logger too!
  We currently maintain a copy (with a copy of the license) in its own exported package here:
  https://github.com/ethereum-optimism/optimism/tree/develop/op-service/testlog
• Minor testlog improvements: we added dynamic padding to the start, to handle the varying source-file length, to align more of the log messages for a more readable output.
• Make testlog implement the slog.Handler

[holiman]

For sure we're keen on slog, however, our policy is to support the two latest golang versions. Which right now are 1.21 and 1.20, so we can't move on slog until 1.22 is released. @jwasinger is already looking into it though

[protolambda]

@holiman deprecating SetHandler on the geth logger, in favor of creating a new logger around a handler, would be nice to do pre-Go-1.22, since that handler-setting isn't supported by slog, and I don't believe it's really used all that much anyway.

[jwasinger]

Hey @protolambda , I have an open draft PR on Geth to integrate slog. After reading your suggestions in this issue, and further looking into slog examples, there are a few changes I want to push to it.

Regarding the points you bring up around supporting slog:

Deprecate geth SetHandler(h) on log.Logger;
completely swapping the handler dynamically is not necessary, and not supported by slog.

This sounds reasonable. We can preserve ability to modify the root logger via a method SetDefault(log.Logger) in the log package (the same as what slog does).

• Implement the Geth log.Logger interface with a new slog.Logger wrapper,
  to pass an slog.Logger into any existing Geth code.
• Above wrapper can be compatible with both log.Logger and slog.Logger interfaces, so Geth can pass its logger into dependencies that do leveled logging.

slog.Logger is a struct not an interface.

My draft PR currently wraps an slog.Logger instance behind a type that implements log.Logger.

Some additional options are:

1. expose a log package method to instantiate a log.Logger directly from an existing slog.Logger.
2. allow log.Logger to leak the underlying slog.Logger via an interface method.

I'm more inclined to 1 and not 2. But would be good to factor in the specific use-cases of users of Geth codebase when evaluating.

slog.Handler interface implemented by wrapper around log.Handler,
to direct any slog records to existing geth log handlers. (since Geth has many log handlers that we probably want to keep supporting)

This is implemented in the draft PR as well.

• Add a SlogLevel() method to Geth log.Lvl type, to translate it easily.
• Define slog.Level "crit" and "trace" constant ints.

👍 Currently, the draft PR preserves the same values for level constants as Geth does now. But it makes sense to keep consistency with slog conventions. I will change this in the PR.

[karalabe]

Geth's master switched over to using golang.org/x/exp/slog, so we're kind of one step closer to doing the integration, but we need to wait for Go 1.22 to make the final switch. Should land in 2 months or so, so, almost there. Closing this issue in the mean time.