2019-07-22 12:17:27 +03:00
|
|
|
// Copyright 2019 The go-ethereum Authors
|
2019-04-30 13:12:11 +02:00
|
|
|
// This file is part of the go-ethereum library.
|
|
|
|
//
|
|
|
|
// The go-ethereum library is free software: you can redistribute it and/or modify
|
|
|
|
// it under the terms of the GNU Lesser General Public License as published by
|
|
|
|
// the Free Software Foundation, either version 3 of the License, or
|
|
|
|
// (at your option) any later version.
|
|
|
|
//
|
|
|
|
// The go-ethereum library is distributed in the hope that it will be useful,
|
|
|
|
// but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
|
|
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
|
|
|
|
// GNU Lesser General Public License for more details.
|
|
|
|
//
|
|
|
|
// You should have received a copy of the GNU Lesser General Public License
|
|
|
|
// along with the go-ethereum library. If not, see <http://www.gnu.org/licenses/>.
|
|
|
|
|
|
|
|
// Package testlog provides a log handler for unit tests.
|
|
|
|
package testlog
|
|
|
|
|
|
|
|
import (
|
2023-11-29 15:33:50 +08:00
|
|
|
"bytes"
|
|
|
|
"context"
|
|
|
|
"fmt"
|
2024-03-22 13:17:59 +01:00
|
|
|
"log/slog"
|
2020-01-08 16:11:51 +01:00
|
|
|
"sync"
|
2019-04-30 13:12:11 +02:00
|
|
|
"testing"
|
|
|
|
|
|
|
|
"github.com/ethereum/go-ethereum/log"
|
|
|
|
)
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
const (
|
|
|
|
termTimeFormat = "01-02|15:04:05.000"
|
|
|
|
)
|
2020-01-08 16:11:51 +01:00
|
|
|
|
|
|
|
// logger implements log.Logger such that all output goes to the unit test log via
|
|
|
|
// t.Logf(). All methods in between logger.Trace, logger.Debug, etc. are marked as test
|
|
|
|
// helpers, so the file and line number in unit test output correspond to the call site
|
|
|
|
// which emitted the log message.
|
|
|
|
type logger struct {
|
|
|
|
t *testing.T
|
|
|
|
l log.Logger
|
|
|
|
mu *sync.Mutex
|
|
|
|
h *bufHandler
|
|
|
|
}
|
|
|
|
|
|
|
|
type bufHandler struct {
|
2023-11-29 15:33:50 +08:00
|
|
|
buf []slog.Record
|
|
|
|
attrs []slog.Attr
|
|
|
|
level slog.Level
|
2024-03-20 15:22:52 +01:00
|
|
|
mu sync.Mutex
|
2020-01-08 16:11:51 +01:00
|
|
|
}
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
func (h *bufHandler) Handle(_ context.Context, r slog.Record) error {
|
2024-03-20 15:22:52 +01:00
|
|
|
h.mu.Lock()
|
|
|
|
defer h.mu.Unlock()
|
2020-01-08 16:11:51 +01:00
|
|
|
h.buf = append(h.buf, r)
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
func (h *bufHandler) Enabled(_ context.Context, lvl slog.Level) bool {
|
p2p/discover: improved node revalidation (#29572)
Node discovery periodically revalidates the nodes in its table by sending PING, checking
if they are still alive. I recently noticed some issues with the implementation of this
process, which can cause strange results such as nodes dropping unexpectedly, certain
nodes not getting revalidated often enough, and bad results being returned to incoming
FINDNODE queries.
In this change, the revalidation process is improved with the following logic:
- We maintain two 'revalidation lists' containing the table nodes, named 'fast' and 'slow'.
- The process chooses random nodes from each list on a randomized interval, the interval being
faster for the 'fast' list, and performs revalidation for the chosen node.
- Whenever a node is newly inserted into the table, it goes into the 'fast' list.
Once validation passes, it transfers to the 'slow' list. If a request fails, or the
node changes endpoint, it transfers back into 'fast'.
- livenessChecks is incremented by one for successful checks. Unlike the old implementation,
we will not drop the node on the first failing check. We instead quickly decay the
livenessChecks give it another chance.
- Order of nodes in bucket doesn't matter anymore.
I am also adding a debug API endpoint to dump the node table content.
Co-authored-by: Martin HS <martin@swende.se>
2024-05-23 14:26:09 +02:00
|
|
|
return lvl >= h.level
|
2023-11-29 15:33:50 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
func (h *bufHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
|
2024-03-20 15:22:52 +01:00
|
|
|
h.mu.Lock()
|
|
|
|
defer h.mu.Unlock()
|
2023-11-29 15:33:50 +08:00
|
|
|
records := make([]slog.Record, len(h.buf))
|
|
|
|
copy(records[:], h.buf[:])
|
|
|
|
return &bufHandler{
|
2024-03-20 15:22:52 +01:00
|
|
|
buf: records,
|
|
|
|
attrs: append(h.attrs, attrs...),
|
|
|
|
level: h.level,
|
2023-11-29 15:33:50 +08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
func (h *bufHandler) WithGroup(_ string) slog.Handler {
|
|
|
|
panic("not implemented")
|
|
|
|
}
|
|
|
|
|
2020-01-08 16:11:51 +01:00
|
|
|
// Logger returns a logger which logs to the unit test log of t.
|
2023-11-29 15:33:50 +08:00
|
|
|
func Logger(t *testing.T, level slog.Level) log.Logger {
|
|
|
|
handler := bufHandler{
|
2024-03-20 15:22:52 +01:00
|
|
|
buf: []slog.Record{},
|
|
|
|
attrs: []slog.Attr{},
|
|
|
|
level: level,
|
2023-11-29 15:33:50 +08:00
|
|
|
}
|
|
|
|
return &logger{
|
|
|
|
t: t,
|
|
|
|
l: log.NewLogger(&handler),
|
|
|
|
mu: new(sync.Mutex),
|
|
|
|
h: &handler,
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
// LoggerWithHandler returns
|
|
|
|
func LoggerWithHandler(t *testing.T, handler slog.Handler) log.Logger {
|
|
|
|
var bh bufHandler
|
|
|
|
return &logger{
|
2020-01-08 16:11:51 +01:00
|
|
|
t: t,
|
2023-11-29 15:33:50 +08:00
|
|
|
l: log.NewLogger(handler),
|
2020-01-08 16:11:51 +01:00
|
|
|
mu: new(sync.Mutex),
|
2023-11-29 15:33:50 +08:00
|
|
|
h: &bh,
|
2020-01-08 16:11:51 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2024-03-08 00:01:31 +01:00
|
|
|
func (l *logger) Handler() slog.Handler {
|
|
|
|
return l.l.Handler()
|
|
|
|
}
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
func (l *logger) Write(level slog.Level, msg string, ctx ...interface{}) {}
|
|
|
|
|
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)
```
2023-12-05 11:54:44 +01:00
|
|
|
func (l *logger) Enabled(ctx context.Context, level slog.Level) bool {
|
|
|
|
return l.l.Enabled(ctx, level)
|
|
|
|
}
|
|
|
|
|
2020-01-08 16:11:51 +01:00
|
|
|
func (l *logger) Trace(msg string, ctx ...interface{}) {
|
|
|
|
l.t.Helper()
|
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.l.Trace(msg, ctx...)
|
|
|
|
l.flush()
|
|
|
|
}
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
func (l *logger) Log(level slog.Level, msg string, ctx ...interface{}) {
|
|
|
|
l.t.Helper()
|
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.l.Log(level, msg, ctx...)
|
|
|
|
l.flush()
|
|
|
|
}
|
|
|
|
|
2020-01-08 16:11:51 +01:00
|
|
|
func (l *logger) Debug(msg string, ctx ...interface{}) {
|
|
|
|
l.t.Helper()
|
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.l.Debug(msg, ctx...)
|
|
|
|
l.flush()
|
|
|
|
}
|
|
|
|
|
|
|
|
func (l *logger) Info(msg string, ctx ...interface{}) {
|
|
|
|
l.t.Helper()
|
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.l.Info(msg, ctx...)
|
|
|
|
l.flush()
|
|
|
|
}
|
|
|
|
|
|
|
|
func (l *logger) Warn(msg string, ctx ...interface{}) {
|
|
|
|
l.t.Helper()
|
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.l.Warn(msg, ctx...)
|
|
|
|
l.flush()
|
|
|
|
}
|
|
|
|
|
|
|
|
func (l *logger) Error(msg string, ctx ...interface{}) {
|
|
|
|
l.t.Helper()
|
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.l.Error(msg, ctx...)
|
|
|
|
l.flush()
|
|
|
|
}
|
|
|
|
|
|
|
|
func (l *logger) Crit(msg string, ctx ...interface{}) {
|
|
|
|
l.t.Helper()
|
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.l.Crit(msg, ctx...)
|
|
|
|
l.flush()
|
|
|
|
}
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
func (l *logger) With(ctx ...interface{}) log.Logger {
|
|
|
|
return &logger{l.t, l.l.With(ctx...), l.mu, l.h}
|
2020-01-08 16:11:51 +01:00
|
|
|
}
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
func (l *logger) New(ctx ...interface{}) log.Logger {
|
|
|
|
return l.With(ctx...)
|
2020-01-08 16:11:51 +01:00
|
|
|
}
|
|
|
|
|
2023-11-29 15:33:50 +08:00
|
|
|
// terminalFormat formats a message similarly to the NewTerminalHandler in the log package.
|
|
|
|
// The difference is that terminalFormat does not escape messages/attributes and does not pad attributes.
|
|
|
|
func (h *bufHandler) terminalFormat(r slog.Record) string {
|
|
|
|
buf := &bytes.Buffer{}
|
|
|
|
lvl := log.LevelAlignedString(r.Level)
|
|
|
|
attrs := []slog.Attr{}
|
|
|
|
r.Attrs(func(attr slog.Attr) bool {
|
|
|
|
attrs = append(attrs, attr)
|
|
|
|
return true
|
|
|
|
})
|
|
|
|
|
|
|
|
attrs = append(h.attrs, attrs...)
|
|
|
|
|
|
|
|
fmt.Fprintf(buf, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), r.Message)
|
|
|
|
if length := len(r.Message); length < 40 {
|
|
|
|
buf.Write(bytes.Repeat([]byte{' '}, 40-length))
|
|
|
|
}
|
|
|
|
|
|
|
|
for _, attr := range attrs {
|
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)
```
2023-12-05 11:54:44 +01:00
|
|
|
fmt.Fprintf(buf, " %s=%s", attr.Key, string(log.FormatSlogValue(attr.Value, nil)))
|
2023-11-29 15:33:50 +08:00
|
|
|
}
|
|
|
|
buf.WriteByte('\n')
|
|
|
|
return buf.String()
|
2020-01-08 16:11:51 +01:00
|
|
|
}
|
|
|
|
|
|
|
|
// flush writes all buffered messages and clears the buffer.
|
|
|
|
func (l *logger) flush() {
|
|
|
|
l.t.Helper()
|
2024-03-20 15:22:52 +01:00
|
|
|
l.h.mu.Lock()
|
|
|
|
defer l.h.mu.Unlock()
|
2020-01-08 16:11:51 +01:00
|
|
|
for _, r := range l.h.buf {
|
2023-11-29 15:33:50 +08:00
|
|
|
l.t.Logf("%s", l.h.terminalFormat(r))
|
2020-01-08 16:11:51 +01:00
|
|
|
}
|
|
|
|
l.h.buf = nil
|
|
|
|
}
|