2019-07-22 12:17:27 +03:00
|
|
|
// Copyright 2019 The go-ethereum Authors
|
2019-04-30 14:12:11 +03: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 10:33:50 +03:00
|
|
|
"bytes"
|
|
|
|
"context"
|
|
|
|
"fmt"
|
2020-01-08 18:11:51 +03:00
|
|
|
"sync"
|
2019-04-30 14:12:11 +03:00
|
|
|
"testing"
|
|
|
|
|
|
|
|
"github.com/ethereum/go-ethereum/log"
|
2023-11-29 10:33:50 +03:00
|
|
|
"golang.org/x/exp/slog"
|
2019-04-30 14:12:11 +03:00
|
|
|
)
|
|
|
|
|
2023-11-29 10:33:50 +03:00
|
|
|
const (
|
|
|
|
termTimeFormat = "01-02|15:04:05.000"
|
|
|
|
)
|
2020-01-08 18:11:51 +03: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 10:33:50 +03:00
|
|
|
buf []slog.Record
|
|
|
|
attrs []slog.Attr
|
|
|
|
level slog.Level
|
2020-01-08 18:11:51 +03:00
|
|
|
}
|
|
|
|
|
2023-11-29 10:33:50 +03:00
|
|
|
func (h *bufHandler) Handle(_ context.Context, r slog.Record) error {
|
2020-01-08 18:11:51 +03:00
|
|
|
h.buf = append(h.buf, r)
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
2023-11-29 10:33:50 +03:00
|
|
|
func (h *bufHandler) Enabled(_ context.Context, lvl slog.Level) bool {
|
|
|
|
return lvl <= h.level
|
|
|
|
}
|
|
|
|
|
|
|
|
func (h *bufHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
|
|
|
|
records := make([]slog.Record, len(h.buf))
|
|
|
|
copy(records[:], h.buf[:])
|
|
|
|
return &bufHandler{
|
|
|
|
records,
|
|
|
|
append(h.attrs, attrs...),
|
|
|
|
h.level,
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
func (h *bufHandler) WithGroup(_ string) slog.Handler {
|
|
|
|
panic("not implemented")
|
|
|
|
}
|
|
|
|
|
2020-01-08 18:11:51 +03:00
|
|
|
// Logger returns a logger which logs to the unit test log of t.
|
2023-11-29 10:33:50 +03:00
|
|
|
func Logger(t *testing.T, level slog.Level) log.Logger {
|
|
|
|
handler := bufHandler{
|
|
|
|
[]slog.Record{},
|
|
|
|
[]slog.Attr{},
|
|
|
|
level,
|
|
|
|
}
|
|
|
|
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 18:11:51 +03:00
|
|
|
t: t,
|
2023-11-29 10:33:50 +03:00
|
|
|
l: log.NewLogger(handler),
|
2020-01-08 18:11:51 +03:00
|
|
|
mu: new(sync.Mutex),
|
2023-11-29 10:33:50 +03:00
|
|
|
h: &bh,
|
2020-01-08 18:11:51 +03:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2023-11-29 10:33:50 +03:00
|
|
|
func (l *logger) Write(level slog.Level, msg string, ctx ...interface{}) {}
|
|
|
|
|
2020-01-08 18:11:51 +03: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 10:33:50 +03: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 18:11:51 +03: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 10:33:50 +03:00
|
|
|
func (l *logger) With(ctx ...interface{}) log.Logger {
|
|
|
|
return &logger{l.t, l.l.With(ctx...), l.mu, l.h}
|
2020-01-08 18:11:51 +03:00
|
|
|
}
|
|
|
|
|
2023-11-29 10:33:50 +03:00
|
|
|
func (l *logger) New(ctx ...interface{}) log.Logger {
|
|
|
|
return l.With(ctx...)
|
2020-01-08 18:11:51 +03:00
|
|
|
}
|
|
|
|
|
2023-11-29 10:33:50 +03: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 {
|
slog: faster and less memory-consumption (#28621)
These changes improves the performance of the non-coloured terminal formatting, _quite a lot_.
```
name old time/op new time/op delta
TerminalHandler-8 10.2µs ±15% 5.4µs ± 9% -47.02% (p=0.008 n=5+5)
name old alloc/op new alloc/op delta
TerminalHandler-8 2.17kB ± 0% 0.40kB ± 0% -81.46% (p=0.008 n=5+5)
name old allocs/op new allocs/op delta
TerminalHandler-8 33.0 ± 0% 5.0 ± 0% -84.85% (p=0.008 n=5+5)
```
I tried to _somewhat_ organize the commits, but the it might still be a bit chaotic. Some core insights:
- The function `terminalHandler.Handl` uses a mutex, and writes all output immediately to 'upstream'. Thus, it can reuse a scratch-buffer every time.
- This buffer can be propagated internally, making all the internal formatters either write directly to it,
- OR, make use of the `tmp := buf.AvailableBuffer()` in some cases, where a byte buffer "extra capacity" can be temporarily used.
- The `slog` package uses `Attr` by value. It makes sense to minimize operating on them, since iterating / collecting into a new slice, iterating again etc causes copy-on-heap. Better to operate on them only once.
- If we want to do padding, it's better to copy from a constant `space`-buffer than to invoke `bytes.Repeat` every single time.
2023-12-01 15:28:20 +03:00
|
|
|
fmt.Fprintf(buf, " %s=%s", attr.Key, string(log.FormatSlogValue(attr.Value, true, nil)))
|
2023-11-29 10:33:50 +03:00
|
|
|
}
|
|
|
|
buf.WriteByte('\n')
|
|
|
|
return buf.String()
|
2020-01-08 18:11:51 +03:00
|
|
|
}
|
|
|
|
|
|
|
|
// flush writes all buffered messages and clears the buffer.
|
|
|
|
func (l *logger) flush() {
|
|
|
|
l.t.Helper()
|
|
|
|
for _, r := range l.h.buf {
|
2023-11-29 10:33:50 +03:00
|
|
|
l.t.Logf("%s", l.h.terminalFormat(r))
|
2020-01-08 18:11:51 +03:00
|
|
|
}
|
|
|
|
l.h.buf = nil
|
|
|
|
}
|