From b75f045714bc2609416e38c188381fc12616eb8f Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Thu, 19 Oct 2023 15:03:03 +0200 Subject: [PATCH] cmd/geth: add test for file-logging, fix flaw on CI-runs --- cmd/geth/logging_test.go | 67 ++++++++++++++++++- cmd/geth/testdata/logging/logtest-logfmt.txt | 57 ++++++++-------- .../testdata/logging/logtest-terminal.txt | 57 ++++++++-------- 3 files changed, 126 insertions(+), 55 deletions(-) diff --git a/cmd/geth/logging_test.go b/cmd/geth/logging_test.go index a5470dc28c..534059971e 100644 --- a/cmd/geth/logging_test.go +++ b/cmd/geth/logging_test.go @@ -21,6 +21,7 @@ import ( "bytes" "fmt" "io" + "math/rand" "os" "os/exec" "strings" @@ -42,7 +43,7 @@ func split(input io.Reader) []string { scanner := bufio.NewScanner(input) scanner.Split(bufio.ScanLines) for scanner.Scan() { - output = append(output, scanner.Text()) + output = append(output, strings.TrimSpace(scanner.Text())) } return output } @@ -75,10 +76,17 @@ func testConsoleLogging(t *testing.T, format string, tStart, tEnd int) { 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) } } @@ -107,3 +115,60 @@ func TestVmodule(t *testing.T) { 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 terminal/logfmt format is used, then this test fails -- apparently the file-, or stream-, or + multiplexhandler somehow treats records with duplicate keys differently, adding an extra space + on the log output between the two keys. + Using the `json` format cheats and gets around this, since json cannot represent duplicate keys. + + logging_test.go:153: have vs want: + "repeated-key foo=once foo=twice\nINFO [10-19|14:42:23.554] log " + "repeated-key foo=once foo=twice\nINFO [10-19|14:42:23.554] log" + logging_test.go:154: file content wrong + */ + if want, err = runSelf(fmt.Sprintf("--log.file=%s", path), "--log.format=json", "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/testdata/logging/logtest-logfmt.txt b/cmd/geth/testdata/logging/logtest-logfmt.txt index e69954237d..0f003167c4 100644 --- a/cmd/geth/testdata/logging/logtest-logfmt.txt +++ b/cmd/geth/testdata/logging/logtest-logfmt.txt @@ -1,27 +1,30 @@ -t=2023-10-19T10:05:35+0200 lvl=info msg=big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -t=2023-10-19T10:05:35+0200 lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 -t=2023-10-19T10:05:35+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-19T10:05:35+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-19T10:05:35+0200 lvl=info msg=uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -t=2023-10-19T10:05:35+0200 lvl=info msg=uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -t=2023-10-19T10:05:35+0200 lvl=info msg=int64 1,000,000=1,000,000 -t=2023-10-19T10:05:35+0200 lvl=info msg=int64 -1,000,000=-1,000,000 -t=2023-10-19T10:05:35+0200 lvl=info msg=int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 -t=2023-10-19T10:05:35+0200 lvl=info msg=int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 -t=2023-10-19T10:05:35+0200 lvl=info msg=uint64 1,000,000=1,000,000 -t=2023-10-19T10:05:35+0200 lvl=info msg=uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 -t=2023-10-19T10:05:35+0200 lvl=info msg="Special chars in value" key="special \r\n\t chars" -t=2023-10-19T10:05:35+0200 lvl=info msg="Special chars in key" "special \n\t chars"=value -t=2023-10-19T10:05:35+0200 lvl=info msg=nospace nospace=nospace -t=2023-10-19T10:05:35+0200 lvl=info msg="with space" "with nospace"="with nospace" -t=2023-10-19T10:05:35+0200 lvl=info msg="Bash escapes in value" key="\x1b[1G\x1b[K\x1b[1A" -t=2023-10-19T10:05:35+0200 lvl=info msg="Bash escapes in key" "\x1b[1G\x1b[K\x1b[1A"=value -t=2023-10-19T10:05:35+0200 lvl=info msg="Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value -t=2023-10-19T10:05:35+0200 lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" -t=2023-10-19T10:05:35+0200 lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s -t=2023-10-19T10:05:35+0200 lvl=info msg="Lazy evaluation of value" key="lazy value" -t=2023-10-19T10:05:35+0200 lvl=info msg="A message with wonky 💩 characters" -t=2023-10-19T10:05:35+0200 lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" -t=2023-10-19T10:05:35+0200 lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above" -t=2023-10-19T10:05:35+0200 lvl=info msg=boolean true=true false=false -t=2023-10-19T10:05:35+0200 lvl=info msg=repeated-key foo=once foo=twice +t=2023-10-19T14:54:24+0200 lvl=info msg=big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +t=2023-10-19T14:54:24+0200 lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 +t=2023-10-19T14:54:24+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-19T14:54:24+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-19T14:54:24+0200 lvl=info msg=uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +t=2023-10-19T14:54:24+0200 lvl=info msg=uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +t=2023-10-19T14:54:24+0200 lvl=info msg=int64 1,000,000=1,000,000 +t=2023-10-19T14:54:24+0200 lvl=info msg=int64 -1,000,000=-1,000,000 +t=2023-10-19T14:54:24+0200 lvl=info msg=int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 +t=2023-10-19T14:54:24+0200 lvl=info msg=int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 +t=2023-10-19T14:54:24+0200 lvl=info msg=uint64 1,000,000=1,000,000 +t=2023-10-19T14:54:24+0200 lvl=info msg=uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 +t=2023-10-19T14:54:24+0200 lvl=info msg="Special chars in value" key="special \r\n\t chars" +t=2023-10-19T14:54:24+0200 lvl=info msg="Special chars in key" "special \n\t chars"=value +t=2023-10-19T14:54:24+0200 lvl=info msg=nospace nospace=nospace +t=2023-10-19T14:54:24+0200 lvl=info msg="with space" "with nospace"="with nospace" +t=2023-10-19T14:54:24+0200 lvl=info msg="Bash escapes in value" key="\x1b[1G\x1b[K\x1b[1A" +t=2023-10-19T14:54:24+0200 lvl=info msg="Bash escapes in key" "\x1b[1G\x1b[K\x1b[1A"=value +t=2023-10-19T14:54:24+0200 lvl=info msg="Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value +t=2023-10-19T14:54:24+0200 lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" +t=2023-10-19T14:54:24+0200 lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s +t=2023-10-19T14:54:24+0200 lvl=info msg="Lazy evaluation of value" key="lazy value" +t=2023-10-19T14:54:24+0200 lvl=info msg="A message with wonky 💩 characters" +t=2023-10-19T14:54:24+0200 lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" +t=2023-10-19T14:54:24+0200 lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above" +t=2023-10-19T14:54:24+0200 lvl=info msg=boolean true=true false=false +t=2023-10-19T14:54:24+0200 lvl=info msg=repeated-key foo=once foo=twice +t=2023-10-19T14:54:24+0200 lvl=info msg="log at level info" +t=2023-10-19T14:54:24+0200 lvl=warn msg="log at level warn" +t=2023-10-19T14:54:24+0200 lvl=eror msg="log at level error" diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt index cf13f4fdc1..a8903fec6c 100644 --- a/cmd/geth/testdata/logging/logtest-terminal.txt +++ b/cmd/geth/testdata/logging/logtest-terminal.txt @@ -1,28 +1,31 @@ -INFO [10-19|10:06:00.208] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [10-19|10:06:00.208] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 -INFO [10-19|10:06:00.208] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [10-19|10:06:00.208] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 -INFO [10-19|10:06:00.208] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [10-19|10:06:00.208] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [10-19|10:06:00.208] int64 1,000,000=1,000,000 -INFO [10-19|10:06:00.209] int64 -1,000,000=-1,000,000 -INFO [10-19|10:06:00.209] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 -INFO [10-19|10:06:00.209] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 -INFO [10-19|10:06:00.209] uint64 1,000,000=1,000,000 -INFO [10-19|10:06:00.209] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 -INFO [10-19|10:06:00.209] Special chars in value key="special \r\n\t chars" -INFO [10-19|10:06:00.209] Special chars in key "special \n\t chars"=value -INFO [10-19|10:06:00.209] nospace nospace=nospace -INFO [10-19|10:06:00.209] with space "with nospace"="with nospace" -INFO [10-19|10:06:00.209] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A" -INFO [10-19|10:06:00.209] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value -INFO [10-19|10:06:00.209] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value -INFO [10-19|10:06:00.209] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" -INFO [10-19|10:06:00.209] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s -INFO [10-19|10:06:00.209] Lazy evaluation of value key="lazy value" -INFO [10-19|10:06:00.209] "A message with wonky 💩 characters" -INFO [10-19|10:06:00.209] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" -INFO [10-19|10:06:00.209] A multiline message +INFO [10-19|14:54:34.604] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +INFO [10-19|14:54:34.605] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 +INFO [10-19|14:54:34.605] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +INFO [10-19|14:54:34.605] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 +INFO [10-19|14:54:34.605] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +INFO [10-19|14:54:34.605] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +INFO [10-19|14:54:34.605] int64 1,000,000=1,000,000 +INFO [10-19|14:54:34.605] int64 -1,000,000=-1,000,000 +INFO [10-19|14:54:34.605] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 +INFO [10-19|14:54:34.605] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 +INFO [10-19|14:54:34.605] uint64 1,000,000=1,000,000 +INFO [10-19|14:54:34.605] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 +INFO [10-19|14:54:34.605] Special chars in value key="special \r\n\t chars" +INFO [10-19|14:54:34.605] Special chars in key "special \n\t chars"=value +INFO [10-19|14:54:34.605] nospace nospace=nospace +INFO [10-19|14:54:34.605] with space "with nospace"="with nospace" +INFO [10-19|14:54:34.605] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A" +INFO [10-19|14:54:34.605] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value +INFO [10-19|14:54:34.605] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value +INFO [10-19|14:54:34.605] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" +INFO [10-19|14:54:34.605] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s +INFO [10-19|14:54:34.605] Lazy evaluation of value key="lazy value" +INFO [10-19|14:54:34.605] "A message with wonky 💩 characters" +INFO [10-19|14:54:34.605] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" +INFO [10-19|14:54:34.605] A multiline message LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above -INFO [10-19|10:06:00.209] boolean true=true false=false -INFO [10-19|10:06:00.209] repeated-key foo=once foo=twice +INFO [10-19|14:54:34.605] boolean true=true false=false +INFO [10-19|14:54:34.605] repeated-key foo=once foo=twice +INFO [10-19|14:54:34.605] log at level info +WARN [10-19|14:54:34.605] log at level warn +ERROR[10-19|14:54:34.605] log at level error