cerc-io/plugeth
12
0
Fork 1
Code Issues 4 Pull Requests Packages Projects Releases Wiki Activity

cmd/geth: test for logging-output (#28373)

Browse Source 
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.
This commit is contained in:
Martin Holst Swende
2023-10-25 17:57:12 +02:00
committed by GitHub
parent d8c6ae054c
commit 58ae1df684
10 changed files with 447 additions and 151 deletions
Download Patch File Download Diff File Expand all files Collapse all files
cmd/geth/testdata/logging/logtest-logfmt.txt
Vendored
+39
View File
@@ -0,0 +1,39 @@
t=2023-10-20T12:56:08+0200 lvl=info msg=big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999
t=2023-10-20T12:56:08+0200 lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999
t=2023-10-20T12:56:08+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-20T12:56:08+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-20T12:56:08+0200 lvl=info msg=uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999
t=2023-10-20T12:56:08+0200 lvl=info msg=uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
t=2023-10-20T12:56:08+0200 lvl=info msg=int64 1,000,000=1,000,000
t=2023-10-20T12:56:08+0200 lvl=info msg=int64 -1,000,000=-1,000,000
t=2023-10-20T12:56:08+0200 lvl=info msg=int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807
t=2023-10-20T12:56:08+0200 lvl=info msg=int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808
t=2023-10-20T12:56:08+0200 lvl=info msg=uint64 1,000,000=1,000,000
t=2023-10-20T12:56:08+0200 lvl=info msg=uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615
t=2023-10-20T12:56:08+0200 lvl=info msg="Special chars in value" key="special \r\n\t chars"
t=2023-10-20T12:56:08+0200 lvl=info msg="Special chars in key" "special \n\t chars"=value
t=2023-10-20T12:56:08+0200 lvl=info msg=nospace nospace=nospace
t=2023-10-20T12:56:08+0200 lvl=info msg="with space" "with nospace"="with nospace"
t=2023-10-20T12:56:08+0200 lvl=info msg="Bash escapes in value" key="\x1b[1G\x1b[K\x1b[1A"
t=2023-10-20T12:56:08+0200 lvl=info msg="Bash escapes in key" "\x1b[1G\x1b[K\x1b[1A"=value
t=2023-10-20T12:56:08+0200 lvl=info msg="Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value
t=2023-10-20T12:56:08+0200 lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m["
t=2023-10-20T12:56:08+0200 lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s
t=2023-10-20T12:56:08+0200 lvl=info msg="Lazy evaluation of value" key="lazy value"
t=2023-10-20T12:56:08+0200 lvl=info msg="A message with wonky 💩 characters"
t=2023-10-20T12:56:08+0200 lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩"
t=2023-10-20T12:56:08+0200 lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above"
t=2023-10-20T12:56:08+0200 lvl=info msg=boolean true=true false=false
t=2023-10-20T12:56:08+0200 lvl=info msg="repeated-key 1" foo=alpha foo=beta
t=2023-10-20T12:56:08+0200 lvl=info msg="repeated-key 2" xx=short xx=longer
t=2023-10-20T12:56:08+0200 lvl=info msg="log at level info"
t=2023-10-20T12:56:08+0200 lvl=warn msg="log at level warn"
t=2023-10-20T12:56:08+0200 lvl=eror msg="log at level error"
t=2023-10-20T12:56:08+0200 lvl=info msg=test bar=short a="aligned left"
t=2023-10-20T12:56:08+0200 lvl=info msg=test bar="a long message" a=1
t=2023-10-20T12:56:08+0200 lvl=info msg=test bar=short a="aligned right"
t=2023-10-20T12:56:08+0200 lvl=info msg="The following logs should align so that the key-fields make 5 columns"
t=2023-10-20T12:56:08+0200 lvl=info msg="Inserted known block" number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=1,123,123 other=first
t=2023-10-20T12:56:08+0200 lvl=info msg="Inserted new block" number=1 hash=0x0000000000000000000000000000000000000000000000000000000000001235 txs=2 gas=1123 other=second
t=2023-10-20T12:56:08+0200 lvl=info msg="Inserted known block" number=99 hash=0x0000000000000000000000000000000000000000000000000000000000012322 txs=10 gas=1 other=third
t=2023-10-20T12:56:08+0200 lvl=warn msg="Inserted known block" number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=99 other=fourth
cmd/geth/testdata/logging/logtest-terminal.txt
Vendored
+40
View File
@@ -0,0 +1,40 @@
INFO [10-20|12:56:42.532] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999
INFO [10-20|12:56:42.532] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999
INFO [10-20|12:56:42.532] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
INFO [10-20|12:56:42.532] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900
INFO [10-20|12:56:42.532] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999
INFO [10-20|12:56:42.532] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
INFO [10-20|12:56:42.532] int64 1,000,000=1,000,000
INFO [10-20|12:56:42.532] int64 -1,000,000=-1,000,000
INFO [10-20|12:56:42.532] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807
INFO [10-20|12:56:42.532] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808
INFO [10-20|12:56:42.532] uint64 1,000,000=1,000,000
INFO [10-20|12:56:42.532] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615
INFO [10-20|12:56:42.532] Special chars in value key="special \r\n\t chars"
INFO [10-20|12:56:42.532] Special chars in key "special \n\t chars"=value
INFO [10-20|12:56:42.532] nospace nospace=nospace
INFO [10-20|12:56:42.532] with space "with nospace"="with nospace"
INFO [10-20|12:56:42.532] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A"
INFO [10-20|12:56:42.532] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value
INFO [10-20|12:56:42.532] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value
INFO [10-20|12:56:42.532] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m["
INFO [10-20|12:56:42.532] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s
INFO [10-20|12:56:42.532] Lazy evaluation of value key="lazy value"
INFO [10-20|12:56:42.532] "A message with wonky 💩 characters"
INFO [10-20|12:56:42.532] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩"
INFO [10-20|12:56:42.532] A multiline message
LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above
INFO [10-20|12:56:42.532] boolean true=true false=false
INFO [10-20|12:56:42.532] repeated-key 1 foo=alpha foo=beta
INFO [10-20|12:56:42.532] repeated-key 2 xx=short xx=longer
INFO [10-20|12:56:42.532] log at level info
WARN [10-20|12:56:42.532] log at level warn
ERROR[10-20|12:56:42.532] log at level error
INFO [10-20|12:56:42.532] test bar=short a="aligned left"
INFO [10-20|12:56:42.532] test bar="a long message" a=1
INFO [10-20|12:56:42.532] test bar=short a="aligned right"
INFO [10-20|12:56:42.532] The following logs should align so that the key-fields make 5 columns
INFO [10-20|12:56:42.532] Inserted known block number=1012 hash=000000..001234 txs=200 gas=1,123,123 other=first
INFO [10-20|12:56:42.532] Inserted new block number=1 hash=000000..001235 txs=2 gas=1123 other=second
INFO [10-20|12:56:42.532] Inserted known block number=99 hash=000000..012322 txs=10 gas=1 other=third
WARN [10-20|12:56:42.532] Inserted known block number=1012 hash=000000..001234 txs=200 gas=99 other=fourth