diff --git a/cmd/geth/logtestcmd_active.go b/cmd/geth/logtestcmd_active.go index 0ca4cc621..5cce1ec6a 100644 --- a/cmd/geth/logtestcmd_active.go +++ b/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 } diff --git a/cmd/geth/testdata/logging/logtest-json.txt b/cmd/geth/testdata/logging/logtest-json.txt index bdc1ae4de..3bfe71866 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"} @@ -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"} diff --git a/cmd/geth/testdata/logging/logtest-logfmt.txt b/cmd/geth/testdata/logging/logtest-logfmt.txt index 114569e46..f20d66635 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" @@ -49,3 +48,5 @@ t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=nil-custom-struct res= t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="raw nil" res= t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=(*uint64)(nil) res= 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= 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= LOG_ERROR="Normalized odd number of arguments by adding nil" diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt index 4da3f49d4..e3b562117 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 @@ -50,3 +49,5 @@ INFO [xx-xx|xx:xx:xx.xxx] nil-custom-struct res= INFO [xx-xx|xx:xx:xx.xxx] raw nil res= INFO [xx-xx|xx:xx:xx.xxx] (*uint64)(nil) res= 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= LOG_ERROR="Normalized odd number of arguments by adding nil" +INFO [xx-xx|xx:xx:xx.xxx] Odd pair (3 attr) key=value key2= LOG_ERROR="Normalized odd number of arguments by adding nil" diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index a7899c815..037b7ee9c 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() @@ -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() diff --git a/log/format.go b/log/format.go index a2bbcce9c..6447f3c1f 100644 --- a/log/format.go +++ b/log/format.go @@ -23,22 +23,6 @@ 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. @@ -46,7 +30,7 @@ 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("") } 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("")...) - } + 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("")...) - } + 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()) } diff --git a/log/handler.go b/log/handler.go index 1a2557745..7459aad89 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 @@ -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, diff --git a/log/logger.go b/log/logger.go index 3e227745a..93d62f080 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 27e90c5fd..a633f5ad7 100644 --- a/log/logger_test.go +++ b/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= 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 f476d2079..e6dafb0dc 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 4f0879224..de1a3177d 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