diff --git a/build/ci.go b/build/ci.go index 46f1ac281..afe1c332b 100644 --- a/build/ci.go +++ b/build/ci.go @@ -307,6 +307,9 @@ 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 new file mode 100644 index 000000000..cc951d6e9 --- /dev/null +++ b/cmd/geth/logging_test.go @@ -0,0 +1,185 @@ +//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 new file mode 100644 index 000000000..c66013517 --- /dev/null +++ b/cmd/geth/logtestcmd_active.go @@ -0,0 +1,134 @@ +//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 new file mode 100644 index 000000000..691ab5bcd --- /dev/null +++ b/cmd/geth/logtestcmd_inactive.go @@ -0,0 +1,23 @@ +//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 4b26de05a..2d4fe3dc0 100644 --- a/cmd/geth/main.go +++ b/cmd/geth/main.go @@ -234,6 +234,9 @@ 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 new file mode 100644 index 000000000..79f29e1fa --- /dev/null +++ b/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 diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt new file mode 100644 index 000000000..ff68b6047 --- /dev/null +++ b/cmd/geth/testdata/logging/logtest-terminal.txt @@ -0,0 +1,40 @@ +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 736fede94..4f0f5fe86 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -218,10 +218,9 @@ func Setup(ctx *cli.Context) error { return fmt.Errorf("unknown log format: %v", ctx.String(logFormatFlag.Name)) } var ( - stdHandler = log.StreamHandler(output, logfmt) - ostream = stdHandler - logFile = ctx.String(logFileFlag.Name) - rotation = ctx.Bool(logRotateFlag.Name) + ostream = log.StreamHandler(output, logfmt) + logFile = ctx.String(logFileFlag.Name) + rotation = ctx.Bool(logRotateFlag.Name) ) if len(logFile) > 0 { if err := validateLogLocation(filepath.Dir(logFile)); err != nil { @@ -242,20 +241,21 @@ func Setup(ctx *cli.Context) error { } else { context = append(context, "location", filepath.Join(os.TempDir(), "geth-lumberjack.log")) } - ostream = log.MultiHandler(log.StreamHandler(&lumberjack.Logger{ + lumberWriter := &lumberjack.Logger{ Filename: logFile, MaxSize: ctx.Int(logMaxSizeMBsFlag.Name), MaxBackups: ctx.Int(logMaxBackupsFlag.Name), MaxAge: ctx.Int(logMaxAgeFlag.Name), Compress: ctx.Bool(logCompressFlag.Name), - }, logfmt), stdHandler) - } else if logFile != "" { - 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, lumberWriter), logfmt) + } else if logFile != "" { + f, err := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + if err != nil { + return err + } + 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 1adf79c17..2fd1f2855 100644 --- a/log/format.go +++ b/log/format.go @@ -24,6 +24,14 @@ 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 e08c1d1a4..41e1809c3 100644 --- a/log/format_test.go +++ b/log/format_test.go @@ -1,105 +1,10 @@ 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) { @@ -115,47 +20,3 @@ 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) - } - } -}