Skip to content

Commit

Permalink
log: remove notion of lazy handler
Browse files Browse the repository at this point in the history
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)
```
  • Loading branch information
holiman committed Dec 1, 2023
1 parent 75b5c8f commit eacee24
Show file tree
Hide file tree
Showing 10 changed files with 25 additions and 71 deletions.
3 changes: 0 additions & 3 deletions cmd/geth/logtestcmd_active.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down
1 change: 0 additions & 1 deletion cmd/geth/testdata/logging/logtest-json.txt
Original file line number Diff line number Diff line change
Expand Up @@ -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"}
Expand Down
1 change: 0 additions & 1 deletion cmd/geth/testdata/logging/logtest-logfmt.txt
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
3 changes: 1 addition & 2 deletions cmd/geth/testdata/logging/logtest-terminal.txt
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 4 additions & 0 deletions internal/testlog/testlog.go
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down
36 changes: 0 additions & 36 deletions log/handler.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
28 changes: 8 additions & 20 deletions log/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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)
Expand All @@ -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...)
}
Expand Down
8 changes: 3 additions & 5 deletions log/logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}

Expand Down Expand Up @@ -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}
)
Expand All @@ -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)
Expand Down
7 changes: 5 additions & 2 deletions p2p/discover/table.go
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
package discover

import (
"context"
crand "crypto/rand"
"encoding/binary"
"fmt"
Expand Down Expand Up @@ -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)
}
}
Expand Down
5 changes: 4 additions & 1 deletion p2p/msgrate/msgrate.go
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
package msgrate

import (
"context"
"errors"
"math"
"sort"
Expand Down Expand Up @@ -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
Expand Down

0 comments on commit eacee24

Please sign in to comment.