rebuildnodes: Fuss with logging to take advantage of textui

7 files changed, 291 insertions, 239 deletions

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