all: replace log15 with slog

[jwasinger]

This PR replaces Geth's logger package (a fork of log15) with an implementation using slog, a logging library included as part of the Go standard library as of Go1.21.

Main changes are as follows:

• removes any log handlers that were unused in the Geth codebase.
• Json, logfmt, and terminal formatters are now slog handlers.
• Verbosity level constants are changed to match slog constant values. Internal translation is done to make this opaque to the user and backwards compatible with existing --verbosity and --vmodule options.
• --log.backtraceat and --log.debug are removed.

The external-facing API is largely the same as the existing Geth logger. Logger method signatures remain unchanged.

A small semantic difference is that a Handler can only be set once per Logger and not changed dynamically. This just means that a new logger must be instantiated every time the handler of the root logger is changed.

---

For users of the go-ethereum/log module. If you were using this module for your own project, you will need to change the initialization. If you previously did

log.Root().SetHandler(log.LvlFilterHandler(log.LvlInfo, log.StreamHandler(os.Stderr, log.TerminalFormat(true))))

You now instead need to do

log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true)))

See more about reasoning here: #28558 (comment)

[MariusVanDerWijden]

The diff already looks promising, do you have some benchmarks for the new logging lib?

[jwasinger]

I did some benchmarks (https://github.com/ethereum/go-ethereum/blob/bf91275fc6baf3de3028458ad772a6de3dbabd20/log/slog/log/slog_test.go), but the code has since become outdated and I need to update them and add new benchmarks.

BenchmarkSlogJsonLogger-12          	  829551	      1398 ns/op
BenchmarkGethJsonLogger-12          	 1000000	      1149 ns/op
BenchmarkSlogTerminalLogger-12      	 1302140	       918.3 ns/op
BenchmarkGethTerminalLogger-12      	 1971841	       610.5 ns/op

I think those can be improved on to make slog on par with our current logger in terms of performance.

[holiman]

I need to update them and add new benchmarks.

Do you have any newer? Seems not possible to run those. Also, would be interesting to see the performance difference for logging on not-enabled levels, e.g. perf on TRACE when we've only enabled INFO.

[holiman]

Looking into it a bit, you have this curious construction where we still use the ethereum/log package, and under the hood, it holds an slog logger:

func (h *swapLogger) write(level slog.Level, msg string, attrs ...any) {
	(*h.innerLogger.Load().(*slog.Logger)).Log(context.Background(), level, msg, attrs...)
}

Could you please add some information to the PR description about the design/implementation choices that you have made, and why?

[jwasinger]

@holiman updated the description with an explanation.

[jwasinger]

Regarding benchmarks:

Log15/Geth master

goos: darwin
goarch: arm64
pkg: github.com/jwasinger/slog-benchmarks
BenchmarkJson-12                            	  877147	      1330 ns/op
BenchmarkGloggerNotEnabled-12               	 9121382	       131.7 ns/op
BenchmarkGloggerEnabledDiscardHandler-12    	 9030315	       132.4 ns/op
BenchmarkGloggerEnabledStreamHandler-12     	 1000000	      1025 ns/op

Slog

BenchmarkJson-12                            	  719133	      1646 ns/op
BenchmarkGloggerNotEnabled-12               	202831256	         5.916 ns/op
BenchmarkGloggerEnabledDiscardHandler-12    	 4691402	       254.0 ns/op
BenchmarkGloggerEnabledStreamHandler-12     	 1000000	      1004 ns/op

Also, would be interesting to see the performance difference for logging on not-enabled levels, e.g. perf on TRACE when we've only enabled INFO.

This is the GloggerNotEnabled benchmark. Here, slog performs much better because the handler interface allows us to abort log handling early before a Record is instantiated.

[jwasinger]

@holiman Are we okay with removing the alignment of provided attributes when using logfmt format?

i.e. t=2023-10-18T23:44:05+0800 lvl=info msg="NAT mapped port" proto=TCP extport=30303 intport=30303 interface="UPNP IGDv1-IP1" -> t=2023-10-18T23:44:05+0800 lvl=info msg="NAT mapped port" proto=TCP extport=30303 intport=30303 interface="UPNP IGDv1-IP1"

This is actually a bit of a hack to implement given the rigidity of ReplaceAttr feature of HandlerOptions.

It will make the output less human-readable. But I figure the logfmt format is mostly meant to be consumed by scripts anyways.

[namiloh]

the logfmt format is mostly meant to be consumed by scripts anyways.

I agree. Imo we don't require the alignment

[jwasinger]

I still need to add proper formatting for Uint256 and big.Int types. But that seems like the only other thing outstanding, and it's a matter of direct copying from the current logger code.

[jwasinger]

Updated benchmarks from my local machine:

This PR (source):

BenchmarkJson-12               	 1169445	      1024 ns/op
BenchmarkGloggerDisabled-12    	212140161	         5.626 ns/op
BenchmarkGloggerDiscard-12     	 3455035	       346.0 ns/op
BenchmarkGloggerTerminal-12    	  789492	      1499 ns/op
BenchmarkGloggerLogfmt-12      	  777709	      1515 ns/op
BenchmarkGloggerJson-12        	  801158	      1492 ns/op

Current Geth Log15-based logger (source):

BenchmarkJson-12               	  895046	      1329 ns/op
BenchmarkGloggerDisabled-12    	 9091378	       131.3 ns/op
BenchmarkGloggerDiscard-12     	 9066014	       132.8 ns/op
BenchmarkGloggerTerminal-12    	 1000000	      1029 ns/op
BenchmarkGloggerLogfmt-12      	 1000000	      1105 ns/op
BenchmarkGloggerJson-12        	  714872	      1671 ns/op

[holiman]

... and we would be inhibited from adding these in the future because of breaking compatibility with the interface we are about to introduce with this PR right?

More or less, yes. But afaict, if someone wants to use WithAttrs, then they can just use slog directly, not go via go-ethereum/log, right?

[jwasinger]

I have changed by mind about Inner(). It seemed to me that we were still leaking internals, when we had a Handler()-method to retrieve the inner.Hander. But looking at it now, I don't see why we need to expose any of it. The SetDefault can look like this:

func SetDefault(l Logger) {
	root.Store(l)
	if lg, ok := l.(*logger); ok {
		slog.SetDefault(lg.inner)
	}
}

And we can just drop Inner from the interface. It compiles, not sure what I'm missing...

Deleted my incorrect comment. Yeah we don't need Inner. If a user sets the default logger with something that isn't a logger, this will silently cause any log invocations that are made using slog to silently not appear. But I don't think this is a huge problem.

[holiman]

Deleted my incorrect comment. Yeah we don't need Inner. If a user sets the default logger with something that isn't a logger, this will silently cause any log invocations that are made using slog to silently not appear. But I don't think this is a huge problem.

I didn't see anything incorrect (ah ok now I get what you meant), but yeah, the only fallout will be that a custom logger won't 'stick' on both log and slog invocations equally. Such a caller can fix it by invoking SetDefault both on log and slog though.

[jwasinger]

... and we would be inhibited from adding these in the future because of breaking compatibility with the interface we are about to introduce with this PR right?

More or less, yes. But afaict, if someone wants to use WithAttrs, then they can just use slog directly, not go via go-ethereum/log, right?

Oh right. yeah.

[jwasinger]

The json equivalence tester is actually a bit annoying. The plan was to go line-by-line comparing test data with received output, and ignoring the time. And this would be simple enough because I can easily transform each line string into a map[string][]byte.

However, in cases where user-provided keys clash with the keys used by record object built-in attributes, slog produces invalid json with duplicate keys. So writing the tester is a bit hackier (have to "decode" each line by extracting fields/values directly from the string). still straightforward enough I think.

[holiman]

The json equivalence tester is actually a bit annoying. The plan was to go line-by-line comparing test data with received output, and ignoring the time. And this would be simple enough because I can easily transform each line string into a map[string][]byte.

I think map[string]any might be better.

However, in cases where user-provided keys clash with the keys used by record object built-in attributes, slog produces invalid json with duplicate keys.

It's not so invalid that the golang json parser refuses to parse it, so let's just do that. That's what a "consumer" of this json stream would do, so that's IMO the best way to test it

[holiman]

func TestJsonLogging(t *testing.T) {
	t.Parallel()
	haveB, err := runSelf("--log.format", "json", "logtest")
	if err != nil {
		t.Fatal(err)
	}
	readFile, err := os.Open("testdata/logging/logtest-json.txt")
	if err != nil {
		t.Fatal(err)
	}
	wantLines := split(readFile)
	haveLines := split(bytes.NewBuffer(haveB))
	for i, want := range wantLines {
		if i > len(haveLines)-1 {
			t.Fatalf("format %v, line %d missing, want:%v", "json", i, want)
		}
		have := haveLines[i]
		for strings.Contains(have, "Unknown config environment variable") {
			// This can happen on CI runs. Drop it.
			haveLines = append(haveLines[:i], haveLines[i+1:]...)
			have = haveLines[i]
		}
		var h map[string]any
		var w map[string]any
		if err := json.Unmarshal([]byte(have), &h); err != nil {
			t.Fatal(err)
		}
		if err := json.Unmarshal([]byte(want), &w); err != nil {
			t.Fatal(err)
		}
		h["t"] = "xxx"
		w["t"] = "xxx"
		outh, _ := json.Marshal(h)
		outw, _ := json.Marshal(w)
		if !bytes.Equal(outh, outw) {
			// show an intelligent diff
			t.Logf(nicediff(outh, outw))
			t.Errorf("file content wrong")
		}
	}
}

Works for me ... ?

[jwasinger]

From RFC 8529:

The names within an object SHOULD be unique.

So I guess it's not strictly required and may deviate between software implementations. Okay, then checking that testdata == expected according to the Go json marshaller is probably the proper thing to do here. Pls push that commit to the PR.

[holiman]

>>> build/cache/golangci-lint-1.51.1-linux-amd64/golangci-lint run --config .golangci.yml ./...
log/handler.go:188:12: composites: golang.org/x/exp/slog.Attr struct literal uses unkeyed fields (govet)
				return slog.Attr{"t", attr.Value}
				       ^
util.go:48: exit status 1

[holiman]

LGTM

[islishude]

the pr prevents all logs

package main

import (
	"context"
	"fmt"
	"log"

	"github.com/ethereum/go-ethereum/ethclient"
)

func main() {
	rpcclient, err := ethclient.Dial("https://eth.llamarpc.com")
	if err != nil {
		panic(err)
	}

	fmt.Println("...log.Println has no outpus")
	log.Println(rpcclient.ChainID(context.TODO()))
	fmt.Println("...log.Println has no outpus")
}

Can we remove this line?

go-ethereum/log/root.go

Lines 14 to 15 in 09e0208

	SetDefault(defaultLogger)
	}

[fjl]

#28738 is about this problem