Log base item kopia mod time

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,
@@ -586,6 +591,12 @@ func streamBaseEntries(
 				progress.put(encodeAsPath(itemPath.PopFront().Elements()...), d)
 			}
 
+			logger.Ctx(ctx).Debugw(
+				"uploading base item",
+				"item_size", entry.Size(),
+				"item_mod_time", entry.ModTime(),
+				"item_repo_ref", itemPath)
+
 			if err := ctr(ctx, entry); err != nil {
 				return clues.Wrap(err, "executing callback on item").
 					WithClues(ctx).

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,