From 31341857abc73334852d3b888f4fb558d8ed3c61 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Sun, 25 Dec 2022 14:03:02 -0700 Subject: Factor logger code from main.go in to textui --- lib/textui/log.go | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) create mode 100644 lib/textui/log.go (limited to 'lib/textui/log.go') diff --git a/lib/textui/log.go b/lib/textui/log.go new file mode 100644 index 0000000..cee51db --- /dev/null +++ b/lib/textui/log.go @@ -0,0 +1,33 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package textui + +import ( + "github.com/datawire/dlib/dlog" + "github.com/sirupsen/logrus" + "github.com/spf13/pflag" +) + +type LogLevelFlag struct { + logrus.Level +} + +var _ pflag.Value = (*LogLevelFlag)(nil) + +// Type implements pflag.Value. +func (lvl *LogLevelFlag) Type() string { return "loglevel" } + +// Type implements pflag.Value. +func (lvl *LogLevelFlag) Set(str string) error { + var err error + lvl.Level, err = logrus.ParseLevel(str) + return err +} + +func NewLogger(lvl logrus.Level) dlog.Logger { + logger := logrus.New() + logger.SetLevel(lvl) + return dlog.WrapLogrus(logger) +} -- cgit v1.2.3-2-g168b From 29ad8ec24e07888953c14fb5435d2e8e2023931b Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Sun, 25 Dec 2022 22:47:51 -0700 Subject: textui: Implement a custom dlog backend that uses x/text/message --- lib/textui/log.go | 282 ++++++++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 272 insertions(+), 10 deletions(-) (limited to 'lib/textui/log.go') diff --git a/lib/textui/log.go b/lib/textui/log.go index cee51db..ca8c201 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -1,17 +1,33 @@ +// Copyright (C) 2019-2022 Ambassador Labs // Copyright (C) 2022 Luke Shumaker // -// SPDX-License-Identifier: GPL-2.0-or-later +// SPDX-License-Identifier: Apache-2.0 +// +// Contains code based on: +// https://github.com/datawire/dlib/blob/b09ab2e017e16d261f05fff5b3b860d645e774d4/dlog/logger_logrus.go +// https://github.com/datawire/dlib/blob/b09ab2e017e16d261f05fff5b3b860d645e774d4/dlog/logger_testing.go +// https://github.com/telepresenceio/telepresence/blob/ece94a40b00a90722af36b12e40f91cbecc0550c/pkg/log/formatter.go package textui import ( + "bytes" + "fmt" + "io" + "log" + "path/filepath" + "runtime" + "sort" + "strings" + "sync" + "time" + "github.com/datawire/dlib/dlog" - "github.com/sirupsen/logrus" "github.com/spf13/pflag" ) type LogLevelFlag struct { - logrus.Level + Level dlog.LogLevel } var _ pflag.Value = (*LogLevelFlag)(nil) @@ -21,13 +37,259 @@ func (lvl *LogLevelFlag) Type() string { return "loglevel" } // Type implements pflag.Value. func (lvl *LogLevelFlag) Set(str string) error { - var err error - lvl.Level, err = logrus.ParseLevel(str) - return err + switch strings.ToLower(str) { + case "error": + lvl.Level = dlog.LogLevelError + case "warn", "warning": + lvl.Level = dlog.LogLevelWarn + case "info": + lvl.Level = dlog.LogLevelInfo + case "debug": + lvl.Level = dlog.LogLevelDebug + case "trace": + lvl.Level = dlog.LogLevelTrace + default: + return fmt.Errorf("invalid log level: %q", str) + } + return nil +} + +// Type implements pflag.Value. +func (lvl *LogLevelFlag) String() string { + switch lvl.Level { + case dlog.LogLevelError: + return "error" + case dlog.LogLevelWarn: + return "warn" + case dlog.LogLevelInfo: + return "info" + case dlog.LogLevelDebug: + return "debug" + case dlog.LogLevelTrace: + return "trace" + default: + panic(fmt.Errorf("invalid log level: %#v", lvl.Level)) + } +} + +type logger struct { + parent *logger + out io.Writer + lvl dlog.LogLevel + + // only valid if parent is non-nil + fieldKey string + fieldVal any +} + +var _ dlog.OptimizedLogger = (*logger)(nil) + +func NewLogger(out io.Writer, lvl dlog.LogLevel) dlog.Logger { + return &logger{ + out: out, + lvl: lvl, + } +} + +// Helper implements dlog.Logger. +func (l *logger) Helper() {} + +// WithField implements dlog.Logger. +func (l *logger) WithField(key string, value any) dlog.Logger { + return &logger{ + parent: l, + out: l.out, + lvl: l.lvl, + + fieldKey: key, + fieldVal: value, + } +} + +type logWriter struct { + log *logger + lvl dlog.LogLevel +} + +// Write implements io.Writer. +func (lw logWriter) Write(data []byte) (int, error) { + lw.log.log(lw.lvl, func(w io.Writer) { + _, _ = w.Write(data) + }) + return len(data), nil +} + +// StdLogger implements dlog.Logger. +func (l *logger) StdLogger(lvl dlog.LogLevel) *log.Logger { + return log.New(logWriter{log: l, lvl: lvl}, "", 0) +} + +// Log implements dlog.Logger. +func (l *logger) Log(lvl dlog.LogLevel, msg string) { + panic("should not happen: optimized log methods should be used instead") +} + +// UnformattedLog implements dlog.OptimizedLogger. +func (l *logger) UnformattedLog(lvl dlog.LogLevel, args ...any) { + l.log(lvl, func(w io.Writer) { + printer.Fprint(w, args...) + }) +} + +// UnformattedLogln implements dlog.OptimizedLogger. +func (l *logger) UnformattedLogln(lvl dlog.LogLevel, args ...any) { + l.log(lvl, func(w io.Writer) { + printer.Fprintln(w, args...) + }) +} + +// UnformattedLogf implements dlog.OptimizedLogger. +func (l *logger) UnformattedLogf(lvl dlog.LogLevel, format string, args ...any) { + l.log(lvl, func(w io.Writer) { + printer.Fprintf(w, format, args...) + }) +} + +var ( + logBuf bytes.Buffer + logMu sync.Mutex + thisModDir string +) + +func init() { + _, file, _, _ := runtime.Caller(0) + thisModDir = filepath.Dir(filepath.Dir(filepath.Dir(file))) +} + +func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { + // boilerplate ///////////////////////////////////////////////////////// + if lvl > l.lvl { + return + } + // This is optimized for mostly-single-threaded usage. If I cared more + // about multi-threaded performance, I'd trade in some + // memory-use/allocations and (1) instead of using a static `logBuf`, + // I'd have a `logBufPool` `sync.Pool`, and (2) have the the final call + // to `l.out.Write()` be the only thing protected by `logMu`. + logMu.Lock() + defer logMu.Unlock() + defer logBuf.Reset() + + // time //////////////////////////////////////////////////////////////// + now := time.Now() + const timeFmt = "2006-01-02 15:04:05.0000" + logBuf.WriteString(timeFmt) + now.AppendFormat(logBuf.Bytes()[:0], timeFmt) + + // level /////////////////////////////////////////////////////////////// + switch lvl { + case dlog.LogLevelError: + logBuf.WriteString(" ERR") + case dlog.LogLevelWarn: + logBuf.WriteString(" WRN") + case dlog.LogLevelInfo: + logBuf.WriteString(" INF") + case dlog.LogLevelDebug: + logBuf.WriteString(" DBG") + case dlog.LogLevelTrace: + logBuf.WriteString(" TRC") + } + + // fields (early) ////////////////////////////////////////////////////// + fields := make(map[string]any) + var fieldKeys []string + for f := l; f.parent != nil; f = f.parent { + if _, exists := fields[f.fieldKey]; exists { + continue + } + fields[f.fieldKey] = f.fieldVal + fieldKeys = append(fieldKeys, f.fieldKey) + } + sort.Slice(fieldKeys, func(i, j int) bool { + iOrd := fieldOrd(fieldKeys[i]) + jOrd := fieldOrd(fieldKeys[j]) + if iOrd != jOrd { + return iOrd < jOrd + } + return fieldKeys[i] < fieldKeys[j] + }) + nextField := len(fieldKeys) + for i, fieldKey := range fieldKeys { + if fieldOrd(fieldKey) >= 0 { + nextField = i + break + } + printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + } + + // message ///////////////////////////////////////////////////////////// + logBuf.WriteString(" : ") + writeMsg(&logBuf) + + // fields (late) /////////////////////////////////////////////////////// + if nextField < len(fieldKeys) { + logBuf.WriteString(" :") + } + for _, fieldKey := range fieldKeys[nextField:] { + printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + } + + // caller ////////////////////////////////////////////////////////////// + const ( + thisModule = "git.lukeshu.com/btrfs-progs-ng" + thisPackage = "git.lukeshu.com/btrfs-progs-ng/lib/textui" + maximumCallerDepth int = 25 + minimumCallerDepth int = 3 // runtime.Callers + .log + .Log + ) + var pcs [maximumCallerDepth]uintptr + depth := runtime.Callers(minimumCallerDepth, pcs[:]) + frames := runtime.CallersFrames(pcs[:depth]) + for f, again := frames.Next(); again; f, again = frames.Next() { + if !strings.HasPrefix(f.Function, thisModule+"/") { + continue + } + if strings.HasPrefix(f.Function, thisPackage+".") { + continue + } + if nextField == len(fieldKeys) { + logBuf.WriteString(" :") + } + file := f.File[strings.LastIndex(f.File, thisModDir+"/")+len(thisModDir+"/"):] + fmt.Fprintf(&logBuf, " (from %s:%d)", file, f.Line) + break + } + + // boilerplate ///////////////////////////////////////////////////////// + logBuf.WriteByte('\n') + _, _ = l.out.Write(logBuf.Bytes()) +} + +// fieldOrd returns the sort-position for a given log-field-key. Lower return +// values should be positioned on the left when logging, and higher values +// should be positioned on the right; values <0 should be on the left of the log +// message, while values ≥0 should be on the right of the log message. +func fieldOrd(key string) int { + switch key { + case "THREAD": // dgroup + return -7 + case "dexec.pid": + return -6 + case "dexec.stream": + return -5 + case "dexec.data": + return -4 + case "dexec.err": + return -3 + default: + return 1 + } } -func NewLogger(lvl logrus.Level) dlog.Logger { - logger := logrus.New() - logger.SetLevel(lvl) - return dlog.WrapLogrus(logger) +func fieldName(key string) string { + switch key { + case "THREAD": + return "thread" + default: + return key + } } -- cgit v1.2.3-2-g168b From 26a23c51f9b3e22ef3e68d0d174d118a78dd4172 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Sun, 25 Dec 2022 23:46:53 -0700 Subject: tree-wide, except rebuildnodes: Fuss with logging to take advantage of textui --- lib/textui/log.go | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-) (limited to 'lib/textui/log.go') diff --git a/lib/textui/log.go b/lib/textui/log.go index ca8c201..4421074 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -280,6 +280,14 @@ func fieldOrd(key string) int { return -4 case "dexec.err": return -3 + + case "btrfsinspect.scandevices.dev": + return -1 + case "btrfsinspect.rebuild-mappings.step": + return -2 + case "btrfsinspect.rebuild-mappings.substep": + return -1 + default: return 1 } @@ -290,6 +298,13 @@ func fieldName(key string) string { case "THREAD": return "thread" default: - return key + switch { + case strings.HasPrefix(key, "btrfsinspect.scandevices."): + return strings.TrimPrefix(key, "btrfsinspect.scandevices.") + case strings.HasPrefix(key, "btrfsinspect.rebuild-mappings."): + return strings.TrimPrefix(key, "btrfsinspect.rebuild-mappings.") + default: + return key + } } } -- cgit v1.2.3-2-g168b From d5737a0e71b17a97b82ae68e49acc41a08fcc0ad Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Mon, 26 Dec 2022 22:02:13 -0700 Subject: cmd/btrfs-rec: Add a utility function for reading JSON files with progress --- lib/textui/log.go | 4 ++++ 1 file changed, 4 insertions(+) (limited to 'lib/textui/log.go') diff --git a/lib/textui/log.go b/lib/textui/log.go index 4421074..e94a24f 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -288,6 +288,8 @@ func fieldOrd(key string) int { case "btrfsinspect.rebuild-mappings.substep": return -1 + case "btrfs.read-json-file": + return -1 default: return 1 } @@ -303,6 +305,8 @@ func fieldName(key string) string { return strings.TrimPrefix(key, "btrfsinspect.scandevices.") case strings.HasPrefix(key, "btrfsinspect.rebuild-mappings."): return strings.TrimPrefix(key, "btrfsinspect.rebuild-mappings.") + case strings.HasPrefix(key, "btrfs."): + return strings.TrimPrefix(key, "btrfs.") default: return key } -- cgit v1.2.3-2-g168b From 6e8e2960c5412685c1ac87c20b4d34d2caf90640 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Mon, 26 Dec 2022 16:32:15 -0700 Subject: rebuildnodes: Fuss with logging to take advantage of textui --- lib/textui/log.go | 124 +++++++++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 104 insertions(+), 20 deletions(-) (limited to 'lib/textui/log.go') diff --git a/lib/textui/log.go b/lib/textui/log.go index e94a24f..5ddc7a8 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -18,9 +18,11 @@ import ( "path/filepath" "runtime" "sort" + "strconv" "strings" "sync" "time" + "unicode" "github.com/datawire/dlib/dlog" "github.com/spf13/pflag" @@ -219,7 +221,7 @@ func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { nextField = i break } - printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + writeField(&logBuf, fieldKey, fields[fieldKey]) } // message ///////////////////////////////////////////////////////////// @@ -231,7 +233,7 @@ func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { logBuf.WriteString(" :") } for _, fieldKey := range fieldKeys[nextField:] { - printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + writeField(&logBuf, fieldKey, fields[fieldKey]) } // caller ////////////////////////////////////////////////////////////// @@ -270,24 +272,65 @@ func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { // message, while values ≥0 should be on the right of the log message. func fieldOrd(key string) int { switch key { + // dlib //////////////////////////////////////////////////////////////// case "THREAD": // dgroup - return -7 + return -99 case "dexec.pid": - return -6 + return -98 case "dexec.stream": - return -5 + return -97 case "dexec.data": - return -4 + return -96 case "dexec.err": - return -3 + return -95 + // btrfsinspect scandevices //////////////////////////////////////////// case "btrfsinspect.scandevices.dev": return -1 + + // btrfsinspect rebuild-mappings /////////////////////////////////////// case "btrfsinspect.rebuild-mappings.step": return -2 case "btrfsinspect.rebuild-mappings.substep": return -1 + // btrfsinspect rebuild-nodes ////////////////////////////////////////// + case "btrfsinspect.rebuild-nodes.step": + return -50 + // step=read-fs-data + case "btrfsinspect.rebuild-nodes.read.substep": + return -1 + // step=rebuild + case "btrfsinspect.rebuild-nodes.rebuild.pass": + return -49 + case "btrfsinspect.rebuild-nodes.rebuild.substep": + return -48 + case "btrfsinspect.rebuild-nodes.rebuild.substep.progress": + return -47 + // step=rebuild, substep=collect-items (1/3) + // step=rebuild, substep=process-items (2/3) + case "btrfsinspect.rebuild-nodes.rebuild.process.item": + return -25 + // step=rebuild, substep=apply-augments (3/3) + case "btrfsinspect.rebuild-nodes.rebuild.augment.tree": + return -25 + // step=rebuild (any substep) + case "btrfsinspect.rebuild-nodes.rebuild.want.key": + return -7 + case "btrfsinspect.rebuild-nodes.rebuild.want.reason": + return -6 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree": + return -5 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree.substep": + return -4 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.key": + return -3 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.reason": + return -2 + case "btrfsinspect.rebuild-nodes.rebuild.add-root": + return -1 + + // other /////////////////////////////////////////////////////////////// case "btrfs.read-json-file": return -1 default: @@ -295,20 +338,61 @@ func fieldOrd(key string) int { } } -func fieldName(key string) string { - switch key { - case "THREAD": - return "thread" - default: - switch { - case strings.HasPrefix(key, "btrfsinspect.scandevices."): - return strings.TrimPrefix(key, "btrfsinspect.scandevices.") - case strings.HasPrefix(key, "btrfsinspect.rebuild-mappings."): - return strings.TrimPrefix(key, "btrfsinspect.rebuild-mappings.") - case strings.HasPrefix(key, "btrfs."): - return strings.TrimPrefix(key, "btrfs.") +func writeField(w io.Writer, key string, val any) { + valStr := printer.Sprint(val) + needsQuote := false + if strings.HasPrefix(valStr, `"`) { + needsQuote = true + } else { + for _, r := range valStr { + if !(unicode.IsPrint(r) && r != ' ') { + needsQuote = true + break + } + } + } + if needsQuote { + valStr = strconv.Quote(valStr) + } + + name := key + + switch { + case name == "THREAD": + name = "thread" + switch valStr { + case "", "/main": + return default: - return key + if strings.HasPrefix(valStr, "/main/") { + valStr = strings.TrimPrefix(valStr, "/main") + } } + case strings.HasSuffix(name, ".pass"): + fmt.Fprintf(w, "/pass-%s", valStr) + return + case strings.HasSuffix(name, ".substep") && name != "btrfsinspect.rebuild-nodes.rebuild.add-tree.substep": + fmt.Fprintf(w, "/%s", valStr) + return + case strings.HasPrefix(name, "btrfsinspect."): + name = strings.TrimPrefix(name, "btrfsinspect.") + switch { + case strings.HasPrefix(name, "scandevices."): + name = strings.TrimPrefix(name, "scandevices.") + case strings.HasPrefix(name, "rebuild-mappings."): + name = strings.TrimPrefix(name, "rebuild-mappings.") + case strings.HasPrefix(name, "rebuild-nodes."): + name = strings.TrimPrefix(name, "rebuild-nodes.") + switch { + case strings.HasPrefix(name, "read."): + name = strings.TrimPrefix(name, "read.") + case strings.HasPrefix(name, "rebuild."): + name = strings.TrimPrefix(name, "rebuild.") + } + } + case strings.HasPrefix(name, "btrfs."): + name = strings.TrimPrefix(name, "btrfs.") } + + fmt.Fprintf(w, " %s=%s", name, valStr) } -- cgit v1.2.3-2-g168b