From 14acdf2dd194ee30fb8c8501069fd81d9fd32f81 Mon Sep 17 00:00:00 2001 From: Daniel Liu Date: Fri, 15 Nov 2024 10:02:42 +0800 Subject: [PATCH] log: remove lazy, remove unused interfaces, unexport methods (#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) ``` --- internal/testlog/testlog.go | 6 +++- light/txpool.go | 5 +++- log/format.go | 55 ++++++++----------------------------- log/handler.go | 39 ++------------------------ log/logger.go | 28 ++++++------------- log/logger_test.go | 4 +-- log/root.go | 5 ++++ p2p/discover/table.go | 30 ++++++++++++-------- p2p/discover/udp.go | 3 ++ p2p/discv5/net.go | 23 ++++++++-------- 10 files changed, 70 insertions(+), 128 deletions(-) diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index 59aa7e0041..8f68792d37 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/light/txpool.go b/light/txpool.go index 5783239144..a1d9190a38 100644 --- a/light/txpool.go +++ b/light/txpool.go @@ -450,7 +450,10 @@ func (p *TxPool) add(ctx context.Context, tx *types.Transaction) error { } // Print a log message if low enough level is set - log.Debug("Pooled new transaction", "hash", hash, "from", log.Lazy{Fn: func() common.Address { from, _ := types.Sender(p.signer, tx); return from }}, "to", tx.To()) + if log.Enabled(log.LevelDebug) { + from, _ := types.Sender(p.signer, tx) + log.Debug("Pooled new transaction", "hash", hash, "from", from, "to", tx.To()) + } return nil } diff --git a/log/format.go b/log/format.go index a2bbcce9c0..6447f3c1f1 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 513c230c9e..88efc491c8 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 b5b83cd71f..717ec94caa 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..a633f5ad7a 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/log/root.go b/log/root.go index 71040fff47..69b9bccc37 100644 --- a/log/root.go +++ b/log/root.go @@ -1,6 +1,7 @@ package log import ( + "context" "os" "sync/atomic" @@ -115,3 +116,7 @@ func Crit(msg string, ctx ...interface{}) { func New(ctx ...interface{}) Logger { return Root().With(ctx...) } + +func Enabled(level slog.Level) bool { + return Root().Enabled(context.Background(), level) +} diff --git a/p2p/discover/table.go b/p2p/discover/table.go index dff614c1d6..b930cdf0b8 100644 --- a/p2p/discover/table.go +++ b/p2p/discover/table.go @@ -23,6 +23,7 @@ package discover import ( + "context" crand "crypto/rand" "encoding/binary" "errors" @@ -72,7 +73,10 @@ type Table struct { rand *mrand.Rand // source of randomness, periodically reseeded ips netutil.DistinctNetSet - db *nodeDB // database of known nodes + db *nodeDB // database of known nodes + log log.Logger + + // loop channels refreshReq chan chan struct{} initDone chan struct{} closeReq chan struct{} @@ -118,9 +122,11 @@ func newTable(t transport, ourID NodeID, ourAddr *net.UDPAddr, nodeDBPath string if err != nil { return nil, err } + tab := &Table{ net: t, db: db, + log: log.Root(), self: NewNode(ourID, ourAddr.IP, uint16(ourAddr.Port), uint16(ourAddr.Port)), bonding: make(map[NodeID]*bondproc), bondslots: make(chan struct{}, maxBondingPingPongs), @@ -322,10 +328,10 @@ func (tab *Table) lookup(targetID NodeID, refreshIfEmpty bool) []*Node { // Bump the failure counter to detect and evacuate non-bonded entries fails := tab.db.findFails(n.ID) + 1 tab.db.updateFindFails(n.ID, fails) - log.Trace("Bumping findnode failure counter", "id", n.ID, "failcount", fails) + tab.log.Trace("Bumping findnode failure counter", "id", n.ID, "failcount", fails) if fails >= maxFindnodeFailures { - log.Trace("Too many findnode failures, dropping", "id", n.ID, "failcount", fails) + tab.log.Trace("Too many findnode failures, dropping", "id", n.ID, "failcount", fails) tab.delete(n) } } @@ -455,8 +461,10 @@ func (tab *Table) loadSeedNodes(bond bool) { } for i := range seeds { seed := seeds[i] - age := log.Lazy{Fn: func() interface{} { return time.Since(tab.db.bondTime(seed.ID)) }} - log.Debug("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.bondTime(seed.ID)) + tab.log.Debug("Found seed node in database", "id", seed.ID, "addr", seed.addr(), "age", age) + } tab.add(seed) } } @@ -480,16 +488,16 @@ func (tab *Table) doRevalidate(done chan<- struct{}) { b := tab.buckets[bi] if err == nil { // The node responded, move it to the front. - log.Debug("Revalidated node", "b", bi, "id", last.ID) + tab.log.Debug("Revalidated node", "b", bi, "id", last.ID) b.bump(last) return } // No reply received, pick a replacement or delete the node if there aren't // any replacements. if r := tab.replace(b, last); r != nil { - log.Debug("Replaced dead node", "b", bi, "id", last.ID, "ip", last.IP, "r", r.ID, "rip", r.IP) + tab.log.Debug("Replaced dead node", "b", bi, "id", last.ID, "ip", last.IP, "r", r.ID, "rip", r.IP) } else { - log.Debug("Removed dead node", "b", bi, "id", last.ID, "ip", last.IP) + tab.log.Debug("Removed dead node", "b", bi, "id", last.ID, "ip", last.IP) } } @@ -599,7 +607,7 @@ func (tab *Table) bond(pinged bool, id NodeID, addr *net.UDPAddr, tcpPort uint16 age := time.Since(tab.db.bondTime(id)) var result error if fails > 0 || age > nodeDBNodeExpiration { - log.Trace("Starting bonding ping/pong", "id", id, "known", node != nil, "failcount", fails, "age", age) + tab.log.Trace("Starting bonding ping/pong", "id", id, "known", node != nil, "failcount", fails, "age", age) tab.bondmu.Lock() w := tab.bonding[id] @@ -724,11 +732,11 @@ func (tab *Table) addIP(b *bucket, ip net.IP) bool { return true } if !tab.ips.Add(ip) { - log.Debug("IP exceeds table limit", "ip", ip) + tab.log.Debug("IP exceeds table limit", "ip", ip) return false } if !b.ips.Add(ip) { - log.Debug("IP exceeds bucket limit", "ip", ip) + tab.log.Debug("IP exceeds bucket limit", "ip", ip) tab.ips.Remove(ip) return false } diff --git a/p2p/discover/udp.go b/p2p/discover/udp.go index 701747bb04..bb541ab07a 100644 --- a/p2p/discover/udp.go +++ b/p2p/discover/udp.go @@ -228,6 +228,9 @@ type Config struct { NetRestrict *netutil.Netlist // network whitelist Bootnodes []*Node // list of bootstrap nodes Unhandled chan<- ReadPacket // unhandled packets are sent on this channel + + // The options below are useful in very specific cases, like in unit tests. + Log log.Logger // if set, log messages go here } // ListenUDP returns a new table that listens for UDP packets on laddr. diff --git a/p2p/discv5/net.go b/p2p/discv5/net.go index 54981a4f7b..6c5c0b1174 100644 --- a/p2p/discv5/net.go +++ b/p2p/discv5/net.go @@ -420,7 +420,6 @@ loop: // Ingress packet handling. case pkt := <-net.read: - //fmt.Println("read", pkt.ev) log.Trace("<-net.read") n := net.internNode(&pkt) prestate := n.state @@ -428,10 +427,10 @@ loop: if err := net.handle(n, pkt.ev, &pkt); err != nil { status = err.Error() } - log.Trace("", "msg", log.Lazy{Fn: func() string { - return fmt.Sprintf("<<< (%d) %v from %x@%v: %v -> %v (%v)", - net.tab.count, pkt.ev, pkt.remoteID[:8], pkt.remoteAddr, prestate, n.state, status) - }}) + if log.Enabled(log.LevelTrace) { + msg := fmt.Sprintf("<<< (%d) %v from %x@%v: %v -> %v (%v)", net.tab.count, pkt.ev, pkt.remoteID[:8], pkt.remoteAddr, prestate, n.state, status) + log.Trace("", "msg", msg) + } // TODO: persist state if n.state goes >= known, delete if it goes <= known // State transition timeouts. @@ -447,10 +446,10 @@ loop: if err := net.handle(timeout.node, timeout.ev, nil); err != nil { status = err.Error() } - log.Trace("", "msg", log.Lazy{Fn: func() string { - return fmt.Sprintf("--- (%d) %v for %x@%v: %v -> %v (%v)", - net.tab.count, timeout.ev, timeout.node.ID[:8], timeout.node.addr(), prestate, timeout.node.state, status) - }}) + if log.Enabled(log.LevelTrace) { + msg := fmt.Sprintf("--- (%d) %v for %x@%v: %v -> %v (%v)", net.tab.count, timeout.ev, timeout.node.ID[:8], timeout.node.addr(), prestate, timeout.node.state, status) + log.Trace("", "msg", msg) + } // Querying. case q := <-net.queryReq: @@ -683,15 +682,15 @@ func (net *Network) refresh(done chan<- struct{}) { return } for _, n := range seeds { - log.Debug("", "msg", log.Lazy{Fn: func() string { + if log.Enabled(log.LevelDebug) { var age string if net.db != nil { age = time.Since(net.db.lastPong(n.ID)).String() } else { age = "unknown" } - return fmt.Sprintf("seed node (age %s): %v", age, n) - }}) + log.Debug("", "msg", fmt.Sprintf("seed node (age %s): %v", age, n)) + } n = net.internNodeFromDB(n) if n.state == unknown { net.transition(n, verifyinit)