From 7d4613f39fbd15846fe1acd255a72bb79bc3207f Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Wed, 29 Nov 2023 10:27:42 +0100 Subject: [PATCH 1/4] log: remove unused code, un-exports other code, clean up --- internal/debug/flags.go | 6 ++-- internal/testlog/testlog.go | 2 +- log/format.go | 55 ++++++++----------------------------- log/handler.go | 9 +++--- 4 files changed, 21 insertions(+), 51 deletions(-) diff --git a/internal/debug/flags.go b/internal/debug/flags.go index 23e4745e8c8..228213053a3 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -241,11 +241,11 @@ func Setup(ctx *cli.Context) error { case ctx.Bool(logjsonFlag.Name): // Retain backwards compatibility with `--log.json` flag if `--log.format` not set defer log.Warn("The flag '--log.json' is deprecated, please use '--log.format=json' instead") - handler = log.JSONHandler(output) + handler = log.NewJSONHandler(output) case logFmtFlag == "json": - handler = log.JSONHandler(output) + handler = log.NewJSONHandler(output) case logFmtFlag == "logfmt": - handler = log.LogfmtHandler(output) + handler = log.NewLogfmtHandler(output) case logFmtFlag == "", logFmtFlag == "terminal": useColor := (isatty.IsTerminal(os.Stderr.Fd()) || isatty.IsCygwinTerminal(os.Stderr.Fd())) && os.Getenv("TERM") != "dumb" if useColor { diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index a7899c81589..735baa2101b 100644 --- a/internal/testlog/testlog.go +++ b/internal/testlog/testlog.go @@ -183,7 +183,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 a2bbcce9c05..6447f3c1f1e 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 1a25577450e..ff1a2302f01 100644 --- a/log/handler.go +++ b/log/handler.go @@ -112,7 +112,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,17 +149,18 @@ func (l *leveler) Level() slog.Level { return l.minLevel } -func JSONHandler(wr io.Writer) slog.Handler { +// NewJSONHandler returns a handler which prints records in JSON format. +func NewJSONHandler(wr io.Writer) slog.Handler { return slog.NewJSONHandler(wr, &slog.HandlerOptions{ ReplaceAttr: builtinReplaceJSON, }) } -// LogfmtHandler returns a handler which prints records in logfmt format, an easy machine-parseable but human-readable +// NewLogfmtHandler returns a handler which prints records in logfmt format, an easy machine-parseable but human-readable // format for key/value pairs. // // For more details see: http://godoc.org/github.com/kr/logfmt -func LogfmtHandler(wr io.Writer) slog.Handler { +func NewLogfmtHandler(wr io.Writer) slog.Handler { return slog.NewTextHandler(wr, &slog.HandlerOptions{ ReplaceAttr: builtinReplaceLogfmt, }) From 75b5c8f93fd1595fd0c8282c940e39b1b8e61a4f Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Wed, 29 Nov 2023 15:14:29 +0100 Subject: [PATCH 2/4] cmd/geth: add tests for log entries with mising attributes --- cmd/geth/logtestcmd_active.go | 7 +++++-- cmd/geth/testdata/logging/logtest-json.txt | 2 ++ cmd/geth/testdata/logging/logtest-logfmt.txt | 2 ++ cmd/geth/testdata/logging/logtest-terminal.txt | 2 ++ 4 files changed, 11 insertions(+), 2 deletions(-) diff --git a/cmd/geth/logtestcmd_active.go b/cmd/geth/logtestcmd_active.go index 0ca4cc621dc..21313c24b5e 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") @@ -166,6 +165,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 bdc1ae4de6c..29435288331 100644 --- a/cmd/geth/testdata/logging/logtest-json.txt +++ b/cmd/geth/testdata/logging/logtest-json.txt @@ -49,3 +49,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 114569e467c..25ca7c004b2 100644 --- a/cmd/geth/testdata/logging/logtest-logfmt.txt +++ b/cmd/geth/testdata/logging/logtest-logfmt.txt @@ -49,3 +49,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 4da3f49d46a..ae6f633d70d 100644 --- a/cmd/geth/testdata/logging/logtest-terminal.txt +++ b/cmd/geth/testdata/logging/logtest-terminal.txt @@ -50,3 +50,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" From eacee243a308b28678fb93a38dfc098357ce1f3f Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Wed, 29 Nov 2023 15:27:58 +0100 Subject: [PATCH 3/4] log: remove notion of lazy handler 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) ``` --- cmd/geth/logtestcmd_active.go | 3 -- cmd/geth/testdata/logging/logtest-json.txt | 1 - cmd/geth/testdata/logging/logtest-logfmt.txt | 1 - .../testdata/logging/logtest-terminal.txt | 3 +- internal/testlog/testlog.go | 4 +++ log/handler.go | 36 ------------------- log/logger.go | 28 +++++---------- log/logger_test.go | 8 ++--- p2p/discover/table.go | 7 ++-- p2p/msgrate/msgrate.go | 5 ++- 10 files changed, 25 insertions(+), 71 deletions(-) diff --git a/cmd/geth/logtestcmd_active.go b/cmd/geth/logtestcmd_active.go index 21313c24b5e..5cce1ec6abc 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 29435288331..3bfe718660c 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 25ca7c004b2..f20d66635d3 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 ae6f633d70d..e3b562117c4 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 735baa2101b..037b7ee9c12 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 ff1a2302f01..3a205902de6 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 3e227745adf..93d62f080b7 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 27e90c5fd20..a2a114bb5f6 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 f476d2079f8..e6dafb0dcaa 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 4f08792242a..de1a3177db0 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 From 4d38c842bf4e32f6a4ce684a0985a03831db9b5c Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Tue, 5 Dec 2023 10:10:54 +0100 Subject: [PATCH 4/4] log: undo New-renaming for handler constructors --- internal/debug/flags.go | 6 +++--- log/handler.go | 8 ++++---- log/logger_test.go | 4 ++-- 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/internal/debug/flags.go b/internal/debug/flags.go index 228213053a3..23e4745e8c8 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -241,11 +241,11 @@ func Setup(ctx *cli.Context) error { case ctx.Bool(logjsonFlag.Name): // Retain backwards compatibility with `--log.json` flag if `--log.format` not set defer log.Warn("The flag '--log.json' is deprecated, please use '--log.format=json' instead") - handler = log.NewJSONHandler(output) + handler = log.JSONHandler(output) case logFmtFlag == "json": - handler = log.NewJSONHandler(output) + handler = log.JSONHandler(output) case logFmtFlag == "logfmt": - handler = log.NewLogfmtHandler(output) + handler = log.LogfmtHandler(output) case logFmtFlag == "", logFmtFlag == "terminal": useColor := (isatty.IsTerminal(os.Stderr.Fd()) || isatty.IsCygwinTerminal(os.Stderr.Fd())) && os.Getenv("TERM") != "dumb" if useColor { diff --git a/log/handler.go b/log/handler.go index 3a205902de6..7459aad8913 100644 --- a/log/handler.go +++ b/log/handler.go @@ -113,18 +113,18 @@ func (l *leveler) Level() slog.Level { return l.minLevel } -// NewJSONHandler returns a handler which prints records in JSON format. -func NewJSONHandler(wr io.Writer) slog.Handler { +// 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, }) } -// NewLogfmtHandler returns a handler which prints records in logfmt format, an easy machine-parseable but human-readable +// LogfmtHandler returns a handler which prints records in logfmt format, an easy machine-parseable but human-readable // format for key/value pairs. // // For more details see: http://godoc.org/github.com/kr/logfmt -func NewLogfmtHandler(wr io.Writer) slog.Handler { +func LogfmtHandler(wr io.Writer) slog.Handler { return slog.NewTextHandler(wr, &slog.HandlerOptions{ ReplaceAttr: builtinReplaceLogfmt, }) diff --git a/log/logger_test.go b/log/logger_test.go index a2a114bb5f6..a633f5ad7a4 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(NewLogfmtHandler(io.Discard)) + l := NewLogger(LogfmtHandler(io.Discard)) benchmarkLogger(b, l) } func BenchmarkJSONHandler(b *testing.B) { - l := NewLogger(NewJSONHandler(io.Discard)) + l := NewLogger(JSONHandler(io.Discard)) benchmarkLogger(b, l) }