diff --git a/cmd/geth/logtestcmd.go b/cmd/geth/logtestcmd.go index 3630324031..2e04d014ae 100644 --- a/cmd/geth/logtestcmd.go +++ b/cmd/geth/logtestcmd.go @@ -101,5 +101,13 @@ func logTest(ctx *cli.Context) error { 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") + } return nil } diff --git a/cmd/geth/testdata/logging/logtest-logfmt.txt b/cmd/geth/testdata/logging/logtest-logfmt.txt index 0f003167c4..f6a64855a4 100644 --- a/cmd/geth/testdata/logging/logtest-logfmt.txt +++ b/cmd/geth/testdata/logging/logtest-logfmt.txt @@ -1,30 +1,33 @@ -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" +t=2023-10-20T08:16:02+0200 lvl=info msg=big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +t=2023-10-20T08:16:02+0200 lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 +t=2023-10-20T08:16:02+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-20T08:16:02+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-20T08:16:02+0200 lvl=info msg=uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +t=2023-10-20T08:16:02+0200 lvl=info msg=uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +t=2023-10-20T08:16:02+0200 lvl=info msg=int64 1,000,000=1,000,000 +t=2023-10-20T08:16:02+0200 lvl=info msg=int64 -1,000,000=-1,000,000 +t=2023-10-20T08:16:02+0200 lvl=info msg=int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 +t=2023-10-20T08:16:02+0200 lvl=info msg=int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 +t=2023-10-20T08:16:02+0200 lvl=info msg=uint64 1,000,000=1,000,000 +t=2023-10-20T08:16:02+0200 lvl=info msg=uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 +t=2023-10-20T08:16:02+0200 lvl=info msg="Special chars in value" key="special \r\n\t chars" +t=2023-10-20T08:16:02+0200 lvl=info msg="Special chars in key" "special \n\t chars"=value +t=2023-10-20T08:16:02+0200 lvl=info msg=nospace nospace=nospace +t=2023-10-20T08:16:02+0200 lvl=info msg="with space" "with nospace"="with nospace" +t=2023-10-20T08:16:02+0200 lvl=info msg="Bash escapes in value" key="\x1b[1G\x1b[K\x1b[1A" +t=2023-10-20T08:16:02+0200 lvl=info msg="Bash escapes in key" "\x1b[1G\x1b[K\x1b[1A"=value +t=2023-10-20T08:16:02+0200 lvl=info msg="Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value +t=2023-10-20T08:16:02+0200 lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" +t=2023-10-20T08:16:02+0200 lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s +t=2023-10-20T08:16:02+0200 lvl=info msg="Lazy evaluation of value" key="lazy value" +t=2023-10-20T08:16:02+0200 lvl=info msg="A message with wonky 💩 characters" +t=2023-10-20T08:16:02+0200 lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" +t=2023-10-20T08:16:02+0200 lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above" +t=2023-10-20T08:16:02+0200 lvl=info msg=boolean true=true false=false +t=2023-10-20T08:16:02+0200 lvl=info msg=repeated-key foo=alpha foo=beta +t=2023-10-20T08:16:02+0200 lvl=info msg="log at level info" +t=2023-10-20T08:16:02+0200 lvl=warn msg="log at level warn" +t=2023-10-20T08:16:02+0200 lvl=eror msg="log at level error" +t=2023-10-20T08:16:02+0200 lvl=info msg=test bar=short a="aligned left" +t=2023-10-20T08:16:02+0200 lvl=info msg=test bar="a long message" a=1 +t=2023-10-20T08:16:02+0200 lvl=info msg=test bar=short a="aligned right" diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt index a8903fec6c..0da1c3a09f 100644 --- a/cmd/geth/testdata/logging/logtest-terminal.txt +++ b/cmd/geth/testdata/logging/logtest-terminal.txt @@ -1,31 +1,34 @@ -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 +INFO [10-20|08:15:21.795] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +INFO [10-20|08:15:21.795] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 +INFO [10-20|08:15:21.795] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +INFO [10-20|08:15:21.795] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 +INFO [10-20|08:15:21.795] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +INFO [10-20|08:15:21.795] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +INFO [10-20|08:15:21.795] int64 1,000,000=1,000,000 +INFO [10-20|08:15:21.795] int64 -1,000,000=-1,000,000 +INFO [10-20|08:15:21.795] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 +INFO [10-20|08:15:21.795] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 +INFO [10-20|08:15:21.795] uint64 1,000,000=1,000,000 +INFO [10-20|08:15:21.795] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 +INFO [10-20|08:15:21.795] Special chars in value key="special \r\n\t chars" +INFO [10-20|08:15:21.795] Special chars in key "special \n\t chars"=value +INFO [10-20|08:15:21.795] nospace nospace=nospace +INFO [10-20|08:15:21.795] with space "with nospace"="with nospace" +INFO [10-20|08:15:21.795] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A" +INFO [10-20|08:15:21.795] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value +INFO [10-20|08:15:21.795] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value +INFO [10-20|08:15:21.795] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" +INFO [10-20|08:15:21.795] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s +INFO [10-20|08:15:21.795] Lazy evaluation of value key="lazy value" +INFO [10-20|08:15:21.795] "A message with wonky 💩 characters" +INFO [10-20|08:15:21.795] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" +INFO [10-20|08:15:21.795] A multiline message LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above -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 +INFO [10-20|08:15:21.795] boolean true=true false=false +INFO [10-20|08:15:21.795] repeated-key foo=alpha foo=beta +INFO [10-20|08:15:21.795] log at level info +WARN [10-20|08:15:21.795] log at level warn +ERROR[10-20|08:15:21.795] log at level error +INFO [10-20|08:15:21.795] test bar=short a="aligned left" +INFO [10-20|08:15:21.795] test bar="a long message" a=1 +INFO [10-20|08:15:21.795] test bar=short a="aligned right"