log: remove lazy, remove unused interfaces, unexport methods (ethereum#28622)

This change 

- Removes interface `log.Format`, 
- Removes method `log.FormatFunc`, 
- unexports `TerminalHandler.TerminalFormat` formatting methods (renamed to `TerminalHandler.format`)
- removes the notion of `log.Lazy` values


The lazy handler was useful in the old log package, since it
could defer the evaluation of costly attributes until later in the
log pipeline: thus, if the logging was done at 'Trace', we could
skip evaluation if logging only was set to 'Info'.

With the move to slog, this way of deferring evaluation is no longer
needed, since slog introduced 'Enabled': the caller can thus do
the evaluate-or-not decision at the callsite, which is much more
straight-forward than dealing with lazy reflect-based evaluation.

Also, lazy evaluation would not work with 'native' slog, as in, these
two statements would be evaluated differently:

```golang
  log.Info("foo", "my lazy", lazyObj)
  slog.Info("foo", "my lazy", lazyObj)
```

Author: holiman

cmd/geth/logtestcmd_active.go

@@ -43,6 +43,7 @@ This command is only meant for testing.
 
 type customQuotedStringer struct {
 }
+
 func (c customQuotedStringer) String() string {
 	return "output with 'quotes'"
 }
@@ -80,8 +81,6 @@ func logTest(ctx *cli.Context) error {
 		log.Info("uint64", "18,446,744,073,709,551,615", uint64(math.MaxUint64))
 	}
 	{ // Special characters
-
-
 		log.Info("Special chars in value", "key", "special \r\n\t chars")
 		log.Info("Special chars in key", "special \n\t chars", "value")
 
@@ -103,9 +102,6 @@ func logTest(ctx *cli.Context) error {
 		var c customQuotedStringer
 		log.Info("a custom stringer that emits quoted text", "output", c)
 	}
-	{ // Lazy eval
-		log.Info("Lazy evaluation of value", "key", log.Lazy{Fn: func() interface{} { return "lazy value" }})
-	}
 	{ // Multi-line message
 		log.Info("A message with wonky \U0001F4A9 characters")
 		log.Info("A multiline message \nINFO [10-18|14:11:31.106] with wonky characters \U0001F4A9")
@@ -166,6 +162,10 @@ func logTest(ctx *cli.Context) error {
 	{ // Logging with 'reserved' keys
 		log.Info("Using keys 't', 'lvl', 'time', 'level' and 'msg'", "t", "t", "time", "time", "lvl", "lvl", "level", "level", "msg", "msg")
 	}
+	{ // Logging with wrong attr-value pairs
+		log.Info("Odd pair (1 attr)", "key")
+		log.Info("Odd pair (3 attr)", "key", "value", "key2")
+	}
 	return nil
 }
 

cmd/geth/testdata/logging/logtest-json.txt

@@ -21,7 +21,6 @@
 {"t":"2023-11-22T15:42:00.408197+08:00","lvl":"info","msg":"an error message with quotes","error":"this is an 'error'"}
 {"t":"2023-11-22T15:42:00.408202+08:00","lvl":"info","msg":"Custom Stringer value","2562047h47m16.854s":"2562047h47m16.854s"}
 {"t":"2023-11-22T15:42:00.408208+08:00","lvl":"info","msg":"a custom stringer that emits quoted text","output":"output with 'quotes'"}
-{"t":"2023-11-22T15:42:00.408215+08:00","lvl":"info","msg":"Lazy evaluation of value","key":"lazy value"}
 {"t":"2023-11-22T15:42:00.408219+08:00","lvl":"info","msg":"A message with wonky 💩 characters"}
 {"t":"2023-11-22T15:42:00.408222+08:00","lvl":"info","msg":"A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩"}
 {"t":"2023-11-22T15:42:00.408226+08:00","lvl":"info","msg":"A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above"}
@@ -49,3 +48,5 @@
 {"t":"2023-11-22T15:42:00.40835+08:00","lvl":"info","msg":"raw nil","res":null}
 {"t":"2023-11-22T15:42:00.408354+08:00","lvl":"info","msg":"(*uint64)(nil)","res":null}
 {"t":"2023-11-22T15:42:00.408361+08:00","lvl":"info","msg":"Using keys 't', 'lvl', 'time', 'level' and 'msg'","t":"t","time":"time","lvl":"lvl","level":"level","msg":"msg"}
+{"t":"2023-11-29T15:13:00.195655931+01:00","lvl":"info","msg":"Odd pair (1 attr)","key":null,"LOG_ERROR":"Normalized odd number of arguments by adding nil"}
+{"t":"2023-11-29T15:13:00.195681832+01:00","lvl":"info","msg":"Odd pair (3 attr)","key":"value","key2":null,"LOG_ERROR":"Normalized odd number of arguments by adding nil"}

cmd/geth/testdata/logging/logtest-logfmt.txt

@@ -21,7 +21,6 @@ t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColor
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="an error message with quotes" error="this is an 'error'"
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="a custom stringer that emits quoted text" output="output with 'quotes'"
-t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Lazy evaluation of value" key="lazy value"
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="A message with wonky 💩 characters"
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩"
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above"
@@ -49,3 +48,5 @@ t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=nil-custom-struct res=<nil>
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="raw nil" res=<nil>
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=(*uint64)(nil) res=<nil>
 t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Using keys 't', 'lvl', 'time', 'level' and 'msg'" t=t time=time lvl=lvl level=level msg=msg
+t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Odd pair (1 attr)" key=<nil> LOG_ERROR="Normalized odd number of arguments by adding nil"
+t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Odd pair (3 attr)" key=value key2=<nil> LOG_ERROR="Normalized odd number of arguments by adding nil"

cmd/geth/testdata/logging/logtest-terminal.txt

@@ -21,8 +21,7 @@ INFO [xx-xx|xx:xx:xx.xxx] "\x1b[35mColored\x1b[0m["                "\x1b[35mColo
 INFO [xx-xx|xx:xx:xx.xxx] an error message with quotes             error="this is an 'error'"
 INFO [xx-xx|xx:xx:xx.xxx] Custom Stringer value                    2562047h47m16.854s=2562047h47m16.854s
 INFO [xx-xx|xx:xx:xx.xxx] a custom stringer that emits quoted text output="output with 'quotes'"
-INFO [xx-xx|xx:xx:xx.xxx] Lazy evaluation of value                 key="lazy value"
-INFO [xx-xx|xx:xx:xx.xxx] "A message with wonky 💩 characters" 
+INFO [xx-xx|xx:xx:xx.xxx] "A message with wonky 💩 characters"
 INFO [xx-xx|xx:xx:xx.xxx] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" 
 INFO [xx-xx|xx:xx:xx.xxx] A multiline message 
 LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above 
@@ -50,3 +49,5 @@ INFO [xx-xx|xx:xx:xx.xxx] nil-custom-struct                        res=<nil>
 INFO [xx-xx|xx:xx:xx.xxx] raw nil                                  res=<nil>
 INFO [xx-xx|xx:xx:xx.xxx] (*uint64)(nil)                           res=<nil>
 INFO [xx-xx|xx:xx:xx.xxx] Using keys 't', 'lvl', 'time', 'level' and 'msg' t=t time=time lvl=lvl level=level msg=msg
+INFO [xx-xx|xx:xx:xx.xxx] Odd pair (1 attr)                        key=<nil>                  LOG_ERROR="Normalized odd number of arguments by adding nil"
+INFO [xx-xx|xx:xx:xx.xxx] Odd pair (3 attr)                        key=value                  key2=<nil> LOG_ERROR="Normalized odd number of arguments by adding nil"

internal/testlog/testlog.go

@@ -100,6 +100,10 @@ func LoggerWithHandler(t *testing.T, handler slog.Handler) log.Logger {
 
 func (l *logger) Write(level slog.Level, msg string, ctx ...interface{}) {}
 
+func (l *logger) Enabled(ctx context.Context, level slog.Level) bool {
+	return l.l.Enabled(ctx, level)
+}
+
 func (l *logger) Trace(msg string, ctx ...interface{}) {
 	l.t.Helper()
 	l.mu.Lock()
@@ -183,7 +187,7 @@ func (h *bufHandler) terminalFormat(r slog.Record) string {
 	}
 
 	for _, attr := range attrs {
-		fmt.Fprintf(buf, " %s=%s", attr.Key, string(log.FormatSlogValue(attr.Value, true, nil)))
+		fmt.Fprintf(buf, " %s=%s", attr.Key, string(log.FormatSlogValue(attr.Value, nil)))
 	}
 	buf.WriteByte('\n')
 	return buf.String()

log/format.go

@@ -23,30 +23,14 @@ const (
 // 40 spaces
 var spaces = []byte("                                        ")
 
-type Format interface {
-	Format(r slog.Record) []byte
-}
-
-// FormatFunc returns a new Format object which uses
-// the given function to perform record formatting.
-func FormatFunc(f func(slog.Record) []byte) Format {
-	return formatFunc(f)
-}
-
-type formatFunc func(slog.Record) []byte
-
-func (f formatFunc) Format(r slog.Record) []byte {
-	return f(r)
-}
-
 // TerminalStringer is an analogous interface to the stdlib stringer, allowing
 // own types to have custom shortened serialization formats when printed to the
 // screen.
 type TerminalStringer interface {
 	TerminalString() string
 }
 
-func (h *TerminalHandler) TerminalFormat(buf []byte, r slog.Record, usecolor bool) []byte {
+func (h *TerminalHandler) format(buf []byte, r slog.Record, usecolor bool) []byte {
 	msg := escapeMessage(r.Message)
 	var color = ""
 	if usecolor {
@@ -88,13 +72,13 @@ func (h *TerminalHandler) TerminalFormat(buf []byte, r slog.Record, usecolor boo
 	if (r.NumAttrs()+len(h.attrs)) > 0 && length < termMsgJust {
 		b.Write(spaces[:termMsgJust-length])
 	}
-	// print the keys logfmt style
-	h.logfmt(b, r, color)
+	// print the attributes
+	h.formatAttributes(b, r, color)
 
 	return b.Bytes()
 }
 
-func (h *TerminalHandler) logfmt(buf *bytes.Buffer, r slog.Record, color string) {
+func (h *TerminalHandler) formatAttributes(buf *bytes.Buffer, r slog.Record, color string) {
 	// tmp is a temporary buffer we use, until bytes.Buffer.AvailableBuffer() (1.21)
 	// can be used.
 	var tmp = make([]byte, 40)
@@ -112,7 +96,7 @@ func (h *TerminalHandler) logfmt(buf *bytes.Buffer, r slog.Record, color string)
 			buf.WriteByte('=')
 		}
 		//val := FormatSlogValue(attr.Value, true, buf.AvailableBuffer())
-		val := FormatSlogValue(attr.Value, true, tmp[:0])
+		val := FormatSlogValue(attr.Value, tmp[:0])
 
 		padding := h.fieldPadding[attr.Key]
 
@@ -140,8 +124,8 @@ func (h *TerminalHandler) logfmt(buf *bytes.Buffer, r slog.Record, color string)
 	buf.WriteByte('\n')
 }
 
-// FormatSlogValue formats a slog.Value for serialization
-func FormatSlogValue(v slog.Value, term bool, tmp []byte) (result []byte) {
+// FormatSlogValue formats a slog.Value for serialization to terminal.
+func FormatSlogValue(v slog.Value, tmp []byte) (result []byte) {
 	var value any
 	defer func() {
 		if err := recover(); err != nil {
@@ -156,11 +140,9 @@ func FormatSlogValue(v slog.Value, term bool, tmp []byte) (result []byte) {
 	switch v.Kind() {
 	case slog.KindString:
 		return appendEscapeString(tmp, v.String())
-	case slog.KindAny:
-		value = v.Any()
-	case slog.KindInt64: // All int-types (int8 ,int16 etc) wind up here
+	case slog.KindInt64: // All int-types (int8, int16 etc) wind up here
 		return appendInt64(tmp, v.Int64())
-	case slog.KindUint64: // All uint-types (int8 ,int16 etc) wind up here
+	case slog.KindUint64: // All uint-types (uint8, uint16 etc) wind up here
 		return appendUint64(tmp, v.Uint64(), false)
 	case slog.KindFloat64:
 		return strconv.AppendFloat(tmp, v.Float64(), floatFormat, 3, 64)
@@ -180,27 +162,14 @@ func FormatSlogValue(v slog.Value, term bool, tmp []byte) (result []byte) {
 		return []byte("<nil>")
 	}
 	switch v := value.(type) {
-	case *big.Int:
-		// Big ints get consumed by the Stringer clause, so we need to handle
-		// them earlier on.
-		if v == nil {
-			return append(tmp, []byte("<nil>")...)
-		}
+	case *big.Int: // Need to be before fmt.Stringer-clause
 		return appendBigInt(tmp, v)
-
-	case *uint256.Int:
-		// Uint256s get consumed by the Stringer clause, so we need to handle
-		// them earlier on.
-		if v == nil {
-			return append(tmp, []byte("<nil>")...)
-		}
+	case *uint256.Int: // Need to be before fmt.Stringer-clause
 		return appendU256(tmp, v)
 	case error:
 		return appendEscapeString(tmp, v.Error())
 	case TerminalStringer:
-		if term {
-			return appendEscapeString(tmp, v.TerminalString()) // Custom terminal stringer provided, use that
-		}
+		return appendEscapeString(tmp, v.TerminalString())
 	case fmt.Stringer:
 		return appendEscapeString(tmp, v.String())
 	}

log/handler.go

@@ -13,42 +13,6 @@ import (
 	"golang.org/x/exp/slog"
 )
 
-// Lazy allows you to defer calculation of a logged value that is expensive
-// to compute until it is certain that it must be evaluated with the given filters.
-//
-// You may wrap any function which takes no arguments to Lazy. It may return any
-// number of values of any type.
-type Lazy struct {
-	Fn interface{}
-}
-
-func evaluateLazy(lz Lazy) (interface{}, error) {
-	t := reflect.TypeOf(lz.Fn)
-
-	if t.Kind() != reflect.Func {
-		return nil, fmt.Errorf("INVALID_LAZY, not func: %+v", lz.Fn)
-	}
-
-	if t.NumIn() > 0 {
-		return nil, fmt.Errorf("INVALID_LAZY, func takes args: %+v", lz.Fn)
-	}
-
-	if t.NumOut() == 0 {
-		return nil, fmt.Errorf("INVALID_LAZY, no func return val: %+v", lz.Fn)
-	}
-
-	value := reflect.ValueOf(lz.Fn)
-	results := value.Call([]reflect.Value{})
-	if len(results) == 1 {
-		return results[0].Interface(), nil
-	}
-	values := make([]interface{}, len(results))
-	for i, v := range results {
-		values[i] = v.Interface()
-	}
-	return values, nil
-}
-
 type discardHandler struct{}
 
 // DiscardHandler returns a no-op handler
@@ -112,7 +76,7 @@ func NewTerminalHandlerWithLevel(wr io.Writer, lvl slog.Level, useColor bool) *T
 func (h *TerminalHandler) Handle(_ context.Context, r slog.Record) error {
 	h.mu.Lock()
 	defer h.mu.Unlock()
-	buf := h.TerminalFormat(h.buf, r, h.useColor)
+	buf := h.format(h.buf, r, h.useColor)
 	h.wr.Write(buf)
 	h.buf = buf[:0]
 	return nil
@@ -149,6 +113,7 @@ func (l *leveler) Level() slog.Level {
 	return l.minLevel
 }
 
+// JSONHandler returns a handler which prints records in JSON format.
 func JSONHandler(wr io.Writer) slog.Handler {
 	return slog.NewJSONHandler(wr, &slog.HandlerOptions{
 		ReplaceAttr: builtinReplaceJSON,

log/logger.go

@@ -134,6 +134,9 @@ type Logger interface {
 
 	// Write logs a message at the specified level
 	Write(level slog.Level, msg string, attrs ...any)
+
+	// Enabled reports whether l emits log records at the given context and level.
+	Enabled(ctx context.Context, level slog.Level) bool
 }
 
 type logger struct {
@@ -159,26 +162,6 @@ func (l *logger) Write(level slog.Level, msg string, attrs ...any) {
 	if len(attrs)%2 != 0 {
 		attrs = append(attrs, nil, errorKey, "Normalized odd number of arguments by adding nil")
 	}
-
-	// evaluate lazy values
-	var hadErr bool
-	for i := 1; i < len(attrs); i += 2 {
-		lz, ok := attrs[i].(Lazy)
-		if ok {
-			v, err := evaluateLazy(lz)
-			if err != nil {
-				hadErr = true
-				attrs[i] = err
-			} else {
-				attrs[i] = v
-			}
-		}
-	}
-
-	if hadErr {
-		attrs = append(attrs, errorKey, "bad lazy")
-	}
-
 	r := slog.NewRecord(time.Now(), level, msg, pcs[0])
 	r.Add(attrs...)
 	l.inner.Handler().Handle(context.Background(), r)
@@ -196,6 +179,11 @@ func (l *logger) New(ctx ...interface{}) Logger {
 	return l.With(ctx...)
 }
 
+// Enabled reports whether l emits log records at the given context and level.
+func (l *logger) Enabled(ctx context.Context, level slog.Level) bool {
+	return l.inner.Enabled(ctx, level)
+}
+
 func (l *logger) Trace(msg string, ctx ...interface{}) {
 	l.Write(LevelTrace, msg, ctx...)
 }

log/logger_test.go

@@ -107,7 +107,6 @@ func TestLoggerOutput(t *testing.T) {
 		bigint    = big.NewInt(100)
 		nilbig    *big.Int
 		err       = fmt.Errorf("Oh nooes it's crap")
-		lazy      = Lazy{Fn: func() interface{} { return "lazy value" }}
 		smallUint = uint256.NewInt(500_000)
 		bigUint   = &uint256.Int{0xff, 0xff, 0xff, 0xff}
 	)
@@ -126,13 +125,12 @@ func TestLoggerOutput(t *testing.T) {
 		"struct", customA,
 		"struct", customB,
 		"ptrstruct", &customA,
-		"lazy", lazy,
 		"smalluint", smallUint,
 		"bigUint", bigUint)
 
 	have := out.String()
 	t.Logf("output %v", out.String())
-	want := `INFO [11-07|19:14:33.821] This is a message                        foo=123 bytes="[0 0 0 0 0 0 0 0 0 0]" bonk="a string with text" time=0001-01-01T00:00:00+0000 bigint=100 nilbig=<nil> err="Oh nooes it's crap" struct="{A:Foo B:12}" struct="{A:Foo\nLinebreak B:122}" ptrstruct="&{A:Foo B:12}" lazy="lazy value" smalluint=500,000 bigUint=1,600,660,942,523,603,594,864,898,306,482,794,244,293,965,082,972,225,630,372,095
+	want := `INFO [11-07|19:14:33.821] This is a message                        foo=123 bytes="[0 0 0 0 0 0 0 0 0 0]" bonk="a string with text" time=0001-01-01T00:00:00+0000 bigint=100 nilbig=<nil> err="Oh nooes it's crap" struct="{A:Foo B:12}" struct="{A:Foo\nLinebreak B:122}" ptrstruct="&{A:Foo B:12}" smalluint=500,000 bigUint=1,600,660,942,523,603,594,864,898,306,482,794,244,293,965,082,972,225,630,372,095
 `
 	if !bytes.Equal([]byte(have)[25:], []byte(want)[25:]) {
 		t.Errorf("Error\nhave: %q\nwant: %q", have, want)

p2p/discover/table.go

@@ -23,6 +23,7 @@
 package discover
 
 import (
+	"context"
 	crand "crypto/rand"
 	"encoding/binary"
 	"fmt"
@@ -330,8 +331,10 @@ func (tab *Table) loadSeedNodes() {
 	seeds = append(seeds, tab.nursery...)
 	for i := range seeds {
 		seed := seeds[i]
-		age := log.Lazy{Fn: func() interface{} { return time.Since(tab.db.LastPongReceived(seed.ID(), seed.IP())) }}
-		tab.log.Trace("Found seed node in database", "id", seed.ID(), "addr", seed.addr(), "age", age)
+		if tab.log.Enabled(context.Background(), log.LevelTrace) {
+			age := time.Since(tab.db.LastPongReceived(seed.ID(), seed.IP()))
+			tab.log.Trace("Found seed node in database", "id", seed.ID(), "addr", seed.addr(), "age", age)
+		}
 		tab.addSeenNode(seed)
 	}
 }

p2p/msgrate/msgrate.go

@@ -18,6 +18,7 @@
 package msgrate
 
 import (
+	"context"
 	"errors"
 	"math"
 	"sort"
@@ -410,7 +411,9 @@ func (t *Trackers) tune() {
 
 	t.tuned = time.Now()
 	t.log.Debug("Recalculated msgrate QoS values", "rtt", t.roundtrip, "confidence", t.confidence, "ttl", t.targetTimeout(), "next", t.tuned.Add(t.roundtrip))
-	t.log.Trace("Debug dump of mean capacities", "caps", log.Lazy{Fn: t.meanCapacities})
+	if t.log.Enabled(context.Background(), log.LevelTrace) {
+		t.log.Trace("Debug dump of mean capacities", "caps", t.meanCapacities())
+	}
 }
 
 // detune reduces the tracker's confidence in order to make fresh measurements