diff --git a/cmd/geth/logtestcmd_active.go b/cmd/geth/logtestcmd_active.go index 21313c24b5..5cce1ec6ab 100644 --- a/cmd/geth/logtestcmd_active.go +++ b/cmd/geth/logtestcmd_active.go @@ -102,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") diff --git a/cmd/geth/testdata/logging/logtest-json.txt b/cmd/geth/testdata/logging/logtest-json.txt index 2943528833..3bfe718660 100644 --- a/cmd/geth/testdata/logging/logtest-json.txt +++ b/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"} diff --git a/cmd/geth/testdata/logging/logtest-logfmt.txt b/cmd/geth/testdata/logging/logtest-logfmt.txt index 25ca7c004b..f20d66635d 100644 --- a/cmd/geth/testdata/logging/logtest-logfmt.txt +++ b/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" diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt index ae6f633d70..e3b562117c 100644 --- a/cmd/geth/testdata/logging/logtest-terminal.txt +++ b/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 diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index 735baa2101..037b7ee9c1 100644 --- a/internal/testlog/testlog.go +++ b/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() diff --git a/log/handler.go b/log/handler.go index ff1a2302f0..3a205902de 100644 --- a/log/handler.go +++ b/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 diff --git a/log/logger.go b/log/logger.go index 3e227745ad..93d62f080b 100644 --- a/log/logger.go +++ b/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...) } diff --git a/log/logger_test.go b/log/logger_test.go index 27e90c5fd2..a2a114bb5f 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -62,12 +62,12 @@ func BenchmarkTerminalHandler(b *testing.B) { benchmarkLogger(b, l) } func BenchmarkLogfmtHandler(b *testing.B) { - l := NewLogger(LogfmtHandler(io.Discard)) + l := NewLogger(NewLogfmtHandler(io.Discard)) benchmarkLogger(b, l) } func BenchmarkJSONHandler(b *testing.B) { - l := NewLogger(JSONHandler(io.Discard)) + l := NewLogger(NewJSONHandler(io.Discard)) benchmarkLogger(b, l) } @@ -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= 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= 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) diff --git a/p2p/discover/table.go b/p2p/discover/table.go index f476d2079f..e6dafb0dca 100644 --- a/p2p/discover/table.go +++ b/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) } } diff --git a/p2p/msgrate/msgrate.go b/p2p/msgrate/msgrate.go index 4f08792242..de1a3177db 100644 --- a/p2p/msgrate/msgrate.go +++ b/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