From c03f863ee313c8359c1c42ae54e48135ce519aba Mon Sep 17 00:00:00 2001 From: devopsbo3 <69951731+devopsbo3@users.noreply.github.com> Date: Fri, 10 Nov 2023 12:27:53 -0600 Subject: [PATCH] Revert "cmd/geth: test for logging-output (#28373)" This reverts commit 6a1deaea39986d0654e5638cc7a9b2c1e92e3fdf. --- build/ci.go | 3 - cmd/geth/logging_test.go | 185 ------------------ cmd/geth/logtestcmd_active.go | 134 ------------- cmd/geth/logtestcmd_inactive.go | 23 --- cmd/geth/main.go | 3 - cmd/geth/testdata/logging/logtest-logfmt.txt | 39 ---- .../testdata/logging/logtest-terminal.txt | 40 ---- internal/debug/flags.go | 20 +- log/format.go | 8 - log/format_test.go | 139 +++++++++++++ 10 files changed, 149 insertions(+), 445 deletions(-) delete mode 100644 cmd/geth/logging_test.go delete mode 100644 cmd/geth/logtestcmd_active.go delete mode 100644 cmd/geth/logtestcmd_inactive.go delete mode 100644 cmd/geth/testdata/logging/logtest-logfmt.txt delete mode 100644 cmd/geth/testdata/logging/logtest-terminal.txt diff --git a/build/ci.go b/build/ci.go index afe1c332b8..46f1ac2812 100644 --- a/build/ci.go +++ b/build/ci.go @@ -307,9 +307,6 @@ func doTest(cmdline []string) { // Enable CKZG backend in CI. gotest.Args = append(gotest.Args, "-tags=ckzg") - // Enable integration-tests - gotest.Args = append(gotest.Args, "-tags=integrationtests") - // Test a single package at a time. CI builders are slow // and some tests run into timeouts under load. gotest.Args = append(gotest.Args, "-p", "1") diff --git a/cmd/geth/logging_test.go b/cmd/geth/logging_test.go deleted file mode 100644 index cc951d6e97..0000000000 --- a/cmd/geth/logging_test.go +++ /dev/null @@ -1,185 +0,0 @@ -//go:build integrationtests - -// 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 . - -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_active.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") - } -} diff --git a/cmd/geth/logtestcmd_active.go b/cmd/geth/logtestcmd_active.go deleted file mode 100644 index c66013517a..0000000000 --- a/cmd/geth/logtestcmd_active.go +++ /dev/null @@ -1,134 +0,0 @@ -//go:build integrationtests - -// 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 . - -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" -) - -var logTestCommand = &cli.Command{ - Action: logTest, - Name: "logtest", - Usage: "Print some log messages", - ArgsUsage: " ", - Description: ` -This command is only meant for testing. -`} - -// 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 -} diff --git a/cmd/geth/logtestcmd_inactive.go b/cmd/geth/logtestcmd_inactive.go deleted file mode 100644 index 691ab5bcd8..0000000000 --- a/cmd/geth/logtestcmd_inactive.go +++ /dev/null @@ -1,23 +0,0 @@ -//go:build !integrationtests - -// 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 . - -package main - -import "github.com/urfave/cli/v2" - -var logTestCommand *cli.Command diff --git a/cmd/geth/main.go b/cmd/geth/main.go index 2d4fe3dc06..4b26de05a9 100644 --- a/cmd/geth/main.go +++ b/cmd/geth/main.go @@ -234,9 +234,6 @@ func init() { // See verkle.go verkleCommand, } - if logTestCommand != nil { - app.Commands = append(app.Commands, logTestCommand) - } sort.Sort(cli.CommandsByName(app.Commands)) app.Flags = flags.Merge( diff --git a/cmd/geth/testdata/logging/logtest-logfmt.txt b/cmd/geth/testdata/logging/logtest-logfmt.txt deleted file mode 100644 index 79f29e1fae..0000000000 --- a/cmd/geth/testdata/logging/logtest-logfmt.txt +++ /dev/null @@ -1,39 +0,0 @@ -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 diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt deleted file mode 100644 index ff68b6047a..0000000000 --- a/cmd/geth/testdata/logging/logtest-terminal.txt +++ /dev/null @@ -1,40 +0,0 @@ -INFO [10-20|12:56:42.532] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [10-20|12:56:42.532] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 -INFO [10-20|12:56:42.532] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [10-20|12:56:42.532] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 -INFO [10-20|12:56:42.532] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [10-20|12:56:42.532] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [10-20|12:56:42.532] int64 1,000,000=1,000,000 -INFO [10-20|12:56:42.532] int64 -1,000,000=-1,000,000 -INFO [10-20|12:56:42.532] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 -INFO [10-20|12:56:42.532] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 -INFO [10-20|12:56:42.532] uint64 1,000,000=1,000,000 -INFO [10-20|12:56:42.532] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 -INFO [10-20|12:56:42.532] Special chars in value key="special \r\n\t chars" -INFO [10-20|12:56:42.532] Special chars in key "special \n\t chars"=value -INFO [10-20|12:56:42.532] nospace nospace=nospace -INFO [10-20|12:56:42.532] with space "with nospace"="with nospace" -INFO [10-20|12:56:42.532] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A" -INFO [10-20|12:56:42.532] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value -INFO [10-20|12:56:42.532] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value -INFO [10-20|12:56:42.532] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" -INFO [10-20|12:56:42.532] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s -INFO [10-20|12:56:42.532] Lazy evaluation of value key="lazy value" -INFO [10-20|12:56:42.532] "A message with wonky 💩 characters" -INFO [10-20|12:56:42.532] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" -INFO [10-20|12:56:42.532] A multiline message -LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above -INFO [10-20|12:56:42.532] boolean true=true false=false -INFO [10-20|12:56:42.532] repeated-key 1 foo=alpha foo=beta -INFO [10-20|12:56:42.532] repeated-key 2 xx=short xx=longer -INFO [10-20|12:56:42.532] log at level info -WARN [10-20|12:56:42.532] log at level warn -ERROR[10-20|12:56:42.532] log at level error -INFO [10-20|12:56:42.532] test bar=short a="aligned left" -INFO [10-20|12:56:42.532] test bar="a long message" a=1 -INFO [10-20|12:56:42.532] test bar=short a="aligned right" -INFO [10-20|12:56:42.532] The following logs should align so that the key-fields make 5 columns -INFO [10-20|12:56:42.532] Inserted known block number=1012 hash=000000..001234 txs=200 gas=1,123,123 other=first -INFO [10-20|12:56:42.532] Inserted new block number=1 hash=000000..001235 txs=2 gas=1123 other=second -INFO [10-20|12:56:42.532] Inserted known block number=99 hash=000000..012322 txs=10 gas=1 other=third -WARN [10-20|12:56:42.532] Inserted known block number=1012 hash=000000..001234 txs=200 gas=99 other=fourth diff --git a/internal/debug/flags.go b/internal/debug/flags.go index 4f0f5fe860..736fede943 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -218,9 +218,10 @@ func Setup(ctx *cli.Context) error { return fmt.Errorf("unknown log format: %v", ctx.String(logFormatFlag.Name)) } var ( - ostream = log.StreamHandler(output, logfmt) - logFile = ctx.String(logFileFlag.Name) - rotation = ctx.Bool(logRotateFlag.Name) + stdHandler = log.StreamHandler(output, logfmt) + ostream = stdHandler + logFile = ctx.String(logFileFlag.Name) + rotation = ctx.Bool(logRotateFlag.Name) ) if len(logFile) > 0 { if err := validateLogLocation(filepath.Dir(logFile)); err != nil { @@ -241,21 +242,20 @@ func Setup(ctx *cli.Context) error { } else { context = append(context, "location", filepath.Join(os.TempDir(), "geth-lumberjack.log")) } - lumberWriter := &lumberjack.Logger{ + ostream = log.MultiHandler(log.StreamHandler(&lumberjack.Logger{ Filename: logFile, MaxSize: ctx.Int(logMaxSizeMBsFlag.Name), MaxBackups: ctx.Int(logMaxBackupsFlag.Name), MaxAge: ctx.Int(logMaxAgeFlag.Name), Compress: ctx.Bool(logCompressFlag.Name), - } - ostream = log.StreamHandler(io.MultiWriter(output, lumberWriter), logfmt) + }, logfmt), stdHandler) } else if logFile != "" { - f, err := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) - if err != nil { + if logOutputStream, err := log.FileHandler(logFile, logfmt); err != nil { return err + } else { + ostream = log.MultiHandler(logOutputStream, stdHandler) + context = append(context, "location", logFile) } - ostream = log.StreamHandler(io.MultiWriter(output, f), logfmt) - context = append(context, "location", logFile) } glogger.SetHandler(ostream) diff --git a/log/format.go b/log/format.go index 2fd1f28558..1adf79c17e 100644 --- a/log/format.go +++ b/log/format.go @@ -24,14 +24,6 @@ const ( termCtxMaxPadding = 40 ) -// ResetGlobalState resets the fieldPadding, which is useful for producing -// predictable output. -func ResetGlobalState() { - fieldPaddingLock.Lock() - fieldPadding = make(map[string]int) - fieldPaddingLock.Unlock() -} - // locationTrims are trimmed for display to avoid unwieldy log lines. var locationTrims = []string{ "github.com/ethereum/go-ethereum/", diff --git a/log/format_test.go b/log/format_test.go index 41e1809c38..e08c1d1a4a 100644 --- a/log/format_test.go +++ b/log/format_test.go @@ -1,10 +1,105 @@ package log import ( + "fmt" + "math" + "math/big" "math/rand" + "strings" "testing" + + "github.com/holiman/uint256" ) +func TestPrettyInt64(t *testing.T) { + tests := []struct { + n int64 + s string + }{ + {0, "0"}, + {10, "10"}, + {-10, "-10"}, + {100, "100"}, + {-100, "-100"}, + {1000, "1000"}, + {-1000, "-1000"}, + {10000, "10000"}, + {-10000, "-10000"}, + {99999, "99999"}, + {-99999, "-99999"}, + {100000, "100,000"}, + {-100000, "-100,000"}, + {1000000, "1,000,000"}, + {-1000000, "-1,000,000"}, + {math.MaxInt64, "9,223,372,036,854,775,807"}, + {math.MinInt64, "-9,223,372,036,854,775,808"}, + } + for i, tt := range tests { + if have := FormatLogfmtInt64(tt.n); have != tt.s { + t.Errorf("test %d: format mismatch: have %s, want %s", i, have, tt.s) + } + } +} + +func TestPrettyUint64(t *testing.T) { + tests := []struct { + n uint64 + s string + }{ + {0, "0"}, + {10, "10"}, + {100, "100"}, + {1000, "1000"}, + {10000, "10000"}, + {99999, "99999"}, + {100000, "100,000"}, + {1000000, "1,000,000"}, + {math.MaxUint64, "18,446,744,073,709,551,615"}, + } + for i, tt := range tests { + if have := FormatLogfmtUint64(tt.n); have != tt.s { + t.Errorf("test %d: format mismatch: have %s, want %s", i, have, tt.s) + } + } +} + +func TestPrettyBigInt(t *testing.T) { + tests := []struct { + int string + s string + }{ + {"111222333444555678999", "111,222,333,444,555,678,999"}, + {"-111222333444555678999", "-111,222,333,444,555,678,999"}, + {"11122233344455567899900", "11,122,233,344,455,567,899,900"}, + {"-11122233344455567899900", "-11,122,233,344,455,567,899,900"}, + } + + for _, tt := range tests { + v, _ := new(big.Int).SetString(tt.int, 10) + if have := formatLogfmtBigInt(v); have != tt.s { + t.Errorf("invalid output %s, want %s", have, tt.s) + } + } +} + +func TestPrettyUint256(t *testing.T) { + tests := []struct { + int string + s string + }{ + {"111222333444555678999", "111,222,333,444,555,678,999"}, + {"11122233344455567899900", "11,122,233,344,455,567,899,900"}, + } + + for _, tt := range tests { + v := new(uint256.Int) + v.SetFromDecimal(tt.int) + if have := formatLogfmtUint256(v); have != tt.s { + t.Errorf("invalid output %s, want %s", have, tt.s) + } + } +} + var sink string func BenchmarkPrettyInt64Logfmt(b *testing.B) { @@ -20,3 +115,47 @@ func BenchmarkPrettyUint64Logfmt(b *testing.B) { sink = FormatLogfmtUint64(rand.Uint64()) } } + +func TestSanitation(t *testing.T) { + msg := "\u001b[1G\u001b[K\u001b[1A" + msg2 := "\u001b \u0000" + msg3 := "NiceMessage" + msg4 := "Space Message" + msg5 := "Enter\nMessage" + + for i, tt := range []struct { + msg string + want string + }{ + { + msg: msg, + want: fmt.Sprintf("] %q %q=%q\n", msg, msg, msg), + }, + { + msg: msg2, + want: fmt.Sprintf("] %q %q=%q\n", msg2, msg2, msg2), + }, + { + msg: msg3, + want: fmt.Sprintf("] %s %s=%s\n", msg3, msg3, msg3), + }, + { + msg: msg4, + want: fmt.Sprintf("] %s %q=%q\n", msg4, msg4, msg4), + }, + { + msg: msg5, + want: fmt.Sprintf("] %s %q=%q\n", msg5, msg5, msg5), + }, + } { + var ( + logger = New() + out = new(strings.Builder) + ) + logger.SetHandler(LvlFilterHandler(LvlInfo, StreamHandler(out, TerminalFormat(false)))) + logger.Info(tt.msg, tt.msg, tt.msg) + if have := out.String()[24:]; tt.want != have { + t.Fatalf("test %d: want / have: \n%v\n%v", i, tt.want, have) + } + } +}