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)