log: polishes to exported interface

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