go-ethereum/log/logger_test.go

package log

import (
	"bytes"
	"errors"
	"fmt"
	"io"
	"log/slog"
	"math/big"
	"strings"
	"testing"
	"time"

	"github.com/holiman/uint256"
)

// TestLoggingWithVmodule checks that vmodule works.
func TestLoggingWithVmodule(t *testing.T) {
	out := new(bytes.Buffer)
	glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false))
	glog.Verbosity(LevelCrit)
	logger := NewLogger(glog)
	logger.Warn("This should not be seen", "ignored", "true")
	glog.Vmodule("logger_test.go=5")
	logger.Trace("a message", "foo", "bar")
	have := out.String()
	// The timestamp is locale-dependent, so we want to trim that off
	// "INFO [01-01|00:00:00.000] a message ..." -> "a message..."
	have = strings.Split(have, "]")[1]
	want := " a message                                foo=bar\n"
	if have != want {
		t.Errorf("\nhave: %q\nwant: %q\n", have, want)
	}
}

// TestLoggingWithVmoduleDowngrade checks that vmodule can be downgraded.
func TestLoggingWithVmoduleDowngrade(t *testing.T) {
	out := new(bytes.Buffer)
	glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false))
	glog.Verbosity(LevelTrace) // Allow all logs globally
	logger := NewLogger(glog)

	// This should appear (global level allows it)
	logger.Info("before vmodule downgrade, this should be logged")
	if !bytes.Contains(out.Bytes(), []byte("before vmodule downgrade")) {
		t.Fatal("expected 'before vmodule downgrade' to be logged")
	}
	out.Reset()

	// Downgrade this file to only allow Warn and above
	glog.Vmodule("logger_test.go=2")

	// Info should now be filtered out
	logger.Info("after vmodule downgrade, this should be filtered")
	if bytes.Contains(out.Bytes(), []byte("after vmodule downgrade, this should be filtered")) {
		t.Fatal("expected 'after vmodule downgrade, this should be filtered' to NOT be logged after vmodule downgrade")
	}

	// Warn should still appear
	logger.Warn("after vmodule downgrade, this should be logged")
	if !bytes.Contains(out.Bytes(), []byte("after vmodule downgrade, this should be logged")) {
		t.Fatal("expected 'should appear' to be logged")
	}
}

// TestWithAttrsVerbosityChange checks that verbosity changes affect child loggers.
func TestWithAttrsVerbosityChange(t *testing.T) {
	out := new(bytes.Buffer)
	glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false))
	glog.Verbosity(LevelInfo)

	// Create a child logger with an extra attribute.
	child := slog.New(glog.WithAttrs([]slog.Attr{slog.String("peer", "foo")}))

	// Debug should be filtered at Info level.
	child.Debug("this should be filtered")
	if bytes.Contains(out.Bytes(), []byte("this should be filtered")) {
		t.Fatal("expected debug message to be filtered at Info level")
	}

	// Change verbosity on the parent to allow Debug.
	glog.Verbosity(LevelDebug)

	// Child should pick up the new level and include its attributes.
	child.Debug("this should be logged")
	if !bytes.Contains(out.Bytes(), []byte("this should be logged")) {
		t.Fatal("expected child logger to pick up verbosity change")
	}
	if !bytes.Contains(out.Bytes(), []byte("peer=foo")) {
		t.Fatal("expected child logger to include WithAttrs attributes")
	}
}

func TestTerminalHandlerWithAttrs(t *testing.T) {
	out := new(bytes.Buffer)
	glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false).WithAttrs([]slog.Attr{slog.String("baz", "bat")}))
	glog.Verbosity(LevelTrace)
	logger := NewLogger(glog)
	logger.Trace("a message", "foo", "bar")
	have := out.String()
	// The timestamp is locale-dependent, so we want to trim that off
	// "INFO [01-01|00:00:00.000] a message ..." -> "a message..."
	have = strings.Split(have, "]")[1]
	want := " a message                                baz=bat foo=bar\n"
	if have != want {
		t.Errorf("\nhave: %q\nwant: %q\n", have, want)
	}
}

// Make sure the default json handler outputs debug log lines
func TestJSONHandler(t *testing.T) {
	out := new(bytes.Buffer)
	handler := JSONHandler(out)
	logger := slog.New(handler)
	logger.Debug("hi there")
	if len(out.String()) == 0 {
		t.Error("expected non-empty debug log output from default JSON Handler")
	}

	out.Reset()
	handler = JSONHandlerWithLevel(out, slog.LevelInfo)
	logger = slog.New(handler)
	logger.Debug("hi there")
	if len(out.String()) != 0 {
		t.Errorf("expected empty debug log output, but got: %v", out.String())
	}
}

func BenchmarkTraceLogging(b *testing.B) {
	SetDefault(NewLogger(NewTerminalHandler(io.Discard, true)))
	i := 0
	for b.Loop() {
		Trace("a message", "v", i)
		i++
	}
}

func BenchmarkTerminalHandler(b *testing.B) {
	l := NewLogger(NewTerminalHandler(io.Discard, false))
	benchmarkLogger(b, l)
}
func BenchmarkLogfmtHandler(b *testing.B) {
	l := NewLogger(LogfmtHandler(io.Discard))
	benchmarkLogger(b, l)
}

func BenchmarkJSONHandler(b *testing.B) {
	l := NewLogger(JSONHandler(io.Discard))
	benchmarkLogger(b, l)
}

func benchmarkLogger(b *testing.B, l Logger) {
	var (
		bb     = make([]byte, 10)
		tt     = time.Now()
		bigint = big.NewInt(100)
		nilbig *big.Int
		err    = errors.New("oh nooes it's crap")
	)
	b.ReportAllocs()
	i := 0
	for b.Loop() {
		l.Info("This is a message",
			"foo", int16(i),
			"bytes", bb,
			"bonk", "a string with text",
			"time", tt,
			"bigint", bigint,
			"nilbig", nilbig,
			"err", err)
		i++
	}
}

func TestLoggerOutput(t *testing.T) {
	type custom struct {
		A string
		B int8
	}
	var (
		customA   = custom{"Foo", 12}
		customB   = custom{"Foo\nLinebreak", 122}
		bb        = make([]byte, 10)
		tt        = time.Time{}
		bigint    = big.NewInt(100)
		nilbig    *big.Int
		err       = errors.New("oh nooes it's crap")
		smallUint = uint256.NewInt(500_000)
		bigUint   = &uint256.Int{0xff, 0xff, 0xff, 0xff}
	)

	out := new(bytes.Buffer)
	glogHandler := NewGlogHandler(NewTerminalHandler(out, false))
	glogHandler.Verbosity(LevelInfo)
	NewLogger(glogHandler).Info("This is a message",
		"foo", int16(123),
		"bytes", bb,
		"bonk", "a string with text",
		"time", tt,
		"bigint", bigint,
		"nilbig", nilbig,
		"err", err,
		"struct", customA,
		"struct", customB,
		"ptrstruct", &customA,
		"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}" 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)
	}
}

const termTimeFormat = "01-02|15:04:05.000"

func BenchmarkAppendFormat(b *testing.B) {
	var now = time.Now()
	b.Run("fmt time.Format", func(b *testing.B) {
		for b.Loop() {
			fmt.Fprintf(io.Discard, "%s", now.Format(termTimeFormat))
		}
	})
	b.Run("time.AppendFormat", func(b *testing.B) {
		for b.Loop() {
			now.AppendFormat(nil, termTimeFormat)
		}
	})
	var buf = new(bytes.Buffer)
	b.Run("time.Custom", func(b *testing.B) {
		for b.Loop() {
			writeTimeTermFormat(buf, now)
			buf.Reset()
		}
	})
}

func TestTermTimeFormat(t *testing.T) {
	var now = time.Now()
	want := now.AppendFormat(nil, termTimeFormat)
	var b = new(bytes.Buffer)
	writeTimeTermFormat(b, now)
	have := b.Bytes()
	if !bytes.Equal(have, want) {
		t.Errorf("have != want\nhave: %q\nwant: %q\n", have, want)
	}
}