From 928246416a9e267c3121fa491f07054ff3b95341 Mon Sep 17 00:00:00 2001 From: Jared Wasinger Date: Tue, 7 Nov 2023 21:28:19 +0800 Subject: [PATCH] all: replace log15 with slog --- cmd/abigen/main.go | 2 +- cmd/bootnode/main.go | 9 +- cmd/clef/main.go | 3 +- cmd/devp2p/runtest.go | 2 +- cmd/evm/blockrunner.go | 1 - cmd/evm/internal/t8ntool/block.go | 8 +- cmd/evm/internal/t8ntool/transaction.go | 8 +- cmd/evm/internal/t8ntool/transition.go | 8 +- cmd/faucet/faucet.go | 4 +- 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 +- eth/protocols/snap/sync.go | 10 +- internal/debug/api.go | 9 +- internal/debug/flags.go | 113 +++-- internal/testlog/testlog.go | 101 +++-- les/api_test.go | 5 +- log/CONTRIBUTORS | 11 - log/LICENSE | 13 - log/README.md | 77 ---- log/README_ETHEREUM.md | 5 - log/doc.go | 327 -------------- log/format.go | 285 +++--------- log/handler.go | 551 ++++++++++-------------- log/handler_glog.go | 148 +++---- log/logger.go | 380 +++++++--------- log/logger_test.go | 48 +-- log/root.go | 46 +- log/syslog.go | 58 --- miner/stress/clique/main.go | 2 +- node/rpcstack_test.go | 2 +- p2p/dial_test.go | 2 +- p2p/discover/v4_udp_test.go | 15 +- p2p/discover/v5_udp_test.go | 14 +- p2p/dnsdisc/client_test.go | 16 +- p2p/peer.go | 2 +- p2p/server.go | 2 +- p2p/server_nat_test.go | 2 +- p2p/server_test.go | 14 +- p2p/simulations/adapters/exec.go | 20 +- p2p/simulations/adapters/types.go | 7 +- p2p/simulations/examples/ping-pong.go | 4 +- p2p/simulations/http_test.go | 4 +- rpc/handler.go | 2 +- signer/core/auditlog.go | 10 +- signer/storage/aes_gcm_storage_test.go | 6 +- 47 files changed, 778 insertions(+), 1596 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..cf206bb54b 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.TerminalHandlerWithLevel(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..dc3b0f97ce 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() { @@ -44,7 +45,7 @@ func main() { natdesc = flag.String("nat", "none", "port mapping mechanism (any|none|upnp|pmp|pmp:|extip:)") netrestrict = flag.String("netrestrict", "", "restrict network communication to the given IP networks (CIDR masks)") runv5 = flag.Bool("v5", false, "run a v5 topic discovery bootnode") - verbosity = flag.Int("verbosity", int(log.LvlInfo), "log verbosity (0-5)") + verbosity = flag.Int("verbosity", int(log.LevelInfo), "log verbosity (0-5)") vmodule = flag.String("vmodule", "", "log verbosity pattern") nodeKey *ecdsa.PrivateKey @@ -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.TerminalHandler(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 06a8cd7ab7..b1328a3fd6 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.TerminalHandlerWithLevel(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/blockrunner.go b/cmd/evm/blockrunner.go index ff65574586..b3a2f46142 100644 --- a/cmd/evm/blockrunner.go +++ b/cmd/evm/blockrunner.go @@ -49,7 +49,6 @@ func blockTestCmd(ctx *cli.Context) error { if len(ctx.Args().First()) == 0 { return errors.New("path-to-test argument required") } - var tracer vm.EVMLogger // Configure the EVM logger if ctx.Bool(MachineFlag.Name) { diff --git a/cmd/evm/internal/t8ntool/block.go b/cmd/evm/internal/t8ntool/block.go index 5c0e28e284..00e25b596a 100644 --- a/cmd/evm/internal/t8ntool/block.go +++ b/cmd/evm/internal/t8ntool/block.go @@ -24,6 +24,8 @@ import ( "math/big" "os" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/common/math" @@ -216,9 +218,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.TerminalHandler(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..d5182259ed 100644 --- a/cmd/evm/internal/t8ntool/transaction.go +++ b/cmd/evm/internal/t8ntool/transaction.go @@ -24,6 +24,8 @@ import ( "os" "strings" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/core" @@ -66,9 +68,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.TerminalHandler(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..e109aa5c01 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.TerminalHandler(os.Stderr, false)) + glogger.Verbosity(slog.Level(ctx.Int(VerbosityFlag.Name))) + log.SetDefault(log.NewLogger(glogger)) var ( err error diff --git a/cmd/faucet/faucet.go b/cmd/faucet/faucet.go index e4d6ad6977..a78a58abab 100644 --- a/cmd/faucet/faucet.go +++ b/cmd/faucet/faucet.go @@ -39,6 +39,8 @@ import ( "sync" "time" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/accounts" "github.com/ethereum/go-ethereum/accounts/keystore" "github.com/ethereum/go-ethereum/cmd/utils" @@ -99,7 +101,7 @@ var websiteTmpl string func main() { // Parse the flags and set up the logger to print everything requested flag.Parse() - log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(*logFlag), log.StreamHandler(os.Stderr, log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.TerminalHandlerWithLevel(os.Stderr, slog.Level(*logFlag), true))) // Construct the payout tiers amounts := make([]string, *tiersFlag) diff --git a/core/state/snapshot/generate_test.go b/core/state/snapshot/generate_test.go index 07016b675c..4ad9bd8a60 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.TerminalHandlerWithLevel(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..7eaf93ac19 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.TerminalHandlerWithLevel(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.TerminalHandlerWithLevel(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.TerminalHandlerWithLevel(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.TerminalHandlerWithLevel(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.TerminalHandlerWithLevel(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..7351d0b889 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.TerminalHandlerWithLevel(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/eth/protocols/snap/sync.go b/eth/protocols/snap/sync.go index 887a50775d..4a6f9ba1cb 100644 --- a/eth/protocols/snap/sync.go +++ b/eth/protocols/snap/sync.go @@ -2438,7 +2438,7 @@ func (s *Syncer) OnAccounts(peer SyncPeer, id uint64, hashes []common.Hash, acco for _, node := range proof { size += common.StorageSize(len(node)) } - logger := peer.Log().New("reqid", id) + logger := peer.Log().With("reqid", id) logger.Trace("Delivering range of accounts", "hashes", len(hashes), "accounts", len(accounts), "proofs", len(proof), "bytes", size) // Whether or not the response is valid, we can mark the peer as idle and @@ -2548,7 +2548,7 @@ func (s *Syncer) onByteCodes(peer SyncPeer, id uint64, bytecodes [][]byte) error for _, code := range bytecodes { size += common.StorageSize(len(code)) } - logger := peer.Log().New("reqid", id) + logger := peer.Log().With("reqid", id) logger.Trace("Delivering set of bytecodes", "bytecodes", len(bytecodes), "bytes", size) // Whether or not the response is valid, we can mark the peer as idle and @@ -2661,7 +2661,7 @@ func (s *Syncer) OnStorage(peer SyncPeer, id uint64, hashes [][]common.Hash, slo for _, node := range proof { size += common.StorageSize(len(node)) } - logger := peer.Log().New("reqid", id) + logger := peer.Log().With("reqid", id) logger.Trace("Delivering ranges of storage slots", "accounts", len(hashes), "hashes", hashCount, "slots", slotCount, "proofs", len(proof), "size", size) // Whether or not the response is valid, we can mark the peer as idle and @@ -2795,7 +2795,7 @@ func (s *Syncer) OnTrieNodes(peer SyncPeer, id uint64, trienodes [][]byte) error for _, node := range trienodes { size += common.StorageSize(len(node)) } - logger := peer.Log().New("reqid", id) + logger := peer.Log().With("reqid", id) logger.Trace("Delivering set of healing trienodes", "trienodes", len(trienodes), "bytes", size) // Whether or not the response is valid, we can mark the peer as idle and @@ -2902,7 +2902,7 @@ func (s *Syncer) onHealByteCodes(peer SyncPeer, id uint64, bytecodes [][]byte) e for _, code := range bytecodes { size += common.StorageSize(len(code)) } - logger := peer.Log().New("reqid", id) + logger := peer.Log().With("reqid", id) logger.Trace("Delivering set of healing bytecodes", "bytecodes", len(bytecodes), "bytes", size) // Whether or not the response is valid, we can mark the peer as idle and 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..ef7d19ceec 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -35,6 +35,8 @@ import ( "github.com/mattn/go-isatty" "github.com/urfave/cli/v2" "gopkg.in/natefinch/lumberjack.v2" + + "golang.org/x/exp/slog" ) var Memsize memsizeui.Handler @@ -75,17 +77,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 +151,6 @@ var Flags = []cli.Flag{ verbosityFlag, logVmoduleFlag, vmoduleFlag, - backtraceAtFlag, - debugFlag, logjsonFlag, logFormatFlag, logFileFlag, @@ -180,45 +169,27 @@ var Flags = []cli.Flag{ } var ( - glogger *log.GlogHandler - logOutputStream log.Handler + glogger *log.GlogHandler + logOutputF *os.File ) func init() { - glogger = log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat(false))) - glogger.Verbosity(log.LvlInfo) - log.Root().SetHandler(glogger) + glogger = log.NewGlogHandler(log.TerminalHandler(os.Stderr, false)) + glogger.Verbosity(log.LevelInfo) + log.SetDefault(log.NewLogger(glogger)) } // 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 + fileOutput io.Writer + 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) ) @@ -233,6 +204,7 @@ func Setup(ctx *cli.Context) error { } else { context = append(context, "format", "terminal") } + if rotation { // Lumberjack uses -lumberjack.log in is.TempDir() if empty. // so typically /tmp/geth-lumberjack.log on linux @@ -241,27 +213,55 @@ func Setup(ctx *cli.Context) error { } else { context = append(context, "location", filepath.Join(os.TempDir(), "geth-lumberjack.log")) } - lumberWriter := &lumberjack.Logger{ + fileOutput = &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, fileOutput) } 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 fileOutput, 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(fileOutput, 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 = slog.NewJSONHandler(output, nil) + case logFmtFlag == "json": + handler = slog.NewJSONHandler(output, nil) + 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 fileOutput != nil { + output = io.MultiWriter(fileOutput, terminalOutput) + } else { + output = terminalOutput + } + } + handler = log.TerminalHandler(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 +272,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 +332,8 @@ func StartPProf(address string, withMetrics bool) { func Exit() { Handler.StopCPUProfile() Handler.StopGoTrace() - if closer, ok := logOutputStream.(io.Closer); ok { - closer.Close() + if logOutputF != nil { + logOutputF.Close() } } diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index 684339f16d..70c406b0e8 100644 --- a/internal/testlog/testlog.go +++ b/internal/testlog/testlog.go @@ -18,27 +18,14 @@ package testlog import ( + "context" "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 -} - // 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 // helpers, so the file and line number in unit test output correspond to the call site @@ -51,25 +38,63 @@ 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)}, +func (h *bufHandler) Enabled(_ context.Context, lvl slog.Level) bool { + return lvl <= h.level +} + +// TODO: does testlogger make use of attrs? +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, } - l.l.SetHandler(log.LvlFilterHandler(level, l.h)) - return l +} + +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) Handler() slog.Handler { + return l.l.Handler() } func (l *logger) Trace(msg string, ctx ...interface{}) { @@ -80,6 +105,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 +153,15 @@ func (l *logger) Crit(msg string, ctx ...interface{}) { l.flush() } -func (l *logger) New(ctx ...interface{}) log.Logger { - return &logger{l.t, l.l.New(ctx...), l.mu, l.h} -} - -func (l *logger) GetHandler() log.Handler { - return l.l.GetHandler() -} - -func (l *logger) SetHandler(h log.Handler) { - l.l.SetHandler(h) +func (l *logger) With(ctx ...interface{}) log.Logger { + return &logger{l.t, l.l.With(ctx...), l.mu, l.h} } // 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", log.TerminalFormat(r, false)) } l.h.buf = nil } diff --git a/les/api_test.go b/les/api_test.go index 484c95504c..34daa144e4 100644 --- a/les/api_test.go +++ b/les/api_test.go @@ -28,6 +28,8 @@ import ( "testing" "time" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/eth" @@ -51,8 +53,7 @@ var ( func TestMain(m *testing.M) { 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.TerminalHandlerWithLevel(colorable.NewColorableStderr(), slog.Level(*loglevel), true))) // register the Delivery service which will run as a devp2p // protocol when using the exec adapter adapters.RegisterLifecycles(services) 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..c708b854cb 100644 --- a/log/format.go +++ b/log/format.go @@ -2,20 +2,22 @@ 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 timeKey = "t" +const lvlKey = "lvl" +const msgKey = "msg" + const ( timeFormat = "2006-01-02T15:04:05-0700" termTimeFormat = "01-02|15:04:05.000" @@ -24,41 +26,6 @@ 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) @@ -67,18 +34,18 @@ var fieldPadding = make(map[string]int) 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) } @@ -98,65 +65,41 @@ type TerminalStringer interface { // 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 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)) - - // 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() - }) + 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 + logfmt(b, []slog.Attr{}, r, color, true) + return b.Bytes() } // LogfmtFormat prints records in logfmt format, an easy machine-parseable but human-readable @@ -164,146 +107,60 @@ func TerminalFormat(usecolor bool) Format { // // 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} + return FormatFunc(func(r slog.Record) []byte { + common := []slog.Attr{slog.Time(timeKey, r.Time), slog.Int(lvlKey, int(r.Level)), slog.String(msgKey, r.Message)} buf := &bytes.Buffer{} - logfmt(buf, append(common, r.Ctx...), 0, false) + logfmt(buf, common, r, 0, false) return buf.Bytes() }) } -func logfmt(buf *bytes.Buffer, ctx []interface{}, color int, term bool) { - for i := 0; i < len(ctx); i += 2 { +func logfmt(buf *bytes.Buffer, commonAttrs []slog.Attr, r slog.Record, color int, term bool) { + attrs := []slog.Attr{} + r.Attrs(func(attr slog.Attr) bool { + attrs = append(attrs, attr) + return true + }) + + attrs = append(commonAttrs, 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 + // TODO (jwasinger) above comment was from log15 code. what does it mean? check that key bytes are ascii characters? fieldPaddingLock.RLock() - padding := fieldPadding[k] + padding := fieldPadding[key] fieldPaddingLock.RUnlock() - length := utf8.RuneCountInString(v) + length := utf8.RuneCountInString(val) if padding < length && length <= termCtxMaxPadding { padding = length fieldPaddingLock.Lock() - fieldPadding[k] = padding + fieldPadding[key] = padding fieldPaddingLock.Unlock() } 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, "", " ") - } - } - 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 { @@ -330,16 +187,6 @@ func formatShared(value interface{}) (result interface{}) { } } -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 { diff --git a/log/handler.go b/log/handler.go index 4a0cf578f6..3f7027fc74 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,242 @@ 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{} } -// 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 +func (h *discardHandler) Handle(_ context.Context, r slog.Record) error { + return nil +} -func must(h Handler, err error) Handler { - if err != nil { - panic(err) +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 funcHandler struct { + handler handlerFunc + attrs []slog.Attr +} + +type handlerFunc func(_ context.Context, r slog.Record) error + +// FuncHandler returns a handler which forwards all records to the provided handler function +func FuncHandler(fn handlerFunc) slog.Handler { + return &funcHandler{fn, []slog.Attr{}} +} + +func (h funcHandler) Handle(_ context.Context, r slog.Record) error { + r.AddAttrs(h.attrs...) + return h.handler(context.Background(), r) +} + +func (h *funcHandler) Enabled(_ context.Context, level slog.Level) bool { + return true +} + +func (h *funcHandler) WithGroup(name string) slog.Handler { + panic("not implemented") +} + +func (h *funcHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &funcHandler{ + h.handler, + append(h.attrs, attrs...), } - return h } -type muster struct{} - -func (m muster) FileHandler(path string, fmtr Format) Handler { - return must(FileHandler(path, fmtr)) +type terminalHandler struct { + mu sync.Mutex + wr io.Writer + lvl slog.Level + useColor bool + attrs []slog.Attr } -func (m muster) NetHandler(network, addr string, fmtr Format) Handler { - return must(NetHandler(network, addr, fmtr)) +// TerminalHandler 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 TerminalHandler(wr io.Writer, useColor bool) slog.Handler { + return TerminalHandlerWithLevel(wr, levelMaxVerbosity, useColor) } -// swapHandler wraps another handler that may be swapped out -// dynamically at runtime in a thread-safe fashion. -type swapHandler struct { - handler atomic.Value +// TerminalHandlerWithLevel returns the same handler as TerminalHandler but only outputs +// records which are less than or equal to the specified verbosity level. +func TerminalHandlerWithLevel(wr io.Writer, lvl slog.Level, useColor bool) slog.Handler { + return &terminalHandler{ + sync.Mutex{}, + wr, + lvl, + useColor, + []slog.Attr{}, + } } -func (h *swapHandler) Log(r *Record) error { - return (*h.handler.Load().(*Handler)).Log(r) +func (h *terminalHandler) Handle(_ context.Context, r slog.Record) error { + h.mu.Lock() + defer h.mu.Unlock() + r.AddAttrs(h.attrs...) + h.wr.Write(TerminalFormat(r, h.useColor)) + return nil } -func (h *swapHandler) Swap(newHandler Handler) { - h.handler.Store(&newHandler) +func (h *terminalHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.lvl } -func (h *swapHandler) Get() Handler { - return *h.handler.Load().(*Handler) +func (h *terminalHandler) WithGroup(name string) slog.Handler { + panic("not implemented") +} + +func (h *terminalHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &terminalHandler{ + sync.Mutex{}, + h.wr, + h.lvl, + h.useColor, + append(h.attrs, attrs...), + } +} + +type leveler struct{ minLevel slog.Level } + +func (l *leveler) Level() slog.Level { + return l.minLevel +} + +func JsonHandler(wr io.Writer) slog.Handler { + return &builtinHandler{slog.NewJSONHandler(wr, &slog.HandlerOptions{ + ReplaceAttr: builtinReplace, + })} +} + +// 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 &builtinHandler{slog.NewTextHandler(wr, &slog.HandlerOptions{ + ReplaceAttr: builtinReplace, + })} +} + +// 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 &builtinHandler{slog.NewTextHandler(wr, &slog.HandlerOptions{ + ReplaceAttr: builtinReplace, + Level: &leveler{level}, + })} +} + +// builtinHandler wraps an instance of the built-in slog json/text handlers +// a wrapper is needed because with slog.HandlerOptions.ReplaceAttr, there is +// no way to differentiate between an attribute that is a property of the Record +// and a user-provided attribute (e.g. providing an attribute who's key is "time" +// conflicts with the Record.Time property). +type builtinHandler struct { + inner slog.Handler +} + +func (h *builtinHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &builtinHandler{ + h.inner.WithAttrs(attrs), + } +} + +const diffMarker = "xxxxxx" + +func (h *builtinHandler) WithGroup(name string) slog.Handler { + return &builtinHandler{ + h.inner.WithGroup(name), + } +} + +func (h *builtinHandler) Enabled(_ context.Context, level slog.Level) bool { + return h.inner.Enabled(context.Background(), level) +} + +func (h *builtinHandler) Handle(_ context.Context, r slog.Record) error { + var sanitizedAttrs []slog.Attr + sanitizedRecord := slog.NewRecord(r.Time, r.Level, r.Message, r.PC) + + // iterate user-provided attrs. prepend key with marker for + // any that would conflict with keys for Record obj properties. + r.Attrs(func(attr slog.Attr) bool { + switch attr.Key { + case slog.TimeKey: + attr.Key = diffMarker + slog.TimeKey + case slog.LevelKey: + attr.Key = diffMarker + slog.LevelKey + case slog.MessageKey: + attr.Key = diffMarker + slog.MessageKey + case slog.SourceKey: + attr.Key = diffMarker + slog.SourceKey + } + sanitizedAttrs = append(sanitizedAttrs, attr) + return true + }) + + sanitizedRecord.AddAttrs(sanitizedAttrs...) + return h.inner.Handle(context.Background(), sanitizedRecord) +} + +func builtinReplace(_ []string, attr slog.Attr) slog.Attr { + switch attr.Key { + case slog.TimeKey: + attr = slog.Any("t", attr.Value.Time().Format(timeFormat)) + return attr + case slog.LevelKey: + attr = slog.Any("lvl", LevelString(attr.Value.Any().(slog.Level))) + return attr + case slog.MessageKey: + return attr + case slog.SourceKey: + return attr + + // strip the marker from attr keys that conflict with Record obj property keys + case diffMarker + slog.TimeKey: + attr.Key = slog.TimeKey + case diffMarker + slog.LevelKey: + attr.Key = slog.LevelKey + case diffMarker + slog.MessageKey: + attr.Key = slog.MessageKey + case diffMarker + slog.SourceKey: + attr.Key = slog.SourceKey + } + + switch v := attr.Value.Any().(type) { + case time.Time: + attr = slog.Any(attr.Key, v.Format(timeFormat)) + case *big.Int: + if v == nil { + attr.Value = slog.AnyValue("") + } else { + attr.Value = slog.AnyValue(formatLogfmtBigInt(v)) + } + case *uint256.Int: + if v == nil { + attr.Value = slog.AnyValue("") + } else { + attr.Value = slog.AnyValue(formatLogfmtUint256(v)) + } + } + return attr } diff --git a/log/handler_glog.go b/log/handler_glog.go index afca0808b3..4a73599b97 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,77 @@ 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 { + res := GlogHandler{ + h.origin.WithAttrs(attrs), + atomic.Int32{}, + atomic.Bool{}, + h.patterns, + h.siteCache, + h.location, + sync.RWMutex{}, + } + + 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..d885f288c5 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 +) + +// 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: - return "eror" - case LvlCrit: + case slog.LevelError: + return "error" + 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 - New(ctx ...interface{}) Logger + // Handler returns the handler associated with this logger + Handler() slog.Handler - // GetHandler gets the handler associated with the logger. - GetHandler() Handler + // TODO: add WithGroup()? - // SetHandler updates the logger to write records to the specified handler. - SetHandler(h Handler) + // With returns a new Logger that has this logger's attributes plus the given attributes + With(ctx ...interface{}) Logger - // 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) + // Log logs a message at the specified level with context key/value pairs + Log(level slog.Level, msg string, ctx ...interface{}) + + // 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{}) } 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) +} + +func (l *logger) Handler() slog.Handler { + return l.inner.Handler() +} + +// 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) -} + // TODO we will want to 'sanitize' record keys: + // e.g. an attr is provided with key name 'time' (conflicting with the built-in time key name). + // ReplaceAttr() has no way to differentiate between this provided attribute and Record.Time. + // To get around this, in the below loop, we can prefix the attr with a fixed string value, + // which then gets stripped from the handler before printing. -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) 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..ffed73ba48 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -7,46 +7,14 @@ import ( "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) - } -} - // 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(TerminalHandlerWithLevel(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 @@ -59,9 +27,13 @@ func TestLoggingWithVmodule(t *testing.T) { } func BenchmarkTraceLogging(b *testing.B) { - Root().SetHandler(LvlFilterHandler(LvlInfo, StreamHandler(os.Stderr, TerminalFormat(true)))) + SetDefault(NewLogger(TerminalHandler(os.Stderr, true))) b.ResetTimer() for i := 0; i < b.N; i++ { Trace("a message", "v", i) } } + +func TestLoggingWithAttrs(t *testing.T) { + // TODO: test logger.With(...) +} diff --git a/log/root.go b/log/root.go index 5a41723c3e..eeeb6451ab 100644 --- a/log/root.go +++ b/log/root.go @@ -2,27 +2,32 @@ 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()) + root = new(atomic.Value) ) func init() { - root.SetHandler(DiscardHandler()) + defaultLogger := &logger{slog.New(DiscardHandler())} + root.Store(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...) +func SetDefault(l Logger) { + root.Store(l) } // Root returns the root logger func Root() Logger { - return root + return rootLogger() +} + +func rootLogger() *logger { + res, _ := root.Load().(*logger) + return res } // The following functions bypass the exported logger methods (logger.Debug, @@ -39,7 +44,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) + rootLogger().write(LevelTrace, msg, ctx...) } // Debug is a convenient alias for Root().Debug @@ -52,7 +57,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) + rootLogger().write(slog.LevelDebug, msg, ctx...) } // Info is a convenient alias for Root().Info @@ -65,7 +70,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) + rootLogger().write(slog.LevelInfo, msg, ctx...) } // Warn is a convenient alias for Root().Warn @@ -78,7 +83,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) + rootLogger().write(slog.LevelWarn, msg, ctx...) } // Error is a convenient alias for Root().Error @@ -91,7 +96,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) + rootLogger().write(slog.LevelError, msg, ctx...) } // Crit is a convenient alias for Root().Crit @@ -104,15 +109,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) + rootLogger().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 rootLogger().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..a0d0ab4eb4 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.TerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true))) fdlimit.Raise(2048) // Generate a batch of accounts to seal and fund with diff --git a/node/rpcstack_test.go b/node/rpcstack_test.go index e41cc51ad3..2eb47b7331 100644 --- a/node/rpcstack_test.go +++ b/node/rpcstack_test.go @@ -241,7 +241,7 @@ func createAndStartServer(t *testing.T, conf *httpConfig, ws bool, wsConf *wsCon if timeouts == nil { timeouts = &rpc.DefaultHTTPTimeouts } - srv := newHTTPServer(testlog.Logger(t, log.LvlDebug), *timeouts) + srv := newHTTPServer(testlog.Logger(t, log.LevelDebug), *timeouts) assert.NoError(t, srv.enableRPC(apis(), *conf)) if ws { assert.NoError(t, srv.enableWS(nil, *wsConf)) diff --git a/p2p/dial_test.go b/p2p/dial_test.go index 13908f11ea..c70bba7194 100644 --- a/p2p/dial_test.go +++ b/p2p/dial_test.go @@ -422,7 +422,7 @@ func runDialTest(t *testing.T, config dialConfig, rounds []dialTestRound) { config.clock = clock config.dialer = dialer config.resolver = resolver - config.log = testlog.Logger(t, log.LvlTrace) + config.log = testlog.Logger(t, log.LevelTrace) config.rand = rand.New(rand.NewSource(0x1111)) // Set up the dialer. The setup function below runs on the dialTask diff --git a/p2p/discover/v4_udp_test.go b/p2p/discover/v4_udp_test.go index 5add9cefa1..17d1ed0fc5 100644 --- a/p2p/discover/v4_udp_test.go +++ b/p2p/discover/v4_udp_test.go @@ -18,6 +18,7 @@ package discover import ( "bytes" + "context" "crypto/ecdsa" crand "crypto/rand" "encoding/binary" @@ -31,6 +32,8 @@ import ( "testing" "time" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/internal/testlog" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/p2p/discover/v4wire" @@ -71,7 +74,7 @@ func newUDPTest(t *testing.T) *udpTest { ln := enode.NewLocalNode(test.db, test.localkey) test.udp, _ = ListenV4(test.pipe, ln, Config{ PrivateKey: test.localkey, - Log: testlog.Logger(t, log.LvlTrace), + Log: testlog.Logger(t, log.LevelTrace), }) test.table = test.udp.tab // Wait for initial refresh so the table doesn't send unexpected findnode. @@ -557,10 +560,12 @@ 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)) + cfg.Log = testlog.LoggerWithHandler(t, log.FuncHandler(func(_ context.Context, r slog.Record) error { + if r.Level <= log.LevelTrace { + return nil + } + + t.Logf("%s %s", lprefix, log.TerminalFormat(r, false)) return nil })) diff --git a/p2p/discover/v5_udp_test.go b/p2p/discover/v5_udp_test.go index 880b71a991..d7894a4b14 100644 --- a/p2p/discover/v5_udp_test.go +++ b/p2p/discover/v5_udp_test.go @@ -18,6 +18,7 @@ package discover import ( "bytes" + "context" "crypto/ecdsa" "encoding/binary" "fmt" @@ -27,6 +28,8 @@ import ( "testing" "time" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/internal/testlog" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/p2p/discover/v5wire" @@ -79,10 +82,11 @@ 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)) + cfg.Log = testlog.LoggerWithHandler(t, log.FuncHandler(func(_ context.Context, r slog.Record) error { + if r.Level <= log.LevelTrace { + return nil + } + t.Logf("%s %s", lprefix, log.TerminalFormat(r, false)) return nil })) @@ -765,7 +769,7 @@ func newUDPV5Test(t *testing.T) *udpV5Test { ln.Set(enr.UDP(30303)) test.udp, _ = ListenV5(test.pipe, ln, Config{ PrivateKey: test.localkey, - Log: testlog.Logger(t, log.LvlTrace), + Log: testlog.Logger(t, log.LevelTrace), ValidSchemes: enode.ValidSchemesForTesting, }) test.udp.codec = &testCodec{test: test, id: ln.ID()} diff --git a/p2p/dnsdisc/client_test.go b/p2p/dnsdisc/client_test.go index abc35ddbd3..a910ac409c 100644 --- a/p2p/dnsdisc/client_test.go +++ b/p2p/dnsdisc/client_test.go @@ -57,7 +57,7 @@ func TestClientSyncTree(t *testing.T) { wantSeq = uint(1) ) - c := NewClient(Config{Resolver: r, Logger: testlog.Logger(t, log.LvlTrace)}) + c := NewClient(Config{Resolver: r, Logger: testlog.Logger(t, log.LevelTrace)}) stree, err := c.SyncTree("enrtree://AKPYQIUQIL7PSIACI32J7FGZW56E5FKHEFCCOFHILBIMW3M6LWXS2@n") if err != nil { t.Fatal("sync error:", err) @@ -91,7 +91,7 @@ func TestClientSyncTreeBadNode(t *testing.T) { "C7HRFPF3BLGF3YR4DY5KX3SMBE.n": "enrtree://AM5FCQLWIZX2QFPNJAP7VUERCCRNGRHWZG3YYHIUV7BVDQ5FDPRT2@morenodes.example.org", "INDMVBZEEQ4ESVYAKGIYU74EAA.n": "enr:-----", } - c := NewClient(Config{Resolver: r, Logger: testlog.Logger(t, log.LvlTrace)}) + c := NewClient(Config{Resolver: r, Logger: testlog.Logger(t, log.LevelTrace)}) _, err := c.SyncTree("enrtree://AKPYQIUQIL7PSIACI32J7FGZW56E5FKHEFCCOFHILBIMW3M6LWXS2@n") wantErr := nameError{name: "INDMVBZEEQ4ESVYAKGIYU74EAA.n", err: entryError{typ: "enr", err: errInvalidENR}} if err != wantErr { @@ -110,7 +110,7 @@ func TestIterator(t *testing.T) { c := NewClient(Config{ Resolver: r, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), RateLimit: 500, }) it, err := c.NewIterator(url) @@ -174,7 +174,7 @@ func TestIteratorLinks(t *testing.T) { c := NewClient(Config{ Resolver: newMapResolver(tree1.ToTXT("t1"), tree2.ToTXT("t2")), - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), RateLimit: 500, }) it, err := c.NewIterator(url2) @@ -195,7 +195,7 @@ func TestIteratorNodeUpdates(t *testing.T) { resolver = newMapResolver() c = NewClient(Config{ Resolver: resolver, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), RecheckInterval: 20 * time.Minute, RateLimit: 500, }) @@ -233,7 +233,7 @@ func TestIteratorRootRecheckOnFail(t *testing.T) { resolver = newMapResolver() c = NewClient(Config{ Resolver: resolver, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), RecheckInterval: 20 * time.Minute, RateLimit: 500, // Disabling the cache is required for this test because the client doesn't @@ -271,7 +271,7 @@ func TestIteratorEmptyTree(t *testing.T) { resolver = newMapResolver() c = NewClient(Config{ Resolver: resolver, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), RecheckInterval: 20 * time.Minute, RateLimit: 500, }) @@ -332,7 +332,7 @@ func TestIteratorLinkUpdates(t *testing.T) { resolver = newMapResolver() c = NewClient(Config{ Resolver: resolver, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), RecheckInterval: 20 * time.Minute, RateLimit: 500, }) diff --git a/p2p/peer.go b/p2p/peer.go index 65a7903f58..577e473731 100644 --- a/p2p/peer.go +++ b/p2p/peer.go @@ -235,7 +235,7 @@ func newPeer(log log.Logger, conn *conn, protocols []Protocol) *Peer { protoErr: make(chan error, len(protomap)+1), // protocols + pingLoop closed: make(chan struct{}), pingRecv: make(chan struct{}, 16), - log: log.New("id", conn.node.ID(), "conn", conn.flags), + log: log.With("id", conn.node.ID(), "conn", conn.flags), } return p } diff --git a/p2p/server.go b/p2p/server.go index 8f42765a8c..fe4dba49c7 100644 --- a/p2p/server.go +++ b/p2p/server.go @@ -977,7 +977,7 @@ func (srv *Server) setupConn(c *conn, flags connFlag, dialDest *enode.Node) erro } else { c.node = nodeFromConn(remotePubkey, c.fd) } - clog := srv.log.New("id", c.node.ID(), "addr", c.fd.RemoteAddr(), "conn", c.flags) + clog := srv.log.With("id", c.node.ID(), "addr", c.fd.RemoteAddr(), "conn", c.flags) err = srv.checkpoint(c, srv.checkpointPostHandshake) if err != nil { clog.Trace("Rejected peer", "err", err) diff --git a/p2p/server_nat_test.go b/p2p/server_nat_test.go index de935fcfc5..a92b59c99e 100644 --- a/p2p/server_nat_test.go +++ b/p2p/server_nat_test.go @@ -36,7 +36,7 @@ func TestServerPortMapping(t *testing.T) { NoDial: true, ListenAddr: ":0", NAT: mockNAT, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), clock: clock, }, } diff --git a/p2p/server_test.go b/p2p/server_test.go index a0491e984a..4849902503 100644 --- a/p2p/server_test.go +++ b/p2p/server_test.go @@ -75,7 +75,7 @@ func startTestServer(t *testing.T, remoteKey *ecdsa.PublicKey, pf func(*Peer)) * ListenAddr: "127.0.0.1:0", NoDiscovery: true, PrivateKey: newkey(), - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), } server := &Server{ Config: config, @@ -211,7 +211,7 @@ func TestServerRemovePeerDisconnect(t *testing.T) { PrivateKey: newkey(), MaxPeers: 1, NoDiscovery: true, - Logger: testlog.Logger(t, log.LvlTrace).New("server", "1"), + Logger: testlog.Logger(t, log.LevelTrace).With("server", "1"), }} srv2 := &Server{Config: Config{ PrivateKey: newkey(), @@ -219,7 +219,7 @@ func TestServerRemovePeerDisconnect(t *testing.T) { NoDiscovery: true, NoDial: true, ListenAddr: "127.0.0.1:0", - Logger: testlog.Logger(t, log.LvlTrace).New("server", "2"), + Logger: testlog.Logger(t, log.LevelTrace).With("server", "2"), }} srv1.Start() defer srv1.Stop() @@ -255,7 +255,7 @@ func TestServerAtCap(t *testing.T) { NoDial: true, NoDiscovery: true, TrustedNodes: []*enode.Node{newNode(trustedID, "")}, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), }, } if err := srv.Start(); err != nil { @@ -331,7 +331,7 @@ func TestServerPeerLimits(t *testing.T) { NoDial: true, NoDiscovery: true, Protocols: []Protocol{discard}, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), }, newTransport: func(fd net.Conn, dialDest *ecdsa.PublicKey) transport { return tp }, } @@ -438,7 +438,7 @@ func TestServerSetupConn(t *testing.T) { NoDial: true, NoDiscovery: true, Protocols: []Protocol{discard}, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), } srv := &Server{ Config: cfg, @@ -525,7 +525,7 @@ func TestServerInboundThrottle(t *testing.T) { NoDial: true, NoDiscovery: true, Protocols: []Protocol{discard}, - Logger: testlog.Logger(t, log.LvlTrace), + Logger: testlog.Logger(t, log.LevelTrace), }, newTransport: func(fd net.Conn, dialDest *ecdsa.PublicKey) transport { newTransportCalled <- struct{}{} diff --git a/p2p/simulations/adapters/exec.go b/p2p/simulations/adapters/exec.go index 5ac3379393..28898ea4c6 100644 --- a/p2p/simulations/adapters/exec.go +++ b/p2p/simulations/adapters/exec.go @@ -35,6 +35,7 @@ import ( "time" "github.com/ethereum/go-ethereum/internal/reexec" + "golang.org/x/exp/slog" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/node" "github.com/ethereum/go-ethereum/p2p" @@ -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.TerminalHandler(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..96ef7bb4d8 100644 --- a/p2p/simulations/adapters/types.go +++ b/p2p/simulations/adapters/types.go @@ -25,6 +25,7 @@ import ( "os" "strconv" + "golang.org/x/exp/slog" "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/internal/reexec" "github.com/ethereum/go-ethereum/log" @@ -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 } @@ -227,7 +228,7 @@ func RandomNodeConfig() *NodeConfig { Name: fmt.Sprintf("node_%s", enodId.String()), Port: port, EnableMsgEvents: true, - LogVerbosity: log.LvlInfo, + LogVerbosity: log.LevelInfo, } } diff --git a/p2p/simulations/examples/ping-pong.go b/p2p/simulations/examples/ping-pong.go index f6cf5113a6..6072e07b93 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.TerminalHandlerWithLevel(os.Stderr, log.LevelTrace, false))) // register a single ping-pong service services := map[string]adapters.LifecycleConstructor{ @@ -137,7 +137,7 @@ const ( // Run implements the ping-pong protocol which sends ping messages to the peer // at 10s intervals, and responds to pings with pong messages. func (p *pingPongService) Run(peer *p2p.Peer, rw p2p.MsgReadWriter) error { - log := p.log.New("peer.id", peer.ID()) + log := p.log.With("peer.id", peer.ID()) errC := make(chan error, 1) go func() { diff --git a/p2p/simulations/http_test.go b/p2p/simulations/http_test.go index 05e43238ab..8105afa89d 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.TerminalHandlerWithLevel(colorable.NewColorableStderr(), slog.Level(*loglevel), true))) os.Exit(m.Run()) } diff --git a/rpc/handler.go b/rpc/handler.go index f44e4d7b01..87c836e246 100644 --- a/rpc/handler.go +++ b/rpc/handler.go @@ -89,7 +89,7 @@ func newHandler(connCtx context.Context, conn jsonWriter, idgen func() ID, reg * batchResponseMaxSize: batchResponseMaxSize, } if conn.remoteAddr() != "" { - h.log = h.log.New("conn", conn.remoteAddr()) + h.log = h.log.With("conn", conn.remoteAddr()) } h.unsubscribeCb = newCallback(reflect.Value{}, reflect.ValueOf(h.unsubscribe)) return h diff --git a/signer/core/auditlog.go b/signer/core/auditlog.go index a0b292bf71..bd8839371d 100644 --- a/signer/core/auditlog.go +++ b/signer/core/auditlog.go @@ -19,6 +19,9 @@ package core import ( "context" "encoding/json" + "os" + + "golang.org/x/exp/slog" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" @@ -113,12 +116,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 e1fea59280..b3102e3cda 100644 --- a/signer/storage/aes_gcm_storage_test.go +++ b/signer/storage/aes_gcm_storage_test.go @@ -23,6 +23,8 @@ import ( "os" "testing" + "golang.org/x/exp/slog" + "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/log" "github.com/mattn/go-colorable" @@ -89,7 +91,7 @@ func TestFileStorage(t *testing.T) { } } func TestEnd2End(t *testing.T) { - log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(3), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) + log.SetDefault(log.NewLogger(log.TerminalHandlerWithLevel(colorable.NewColorableStderr(), slog.LevelInfo, true))) d := t.TempDir() @@ -111,7 +113,7 @@ func TestEnd2End(t *testing.T) { func TestSwappedKeys(t *testing.T) { // 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.TerminalHandlerWithLevel(colorable.NewColorableStderr(), slog.LevelInfo, true))) d := t.TempDir()