mirror of
https://github.com/ethereum/go-ethereum.git
synced 2026-08-20 10:52:25 +00:00
cmd/geth: add test for file-logging, fix flaw on CI-runs
This commit is contained in:
Martin Holst Swende
parent
5ef12a8bda
commit
b75f045714
3 changed files with 126 additions and 55 deletions
|
|
@ -21,6 +21,7 @@ import (
|
||||||
"bytes"
|
"bytes"
|
||||||
"fmt"
|
"fmt"
|
||||||
"io"
|
"io"
|
||||||
|
"math/rand"
|
||||||
"os"
|
"os"
|
||||||
"os/exec"
|
"os/exec"
|
||||||
"strings"
|
"strings"
|
||||||
|
|
@ -42,7 +43,7 @@ func split(input io.Reader) []string {
|
||||||
scanner := bufio.NewScanner(input)
|
scanner := bufio.NewScanner(input)
|
||||||
scanner.Split(bufio.ScanLines)
|
scanner.Split(bufio.ScanLines)
|
||||||
for scanner.Scan() {
|
for scanner.Scan() {
|
||||||
output = append(output, scanner.Text())
|
output = append(output, strings.TrimSpace(scanner.Text()))
|
||||||
}
|
}
|
||||||
return output
|
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)
|
t.Fatalf("format %v, line %d missing, want:%v", format, i, want)
|
||||||
}
|
}
|
||||||
have := haveLines[i]
|
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
|
// Black out the timestamp
|
||||||
have = censor(have, tStart, tEnd)
|
have = censor(have, tStart, tEnd)
|
||||||
want = censor(want, tStart, tEnd)
|
want = censor(want, tStart, tEnd)
|
||||||
if have != want {
|
if have != want {
|
||||||
|
t.Logf(nicediff([]byte(have), []byte(want)))
|
||||||
t.Fatalf("format %v, line %d\nhave %v\nwant %v", format, i, have, 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(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
|
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")
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
|
||||||
57
cmd/geth/testdata/logging/logtest-logfmt.txt
vendored
57
cmd/geth/testdata/logging/logtest-logfmt.txt
vendored
|
|
@ -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-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-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-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-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-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-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-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-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-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-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-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-19T10:05:35+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-19T10:05:35+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-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-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-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-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-19T10:05:35+0200 lvl=info msg=uint64 1,000,000=1,000,000
|
t=2023-10-19T14:54:24+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-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-19T10:05:35+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 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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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-19T14:54:24+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=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"
|
||||||
|
|
|
||||||
57
cmd/geth/testdata/logging/logtest-terminal.txt
vendored
57
cmd/geth/testdata/logging/logtest-terminal.txt
vendored
|
|
@ -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|14:54:34.604] 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|14:54:34.605] -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|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|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|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|10:06:00.208] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999
|
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|10:06:00.208] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
|
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|10:06:00.208] int64 1,000,000=1,000,000
|
INFO [10-19|14:54:34.605] int64 1,000,000=1,000,000
|
||||||
INFO [10-19|10:06:00.209] int64 -1,000,000=-1,000,000
|
INFO [10-19|14:54:34.605] 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|14:54:34.605] 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|14:54:34.605] 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|14:54:34.605] 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|14:54:34.605] 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|14:54:34.605] 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|14:54:34.605] Special chars in key "special \n\t chars"=value
|
||||||
INFO [10-19|10:06:00.209] nospace nospace=nospace
|
INFO [10-19|14:54:34.605] nospace nospace=nospace
|
||||||
INFO [10-19|10:06:00.209] with space "with nospace"="with nospace"
|
INFO [10-19|14:54:34.605] 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|14:54:34.605] 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|14:54:34.605] 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|14:54:34.605] "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|14:54:34.605] "\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|14:54:34.605] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s
|
||||||
INFO [10-19|10:06:00.209] Lazy evaluation of value key="lazy value"
|
INFO [10-19|14:54:34.605] Lazy evaluation of value key="lazy value"
|
||||||
INFO [10-19|10:06:00.209] "A message with wonky 💩 characters"
|
INFO [10-19|14:54:34.605] "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|14:54:34.605] "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.605] A multiline message
|
||||||
LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above
|
LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above
|
||||||
INFO [10-19|10:06:00.209] boolean true=true false=false
|
INFO [10-19|14:54:34.605] 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] 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
|
||||||
|
|
|
||||||
Loading…
Reference in a new issue