cmd/geth: test for logging-output

cmd/geth/logging_test.go

@@ -0,0 +1,183 @@
+// Copyright 2023 The go-ethereum Authors
+// This file is part of go-ethereum.
+//
+// go-ethereum is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+//
+// go-ethereum 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 General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License
+// along with go-ethereum. If not, see <http://www.gnu.org/licenses/>.
+
+package main
+
+import (
+	"bufio"
+	"bytes"
+	"fmt"
+	"io"
+	"math/rand"
+	"os"
+	"os/exec"
+	"strings"
+	"testing"
+
+	"github.com/docker/docker/pkg/reexec"
+)
+
+func runSelf(args ...string) ([]byte, error) {
+	cmd := &exec.Cmd{
+		Path: reexec.Self(),
+		Args: append([]string{"geth-test"}, args...),
+	}
+	return cmd.CombinedOutput()
+}
+
+func split(input io.Reader) []string {
+	var output []string
+	scanner := bufio.NewScanner(input)
+	scanner.Split(bufio.ScanLines)
+	for scanner.Scan() {
+		output = append(output, strings.TrimSpace(scanner.Text()))
+	}
+	return output
+}
+
+func censor(input string, start, end int) string {
+	if len(input) < end {
+		return input
+	}
+	return input[:start] + strings.Repeat("X", end-start) + input[end:]
+}
+
+func TestLogging(t *testing.T) {
+	testConsoleLogging(t, "terminal", 6, 24)
+	testConsoleLogging(t, "logfmt", 2, 26)
+}
+
+func testConsoleLogging(t *testing.T, format string, tStart, tEnd int) {
+	haveB, err := runSelf("--log.format", format, "logtest")
+	if err != nil {
+		t.Fatal(err)
+	}
+	readFile, err := os.Open(fmt.Sprintf("testdata/logging/logtest-%v.txt", format))
+	if err != nil {
+		t.Fatal(err)
+	}
+	wantLines := split(readFile)
+	haveLines := split(bytes.NewBuffer(haveB))
+	for i, want := range wantLines {
+		if i > len(haveLines)-1 {
+			t.Fatalf("format %v, line %d missing, want:%v", format, i, want)
+		}
+		have := haveLines[i]
+		for strings.Contains(have, "Unknown config environment variable") {
+			// This can happen on CI runs. Drop it.
+			haveLines = append(haveLines[:i], haveLines[i+1:]...)
+			have = haveLines[i]
+		}
+
+		// Black out the timestamp
+		have = censor(have, tStart, tEnd)
+		want = censor(want, tStart, tEnd)
+		if have != want {
+			t.Logf(nicediff([]byte(have), []byte(want)))
+			t.Fatalf("format %v, line %d\nhave %v\nwant %v", format, i, have, want)
+		}
+	}
+	if len(haveLines) != len(wantLines) {
+		t.Errorf("format %v, want %d lines, have %d", format, len(haveLines), len(wantLines))
+	}
+}
+
+func TestVmodule(t *testing.T) {
+	checkOutput := func(level int, want, wantNot string) {
+		t.Helper()
+		output, err := runSelf("--log.format", "terminal", "--verbosity=0", "--log.vmodule", fmt.Sprintf("logtestcmd.go=%d", level), "logtest")
+		if err != nil {
+			t.Fatal(err)
+		}
+		if len(want) > 0 && !strings.Contains(string(output), want) { // trace should be present at 5
+			t.Errorf("failed to find expected string ('%s') in output", want)
+		}
+		if len(wantNot) > 0 && strings.Contains(string(output), wantNot) { // trace should be present at 5
+			t.Errorf("string ('%s') should not be present in output", wantNot)
+		}
+	}
+	checkOutput(5, "log at level trace", "")                   // trace should be present at 5
+	checkOutput(4, "log at level debug", "log at level trace") // debug should be present at 4, but trace should be missing
+	checkOutput(3, "log at level info", "log at level debug")  // info should be present at 3, but debug should be missing
+	checkOutput(2, "log at level warn", "log at level info")   // warn should be present at 2, but info should be missing
+	checkOutput(1, "log at level error", "log at level warn")  // error should be present at 1, but warn should be missing
+}
+
+func nicediff(have, want []byte) string {
+	var i = 0
+	for ; i < len(have) && i < len(want); i++ {
+		if want[i] != have[i] {
+			break
+		}
+	}
+	var end = i + 40
+	var start = i - 50
+	if start < 0 {
+		start = 0
+	}
+	var h, w string
+	if end < len(have) {
+		h = string(have[start:end])
+	} else {
+		h = string(have[start:])
+	}
+	if end < len(want) {
+		w = string(want[start:end])
+	} else {
+		w = string(want[start:])
+	}
+	return fmt.Sprintf("have vs want:\n%q\n%q\n", h, w)
+}
+
+func TestFileOut(t *testing.T) {
+	var (
+		have, want []byte
+		err        error
+		path       = fmt.Sprintf("%s/test_file_out-%d", os.TempDir(), rand.Int63())
+	)
+	t.Cleanup(func() { os.Remove(path) })
+	if want, err = runSelf(fmt.Sprintf("--log.file=%s", path), "logtest"); err != nil {
+		t.Fatal(err)
+	}
+	if have, err = os.ReadFile(path); err != nil {
+		t.Fatal(err)
+	}
+	if !bytes.Equal(have, want) {
+		// show an intelligent diff
+		t.Logf(nicediff(have, want))
+		t.Errorf("file content wrong")
+	}
+}
+
+func TestRotatingFileOut(t *testing.T) {
+	var (
+		have, want []byte
+		err        error
+		path       = fmt.Sprintf("%s/test_file_out-%d", os.TempDir(), rand.Int63())
+	)
+	t.Cleanup(func() { os.Remove(path) })
+	if want, err = runSelf(fmt.Sprintf("--log.file=%s", path), "--log.rotate", "logtest"); err != nil {
+		t.Fatal(err)
+	}
+	if have, err = os.ReadFile(path); err != nil {
+		t.Fatal(err)
+	}
+	if !bytes.Equal(have, want) {
+		// show an intelligent diff
+		t.Logf(nicediff(have, want))
+		t.Errorf("file content wrong")
+	}
+}

cmd/geth/logtestcmd.go

@@ -0,0 +1,123 @@
+// Copyright 2023 The go-ethereum Authors
+// This file is part of go-ethereum.
+//
+// go-ethereum is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+//
+// go-ethereum 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 General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License
+// along with go-ethereum. If not, see <http://www.gnu.org/licenses/>.
+
+package main
+
+import (
+	"fmt"
+	"math"
+	"math/big"
+	"time"
+
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/holiman/uint256"
+	"github.com/urfave/cli/v2"
+)
+
+// logTest is an entry point which spits out some logs. This is used by testing
+// to verify expected outputs
+func logTest(ctx *cli.Context) error {
+	log.ResetGlobalState()
+	{ // big.Int
+		ba, _ := new(big.Int).SetString("111222333444555678999", 10)    // "111,222,333,444,555,678,999"
+		bb, _ := new(big.Int).SetString("-111222333444555678999", 10)   // "-111,222,333,444,555,678,999"
+		bc, _ := new(big.Int).SetString("11122233344455567899900", 10)  // "11,122,233,344,455,567,899,900"
+		bd, _ := new(big.Int).SetString("-11122233344455567899900", 10) // "-11,122,233,344,455,567,899,900"
+		log.Info("big.Int", "111,222,333,444,555,678,999", ba)
+		log.Info("-big.Int", "-111,222,333,444,555,678,999", bb)
+		log.Info("big.Int", "11,122,233,344,455,567,899,900", bc)
+		log.Info("-big.Int", "-11,122,233,344,455,567,899,900", bd)
+	}
+	{ //uint256
+		ua, _ := uint256.FromDecimal("111222333444555678999")
+		ub, _ := uint256.FromDecimal("11122233344455567899900")
+		log.Info("uint256", "111,222,333,444,555,678,999", ua)
+		log.Info("uint256", "11,122,233,344,455,567,899,900", ub)
+	}
+	{ // int64
+		log.Info("int64", "1,000,000", int64(1000000))
+		log.Info("int64", "-1,000,000", int64(-1000000))
+		log.Info("int64", "9,223,372,036,854,775,807", int64(math.MaxInt64))
+		log.Info("int64", "-9,223,372,036,854,775,808", int64(math.MinInt64))
+	}
+	{ // uint64
+		log.Info("uint64", "1,000,000", uint64(1000000))
+		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")
+
+		log.Info("nospace", "nospace", "nospace")
+		log.Info("with space", "with nospace", "with nospace")
+
+		log.Info("Bash escapes in value", "key", "\u001b[1G\u001b[K\u001b[1A")
+		log.Info("Bash escapes in key", "\u001b[1G\u001b[K\u001b[1A", "value")
+
+		log.Info("Bash escapes in message  \u001b[1G\u001b[K\u001b[1A end", "key", "value")
+
+		colored := fmt.Sprintf("\u001B[%dmColored\u001B[0m[", 35)
+		log.Info(colored, colored, colored)
+	}
+	{ // Custom Stringer() - type
+		log.Info("Custom Stringer value", "2562047h47m16.854s", common.PrettyDuration(time.Duration(9223372036854775807)))
+	}
+	{ // 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")
+		log.Info("A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above")
+	}
+	{ // Miscellaneous json-quirks
+		// This will check if the json output uses strings or json-booleans to represent bool values
+		log.Info("boolean", "true", true, "false", false)
+		// Handling of duplicate keys.
+		// This is actually ill-handled by the current handler: the format.go
+		// uses a global 'fieldPadding' map and mixes up the two keys. If 'alpha'
+		// is shorter than beta, it sometimes causes erroneous padding -- and what's more
+		// it causes _different_ padding in multi-handler context, e.g. both file-
+		// and console output, making the two mismatch.
+		log.Info("repeated-key 1", "foo", "alpha", "foo", "beta")
+		log.Info("repeated-key 2", "xx", "short", "xx", "longer")
+	}
+	{ // loglevels
+		log.Debug("log at level debug")
+		log.Trace("log at level trace")
+		log.Info("log at level info")
+		log.Warn("log at level warn")
+		log.Error("log at level error")
+	}
+	{
+		// The current log formatter has a global map of paddings, storing the
+		// longest seen padding per key in a map. This results in a statefulness
+		// which has some odd side-effects. Demonstrated here:
+		log.Info("test", "bar", "short", "a", "aligned left")
+		log.Info("test", "bar", "a long message", "a", 1)
+		log.Info("test", "bar", "short", "a", "aligned right")
+	}
+	{
+		// This sequence of logs should be output with alignment, so each field becoems a column.
+		log.Info("The following logs should align so that the key-fields make 5 columns")
+		log.Info("Inserted known block", "number", 1_012, "hash", common.HexToHash("0x1234"), "txs", 200, "gas", 1_123_123, "other", "first")
+		log.Info("Inserted new block", "number", 1, "hash", common.HexToHash("0x1235"), "txs", 2, "gas", 1_123, "other", "second")
+		log.Info("Inserted known block", "number", 99, "hash", common.HexToHash("0x12322"), "txs", 10, "gas", 1, "other", "third")
+		log.Warn("Inserted known block", "number", 1_012, "hash", common.HexToHash("0x1234"), "txs", 200, "gas", 99, "other", "fourth")
+	}
+	return nil
+}

cmd/geth/main.go

@@ -233,6 +233,7 @@ func init() {
 		snapshotCommand,
 		// See verkle.go
 		verkleCommand,
+		logTestCommand,
 	}
 	sort.Sort(cli.CommandsByName(app.Commands))
 

cmd/geth/misccmd.go

@@ -67,6 +67,14 @@ and displays information about any security vulnerabilities that affect the curr
 		Usage:     "Display license information",
 		ArgsUsage: " ",
 	}
+	logTestCommand = &cli.Command{
+		Action:    logTest,
+		Name:      "logtest",
+		Usage:     "Print some log messages",
+		ArgsUsage: " ",
+		Description: `
+This command is only meant for testing.
+`}
 )
 
 func printVersion(ctx *cli.Context) error {

cmd/geth/testdata/logging/logtest-logfmt.txt

@@ -0,0 +1,39 @@
+t=2023-10-20T12:56:08+0200 lvl=info msg=big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999
+t=2023-10-20T12:56:08+0200 lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999
+t=2023-10-20T12:56:08+0200 lvl=info msg=big.Int  11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
+t=2023-10-20T12:56:08+0200 lvl=info msg=-big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900
+t=2023-10-20T12:56:08+0200 lvl=info msg=uint256  111,222,333,444,555,678,999=111,222,333,444,555,678,999
+t=2023-10-20T12:56:08+0200 lvl=info msg=uint256  11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
+t=2023-10-20T12:56:08+0200 lvl=info msg=int64    1,000,000=1,000,000
+t=2023-10-20T12:56:08+0200 lvl=info msg=int64    -1,000,000=-1,000,000
+t=2023-10-20T12:56:08+0200 lvl=info msg=int64    9,223,372,036,854,775,807=9,223,372,036,854,775,807
+t=2023-10-20T12:56:08+0200 lvl=info msg=int64    -9,223,372,036,854,775,808=-9,223,372,036,854,775,808
+t=2023-10-20T12:56:08+0200 lvl=info msg=uint64   1,000,000=1,000,000
+t=2023-10-20T12:56:08+0200 lvl=info msg=uint64   18,446,744,073,709,551,615=18,446,744,073,709,551,615
+t=2023-10-20T12:56:08+0200 lvl=info msg="Special chars in value" key="special \r\n\t chars"
+t=2023-10-20T12:56:08+0200 lvl=info msg="Special chars in key"   "special \n\t chars"=value
+t=2023-10-20T12:56:08+0200 lvl=info msg=nospace                  nospace=nospace
+t=2023-10-20T12:56:08+0200 lvl=info msg="with space"             "with nospace"="with nospace"
+t=2023-10-20T12:56:08+0200 lvl=info msg="Bash escapes in value"  key="\x1b[1G\x1b[K\x1b[1A"
+t=2023-10-20T12:56:08+0200 lvl=info msg="Bash escapes in key"    "\x1b[1G\x1b[K\x1b[1A"=value
+t=2023-10-20T12:56:08+0200 lvl=info msg="Bash escapes in message  \x1b[1G\x1b[K\x1b[1A end" key=value
+t=2023-10-20T12:56:08+0200 lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m["
+t=2023-10-20T12:56:08+0200 lvl=info msg="Custom Stringer value"   2562047h47m16.854s=2562047h47m16.854s
+t=2023-10-20T12:56:08+0200 lvl=info msg="Lazy evaluation of value" key="lazy value"
+t=2023-10-20T12:56:08+0200 lvl=info msg="A message with wonky 💩 characters"
+t=2023-10-20T12:56:08+0200 lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩"
+t=2023-10-20T12:56:08+0200 lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above"
+t=2023-10-20T12:56:08+0200 lvl=info msg=boolean                             true=true false=false
+t=2023-10-20T12:56:08+0200 lvl=info msg="repeated-key 1"                    foo=alpha foo=beta
+t=2023-10-20T12:56:08+0200 lvl=info msg="repeated-key 2"                    xx=short xx=longer
+t=2023-10-20T12:56:08+0200 lvl=info msg="log at level info"
+t=2023-10-20T12:56:08+0200 lvl=warn msg="log at level warn"
+t=2023-10-20T12:56:08+0200 lvl=eror msg="log at level error"
+t=2023-10-20T12:56:08+0200 lvl=info msg=test                                bar=short a="aligned left"
+t=2023-10-20T12:56:08+0200 lvl=info msg=test                                bar="a long message" a=1
+t=2023-10-20T12:56:08+0200 lvl=info msg=test                                bar=short            a="aligned right"
+t=2023-10-20T12:56:08+0200 lvl=info msg="The following logs should align so that the key-fields make 5 columns"
+t=2023-10-20T12:56:08+0200 lvl=info msg="Inserted known block"              number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=1,123,123 other=first
+t=2023-10-20T12:56:08+0200 lvl=info msg="Inserted new block"                number=1    hash=0x0000000000000000000000000000000000000000000000000000000000001235 txs=2   gas=1123      other=second
+t=2023-10-20T12:56:08+0200 lvl=info msg="Inserted known block"              number=99   hash=0x0000000000000000000000000000000000000000000000000000000000012322 txs=10  gas=1         other=third
+t=2023-10-20T12:56:08+0200 lvl=warn msg="Inserted known block"              number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=99        other=fourth