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-54-g00ecf 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 --- cmd/btrfs-rec/main.go | 5 +- lib/textui/log.go | 282 +++++++++++++++++++++++++++++++++++++++++++++++-- lib/textui/log_test.go | 64 +++++++++++ 3 files changed, 338 insertions(+), 13 deletions(-) create mode 100644 lib/textui/log_test.go (limited to 'lib/textui/log.go') diff --git a/cmd/btrfs-rec/main.go b/cmd/btrfs-rec/main.go index d14675d..1135be2 100644 --- a/cmd/btrfs-rec/main.go +++ b/cmd/btrfs-rec/main.go @@ -12,7 +12,6 @@ import ( "github.com/datawire/dlib/dgroup" "github.com/datawire/dlib/dlog" "github.com/datawire/ocibuild/pkg/cliutil" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs" @@ -30,7 +29,7 @@ var inspectors, repairers []subcommand func main() { logLevelFlag := textui.LogLevelFlag{ - Level: logrus.InfoLevel, + Level: dlog.LogLevelInfo, } var pvsFlag []string var mappingsFlag string @@ -101,7 +100,7 @@ func main() { runE := child.RunE cmd.RunE = func(cmd *cobra.Command, args []string) error { ctx := cmd.Context() - ctx = dlog.WithLogger(ctx, textui.NewLogger(logLevelFlag.Level)) + ctx = dlog.WithLogger(ctx, textui.NewLogger(os.Stderr, logLevelFlag.Level)) grp := dgroup.NewGroup(ctx, dgroup.GroupConfig{ EnableSignalHandling: true, 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 + } } diff --git a/lib/textui/log_test.go b/lib/textui/log_test.go new file mode 100644 index 0000000..08eb38c --- /dev/null +++ b/lib/textui/log_test.go @@ -0,0 +1,64 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package textui_test + +import ( + "context" + "strings" + "testing" + + "github.com/datawire/dlib/dlog" + "github.com/stretchr/testify/assert" + + "git.lukeshu.com/btrfs-progs-ng/lib/textui" +) + +func logLineRegexp(inner string) string { + return `[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]{4} ` + inner + ` \(from lib/textui/log_test\.go:[0-9]+\)\n` +} + +func TestLogFormat(t *testing.T) { + var out strings.Builder + ctx := dlog.WithLogger(context.Background(), textui.NewLogger(&out, dlog.LogLevelTrace)) + dlog.Debugf(ctx, "foo %d", 12345) + assert.Regexp(t, + `^`+logLineRegexp(`DBG : foo 12,345 :`)+`$`, + out.String()) +} + +func TestLogLevel(t *testing.T) { + var out strings.Builder + ctx := dlog.WithLogger(context.Background(), textui.NewLogger(&out, dlog.LogLevelInfo)) + dlog.Error(ctx, "Error") + dlog.Warn(ctx, "Warn") + dlog.Info(ctx, "Info") + dlog.Debug(ctx, "Debug") + dlog.Trace(ctx, "Trace") + dlog.Trace(ctx, "Trace") + dlog.Debug(ctx, "Debug") + dlog.Info(ctx, "Info") + dlog.Warn(ctx, "Warn") + dlog.Error(ctx, "Error") + assert.Regexp(t, + `^`+ + logLineRegexp(`ERR : Error :`)+ + logLineRegexp(`WRN : Warn :`)+ + logLineRegexp(`INF : Info :`)+ + logLineRegexp(`INF : Info :`)+ + logLineRegexp(`WRN : Warn :`)+ + logLineRegexp(`ERR : Error :`)+ + `$`, + out.String()) +} + +func TestLogField(t *testing.T) { + var out strings.Builder + ctx := dlog.WithLogger(context.Background(), textui.NewLogger(&out, dlog.LogLevelInfo)) + ctx = dlog.WithField(ctx, "foo", 12345) + dlog.Info(ctx, "msg") + assert.Regexp(t, + `^`+logLineRegexp(`INF : msg : foo=12,345`)+`$`, + out.String()) +} -- cgit v1.2.3-54-g00ecf 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 --- .../btrfsinspect/rebuildmappings/fuzzymatchsums.go | 16 ++++--- .../btrfsinspect/rebuildmappings/matchsums.go | 6 +-- .../rebuildmappings/rebuildmappings.go | 44 ++++++++++------- lib/btrfsprogs/btrfsinspect/scandevices.go | 56 +++++++++++----------- lib/textui/log.go | 17 ++++++- 5 files changed, 82 insertions(+), 57 deletions(-) (limited to 'lib/textui/log.go') diff --git a/lib/btrfsprogs/btrfsinspect/rebuildmappings/fuzzymatchsums.go b/lib/btrfsprogs/btrfsinspect/rebuildmappings/fuzzymatchsums.go index 0b5fc6f..ae83513 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildmappings/fuzzymatchsums.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildmappings/fuzzymatchsums.go @@ -43,7 +43,10 @@ func fuzzyMatchBlockGroupSums(ctx context.Context, physicalSums map[btrfsvol.DeviceID]btrfssum.SumRun[btrfsvol.PhysicalAddr], logicalSums btrfssum.SumRunWithGaps[btrfsvol.LogicalAddr], ) error { - dlog.Info(ctx, "... Indexing physical regions...") // O(m) + _ctx := ctx + + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.substep", "indexing") + dlog.Info(ctx, "Indexing physical regions...") // O(m) regions := ListUnmappedPhysicalRegions(fs) physicalIndex := make(map[btrfssum.ShortSum][]btrfsvol.QualifiedPhysicalAddr) if err := WalkUnmappedPhysicalRegions(ctx, physicalSums, regions, func(devID btrfsvol.DeviceID, region btrfssum.SumRun[btrfsvol.PhysicalAddr]) error { @@ -57,9 +60,10 @@ func fuzzyMatchBlockGroupSums(ctx context.Context, }); err != nil { return err } - dlog.Info(ctx, "... ... done indexing") + dlog.Info(ctx, "... done indexing") - dlog.Info(ctx, "... Searching...") + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.substep", "searching") + dlog.Info(ctx, "Searching...") numBlockgroups := len(blockgroups) for i, bgLAddr := range maps.SortedKeys(blockgroups) { blockgroup := blockgroups[bgLAddr] @@ -108,7 +112,7 @@ func fuzzyMatchBlockGroupSums(ctx context.Context, if apply { lvl = dlog.LogLevelInfo } - dlog.Logf(ctx, lvl, "... (%v/%v) blockgroup[laddr=%v] matches=[%s]; bestpossible=%v%% (based on %v runs)", + dlog.Logf(ctx, lvl, "(%v/%v) blockgroup[laddr=%v] matches=[%s]; bestpossible=%v%% (based on %v runs)", i+1, numBlockgroups, bgLAddr, matchesStr, int(100*bgRun.PctFull()), len(bgRun.Runs)) if !apply { continue @@ -125,12 +129,12 @@ func fuzzyMatchBlockGroupSums(ctx context.Context, }, } if err := fs.LV.AddMapping(mapping); err != nil { - dlog.Errorf(ctx, "... error: %v", err) + dlog.Errorf(ctx, "error: %v", err) continue } delete(blockgroups, bgLAddr) } - dlog.Info(ctx, "... ... done searching") + dlog.Info(ctx, "done searching") return nil } diff --git a/lib/btrfsprogs/btrfsinspect/rebuildmappings/matchsums.go b/lib/btrfsprogs/btrfsinspect/rebuildmappings/matchsums.go index 6a8333a..be82f87 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildmappings/matchsums.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildmappings/matchsums.go @@ -29,7 +29,7 @@ func matchBlockGroupSums(ctx context.Context, blockgroup := blockgroups[bgLAddr] bgRun := SumsForLogicalRegion(logicalSums, blockgroup.LAddr, blockgroup.Size) if len(bgRun.Runs) == 0 { - dlog.Errorf(ctx, "... (%v/%v) blockgroup[laddr=%v] can't be matched because it has 0 runs", + dlog.Errorf(ctx, "(%v/%v) blockgroup[laddr=%v] can't be matched because it has 0 runs", i+1, numBlockgroups, bgLAddr) continue } @@ -55,7 +55,7 @@ func matchBlockGroupSums(ctx context.Context, if len(matches) == 1 { lvl = dlog.LogLevelInfo } - dlog.Logf(ctx, lvl, "... (%v/%v) blockgroup[laddr=%v] has %v matches based on %v%% coverage from %v runs", + dlog.Logf(ctx, lvl, "(%v/%v) blockgroup[laddr=%v] has %v matches based on %v%% coverage from %v runs", i+1, numBlockgroups, bgLAddr, len(matches), int(100*bgRun.PctFull()), len(bgRun.Runs)) if len(matches) != 1 { continue @@ -72,7 +72,7 @@ func matchBlockGroupSums(ctx context.Context, }, } if err := fs.LV.AddMapping(mapping); err != nil { - dlog.Errorf(ctx, "... error: %v", err) + dlog.Errorf(ctx, "error: %v", err) continue } delete(blockgroups, bgLAddr) diff --git a/lib/btrfsprogs/btrfsinspect/rebuildmappings/rebuildmappings.go b/lib/btrfsprogs/btrfsinspect/rebuildmappings/rebuildmappings.go index 5d44b4e..9807764 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildmappings/rebuildmappings.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildmappings/rebuildmappings.go @@ -53,35 +53,39 @@ func RebuildMappings(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect dlog.Infof(ctx, "plan: 5/6 search for block groups in checksum map (exact)") dlog.Infof(ctx, "plan: 6/6 search for block groups in checksum map (fuzzy)") - dlog.Infof(ctx, "1/6: Processing %d chunks...", numChunks) + _ctx := ctx + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.step", "1/6") + dlog.Infof(_ctx, "1/6: Processing %d chunks...", numChunks) for _, devID := range devIDs { devResults := scanResults[devID] for _, chunk := range devResults.FoundChunks { for _, mapping := range chunk.Chunk.Mappings(chunk.Key) { if err := fs.LV.AddMapping(mapping); err != nil { - dlog.Errorf(ctx, "... error: adding chunk: %v", err) + dlog.Errorf(ctx, "error: adding chunk: %v", err) } } } } - dlog.Info(ctx, "... done processing chunks") + dlog.Info(_ctx, "... done processing chunks") - dlog.Infof(ctx, "2/6: Processing %d device extents...", numDevExts) + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.step", "2/6") + dlog.Infof(_ctx, "2/6: Processing %d device extents...", numDevExts) for _, devID := range devIDs { devResults := scanResults[devID] for _, ext := range devResults.FoundDevExtents { if err := fs.LV.AddMapping(ext.DevExt.Mapping(ext.Key)); err != nil { - dlog.Errorf(ctx, "... error: adding devext: %v", err) + dlog.Errorf(ctx, "error: adding devext: %v", err) } } } - dlog.Info(ctx, "... done processing device extents") + dlog.Info(_ctx, "... done processing device extents") // Do the nodes "last" to avoid bloating the mappings table // too much. (Because nodes are numerous and small, while the // others are few and large; so it is likely that many of the // nodes will be subsumed by other things.) - dlog.Infof(ctx, "3/6: Processing %d nodes...", numNodes) + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.step", "3/6") + dlog.Infof(_ctx, "3/6: Processing %d nodes...", numNodes) for _, devID := range devIDs { devResults := scanResults[devID] // Sort them so that progress numbers are predictable. @@ -96,16 +100,17 @@ func RebuildMappings(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect Size: nodeSize, SizeLocked: false, }); err != nil { - dlog.Errorf(ctx, "... error: adding node ident: %v", err) + dlog.Errorf(ctx, "error: adding node ident: %v", err) } } } } - dlog.Info(ctx, "... done processing nodes") + dlog.Info(_ctx, "... done processing nodes") // Use block groups to add missing flags (and as a hint to // combine node entries). - dlog.Infof(ctx, "4/6: Processing %d block groups...", numBlockGroups) + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.step", "4/6") + dlog.Infof(_ctx, "4/6: Processing %d block groups...", numBlockGroups) // First dedup them, because they change for allocations and // CoW means that they'll bounce around a lot, so you likely // have oodles of duplicates? @@ -118,7 +123,7 @@ func RebuildMappings(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect bg := bgs[bgLAddr] otherLAddr, otherPAddr := fs.LV.ResolveAny(bg.LAddr, bg.Size) if otherLAddr < 0 || otherPAddr.Addr < 0 { - dlog.Errorf(ctx, "... error: could not pair blockgroup laddr=%v (size=%v flags=%v) with a mapping", + dlog.Errorf(ctx, "error: could not pair blockgroup laddr=%v (size=%v flags=%v) with a mapping", bg.LAddr, bg.Size, bg.Flags) continue } @@ -135,14 +140,15 @@ func RebuildMappings(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect }, } if err := fs.LV.AddMapping(mapping); err != nil { - dlog.Errorf(ctx, "... error: adding flags from blockgroup: %v", err) + dlog.Errorf(ctx, "error: adding flags from blockgroup: %v", err) continue } delete(bgs, bgLAddr) } - dlog.Info(ctx, "... done processing block groups") + dlog.Info(_ctx, "... done processing block groups") - dlog.Infof(ctx, "5/6: Searching for %d block groups in checksum map (exact)...", len(bgs)) + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.step", "5/6") + dlog.Infof(_ctx, "5/6: Searching for %d block groups in checksum map (exact)...", len(bgs)) physicalSums := ExtractPhysicalSums(scanResults) logicalSums := ExtractLogicalSums(ctx, scanResults) if err := matchBlockGroupSums(ctx, fs, bgs, physicalSums, logicalSums); err != nil { @@ -150,13 +156,15 @@ func RebuildMappings(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect } dlog.Info(ctx, "... done searching for exact block groups") - dlog.Infof(ctx, "6/6: Searching for %d block groups in checksum map (fuzzy)...", len(bgs)) + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.step", "6/6") + dlog.Infof(_ctx, "6/6: Searching for %d block groups in checksum map (fuzzy)...", len(bgs)) if err := fuzzyMatchBlockGroupSums(ctx, fs, bgs, physicalSums, logicalSums); err != nil { return err } - dlog.Info(ctx, "... done searching for fuzzy block groups") + dlog.Info(_ctx, "... done searching for fuzzy block groups") - dlog.Info(ctx, "report:") + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-mappings.step", "report") + dlog.Info(_ctx, "report:") unmappedPhysicalRegions := ListUnmappedPhysicalRegions(fs) var unmappedPhysical btrfsvol.AddrDelta @@ -182,7 +190,7 @@ func RebuildMappings(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect } dlog.Infof(ctx, "... %d KiB of unmapped block groups (across %d groups)", int(unmappedBlockGroups/1024), len(bgs)) - dlog.Info(ctx, "detailed report:") + dlog.Info(_ctx, "detailed report:") for _, devID := range maps.SortedKeys(unmappedPhysicalRegions) { for _, region := range unmappedPhysicalRegions[devID] { dlog.Infof(ctx, "... unmapped physical region: dev=%v beg=%v end=%v (size=%v)", diff --git a/lib/btrfsprogs/btrfsinspect/scandevices.go b/lib/btrfsprogs/btrfsinspect/scandevices.go index b6c929b..628995a 100644 --- a/lib/btrfsprogs/btrfsinspect/scandevices.go +++ b/lib/btrfsprogs/btrfsinspect/scandevices.go @@ -34,7 +34,7 @@ func ScanDevices(ctx context.Context, fs *btrfs.FS) (ScanDevicesResult, error) { for id, dev := range fs.LV.PhysicalVolumes() { id := id dev := dev - grp.Go(dev.Name(), func(ctx context.Context) error { + grp.Go(fmt.Sprintf("dev-%d", id), func(ctx context.Context) error { sb, err := dev.Superblock() if err != nil { return err @@ -80,10 +80,7 @@ type SysExtentCSum struct { } type scanStats struct { - DevName string - DevSize btrfsvol.PhysicalAddr - - Pos btrfsvol.PhysicalAddr + textui.Portion[btrfsvol.PhysicalAddr] NumFoundNodes int NumFoundChunks int @@ -93,10 +90,8 @@ type scanStats struct { } func (s scanStats) String() string { - return fmt.Sprintf("... dev[%q] scanned %v%% (%d/%d) (found: %v nodes, %v chunks, %v block groups, %v dev extents, %v sum items)", - s.DevName, - int(100*float64(s.Pos)/float64(s.DevSize)), - s.Pos, s.DevSize, + return textui.Sprintf("scanned %v (found: %v nodes, %v chunks, %v block groups, %v dev extents, %v sum items)", + s.Portion, s.NumFoundNodes, s.NumFoundChunks, s.NumFoundBlockGroups, @@ -107,6 +102,8 @@ func (s scanStats) String() string { // ScanOneDevice mostly mimics btrfs-progs // cmds/rescue-chunk-recover.c:scan_one_device(). func ScanOneDevice(ctx context.Context, dev *btrfs.Device, sb btrfstree.Superblock) (ScanOneDeviceResult, error) { + ctx = dlog.WithField(ctx, "btrfsinspect.scandevices.dev", dev.Name()) + result := ScanOneDeviceResult{ FoundNodes: make(map[btrfsvol.LogicalAddr][]btrfsvol.PhysicalAddr), } @@ -132,9 +129,10 @@ func ScanOneDevice(ctx context.Context, dev *btrfs.Device, sb btrfstree.Superblo progressWriter := textui.NewProgress[scanStats](ctx, dlog.LogLevelInfo, 1*time.Second) progress := func(pos btrfsvol.PhysicalAddr) { progressWriter.Set(scanStats{ - DevName: dev.Name(), - DevSize: devSize, - Pos: pos, + Portion: textui.Portion[btrfsvol.PhysicalAddr]{ + N: pos, + D: devSize, + }, NumFoundNodes: len(result.FoundNodes), NumFoundChunks: len(result.FoundChunks), NumFoundBlockGroups: len(result.FoundBlockGroups), @@ -171,7 +169,7 @@ func ScanOneDevice(ctx context.Context, dev *btrfs.Device, sb btrfstree.Superblo nodeRef, err := btrfstree.ReadNode[btrfsvol.PhysicalAddr](dev, sb, pos, btrfstree.NodeExpectations{}) if err != nil { if !errors.Is(err, btrfstree.ErrNotANode) { - dlog.Errorf(ctx, "... dev[%q] error: %v", dev.Name(), err) + dlog.Errorf(ctx, "error: %v", err) } } else { result.FoundNodes[nodeRef.Data.Head.Addr] = append(result.FoundNodes[nodeRef.Data.Head.Addr], nodeRef.Addr) @@ -180,12 +178,12 @@ func ScanOneDevice(ctx context.Context, dev *btrfs.Device, sb btrfstree.Superblo case btrfsitem.CHUNK_ITEM_KEY: chunk, ok := item.Body.(btrfsitem.Chunk) if !ok { - dlog.Errorf(ctx, "... dev[%q] node@%v: item %v: error: type is CHUNK_ITEM_KEY, but struct is %T", - dev.Name(), nodeRef.Addr, i, item.Body) + dlog.Errorf(ctx, "node@%v: item %v: error: type is CHUNK_ITEM_KEY, but struct is %T", + nodeRef.Addr, i, item.Body) continue } - //dlog.Tracef(ctx, "... dev[%q] node@%v: item %v: found chunk", - // dev.Name(), nodeRef.Addr, i) + dlog.Tracef(ctx, "node@%v: item %v: found chunk", + nodeRef.Addr, i) result.FoundChunks = append(result.FoundChunks, btrfstree.SysChunk{ Key: item.Key, Chunk: chunk, @@ -193,12 +191,12 @@ func ScanOneDevice(ctx context.Context, dev *btrfs.Device, sb btrfstree.Superblo case btrfsitem.BLOCK_GROUP_ITEM_KEY: bg, ok := item.Body.(btrfsitem.BlockGroup) if !ok { - dlog.Errorf(ctx, "... dev[%q] node@%v: item %v: error: type is BLOCK_GROUP_ITEM_KEY, but struct is %T", - dev.Name(), nodeRef.Addr, i, item.Body) + dlog.Errorf(ctx, "node@%v: item %v: error: type is BLOCK_GROUP_ITEM_KEY, but struct is %T", + nodeRef.Addr, i, item.Body) continue } - //dlog.Tracef(ctx, "... dev[%q] node@%v: item %v: found block group", - // dev.Name(), nodeRef.Addr, i) + dlog.Tracef(ctx, "node@%v: item %v: found block group", + nodeRef.Addr, i) result.FoundBlockGroups = append(result.FoundBlockGroups, SysBlockGroup{ Key: item.Key, BG: bg, @@ -206,12 +204,12 @@ func ScanOneDevice(ctx context.Context, dev *btrfs.Device, sb btrfstree.Superblo case btrfsitem.DEV_EXTENT_KEY: devext, ok := item.Body.(btrfsitem.DevExtent) if !ok { - dlog.Errorf(ctx, "... dev[%q] node@%v: item %v: error: type is DEV_EXTENT_KEY, but struct is %T", - dev.Name(), nodeRef.Addr, i, item.Body) + dlog.Errorf(ctx, "node@%v: item %v: error: type is DEV_EXTENT_KEY, but struct is %T", + nodeRef.Addr, i, item.Body) continue } - //dlog.Tracef(ctx, "... dev[%q] node@%v: item %v: found dev extent", - // dev.Name(), nodeRef.Addr, i) + dlog.Tracef(ctx, "node@%v: item %v: found dev extent", + nodeRef.Addr, i) result.FoundDevExtents = append(result.FoundDevExtents, SysDevExtent{ Key: item.Key, DevExt: devext, @@ -219,12 +217,12 @@ func ScanOneDevice(ctx context.Context, dev *btrfs.Device, sb btrfstree.Superblo case btrfsitem.EXTENT_CSUM_KEY: sums, ok := item.Body.(btrfsitem.ExtentCSum) if !ok { - dlog.Errorf(ctx, "... dev[%q] node@%v: item %v: error: type is EXTENT_CSUM_OBJECTID, but struct is %T", - dev.Name(), nodeRef.Addr, i, item.Body) + dlog.Errorf(ctx, "node@%v: item %v: error: type is EXTENT_CSUM_OBJECTID, but struct is %T", + nodeRef.Addr, i, item.Body) continue } - //dlog.Tracef(ctx, "... dev[%q] node@%v: item %v: found csums", - // dev.Name(), nodeRef.Addr, i) + dlog.Tracef(ctx, "node@%v: item %v: found csums", + nodeRef.Addr, i) result.FoundExtentCSums = append(result.FoundExtentCSums, SysExtentCSum{ Generation: nodeRef.Data.Head.Generation, Sums: sums, 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-54-g00ecf 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 --- cmd/btrfs-rec/inspect_lstrees.go | 12 ++--- cmd/btrfs-rec/inspect_rebuildmappings.go | 3 +- cmd/btrfs-rec/inspect_rebuildnodes.go | 3 +- cmd/btrfs-rec/inspect_scandevices.go | 14 ------ cmd/btrfs-rec/main.go | 7 +-- cmd/btrfs-rec/util.go | 83 ++++++++++++++++++++++++++++++++ lib/textui/log.go | 4 ++ 7 files changed, 97 insertions(+), 29 deletions(-) create mode 100644 cmd/btrfs-rec/util.go (limited to 'lib/textui/log.go') diff --git a/cmd/btrfs-rec/inspect_lstrees.go b/cmd/btrfs-rec/inspect_lstrees.go index 7f59eaa..e92c544 100644 --- a/cmd/btrfs-rec/inspect_lstrees.go +++ b/cmd/btrfs-rec/inspect_lstrees.go @@ -5,7 +5,6 @@ package main import ( - "encoding/json" "os" "strconv" "text/tabwriter" @@ -36,15 +35,14 @@ func init() { Args: cliutil.WrapPositionalArgs(cobra.NoArgs), }, RunE: func(fs *btrfs.FS, cmd *cobra.Command, _ []string) error { - var scanResults map[btrfsvol.DeviceID]btrfsinspect.ScanOneDeviceResult + ctx := cmd.Context() + var scanResults btrfsinspect.ScanDevicesResult if scandevicesFilename != "" { - scanResultsBytes, err := os.ReadFile(scandevicesFilename) + var err error + scanResults, err = readJSONFile[btrfsinspect.ScanDevicesResult](ctx, scandevicesFilename) if err != nil { return err } - if err := json.Unmarshal(scanResultsBytes, &scanResults); err != nil { - return err - } } var treeErrCnt int @@ -65,7 +63,7 @@ func init() { table.Flush() } visitedNodes := make(containers.Set[btrfsvol.LogicalAddr]) - btrfsutil.WalkAllTrees(cmd.Context(), fs, btrfsutil.WalkAllTreesHandler{ + btrfsutil.WalkAllTrees(ctx, fs, btrfsutil.WalkAllTreesHandler{ PreTree: func(name string, treeID btrfsprim.ObjID) { treeErrCnt = 0 treeItemCnt = make(map[btrfsitem.Type]int) diff --git a/cmd/btrfs-rec/inspect_rebuildmappings.go b/cmd/btrfs-rec/inspect_rebuildmappings.go index 54535ec..da7d12e 100644 --- a/cmd/btrfs-rec/inspect_rebuildmappings.go +++ b/cmd/btrfs-rec/inspect_rebuildmappings.go @@ -15,6 +15,7 @@ import ( "github.com/spf13/cobra" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs" + "git.lukeshu.com/btrfs-progs-ng/lib/btrfsprogs/btrfsinspect" "git.lukeshu.com/btrfs-progs-ng/lib/btrfsprogs/btrfsinspect/rebuildmappings" ) @@ -37,7 +38,7 @@ func init() { ctx := cmd.Context() dlog.Infof(ctx, "Reading %q...", args[0]) - scanResults, err := readScanResults(args[0]) + scanResults, err := readJSONFile[btrfsinspect.ScanDevicesResult](ctx, args[0]) if err != nil { return err } diff --git a/cmd/btrfs-rec/inspect_rebuildnodes.go b/cmd/btrfs-rec/inspect_rebuildnodes.go index 5f6d9b5..0f3d60e 100644 --- a/cmd/btrfs-rec/inspect_rebuildnodes.go +++ b/cmd/btrfs-rec/inspect_rebuildnodes.go @@ -17,6 +17,7 @@ import ( "git.lukeshu.com/btrfs-progs-ng/lib/btrfs" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsprim" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsvol" + "git.lukeshu.com/btrfs-progs-ng/lib/btrfsprogs/btrfsinspect" "git.lukeshu.com/btrfs-progs-ng/lib/btrfsprogs/btrfsinspect/rebuildnodes" "git.lukeshu.com/btrfs-progs-ng/lib/containers" ) @@ -31,7 +32,7 @@ func init() { ctx := cmd.Context() dlog.Infof(ctx, "Reading %q...", args[0]) - nodeScanResults, err := readScanResults(args[0]) + nodeScanResults, err := readJSONFile[btrfsinspect.ScanDevicesResult](ctx, args[0]) if err != nil { return err } diff --git a/cmd/btrfs-rec/inspect_scandevices.go b/cmd/btrfs-rec/inspect_scandevices.go index 5c8b2b0..7235e45 100644 --- a/cmd/btrfs-rec/inspect_scandevices.go +++ b/cmd/btrfs-rec/inspect_scandevices.go @@ -58,17 +58,3 @@ func writeScanResults(w io.Writer, results btrfsinspect.ScanDevicesResult) (err CompactIfUnder: 16, }, results) } - -func readScanResults(filename string) (btrfsinspect.ScanDevicesResult, error) { - fh, err := os.Open(filename) - if err != nil { - return nil, err - } - var scanResults btrfsinspect.ScanDevicesResult - buf := bufio.NewReader(fh) - if err := lowmemjson.DecodeThenEOF(buf, &scanResults); err != nil { - return nil, err - } - _ = fh.Close() - return scanResults, nil -} diff --git a/cmd/btrfs-rec/main.go b/cmd/btrfs-rec/main.go index 3a00544..87e8696 100644 --- a/cmd/btrfs-rec/main.go +++ b/cmd/btrfs-rec/main.go @@ -6,7 +6,6 @@ package main import ( "context" - "encoding/json" "os" "github.com/datawire/dlib/dgroup" @@ -122,14 +121,10 @@ func main() { }() if mappingsFlag != "" { - bs, err := os.ReadFile(mappingsFlag) + mappingsJSON, err := readJSONFile[[]btrfsvol.Mapping](ctx, mappingsFlag) if err != nil { return err } - var mappingsJSON []btrfsvol.Mapping - if err := json.Unmarshal(bs, &mappingsJSON); err != nil { - return err - } for _, mapping := range mappingsJSON { if err := fs.LV.AddMapping(mapping); err != nil { return err diff --git a/cmd/btrfs-rec/util.go b/cmd/btrfs-rec/util.go new file mode 100644 index 0000000..adfe97e --- /dev/null +++ b/cmd/btrfs-rec/util.go @@ -0,0 +1,83 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package main + +import ( + "bufio" + "context" + "io" + "os" + "time" + + "git.lukeshu.com/go/lowmemjson" + "github.com/datawire/dlib/dlog" + + "git.lukeshu.com/btrfs-progs-ng/lib/textui" +) + +type runeScanner struct { + progress textui.Portion[int64] + progressWriter *textui.Progress[textui.Portion[int64]] + unreadCnt uint64 + reader *bufio.Reader + closer io.Closer +} + +func newRuneScanner(ctx context.Context, fh *os.File) (*runeScanner, error) { + fi, err := fh.Stat() + if err != nil { + return nil, err + } + ret := &runeScanner{ + progress: textui.Portion[int64]{ + D: fi.Size(), + }, + progressWriter: textui.NewProgress[textui.Portion[int64]](ctx, dlog.LogLevelInfo, 1*time.Second), + reader: bufio.NewReader(fh), + closer: fh, + } + return ret, nil +} + +func (rs *runeScanner) ReadRune() (r rune, size int, err error) { + r, size, err = rs.reader.ReadRune() + if rs.unreadCnt > 0 { + rs.unreadCnt-- + } else { + rs.progress.N += int64(size) + rs.progressWriter.Set(rs.progress) + } + return +} + +func (rs *runeScanner) UnreadRune() error { + rs.unreadCnt++ + return rs.reader.UnreadRune() +} + +func (rs *runeScanner) Close() error { + rs.progressWriter.Done() + return rs.closer.Close() +} + +func readJSONFile[T any](ctx context.Context, filename string) (T, error) { + fh, err := os.Open(filename) + if err != nil { + var zero T + return zero, err + } + buf, err := newRuneScanner(dlog.WithField(ctx, "btrfs.read-json-file", filename), fh) + if err != nil { + var zero T + return zero, err + } + var ret T + if err := lowmemjson.DecodeThenEOF(buf, &ret); err != nil { + var zero T + return zero, err + } + _ = buf.Close() + return ret, nil +} 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-54-g00ecf 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 --- .../rebuildnodes/btrees/rebuilt_btrees.go | 78 ++++------ .../btrfsinspect/rebuildnodes/graph/graph.go | 23 ++- .../btrfsinspect/rebuildnodes/keyio/keyio.go | 11 +- .../btrfsinspect/rebuildnodes/rebuild.go | 169 +++++++++++---------- .../btrfsinspect/rebuildnodes/rebuild_graph.go | 95 ++++++------ lib/btrfsprogs/btrfsinspect/rebuildnodes/scan.go | 30 ++-- lib/textui/log.go | 124 ++++++++++++--- 7 files changed, 291 insertions(+), 239 deletions(-) (limited to 'lib/textui/log.go') diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/btrees/rebuilt_btrees.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/btrees/rebuilt_btrees.go index 4f0f5d4..33eb352 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/btrees/rebuilt_btrees.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/btrees/rebuilt_btrees.go @@ -168,21 +168,14 @@ func NewRebuiltTrees( } type rootStats struct { - TreeID btrfsprim.ObjID - RootNode btrfsvol.LogicalAddr - - DoneLeafs int - TotalLeafs int + Leafs textui.Portion[int] AddedItems int ReplacedItems int } func (s rootStats) String() string { - return textui.Sprintf("tree %v: adding root node@%v: %v%% (%v/%v) (added %v items, replaced %v items)", - s.TreeID, s.RootNode, - int(100*float64(s.DoneLeafs)/float64(s.TotalLeafs)), - s.DoneLeafs, s.TotalLeafs, - s.AddedItems, s.ReplacedItems) + return textui.Sprintf("%v (added %v items, replaced %v items)", + s.Leafs, s.AddedItems, s.ReplacedItems) } // AddRoot adds an additional root node to an existing tree. It is @@ -192,24 +185,16 @@ func (s rootStats) String() string { // It is invalid (panic) to call AddRoot for a tree without having // called AddTree first. func (ts *RebuiltTrees) AddRoot(ctx context.Context, treeID btrfsprim.ObjID, rootNode btrfsvol.LogicalAddr) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.add-root", fmt.Sprintf("tree=%v rootNode=%v", treeID, rootNode)) tree := ts.trees[treeID] tree.Roots.Insert(rootNode) + var stats rootStats + stats.Leafs.D = len(tree.leafToRoots) progressWriter := textui.NewProgress[rootStats](ctx, dlog.LogLevelInfo, 1*time.Second) - numAdded := 0 - numReplaced := 0 - progress := func(done int) { - progressWriter.Set(rootStats{ - TreeID: treeID, - RootNode: rootNode, - DoneLeafs: done, - TotalLeafs: len(tree.leafToRoots), - AddedItems: numAdded, - ReplacedItems: numReplaced, - }) - } for i, leaf := range maps.SortedKeys(tree.leafToRoots) { - progress(i) + stats.Leafs.N = i + progressWriter.Set(stats) if tree.Leafs.Has(leaf) || !tree.leafToRoots[leaf].Has(rootNode) { continue } @@ -221,16 +206,17 @@ func (ts *RebuiltTrees) AddRoot(ctx context.Context, treeID btrfsprim.ObjID, roo } if oldPtr, exists := tree.Items.Load(itemKey); !exists { tree.Items.Store(itemKey, newPtr) - numAdded++ + stats.AddedItems++ } else if tree.shouldReplace(ts.graph, oldPtr.Node, newPtr.Node) { tree.Items.Store(itemKey, newPtr) - numReplaced++ + stats.ReplacedItems++ } ts.cbAddedItem(ctx, treeID, itemKey) - progress(i) + progressWriter.Set(stats) } } - progress(len(tree.leafToRoots)) + stats.Leafs.N = len(tree.leafToRoots) + progressWriter.Set(stats) progressWriter.Done() } @@ -250,6 +236,9 @@ func (ts *RebuiltTrees) addTree(ctx context.Context, treeID btrfsprim.ObjID, sta if slices.Contains(treeID, stack) { return false } + stack = append(stack, treeID) + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.add-tree", stack) + dlog.Info(ctx, "adding tree...") tree := &rebuiltTree{ ID: treeID, @@ -267,7 +256,6 @@ func (ts *RebuiltTrees) addTree(ctx context.Context, treeID btrfsprim.ObjID, sta case btrfsprim.BLOCK_GROUP_TREE_OBJECTID: root = ts.sb.BlockGroupRoot default: - stack := append(stack, treeID) if !ts.addTree(ctx, btrfsprim.ROOT_TREE_OBJECTID, stack) { return false } @@ -279,7 +267,7 @@ func (ts *RebuiltTrees) addTree(ctx context.Context, treeID btrfsprim.ObjID, sta tree.UUID = rootItem.UUID if rootItem.ParentUUID != (btrfsprim.UUID{}) { tree.ParentGen = rootOff - if !ts.addTree(ctx, btrfsprim.ROOT_TREE_OBJECTID, stack) { + if !ts.addTree(ctx, btrfsprim.UUID_TREE_OBJECTID, stack) { return false } parentID, ok := ts.cbLookupUUID(ctx, rootItem.ParentUUID) @@ -299,32 +287,22 @@ func (ts *RebuiltTrees) addTree(ctx context.Context, treeID btrfsprim.ObjID, sta ts.AddRoot(ctx, treeID, root) } - return true -} - -type indexStats struct { - TreeID btrfsprim.ObjID - DoneNodes int - TotalNodes int -} - -func (s indexStats) String() string { - return textui.Sprintf("tree %v: indexing leaf nodes: %v%% (%v/%v)", - s.TreeID, - int(100*float64(s.DoneNodes)/float64(s.TotalNodes)), - s.DoneNodes, s.TotalNodes) + return } func (tree *rebuiltTree) indexLeafs(ctx context.Context, graph pkggraph.Graph) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.add-tree.substep", "index-nodes") + nodeToRoots := make(map[btrfsvol.LogicalAddr]containers.Set[btrfsvol.LogicalAddr]) - progressWriter := textui.NewProgress[indexStats](ctx, dlog.LogLevelInfo, 1*time.Second) + + var stats textui.Portion[int] + stats.D = len(graph.Nodes) + progressWriter := textui.NewProgress[textui.Portion[int]](ctx, dlog.LogLevelInfo, 1*time.Second) progress := func() { - progressWriter.Set(indexStats{ - TreeID: tree.ID, - DoneNodes: len(nodeToRoots), - TotalNodes: len(graph.Nodes), - }) + stats.N = len(nodeToRoots) + progressWriter.Set(stats) } + progress() for _, node := range maps.SortedKeys(graph.Nodes) { tree.indexNode(graph, node, nodeToRoots, progress, nil) @@ -397,7 +375,7 @@ func (ts *RebuiltTrees) Load(ctx context.Context, treeID btrfsprim.ObjID, key bt if !ok { return nil, false } - return ts.keyIO.ReadItem(ptr) + return ts.keyIO.ReadItem(ctx, ptr) } // Search searches for an item from a tree. diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/graph/graph.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/graph/graph.go index d3dd19a..c4ed675 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/graph/graph.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/graph/graph.go @@ -191,19 +191,13 @@ func (g Graph) InsertNode(nodeRef *diskio.Ref[btrfsvol.LogicalAddr, btrfstree.No } } -type progStats struct { - textui.Portion[int] -} - -func (s progStats) String() string { - return "... " + s.Portion.String() -} - func (g Graph) FinalCheck(ctx context.Context, fs diskio.File[btrfsvol.LogicalAddr], sb btrfstree.Superblock) error { - var stats progStats + var stats textui.Portion[int] + _ctx := ctx - dlog.Info(ctx, "Checking keypointers for dead-ends...") - progressWriter := textui.NewProgress[progStats](ctx, dlog.LogLevelInfo, 1*time.Second) + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-nodes.read.substep", "check-keypointers") + dlog.Info(_ctx, "Checking keypointers for dead-ends...") + progressWriter := textui.NewProgress[textui.Portion[int]](ctx, dlog.LogLevelInfo, 1*time.Second) stats.D = len(g.EdgesTo) progressWriter.Set(stats) for laddr := range g.EdgesTo { @@ -223,10 +217,11 @@ func (g Graph) FinalCheck(ctx context.Context, fs diskio.File[btrfsvol.LogicalAd progressWriter.Done() dlog.Info(ctx, "... done checking keypointers") - dlog.Info(ctx, "Checking for btree loops...") + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-nodes.read.substep", "check-for-loops") + dlog.Info(_ctx, "Checking for btree loops...") stats.D = len(g.Nodes) stats.N = 0 - progressWriter = textui.NewProgress[progStats](ctx, dlog.LogLevelInfo, 1*time.Second) + progressWriter = textui.NewProgress[textui.Portion[int]](ctx, dlog.LogLevelInfo, 1*time.Second) progressWriter.Set(stats) visited := make(containers.Set[btrfsvol.LogicalAddr], len(g.Nodes)) numLoops := 0 @@ -260,7 +255,7 @@ func (g Graph) FinalCheck(ctx context.Context, fs diskio.File[btrfsvol.LogicalAd if numLoops > 0 { return fmt.Errorf("%d btree loops", numLoops) } - dlog.Info(ctx, "... done checking for loops") + dlog.Info(_ctx, "... done checking for loops") return nil } diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/keyio/keyio.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/keyio/keyio.go index d92495e..b1e68f9 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/keyio/keyio.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/keyio/keyio.go @@ -5,8 +5,11 @@ package keyio import ( + "context" "fmt" + "github.com/datawire/dlib/dlog" + "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsitem" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsprim" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfstree" @@ -85,8 +88,9 @@ func (o *Handle) SetGraph(graph graph.Graph) { o.graph = graph } -func (o *Handle) readNode(laddr btrfsvol.LogicalAddr) *diskio.Ref[btrfsvol.LogicalAddr, btrfstree.Node] { +func (o *Handle) readNode(ctx context.Context, laddr btrfsvol.LogicalAddr) *diskio.Ref[btrfsvol.LogicalAddr, btrfstree.Node] { if cached, ok := o.cache.Get(laddr); ok { + dlog.Tracef(ctx, "cache-hit node@%v", laddr) return cached } @@ -95,6 +99,7 @@ func (o *Handle) readNode(laddr btrfsvol.LogicalAddr) *diskio.Ref[btrfsvol.Logic panic(fmt.Errorf("should not happen: node@%v is not mentioned in the in-memory graph", laddr)) } + dlog.Infof(ctx, "cache-miss node@%v, reading...", laddr) ref, err := btrfstree.ReadNode(o.rawFile, o.sb, laddr, btrfstree.NodeExpectations{ LAddr: containers.Optional[btrfsvol.LogicalAddr]{OK: true, Val: laddr}, Level: containers.Optional[uint8]{OK: true, Val: graphInfo.Level}, @@ -118,11 +123,11 @@ func (o *Handle) readNode(laddr btrfsvol.LogicalAddr) *diskio.Ref[btrfsvol.Logic return ref } -func (o *Handle) ReadItem(ptr ItemPtr) (item btrfsitem.Item, ok bool) { +func (o *Handle) ReadItem(ctx context.Context, ptr ItemPtr) (item btrfsitem.Item, ok bool) { if o.graph.Nodes[ptr.Node].Level != 0 || ptr.Idx < 0 { return nil, false } - items := o.readNode(ptr.Node).Data.BodyLeaf + items := o.readNode(ctx, ptr.Node).Data.BodyLeaf if ptr.Idx >= len(items) { return nil, false } diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go index 4df3a9a..a7fe5c7 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go @@ -38,6 +38,10 @@ func (a keyAndTree) Cmp(b keyAndTree) int { return containers.NativeCmp(a.TreeID, b.TreeID) } +func (o keyAndTree) String() string { + return fmt.Sprintf("tree=%v key=%v", o.TreeID, o.Key) +} + type rebuilder struct { sb btrfstree.Superblock rebuilt *btrees.RebuiltTrees @@ -52,17 +56,20 @@ type rebuilder struct { } func RebuildNodes(ctx context.Context, fs *btrfs.FS, nodeScanResults btrfsinspect.ScanDevicesResult) (map[btrfsprim.ObjID]containers.Set[btrfsvol.LogicalAddr], error) { + _ctx := ctx + + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-nodes.step", "read-fs-data") dlog.Info(ctx, "Reading superblock...") sb, err := fs.Superblock() if err != nil { return nil, err } - nodeGraph, keyIO, err := ScanDevices(ctx, fs, nodeScanResults) // ScanDevices does its own logging if err != nil { return nil, err } + ctx = dlog.WithField(_ctx, "btrfsinspect.rebuild-nodes.step", "rebuild") dlog.Info(ctx, "Rebuilding node tree...") o := &rebuilder{ sb: *sb, @@ -85,22 +92,7 @@ func (o *rebuilder) ioErr(ctx context.Context, err error) { panic(err) } -type rebuildStats struct { - PassNum int - Task string - N, D int -} - -func (s rebuildStats) String() string { - pct := 100 - if s.D > 0 { - pct = int(100 * float64(s.N) / float64(s.D)) - } - return fmt.Sprintf("... pass %d: %s %v%% (%v/%v)", - s.PassNum, s.Task, pct, s.N, s.D) -} - -func (o *rebuilder) rebuild(ctx context.Context) error { +func (o *rebuilder) rebuild(_ctx context.Context) error { // Initialize o.augmentQueue = make(map[btrfsprim.ObjID][]map[btrfsvol.LogicalAddr]int) @@ -113,37 +105,39 @@ func (o *rebuilder) rebuild(ctx context.Context) error { } for passNum := 0; len(o.treeQueue) > 0 || len(o.itemQueue) > 0 || len(o.augmentQueue) > 0; passNum++ { + passCtx := dlog.WithField(_ctx, "btrfsinspect.rebuild-nodes.rebuild.pass", passNum) + // Add items to the queue (drain o.treeQueue, fill o.itemQueue) - dlog.Infof(ctx, "... pass %d: scanning for implied items", passNum) + stepCtx := dlog.WithField(passCtx, "btrfsinspect.rebuild-nodes.rebuild.substep", "collect-items") treeQueue := o.treeQueue o.treeQueue = nil sort.Slice(treeQueue, func(i, j int) bool { return treeQueue[i] < treeQueue[j] }) + // Because trees can be wildly different sizes, it's impossible to have a meaningful + // progress percentage here. for _, treeID := range treeQueue { - o.rebuilt.AddTree(ctx, treeID) + o.rebuilt.AddTree(stepCtx, treeID) } // Handle items in the queue (drain o.itemQueue, fill o.augmentQueue and o.treeQueue) + stepCtx = dlog.WithField(passCtx, "btrfsinspect.rebuild-nodes.rebuild.substep", "process-items") itemQueue := o.itemQueue o.itemQueue = nil - progressWriter := textui.NewProgress[rebuildStats](ctx, dlog.LogLevelInfo, 1*time.Second) - queueProgress := func(done int) { - progressWriter.Set(rebuildStats{ - PassNum: passNum, - Task: "processing item queue", - N: done, - D: len(itemQueue), - }) - } + var progress textui.Portion[int] + progress.D = len(itemQueue) + progressWriter := textui.NewProgress[textui.Portion[int]](stepCtx, dlog.LogLevelInfo, 1*time.Second) + stepCtx = dlog.WithField(stepCtx, "btrfsinspect.rebuild-nodes.rebuild.substep.progress", &progress) for i, key := range itemQueue { - queueProgress(i) + itemCtx := dlog.WithField(stepCtx, "btrfsinspect.rebuild-nodes.rebuild.process.item", key) + progress.N = i + progressWriter.Set(progress) o.curKey = key - itemBody, ok := o.rebuilt.Load(ctx, key.TreeID, key.Key) + itemBody, ok := o.rebuilt.Load(itemCtx, key.TreeID, key.Key) if !ok { - o.ioErr(ctx, fmt.Errorf("could not read previously read item: %v", key)) + o.ioErr(itemCtx, fmt.Errorf("could not read previously read item: %v", key)) } - handleItem(o, ctx, key.TreeID, btrfstree.Item{ + handleItem(o, itemCtx, key.TreeID, btrfstree.Item{ Key: key.Key, Body: itemBody, }) @@ -151,36 +145,32 @@ func (o *rebuilder) rebuild(ctx context.Context) error { o.treeQueue = append(o.treeQueue, key.ObjectID) } } - queueProgress(len(itemQueue)) + progress.N = len(itemQueue) + progressWriter.Set(progress) progressWriter.Done() // Apply augments (drain o.augmentQueue, fill o.itemQueue) + stepCtx = dlog.WithField(passCtx, "btrfsinspect.rebuild-nodes.rebuild.substep", "apply-augments") resolvedAugments := make(map[btrfsprim.ObjID]containers.Set[btrfsvol.LogicalAddr], len(o.augmentQueue)) - numAugments := 0 + progress.N = 0 + progress.D = 0 for _, treeID := range maps.SortedKeys(o.augmentQueue) { - dlog.Infof(ctx, "... ... augments for tree %v:", treeID) - resolvedAugments[treeID] = o.resolveTreeAugments(ctx, o.augmentQueue[treeID]) - numAugments += len(resolvedAugments[treeID]) + treeCtx := dlog.WithField(stepCtx, "btrfsinspect.rebuild-nodes.rebuild.augment.tree", treeID) + resolvedAugments[treeID] = o.resolveTreeAugments(treeCtx, o.augmentQueue[treeID]) + progress.D += len(resolvedAugments[treeID]) } o.augmentQueue = make(map[btrfsprim.ObjID][]map[btrfsvol.LogicalAddr]int) - progressWriter = textui.NewProgress[rebuildStats](ctx, dlog.LogLevelInfo, 1*time.Second) - numAugmented := 0 - augmentProgress := func() { - progressWriter.Set(rebuildStats{ - PassNum: passNum, - Task: "applying augments", - N: numAugmented, - D: numAugments, - }) - } + progressWriter = textui.NewProgress[textui.Portion[int]](stepCtx, dlog.LogLevelInfo, 1*time.Second) + stepCtx = dlog.WithField(stepCtx, "btrfsinspect.rebuild-nodes.rebuild.substep.progress", &progress) for _, treeID := range maps.SortedKeys(resolvedAugments) { + treeCtx := dlog.WithField(stepCtx, "btrfsinspect.rebuild-nodes.rebuild.augment.tree", treeID) for _, nodeAddr := range maps.SortedKeys(resolvedAugments[treeID]) { - augmentProgress() - o.rebuilt.AddRoot(ctx, treeID, nodeAddr) - numAugmented++ + progressWriter.Set(progress) + o.rebuilt.AddRoot(treeCtx, treeID, nodeAddr) + progress.N++ } } - augmentProgress() + progressWriter.Set(progress) progressWriter.Done() } return nil @@ -194,6 +184,9 @@ func (o *rebuilder) cbAddedItem(ctx context.Context, tree btrfsprim.ObjID, key b } func (o *rebuilder) cbLookupRoot(ctx context.Context, tree btrfsprim.ObjID) (offset btrfsprim.Generation, item btrfsitem.Root, ok bool) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.reason", "tree Root") + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.key", + fmt.Sprintf("tree=%v key={%v %v ?}", btrfsprim.ROOT_TREE_OBJECTID, tree, btrfsitem.ROOT_ITEM_KEY)) key, ok := o._want(ctx, btrfsprim.ROOT_TREE_OBJECTID, tree, btrfsitem.ROOT_ITEM_KEY) if !ok { o.itemQueue = append(o.itemQueue, o.curKey) @@ -218,7 +211,9 @@ func (o *rebuilder) cbLookupRoot(ctx context.Context, tree btrfsprim.ObjID) (off func (o *rebuilder) cbLookupUUID(ctx context.Context, uuid btrfsprim.UUID) (id btrfsprim.ObjID, ok bool) { key := btrfsitem.UUIDToKey(uuid) - if ok := o._wantOff(ctx, btrfsprim.UUID_TREE_OBJECTID, key.ObjectID, key.ItemType, key.Offset); !ok { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.reason", "resolve parent UUID") + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.key", keyAndTree{TreeID: btrfsprim.UUID_TREE_OBJECTID, Key: key}) + if ok := o._wantOff(ctx, btrfsprim.UUID_TREE_OBJECTID, key); !ok { o.itemQueue = append(o.itemQueue, o.curKey) return 0, false } @@ -349,9 +344,9 @@ func (o *rebuilder) resolveTreeAugments(ctx context.Context, listsWithDistances for i, list := range lists { chose := list.Intersection(ret) if len(chose) == 0 { - dlog.Infof(ctx, "... ... ... lists[%d]: chose (none) from %v", i, maps.SortedKeys(list)) + dlog.Infof(ctx, "lists[%d]: chose (none) from %v", i, maps.SortedKeys(list)) } else { - dlog.Infof(ctx, "... ... ... lists[%d]: chose %v from %v", i, chose.TakeOne(), maps.SortedKeys(list)) + dlog.Infof(ctx, "lists[%d]: chose %v from %v", i, chose.TakeOne(), maps.SortedKeys(list)) } } @@ -362,7 +357,7 @@ func (o *rebuilder) resolveTreeAugments(ctx context.Context, listsWithDistances func (o *rebuilder) wantAugment(ctx context.Context, treeID btrfsprim.ObjID, choices containers.Set[btrfsvol.LogicalAddr]) { if len(choices) == 0 { - dlog.Errorf(ctx, "augment(tree=%v): could not find wanted item", treeID) + dlog.Error(ctx, "could not find wanted item") return } choicesWithDist := make(map[btrfsvol.LogicalAddr]int, len(choices)) @@ -373,7 +368,7 @@ func (o *rebuilder) wantAugment(ctx context.Context, treeID btrfsprim.ObjID, cho } choicesWithDist[choice] = dist } - dlog.Infof(ctx, "augment(tree=%v): %v", treeID, maps.SortedKeys(choicesWithDist)) + dlog.Infof(ctx, "choices=%v", maps.SortedKeys(choicesWithDist)) o.augmentQueue[treeID] = append(o.augmentQueue[treeID], choicesWithDist) } @@ -385,7 +380,10 @@ func (o *rebuilder) fsErr(ctx context.Context, e error) { } // want implements rebuildCallbacks. -func (o *rebuilder) want(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType) { +func (o *rebuilder) want(ctx context.Context, reason string, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.reason", reason) + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.key", + fmt.Sprintf("tree=%v key={%v %v ?}", treeID, objID, typ)) o._want(ctx, treeID, objID, typ) } func (o *rebuilder) _want(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType) (key btrfsprim.Key, ok bool) { @@ -409,7 +407,6 @@ func (o *rebuilder) _want(ctx context.Context, treeID btrfsprim.ObjID, objID btr // OK, we need to insert it - ctx = dlog.WithField(ctx, "want_key", fmt.Sprintf("tree=%v key={%v %v ?}", treeID, objID, typ)) wants := make(containers.Set[btrfsvol.LogicalAddr]) o.rebuilt.Keys(treeID).Subrange( func(k btrfsprim.Key, _ keyio.ItemPtr) int { k.Offset = 0; return tgt.Cmp(k) }, @@ -422,10 +419,17 @@ func (o *rebuilder) _want(ctx context.Context, treeID btrfsprim.ObjID, objID btr } // wantOff implements rebuildCallbacks. -func (o *rebuilder) wantOff(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, off uint64) { - o._wantOff(ctx, treeID, objID, typ, off) +func (o *rebuilder) wantOff(ctx context.Context, reason string, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, off uint64) { + key := btrfsprim.Key{ + ObjectID: objID, + ItemType: typ, + Offset: off, + } + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.reason", reason) + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.key", keyAndTree{TreeID: treeID, Key: key}) + o._wantOff(ctx, treeID, key) } -func (o *rebuilder) _wantOff(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, off uint64) (ok bool) { +func (o *rebuilder) _wantOff(ctx context.Context, treeID btrfsprim.ObjID, tgt btrfsprim.Key) (ok bool) { if !o.rebuilt.AddTree(ctx, treeID) { o.itemQueue = append(o.itemQueue, o.curKey) return false @@ -433,18 +437,12 @@ func (o *rebuilder) _wantOff(ctx context.Context, treeID btrfsprim.ObjID, objID // check if we already have it - tgt := btrfsprim.Key{ - ObjectID: objID, - ItemType: typ, - Offset: off, - } if _, ok := o.rebuilt.Load(ctx, treeID, tgt); ok { return true } // OK, we need to insert it - ctx = dlog.WithField(ctx, "want_key", fmt.Sprintf("tree=%v key=%v", treeID, tgt)) wants := make(containers.Set[btrfsvol.LogicalAddr]) o.rebuilt.Keys(treeID).Subrange( func(k btrfsprim.Key, _ keyio.ItemPtr) int { return tgt.Cmp(k) }, @@ -457,7 +455,11 @@ func (o *rebuilder) _wantOff(ctx context.Context, treeID btrfsprim.ObjID, objID } // wantFunc implements rebuildCallbacks. -func (o *rebuilder) wantFunc(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, fn func(btrfsitem.Item) bool) { +func (o *rebuilder) wantFunc(ctx context.Context, reason string, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, fn func(btrfsitem.Item) bool) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.reason", reason) + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.key", + fmt.Sprintf("tree=%v key={%v %v ?} +func", treeID, objID, typ)) + if !o.rebuilt.AddTree(ctx, treeID) { o.itemQueue = append(o.itemQueue, o.curKey) return @@ -485,12 +487,11 @@ func (o *rebuilder) wantFunc(ctx context.Context, treeID btrfsprim.ObjID, objID // OK, we need to insert it - ctx = dlog.WithField(ctx, "want_key", fmt.Sprintf("tree=%v key=%v +func", treeID, tgt)) wants := make(containers.Set[btrfsvol.LogicalAddr]) o.rebuilt.Keys(treeID).Subrange( func(k btrfsprim.Key, _ keyio.ItemPtr) int { k.Offset = 0; return tgt.Cmp(k) }, func(k btrfsprim.Key, v keyio.ItemPtr) bool { - itemBody, ok := o.keyIO.ReadItem(v) + itemBody, ok := o.keyIO.ReadItem(ctx, v) if !ok { o.ioErr(ctx, fmt.Errorf("could not read previously read item: %v at %v", k, v)) } @@ -507,6 +508,9 @@ func (o *rebuilder) _wantRange( treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, beg, end uint64, ) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.key", + fmt.Sprintf("tree=%v key={%v %v ?}", treeID, objID, typ)) + if !o.rebuilt.AddTree(ctx, treeID) { o.itemQueue = append(o.itemQueue, o.curKey) return @@ -651,22 +655,23 @@ func (o *rebuilder) _wantRange( // TODO: This is dumb and greedy. if last < runBeg { // log an error - o.wantAugment(dlog.WithField(ctx, "want_key", fmt.Sprintf("tree=%v key={%v, %v, %v-%v}", - treeID, objID, typ, last, runBeg)), - treeID, nil) + wantCtx := dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.key", + fmt.Sprintf("tree=%v key={%v %v %v-%v}", treeID, objID, typ, last, runBeg)) + o.wantAugment(wantCtx, treeID, nil) } - o.wantAugment(dlog.WithField(ctx, "want_key", fmt.Sprintf("tree=%v key={%v, %v, %v-%v}", - treeID, objID, typ, gap.Beg, gap.End)), - treeID, o.rebuilt.LeafToRoots(ctx, treeID, v.Node)) + wantCtx := dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.key", + fmt.Sprintf("tree=%v key={%v %v %v-%v}", treeID, objID, typ, gap.Beg, gap.End)) + o.wantAugment(wantCtx, treeID, o.rebuilt.LeafToRoots(ctx, treeID, v.Node)) last = runEnd return true }) if last < gap.End { // log an error - o.wantAugment(dlog.WithField(ctx, "want_key", fmt.Sprintf("tree=%v key={%v, %v, %v-%v}", - treeID, objID, typ, last, gap.End)), - treeID, nil) + wantCtx := dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.key", + fmt.Sprintf("tree=%v key={%v, %v, %v-%v}", + treeID, objID, typ, last, gap.End)) + o.wantAugment(wantCtx, treeID, nil) } return nil }) @@ -675,14 +680,16 @@ func (o *rebuilder) _wantRange( // func implements rebuildCallbacks. // // interval is [beg, end) -func (o *rebuilder) wantCSum(ctx context.Context, beg, end btrfsvol.LogicalAddr) { +func (o *rebuilder) wantCSum(ctx context.Context, reason string, beg, end btrfsvol.LogicalAddr) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.reason", reason) const treeID = btrfsprim.CSUM_TREE_OBJECTID o._wantRange(ctx, treeID, btrfsprim.EXTENT_CSUM_OBJECTID, btrfsprim.EXTENT_CSUM_KEY, uint64(beg), uint64(end)) } // wantFileExt implements rebuildCallbacks. -func (o *rebuilder) wantFileExt(ctx context.Context, treeID btrfsprim.ObjID, ino btrfsprim.ObjID, size int64) { +func (o *rebuilder) wantFileExt(ctx context.Context, reason string, treeID btrfsprim.ObjID, ino btrfsprim.ObjID, size int64) { + ctx = dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.rebuild.want.reason", reason) o._wantRange(ctx, treeID, ino, btrfsprim.EXTENT_DATA_KEY, 0, uint64(size)) } diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild_graph.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild_graph.go index db7a7a5..45c9c97 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild_graph.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild_graph.go @@ -9,8 +9,6 @@ import ( "fmt" "reflect" - "github.com/datawire/dlib/dlog" - "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsitem" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsprim" "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfssum" @@ -20,40 +18,37 @@ import ( type rebuildCallbacks interface { fsErr(ctx context.Context, e error) - want(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType) - wantOff(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, off uint64) - wantFunc(ctx context.Context, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, fn func(btrfsitem.Item) bool) - wantCSum(ctx context.Context, beg, end btrfsvol.LogicalAddr) // interval is [beg, end) - wantFileExt(ctx context.Context, treeID btrfsprim.ObjID, ino btrfsprim.ObjID, size int64) + want(ctx context.Context, reason string, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType) + wantOff(ctx context.Context, reason string, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, off uint64) + wantFunc(ctx context.Context, reason string, treeID btrfsprim.ObjID, objID btrfsprim.ObjID, typ btrfsprim.ItemType, fn func(btrfsitem.Item) bool) + wantCSum(ctx context.Context, reason string, beg, end btrfsvol.LogicalAddr) // interval is [beg, end) + wantFileExt(ctx context.Context, reason string, treeID btrfsprim.ObjID, ino btrfsprim.ObjID, size int64) } func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, item btrfstree.Item) { - ctx = dlog.WithField(ctx, "tree", treeID) - ctx = dlog.WithField(ctx, "key", item.Key) - // Notionally, just express the relationships shown in // https://btrfs.wiki.kernel.org/index.php/File:References.png (from the page // https://btrfs.wiki.kernel.org/index.php/Data_Structures ) switch body := item.Body.(type) { case btrfsitem.BlockGroup: - o.want(dlog.WithField(ctx, "wants", "Chunk"), + o.want(ctx, "Chunk", btrfsprim.CHUNK_TREE_OBJECTID, body.ChunkObjectID, btrfsitem.CHUNK_ITEM_KEY) - o.wantOff(dlog.WithField(ctx, "wants", "FreeSpaceInfo"), + o.wantOff(ctx, "FreeSpaceInfo", btrfsprim.FREE_SPACE_TREE_OBJECTID, item.Key.ObjectID, btrfsitem.FREE_SPACE_INFO_KEY, item.Key.Offset) case btrfsitem.Chunk: - o.want(dlog.WithField(ctx, "wants", "owning Root"), + o.want(ctx, "owning Root", btrfsprim.ROOT_TREE_OBJECTID, body.Head.Owner, btrfsitem.ROOT_ITEM_KEY) case btrfsitem.Dev: // nothing case btrfsitem.DevExtent: - o.wantOff(dlog.WithField(ctx, "wants", "Chunk"), + o.wantOff(ctx, "Chunk", body.ChunkTree, body.ChunkObjectID, btrfsitem.CHUNK_ITEM_KEY, @@ -62,7 +57,7 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, // nothing case btrfsitem.DirEntry: // containing-directory - o.wantOff(dlog.WithField(ctx, "wants", "containing dir inode"), + o.wantOff(ctx, "containing dir inode", treeID, item.Key.ObjectID, btrfsitem.INODE_ITEM_KEY, @@ -70,7 +65,7 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, // siblings switch item.Key.ItemType { case btrfsitem.DIR_ITEM_KEY: - o.wantFunc(dlog.WithField(ctx, "wants", "corresponding DIR_INDEX"), + o.wantFunc(ctx, "corresponding DIR_INDEX", treeID, item.Key.ObjectID, btrfsitem.DIR_INDEX_KEY, @@ -78,7 +73,7 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, return reflect.DeepEqual(item, peerItem) }) case btrfsitem.DIR_INDEX_KEY: - o.wantOff(dlog.WithField(ctx, "wants", "corresponding DIR_ITEM"), + o.wantOff(ctx, "corresponding DIR_ITEM", treeID, item.Key.ObjectID, btrfsitem.DIR_ITEM_KEY, @@ -95,18 +90,18 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, if body.Location != (btrfsprim.Key{}) { switch body.Location.ItemType { case btrfsitem.INODE_ITEM_KEY: - o.wantOff(dlog.WithField(ctx, "wants", "item being pointed to"), + o.wantOff(ctx, "item being pointed to", treeID, body.Location.ObjectID, body.Location.ItemType, body.Location.Offset) - o.wantOff(dlog.WithField(ctx, "wants", "backref from item being pointed to"), + o.wantOff(ctx, "backref from item being pointed to", treeID, body.Location.ObjectID, btrfsitem.INODE_REF_KEY, uint64(item.Key.ObjectID)) case btrfsitem.ROOT_ITEM_KEY: - o.want(dlog.WithField(ctx, "wants", "Root of subvolume being pointed to"), + o.want(ctx, "Root of subvolume being pointed to", btrfsprim.ROOT_TREE_OBJECTID, body.Location.ObjectID, body.Location.ItemType) @@ -129,12 +124,12 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, case nil: // nothing case btrfsitem.ExtentDataRef: - o.wantOff(dlog.WithField(ctx, "wants", "referencing Inode"), + o.wantOff(ctx, "referencing Inode", refBody.Root, refBody.ObjectID, btrfsitem.INODE_ITEM_KEY, 0) - o.wantOff(dlog.WithField(ctx, "wants", "referencing FileExtent"), + o.wantOff(ctx, "referencing FileExtent", refBody.Root, refBody.ObjectID, btrfsitem.EXTENT_DATA_KEY, @@ -150,22 +145,22 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, case btrfsitem.ExtentCSum: // nothing case btrfsitem.ExtentDataRef: - o.want(dlog.WithField(ctx, "wants", "Extent being referenced"), + o.want(ctx, "Extent being referenced", btrfsprim.EXTENT_TREE_OBJECTID, item.Key.ObjectID, btrfsitem.EXTENT_ITEM_KEY) - o.wantOff(dlog.WithField(ctx, "wants", "referencing Inode"), + o.wantOff(ctx, "referencing Inode", body.Root, body.ObjectID, btrfsitem.INODE_ITEM_KEY, 0) - o.wantOff(dlog.WithField(ctx, "wants", "referencing FileExtent"), + o.wantOff(ctx, "referencing FileExtent", body.Root, body.ObjectID, btrfsitem.EXTENT_DATA_KEY, uint64(body.Offset)) case btrfsitem.FileExtent: - o.wantOff(dlog.WithField(ctx, "wants", "containing Inode"), + o.wantOff(ctx, "containing Inode", treeID, item.Key.ObjectID, btrfsitem.INODE_ITEM_KEY, @@ -175,63 +170,63 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, // nothing case btrfsitem.FILE_EXTENT_REG, btrfsitem.FILE_EXTENT_PREALLOC: // TODO: Check if inodeBody.Flags.Has(btrfsitem.INODE_NODATASUM) - o.wantCSum(dlog.WithField(ctx, "wants", "data sum"), + o.wantCSum(ctx, "data sum", roundDown(body.BodyExtent.DiskByteNr, btrfssum.BlockSize), roundUp(body.BodyExtent.DiskByteNr.Add(body.BodyExtent.DiskNumBytes), btrfssum.BlockSize)) default: o.fsErr(ctx, fmt.Errorf("FileExtent: unexpected body.Type=%v", body.Type)) } case btrfsitem.FreeSpaceBitmap: - o.wantOff(dlog.WithField(ctx, "wants", "FreeSpaceInfo"), + o.wantOff(ctx, "FreeSpaceInfo", treeID, item.Key.ObjectID, btrfsitem.FREE_SPACE_INFO_KEY, item.Key.Offset) case btrfsitem.FreeSpaceHeader: - o.wantOff(dlog.WithField(ctx, "wants", ".Location"), + o.wantOff(ctx, ".Location", treeID, body.Location.ObjectID, body.Location.ItemType, body.Location.Offset) case btrfsitem.FreeSpaceInfo: if body.Flags.Has(btrfsitem.FREE_SPACE_USING_BITMAPS) { - o.wantOff(dlog.WithField(ctx, "wants", "FreeSpaceBitmap"), + o.wantOff(ctx, "FreeSpaceBitmap", treeID, item.Key.ObjectID, btrfsitem.FREE_SPACE_BITMAP_KEY, item.Key.Offset) } case btrfsitem.Inode: - o.want(dlog.WithField(ctx, "wants", "backrefs"), + o.want(ctx, "backrefs", treeID, // TODO: validate the number of these against body.NLink item.Key.ObjectID, btrfsitem.INODE_REF_KEY) - o.wantFileExt(dlog.WithField(ctx, "wants", "FileExtents"), + o.wantFileExt(ctx, "FileExtents", treeID, item.Key.ObjectID, body.Size) if body.BlockGroup != 0 { - o.want(dlog.WithField(ctx, "wants", "BlockGroup"), + o.want(ctx, "BlockGroup", btrfsprim.EXTENT_TREE_OBJECTID, body.BlockGroup, btrfsitem.BLOCK_GROUP_ITEM_KEY) } case btrfsitem.InodeRefs: - o.wantOff(dlog.WithField(ctx, "wants", "child Inode"), + o.wantOff(ctx, "child Inode", treeID, item.Key.ObjectID, btrfsitem.INODE_ITEM_KEY, 0) - o.wantOff(dlog.WithField(ctx, "wants", "parent Inode"), + o.wantOff(ctx, "parent Inode", treeID, btrfsprim.ObjID(item.Key.Offset), btrfsitem.INODE_ITEM_KEY, 0) for _, ref := range body { - o.wantOff(dlog.WithField(ctx, "wants", "DIR_ITEM"), + o.wantOff(ctx, "DIR_ITEM", treeID, btrfsprim.ObjID(item.Key.Offset), btrfsitem.DIR_ITEM_KEY, btrfsitem.NameHash(ref.Name)) - o.wantOff(dlog.WithField(ctx, "wants", "DIR_INDEX"), + o.wantOff(ctx, "DIR_INDEX", treeID, btrfsprim.ObjID(item.Key.Offset), btrfsitem.DIR_INDEX_KEY, @@ -243,12 +238,12 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, case nil: // nothing case btrfsitem.ExtentDataRef: - o.wantOff(dlog.WithField(ctx, "wants", "referencing INode"), + o.wantOff(ctx, "referencing INode", refBody.Root, refBody.ObjectID, btrfsitem.INODE_ITEM_KEY, 0) - o.wantOff(dlog.WithField(ctx, "wants", "referencing FileExtent"), + o.wantOff(ctx, "referencing FileExtent", refBody.Root, refBody.ObjectID, btrfsitem.EXTENT_DATA_KEY, @@ -263,7 +258,7 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, } case btrfsitem.Root: if body.RootDirID != 0 { - o.wantOff(dlog.WithField(ctx, "wants", "root directory"), + o.wantOff(ctx, "root directory", item.Key.ObjectID, body.RootDirID, btrfsitem.INODE_ITEM_KEY, @@ -271,7 +266,7 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, } if body.UUID != (btrfsprim.UUID{}) { key := btrfsitem.UUIDToKey(body.UUID) - o.wantOff(dlog.WithField(ctx, "wants", "uuid"), + o.wantOff(ctx, "uuid", btrfsprim.UUID_TREE_OBJECTID, key.ObjectID, key.ItemType, @@ -279,7 +274,7 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, } if body.ParentUUID != (btrfsprim.UUID{}) { key := btrfsitem.UUIDToKey(body.ParentUUID) - o.wantOff(dlog.WithField(ctx, "wants", "parent uuid"), + o.wantOff(ctx, "parent uuid", btrfsprim.UUID_TREE_OBJECTID, key.ObjectID, key.ItemType, @@ -304,43 +299,43 @@ func handleItem(o rebuildCallbacks, ctx context.Context, treeID btrfsprim.ObjID, panic(fmt.Errorf("should not happen: RootRef: unexpected ItemType=%v", item.Key.ItemType)) } // sibling - o.wantOff(dlog.WithField(ctx, "wants", fmt.Sprintf("corresponding %v", otherType)), + o.wantOff(ctx, fmt.Sprintf("corresponding %v", otherType), treeID, btrfsprim.ObjID(item.Key.Offset), otherType, uint64(item.Key.ObjectID)) // parent - o.want(dlog.WithField(ctx, "wants", "parent subvolume: Root"), + o.want(ctx, "parent subvolume: Root", treeID, parent, btrfsitem.ROOT_ITEM_KEY) - o.wantOff(dlog.WithField(ctx, "wants", "parent subvolume: Inode of parent dir"), + o.wantOff(ctx, "parent subvolume: Inode of parent dir", parent, body.DirID, btrfsitem.INODE_ITEM_KEY, 0) - o.wantOff(dlog.WithField(ctx, "wants", "parent subvolume: DIR_ITEM in parent dir"), + o.wantOff(ctx, "parent subvolume: DIR_ITEM in parent dir", parent, body.DirID, btrfsitem.DIR_ITEM_KEY, btrfsitem.NameHash(body.Name)) - o.wantOff(dlog.WithField(ctx, "wants", "parent subvolume: DIR_INDEX in parent dir"), + o.wantOff(ctx, "parent subvolume: DIR_INDEX in parent dir", parent, body.DirID, btrfsitem.DIR_INDEX_KEY, uint64(body.Sequence)) // child - o.want(dlog.WithField(ctx, "wants", "child subvolume: Root"), + o.want(ctx, "child subvolume: Root", treeID, child, btrfsitem.ROOT_ITEM_KEY) case btrfsitem.SharedDataRef: - o.want(dlog.WithField(ctx, "wants", "Extent"), + o.want(ctx, "Extent", btrfsprim.EXTENT_TREE_OBJECTID, item.Key.ObjectID, btrfsitem.EXTENT_ITEM_KEY) case btrfsitem.UUIDMap: - o.want(dlog.WithField(ctx, "wants", "subvolume Root"), + o.want(ctx, "subvolume Root", btrfsprim.ROOT_TREE_OBJECTID, body.ObjID, btrfsitem.ROOT_ITEM_KEY) diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/scan.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/scan.go index cdd5cba..7a112b4 100644 --- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/scan.go +++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/scan.go @@ -6,7 +6,6 @@ package rebuildnodes import ( "context" - "fmt" "time" "github.com/datawire/dlib/dlog" @@ -21,16 +20,6 @@ import ( "git.lukeshu.com/btrfs-progs-ng/lib/textui" ) -type scanStats struct { - N, D int -} - -func (s scanStats) String() string { - return fmt.Sprintf("... %v%% (%v/%v)", - int(100*float64(s.N)/float64(s.D)), - s.N, s.D) -} - func ScanDevices(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect.ScanDevicesResult) (graph.Graph, *keyio.Handle, error) { dlog.Infof(ctx, "Reading node data from FS...") @@ -39,17 +28,16 @@ func ScanDevices(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect.Sca return graph.Graph{}, nil, err } - total := countNodes(scanResults) - done := 0 - progressWriter := textui.NewProgress[scanStats](ctx, dlog.LogLevelInfo, 1*time.Second) - progress := func(done, total int) { - progressWriter.Set(scanStats{N: done, D: total}) - } + var stats textui.Portion[int] + stats.D = countNodes(scanResults) + progressWriter := textui.NewProgress[textui.Portion[int]]( + dlog.WithField(ctx, "btrfsinspect.rebuild-nodes.read.substep", "read-nodes"), + dlog.LogLevelInfo, 1*time.Second) nodeGraph := graph.New(*sb) keyIO := keyio.NewHandle(fs, *sb) - progress(done, total) + progressWriter.Set(stats) for _, devResults := range scanResults { for laddr := range devResults.FoundNodes { nodeRef, err := btrfstree.ReadNode[btrfsvol.LogicalAddr](fs, *sb, laddr, btrfstree.NodeExpectations{ @@ -62,11 +50,11 @@ func ScanDevices(ctx context.Context, fs *btrfs.FS, scanResults btrfsinspect.Sca nodeGraph.InsertNode(nodeRef) keyIO.InsertNode(nodeRef) - done++ - progress(done, total) + stats.N++ + progressWriter.Set(stats) } } - if done != total { + if stats.N != stats.D { panic("should not happen") } progressWriter.Done() 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-54-g00ecf