internal, log: support debug log prints, displaying log origins

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 <pattern>=<level> (e.g. eth/*=6,p2p=5)",
+		Usage: "Per-module verbosity: comma-separated list of <pattern>=<level> (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))

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)))