From 28e73717016cdc9ebdb5fdb3474cfbd3bd2d2524 Mon Sep 17 00:00:00 2001 From: jwasinger Date: Wed, 29 Nov 2023 15:33:50 +0800 Subject: [PATCH] all: replace log15 with slog (#28187) This PR replaces Geth's logger package (a fork of [log15](https://github.com/inconshreveable/log15)) with an implementation using slog, a logging library included as part of the Go standard library as of Go1.21. Main changes are as follows: * removes any log handlers that were unused in the Geth codebase. * Json, logfmt, and terminal formatters are now slog handlers. * Verbosity level constants are changed to match slog constant values. Internal translation is done to make this opaque to the user and backwards compatible with existing `--verbosity` and `--vmodule` options. * `--log.backtraceat` and `--log.debug` are removed. The external-facing API is largely the same as the existing Geth logger. Logger method signatures remain unchanged. A small semantic difference is that a `Handler` can only be set once per `Logger` and not changed dynamically. This just means that a new logger must be instantiated every time the handler of the root logger is changed. ---- For users of the `go-ethereum/log` module. If you were using this module for your own project, you will need to change the initialization. If you previously did ```golang log.Root().SetHandler(log.LvlFilterHandler(log.LvlInfo, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) ``` You now instead need to do ```golang log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true))) ``` See more about reasoning here: https://github.com/ethereum/go-ethereum/issues/28558#issuecomment-1820606613 --- cmd/abigen/main.go | 2 +- cmd/bootnode/main.go | 7 +- cmd/clef/main.go | 3 +- cmd/devp2p/runtest.go | 2 +- cmd/evm/internal/t8ntool/block.go | 7 +- cmd/evm/internal/t8ntool/transaction.go | 7 +- cmd/evm/internal/t8ntool/transition.go | 8 +- cmd/geth/logging_test.go | 48 ++ cmd/geth/logtestcmd_active.go | 5 +- cmd/geth/main.go | 2 + cmd/geth/testdata/logging/logtest-json.txt | 100 ++-- cmd/geth/testdata/logging/logtest-logfmt.txt | 102 ++-- .../testdata/logging/logtest-terminal.txt | 102 ++-- cmd/utils/flags.go | 7 + cmd/utils/flags_legacy.go | 14 + core/state/snapshot/generate_test.go | 2 +- core/txpool/blobpool/blobpool_test.go | 10 +- eth/catalyst/api_test.go | 2 +- eth/downloader/queue_test.go | 4 +- go.mod | 17 +- go.sum | 34 +- internal/debug/api.go | 9 +- internal/debug/flags.go | 116 ++-- internal/testlog/testlog.go | 126 +++-- log/CONTRIBUTORS | 11 - log/LICENSE | 13 - log/README.md | 77 --- log/README_ETHEREUM.md | 5 - log/doc.go | 327 ------------ log/format.go | 337 +++--------- log/handler.go | 504 ++++++------------ log/handler_glog.go | 155 +++--- log/logger.go | 380 ++++++------- log/logger_test.go | 62 +-- log/root.go | 49 +- log/syslog.go | 58 -- miner/stress/clique/main.go | 2 +- p2p/discover/v4_udp_test.go | 7 +- p2p/discover/v5_udp_test.go | 7 +- p2p/simulations/adapters/exec.go | 20 +- p2p/simulations/adapters/types.go | 5 +- p2p/simulations/examples/ping-pong.go | 2 +- p2p/simulations/http_test.go | 4 +- signer/core/auditlog.go | 9 +- signer/storage/aes_gcm_storage_test.go | 5 +- 45 files changed, 971 insertions(+), 1804 deletions(-) delete mode 100644 log/CONTRIBUTORS delete mode 100644 log/LICENSE delete mode 100644 log/README.md delete mode 100644 log/README_ETHEREUM.md delete mode 100644 log/doc.go delete mode 100644 log/syslog.go diff --git a/cmd/abigen/main.go b/cmd/abigen/main.go index 221f45c078..0149dec527 100644 --- a/cmd/abigen/main.go +++ b/cmd/abigen/main.go @@ -232,7 +232,7 @@ func abigen(c *cli.Context) error { } func main() { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlInfo, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true))) if err := app.Run(os.Args); err != nil { fmt.Fprintln(os.Stderr, err) diff --git a/cmd/bootnode/main.go b/cmd/bootnode/main.go index 5c1635de39..1660b43b74 100644 --- a/cmd/bootnode/main.go +++ b/cmd/bootnode/main.go @@ -32,6 +32,7 @@ import ( "github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/p2p/nat" "github.com/ethereum/go-ethereum/p2p/netutil" + "golang.org/x/exp/slog" ) func main() { @@ -52,10 +53,10 @@ func main() { ) flag.Parse() - glogger := log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat(false))) - glogger.Verbosity(log.Lvl(*verbosity)) + glogger := log.NewGlogHandler(log.NewTerminalHandler(os.Stderr, false)) + glogger.Verbosity(slog.Level(*verbosity)) glogger.Vmodule(*vmodule) - log.Root().SetHandler(glogger) + log.SetDefault(log.NewLogger(glogger)) natm, err := nat.Parse(*natdesc) if err != nil { diff --git a/cmd/clef/main.go b/cmd/clef/main.go index 63f34effb7..27b7b70771 100644 --- a/cmd/clef/main.go +++ b/cmd/clef/main.go @@ -57,6 +57,7 @@ import ( "github.com/mattn/go-colorable" "github.com/mattn/go-isatty" "github.com/urfave/cli/v2" + "golang.org/x/exp/slog" ) const legalWarning = ` @@ -492,7 +493,7 @@ func initialize(c *cli.Context) error { if usecolor { output = colorable.NewColorable(logOutput) } - log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(c.Int(logLevelFlag.Name)), log.StreamHandler(output, log.TerminalFormat(usecolor)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(output, slog.Level(c.Int(logLevelFlag.Name)), usecolor))) return nil } diff --git a/cmd/devp2p/runtest.go b/cmd/devp2p/runtest.go index f72aa91119..76af53ee4d 100644 --- a/cmd/devp2p/runtest.go +++ b/cmd/devp2p/runtest.go @@ -54,7 +54,7 @@ func runTests(ctx *cli.Context, tests []utesting.Test) error { } // Disable logging unless explicitly enabled. if !ctx.IsSet("verbosity") && !ctx.IsSet("vmodule") { - log.Root().SetHandler(log.DiscardHandler()) + log.SetDefault(log.NewLogger(log.DiscardHandler())) } // Run the tests. var run = utesting.RunTests diff --git a/cmd/evm/internal/t8ntool/block.go b/cmd/evm/internal/t8ntool/block.go index 5c0e28e284..429ae12c54 100644 --- a/cmd/evm/internal/t8ntool/block.go +++ b/cmd/evm/internal/t8ntool/block.go @@ -33,6 +33,7 @@ import ( "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rlp" "github.com/urfave/cli/v2" + "golang.org/x/exp/slog" ) //go:generate go run github.com/fjl/gencodec -type header -field-override headerMarshaling -out gen_header.go @@ -216,9 +217,9 @@ func (i *bbInput) sealClique(block *types.Block) (*types.Block, error) { // BuildBlock constructs a block from the given inputs. func BuildBlock(ctx *cli.Context) error { // Configure the go-ethereum logger - glogger := log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat(false))) - glogger.Verbosity(log.Lvl(ctx.Int(VerbosityFlag.Name))) - log.Root().SetHandler(glogger) + glogger := log.NewGlogHandler(log.NewTerminalHandler(os.Stderr, false)) + glogger.Verbosity(slog.Level(ctx.Int(VerbosityFlag.Name))) + log.SetDefault(log.NewLogger(glogger)) baseDir, err := createBasedir(ctx) if err != nil { diff --git a/cmd/evm/internal/t8ntool/transaction.go b/cmd/evm/internal/t8ntool/transaction.go index 03a2e2eb99..e1c98c7fe2 100644 --- a/cmd/evm/internal/t8ntool/transaction.go +++ b/cmd/evm/internal/t8ntool/transaction.go @@ -33,6 +33,7 @@ import ( "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/tests" "github.com/urfave/cli/v2" + "golang.org/x/exp/slog" ) type result struct { @@ -66,9 +67,9 @@ func (r *result) MarshalJSON() ([]byte, error) { func Transaction(ctx *cli.Context) error { // Configure the go-ethereum logger - glogger := log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat(false))) - glogger.Verbosity(log.Lvl(ctx.Int(VerbosityFlag.Name))) - log.Root().SetHandler(glogger) + glogger := log.NewGlogHandler(log.NewTerminalHandler(os.Stderr, false)) + glogger.Verbosity(slog.Level(ctx.Int(VerbosityFlag.Name))) + log.SetDefault(log.NewLogger(glogger)) var ( err error diff --git a/cmd/evm/internal/t8ntool/transition.go b/cmd/evm/internal/t8ntool/transition.go index d517592e5c..a01dfedab9 100644 --- a/cmd/evm/internal/t8ntool/transition.go +++ b/cmd/evm/internal/t8ntool/transition.go @@ -24,6 +24,8 @@ import ( "os" "path" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/consensus/misc/eip1559" @@ -81,9 +83,9 @@ type input struct { func Transition(ctx *cli.Context) error { // Configure the go-ethereum logger - glogger := log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat(false))) - glogger.Verbosity(log.Lvl(ctx.Int(VerbosityFlag.Name))) - log.Root().SetHandler(glogger) + glogger := log.NewGlogHandler(log.NewTerminalHandler(os.Stderr, false)) + glogger.Verbosity(slog.Level(ctx.Int(VerbosityFlag.Name))) + log.SetDefault(log.NewLogger(glogger)) var ( err error diff --git a/cmd/geth/logging_test.go b/cmd/geth/logging_test.go index 69fe0fadf7..50991554b4 100644 --- a/cmd/geth/logging_test.go +++ b/cmd/geth/logging_test.go @@ -28,6 +28,7 @@ import ( "os/exec" "strings" "testing" + "encoding/json" "github.com/ethereum/go-ethereum/internal/reexec" ) @@ -98,6 +99,53 @@ func testConsoleLogging(t *testing.T, format string, tStart, tEnd int) { } } +func TestJsonLogging(t *testing.T) { + t.Parallel() + haveB, err := runSelf("--log.format", "json", "logtest") + if err != nil { + t.Fatal(err) + } + readFile, err := os.Open("testdata/logging/logtest-json.txt") + if err != nil { + t.Fatal(err) + } + wantLines := split(readFile) + haveLines := split(bytes.NewBuffer(haveB)) + for i, wantLine := range wantLines { + if i > len(haveLines)-1 { + t.Fatalf("format %v, line %d missing, want:%v", "json", i, wantLine) + } + haveLine := haveLines[i] + for strings.Contains(haveLine, "Unknown config environment variable") { + // This can happen on CI runs. Drop it. + haveLines = append(haveLines[:i], haveLines[i+1:]...) + haveLine = haveLines[i] + } + var have, want []byte + { + var h map[string]any + if err := json.Unmarshal([]byte(haveLine), &h); err != nil { + t.Fatal(err) + } + h["t"] = "xxx" + have, _ = json.Marshal(h) + } + { + var w map[string]any + if err := json.Unmarshal([]byte(wantLine), &w); err != nil { + t.Fatal(err) + } + w["t"] = "xxx" + want, _ = json.Marshal(w) + } + if !bytes.Equal(have, want) { + // show an intelligent diff + t.Logf(nicediff(have, want)) + t.Errorf("file content wrong") + } + } +} + func TestVmodule(t *testing.T) { t.Parallel() checkOutput := func(level int, want, wantNot string) { diff --git a/cmd/geth/logtestcmd_active.go b/cmd/geth/logtestcmd_active.go index 0632f9ca4b..0ca4cc621d 100644 --- a/cmd/geth/logtestcmd_active.go +++ b/cmd/geth/logtestcmd_active.go @@ -26,6 +26,7 @@ import ( "time" "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/holiman/uint256" "github.com/urfave/cli/v2" @@ -49,7 +50,9 @@ func (c customQuotedStringer) String() string { // 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 { - log.ResetGlobalState() + // clear field padding map + debug.ResetLogging() + { // 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" diff --git a/cmd/geth/main.go b/cmd/geth/main.go index e5a17e45cf..0d5939bd20 100644 --- a/cmd/geth/main.go +++ b/cmd/geth/main.go @@ -144,6 +144,8 @@ var ( utils.GpoMaxGasPriceFlag, utils.GpoIgnoreGasPriceFlag, configFileFlag, + utils.LogDebugFlag, + utils.LogBacktraceAtFlag, }, utils.NetworkFlags, utils.DatabaseFlags) rpcFlags = []cli.Flag{ diff --git a/cmd/geth/testdata/logging/logtest-json.txt b/cmd/geth/testdata/logging/logtest-json.txt index 6cb2476dbd..bdc1ae4de6 100644 --- a/cmd/geth/testdata/logging/logtest-json.txt +++ b/cmd/geth/testdata/logging/logtest-json.txt @@ -1,49 +1,51 @@ -{"111,222,333,444,555,678,999":"111222333444555678999","lvl":"info","msg":"big.Int","t":"2023-11-09T08:33:19.464383209+01:00"} -{"-111,222,333,444,555,678,999":"-111222333444555678999","lvl":"info","msg":"-big.Int","t":"2023-11-09T08:33:19.46455928+01:00"} -{"11,122,233,344,455,567,899,900":"11122233344455567899900","lvl":"info","msg":"big.Int","t":"2023-11-09T08:33:19.464582073+01:00"} -{"-11,122,233,344,455,567,899,900":"-11122233344455567899900","lvl":"info","msg":"-big.Int","t":"2023-11-09T08:33:19.464594846+01:00"} -{"111,222,333,444,555,678,999":"0x607851afc94ca2517","lvl":"info","msg":"uint256","t":"2023-11-09T08:33:19.464607873+01:00"} -{"11,122,233,344,455,567,899,900":"0x25aeffe8aaa1ef67cfc","lvl":"info","msg":"uint256","t":"2023-11-09T08:33:19.464694639+01:00"} -{"1,000,000":1000000,"lvl":"info","msg":"int64","t":"2023-11-09T08:33:19.464708835+01:00"} -{"-1,000,000":-1000000,"lvl":"info","msg":"int64","t":"2023-11-09T08:33:19.464725054+01:00"} -{"9,223,372,036,854,775,807":9223372036854775807,"lvl":"info","msg":"int64","t":"2023-11-09T08:33:19.464735773+01:00"} -{"-9,223,372,036,854,775,808":-9223372036854775808,"lvl":"info","msg":"int64","t":"2023-11-09T08:33:19.464744532+01:00"} -{"1,000,000":1000000,"lvl":"info","msg":"uint64","t":"2023-11-09T08:33:19.464752807+01:00"} -{"18,446,744,073,709,551,615":18446744073709551615,"lvl":"info","msg":"uint64","t":"2023-11-09T08:33:19.464779296+01:00"} -{"key":"special \r\n\t chars","lvl":"info","msg":"Special chars in value","t":"2023-11-09T08:33:19.464794181+01:00"} -{"lvl":"info","msg":"Special chars in key","special \n\t chars":"value","t":"2023-11-09T08:33:19.464827197+01:00"} -{"lvl":"info","msg":"nospace","nospace":"nospace","t":"2023-11-09T08:33:19.464841118+01:00"} -{"lvl":"info","msg":"with space","t":"2023-11-09T08:33:19.464862818+01:00","with nospace":"with nospace"} -{"key":"\u001b[1G\u001b[K\u001b[1A","lvl":"info","msg":"Bash escapes in value","t":"2023-11-09T08:33:19.464876802+01:00"} -{"\u001b[1G\u001b[K\u001b[1A":"value","lvl":"info","msg":"Bash escapes in key","t":"2023-11-09T08:33:19.464885416+01:00"} -{"key":"value","lvl":"info","msg":"Bash escapes in message \u001b[1G\u001b[K\u001b[1A end","t":"2023-11-09T08:33:19.464906946+01:00"} -{"\u001b[35mColored\u001b[0m[":"\u001b[35mColored\u001b[0m[","lvl":"info","msg":"\u001b[35mColored\u001b[0m[","t":"2023-11-09T08:33:19.464921455+01:00"} -{"2562047h47m16.854s":"2562047h47m16.854s","lvl":"info","msg":"Custom Stringer value","t":"2023-11-09T08:33:19.464943893+01:00"} -{"key":"lazy value","lvl":"info","msg":"Lazy evaluation of value","t":"2023-11-09T08:33:19.465013552+01:00"} -{"lvl":"info","msg":"A message with wonky 💩 characters","t":"2023-11-09T08:33:19.465069437+01:00"} -{"lvl":"info","msg":"A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩","t":"2023-11-09T08:33:19.465083053+01:00"} -{"lvl":"info","msg":"A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above","t":"2023-11-09T08:33:19.465104289+01:00"} -{"false":"false","lvl":"info","msg":"boolean","t":"2023-11-09T08:33:19.465117185+01:00","true":"true"} -{"foo":"beta","lvl":"info","msg":"repeated-key 1","t":"2023-11-09T08:33:19.465143425+01:00"} -{"lvl":"info","msg":"repeated-key 2","t":"2023-11-09T08:33:19.465156323+01:00","xx":"longer"} -{"lvl":"info","msg":"log at level info","t":"2023-11-09T08:33:19.465193158+01:00"} -{"lvl":"warn","msg":"log at level warn","t":"2023-11-09T08:33:19.465228964+01:00"} -{"lvl":"eror","msg":"log at level error","t":"2023-11-09T08:33:19.465240352+01:00"} -{"a":"aligned left","bar":"short","lvl":"info","msg":"test","t":"2023-11-09T08:33:19.465247226+01:00"} -{"a":1,"bar":"a long message","lvl":"info","msg":"test","t":"2023-11-09T08:33:19.465269028+01:00"} -{"a":"aligned right","bar":"short","lvl":"info","msg":"test","t":"2023-11-09T08:33:19.465313611+01:00"} -{"lvl":"info","msg":"The following logs should align so that the key-fields make 5 columns","t":"2023-11-09T08:33:19.465328188+01:00"} -{"gas":1123123,"hash":"0x0000000000000000000000000000000000000000000000000000000000001234","lvl":"info","msg":"Inserted known block","number":1012,"other":"first","t":"2023-11-09T08:33:19.465350507+01:00","txs":200} -{"gas":1123,"hash":"0x0000000000000000000000000000000000000000000000000000000000001235","lvl":"info","msg":"Inserted new block","number":1,"other":"second","t":"2023-11-09T08:33:19.465387952+01:00","txs":2} -{"gas":1,"hash":"0x0000000000000000000000000000000000000000000000000000000000012322","lvl":"info","msg":"Inserted known block","number":99,"other":"third","t":"2023-11-09T08:33:19.465406687+01:00","txs":10} -{"gas":99,"hash":"0x0000000000000000000000000000000000000000000000000000000000001234","lvl":"warn","msg":"Inserted known block","number":1012,"other":"fourth","t":"2023-11-09T08:33:19.465433025+01:00","txs":200} -{"\u003cnil\u003e":"\u003cnil\u003e","lvl":"info","msg":"(*big.Int)(nil)","t":"2023-11-09T08:33:19.465450283+01:00"} -{"\u003cnil\u003e":"nil","lvl":"info","msg":"(*uint256.Int)(nil)","t":"2023-11-09T08:33:19.465472953+01:00"} -{"lvl":"info","msg":"(fmt.Stringer)(nil)","res":"\u003cnil\u003e","t":"2023-11-09T08:33:19.465538633+01:00"} -{"lvl":"info","msg":"nil-concrete-stringer","res":"nil","t":"2023-11-09T08:33:19.465552355+01:00"} -{"lvl":"info","msg":"error(nil) ","res":"\u003cnil\u003e","t":"2023-11-09T08:33:19.465601029+01:00"} -{"lvl":"info","msg":"nil-concrete-error","res":"","t":"2023-11-09T08:33:19.46561622+01:00"} -{"lvl":"info","msg":"nil-custom-struct","res":"\u003cnil\u003e","t":"2023-11-09T08:33:19.465638888+01:00"} -{"lvl":"info","msg":"raw nil","res":"\u003cnil\u003e","t":"2023-11-09T08:33:19.465673664+01:00"} -{"lvl":"info","msg":"(*uint64)(nil)","res":"\u003cnil\u003e","t":"2023-11-09T08:33:19.465700264+01:00"} -{"level":"level","lvl":"lvl","msg":"msg","t":"t","time":"time"} +{"t":"2023-11-22T15:42:00.407963+08:00","lvl":"info","msg":"big.Int","111,222,333,444,555,678,999":"111222333444555678999"} +{"t":"2023-11-22T15:42:00.408084+08:00","lvl":"info","msg":"-big.Int","-111,222,333,444,555,678,999":"-111222333444555678999"} +{"t":"2023-11-22T15:42:00.408092+08:00","lvl":"info","msg":"big.Int","11,122,233,344,455,567,899,900":"11122233344455567899900"} +{"t":"2023-11-22T15:42:00.408097+08:00","lvl":"info","msg":"-big.Int","-11,122,233,344,455,567,899,900":"-11122233344455567899900"} +{"t":"2023-11-22T15:42:00.408127+08:00","lvl":"info","msg":"uint256","111,222,333,444,555,678,999":"111222333444555678999"} +{"t":"2023-11-22T15:42:00.408133+08:00","lvl":"info","msg":"uint256","11,122,233,344,455,567,899,900":"11122233344455567899900"} +{"t":"2023-11-22T15:42:00.408137+08:00","lvl":"info","msg":"int64","1,000,000":1000000} +{"t":"2023-11-22T15:42:00.408145+08:00","lvl":"info","msg":"int64","-1,000,000":-1000000} +{"t":"2023-11-22T15:42:00.408149+08:00","lvl":"info","msg":"int64","9,223,372,036,854,775,807":9223372036854775807} +{"t":"2023-11-22T15:42:00.408153+08:00","lvl":"info","msg":"int64","-9,223,372,036,854,775,808":-9223372036854775808} +{"t":"2023-11-22T15:42:00.408156+08:00","lvl":"info","msg":"uint64","1,000,000":1000000} +{"t":"2023-11-22T15:42:00.40816+08:00","lvl":"info","msg":"uint64","18,446,744,073,709,551,615":18446744073709551615} +{"t":"2023-11-22T15:42:00.408164+08:00","lvl":"info","msg":"Special chars in value","key":"special \r\n\t chars"} +{"t":"2023-11-22T15:42:00.408167+08:00","lvl":"info","msg":"Special chars in key","special \n\t chars":"value"} +{"t":"2023-11-22T15:42:00.408171+08:00","lvl":"info","msg":"nospace","nospace":"nospace"} +{"t":"2023-11-22T15:42:00.408174+08:00","lvl":"info","msg":"with space","with nospace":"with nospace"} +{"t":"2023-11-22T15:42:00.408178+08:00","lvl":"info","msg":"Bash escapes in value","key":"\u001b[1G\u001b[K\u001b[1A"} +{"t":"2023-11-22T15:42:00.408182+08:00","lvl":"info","msg":"Bash escapes in key","\u001b[1G\u001b[K\u001b[1A":"value"} +{"t":"2023-11-22T15:42:00.408186+08:00","lvl":"info","msg":"Bash escapes in message \u001b[1G\u001b[K\u001b[1A end","key":"value"} +{"t":"2023-11-22T15:42:00.408194+08:00","lvl":"info","msg":"\u001b[35mColored\u001b[0m[","\u001b[35mColored\u001b[0m[":"\u001b[35mColored\u001b[0m["} +{"t":"2023-11-22T15:42:00.408197+08:00","lvl":"info","msg":"an error message with quotes","error":"this is an 'error'"} +{"t":"2023-11-22T15:42:00.408202+08:00","lvl":"info","msg":"Custom Stringer value","2562047h47m16.854s":"2562047h47m16.854s"} +{"t":"2023-11-22T15:42:00.408208+08:00","lvl":"info","msg":"a custom stringer that emits quoted text","output":"output with 'quotes'"} +{"t":"2023-11-22T15:42:00.408215+08:00","lvl":"info","msg":"Lazy evaluation of value","key":"lazy value"} +{"t":"2023-11-22T15:42:00.408219+08:00","lvl":"info","msg":"A message with wonky 💩 characters"} +{"t":"2023-11-22T15:42:00.408222+08:00","lvl":"info","msg":"A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩"} +{"t":"2023-11-22T15:42:00.408226+08:00","lvl":"info","msg":"A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above"} +{"t":"2023-11-22T15:42:00.408229+08:00","lvl":"info","msg":"boolean","true":true,"false":false} +{"t":"2023-11-22T15:42:00.408234+08:00","lvl":"info","msg":"repeated-key 1","foo":"alpha","foo":"beta"} +{"t":"2023-11-22T15:42:00.408237+08:00","lvl":"info","msg":"repeated-key 2","xx":"short","xx":"longer"} +{"t":"2023-11-22T15:42:00.408241+08:00","lvl":"info","msg":"log at level info"} +{"t":"2023-11-22T15:42:00.408244+08:00","lvl":"warn","msg":"log at level warn"} +{"t":"2023-11-22T15:42:00.408247+08:00","lvl":"eror","msg":"log at level error"} +{"t":"2023-11-22T15:42:00.408251+08:00","lvl":"info","msg":"test","bar":"short","a":"aligned left"} +{"t":"2023-11-22T15:42:00.408254+08:00","lvl":"info","msg":"test","bar":"a long message","a":1} +{"t":"2023-11-22T15:42:00.408258+08:00","lvl":"info","msg":"test","bar":"short","a":"aligned right"} +{"t":"2023-11-22T15:42:00.408261+08:00","lvl":"info","msg":"The following logs should align so that the key-fields make 5 columns"} +{"t":"2023-11-22T15:42:00.408275+08:00","lvl":"info","msg":"Inserted known block","number":1012,"hash":"0x0000000000000000000000000000000000000000000000000000000000001234","txs":200,"gas":1123123,"other":"first"} +{"t":"2023-11-22T15:42:00.408281+08:00","lvl":"info","msg":"Inserted new block","number":1,"hash":"0x0000000000000000000000000000000000000000000000000000000000001235","txs":2,"gas":1123,"other":"second"} +{"t":"2023-11-22T15:42:00.408287+08:00","lvl":"info","msg":"Inserted known block","number":99,"hash":"0x0000000000000000000000000000000000000000000000000000000000012322","txs":10,"gas":1,"other":"third"} +{"t":"2023-11-22T15:42:00.408296+08:00","lvl":"warn","msg":"Inserted known block","number":1012,"hash":"0x0000000000000000000000000000000000000000000000000000000000001234","txs":200,"gas":99,"other":"fourth"} +{"t":"2023-11-22T15:42:00.4083+08:00","lvl":"info","msg":"(*big.Int)(nil)","":""} +{"t":"2023-11-22T15:42:00.408303+08:00","lvl":"info","msg":"(*uint256.Int)(nil)","":""} +{"t":"2023-11-22T15:42:00.408311+08:00","lvl":"info","msg":"(fmt.Stringer)(nil)","res":null} +{"t":"2023-11-22T15:42:00.408318+08:00","lvl":"info","msg":"nil-concrete-stringer","res":""} +{"t":"2023-11-22T15:42:00.408322+08:00","lvl":"info","msg":"error(nil) ","res":null} +{"t":"2023-11-22T15:42:00.408326+08:00","lvl":"info","msg":"nil-concrete-error","res":""} +{"t":"2023-11-22T15:42:00.408334+08:00","lvl":"info","msg":"nil-custom-struct","res":null} +{"t":"2023-11-22T15:42:00.40835+08:00","lvl":"info","msg":"raw nil","res":null} +{"t":"2023-11-22T15:42:00.408354+08:00","lvl":"info","msg":"(*uint64)(nil)","res":null} +{"t":"2023-11-22T15:42:00.408361+08:00","lvl":"info","msg":"Using keys 't', 'lvl', 'time', 'level' and 'msg'","t":"t","time":"time","lvl":"lvl","level":"level","msg":"msg"} diff --git a/cmd/geth/testdata/logging/logtest-logfmt.txt b/cmd/geth/testdata/logging/logtest-logfmt.txt index f097143a55..114569e467 100644 --- a/cmd/geth/testdata/logging/logtest-logfmt.txt +++ b/cmd/geth/testdata/logging/logtest-logfmt.txt @@ -1,51 +1,51 @@ -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=-big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=int64 1,000,000=1,000,000 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=int64 -1,000,000=-1,000,000 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=uint64 1,000,000=1,000,000 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Special chars in value" key="special \r\n\t chars" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Special chars in key" "special \n\t chars"=value -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=nospace nospace=nospace -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="with space" "with nospace"="with nospace" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Bash escapes in value" key="\x1b[1G\x1b[K\x1b[1A" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Bash escapes in key" "\x1b[1G\x1b[K\x1b[1A"=value -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="an error message with quotes" error="this is an 'error'" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="a custom stringer that emits quoted text" output="output with 'quotes'" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Lazy evaluation of value" key="lazy value" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="A message with wonky 💩 characters" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=boolean true=true false=false -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="repeated-key 1" foo=alpha foo=beta -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="repeated-key 2" xx=short xx=longer -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="log at level info" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=warn msg="log at level warn" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=eror msg="log at level error" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=test bar=short a="aligned left" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=test bar="a long message" a=1 -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=test bar=short a="aligned right" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="The following logs should align so that the key-fields make 5 columns" -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Inserted known block" number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=1,123,123 other=first -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Inserted new block" number=1 hash=0x0000000000000000000000000000000000000000000000000000000000001235 txs=2 gas=1123 other=second -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Inserted known block" number=99 hash=0x0000000000000000000000000000000000000000000000000000000000012322 txs=10 gas=1 other=third -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=warn msg="Inserted known block" number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=99 other=fourth -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=(*big.Int)(nil) = -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=(*uint256.Int)(nil) = -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=(fmt.Stringer)(nil) res=nil -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=nil-concrete-stringer res=nil -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="error(nil) " res=nil -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=nil-concrete-error res= -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=nil-custom-struct res= -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="raw nil" res=nil -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg=(*uint64)(nil) res= -t=xxxxxxxxxxxxxxxxxxxxxxxx lvl=info msg="Using keys 't', 'lvl', 'time', 'level' and 'msg'" t=t time=time lvl=lvl level=level msg=msg +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=big.Int 111,222,333,444,555,678,999=111222333444555678999 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=-big.Int -111,222,333,444,555,678,999=-111222333444555678999 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=big.Int 11,122,233,344,455,567,899,900=11122233344455567899900 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=-big.Int -11,122,233,344,455,567,899,900=-11122233344455567899900 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=uint256 111,222,333,444,555,678,999=111222333444555678999 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=uint256 11,122,233,344,455,567,899,900=11122233344455567899900 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=int64 1,000,000=1000000 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=int64 -1,000,000=-1000000 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=int64 9,223,372,036,854,775,807=9223372036854775807 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=int64 -9,223,372,036,854,775,808=-9223372036854775808 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=uint64 1,000,000=1000000 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=uint64 18,446,744,073,709,551,615=18446744073709551615 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Special chars in value" key="special \r\n\t chars" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Special chars in key" "special \n\t chars"=value +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=nospace nospace=nospace +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="with space" "with nospace"="with nospace" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Bash escapes in value" key="\x1b[1G\x1b[K\x1b[1A" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Bash escapes in key" "\x1b[1G\x1b[K\x1b[1A"=value +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="an error message with quotes" error="this is an 'error'" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Custom Stringer value" 2562047h47m16.854s=2562047h47m16.854s +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="a custom stringer that emits quoted text" output="output with 'quotes'" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Lazy evaluation of value" key="lazy value" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="A message with wonky 💩 characters" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="A multiline message \nLALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=boolean true=true false=false +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="repeated-key 1" foo=alpha foo=beta +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="repeated-key 2" xx=short xx=longer +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="log at level info" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=warn msg="log at level warn" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=eror msg="log at level error" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=test bar=short a="aligned left" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=test bar="a long message" a=1 +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=test bar=short a="aligned right" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="The following logs should align so that the key-fields make 5 columns" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Inserted known block" number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=1123123 other=first +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Inserted new block" number=1 hash=0x0000000000000000000000000000000000000000000000000000000000001235 txs=2 gas=1123 other=second +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Inserted known block" number=99 hash=0x0000000000000000000000000000000000000000000000000000000000012322 txs=10 gas=1 other=third +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=warn msg="Inserted known block" number=1012 hash=0x0000000000000000000000000000000000000000000000000000000000001234 txs=200 gas=99 other=fourth +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=(*big.Int)(nil) = +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=(*uint256.Int)(nil) = +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=(fmt.Stringer)(nil) res= +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=nil-concrete-stringer res= +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="error(nil) " res= +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=nil-concrete-error res="" +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=nil-custom-struct res= +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="raw nil" res= +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=(*uint64)(nil) res= +t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Using keys 't', 'lvl', 'time', 'level' and 'msg'" t=t time=time lvl=lvl level=level msg=msg diff --git a/cmd/geth/testdata/logging/logtest-terminal.txt b/cmd/geth/testdata/logging/logtest-terminal.txt index 051a6267fa..4da3f49d46 100644 --- a/cmd/geth/testdata/logging/logtest-terminal.txt +++ b/cmd/geth/testdata/logging/logtest-terminal.txt @@ -1,52 +1,52 @@ -INFO [XX-XX|XX:XX:XX.XXX] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [XX-XX|XX:XX:XX.XXX] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 -INFO [XX-XX|XX:XX:XX.XXX] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [XX-XX|XX:XX:XX.XXX] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 -INFO [XX-XX|XX:XX:XX.XXX] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 -INFO [XX-XX|XX:XX:XX.XXX] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 -INFO [XX-XX|XX:XX:XX.XXX] int64 1,000,000=1,000,000 -INFO [XX-XX|XX:XX:XX.XXX] int64 -1,000,000=-1,000,000 -INFO [XX-XX|XX:XX:XX.XXX] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 -INFO [XX-XX|XX:XX:XX.XXX] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 -INFO [XX-XX|XX:XX:XX.XXX] uint64 1,000,000=1,000,000 -INFO [XX-XX|XX:XX:XX.XXX] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 -INFO [XX-XX|XX:XX:XX.XXX] Special chars in value key="special \r\n\t chars" -INFO [XX-XX|XX:XX:XX.XXX] Special chars in key "special \n\t chars"=value -INFO [XX-XX|XX:XX:XX.XXX] nospace nospace=nospace -INFO [XX-XX|XX:XX:XX.XXX] with space "with nospace"="with nospace" -INFO [XX-XX|XX:XX:XX.XXX] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A" -INFO [XX-XX|XX:XX:XX.XXX] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value -INFO [XX-XX|XX:XX:XX.XXX] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value -INFO [XX-XX|XX:XX:XX.XXX] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" -INFO [XX-XX|XX:XX:XX.XXX] an error message with quotes error="this is an 'error'" -INFO [XX-XX|XX:XX:XX.XXX] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s -INFO [XX-XX|XX:XX:XX.XXX] a custom stringer that emits quoted text output="output with 'quotes'" -INFO [XX-XX|XX:XX:XX.XXX] Lazy evaluation of value key="lazy value" -INFO [XX-XX|XX:XX:XX.XXX] "A message with wonky 💩 characters" -INFO [XX-XX|XX:XX:XX.XXX] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" -INFO [XX-XX|XX:XX:XX.XXX] A multiline message +INFO [xx-xx|xx:xx:xx.xxx] big.Int 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +INFO [xx-xx|xx:xx:xx.xxx] -big.Int -111,222,333,444,555,678,999=-111,222,333,444,555,678,999 +INFO [xx-xx|xx:xx:xx.xxx] big.Int 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +INFO [xx-xx|xx:xx:xx.xxx] -big.Int -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900 +INFO [xx-xx|xx:xx:xx.xxx] uint256 111,222,333,444,555,678,999=111,222,333,444,555,678,999 +INFO [xx-xx|xx:xx:xx.xxx] uint256 11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900 +INFO [xx-xx|xx:xx:xx.xxx] int64 1,000,000=1,000,000 +INFO [xx-xx|xx:xx:xx.xxx] int64 -1,000,000=-1,000,000 +INFO [xx-xx|xx:xx:xx.xxx] int64 9,223,372,036,854,775,807=9,223,372,036,854,775,807 +INFO [xx-xx|xx:xx:xx.xxx] int64 -9,223,372,036,854,775,808=-9,223,372,036,854,775,808 +INFO [xx-xx|xx:xx:xx.xxx] uint64 1,000,000=1,000,000 +INFO [xx-xx|xx:xx:xx.xxx] uint64 18,446,744,073,709,551,615=18,446,744,073,709,551,615 +INFO [xx-xx|xx:xx:xx.xxx] Special chars in value key="special \r\n\t chars" +INFO [xx-xx|xx:xx:xx.xxx] Special chars in key "special \n\t chars"=value +INFO [xx-xx|xx:xx:xx.xxx] nospace nospace=nospace +INFO [xx-xx|xx:xx:xx.xxx] with space "with nospace"="with nospace" +INFO [xx-xx|xx:xx:xx.xxx] Bash escapes in value key="\x1b[1G\x1b[K\x1b[1A" +INFO [xx-xx|xx:xx:xx.xxx] Bash escapes in key "\x1b[1G\x1b[K\x1b[1A"=value +INFO [xx-xx|xx:xx:xx.xxx] "Bash escapes in message \x1b[1G\x1b[K\x1b[1A end" key=value +INFO [xx-xx|xx:xx:xx.xxx] "\x1b[35mColored\x1b[0m[" "\x1b[35mColored\x1b[0m["="\x1b[35mColored\x1b[0m[" +INFO [xx-xx|xx:xx:xx.xxx] an error message with quotes error="this is an 'error'" +INFO [xx-xx|xx:xx:xx.xxx] Custom Stringer value 2562047h47m16.854s=2562047h47m16.854s +INFO [xx-xx|xx:xx:xx.xxx] a custom stringer that emits quoted text output="output with 'quotes'" +INFO [xx-xx|xx:xx:xx.xxx] Lazy evaluation of value key="lazy value" +INFO [xx-xx|xx:xx:xx.xxx] "A message with wonky 💩 characters" +INFO [xx-xx|xx:xx:xx.xxx] "A multiline message \nINFO [10-18|14:11:31.106] with wonky characters 💩" +INFO [xx-xx|xx:xx:xx.xxx] A multiline message LALA [ZZZZZZZZZZZZZZZZZZ] Actually part of message above -INFO [XX-XX|XX:XX:XX.XXX] boolean true=true false=false -INFO [XX-XX|XX:XX:XX.XXX] repeated-key 1 foo=alpha foo=beta -INFO [XX-XX|XX:XX:XX.XXX] repeated-key 2 xx=short xx=longer -INFO [XX-XX|XX:XX:XX.XXX] log at level info -WARN [XX-XX|XX:XX:XX.XXX] log at level warn -ERROR[XX-XX|XX:XX:XX.XXX] log at level error -INFO [XX-XX|XX:XX:XX.XXX] test bar=short a="aligned left" -INFO [XX-XX|XX:XX:XX.XXX] test bar="a long message" a=1 -INFO [XX-XX|XX:XX:XX.XXX] test bar=short a="aligned right" -INFO [XX-XX|XX:XX:XX.XXX] The following logs should align so that the key-fields make 5 columns -INFO [XX-XX|XX:XX:XX.XXX] Inserted known block number=1012 hash=000000..001234 txs=200 gas=1,123,123 other=first -INFO [XX-XX|XX:XX:XX.XXX] Inserted new block number=1 hash=000000..001235 txs=2 gas=1123 other=second -INFO [XX-XX|XX:XX:XX.XXX] Inserted known block number=99 hash=000000..012322 txs=10 gas=1 other=third -WARN [XX-XX|XX:XX:XX.XXX] Inserted known block number=1012 hash=000000..001234 txs=200 gas=99 other=fourth -INFO [XX-XX|XX:XX:XX.XXX] (*big.Int)(nil) = -INFO [XX-XX|XX:XX:XX.XXX] (*uint256.Int)(nil) = -INFO [XX-XX|XX:XX:XX.XXX] (fmt.Stringer)(nil) res=nil -INFO [XX-XX|XX:XX:XX.XXX] nil-concrete-stringer res=nil -INFO [XX-XX|XX:XX:XX.XXX] error(nil) res=nil -INFO [XX-XX|XX:XX:XX.XXX] nil-concrete-error res= -INFO [XX-XX|XX:XX:XX.XXX] nil-custom-struct res= -INFO [XX-XX|XX:XX:XX.XXX] raw nil res=nil -INFO [XX-XX|XX:XX:XX.XXX] (*uint64)(nil) res= -INFO [XX-XX|XX:XX:XX.XXX] Using keys 't', 'lvl', 'time', 'level' and 'msg' t=t time=time lvl=lvl level=level msg=msg +INFO [xx-xx|xx:xx:xx.xxx] boolean true=true false=false +INFO [xx-xx|xx:xx:xx.xxx] repeated-key 1 foo=alpha foo=beta +INFO [xx-xx|xx:xx:xx.xxx] repeated-key 2 xx=short xx=longer +INFO [xx-xx|xx:xx:xx.xxx] log at level info +WARN [xx-xx|xx:xx:xx.xxx] log at level warn +ERROR[xx-xx|xx:xx:xx.xxx] log at level error +INFO [xx-xx|xx:xx:xx.xxx] test bar=short a="aligned left" +INFO [xx-xx|xx:xx:xx.xxx] test bar="a long message" a=1 +INFO [xx-xx|xx:xx:xx.xxx] test bar=short a="aligned right" +INFO [xx-xx|xx:xx:xx.xxx] The following logs should align so that the key-fields make 5 columns +INFO [xx-xx|xx:xx:xx.xxx] Inserted known block number=1012 hash=000000..001234 txs=200 gas=1,123,123 other=first +INFO [xx-xx|xx:xx:xx.xxx] Inserted new block number=1 hash=000000..001235 txs=2 gas=1123 other=second +INFO [xx-xx|xx:xx:xx.xxx] Inserted known block number=99 hash=000000..012322 txs=10 gas=1 other=third +WARN [xx-xx|xx:xx:xx.xxx] Inserted known block number=1012 hash=000000..001234 txs=200 gas=99 other=fourth +INFO [xx-xx|xx:xx:xx.xxx] (*big.Int)(nil) = +INFO [xx-xx|xx:xx:xx.xxx] (*uint256.Int)(nil) = +INFO [xx-xx|xx:xx:xx.xxx] (fmt.Stringer)(nil) res= +INFO [xx-xx|xx:xx:xx.xxx] nil-concrete-stringer res= +INFO [xx-xx|xx:xx:xx.xxx] error(nil) res= +INFO [xx-xx|xx:xx:xx.xxx] nil-concrete-error res= +INFO [xx-xx|xx:xx:xx.xxx] nil-custom-struct res= +INFO [xx-xx|xx:xx:xx.xxx] raw nil res= +INFO [xx-xx|xx:xx:xx.xxx] (*uint64)(nil) res= +INFO [xx-xx|xx:xx:xx.xxx] Using keys 't', 'lvl', 'time', 'level' and 'msg' t=t time=time lvl=lvl level=level msg=msg diff --git a/cmd/utils/flags.go b/cmd/utils/flags.go index b49c7c36d5..27e1b3f623 100644 --- a/cmd/utils/flags.go +++ b/cmd/utils/flags.go @@ -1389,6 +1389,13 @@ func SetNodeConfig(ctx *cli.Context, cfg *node.Config) { log.Info(fmt.Sprintf("Using %s as db engine", dbEngine)) cfg.DBEngine = dbEngine } + // deprecation notice for log debug flags (TODO: find a more appropriate place to put these?) + if ctx.IsSet(LogBacktraceAtFlag.Name) { + log.Warn("log.backtrace flag is deprecated") + } + if ctx.IsSet(LogDebugFlag.Name) { + log.Warn("log.debug flag is deprecated") + } } func setSmartCard(ctx *cli.Context, cfg *node.Config) { diff --git a/cmd/utils/flags_legacy.go b/cmd/utils/flags_legacy.go index 00237fecaf..243abd8311 100644 --- a/cmd/utils/flags_legacy.go +++ b/cmd/utils/flags_legacy.go @@ -45,6 +45,8 @@ var DeprecatedFlags = []cli.Flag{ LightMaxPeersFlag, LightNoPruneFlag, LightNoSyncServeFlag, + LogBacktraceAtFlag, + LogDebugFlag, } var ( @@ -118,6 +120,18 @@ var ( Usage: "Enables serving light clients before syncing (deprecated)", Category: flags.LightCategory, } + // Deprecated November 2023 + LogBacktraceAtFlag = &cli.StringFlag{ + Name: "log.backtrace", + Usage: "Request a stack trace at a specific logging statement (deprecated)", + Value: "", + Category: flags.DeprecatedCategory, + } + LogDebugFlag = &cli.BoolFlag{ + Name: "log.debug", + Usage: "Prepends log messages with call-site location (deprecated)", + Category: flags.DeprecatedCategory, + } ) // showDeprecated displays deprecated flags that will be soon removed from the codebase. diff --git a/core/state/snapshot/generate_test.go b/core/state/snapshot/generate_test.go index 07016b675c..c25f3e7e8b 100644 --- a/core/state/snapshot/generate_test.go +++ b/core/state/snapshot/generate_test.go @@ -601,7 +601,7 @@ func testGenerateWithExtraAccounts(t *testing.T, scheme string) { } func enableLogging() { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelTrace, true))) } // Tests that snapshot generation when an extra account with storage exists in the snap state. diff --git a/core/txpool/blobpool/blobpool_test.go b/core/txpool/blobpool/blobpool_test.go index 8914301e14..fa3e8edc90 100644 --- a/core/txpool/blobpool/blobpool_test.go +++ b/core/txpool/blobpool/blobpool_test.go @@ -319,7 +319,7 @@ func verifyPoolInternals(t *testing.T, pool *BlobPool) { // - 3. All transactions after a nonce gap must be dropped // - 4. All transactions after an underpriced one (including it) must be dropped func TestOpenDrops(t *testing.T) { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelTrace, true))) // Create a temporary folder for the persistent backend storage, _ := os.MkdirTemp("", "blobpool-") @@ -600,7 +600,7 @@ func TestOpenDrops(t *testing.T) { // - 2. Eviction thresholds are calculated correctly for the sequences // - 3. Balance usage of an account is totals across all transactions func TestOpenIndex(t *testing.T) { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelTrace, true))) // Create a temporary folder for the persistent backend storage, _ := os.MkdirTemp("", "blobpool-") @@ -689,7 +689,7 @@ func TestOpenIndex(t *testing.T) { // Tests that after indexing all the loaded transactions from disk, a price heap // is correctly constructed based on the head basefee and blobfee. func TestOpenHeap(t *testing.T) { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelTrace, true))) // Create a temporary folder for the persistent backend storage, _ := os.MkdirTemp("", "blobpool-") @@ -776,7 +776,7 @@ func TestOpenHeap(t *testing.T) { // Tests that after the pool's previous state is loaded back, any transactions // over the new storage cap will get dropped. func TestOpenCap(t *testing.T) { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelTrace, true))) // Create a temporary folder for the persistent backend storage, _ := os.MkdirTemp("", "blobpool-") @@ -868,7 +868,7 @@ func TestOpenCap(t *testing.T) { // specific to the blob pool. It does not do an exhaustive transaction validity // check. func TestAdd(t *testing.T) { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelTrace, true))) // seed is a helper tumpe to seed an initial state db and pool type seed struct { diff --git a/eth/catalyst/api_test.go b/eth/catalyst/api_test.go index 59f44fafea..c875c485dd 100644 --- a/eth/catalyst/api_test.go +++ b/eth/catalyst/api_test.go @@ -1562,7 +1562,7 @@ func TestBlockToPayloadWithBlobs(t *testing.T) { // This checks that beaconRoot is applied to the state from the engine API. func TestParentBeaconBlockRoot(t *testing.T) { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(colorable.NewColorableStderr(), log.LevelTrace, true))) genesis, blocks := generateMergeChain(10, true) diff --git a/eth/downloader/queue_test.go b/eth/downloader/queue_test.go index a8b1b45e00..50b9031a27 100644 --- a/eth/downloader/queue_test.go +++ b/eth/downloader/queue_test.go @@ -20,6 +20,7 @@ import ( "fmt" "math/big" "math/rand" + "os" "sync" "testing" "time" @@ -31,6 +32,7 @@ import ( "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/params" "github.com/ethereum/go-ethereum/trie" + "golang.org/x/exp/slog" ) // makeChain creates a chain of n blocks starting at and including parent. @@ -271,7 +273,7 @@ func XTestDelivery(t *testing.T) { world.chain = blo world.progress(10) if false { - log.Root().SetHandler(log.StdoutHandler) + log.SetDefault(log.NewLogger(slog.NewTextHandler(os.Stdout, nil))) } q := newQueue(10, 10) var wg sync.WaitGroup diff --git a/go.mod b/go.mod index 042d7155be..75c2b899d6 100644 --- a/go.mod +++ b/go.mod @@ -28,7 +28,6 @@ require ( github.com/fsnotify/fsnotify v1.6.0 github.com/gballet/go-libpcsclite v0.0.0-20190607065134-2772fd86a8ff github.com/gballet/go-verkle v0.1.1-0.20231031103413-a67434b50f46 - github.com/go-stack/stack v1.8.1 github.com/gofrs/flock v0.8.1 github.com/golang-jwt/jwt/v4 v4.5.0 github.com/golang/protobuf v1.5.3 @@ -64,13 +63,13 @@ require ( github.com/tyler-smith/go-bip39 v1.1.0 github.com/urfave/cli/v2 v2.25.7 go.uber.org/automaxprocs v1.5.2 - golang.org/x/crypto v0.14.0 - golang.org/x/exp v0.0.0-20230905200255-921286631fa9 - golang.org/x/sync v0.4.0 - golang.org/x/sys v0.13.0 - golang.org/x/text v0.13.0 + golang.org/x/crypto v0.15.0 + golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa + golang.org/x/sync v0.5.0 + golang.org/x/sys v0.14.0 + golang.org/x/text v0.14.0 golang.org/x/time v0.3.0 - golang.org/x/tools v0.13.0 + golang.org/x/tools v0.15.0 gopkg.in/natefinch/lumberjack.v2 v2.0.0 gopkg.in/yaml.v3 v3.0.1 ) @@ -136,8 +135,8 @@ require ( github.com/tklauser/go-sysconf v0.3.12 // indirect github.com/tklauser/numcpus v0.6.1 // indirect github.com/xrash/smetrics v0.0.0-20201216005158-039620a65673 // indirect - golang.org/x/mod v0.12.0 // indirect - golang.org/x/net v0.17.0 // indirect + golang.org/x/mod v0.14.0 // indirect + golang.org/x/net v0.18.0 // indirect google.golang.org/protobuf v1.27.1 // indirect gopkg.in/yaml.v2 v2.4.0 // indirect rsc.io/tmplfunc v0.0.3 // indirect diff --git a/go.sum b/go.sum index d5e7901e5a..f89adbe571 100644 --- a/go.sum +++ b/go.sum @@ -228,8 +228,6 @@ github.com/go-openapi/swag v0.19.5/go.mod h1:POnQmlKehdgb5mhVOsnJFsivZCEZ/vjK9gh github.com/go-sourcemap/sourcemap v2.1.3+incompatible h1:W1iEw64niKVGogNgBN3ePyLFfuisuzeidWPMPWmECqU= github.com/go-sourcemap/sourcemap v2.1.3+incompatible/go.mod h1:F8jJfvm2KbVjc5NqelyYJmf/v5J0dwNLS2mL4sNA1Jg= github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= -github.com/go-stack/stack v1.8.1 h1:ntEHSVwIt7PNXNpgPmVfMrNhLtgjlmnZha2kOpuRiDw= -github.com/go-stack/stack v1.8.1/go.mod h1:dcoOX6HbPZSZptuspn9bctJ+N/CnF5gGygcUP3XYfe4= github.com/gobwas/httphead v0.0.0-20180130184737-2c6c146eadee/go.mod h1:L0fX3K22YWvt/FAX9NnzrNzcI4wNYi9Yku4O0LKYflo= github.com/gobwas/pool v0.2.0/go.mod h1:q8bcK0KcYlCgd9e7WYLm9LpyS+YeLd8JVDW6WezmKEw= github.com/gobwas/ws v1.0.2/go.mod h1:szmBTxLgaFppYjEmNtny/v3w89xOydFnnZMcgRRu/EM= @@ -616,8 +614,8 @@ golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPh golang.org/x/crypto v0.0.0-20200820211705-5c72a883971a/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto= golang.org/x/crypto v0.0.0-20201221181555-eec23a3978ad/go.mod h1:jdWPYTVW3xRLrWPugEBEK3UY2ZEsg3UU495nc5E+M+I= golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc= -golang.org/x/crypto v0.14.0 h1:wBqGXzWJW6m1XrIKlAH0Hs1JJ7+9KBwnIO8v66Q9cHc= -golang.org/x/crypto v0.14.0/go.mod h1:MVFd36DqK4CsrnJYDkBA3VC4m2GkXAM0PvzMCn4JQf4= +golang.org/x/crypto v0.15.0 h1:frVn1TEaCEaZcn3Tmd7Y2b5KKPaZ+I32Q2OA3kYp5TA= +golang.org/x/crypto v0.15.0/go.mod h1:4ChreQoLWfG3xLDer1WdlH5NdlQ3+mwnQq1YTKY+72g= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20190306152737-a1d7652674e8/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20190510132918-efd6b22b2522/go.mod h1:ZjyILWgesfNpC6sMxTJOJm9Kp84zZh5NQWvqDGG3Qr8= @@ -628,8 +626,8 @@ golang.org/x/exp v0.0.0-20191227195350-da58074b4299/go.mod h1:2RIsYlXP63K8oxa1u0 golang.org/x/exp v0.0.0-20200119233911-0405dc783f0a/go.mod h1:2RIsYlXP63K8oxa1u096TMicItID8zy7Y6sNkU49FU4= golang.org/x/exp v0.0.0-20200207192155-f17229e696bd/go.mod h1:J/WKrq2StrnmMY6+EHIKF9dgMWnmCNThgcyBT1FY9mM= golang.org/x/exp v0.0.0-20200224162631-6cc2880d07d6/go.mod h1:3jZMyOhIsHpP37uCMkUooju7aAi5cS1Q23tOzKc+0MU= -golang.org/x/exp v0.0.0-20230905200255-921286631fa9 h1:GoHiUyI/Tp2nVkLI2mCxVkOjsbSXD66ic0XW0js0R9g= -golang.org/x/exp v0.0.0-20230905200255-921286631fa9/go.mod h1:S2oDrQGGwySpoQPVqRShND87VCbxmc6bL1Yd2oYrm6k= +golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa h1:FRnLl4eNAQl8hwxVVC17teOw8kdjVDVAiFMtgUdTSRQ= +golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa/go.mod h1:zk2irFbV9DP96SEBUUAy67IdHUaZuSnrz1n472HUCLE= golang.org/x/image v0.0.0-20190227222117-0694c2d4d067/go.mod h1:kZ7UVZpmo3dzQBMxlp+ypCbDeSB+sBbTgSJuh5dn5js= golang.org/x/image v0.0.0-20190802002840-cff245a6509b/go.mod h1:FeLwcggjj3mMvU+oOTbSwawSJRM1uh48EjtB4UJZlP0= golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE= @@ -651,8 +649,8 @@ golang.org/x/mod v0.1.1-0.20191107180719-034126e5016b/go.mod h1:QqPTAvyqsEbceGzB golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.6.0-dev.0.20220419223038-86c51ed26bb4/go.mod h1:jJ57K6gSWd91VN4djpZkiMVwK6gcyfeH4XE8wZrZaV4= -golang.org/x/mod v0.12.0 h1:rmsUpXtvNzj340zd98LZ4KntptpfRHwpFOHG188oHXc= -golang.org/x/mod v0.12.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs= +golang.org/x/mod v0.14.0 h1:dGoOF9QVLYng8IHTm7BAyWqCqSheQ5pYWGhzW00YJr0= +golang.org/x/mod v0.14.0/go.mod h1:hTbmBsO62+eylJbnUtE2MGJUyE7QWk4xUqPFrRgJ+7c= golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180906233101-161cd47e91fd/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= @@ -692,8 +690,8 @@ golang.org/x/net v0.0.0-20210119194325-5f4716e94777/go.mod h1:m0MpNAwzfU5UDzcl9v golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg= golang.org/x/net v0.0.0-20210525063256-abc453219eb5/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y= golang.org/x/net v0.0.0-20220722155237-a158d28d115b/go.mod h1:XRhObCWvk6IyKnWLug+ECip1KBveYUHfp+8e9klMJ9c= -golang.org/x/net v0.17.0 h1:pVaXccu2ozPjCXewfr1S7xza/zcXTity9cCdXQYSjIM= -golang.org/x/net v0.17.0/go.mod h1:NxSsAGuq816PNPmqtQdLE42eU2Fs7NoRIZrHJAlaCOE= +golang.org/x/net v0.18.0 h1:mIYleuAkSbHh0tCv7RvjL3F6ZVbLjq4+R7zbOn3Kokg= +golang.org/x/net v0.18.0/go.mod h1:/czyP5RqHAH4odGYxBJ1qz0+CE5WZ+2j1YgoEo8F2jQ= golang.org/x/oauth2 v0.0.0-20180821212333-d2e6202438be/go.mod h1:N/0e6XlmueqKjAGxoOufVs8QHGRruUQn6yWY3a++T0U= golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421/go.mod h1:gOpvHmFTYa4IltrdGE7lF6nIHvwfUNPOp7c8zoXwtLw= golang.org/x/oauth2 v0.0.0-20190604053449-0f29369cfe45/go.mod h1:gOpvHmFTYa4IltrdGE7lF6nIHvwfUNPOp7c8zoXwtLw= @@ -712,8 +710,8 @@ golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJ golang.org/x/sync v0.0.0-20201207232520-09787c993a3a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20220722155255-886fb9371eb4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= -golang.org/x/sync v0.4.0 h1:zxkM55ReGkDlKSM+Fu41A+zmbZuaPVbGMzvvdUPznYQ= -golang.org/x/sync v0.4.0/go.mod h1:FU7BRWz2tNW+3quACPkgCx/L+uEAv1htQ0V83Z9Rj+Y= +golang.org/x/sync v0.5.0 h1:60k92dhOjHxJkrqnwsfl8KuaHbn/5dl0lUPUklKo3qE= +golang.org/x/sync v0.5.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk= golang.org/x/sys v0.0.0-20180830151530-49385e6e1522/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= @@ -776,8 +774,8 @@ golang.org/x/sys v0.0.0-20220908164124-27713097b956/go.mod h1:oPkhp1MJrh7nUepCBc golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.13.0 h1:Af8nKPmuFypiUBjVoU9V20FiaFXOcuZI21p0ycVYYGE= -golang.org/x/sys v0.13.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.14.0 h1:Vz7Qs629MkJkGyHxUlRHizWJRG2j8fbQKjELVSNhy7Q= +golang.org/x/sys v0.14.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/term v0.0.0-20201117132131-f5c789dd3221/go.mod h1:Nr5EML6q2oocZ2LXRh80K7BxOlk5/8JxuGnuhpl+muw= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= @@ -790,8 +788,8 @@ golang.org/x/text v0.3.5/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ= golang.org/x/text v0.3.8/go.mod h1:E6s5w1FMmriuDzIBO73fBruAKo1PCIq6d2Q6DHfQ8WQ= -golang.org/x/text v0.13.0 h1:ablQoSUd0tRdKxZewP80B+BaqeKJuVhuRxj/dkrun3k= -golang.org/x/text v0.13.0/go.mod h1:TvPlkZtksWOMsz7fbANvkp4WM8x/WCo/om8BMLbz+aE= +golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ= +golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU= golang.org/x/time v0.0.0-20181108054448-85acf8d2951c/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= golang.org/x/time v0.0.0-20190308202827-9d24e82272b4/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= golang.org/x/time v0.0.0-20191024005414-555d28b269f0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= @@ -846,8 +844,8 @@ golang.org/x/tools v0.0.0-20200804011535-6c149bb5ef0d/go.mod h1:njjCfa9FT2d7l9Bc golang.org/x/tools v0.0.0-20200825202427-b303f430e36d/go.mod h1:njjCfa9FT2d7l9Bc6FUM5FLjQPp3cFF28FI3qnDFljA= golang.org/x/tools v0.0.0-20210106214847-113979e3529a/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA= golang.org/x/tools v0.1.12/go.mod h1:hNGJHUnrk76NpqgfD5Aqm5Crs+Hm0VOH/i9J2+nxYbc= -golang.org/x/tools v0.13.0 h1:Iey4qkscZuv0VvIt8E0neZjtPVQFSc870HQ448QgEmQ= -golang.org/x/tools v0.13.0/go.mod h1:HvlwmtVNQAhOuCjW7xxvovg8wbNq7LwfXh/k7wXUl58= +golang.org/x/tools v0.15.0 h1:zdAyfUGbYmuVokhzVmghFl2ZJh5QhcfebBgmVPFYA+8= +golang.org/x/tools v0.15.0/go.mod h1:hpksKq4dtpQWS1uQ61JkdqWM3LscIS6Slf+VVkm+wQk= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= diff --git a/internal/debug/api.go b/internal/debug/api.go index 42d0fa15ed..482989e0d0 100644 --- a/internal/debug/api.go +++ b/internal/debug/api.go @@ -37,6 +37,7 @@ import ( "github.com/ethereum/go-ethereum/log" "github.com/hashicorp/go-bexpr" + "golang.org/x/exp/slog" ) // Handler is the global debugging handler. @@ -56,7 +57,7 @@ type HandlerT struct { // Verbosity sets the log verbosity ceiling. The verbosity of individual packages // and source files can be raised using Vmodule. func (*HandlerT) Verbosity(level int) { - glogger.Verbosity(log.Lvl(level)) + glogger.Verbosity(slog.Level(level)) } // Vmodule sets the log verbosity pattern. See package log for details on the @@ -65,12 +66,6 @@ func (*HandlerT) Vmodule(pattern string) error { return glogger.Vmodule(pattern) } -// BacktraceAt sets the log backtrace location. See package log for details on -// the pattern syntax. -func (*HandlerT) BacktraceAt(location string) error { - return glogger.BacktraceAt(location) -} - // MemStats returns detailed runtime memory statistics. func (*HandlerT) MemStats() *runtime.MemStats { s := new(runtime.MemStats) diff --git a/internal/debug/flags.go b/internal/debug/flags.go index 4f0f5fe860..23e4745e8c 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -34,6 +34,7 @@ import ( "github.com/mattn/go-colorable" "github.com/mattn/go-isatty" "github.com/urfave/cli/v2" + "golang.org/x/exp/slog" "gopkg.in/natefinch/lumberjack.v2" ) @@ -75,17 +76,6 @@ var ( Usage: "Write logs to a file", Category: flags.LoggingCategory, } - backtraceAtFlag = &cli.StringFlag{ - Name: "log.backtrace", - Usage: "Request a stack trace at a specific logging statement (e.g. \"block.go:271\")", - Value: "", - Category: flags.LoggingCategory, - } - debugFlag = &cli.BoolFlag{ - Name: "log.debug", - Usage: "Prepends log messages with call-site location (file and line number)", - Category: flags.LoggingCategory, - } logRotateFlag = &cli.BoolFlag{ Name: "log.rotate", Usage: "Enables log file rotation", @@ -160,8 +150,6 @@ var Flags = []cli.Flag{ verbosityFlag, logVmoduleFlag, vmoduleFlag, - backtraceAtFlag, - debugFlag, logjsonFlag, logFormatFlag, logFileFlag, @@ -180,45 +168,34 @@ var Flags = []cli.Flag{ } var ( - glogger *log.GlogHandler - logOutputStream log.Handler + glogger *log.GlogHandler + logOutputFile io.WriteCloser + defaultTerminalHandler *log.TerminalHandler ) func init() { - glogger = log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat(false))) + defaultTerminalHandler = log.NewTerminalHandler(os.Stderr, false) + glogger = log.NewGlogHandler(defaultTerminalHandler) glogger.Verbosity(log.LvlInfo) - log.Root().SetHandler(glogger) + log.SetDefault(log.NewLogger(glogger)) +} + +func ResetLogging() { + if defaultTerminalHandler != nil { + defaultTerminalHandler.ResetFieldPadding() + } } // Setup initializes profiling and logging based on the CLI flags. // It should be called as early as possible in the program. func Setup(ctx *cli.Context) error { var ( - logfmt log.Format - output = io.Writer(os.Stderr) - logFmtFlag = ctx.String(logFormatFlag.Name) + handler slog.Handler + terminalOutput = io.Writer(os.Stderr) + output io.Writer + logFmtFlag = ctx.String(logFormatFlag.Name) ) - switch { - case ctx.Bool(logjsonFlag.Name): - // Retain backwards compatibility with `--log.json` flag if `--log.format` not set - defer log.Warn("The flag '--log.json' is deprecated, please use '--log.format=json' instead") - logfmt = log.JSONFormat() - case logFmtFlag == "json": - logfmt = log.JSONFormat() - case logFmtFlag == "logfmt": - logfmt = log.LogfmtFormat() - case logFmtFlag == "", logFmtFlag == "terminal": - useColor := (isatty.IsTerminal(os.Stderr.Fd()) || isatty.IsCygwinTerminal(os.Stderr.Fd())) && os.Getenv("TERM") != "dumb" - if useColor { - output = colorable.NewColorableStderr() - } - logfmt = log.TerminalFormat(useColor) - default: - // Unknown log format specified - return fmt.Errorf("unknown log format: %v", ctx.String(logFormatFlag.Name)) - } var ( - ostream = log.StreamHandler(output, logfmt) logFile = ctx.String(logFileFlag.Name) rotation = ctx.Bool(logRotateFlag.Name) ) @@ -241,27 +218,55 @@ func Setup(ctx *cli.Context) error { } else { context = append(context, "location", filepath.Join(os.TempDir(), "geth-lumberjack.log")) } - lumberWriter := &lumberjack.Logger{ + logOutputFile = &lumberjack.Logger{ Filename: logFile, MaxSize: ctx.Int(logMaxSizeMBsFlag.Name), MaxBackups: ctx.Int(logMaxBackupsFlag.Name), MaxAge: ctx.Int(logMaxAgeFlag.Name), Compress: ctx.Bool(logCompressFlag.Name), } - ostream = log.StreamHandler(io.MultiWriter(output, lumberWriter), logfmt) + output = io.MultiWriter(terminalOutput, logOutputFile) } else if logFile != "" { - f, err := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) - if err != nil { + var err error + if logOutputFile, err = os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644); err != nil { return err } - ostream = log.StreamHandler(io.MultiWriter(output, f), logfmt) + output = io.MultiWriter(logOutputFile, terminalOutput) context = append(context, "location", logFile) + } else { + output = terminalOutput } - glogger.SetHandler(ostream) + + switch { + case ctx.Bool(logjsonFlag.Name): + // Retain backwards compatibility with `--log.json` flag if `--log.format` not set + defer log.Warn("The flag '--log.json' is deprecated, please use '--log.format=json' instead") + handler = log.JSONHandler(output) + case logFmtFlag == "json": + handler = log.JSONHandler(output) + case logFmtFlag == "logfmt": + handler = log.LogfmtHandler(output) + case logFmtFlag == "", logFmtFlag == "terminal": + useColor := (isatty.IsTerminal(os.Stderr.Fd()) || isatty.IsCygwinTerminal(os.Stderr.Fd())) && os.Getenv("TERM") != "dumb" + if useColor { + terminalOutput = colorable.NewColorableStderr() + if logOutputFile != nil { + output = io.MultiWriter(logOutputFile, terminalOutput) + } else { + output = terminalOutput + } + } + handler = log.NewTerminalHandler(output, useColor) + default: + // Unknown log format specified + return fmt.Errorf("unknown log format: %v", ctx.String(logFormatFlag.Name)) + } + + glogger = log.NewGlogHandler(handler) // logging - verbosity := ctx.Int(verbosityFlag.Name) - glogger.Verbosity(log.Lvl(verbosity)) + verbosity := log.FromLegacyLevel(ctx.Int(verbosityFlag.Name)) + glogger.Verbosity(verbosity) vmodule := ctx.String(logVmoduleFlag.Name) if vmodule == "" { // Retain backwards compatibility with `--vmodule` flag if `--log.vmodule` not set @@ -272,16 +277,7 @@ func Setup(ctx *cli.Context) error { } glogger.Vmodule(vmodule) - debug := ctx.Bool(debugFlag.Name) - if ctx.IsSet(debugFlag.Name) { - debug = ctx.Bool(debugFlag.Name) - } - log.PrintOrigins(debug) - - backtrace := ctx.String(backtraceAtFlag.Name) - glogger.BacktraceAt(backtrace) - - log.Root().SetHandler(glogger) + log.SetDefault(log.NewLogger(glogger)) // profiling, tracing runtime.MemProfileRate = memprofilerateFlag.Value @@ -341,8 +337,8 @@ func StartPProf(address string, withMetrics bool) { func Exit() { Handler.StopCPUProfile() Handler.StopGoTrace() - if closer, ok := logOutputStream.(io.Closer); ok { - closer.Close() + if logOutputFile != nil { + logOutputFile.Close() } } diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index 684339f16d..68b9fb19f8 100644 --- a/internal/testlog/testlog.go +++ b/internal/testlog/testlog.go @@ -18,26 +18,19 @@ package testlog import ( + "bytes" + "context" + "fmt" "sync" "testing" "github.com/ethereum/go-ethereum/log" + "golang.org/x/exp/slog" ) -// Handler returns a log handler which logs to the unit test log of t. -func Handler(t *testing.T, level log.Lvl) log.Handler { - return log.LvlFilterHandler(level, &handler{t, log.TerminalFormat(false)}) -} - -type handler struct { - t *testing.T - fmt log.Format -} - -func (h *handler) Log(r *log.Record) error { - h.t.Logf("%s", h.fmt.Format(r)) - return nil -} +const ( + termTimeFormat = "01-02|15:04:05.000" +) // logger implements log.Logger such that all output goes to the unit test log via // t.Logf(). All methods in between logger.Trace, logger.Debug, etc. are marked as test @@ -51,27 +44,62 @@ type logger struct { } type bufHandler struct { - buf []*log.Record - fmt log.Format + buf []slog.Record + attrs []slog.Attr + level slog.Level } -func (h *bufHandler) Log(r *log.Record) error { +func (h *bufHandler) Handle(_ context.Context, r slog.Record) error { h.buf = append(h.buf, r) return nil } -// Logger returns a logger which logs to the unit test log of t. -func Logger(t *testing.T, level log.Lvl) log.Logger { - l := &logger{ - t: t, - l: log.New(), - mu: new(sync.Mutex), - h: &bufHandler{fmt: log.TerminalFormat(false)}, - } - l.l.SetHandler(log.LvlFilterHandler(level, l.h)) - return l +func (h *bufHandler) Enabled(_ context.Context, lvl slog.Level) bool { + return lvl <= h.level } +func (h *bufHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + records := make([]slog.Record, len(h.buf)) + copy(records[:], h.buf[:]) + return &bufHandler{ + records, + append(h.attrs, attrs...), + h.level, + } +} + +func (h *bufHandler) WithGroup(_ string) slog.Handler { + panic("not implemented") +} + +// Logger returns a logger which logs to the unit test log of t. +func Logger(t *testing.T, level slog.Level) log.Logger { + handler := bufHandler{ + []slog.Record{}, + []slog.Attr{}, + level, + } + return &logger{ + t: t, + l: log.NewLogger(&handler), + mu: new(sync.Mutex), + h: &handler, + } +} + +// LoggerWithHandler returns +func LoggerWithHandler(t *testing.T, handler slog.Handler) log.Logger { + var bh bufHandler + return &logger{ + t: t, + l: log.NewLogger(handler), + mu: new(sync.Mutex), + h: &bh, + } +} + +func (l *logger) Write(level slog.Level, msg string, ctx ...interface{}) {} + func (l *logger) Trace(msg string, ctx ...interface{}) { l.t.Helper() l.mu.Lock() @@ -80,6 +108,14 @@ func (l *logger) Trace(msg string, ctx ...interface{}) { l.flush() } +func (l *logger) Log(level slog.Level, msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Log(level, msg, ctx...) + l.flush() +} + func (l *logger) Debug(msg string, ctx ...interface{}) { l.t.Helper() l.mu.Lock() @@ -120,23 +156,45 @@ func (l *logger) Crit(msg string, ctx ...interface{}) { l.flush() } +func (l *logger) With(ctx ...interface{}) log.Logger { + return &logger{l.t, l.l.With(ctx...), l.mu, l.h} +} + func (l *logger) New(ctx ...interface{}) log.Logger { - return &logger{l.t, l.l.New(ctx...), l.mu, l.h} + return l.With(ctx...) } -func (l *logger) GetHandler() log.Handler { - return l.l.GetHandler() -} +// terminalFormat formats a message similarly to the NewTerminalHandler in the log package. +// The difference is that terminalFormat does not escape messages/attributes and does not pad attributes. +func (h *bufHandler) terminalFormat(r slog.Record) string { + buf := &bytes.Buffer{} + lvl := log.LevelAlignedString(r.Level) + attrs := []slog.Attr{} + r.Attrs(func(attr slog.Attr) bool { + attrs = append(attrs, attr) + return true + }) -func (l *logger) SetHandler(h log.Handler) { - l.l.SetHandler(h) + attrs = append(h.attrs, attrs...) + + fmt.Fprintf(buf, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), r.Message) + if length := len(r.Message); length < 40 { + buf.Write(bytes.Repeat([]byte{' '}, 40-length)) + } + + for _, attr := range attrs { + rawVal := attr.Value.Any() + fmt.Fprintf(buf, " %s=%s", attr.Key, log.FormatLogfmtValue(rawVal, true)) + } + buf.WriteByte('\n') + return buf.String() } // flush writes all buffered messages and clears the buffer. func (l *logger) flush() { l.t.Helper() for _, r := range l.h.buf { - l.t.Logf("%s", l.h.fmt.Format(r)) + l.t.Logf("%s", l.h.terminalFormat(r)) } l.h.buf = nil } diff --git a/log/CONTRIBUTORS b/log/CONTRIBUTORS deleted file mode 100644 index a0866713be..0000000000 --- a/log/CONTRIBUTORS +++ /dev/null @@ -1,11 +0,0 @@ -Contributors to log15: - -- Aaron L -- Alan Shreve -- Chris Hines -- Ciaran Downey -- Dmitry Chestnykh -- Evan Shaw -- Péter Szilágyi -- Trevor Gattis -- Vincent Vanackere diff --git a/log/LICENSE b/log/LICENSE deleted file mode 100644 index 5f0d1fb6a7..0000000000 --- a/log/LICENSE +++ /dev/null @@ -1,13 +0,0 @@ -Copyright 2014 Alan Shreve - -Licensed under the Apache License, Version 2.0 (the "License"); -you may not use this file except in compliance with the License. -You may obtain a copy of the License at - - http://www.apache.org/licenses/LICENSE-2.0 - -Unless required by applicable law or agreed to in writing, software -distributed under the License is distributed on an "AS IS" BASIS, -WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -See the License for the specific language governing permissions and -limitations under the License. diff --git a/log/README.md b/log/README.md deleted file mode 100644 index 47426806dd..0000000000 --- a/log/README.md +++ /dev/null @@ -1,77 +0,0 @@ -![obligatory xkcd](https://imgs.xkcd.com/comics/standards.png) - -# log15 [![godoc reference](https://godoc.org/github.com/inconshreveable/log15?status.png)](https://godoc.org/github.com/inconshreveable/log15) [![Build Status](https://travis-ci.org/inconshreveable/log15.svg?branch=master)](https://travis-ci.org/inconshreveable/log15) - -Package log15 provides an opinionated, simple toolkit for best-practice logging in Go (golang) that is both human and machine readable. It is modeled after the Go standard library's [`io`](https://golang.org/pkg/io/) and [`net/http`](https://golang.org/pkg/net/http/) packages and is an alternative to the standard library's [`log`](https://golang.org/pkg/log/) package. - -## Features -- A simple, easy-to-understand API -- Promotes structured logging by encouraging use of key/value pairs -- Child loggers which inherit and add their own private context -- Lazy evaluation of expensive operations -- Simple Handler interface allowing for construction of flexible, custom logging configurations with a tiny API. -- Color terminal support -- Built-in support for logging to files, streams, syslog, and the network -- Support for forking records to multiple handlers, buffering records for output, failing over from failed handler writes, + more - -## Versioning -The API of the master branch of log15 should always be considered unstable. If you want to rely on a stable API, -you must vendor the library. - -## Importing - -```go -import log "github.com/inconshreveable/log15" -``` - -## Examples - -```go -// all loggers can have key/value context -srvlog := log.New("module", "app/server") - -// all log messages can have key/value context -srvlog.Warn("abnormal conn rate", "rate", curRate, "low", lowRate, "high", highRate) - -// child loggers with inherited context -connlog := srvlog.New("raddr", c.RemoteAddr()) -connlog.Info("connection open") - -// lazy evaluation -connlog.Debug("ping remote", "latency", log.Lazy{pingRemote}) - -// flexible configuration -srvlog.SetHandler(log.MultiHandler( - log.StreamHandler(os.Stderr, log.LogfmtFormat()), - log.LvlFilterHandler( - log.LvlError, - log.Must.FileHandler("errors.json", log.JSONFormat())))) -``` - -Will result in output that looks like this: - -``` -WARN[06-17|21:58:10] abnormal conn rate module=app/server rate=0.500 low=0.100 high=0.800 -INFO[06-17|21:58:10] connection open module=app/server raddr=10.0.0.1 -``` - -## Breaking API Changes -The following commits broke API stability. This reference is intended to help you understand the consequences of updating to a newer version -of log15. - -- 57a084d014d4150152b19e4e531399a7145d1540 - Added a `Get()` method to the `Logger` interface to retrieve the current handler -- 93404652ee366648fa622b64d1e2b67d75a3094a - `Record` field `Call` changed to `stack.Call` with switch to `github.com/go-stack/stack` -- a5e7613673c73281f58e15a87d2cf0cf111e8152 - Restored `syslog.Priority` argument to the `SyslogXxx` handler constructors - -## FAQ - -### The varargs style is brittle and error prone! Can I have type safety please? -Yes. Use `log.Ctx`: - -```go -srvlog := log.New(log.Ctx{"module": "app/server"}) -srvlog.Warn("abnormal conn rate", log.Ctx{"rate": curRate, "low": lowRate, "high": highRate}) -``` - -## License -Apache diff --git a/log/README_ETHEREUM.md b/log/README_ETHEREUM.md deleted file mode 100644 index f6c42ccc03..0000000000 --- a/log/README_ETHEREUM.md +++ /dev/null @@ -1,5 +0,0 @@ -This package is a fork of https://github.com/inconshreveable/log15, with some -minor modifications required by the go-ethereum codebase: - - * Support for log level `trace` - * Modified behavior to exit on `critical` failure diff --git a/log/doc.go b/log/doc.go deleted file mode 100644 index d2e15140e4..0000000000 --- a/log/doc.go +++ /dev/null @@ -1,327 +0,0 @@ -/* -Package log15 provides an opinionated, simple toolkit for best-practice logging that is -both human and machine readable. It is modeled after the standard library's io and net/http -packages. - -This package enforces you to only log key/value pairs. Keys must be strings. Values may be -any type that you like. The default output format is logfmt, but you may also choose to use -JSON instead if that suits you. Here's how you log: - - log.Info("page accessed", "path", r.URL.Path, "user_id", user.id) - -This will output a line that looks like: - - lvl=info t=2014-05-02T16:07:23-0700 msg="page accessed" path=/org/71/profile user_id=9 - -# Getting Started - -To get started, you'll want to import the library: - - import log "github.com/inconshreveable/log15" - -Now you're ready to start logging: - - func main() { - log.Info("Program starting", "args", os.Args()) - } - -# Convention - -Because recording a human-meaningful message is common and good practice, the first argument to every -logging method is the value to the *implicit* key 'msg'. - -Additionally, the level you choose for a message will be automatically added with the key 'lvl', and so -will the current timestamp with key 't'. - -You may supply any additional context as a set of key/value pairs to the logging function. log15 allows -you to favor terseness, ordering, and speed over safety. This is a reasonable tradeoff for -logging functions. You don't need to explicitly state keys/values, log15 understands that they alternate -in the variadic argument list: - - log.Warn("size out of bounds", "low", lowBound, "high", highBound, "val", val) - -If you really do favor your type-safety, you may choose to pass a log.Ctx instead: - - log.Warn("size out of bounds", log.Ctx{"low": lowBound, "high": highBound, "val": val}) - -# Context loggers - -Frequently, you want to add context to a logger so that you can track actions associated with it. An http -request is a good example. You can easily create new loggers that have context that is automatically included -with each log line: - - requestlogger := log.New("path", r.URL.Path) - - // later - requestlogger.Debug("db txn commit", "duration", txnTimer.Finish()) - -This will output a log line that includes the path context that is attached to the logger: - - lvl=dbug t=2014-05-02T16:07:23-0700 path=/repo/12/add_hook msg="db txn commit" duration=0.12 - -# Handlers - -The Handler interface defines where log lines are printed to and how they are formatted. Handler is a -single interface that is inspired by net/http's handler interface: - - type Handler interface { - Log(r *Record) error - } - -Handlers can filter records, format them, or dispatch to multiple other Handlers. -This package implements a number of Handlers for common logging patterns that are -easily composed to create flexible, custom logging structures. - -Here's an example handler that prints logfmt output to Stdout: - - handler := log.StreamHandler(os.Stdout, log.LogfmtFormat()) - -Here's an example handler that defers to two other handlers. One handler only prints records -from the rpc package in logfmt to standard out. The other prints records at Error level -or above in JSON formatted output to the file /var/log/service.json - - handler := log.MultiHandler( - log.LvlFilterHandler(log.LvlError, log.Must.FileHandler("/var/log/service.json", log.JSONFormat())), - log.MatchFilterHandler("pkg", "app/rpc" log.StdoutHandler()) - ) - -# Logging File Names and Line Numbers - -This package implements three Handlers that add debugging information to the -context, CallerFileHandler, CallerFuncHandler and CallerStackHandler. Here's -an example that adds the source file and line number of each logging call to -the context. - - h := log.CallerFileHandler(log.StdoutHandler) - log.Root().SetHandler(h) - ... - log.Error("open file", "err", err) - -This will output a line that looks like: - - lvl=eror t=2014-05-02T16:07:23-0700 msg="open file" err="file not found" caller=data.go:42 - -Here's an example that logs the call stack rather than just the call site. - - h := log.CallerStackHandler("%+v", log.StdoutHandler) - log.Root().SetHandler(h) - ... - log.Error("open file", "err", err) - -This will output a line that looks like: - - lvl=eror t=2014-05-02T16:07:23-0700 msg="open file" err="file not found" stack="[pkg/data.go:42 pkg/cmd/main.go]" - -The "%+v" format instructs the handler to include the path of the source file -relative to the compile time GOPATH. The github.com/go-stack/stack package -documents the full list of formatting verbs and modifiers available. - -# Custom Handlers - -The Handler interface is so simple that it's also trivial to write your own. Let's create an -example handler which tries to write to one handler, but if that fails it falls back to -writing to another handler and includes the error that it encountered when trying to write -to the primary. This might be useful when trying to log over a network socket, but if that -fails you want to log those records to a file on disk. - - type BackupHandler struct { - Primary Handler - Secondary Handler - } - - func (h *BackupHandler) Log (r *Record) error { - err := h.Primary.Log(r) - if err != nil { - r.Ctx = append(ctx, "primary_err", err) - return h.Secondary.Log(r) - } - return nil - } - -This pattern is so useful that a generic version that handles an arbitrary number of Handlers -is included as part of this library called FailoverHandler. - -# Logging Expensive Operations - -Sometimes, you want to log values that are extremely expensive to compute, but you don't want to pay -the price of computing them if you haven't turned up your logging level to a high level of detail. - -This package provides a simple type to annotate a logging operation that you want to be evaluated -lazily, just when it is about to be logged, so that it would not be evaluated if an upstream Handler -filters it out. Just wrap any function which takes no arguments with the log.Lazy type. For example: - - func factorRSAKey() (factors []int) { - // return the factors of a very large number - } - - log.Debug("factors", log.Lazy{factorRSAKey}) - -If this message is not logged for any reason (like logging at the Error level), then -factorRSAKey is never evaluated. - -# Dynamic context values - -The same log.Lazy mechanism can be used to attach context to a logger which you want to be -evaluated when the message is logged, but not when the logger is created. For example, let's imagine -a game where you have Player objects: - - type Player struct { - name string - alive bool - log.Logger - } - -You always want to log a player's name and whether they're alive or dead, so when you create the player -object, you might do: - - p := &Player{name: name, alive: true} - p.Logger = log.New("name", p.name, "alive", p.alive) - -Only now, even after a player has died, the logger will still report they are alive because the logging -context is evaluated when the logger was created. By using the Lazy wrapper, we can defer the evaluation -of whether the player is alive or not to each log message, so that the log records will reflect the player's -current state no matter when the log message is written: - - p := &Player{name: name, alive: true} - isAlive := func() bool { return p.alive } - player.Logger = log.New("name", p.name, "alive", log.Lazy{isAlive}) - -# Terminal Format - -If log15 detects that stdout is a terminal, it will configure the default -handler for it (which is log.StdoutHandler) to use TerminalFormat. This format -logs records nicely for your terminal, including color-coded output based -on log level. - -# Error Handling - -Becasuse log15 allows you to step around the type system, there are a few ways you can specify -invalid arguments to the logging functions. You could, for example, wrap something that is not -a zero-argument function with log.Lazy or pass a context key that is not a string. Since logging libraries -are typically the mechanism by which errors are reported, it would be onerous for the logging functions -to return errors. Instead, log15 handles errors by making these guarantees to you: - -- Any log record containing an error will still be printed with the error explained to you as part of the log record. - -- Any log record containing an error will include the context key LOG15_ERROR, enabling you to easily -(and if you like, automatically) detect if any of your logging calls are passing bad values. - -Understanding this, you might wonder why the Handler interface can return an error value in its Log method. Handlers -are encouraged to return errors only if they fail to write their log records out to an external source like if the -syslog daemon is not responding. This allows the construction of useful handlers which cope with those failures -like the FailoverHandler. - -# Library Use - -log15 is intended to be useful for library authors as a way to provide configurable logging to -users of their library. Best practice for use in a library is to always disable all output for your logger -by default and to provide a public Logger instance that consumers of your library can configure. Like so: - - package yourlib - - import "github.com/inconshreveable/log15" - - var Log = log.New() - - func init() { - Log.SetHandler(log.DiscardHandler()) - } - -Users of your library may then enable it if they like: - - import "github.com/inconshreveable/log15" - import "example.com/yourlib" - - func main() { - handler := // custom handler setup - yourlib.Log.SetHandler(handler) - } - -# Best practices attaching logger context - -The ability to attach context to a logger is a powerful one. Where should you do it and why? -I favor embedding a Logger directly into any persistent object in my application and adding -unique, tracing context keys to it. For instance, imagine I am writing a web browser: - - type Tab struct { - url string - render *RenderingContext - // ... - - Logger - } - - func NewTab(url string) *Tab { - return &Tab { - // ... - url: url, - - Logger: log.New("url", url), - } - } - -When a new tab is created, I assign a logger to it with the url of -the tab as context so it can easily be traced through the logs. -Now, whenever we perform any operation with the tab, we'll log with its -embedded logger and it will include the tab title automatically: - - tab.Debug("moved position", "idx", tab.idx) - -There's only one problem. What if the tab url changes? We could -use log.Lazy to make sure the current url is always written, but that -would mean that we couldn't trace a tab's full lifetime through our -logs after the user navigate to a new URL. - -Instead, think about what values to attach to your loggers the -same way you think about what to use as a key in a SQL database schema. -If it's possible to use a natural key that is unique for the lifetime of the -object, do so. But otherwise, log15's ext package has a handy RandId -function to let you generate what you might call "surrogate keys" -They're just random hex identifiers to use for tracing. Back to our -Tab example, we would prefer to set up our Logger like so: - - import logext "github.com/inconshreveable/log15/ext" - - t := &Tab { - // ... - url: url, - } - - t.Logger = log.New("id", logext.RandId(8), "url", log.Lazy{t.getUrl}) - return t - -Now we'll have a unique traceable identifier even across loading new urls, but -we'll still be able to see the tab's current url in the log messages. - -# Must - -For all Handler functions which can return an error, there is a version of that -function which will return no error but panics on failure. They are all available -on the Must object. For example: - - log.Must.FileHandler("/path", log.JSONFormat) - log.Must.NetHandler("tcp", ":1234", log.JSONFormat) - -# Inspiration and Credit - -All of the following excellent projects inspired the design of this library: - -code.google.com/p/log4go - -github.com/op/go-logging - -github.com/technoweenie/grohl - -github.com/Sirupsen/logrus - -github.com/kr/logfmt - -github.com/spacemonkeygo/spacelog - -golang's stdlib, notably io and net/http - -# The Name - -https://xkcd.com/927/ -*/ -package log diff --git a/log/format.go b/log/format.go index 2fd1f28558..5cbbe3341e 100644 --- a/log/format.go +++ b/log/format.go @@ -2,18 +2,15 @@ package log import ( "bytes" - "encoding/json" "fmt" "math/big" "reflect" "strconv" - "strings" - "sync" - "sync/atomic" "time" "unicode/utf8" "github.com/holiman/uint256" + "golang.org/x/exp/slog" ) const ( @@ -24,61 +21,19 @@ const ( termCtxMaxPadding = 40 ) -// ResetGlobalState resets the fieldPadding, which is useful for producing -// predictable output. -func ResetGlobalState() { - fieldPaddingLock.Lock() - fieldPadding = make(map[string]int) - fieldPaddingLock.Unlock() -} - -// locationTrims are trimmed for display to avoid unwieldy log lines. -var locationTrims = []string{ - "github.com/ethereum/go-ethereum/", -} - -// PrintOrigins sets or unsets log location (file:line) printing for terminal -// format output. -func PrintOrigins(print bool) { - locationEnabled.Store(print) - if print { - stackEnabled.Store(true) - } -} - -// stackEnabled is an atomic flag controlling whether the log handler needs -// to store the callsite stack. This is needed in case any handler wants to -// print locations (locationEnabled), use vmodule, or print full stacks (BacktraceAt). -var stackEnabled atomic.Bool - -// locationEnabled is an atomic flag controlling whether the terminal formatter -// should append the log locations too when printing entries. -var locationEnabled atomic.Bool - -// locationLength is the maxmimum path length encountered, which all logs are -// padded to to aid in alignment. -var locationLength atomic.Uint32 - -// fieldPadding is a global map with maximum field value lengths seen until now -// to allow padding log contexts in a bit smarter way. -var fieldPadding = make(map[string]int) - -// fieldPaddingLock is a global mutex protecting the field padding map. -var fieldPaddingLock sync.RWMutex - type Format interface { - Format(r *Record) []byte + Format(r slog.Record) []byte } // FormatFunc returns a new Format object which uses // the given function to perform record formatting. -func FormatFunc(f func(*Record) []byte) Format { +func FormatFunc(f func(slog.Record) []byte) Format { return formatFunc(f) } -type formatFunc func(*Record) []byte +type formatFunc func(slog.Record) []byte -func (f formatFunc) Format(r *Record) []byte { +func (f formatFunc) Format(r slog.Record) []byte { return f(r) } @@ -89,263 +44,100 @@ type TerminalStringer interface { TerminalString() string } -// TerminalFormat formats log records optimized for human readability on -// a terminal with color-coded level output and terser human friendly timestamp. -// This format should only be used for interactive programs or while developing. -// -// [LEVEL] [TIME] MESSAGE key=value key=value ... -// -// Example: -// -// [DBUG] [May 16 20:58:45] remove route ns=haproxy addr=127.0.0.1:50002 -func TerminalFormat(usecolor bool) Format { - return FormatFunc(func(r *Record) []byte { - msg := escapeMessage(r.Msg) - var color = 0 - if usecolor { - switch r.Lvl { - case LvlCrit: - color = 35 - case LvlError: - color = 31 - case LvlWarn: - color = 33 - case LvlInfo: - color = 32 - case LvlDebug: - color = 36 - case LvlTrace: - color = 34 - } +func (h *TerminalHandler) TerminalFormat(r slog.Record, usecolor bool) []byte { + msg := escapeMessage(r.Message) + var color = 0 + if usecolor { + switch r.Level { + case LevelCrit: + color = 35 + case slog.LevelError: + color = 31 + case slog.LevelWarn: + color = 33 + case slog.LevelInfo: + color = 32 + case slog.LevelDebug: + color = 36 + case LevelTrace: + color = 34 } + } - b := &bytes.Buffer{} - lvl := r.Lvl.AlignedString() - if locationEnabled.Load() { - // Log origin printing was requested, format the location path and line number - location := fmt.Sprintf("%+v", r.Call) - for _, prefix := range locationTrims { - location = strings.TrimPrefix(location, prefix) - } - // Maintain the maximum location length for fancyer alignment - align := int(locationLength.Load()) - if align < len(location) { - align = len(location) - locationLength.Store(uint32(align)) - } - padding := strings.Repeat(" ", align-len(location)) + b := &bytes.Buffer{} + lvl := LevelAlignedString(r.Level) + if color > 0 { + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), msg) + } else { + fmt.Fprintf(b, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), msg) + } + // try to justify the log output for short messages + length := utf8.RuneCountInString(msg) + if r.NumAttrs() > 0 && length < termMsgJust { + b.Write(bytes.Repeat([]byte{' '}, termMsgJust-length)) + } + // print the keys logfmt style + h.logfmt(b, r, color) - // Assemble and print the log heading - if color > 0 { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s|%s]%s %s ", color, lvl, r.Time.Format(termTimeFormat), location, padding, msg) - } else { - fmt.Fprintf(b, "%s[%s|%s]%s %s ", lvl, r.Time.Format(termTimeFormat), location, padding, msg) - } - } else { - if color > 0 { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), msg) - } else { - fmt.Fprintf(b, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), msg) - } - } - // try to justify the log output for short messages - length := utf8.RuneCountInString(msg) - if len(r.Ctx) > 0 && length < termMsgJust { - b.Write(bytes.Repeat([]byte{' '}, termMsgJust-length)) - } - // print the keys logfmt style - logfmt(b, r.Ctx, color, true) - return b.Bytes() - }) + return b.Bytes() } -// LogfmtFormat prints records in logfmt format, an easy machine-parseable but human-readable -// format for key/value pairs. -// -// For more details see: http://godoc.org/github.com/kr/logfmt -func LogfmtFormat() Format { - return FormatFunc(func(r *Record) []byte { - common := []interface{}{r.KeyNames.Time, r.Time, r.KeyNames.Lvl, r.Lvl, r.KeyNames.Msg, r.Msg} - buf := &bytes.Buffer{} - logfmt(buf, append(common, r.Ctx...), 0, false) - return buf.Bytes() +func (h *TerminalHandler) logfmt(buf *bytes.Buffer, r slog.Record, color int) { + attrs := []slog.Attr{} + r.Attrs(func(attr slog.Attr) bool { + attrs = append(attrs, attr) + return true }) -} -func logfmt(buf *bytes.Buffer, ctx []interface{}, color int, term bool) { - for i := 0; i < len(ctx); i += 2 { + attrs = append(h.attrs, attrs...) + + for i, attr := range attrs { if i != 0 { buf.WriteByte(' ') } - k, ok := ctx[i].(string) - v := formatLogfmtValue(ctx[i+1], term) - if !ok { - k, v = errorKey, fmt.Sprintf("%+T is not a string key", ctx[i]) - } else { - k = escapeString(k) - } + key := escapeString(attr.Key) + rawVal := attr.Value.Any() + val := FormatLogfmtValue(rawVal, true) // XXX: we should probably check that all of your key bytes aren't invalid - fieldPaddingLock.RLock() - padding := fieldPadding[k] - fieldPaddingLock.RUnlock() + // TODO (jwasinger) above comment was from log15 code. what does it mean? check that key bytes are ascii characters? + padding := h.fieldPadding[key] - length := utf8.RuneCountInString(v) + length := utf8.RuneCountInString(val) if padding < length && length <= termCtxMaxPadding { padding = length - - fieldPaddingLock.Lock() - fieldPadding[k] = padding - fieldPaddingLock.Unlock() + h.fieldPadding[key] = padding } if color > 0 { - fmt.Fprintf(buf, "\x1b[%dm%s\x1b[0m=", color, k) + fmt.Fprintf(buf, "\x1b[%dm%s\x1b[0m=", color, key) } else { - buf.WriteString(k) + buf.WriteString(key) buf.WriteByte('=') } - buf.WriteString(v) - if i < len(ctx)-2 && padding > length { + buf.WriteString(val) + if i < r.NumAttrs()-1 && padding > length { buf.Write(bytes.Repeat([]byte{' '}, padding-length)) } } buf.WriteByte('\n') } -// JSONFormat formats log records as JSON objects separated by newlines. -// It is the equivalent of JSONFormatEx(false, true). -func JSONFormat() Format { - return JSONFormatEx(false, true) -} - -// JSONFormatOrderedEx formats log records as JSON arrays. If pretty is true, -// records will be pretty-printed. If lineSeparated is true, records -// will be logged with a new line between each record. -func JSONFormatOrderedEx(pretty, lineSeparated bool) Format { - jsonMarshal := json.Marshal - if pretty { - jsonMarshal = func(v interface{}) ([]byte, error) { - return json.MarshalIndent(v, "", " ") - } +// formatValue formats a value for serialization +func FormatLogfmtValue(value interface{}, term bool) (result string) { + if value == nil { + return "" } - return FormatFunc(func(r *Record) []byte { - props := map[string]interface{}{ - r.KeyNames.Time: r.Time, - r.KeyNames.Lvl: r.Lvl.String(), - r.KeyNames.Msg: r.Msg, - } - - ctx := make([]string, len(r.Ctx)) - for i := 0; i < len(r.Ctx); i += 2 { - if k, ok := r.Ctx[i].(string); ok { - ctx[i] = k - ctx[i+1] = formatLogfmtValue(r.Ctx[i+1], true) - } else { - props[errorKey] = fmt.Sprintf("%+T is not a string key,", r.Ctx[i]) - } - } - props[r.KeyNames.Ctx] = ctx - - b, err := jsonMarshal(props) - if err != nil { - b, _ = jsonMarshal(map[string]string{ - errorKey: err.Error(), - }) - return b - } - if lineSeparated { - b = append(b, '\n') - } - return b - }) -} - -// JSONFormatEx formats log records as JSON objects. If pretty is true, -// records will be pretty-printed. If lineSeparated is true, records -// will be logged with a new line between each record. -func JSONFormatEx(pretty, lineSeparated bool) Format { - jsonMarshal := json.Marshal - if pretty { - jsonMarshal = func(v interface{}) ([]byte, error) { - return json.MarshalIndent(v, "", " ") - } - } - - return FormatFunc(func(r *Record) []byte { - props := map[string]interface{}{ - r.KeyNames.Time: r.Time, - r.KeyNames.Lvl: r.Lvl.String(), - r.KeyNames.Msg: r.Msg, - } - - for i := 0; i < len(r.Ctx); i += 2 { - k, ok := r.Ctx[i].(string) - if !ok { - props[errorKey] = fmt.Sprintf("%+T is not a string key", r.Ctx[i]) - } else { - props[k] = formatJSONValue(r.Ctx[i+1]) - } - } - - b, err := jsonMarshal(props) - if err != nil { - b, _ = jsonMarshal(map[string]string{ - errorKey: err.Error(), - }) - return b - } - - if lineSeparated { - b = append(b, '\n') - } - - return b - }) -} - -func formatShared(value interface{}) (result interface{}) { defer func() { if err := recover(); err != nil { if v := reflect.ValueOf(value); v.Kind() == reflect.Ptr && v.IsNil() { - result = "nil" + result = "" } else { panic(err) } } }() - switch v := value.(type) { - case time.Time: - return v.Format(timeFormat) - - case error: - return v.Error() - - case fmt.Stringer: - return v.String() - - default: - return v - } -} - -func formatJSONValue(value interface{}) interface{} { - value = formatShared(value) - switch value.(type) { - case int, int8, int16, int32, int64, float32, float64, uint, uint8, uint16, uint32, uint64, string: - return value - default: - return fmt.Sprintf("%+v", value) - } -} - -// formatValue formats a value for serialization -func formatLogfmtValue(value interface{}, term bool) string { - if value == nil { - return "nil" - } - switch v := value.(type) { case time.Time: // Performance optimization: No need for escaping since the provided @@ -375,8 +167,11 @@ func formatLogfmtValue(value interface{}, term bool) string { return escapeString(s.TerminalString()) } } - value = formatShared(value) switch v := value.(type) { + case error: + return escapeString(v.Error()) + case fmt.Stringer: + return escapeString(v.String()) case bool: return strconv.FormatBool(v) case float32: diff --git a/log/handler.go b/log/handler.go index 4a0cf578f6..ef1bcc1992 100644 --- a/log/handler.go +++ b/log/handler.go @@ -1,301 +1,25 @@ package log import ( + "context" "fmt" "io" - "net" - "os" + "math/big" "reflect" "sync" - "sync/atomic" + "time" - "github.com/go-stack/stack" + "github.com/holiman/uint256" + "golang.org/x/exp/slog" ) -// Handler defines where and how log records are written. -// A Logger prints its log records by writing to a Handler. -// Handlers are composable, providing you great flexibility in combining -// them to achieve the logging structure that suits your applications. -type Handler interface { - Log(r *Record) error -} - -// FuncHandler returns a Handler that logs records with the given -// function. -func FuncHandler(fn func(r *Record) error) Handler { - return funcHandler(fn) -} - -type funcHandler func(r *Record) error - -func (h funcHandler) Log(r *Record) error { - return h(r) -} - -// StreamHandler writes log records to an io.Writer -// with the given format. StreamHandler can be used -// to easily begin writing log records to other -// outputs. +// Lazy allows you to defer calculation of a logged value that is expensive +// to compute until it is certain that it must be evaluated with the given filters. // -// StreamHandler wraps itself with LazyHandler and SyncHandler -// to evaluate Lazy objects and perform safe concurrent writes. -func StreamHandler(wr io.Writer, fmtr Format) Handler { - h := FuncHandler(func(r *Record) error { - _, err := wr.Write(fmtr.Format(r)) - return err - }) - return LazyHandler(SyncHandler(h)) -} - -// SyncHandler can be wrapped around a handler to guarantee that -// only a single Log operation can proceed at a time. It's necessary -// for thread-safe concurrent writes. -func SyncHandler(h Handler) Handler { - var mu sync.Mutex - return FuncHandler(func(r *Record) error { - mu.Lock() - defer mu.Unlock() - - return h.Log(r) - }) -} - -// FileHandler returns a handler which writes log records to the give file -// using the given format. If the path -// already exists, FileHandler will append to the given file. If it does not, -// FileHandler will create the file with mode 0644. -func FileHandler(path string, fmtr Format) (Handler, error) { - f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) - if err != nil { - return nil, err - } - return closingHandler{f, StreamHandler(f, fmtr)}, nil -} - -// NetHandler opens a socket to the given address and writes records -// over the connection. -func NetHandler(network, addr string, fmtr Format) (Handler, error) { - conn, err := net.Dial(network, addr) - if err != nil { - return nil, err - } - - return closingHandler{conn, StreamHandler(conn, fmtr)}, nil -} - -// XXX: closingHandler is essentially unused at the moment -// it's meant for a future time when the Handler interface supports -// a possible Close() operation -type closingHandler struct { - io.WriteCloser - Handler -} - -func (h *closingHandler) Close() error { - return h.WriteCloser.Close() -} - -// CallerFileHandler returns a Handler that adds the line number and file of -// the calling function to the context with key "caller". -func CallerFileHandler(h Handler) Handler { - return FuncHandler(func(r *Record) error { - r.Ctx = append(r.Ctx, "caller", fmt.Sprint(r.Call)) - return h.Log(r) - }) -} - -// CallerFuncHandler returns a Handler that adds the calling function name to -// the context with key "fn". -func CallerFuncHandler(h Handler) Handler { - return FuncHandler(func(r *Record) error { - r.Ctx = append(r.Ctx, "fn", formatCall("%+n", r.Call)) - return h.Log(r) - }) -} - -// This function is here to please go vet on Go < 1.8. -func formatCall(format string, c stack.Call) string { - return fmt.Sprintf(format, c) -} - -// CallerStackHandler returns a Handler that adds a stack trace to the context -// with key "stack". The stack trace is formatted as a space separated list of -// call sites inside matching []'s. The most recent call site is listed first. -// Each call site is formatted according to format. See the documentation of -// package github.com/go-stack/stack for the list of supported formats. -func CallerStackHandler(format string, h Handler) Handler { - return FuncHandler(func(r *Record) error { - s := stack.Trace().TrimBelow(r.Call).TrimRuntime() - if len(s) > 0 { - r.Ctx = append(r.Ctx, "stack", fmt.Sprintf(format, s)) - } - return h.Log(r) - }) -} - -// FilterHandler returns a Handler that only writes records to the -// wrapped Handler if the given function evaluates true. For example, -// to only log records where the 'err' key is not nil: -// -// logger.SetHandler(FilterHandler(func(r *Record) bool { -// for i := 0; i < len(r.Ctx); i += 2 { -// if r.Ctx[i] == "err" { -// return r.Ctx[i+1] != nil -// } -// } -// return false -// }, h)) -func FilterHandler(fn func(r *Record) bool, h Handler) Handler { - return FuncHandler(func(r *Record) error { - if fn(r) { - return h.Log(r) - } - return nil - }) -} - -// MatchFilterHandler returns a Handler that only writes records -// to the wrapped Handler if the given key in the logged -// context matches the value. For example, to only log records -// from your ui package: -// -// log.MatchFilterHandler("pkg", "app/ui", log.StdoutHandler) -func MatchFilterHandler(key string, value interface{}, h Handler) Handler { - return FilterHandler(func(r *Record) (pass bool) { - switch key { - case r.KeyNames.Lvl: - return r.Lvl == value - case r.KeyNames.Time: - return r.Time == value - case r.KeyNames.Msg: - return r.Msg == value - } - - for i := 0; i < len(r.Ctx); i += 2 { - if r.Ctx[i] == key { - return r.Ctx[i+1] == value - } - } - return false - }, h) -} - -// LvlFilterHandler returns a Handler that only writes -// records which are less than the given verbosity -// level to the wrapped Handler. For example, to only -// log Error/Crit records: -// -// log.LvlFilterHandler(log.LvlError, log.StdoutHandler) -func LvlFilterHandler(maxLvl Lvl, h Handler) Handler { - return FilterHandler(func(r *Record) (pass bool) { - return r.Lvl <= maxLvl - }, h) -} - -// MultiHandler dispatches any write to each of its handlers. -// This is useful for writing different types of log information -// to different locations. For example, to log to a file and -// standard error: -// -// log.MultiHandler( -// log.Must.FileHandler("/var/log/app.log", log.LogfmtFormat()), -// log.StderrHandler) -func MultiHandler(hs ...Handler) Handler { - return FuncHandler(func(r *Record) error { - for _, h := range hs { - // what to do about failures? - h.Log(r) - } - return nil - }) -} - -// FailoverHandler writes all log records to the first handler -// specified, but will failover and write to the second handler if -// the first handler has failed, and so on for all handlers specified. -// For example you might want to log to a network socket, but failover -// to writing to a file if the network fails, and then to -// standard out if the file write fails: -// -// log.FailoverHandler( -// log.Must.NetHandler("tcp", ":9090", log.JSONFormat()), -// log.Must.FileHandler("/var/log/app.log", log.LogfmtFormat()), -// log.StdoutHandler) -// -// All writes that do not go to the first handler will add context with keys of -// the form "failover_err_{idx}" which explain the error encountered while -// trying to write to the handlers before them in the list. -func FailoverHandler(hs ...Handler) Handler { - return FuncHandler(func(r *Record) error { - var err error - for i, h := range hs { - err = h.Log(r) - if err == nil { - return nil - } - r.Ctx = append(r.Ctx, fmt.Sprintf("failover_err_%d", i), err) - } - - return err - }) -} - -// ChannelHandler writes all records to the given channel. -// It blocks if the channel is full. Useful for async processing -// of log messages, it's used by BufferedHandler. -func ChannelHandler(recs chan<- *Record) Handler { - return FuncHandler(func(r *Record) error { - recs <- r - return nil - }) -} - -// BufferedHandler writes all records to a buffered -// channel of the given size which flushes into the wrapped -// handler whenever it is available for writing. Since these -// writes happen asynchronously, all writes to a BufferedHandler -// never return an error and any errors from the wrapped handler are ignored. -func BufferedHandler(bufSize int, h Handler) Handler { - recs := make(chan *Record, bufSize) - go func() { - for m := range recs { - _ = h.Log(m) - } - }() - return ChannelHandler(recs) -} - -// LazyHandler writes all values to the wrapped handler after evaluating -// any lazy functions in the record's context. It is already wrapped -// around StreamHandler and SyslogHandler in this library, you'll only need -// it if you write your own Handler. -func LazyHandler(h Handler) Handler { - return FuncHandler(func(r *Record) error { - // go through the values (odd indices) and reassign - // the values of any lazy fn to the result of its execution - hadErr := false - for i := 1; i < len(r.Ctx); i += 2 { - lz, ok := r.Ctx[i].(Lazy) - if ok { - v, err := evaluateLazy(lz) - if err != nil { - hadErr = true - r.Ctx[i] = err - } else { - if cs, ok := v.(stack.CallStack); ok { - v = cs.TrimBelow(r.Call).TrimRuntime() - } - r.Ctx[i] = v - } - } - } - - if hadErr { - r.Ctx = append(r.Ctx, errorKey, "bad lazy") - } - - return h.Log(r) - }) +// You may wrap any function which takes no arguments to Lazy. It may return any +// number of values of any type. +type Lazy struct { + Fn interface{} } func evaluateLazy(lz Lazy) (interface{}, error) { @@ -325,51 +49,175 @@ func evaluateLazy(lz Lazy) (interface{}, error) { return values, nil } -// DiscardHandler reports success for all writes but does nothing. -// It is useful for dynamically disabling logging at runtime via -// a Logger's SetHandler method. -func DiscardHandler() Handler { - return FuncHandler(func(r *Record) error { - return nil +type discardHandler struct{} + +// DiscardHandler returns a no-op handler +func DiscardHandler() slog.Handler { + return &discardHandler{} +} + +func (h *discardHandler) Handle(_ context.Context, r slog.Record) error { + return nil +} + +func (h *discardHandler) Enabled(_ context.Context, level slog.Level) bool { + return false +} + +func (h *discardHandler) WithGroup(name string) slog.Handler { + panic("not implemented") +} + +func (h *discardHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &discardHandler{} +} + +type TerminalHandler struct { + mu sync.Mutex + wr io.Writer + lvl slog.Level + useColor bool + attrs []slog.Attr + // fieldPadding is a map with maximum field value lengths seen until now + // to allow padding log contexts in a bit smarter way. + fieldPadding map[string]int +} + +// NewTerminalHandler returns a handler which formats log records at all levels optimized for human readability on +// a terminal with color-coded level output and terser human friendly timestamp. +// This format should only be used for interactive programs or while developing. +// +// [LEVEL] [TIME] MESSAGE key=value key=value ... +// +// Example: +// +// [DBUG] [May 16 20:58:45] remove route ns=haproxy addr=127.0.0.1:50002 +func NewTerminalHandler(wr io.Writer, useColor bool) *TerminalHandler { + return NewTerminalHandlerWithLevel(wr, levelMaxVerbosity, useColor) +} + +// NewTerminalHandlerWithLevel returns the same handler as NewTerminalHandler but only outputs +// records which are less than or equal to the specified verbosity level. +func NewTerminalHandlerWithLevel(wr io.Writer, lvl slog.Level, useColor bool) *TerminalHandler { + return &TerminalHandler{ + wr: wr, + lvl: lvl, + useColor: useColor, + fieldPadding: make(map[string]int), + } +} + +func (h *TerminalHandler) Handle(_ context.Context, r slog.Record) error { + h.mu.Lock() + defer h.mu.Unlock() + h.wr.Write(h.TerminalFormat(r, h.useColor)) + return nil +} + +func (h *TerminalHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.lvl +} + +func (h *TerminalHandler) WithGroup(name string) slog.Handler { + panic("not implemented") +} + +func (h *TerminalHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &TerminalHandler{ + wr: h.wr, + lvl: h.lvl, + useColor: h.useColor, + attrs: append(h.attrs, attrs...), + fieldPadding: make(map[string]int), + } +} + +// ResetFieldPadding zeroes the field-padding for all attribute pairs. +func (t *TerminalHandler) ResetFieldPadding() { + t.mu.Lock() + t.fieldPadding = make(map[string]int) + t.mu.Unlock() +} + +type leveler struct{ minLevel slog.Level } + +func (l *leveler) Level() slog.Level { + return l.minLevel +} + +func JSONHandler(wr io.Writer) slog.Handler { + return slog.NewJSONHandler(wr, &slog.HandlerOptions{ + ReplaceAttr: builtinReplaceJSON, }) } -// Must provides the following Handler creation functions -// which instead of returning an error parameter only return a Handler -// and panic on failure: FileHandler, NetHandler, SyslogHandler, SyslogNetHandler -var Must muster +// LogfmtHandler returns a handler which prints records in logfmt format, an easy machine-parseable but human-readable +// format for key/value pairs. +// +// For more details see: http://godoc.org/github.com/kr/logfmt +func LogfmtHandler(wr io.Writer) slog.Handler { + return slog.NewTextHandler(wr, &slog.HandlerOptions{ + ReplaceAttr: builtinReplaceLogfmt, + }) +} -func must(h Handler, err error) Handler { - if err != nil { - panic(err) +// LogfmtHandlerWithLevel returns the same handler as LogfmtHandler but it only outputs +// records which are less than or equal to the specified verbosity level. +func LogfmtHandlerWithLevel(wr io.Writer, level slog.Level) slog.Handler { + return slog.NewTextHandler(wr, &slog.HandlerOptions{ + ReplaceAttr: builtinReplaceLogfmt, + Level: &leveler{level}, + }) +} + +func builtinReplaceLogfmt(_ []string, attr slog.Attr) slog.Attr { + return builtinReplace(nil, attr, true) +} + +func builtinReplaceJSON(_ []string, attr slog.Attr) slog.Attr { + return builtinReplace(nil, attr, false) +} + +func builtinReplace(_ []string, attr slog.Attr, logfmt bool) slog.Attr { + switch attr.Key { + case slog.TimeKey: + if attr.Value.Kind() == slog.KindTime { + if logfmt { + return slog.String("t", attr.Value.Time().Format(timeFormat)) + } else { + return slog.Attr{Key: "t", Value: attr.Value} + } + } + case slog.LevelKey: + if l, ok := attr.Value.Any().(slog.Level); ok { + attr = slog.Any("lvl", LevelString(l)) + return attr + } } - return h -} -type muster struct{} - -func (m muster) FileHandler(path string, fmtr Format) Handler { - return must(FileHandler(path, fmtr)) -} - -func (m muster) NetHandler(network, addr string, fmtr Format) Handler { - return must(NetHandler(network, addr, fmtr)) -} - -// swapHandler wraps another handler that may be swapped out -// dynamically at runtime in a thread-safe fashion. -type swapHandler struct { - handler atomic.Value -} - -func (h *swapHandler) Log(r *Record) error { - return (*h.handler.Load().(*Handler)).Log(r) -} - -func (h *swapHandler) Swap(newHandler Handler) { - h.handler.Store(&newHandler) -} - -func (h *swapHandler) Get() Handler { - return *h.handler.Load().(*Handler) + switch v := attr.Value.Any().(type) { + case time.Time: + if logfmt { + attr = slog.String(attr.Key, v.Format(timeFormat)) + } + case *big.Int: + if v == nil { + attr.Value = slog.StringValue("") + } else { + attr.Value = slog.StringValue(v.String()) + } + case *uint256.Int: + if v == nil { + attr.Value = slog.StringValue("") + } else { + attr.Value = slog.StringValue(v.Dec()) + } + case fmt.Stringer: + if v == nil || (reflect.ValueOf(v).Kind() == reflect.Pointer && reflect.ValueOf(v).IsNil()) { + attr.Value = slog.StringValue("") + } else { + attr.Value = slog.StringValue(v.String()) + } + } + return attr } diff --git a/log/handler_glog.go b/log/handler_glog.go index afca0808b3..fb1e03c5b5 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -17,6 +17,7 @@ package log import ( + "context" "errors" "fmt" "regexp" @@ -25,54 +26,47 @@ import ( "strings" "sync" "sync/atomic" + + "golang.org/x/exp/slog" ) // errVmoduleSyntax is returned when a user vmodule pattern is invalid. var errVmoduleSyntax = errors.New("expect comma-separated list of filename=N") -// errTraceSyntax is returned when a user backtrace pattern is invalid. -var errTraceSyntax = errors.New("expect file.go:234") - // GlogHandler is a log handler that mimics the filtering features of Google's // glog logger: setting global log levels; overriding with callsite pattern // matches; and requesting backtraces at certain positions. type GlogHandler struct { - origin Handler // The origin handler this wraps + origin slog.Handler // The origin handler this wraps - level atomic.Uint32 // Current log level, atomically accessible - override atomic.Bool // Flag whether overrides are used, atomically accessible - backtrace atomic.Bool // Flag whether backtrace location is set + level atomic.Int32 // Current log level, atomically accessible + override atomic.Bool // Flag whether overrides are used, atomically accessible - patterns []pattern // Current list of patterns to override with - siteCache map[uintptr]Lvl // Cache of callsite pattern evaluations - location string // file:line location where to do a stackdump at - lock sync.RWMutex // Lock protecting the override pattern list + patterns []pattern // Current list of patterns to override with + siteCache map[uintptr]slog.Level // Cache of callsite pattern evaluations + location string // file:line location where to do a stackdump at + lock sync.RWMutex // Lock protecting the override pattern list } // NewGlogHandler creates a new log handler with filtering functionality similar // to Google's glog logger. The returned handler implements Handler. -func NewGlogHandler(h Handler) *GlogHandler { +func NewGlogHandler(h slog.Handler) *GlogHandler { return &GlogHandler{ origin: h, } } -// SetHandler updates the handler to write records to the specified sub-handler. -func (h *GlogHandler) SetHandler(nh Handler) { - h.origin = nh -} - // pattern contains a filter for the Vmodule option, holding a verbosity level // and a file pattern to match. type pattern struct { pattern *regexp.Regexp - level Lvl + level slog.Level } // Verbosity sets the glog verbosity ceiling. The verbosity of individual packages // and source files can be raised using Vmodule. -func (h *GlogHandler) Verbosity(level Lvl) { - h.level.Store(uint32(level)) +func (h *GlogHandler) Verbosity(level slog.Level) { + h.level.Store(int32(level)) } // Vmodule sets the glog verbosity pattern. @@ -108,11 +102,13 @@ func (h *GlogHandler) Vmodule(ruleset string) error { return errVmoduleSyntax } // Parse the level and if correct, assemble the filter rule - level, err := strconv.Atoi(parts[1]) + l, err := strconv.Atoi(parts[1]) if err != nil { return errVmoduleSyntax } - if level <= 0 { + level := FromLegacyLevel(l) + + if level == LevelCrit { continue // Ignore. It's harmless but no point in paying the overhead. } // Compile the rule pattern into a regular expression @@ -130,107 +126,84 @@ func (h *GlogHandler) Vmodule(ruleset string) error { matcher = matcher + "$" re, _ := regexp.Compile(matcher) - filter = append(filter, pattern{re, Lvl(level)}) + filter = append(filter, pattern{re, level}) } // Swap out the vmodule pattern for the new filter system h.lock.Lock() defer h.lock.Unlock() h.patterns = filter - h.siteCache = make(map[uintptr]Lvl) + h.siteCache = make(map[uintptr]slog.Level) h.override.Store(len(filter) != 0) - // Enable location storage (globally) - if len(h.patterns) > 0 { - stackEnabled.Store(true) - } + return nil } -// BacktraceAt sets the glog backtrace location. When set to a file and line -// number holding a logging statement, a stack trace will be written to the Info -// log whenever execution hits that statement. -// -// Unlike with Vmodule, the ".go" must be present. -func (h *GlogHandler) BacktraceAt(location string) error { - // Ensure the backtrace location contains two non-empty elements - parts := strings.Split(location, ":") - if len(parts) != 2 { - return errTraceSyntax - } - parts[0] = strings.TrimSpace(parts[0]) - parts[1] = strings.TrimSpace(parts[1]) - if len(parts[0]) == 0 || len(parts[1]) == 0 { - return errTraceSyntax - } - // Ensure the .go prefix is present and the line is valid - if !strings.HasSuffix(parts[0], ".go") { - return errTraceSyntax - } - if _, err := strconv.Atoi(parts[1]); err != nil { - return errTraceSyntax - } - // All seems valid - h.lock.Lock() - defer h.lock.Unlock() +func (h *GlogHandler) Enabled(ctx context.Context, lvl slog.Level) bool { + // fast-track skipping logging if override not enabled and the provided verbosity is above configured + return h.override.Load() || slog.Level(h.level.Load()) <= lvl +} - h.location = location - h.backtrace.Store(len(location) > 0) - // Enable location storage (globally) - stackEnabled.Store(true) - return nil +func (h *GlogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + h.lock.RLock() + siteCache := make(map[uintptr]slog.Level) + for k, v := range h.siteCache { + siteCache[k] = v + } + h.lock.RUnlock() + + patterns := []pattern{} + patterns = append(patterns, h.patterns...) + + res := GlogHandler{ + origin: h.origin.WithAttrs(attrs), + patterns: patterns, + siteCache: siteCache, + location: h.location, + } + + res.level.Store(h.level.Load()) + res.override.Store(h.override.Load()) + return &res +} + +func (h *GlogHandler) WithGroup(name string) slog.Handler { + panic("not implemented") } // Log implements Handler.Log, filtering a log record through the global, local // and backtrace filters, finally emitting it if either allow it through. -func (h *GlogHandler) Log(r *Record) error { - // If backtracing is requested, check whether this is the callsite - if h.backtrace.Load() { - // Everything below here is slow. Although we could cache the call sites the - // same way as for vmodule, backtracing is so rare it's not worth the extra - // complexity. - h.lock.RLock() - match := h.location == r.Call.String() - h.lock.RUnlock() - - if match { - // Callsite matched, raise the log level to info and gather the stacks - r.Lvl = LvlInfo - - buf := make([]byte, 1024*1024) - buf = buf[:runtime.Stack(buf, true)] - r.Msg += "\n\n" + string(buf) - } - } +func (h *GlogHandler) Handle(_ context.Context, r slog.Record) error { // If the global log level allows, fast track logging - if h.level.Load() >= uint32(r.Lvl) { - return h.origin.Log(r) - } - // If no local overrides are present, fast track skipping - if !h.override.Load() { - return nil + if slog.Level(h.level.Load()) <= r.Level { + return h.origin.Handle(context.Background(), r) } + // Check callsite cache for previously calculated log levels h.lock.RLock() - lvl, ok := h.siteCache[r.Call.Frame().PC] + lvl, ok := h.siteCache[r.PC] h.lock.RUnlock() // If we didn't cache the callsite yet, calculate it if !ok { h.lock.Lock() + + fs := runtime.CallersFrames([]uintptr{r.PC}) + frame, _ := fs.Next() + for _, rule := range h.patterns { - if rule.pattern.MatchString(fmt.Sprintf("%+s", r.Call)) { - h.siteCache[r.Call.Frame().PC], lvl, ok = rule.level, rule.level, true - break + if rule.pattern.MatchString(fmt.Sprintf("%+s", frame.File)) { + h.siteCache[r.PC], lvl, ok = rule.level, rule.level, true } } // If no rule matched, remember to drop log the next time if !ok { - h.siteCache[r.Call.Frame().PC] = 0 + h.siteCache[r.PC] = 0 } h.lock.Unlock() } - if lvl >= r.Lvl { - return h.origin.Log(r) + if lvl <= r.Level { + return h.origin.Handle(context.Background(), r) } return nil } diff --git a/log/logger.go b/log/logger.go index 42e7e375d0..3e227745ad 100644 --- a/log/logger.go +++ b/log/logger.go @@ -1,294 +1,222 @@ package log import ( - "fmt" + "context" + "math" "os" + "runtime" "time" - "github.com/go-stack/stack" + "golang.org/x/exp/slog" ) -const timeKey = "t" -const lvlKey = "lvl" -const msgKey = "msg" -const ctxKey = "ctx" -const errorKey = "LOG15_ERROR" -const skipLevel = 2 - -type Lvl int +const errorKey = "LOG_ERROR" const ( - LvlCrit Lvl = iota - LvlError - LvlWarn - LvlInfo - LvlDebug - LvlTrace + legacyLevelCrit = iota + legacyLevelError + legacyLevelWarn + legacyLevelInfo + legacyLevelDebug + legacyLevelTrace ) -// AlignedString returns a 5-character string containing the name of a Lvl. -func (l Lvl) AlignedString() string { +const ( + levelMaxVerbosity slog.Level = math.MinInt + LevelTrace slog.Level = -8 + LevelDebug = slog.LevelDebug + LevelInfo = slog.LevelInfo + LevelWarn = slog.LevelWarn + LevelError = slog.LevelError + LevelCrit slog.Level = 12 + + // for backward-compatibility + LvlTrace = LevelTrace + LvlInfo = LevelInfo + LvlDebug = LevelDebug +) + +// convert from old Geth verbosity level constants +// to levels defined by slog +func FromLegacyLevel(lvl int) slog.Level { + switch lvl { + case legacyLevelCrit: + return LevelCrit + case legacyLevelError: + return slog.LevelError + case legacyLevelWarn: + return slog.LevelWarn + case legacyLevelInfo: + return slog.LevelInfo + case legacyLevelDebug: + return slog.LevelDebug + case legacyLevelTrace: + return LevelTrace + default: + break + } + + // TODO: should we allow use of custom levels or force them to match existing max/min if they fall outside the range as I am doing here? + if lvl > legacyLevelTrace { + return LevelTrace + } + return LevelCrit +} + +// LevelAlignedString returns a 5-character string containing the name of a Lvl. +func LevelAlignedString(l slog.Level) string { switch l { - case LvlTrace: + case LevelTrace: return "TRACE" - case LvlDebug: + case slog.LevelDebug: return "DEBUG" - case LvlInfo: + case slog.LevelInfo: return "INFO " - case LvlWarn: + case slog.LevelWarn: return "WARN " - case LvlError: + case slog.LevelError: return "ERROR" - case LvlCrit: + case LevelCrit: return "CRIT " default: - panic("bad level") + return "unknown level" } } -// String returns the name of a Lvl. -func (l Lvl) String() string { +// LevelString returns a 5-character string containing the name of a Lvl. +func LevelString(l slog.Level) string { switch l { - case LvlTrace: - return "trce" - case LvlDebug: - return "dbug" - case LvlInfo: + case LevelTrace: + return "trace" + case slog.LevelDebug: + return "debug" + case slog.LevelInfo: return "info" - case LvlWarn: + case slog.LevelWarn: return "warn" - case LvlError: + case slog.LevelError: return "eror" - case LvlCrit: + case LevelCrit: return "crit" default: - panic("bad level") + return "unknown" } } -// LvlFromString returns the appropriate Lvl from a string name. -// Useful for parsing command line args and configuration files. -func LvlFromString(lvlString string) (Lvl, error) { - switch lvlString { - case "trace", "trce": - return LvlTrace, nil - case "debug", "dbug": - return LvlDebug, nil - case "info": - return LvlInfo, nil - case "warn": - return LvlWarn, nil - case "error", "eror": - return LvlError, nil - case "crit": - return LvlCrit, nil - default: - return LvlDebug, fmt.Errorf("unknown level: %v", lvlString) - } -} - -// A Record is what a Logger asks its handler to write -type Record struct { - Time time.Time - Lvl Lvl - Msg string - Ctx []interface{} - Call stack.Call - KeyNames RecordKeyNames -} - -// RecordKeyNames gets stored in a Record when the write function is executed. -type RecordKeyNames struct { - Time string - Msg string - Lvl string - Ctx string -} - // A Logger writes key/value pairs to a Handler type Logger interface { - // New returns a new Logger that has this logger's context plus the given context + // With returns a new Logger that has this logger's attributes plus the given attributes + With(ctx ...interface{}) Logger + + // With returns a new Logger that has this logger's attributes plus the given attributes. Identical to 'With'. New(ctx ...interface{}) Logger - // GetHandler gets the handler associated with the logger. - GetHandler() Handler + // Log logs a message at the specified level with context key/value pairs + Log(level slog.Level, msg string, ctx ...interface{}) - // SetHandler updates the logger to write records to the specified handler. - SetHandler(h Handler) - - // Log a message at the trace level with context key/value pairs - // - // # Usage - // - // log.Trace("msg") - // log.Trace("msg", "key1", val1) - // log.Trace("msg", "key1", val1, "key2", val2) + // Trace log a message at the trace level with context key/value pairs Trace(msg string, ctx ...interface{}) - // Log a message at the debug level with context key/value pairs - // - // # Usage Examples - // - // log.Debug("msg") - // log.Debug("msg", "key1", val1) - // log.Debug("msg", "key1", val1, "key2", val2) + // Debug logs a message at the debug level with context key/value pairs Debug(msg string, ctx ...interface{}) - // Log a message at the info level with context key/value pairs - // - // # Usage Examples - // - // log.Info("msg") - // log.Info("msg", "key1", val1) - // log.Info("msg", "key1", val1, "key2", val2) + // Info logs a message at the info level with context key/value pairs Info(msg string, ctx ...interface{}) - // Log a message at the warn level with context key/value pairs - // - // # Usage Examples - // - // log.Warn("msg") - // log.Warn("msg", "key1", val1) - // log.Warn("msg", "key1", val1, "key2", val2) + // Warn logs a message at the warn level with context key/value pairs Warn(msg string, ctx ...interface{}) - // Log a message at the error level with context key/value pairs - // - // # Usage Examples - // - // log.Error("msg") - // log.Error("msg", "key1", val1) - // log.Error("msg", "key1", val1, "key2", val2) + // Error logs a message at the error level with context key/value pairs Error(msg string, ctx ...interface{}) - // Log a message at the crit level with context key/value pairs, and then exit. - // - // # Usage Examples - // - // log.Crit("msg") - // log.Crit("msg", "key1", val1) - // log.Crit("msg", "key1", val1, "key2", val2) + // Crit logs a message at the crit level with context key/value pairs, and exits Crit(msg string, ctx ...interface{}) + + // Write logs a message at the specified level + Write(level slog.Level, msg string, attrs ...any) } type logger struct { - ctx []interface{} - h *swapHandler + inner *slog.Logger } -func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) { - record := &Record{ - Time: time.Now(), - Lvl: lvl, - Msg: msg, - Ctx: newContext(l.ctx, ctx), - KeyNames: RecordKeyNames{ - Time: timeKey, - Msg: msgKey, - Lvl: lvlKey, - Ctx: ctxKey, - }, +// NewLogger returns a logger with the specified handler set +func NewLogger(h slog.Handler) Logger { + return &logger{ + slog.New(h), } - if stackEnabled.Load() { - record.Call = stack.Caller(skip) +} + +// write logs a message at the specified level: +func (l *logger) Write(level slog.Level, msg string, attrs ...any) { + if !l.inner.Enabled(context.Background(), level) { + return } - l.h.Log(record) -} -func (l *logger) New(ctx ...interface{}) Logger { - child := &logger{newContext(l.ctx, ctx), new(swapHandler)} - child.SetHandler(l.h) - return child -} + var pcs [1]uintptr + runtime.Callers(3, pcs[:]) -func newContext(prefix []interface{}, suffix []interface{}) []interface{} { - normalizedSuffix := normalize(suffix) - newCtx := make([]interface{}, len(prefix)+len(normalizedSuffix)) - n := copy(newCtx, prefix) - copy(newCtx[n:], normalizedSuffix) - return newCtx -} + if len(attrs)%2 != 0 { + attrs = append(attrs, nil, errorKey, "Normalized odd number of arguments by adding nil") + } -func (l *logger) Trace(msg string, ctx ...interface{}) { - l.write(msg, LvlTrace, ctx, skipLevel) -} - -func (l *logger) Debug(msg string, ctx ...interface{}) { - l.write(msg, LvlDebug, ctx, skipLevel) -} - -func (l *logger) Info(msg string, ctx ...interface{}) { - l.write(msg, LvlInfo, ctx, skipLevel) -} - -func (l *logger) Warn(msg string, ctx ...interface{}) { - l.write(msg, LvlWarn, ctx, skipLevel) -} - -func (l *logger) Error(msg string, ctx ...interface{}) { - l.write(msg, LvlError, ctx, skipLevel) -} - -func (l *logger) Crit(msg string, ctx ...interface{}) { - l.write(msg, LvlCrit, ctx, skipLevel) - os.Exit(1) -} - -func (l *logger) GetHandler() Handler { - return l.h.Get() -} - -func (l *logger) SetHandler(h Handler) { - l.h.Swap(h) -} - -func normalize(ctx []interface{}) []interface{} { - // if the caller passed a Ctx object, then expand it - if len(ctx) == 1 { - if ctxMap, ok := ctx[0].(Ctx); ok { - ctx = ctxMap.toArray() + // evaluate lazy values + var hadErr bool + for i := 1; i < len(attrs); i += 2 { + lz, ok := attrs[i].(Lazy) + if ok { + v, err := evaluateLazy(lz) + if err != nil { + hadErr = true + attrs[i] = err + } else { + attrs[i] = v + } } } - // ctx needs to be even because it's a series of key/value pairs - // no one wants to check for errors on logging functions, - // so instead of erroring on bad input, we'll just make sure - // that things are the right length and users can fix bugs - // when they see the output looks wrong - if len(ctx)%2 != 0 { - ctx = append(ctx, nil, errorKey, "Normalized odd number of arguments by adding nil") + if hadErr { + attrs = append(attrs, errorKey, "bad lazy") } - return ctx + r := slog.NewRecord(time.Now(), level, msg, pcs[0]) + r.Add(attrs...) + l.inner.Handler().Handle(context.Background(), r) } -// Lazy allows you to defer calculation of a logged value that is expensive -// to compute until it is certain that it must be evaluated with the given filters. -// -// Lazy may also be used in conjunction with a Logger's New() function -// to generate a child logger which always reports the current value of changing -// state. -// -// You may wrap any function which takes no arguments to Lazy. It may return any -// number of values of any type. -type Lazy struct { - Fn interface{} +func (l *logger) Log(level slog.Level, msg string, attrs ...any) { + l.Write(level, msg, attrs...) } -// Ctx is a map of key/value pairs to pass as context to a log function -// Use this only if you really need greater safety around the arguments you pass -// to the logging functions. -type Ctx map[string]interface{} - -func (c Ctx) toArray() []interface{} { - arr := make([]interface{}, len(c)*2) - - i := 0 - for k, v := range c { - arr[i] = k - arr[i+1] = v - i += 2 - } - - return arr +func (l *logger) With(ctx ...interface{}) Logger { + return &logger{l.inner.With(ctx...)} +} + +func (l *logger) New(ctx ...interface{}) Logger { + return l.With(ctx...) +} + +func (l *logger) Trace(msg string, ctx ...interface{}) { + l.Write(LevelTrace, msg, ctx...) +} + +func (l *logger) Debug(msg string, ctx ...interface{}) { + l.Write(slog.LevelDebug, msg, ctx...) +} + +func (l *logger) Info(msg string, ctx ...interface{}) { + l.Write(slog.LevelInfo, msg, ctx...) +} + +func (l *logger) Warn(msg string, ctx ...any) { + l.Write(slog.LevelWarn, msg, ctx...) +} + +func (l *logger) Error(msg string, ctx ...interface{}) { + l.Write(slog.LevelError, msg, ctx...) +} + +func (l *logger) Crit(msg string, ctx ...interface{}) { + l.Write(LevelCrit, msg, ctx...) + os.Exit(1) } diff --git a/log/logger_test.go b/log/logger_test.go index 2e59b3fdf0..fca1f1680f 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -5,48 +5,18 @@ import ( "os" "strings" "testing" -) -// TestLoggingWithTrace checks that if BackTraceAt is set, then the -// gloghandler is capable of spitting out a stacktrace -func TestLoggingWithTrace(t *testing.T) { - defer stackEnabled.Store(stackEnabled.Load()) - out := new(bytes.Buffer) - logger := New() - { - glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false))) - glog.Verbosity(LvlTrace) - if err := glog.BacktraceAt("logger_test.go:24"); err != nil { - t.Fatal(err) - } - logger.SetHandler(glog) - } - logger.Trace("a message", "foo", "bar") // Will be bumped to INFO - have := out.String() - if !strings.HasPrefix(have, "INFO") { - t.Fatalf("backtraceat should bump level to info: %s", have) - } - // The timestamp is locale-dependent, so we want to trim that off - // "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..." - have = strings.Split(have, "]")[1] - wantPrefix := " a message\n\ngoroutine" - if !strings.HasPrefix(have, wantPrefix) { - t.Errorf("\nhave: %q\nwant: %q\n", have, wantPrefix) - } -} + "golang.org/x/exp/slog" +) // TestLoggingWithVmodule checks that vmodule works. func TestLoggingWithVmodule(t *testing.T) { - defer stackEnabled.Store(stackEnabled.Load()) out := new(bytes.Buffer) - logger := New() - { - glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false))) - glog.Verbosity(LvlCrit) - logger.SetHandler(glog) - logger.Warn("This should not be seen", "ignored", "true") - glog.Vmodule("logger_test.go=5") - } + glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false)) + glog.Verbosity(LevelCrit) + logger := NewLogger(glog) + logger.Warn("This should not be seen", "ignored", "true") + glog.Vmodule("logger_test.go=5") logger.Trace("a message", "foo", "bar") have := out.String() // The timestamp is locale-dependent, so we want to trim that off @@ -58,8 +28,24 @@ func TestLoggingWithVmodule(t *testing.T) { } } +func TestTerminalHandlerWithAttrs(t *testing.T) { + out := new(bytes.Buffer) + glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false).WithAttrs([]slog.Attr{slog.String("baz", "bat")})) + glog.Verbosity(LevelTrace) + logger := NewLogger(glog) + logger.Trace("a message", "foo", "bar") + have := out.String() + // The timestamp is locale-dependent, so we want to trim that off + // "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..." + have = strings.Split(have, "]")[1] + want := " a message baz=bat foo=bar\n" + if have != want { + t.Errorf("\nhave: %q\nwant: %q\n", have, want) + } +} + func BenchmarkTraceLogging(b *testing.B) { - Root().SetHandler(LvlFilterHandler(LvlInfo, StreamHandler(os.Stderr, TerminalFormat(true)))) + SetDefault(NewLogger(NewTerminalHandler(os.Stderr, true))) b.ResetTimer() for i := 0; i < b.N; i++ { Trace("a message", "v", i) diff --git a/log/root.go b/log/root.go index 5a41723c3e..71040fff47 100644 --- a/log/root.go +++ b/log/root.go @@ -2,31 +2,33 @@ package log import ( "os" + "sync/atomic" + + "golang.org/x/exp/slog" ) -var ( - root = &logger{[]interface{}{}, new(swapHandler)} - StdoutHandler = StreamHandler(os.Stdout, LogfmtFormat()) - StderrHandler = StreamHandler(os.Stderr, LogfmtFormat()) -) +var root atomic.Value func init() { - root.SetHandler(DiscardHandler()) + defaultLogger := &logger{slog.New(DiscardHandler())} + SetDefault(defaultLogger) } -// New returns a new logger with the given context. -// New is a convenient alias for Root().New -func New(ctx ...interface{}) Logger { - return root.New(ctx...) +// SetDefault sets the default global logger +func SetDefault(l Logger) { + root.Store(l) + if lg, ok := l.(*logger); ok { + slog.SetDefault(lg.inner) + } } // Root returns the root logger func Root() Logger { - return root + return root.Load().(Logger) } // The following functions bypass the exported logger methods (logger.Debug, -// etc.) to keep the call depth the same for all paths to logger.write so +// etc.) to keep the call depth the same for all paths to logger.Write so // runtime.Caller(2) always refers to the call site in client code. // Trace is a convenient alias for Root().Trace @@ -39,7 +41,7 @@ func Root() Logger { // log.Trace("msg", "key1", val1) // log.Trace("msg", "key1", val1, "key2", val2) func Trace(msg string, ctx ...interface{}) { - root.write(msg, LvlTrace, ctx, skipLevel) + Root().Write(LevelTrace, msg, ctx...) } // Debug is a convenient alias for Root().Debug @@ -52,7 +54,7 @@ func Trace(msg string, ctx ...interface{}) { // log.Debug("msg", "key1", val1) // log.Debug("msg", "key1", val1, "key2", val2) func Debug(msg string, ctx ...interface{}) { - root.write(msg, LvlDebug, ctx, skipLevel) + Root().Write(slog.LevelDebug, msg, ctx...) } // Info is a convenient alias for Root().Info @@ -65,7 +67,7 @@ func Debug(msg string, ctx ...interface{}) { // log.Info("msg", "key1", val1) // log.Info("msg", "key1", val1, "key2", val2) func Info(msg string, ctx ...interface{}) { - root.write(msg, LvlInfo, ctx, skipLevel) + Root().Write(slog.LevelInfo, msg, ctx...) } // Warn is a convenient alias for Root().Warn @@ -78,7 +80,7 @@ func Info(msg string, ctx ...interface{}) { // log.Warn("msg", "key1", val1) // log.Warn("msg", "key1", val1, "key2", val2) func Warn(msg string, ctx ...interface{}) { - root.write(msg, LvlWarn, ctx, skipLevel) + Root().Write(slog.LevelWarn, msg, ctx...) } // Error is a convenient alias for Root().Error @@ -91,7 +93,7 @@ func Warn(msg string, ctx ...interface{}) { // log.Error("msg", "key1", val1) // log.Error("msg", "key1", val1, "key2", val2) func Error(msg string, ctx ...interface{}) { - root.write(msg, LvlError, ctx, skipLevel) + Root().Write(slog.LevelError, msg, ctx...) } // Crit is a convenient alias for Root().Crit @@ -104,15 +106,12 @@ func Error(msg string, ctx ...interface{}) { // log.Crit("msg", "key1", val1) // log.Crit("msg", "key1", val1, "key2", val2) func Crit(msg string, ctx ...interface{}) { - root.write(msg, LvlCrit, ctx, skipLevel) + Root().Write(LevelCrit, msg, ctx...) os.Exit(1) } -// Output is a convenient alias for write, allowing for the modification of -// the calldepth (number of stack frames to skip). -// calldepth influences the reported line number of the log message. -// A calldepth of zero reports the immediate caller of Output. -// Non-zero calldepth skips as many stack frames. -func Output(msg string, lvl Lvl, calldepth int, ctx ...interface{}) { - root.write(msg, lvl, ctx, calldepth+skipLevel) +// New returns a new logger with the given context. +// New is a convenient alias for Root().New +func New(ctx ...interface{}) Logger { + return Root().With(ctx...) } diff --git a/log/syslog.go b/log/syslog.go deleted file mode 100644 index 451d831b6d..0000000000 --- a/log/syslog.go +++ /dev/null @@ -1,58 +0,0 @@ -//go:build !windows && !plan9 -// +build !windows,!plan9 - -package log - -import ( - "log/syslog" - "strings" -) - -// SyslogHandler opens a connection to the system syslog daemon by calling -// syslog.New and writes all records to it. -func SyslogHandler(priority syslog.Priority, tag string, fmtr Format) (Handler, error) { - wr, err := syslog.New(priority, tag) - return sharedSyslog(fmtr, wr, err) -} - -// SyslogNetHandler opens a connection to a log daemon over the network and writes -// all log records to it. -func SyslogNetHandler(net, addr string, priority syslog.Priority, tag string, fmtr Format) (Handler, error) { - wr, err := syslog.Dial(net, addr, priority, tag) - return sharedSyslog(fmtr, wr, err) -} - -func sharedSyslog(fmtr Format, sysWr *syslog.Writer, err error) (Handler, error) { - if err != nil { - return nil, err - } - h := FuncHandler(func(r *Record) error { - var syslogFn = sysWr.Info - switch r.Lvl { - case LvlCrit: - syslogFn = sysWr.Crit - case LvlError: - syslogFn = sysWr.Err - case LvlWarn: - syslogFn = sysWr.Warning - case LvlInfo: - syslogFn = sysWr.Info - case LvlDebug: - syslogFn = sysWr.Debug - case LvlTrace: - syslogFn = func(m string) error { return nil } // There's no syslog level for trace - } - - s := strings.TrimSpace(string(fmtr.Format(r))) - return syslogFn(s) - }) - return LazyHandler(&closingHandler{sysWr, h}), nil -} - -func (m muster) SyslogHandler(priority syslog.Priority, tag string, fmtr Format) Handler { - return must(SyslogHandler(priority, tag, fmtr)) -} - -func (m muster) SyslogNetHandler(net, addr string, priority syslog.Priority, tag string, fmtr Format) Handler { - return must(SyslogNetHandler(net, addr, priority, tag, fmtr)) -} diff --git a/miner/stress/clique/main.go b/miner/stress/clique/main.go index 7b29e63dfc..13336cd83c 100644 --- a/miner/stress/clique/main.go +++ b/miner/stress/clique/main.go @@ -45,7 +45,7 @@ import ( ) func main() { - log.Root().SetHandler(log.LvlFilterHandler(log.LvlInfo, log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true))) fdlimit.Raise(2048) // Generate a batch of accounts to seal and fund with diff --git a/p2p/discover/v4_udp_test.go b/p2p/discover/v4_udp_test.go index 5add9cefa1..53ecb1bc6e 100644 --- a/p2p/discover/v4_udp_test.go +++ b/p2p/discover/v4_udp_test.go @@ -557,12 +557,7 @@ func startLocalhostV4(t *testing.T, cfg Config) *UDPv4 { // Prefix logs with node ID. lprefix := fmt.Sprintf("(%s)", ln.ID().TerminalString()) - lfmt := log.TerminalFormat(false) - cfg.Log = testlog.Logger(t, log.LvlTrace) - cfg.Log.SetHandler(log.FuncHandler(func(r *log.Record) error { - t.Logf("%s %s", lprefix, lfmt.Format(r)) - return nil - })) + cfg.Log = testlog.Logger(t, log.LevelTrace).With("node-id", lprefix) // Listen. socket, err := net.ListenUDP("udp4", &net.UDPAddr{IP: net.IP{127, 0, 0, 1}}) diff --git a/p2p/discover/v5_udp_test.go b/p2p/discover/v5_udp_test.go index 880b71a991..18d8aeac6d 100644 --- a/p2p/discover/v5_udp_test.go +++ b/p2p/discover/v5_udp_test.go @@ -79,12 +79,7 @@ func startLocalhostV5(t *testing.T, cfg Config) *UDPv5 { // Prefix logs with node ID. lprefix := fmt.Sprintf("(%s)", ln.ID().TerminalString()) - lfmt := log.TerminalFormat(false) - cfg.Log = testlog.Logger(t, log.LvlTrace) - cfg.Log.SetHandler(log.FuncHandler(func(r *log.Record) error { - t.Logf("%s %s", lprefix, lfmt.Format(r)) - return nil - })) + cfg.Log = testlog.Logger(t, log.LevelTrace).With("node-id", lprefix) // Listen. socket, err := net.ListenUDP("udp4", &net.UDPAddr{IP: net.IP{127, 0, 0, 1}}) diff --git a/p2p/simulations/adapters/exec.go b/p2p/simulations/adapters/exec.go index 5ac3379393..63cc4936c1 100644 --- a/p2p/simulations/adapters/exec.go +++ b/p2p/simulations/adapters/exec.go @@ -41,6 +41,7 @@ import ( "github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/rpc" "github.com/gorilla/websocket" + "golang.org/x/exp/slog" ) func init() { @@ -375,9 +376,11 @@ type execNodeConfig struct { func initLogging() { // Initialize the logging by default first. - glogger := log.NewGlogHandler(log.StreamHandler(os.Stderr, log.LogfmtFormat())) - glogger.Verbosity(log.LvlInfo) - log.Root().SetHandler(glogger) + var innerHandler slog.Handler + innerHandler = slog.NewTextHandler(os.Stderr, nil) + glogger := log.NewGlogHandler(innerHandler) + glogger.Verbosity(log.LevelInfo) + log.SetDefault(log.NewLogger(glogger)) confEnv := os.Getenv(envNodeConfig) if confEnv == "" { @@ -395,14 +398,15 @@ func initLogging() { } writer = logWriter } - var verbosity = log.LvlInfo - if conf.Node.LogVerbosity <= log.LvlTrace && conf.Node.LogVerbosity >= log.LvlCrit { - verbosity = conf.Node.LogVerbosity + var verbosity = log.LevelInfo + if conf.Node.LogVerbosity <= log.LevelTrace && conf.Node.LogVerbosity >= log.LevelCrit { + verbosity = log.FromLegacyLevel(int(conf.Node.LogVerbosity)) } // Reinitialize the logger - glogger = log.NewGlogHandler(log.StreamHandler(writer, log.TerminalFormat(true))) + innerHandler = log.NewTerminalHandler(writer, true) + glogger = log.NewGlogHandler(innerHandler) glogger.Verbosity(verbosity) - log.Root().SetHandler(glogger) + log.SetDefault(log.NewLogger(glogger)) } // execP2PNode starts a simulation node when the current binary is executed with diff --git a/p2p/simulations/adapters/types.go b/p2p/simulations/adapters/types.go index 098759599c..fb8463d221 100644 --- a/p2p/simulations/adapters/types.go +++ b/p2p/simulations/adapters/types.go @@ -34,6 +34,7 @@ import ( "github.com/ethereum/go-ethereum/p2p/enr" "github.com/ethereum/go-ethereum/rpc" "github.com/gorilla/websocket" + "golang.org/x/exp/slog" ) // Node represents a node in a simulation network which is created by a @@ -129,7 +130,7 @@ type NodeConfig struct { // LogVerbosity is the log verbosity of the p2p node at runtime. // // The default verbosity is INFO. - LogVerbosity log.Lvl + LogVerbosity slog.Level } // nodeConfigJSON is used to encode and decode NodeConfig as JSON by encoding @@ -197,7 +198,7 @@ func (n *NodeConfig) UnmarshalJSON(data []byte) error { n.Port = confJSON.Port n.EnableMsgEvents = confJSON.EnableMsgEvents n.LogFile = confJSON.LogFile - n.LogVerbosity = log.Lvl(confJSON.LogVerbosity) + n.LogVerbosity = slog.Level(confJSON.LogVerbosity) return nil } diff --git a/p2p/simulations/examples/ping-pong.go b/p2p/simulations/examples/ping-pong.go index f6cf5113a6..70b35ad777 100644 --- a/p2p/simulations/examples/ping-pong.go +++ b/p2p/simulations/examples/ping-pong.go @@ -41,7 +41,7 @@ func main() { flag.Parse() // set the log level to Trace - log.Root().SetHandler(log.LvlFilterHandler(log.LvlTrace, log.StreamHandler(os.Stderr, log.TerminalFormat(false)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelTrace, false))) // register a single ping-pong service services := map[string]adapters.LifecycleConstructor{ diff --git a/p2p/simulations/http_test.go b/p2p/simulations/http_test.go index 05e43238ab..c53a49797b 100644 --- a/p2p/simulations/http_test.go +++ b/p2p/simulations/http_test.go @@ -37,14 +37,14 @@ import ( "github.com/ethereum/go-ethereum/p2p/simulations/adapters" "github.com/ethereum/go-ethereum/rpc" "github.com/mattn/go-colorable" + "golang.org/x/exp/slog" ) func TestMain(m *testing.M) { loglevel := flag.Int("loglevel", 2, "verbosity of logs") flag.Parse() - log.PrintOrigins(true) - log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(*loglevel), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(colorable.NewColorableStderr(), slog.Level(*loglevel), true))) os.Exit(m.Run()) } diff --git a/signer/core/auditlog.go b/signer/core/auditlog.go index a0b292bf71..d2207c9eb8 100644 --- a/signer/core/auditlog.go +++ b/signer/core/auditlog.go @@ -19,12 +19,14 @@ package core import ( "context" "encoding/json" + "os" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/internal/ethapi" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/signer/core/apitypes" + "golang.org/x/exp/slog" ) type AuditLogger struct { @@ -113,12 +115,13 @@ func (l *AuditLogger) Version(ctx context.Context) (string, error) { } func NewAuditLogger(path string, api ExternalAPI) (*AuditLogger, error) { - l := log.New("api", "signer") - handler, err := log.FileHandler(path, log.LogfmtFormat()) + f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) if err != nil { return nil, err } - l.SetHandler(handler) + + handler := slog.NewTextHandler(f, nil) + l := log.NewLogger(handler).With("api", "signer") l.Info("Configured", "audit log", path) return &AuditLogger{l, api}, nil } diff --git a/signer/storage/aes_gcm_storage_test.go b/signer/storage/aes_gcm_storage_test.go index 74d407e431..a223b1a6b4 100644 --- a/signer/storage/aes_gcm_storage_test.go +++ b/signer/storage/aes_gcm_storage_test.go @@ -26,6 +26,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/log" "github.com/mattn/go-colorable" + "golang.org/x/exp/slog" ) func TestEncryption(t *testing.T) { @@ -92,7 +93,7 @@ func TestFileStorage(t *testing.T) { } func TestEnd2End(t *testing.T) { t.Parallel() - log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(3), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(colorable.NewColorableStderr(), slog.LevelInfo, true))) d := t.TempDir() @@ -115,7 +116,7 @@ func TestSwappedKeys(t *testing.T) { t.Parallel() // It should not be possible to swap the keys/values, so that // K1:V1, K2:V2 can be swapped into K1:V2, K2:V1 - log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(3), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(colorable.NewColorableStderr(), slog.LevelInfo, true))) d := t.TempDir()