Skip to content

Commit 58ae1df

Browse files
holimanholiman
authored
cmd/geth: test for logging-output (#28373)
This PR is a bit in preparation for the slog work in #28187 . Our current test re logging mostly test the internals, but we have no real end-to-end test of the logging output. This PR introduces a simple reexec-based log tester. This also relies upon a special mode in geth, which can be made to eject a set of predefined log messages (only available if the build-tag `integrationtests` is used e.g. go run --tags=integrationtests ./cmd/geth --log.format terminal logtest While working on this, I also noticed a quirk in the setup: when geth was configured to use a file output, then two separate handlers were used (one handler for the file, one handler for the console). Using two separate handlers means that two formatters are used, thus the formatting of any/all records happened twice. This PR changes the mechanism to use two separate io.Writers instead, which is both more optimal and fixes a bug which occurs due to a global statefulness in the formatter.
1 parent d8c6ae0 commit 58ae1df

File tree

10 files changed

+445
-149
lines changed

10 files changed

+445
-149
lines changed

‎build/ci.go

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -307,6 +307,9 @@ func doTest(cmdline []string) {
307307
// Enable CKZG backend in CI.
308308
gotest.Args = append(gotest.Args, "-tags=ckzg")
309309

310+
// Enable integration-tests
311+
gotest.Args = append(gotest.Args, "-tags=integrationtests")
312+
310313
// Test a single package at a time. CI builders are slow
311314
// and some tests run into timeouts under load.
312315
gotest.Args = append(gotest.Args, "-p", "1")

‎cmd/geth/logging_test.go

Lines changed: 185 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,185 @@
1+
//go:build integrationtests
2+
3+
// Copyright 2023 The go-ethereum Authors
4+
// This file is part of go-ethereum.
5+
//
6+
// go-ethereum is free software: you can redistribute it and/or modify
7+
// it under the terms of the GNU General Public License as published by
8+
// the Free Software Foundation, either version 3 of the License, or
9+
// (at your option) any later version.
10+
//
11+
// go-ethereum is distributed in the hope that it will be useful,
12+
// but WITHOUT ANY WARRANTY; without even the implied warranty of
13+
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
14+
// GNU General Public License for more details.
15+
//
16+
// You should have received a copy of the GNU General Public License
17+
// along with go-ethereum. If not, see <http://www.gnu.org/licenses/>.
18+
19+
package main
20+
21+
import (
22+
"bufio"
23+
"bytes"
24+
"fmt"
25+
"io"
26+
"math/rand"
27+
"os"
28+
"os/exec"
29+
"strings"
30+
"testing"
31+
32+
"github.com/docker/docker/pkg/reexec"
33+
)
34+
35+
func runSelf(args ...string) ([]byte, error) {
36+
cmd := &exec.Cmd{
37+
Path: reexec.Self(),
38+
Args: append([]string{"geth-test"}, args...),
39+
}
40+
return cmd.CombinedOutput()
41+
}
42+
43+
func split(input io.Reader) []string {
44+
var output []string
45+
scanner := bufio.NewScanner(input)
46+
scanner.Split(bufio.ScanLines)
47+
for scanner.Scan() {
48+
output = append(output, strings.TrimSpace(scanner.Text()))
49+
}
50+
return output
51+
}
52+
53+
func censor(input string, start, end int) string {
54+
if len(input) < end {
55+
return input
56+
}
57+
return input[:start] + strings.Repeat("X", end-start) + input[end:]
58+
}
59+
60+
func TestLogging(t *testing.T) {
61+
testConsoleLogging(t, "terminal", 6, 24)
62+
testConsoleLogging(t, "logfmt", 2, 26)
63+
}
64+
65+
func testConsoleLogging(t *testing.T, format string, tStart, tEnd int) {
66+
haveB, err := runSelf("--log.format", format, "logtest")
67+
if err != nil {
68+
t.Fatal(err)
69+
}
70+
readFile, err := os.Open(fmt.Sprintf("testdata/logging/logtest-%v.txt", format))
71+
if err != nil {
72+
t.Fatal(err)
73+
}
74+
wantLines := split(readFile)
75+
haveLines := split(bytes.NewBuffer(haveB))
76+
for i, want := range wantLines {
77+
if i > len(haveLines)-1 {
78+
t.Fatalf("format %v, line %d missing, want:%v", format, i, want)
79+
}
80+
have := haveLines[i]
81+
for strings.Contains(have, "Unknown config environment variable") {
82+
// This can happen on CI runs. Drop it.
83+
haveLines = append(haveLines[:i], haveLines[i+1:]...)
84+
have = haveLines[i]
85+
}
86+
87+
// Black out the timestamp
88+
have = censor(have, tStart, tEnd)
89+
want = censor(want, tStart, tEnd)
90+
if have != want {
91+
t.Logf(nicediff([]byte(have), []byte(want)))
92+
t.Fatalf("format %v, line %d\nhave %v\nwant %v", format, i, have, want)
93+
}
94+
}
95+
if len(haveLines) != len(wantLines) {
96+
t.Errorf("format %v, want %d lines, have %d", format, len(haveLines), len(wantLines))
97+
}
98+
}
99+
100+
func TestVmodule(t *testing.T) {
101+
checkOutput := func(level int, want, wantNot string) {
102+
t.Helper()
103+
output, err := runSelf("--log.format", "terminal", "--verbosity=0", "--log.vmodule", fmt.Sprintf("logtestcmd_active.go=%d", level), "logtest")
104+
if err != nil {
105+
t.Fatal(err)
106+
}
107+
if len(want) > 0 && !strings.Contains(string(output), want) { // trace should be present at 5
108+
t.Errorf("failed to find expected string ('%s') in output", want)
109+
}
110+
if len(wantNot) > 0 && strings.Contains(string(output), wantNot) { // trace should be present at 5
111+
t.Errorf("string ('%s') should not be present in output", wantNot)
112+
}
113+
}
114+
checkOutput(5, "log at level trace", "") // trace should be present at 5
115+
checkOutput(4, "log at level debug", "log at level trace") // debug should be present at 4, but trace should be missing
116+
checkOutput(3, "log at level info", "log at level debug") // info should be present at 3, but debug should be missing
117+
checkOutput(2, "log at level warn", "log at level info") // warn should be present at 2, but info should be missing
118+
checkOutput(1, "log at level error", "log at level warn") // error should be present at 1, but warn should be missing
119+
}
120+
121+
func nicediff(have, want []byte) string {
122+
var i = 0
123+
for ; i < len(have) && i < len(want); i++ {
124+
if want[i] != have[i] {
125+
break
126+
}
127+
}
128+
var end = i + 40
129+
var start = i - 50
130+
if start < 0 {
131+
start = 0
132+
}
133+
var h, w string
134+
if end < len(have) {
135+
h = string(have[start:end])
136+
} else {
137+
h = string(have[start:])
138+
}
139+
if end < len(want) {
140+
w = string(want[start:end])
141+
} else {
142+
w = string(want[start:])
143+
}
144+
return fmt.Sprintf("have vs want:\n%q\n%q\n", h, w)
145+
}
146+
147+
func TestFileOut(t *testing.T) {
148+
var (
149+
have, want []byte
150+
err error
151+
path = fmt.Sprintf("%s/test_file_out-%d", os.TempDir(), rand.Int63())
152+
)
153+
t.Cleanup(func() { os.Remove(path) })
154+
if want, err = runSelf(fmt.Sprintf("--log.file=%s", path), "logtest"); err != nil {
155+
t.Fatal(err)
156+
}
157+
if have, err = os.ReadFile(path); err != nil {
158+
t.Fatal(err)
159+
}
160+
if !bytes.Equal(have, want) {
161+
// show an intelligent diff
162+
t.Logf(nicediff(have, want))
163+
t.Errorf("file content wrong")
164+
}
165+
}
166+
167+
func TestRotatingFileOut(t *testing.T) {
168+
var (
169+
have, want []byte
170+
err error
171+
path = fmt.Sprintf("%s/test_file_out-%d", os.TempDir(), rand.Int63())
172+
)
173+
t.Cleanup(func() { os.Remove(path) })
174+
if want, err = runSelf(fmt.Sprintf("--log.file=%s", path), "--log.rotate", "logtest"); err != nil {
175+
t.Fatal(err)
176+
}
177+
if have, err = os.ReadFile(path); err != nil {
178+
t.Fatal(err)
179+
}
180+
if !bytes.Equal(have, want) {
181+
// show an intelligent diff
182+
t.Logf(nicediff(have, want))
183+
t.Errorf("file content wrong")
184+
}
185+
}

‎cmd/geth/logtestcmd_active.go

Lines changed: 134 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,134 @@
1+
//go:build integrationtests
2+
3+
// Copyright 2023 The go-ethereum Authors
4+
// This file is part of go-ethereum.
5+
//
6+
// go-ethereum is free software: you can redistribute it and/or modify
7+
// it under the terms of the GNU General Public License as published by
8+
// the Free Software Foundation, either version 3 of the License, or
9+
// (at your option) any later version.
10+
//
11+
// go-ethereum is distributed in the hope that it will be useful,
12+
// but WITHOUT ANY WARRANTY; without even the implied warranty of
13+
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
14+
// GNU General Public License for more details.
15+
//
16+
// You should have received a copy of the GNU General Public License
17+
// along with go-ethereum. If not, see <http://www.gnu.org/licenses/>.
18+
19+
package main
20+
21+
import (
22+
"fmt"
23+
"math"
24+
"math/big"
25+
"time"
26+
27+
"github.com/ethereum/go-ethereum/common"
28+
"github.com/ethereum/go-ethereum/log"
29+
"github.com/holiman/uint256"
30+
"github.com/urfave/cli/v2"
31+
)
32+
33+
var logTestCommand = &cli.Command{
34+
Action: logTest,
35+
Name: "logtest",
36+
Usage: "Print some log messages",
37+
ArgsUsage: " ",
38+
Description: `
39+
This command is only meant for testing.
40+
`}
41+
42+
// logTest is an entry point which spits out some logs. This is used by testing
43+
// to verify expected outputs
44+
func logTest(ctx *cli.Context) error {
45+
log.ResetGlobalState()
46+
{ // big.Int
47+
ba, _ := new(big.Int).SetString("111222333444555678999", 10) // "111,222,333,444,555,678,999"
48+
bb, _ := new(big.Int).SetString("-111222333444555678999", 10) // "-111,222,333,444,555,678,999"
49+
bc, _ := new(big.Int).SetString("11122233344455567899900", 10) // "11,122,233,344,455,567,899,900"
50+
bd, _ := new(big.Int).SetString("-11122233344455567899900", 10) // "-11,122,233,344,455,567,899,900"
51+
log.Info("big.Int", "111,222,333,444,555,678,999", ba)
52+
log.Info("-big.Int", "-111,222,333,444,555,678,999", bb)
53+
log.Info("big.Int", "11,122,233,344,455,567,899,900", bc)
54+
log.Info("-big.Int", "-11,122,233,344,455,567,899,900", bd)
55+
}
56+
{ //uint256
57+
ua, _ := uint256.FromDecimal("111222333444555678999")
58+
ub, _ := uint256.FromDecimal("11122233344455567899900")
59+
log.Info("uint256", "111,222,333,444,555,678,999", ua)
60+
log.Info("uint256", "11,122,233,344,455,567,899,900", ub)
61+
}
62+
{ // int64
63+
log.Info("int64", "1,000,000", int64(1000000))
64+
log.Info("int64", "-1,000,000", int64(-1000000))
65+
log.Info("int64", "9,223,372,036,854,775,807", int64(math.MaxInt64))
66+
log.Info("int64", "-9,223,372,036,854,775,808", int64(math.MinInt64))
67+
}
68+
{ // uint64
69+
log.Info("uint64", "1,000,000", uint64(1000000))
70+
log.Info("uint64", "18,446,744,073,709,551,615", uint64(math.MaxUint64))
71+
}
72+
{ // Special characters
73+
log.Info("Special chars in value", "key", "special \r\n\t chars")
74+
log.Info("Special chars in key", "special \n\t chars", "value")
75+
76+
log.Info("nospace", "nospace", "nospace")
77+
log.Info("with space", "with nospace", "with nospace")
78+
79+
log.Info("Bash escapes in value", "key", "\u001b[1G\u001b[K\u001b[1A")
80+
log.Info("Bash escapes in key", "\u001b[1G\u001b[K\u001b[1A", "value")
81+
82+
log.Info("Bash escapes in message \u001b[1G\u001b[K\u001b[1A end", "key", "value")
83+
84+
colored := fmt.Sprintf("\u001B[%dmColored\u001B[0m[", 35)
85+
log.Info(colored, colored, colored)
86+
}
87+
{ // Custom Stringer() - type
88+
log.Info("Custom Stringer value", "2562047h47m16.854s", common.PrettyDuration(time.Duration(9223372036854775807)))
89+
}
90+
{ // Lazy eval
91+
log.Info("Lazy evaluation of value", "key", log.Lazy{Fn: func() interface{} { return "lazy value" }})
92+
}
93+
{ // Multi-line message
94+
log.Info("A message with wonky \U0001F4A9 characters")
95+
log.Info("A multiline message \nINFO [10-18|14:11:31.106] with wonky characters \U0001F4A9")
96+
log.Info("A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above")
97+
}
98+
{ // Miscellaneous json-quirks
99+
// This will check if the json output uses strings or json-booleans to represent bool values
100+
log.Info("boolean", "true", true, "false", false)
101+
// Handling of duplicate keys.
102+
// This is actually ill-handled by the current handler: the format.go
103+
// uses a global 'fieldPadding' map and mixes up the two keys. If 'alpha'
104+
// is shorter than beta, it sometimes causes erroneous padding -- and what's more
105+
// it causes _different_ padding in multi-handler context, e.g. both file-
106+
// and console output, making the two mismatch.
107+
log.Info("repeated-key 1", "foo", "alpha", "foo", "beta")
108+
log.Info("repeated-key 2", "xx", "short", "xx", "longer")
109+
}
110+
{ // loglevels
111+
log.Debug("log at level debug")
112+
log.Trace("log at level trace")
113+
log.Info("log at level info")
114+
log.Warn("log at level warn")
115+
log.Error("log at level error")
116+
}
117+
{
118+
// The current log formatter has a global map of paddings, storing the
119+
// longest seen padding per key in a map. This results in a statefulness
120+
// which has some odd side-effects. Demonstrated here:
121+
log.Info("test", "bar", "short", "a", "aligned left")
122+
log.Info("test", "bar", "a long message", "a", 1)
123+
log.Info("test", "bar", "short", "a", "aligned right")
124+
}
125+
{
126+
// This sequence of logs should be output with alignment, so each field becoems a column.
127+
log.Info("The following logs should align so that the key-fields make 5 columns")
128+
log.Info("Inserted known block", "number", 1_012, "hash", common.HexToHash("0x1234"), "txs", 200, "gas", 1_123_123, "other", "first")
129+
log.Info("Inserted new block", "number", 1, "hash", common.HexToHash("0x1235"), "txs", 2, "gas", 1_123, "other", "second")
130+
log.Info("Inserted known block", "number", 99, "hash", common.HexToHash("0x12322"), "txs", 10, "gas", 1, "other", "third")
131+
log.Warn("Inserted known block", "number", 1_012, "hash", common.HexToHash("0x1234"), "txs", 200, "gas", 99, "other", "fourth")
132+
}
133+
return nil
134+
}

‎cmd/geth/logtestcmd_inactive.go

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
//go:build !integrationtests
2+
3+
// Copyright 2023 The go-ethereum Authors
4+
// This file is part of go-ethereum.
5+
//
6+
// go-ethereum is free software: you can redistribute it and/or modify
7+
// it under the terms of the GNU General Public License as published by
8+
// the Free Software Foundation, either version 3 of the License, or
9+
// (at your option) any later version.
10+
//
11+
// go-ethereum is distributed in the hope that it will be useful,
12+
// but WITHOUT ANY WARRANTY; without even the implied warranty of
13+
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
14+
// GNU General Public License for more details.
15+
//
16+
// You should have received a copy of the GNU General Public License
17+
// along with go-ethereum. If not, see <http://www.gnu.org/licenses/>.
18+
19+
package main
20+
21+
import "github.com/urfave/cli/v2"
22+
23+
var logTestCommand *cli.Command

‎cmd/geth/main.go

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -234,6 +234,9 @@ func init() {
234234
// See verkle.go
235235
verkleCommand,
236236
}
237+
if logTestCommand != nil {
238+
app.Commands = append(app.Commands, logTestCommand)
239+
}
237240
sort.Sort(cli.CommandsByName(app.Commands))
238241

239242
app.Flags = flags.Merge(

0 commit comments

Comments
 (0)