diff --git a/cmd/geth/logging_test.go b/cmd/geth/logging_test.go index b85eaf60d8..a5470dc28c 100644 --- a/cmd/geth/logging_test.go +++ b/cmd/geth/logging_test.go @@ -86,3 +86,24 @@ func testConsoleLogging(t *testing.T, format string, tStart, tEnd int) { 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.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 +} diff --git a/cmd/geth/logtestcmd.go b/cmd/geth/logtestcmd.go index d2da907462..77d4417b2d 100644 --- a/cmd/geth/logtestcmd.go +++ b/cmd/geth/logtestcmd.go @@ -18,19 +18,19 @@ 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" - "math" - "math/big" - "time" ) // 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 { - { // 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" @@ -83,5 +83,18 @@ func logTest(ctx *cli.Context) error { 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 ? + log.Info("repeated-key", "foo", "once", "foo", "twice") + } + { // + 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") + } return nil } diff --git a/cmd/geth/testdata/logging/logtest-logfmt.txt b/cmd/geth/testdata/logging/logtest-logfmt.txt index 24673d1d38..e69954237d 100644 --- a/cmd/geth/testdata/logging/logtest-logfmt.txt +++ b/cmd/geth/testdata/logging/logtest-logfmt.txt @@ -1,25 +1,27 @@ -t=2023-10-18T14:27:14+0200 lvl=info msg=big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -t=2023-10-18T14:27:14+0200 lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 -t=2023-10-18T14:27:14+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-18T14:27:14+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-18T14:27:14+0200 lvl=info msg=uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -t=2023-10-18T14:27:14+0200 lvl=info msg=uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -t=2023-10-18T14:27:14+0200 lvl=info msg=int64 1,000,000=1,000,000 -t=2023-10-18T14:27:14+0200 lvl=info msg=int64 -1,000,000=-1,000,000 -t=2023-10-18T14:27:14+0200 lvl=info msg=int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 -t=2023-10-18T14:27:14+0200 lvl=info msg=int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 -t=2023-10-18T14:27:14+0200 lvl=info msg=uint64 1,000,000=1,000,000 -t=2023-10-18T14:27:14+0200 lvl=info msg=uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 -t=2023-10-18T14:27:14+0200 lvl=info msg="Special chars in value" key="special \r\n\t chars" -t=2023-10-18T14:27:14+0200 lvl=info msg="Special chars in key" "special \n\t chars"=value -t=2023-10-18T14:27:14+0200 lvl=info msg=nospace nospace=nospace -t=2023-10-18T14:27:14+0200 lvl=info msg="with space" "with nospace"="with nospace" -t=2023-10-18T14:27:14+0200 lvl=info msg="Bash escapes in value" key="\x1b[1G\x1b[K\x1b[1A" -t=2023-10-18T14:27:14+0200 lvl=info msg="Bash escapes in key" "\x1b[1G\x1b[K\x1b[1A"=value -t=2023-10-18T14:27:14+0200 lvl=info msg="Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value -t=2023-10-18T14:27:14+0200 lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" -t=2023-10-18T14:27:14+0200 lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s -t=2023-10-18T14:27:14+0200 lvl=info msg="Lazy evaluation of value" key="lazy value" -t=2023-10-18T14:27:14+0200 lvl=info msg="A message with wonky 💩 characters" -t=2023-10-18T14:27:14+0200 lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" -t=2023-10-18T14:27:14+0200 lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above" +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 diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt index 923da2faeb..cf13f4fdc1 100644 --- a/cmd/geth/testdata/logging/logtest-terminal.txt +++ b/cmd/geth/testdata/logging/logtest-terminal.txt @@ -1,26 +1,28 @@ -INFO [10-18|14:26:57.326] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [10-18|14:26:57.326] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 -INFO [10-18|14:26:57.326] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [10-18|14:26:57.326] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 -INFO [10-18|14:26:57.326] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [10-18|14:26:57.326] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [10-18|14:26:57.326] int64 1,000,000=1,000,000 -INFO [10-18|14:26:57.326] int64 -1,000,000=-1,000,000 -INFO [10-18|14:26:57.326] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 -INFO [10-18|14:26:57.326] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 -INFO [10-18|14:26:57.326] uint64 1,000,000=1,000,000 -INFO [10-18|14:26:57.326] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 -INFO [10-18|14:26:57.326] Special chars in value key="special \r\n\t chars" -INFO [10-18|14:26:57.326] Special chars in key "special \n\t chars"=value -INFO [10-18|14:26:57.326] nospace nospace=nospace -INFO [10-18|14:26:57.326] with space "with nospace"="with nospace" -INFO [10-18|14:26:57.326] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A" -INFO [10-18|14:26:57.326] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value -INFO [10-18|14:26:57.326] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value -INFO [10-18|14:26:57.326] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" -INFO [10-18|14:26:57.326] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s -INFO [10-18|14:26:57.326] Lazy evaluation of value key="lazy value" -INFO [10-18|14:26:57.326] "A message with wonky 💩 characters" -INFO [10-18|14:26:57.326] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" -INFO [10-18|14:26:57.326] A multiline message -LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above +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 +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