From f89dd627760b43bd405cb3db1e5efdb100835db5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Szil=C3=A1gyi?= Date: Thu, 23 Feb 2017 11:44:16 +0200 Subject: [PATCH] internal, log: support debug log prints, displaying log origins --- internal/debug/flags.go | 14 ++++++++--- log/format.go | 56 +++++++++++++++++++++++++++++++++++++---- 2 files changed, 62 insertions(+), 8 deletions(-) diff --git a/internal/debug/flags.go b/internal/debug/flags.go index 780aa1647..29d1f3388 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -30,12 +30,12 @@ import ( var ( verbosityFlag = cli.IntFlag{ Name: "verbosity", - Usage: "Logging verbosity: 0=silent, 1=error, 2=warn, 3=info, 4=core, 5=debug, 6=detail", + Usage: "Logging verbosity: 0=silent, 1=error, 2=warn, 3=info, 4=debug, 5=detail", Value: 3, } vmoduleFlag = cli.StringFlag{ Name: "vmodule", - Usage: "Per-module verbosity: comma-separated list of = (e.g. eth/*=6,p2p=5)", + Usage: "Per-module verbosity: comma-separated list of = (e.g. eth/*=5,p2p=4)", Value: "", } backtraceAtFlag = cli.StringFlag{ @@ -43,6 +43,10 @@ var ( Usage: "Request a stack trace at a specific logging statement (e.g. \"block.go:271\")", Value: "", } + debugFlag = cli.BoolFlag{ + Name: "debug", + Usage: "Prepends log messages with call-site location (file and line number)", + } pprofFlag = cli.BoolFlag{ Name: "pprof", Usage: "Enable the pprof HTTP server", @@ -78,17 +82,21 @@ var ( // Flags holds all command-line flags required for debugging. var Flags = []cli.Flag{ - verbosityFlag, vmoduleFlag, backtraceAtFlag, + verbosityFlag, vmoduleFlag, backtraceAtFlag, debugFlag, pprofFlag, pprofAddrFlag, pprofPortFlag, memprofilerateFlag, blockprofilerateFlag, cpuprofileFlag, traceFlag, } +// glogger is the glog handler used by Geth, allowing the debug APIs to modify +// verbosity levels, vmodules and backtrace locations. var glogger = log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat())) // 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 { // logging + log.PrintOrigins(ctx.GlobalBool(debugFlag.Name)) + glogger.Verbosity(log.Lvl(ctx.GlobalInt(verbosityFlag.Name))) glogger.Vmodule(ctx.GlobalString(vmoduleFlag.Name)) glogger.BacktraceAt(ctx.GlobalString(backtraceAtFlag.Name)) diff --git a/log/format.go b/log/format.go index 9dcfc8d13..2a3790501 100644 --- a/log/format.go +++ b/log/format.go @@ -8,6 +8,7 @@ import ( "strconv" "strings" "sync" + "sync/atomic" "time" ) @@ -18,6 +19,30 @@ const ( termMsgJust = 40 ) +// locationTrims are trimmed for display to avoid unwieldy log lines. +var locationTrims = []string{ + "github.com/ethereum/go-ethereum/", + "github.com/ethereum/ethash/", +} + +// PrintOrigins sets or unsets log location (file:line) printing for terminal +// format output. +func PrintOrigins(print bool) { + if print { + atomic.StoreUint32(&locationEnabled, 1) + } else { + atomic.StoreUint32(&locationEnabled, 0) + } +} + +// locationEnabled is an atomic flag controlling whether the terminal formatter +// should append the log locations too when printing entries. +var locationEnabled uint32 + +// locationLength is the maxmimum path length encountered, which all logs are +// padded to to aid in alignment. +var locationLength uint32 + type Format interface { Format(r *Record) []byte } @@ -64,12 +89,33 @@ func TerminalFormat() Format { b := &bytes.Buffer{} lvl := strings.ToUpper(r.Lvl.String()) - if color > 0 { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), r.Msg) - } else { - fmt.Fprintf(b, "[%s] [%s] %s ", lvl, r.Time.Format(termTimeFormat), r.Msg) - } + if atomic.LoadUint32(&locationEnabled) != 0 { + // 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(atomic.LoadUint32(&locationLength)) + if align < len(location) { + align = len(location) + atomic.StoreUint32(&locationLength, 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, r.Msg) + } else { + fmt.Fprintf(b, "[%s] [%s|%s]%s %s ", lvl, r.Time.Format(termTimeFormat), location, padding, r.Msg) + } + } else { + if color > 0 { + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), r.Msg) + } else { + fmt.Fprintf(b, "[%s] [%s] %s ", lvl, r.Time.Format(termTimeFormat), r.Msg) + } + } // try to justify the log output for short messages if len(r.Ctx) > 0 && len(r.Msg) < termMsgJust { b.Write(bytes.Repeat([]byte{' '}, termMsgJust-len(r.Msg)))