From 8170074303ba93bd2cec6c3b3638af7cc1f68892 Mon Sep 17 00:00:00 2001
From: Ashlie Martinez <ashmrtnz@alcion.ai>
Date: Wed, 27 Sep 2023 09:08:18 -0700
Subject: [PATCH] Additional logging during details creation

---
 src/internal/kopia/upload.go      |  5 +++++
 src/internal/operations/backup.go | 22 ++++++++++++++++++----
 2 files changed, 23 insertions(+), 4 deletions(-)

diff --git a/src/internal/kopia/upload.go b/src/internal/kopia/upload.go
index bc7a1f034..f68d76b8d 100644
--- a/src/internal/kopia/upload.go
+++ b/src/internal/kopia/upload.go
@@ -217,6 +217,11 @@ func (cp *corsoProgress) FinishedFile(relativePath string, err error) {
 		cp.mu.Lock()
 		defer cp.mu.Unlock()
 
+		logger.Ctx(ctx).Debugw(
+			"adding merger entry",
+			"item_mod_time", d.modTime,
+			"item_prev_path", d.prevPath)
+
 		err := cp.toMerge.addRepoRef(
 			d.prevPath.ToBuilder(),
 			d.modTime,
diff --git a/src/internal/operations/backup.go b/src/internal/operations/backup.go
index 80b74277e..02eeeffa1 100644
--- a/src/internal/operations/backup.go
+++ b/src/internal/operations/backup.go
@@ -635,6 +635,13 @@ func mergeItemsFromBase(
 				With("repo_ref", path.LoggableDir(entry.RepoRef))
 		}
 
+		ictx := clues.Add(
+			ctx,
+			"item_repo_ref",
+			rr,
+			"item_mod_time",
+			entry.Modified())
+
 		// Although this base has an entry it may not be the most recent. Check
 		// the reasons a snapshot was returned to ensure we only choose the recent
 		// entries.
@@ -645,16 +652,16 @@ func mergeItemsFromBase(
 		// with overlapping reasons that then turn into assist bases, but the
 		// modTime check in DetailsMergeInfoer should handle that.
 		if checkReason && !matchesReason(baseBackup.Reasons, rr) {
+			logger.Ctx(ictx).Debug("reason match failure")
 			continue
 		}
 
 		// Skip items that were already found in a previous base backup.
 		if _, ok := alreadySeenItems[rr.ShortRef()]; ok {
+			logger.Ctx(ictx).Debug("already seen")
 			continue
 		}
 
-		ictx := clues.Add(ctx, "repo_ref", rr)
-
 		newPath, newLoc, err := getNewPathRefs(
 			dataFromBackup,
 			entry,
@@ -667,9 +674,12 @@ func mergeItemsFromBase(
 
 		// This entry isn't merged.
 		if newPath == nil {
+			logger.Ctx(ictx).Debug("no new path")
 			continue
 		}
 
+		logger.Ctx(ictx).Debug("merged")
+
 		// Fixup paths in the item.
 		item := entry.ItemInfo
 		details.UpdateItem(&item, newLoc)
@@ -741,8 +751,10 @@ func mergeDetails(
 	// with overlapping Reasons that turn into assist bases, but the modTime check
 	// in DetailsMergeInfoer should handle that.
 	for _, base := range bases.UniqueAssistBackups() {
+		ictx := clues.Add(ctx, "base_type", "assist")
+
 		added, err := mergeItemsFromBase(
-			ctx,
+			ictx,
 			false,
 			base,
 			detailsStore,
@@ -766,8 +778,10 @@ func mergeDetails(
 	// explicitly control which subtrees from the merge base backup are grafted
 	// onto the hierarchy for the currently running backup.
 	for _, base := range bases.Backups() {
+		ictx := clues.Add(ctx, "base_type", "assist")
+
 		added, err := mergeItemsFromBase(
-			ctx,
+			ictx,
 			true,
 			base,
 			detailsStore,