Add more logging to middleware and incremental backup operation logic (#2899)

Ensures:
* context clues are added to logged messages
* kv-pairs added with `log.With` are added to logged messages
* add log messages for how many details items were sourced from a base snapshot during merging
* ensure log messages for base selection have all the info they should

---

#### Does this PR need a docs update or release note?

- [ ] ✅ Yes, it's included
- [ ] 🕐 Yes, but in a later PR
- [x] ⛔ No

#### Type of change

- [ ] 🌻 Feature
- [x] 🐛 Bugfix
- [ ] 🗺️ Documentation
- [ ] 🤖 Supportability/Tests
- [ ] 💻 CI/Deployment
- [ ] 🧹 Tech Debt/Cleanup

#### Test Plan

- [x] 💪 Manual
- [ ] ⚡ Unit test
- [ ] 💚 E2E

src/internal/connector/data_collections.go

@@ -19,6 +19,7 @@ import (
 	"github.com/alcionai/corso/src/pkg/backup/details"
 	"github.com/alcionai/corso/src/pkg/control"
 	"github.com/alcionai/corso/src/pkg/fault"
+	"github.com/alcionai/corso/src/pkg/logger"
 	"github.com/alcionai/corso/src/pkg/path"
 	"github.com/alcionai/corso/src/pkg/selectors"
 )
@@ -181,6 +182,7 @@ func checkServiceEnabled(
 	}
 
 	if _, ok := info.DiscoveredServices[service]; !ok {
+		logger.Ctx(ctx).Error("service not enabled")
 		return false, nil
 	}
 

src/internal/connector/graph/service.go

@@ -271,12 +271,11 @@ func (handler *LoggingMiddleware) Intercept(
 			"url", req.URL, // TODO: pii
 			"request_len", req.ContentLength,
 		)
-		log       = logger.Ctx(ctx)
 		resp, err = pipeline.Next(req, middlewareIndex)
 	)
 
 	if strings.Contains(req.URL.String(), "users//") {
-		log.Error("malformed request url: missing resource")
+		logger.Ctx(ctx).Error("malformed request url: missing resource")
 	}
 
 	if resp == nil {
@@ -284,6 +283,7 @@ func (handler *LoggingMiddleware) Intercept(
 	}
 
 	ctx = clues.Add(ctx, "status", resp.Status, "statusCode", resp.StatusCode)
+	log := logger.Ctx(ctx)
 
 	// Return immediately if the response is good (2xx).
 	// If api logging is toggled, log a body-less dump of the request/resp.
@@ -308,13 +308,13 @@ func (handler *LoggingMiddleware) Intercept(
 
 	// special case for supportability: log all throttling cases.
 	if resp.StatusCode == http.StatusTooManyRequests || resp.StatusCode == http.StatusServiceUnavailable {
-		log.With(
+		log = log.With(
 			"limit", resp.Header.Get(rateLimitHeader),
 			"remaining", resp.Header.Get(rateRemainingHeader),
 			"reset", resp.Header.Get(rateResetHeader),
 			"retry-after", resp.Header.Get(retryAfterHeader))
 	} else if resp.StatusCode/100 == 4 {
-		log.With("response", getRespDump(ctx, resp, true))
+		log = log.With("response", getRespDump(ctx, resp, true))
 	}
 
 	log.Info(msg)

src/internal/kopia/snapshot_manager.go

@@ -251,7 +251,7 @@ func fetchPrevSnapshotManifests(
 		ictx := clues.Add(ctx, "service", reason.Service.String(), "category", reason.Category.String())
 		logger.Ctx(ictx).Info("searching for previous manifests for reason")
 
-		found, err := fetchPrevManifests(ctx, sm, mans, reason, tags)
+		found, err := fetchPrevManifests(ictx, sm, mans, reason, tags)
 		if err != nil {
 			logger.CtxErr(ictx, err).Info("fetching previous snapshot manifests for service/category/resource owner")
 

src/internal/model/model.go

@@ -11,6 +11,10 @@ type (
 	Schema   int
 )
 
+func (id StableID) String() string {
+	return string(id)
+}
+
 // Schema constants denote the type of model stored. The integer values of the
 // constants can be changed without issue, but the string values should remain
 // the same. If the string values are changed, additional code will be needed to

src/internal/operations/backup.go

@@ -445,11 +445,17 @@ func consumeBackupDataCollections(
 			cats = append(cats, k)
 		}
 
+		mbID, ok := m.GetTag(kopia.TagBackupID)
+		if !ok {
+			mbID = "no_backup_id_tag"
+		}
+
 		logger.Ctx(ctx).Infow(
 			"using base for backup",
-			"snapshot_id", m.ID,
+			"base_snapshot_id", m.ID,
 			"services", svcs,
-			"categories", cats)
+			"categories", cats,
+			"base_backup_id", mbID)
 	}
 
 	kopiaStats, deets, itemsSourcedFromBase, err := bu.BackupCollections(
@@ -509,7 +515,10 @@ func mergeDetails(
 	var addedEntries int
 
 	for _, man := range mans {
-		mctx := clues.Add(ctx, "manifest_id", man.ID)
+		var (
+			mctx                 = clues.Add(ctx, "base_manifest_id", man.ID)
+			manifestAddedEntries int
+		)
 
 		// For now skip snapshots that aren't complete. We will need to revisit this
 		// when we tackle restartability.
@@ -522,7 +531,7 @@ func mergeDetails(
 			return clues.New("no backup ID in snapshot manifest").WithClues(mctx)
 		}
 
-		mctx = clues.Add(mctx, "manifest_backup_id", bID)
+		mctx = clues.Add(mctx, "base_manifest_backup_id", bID)
 
 		_, baseDeets, err := getBackupAndDetailsFromID(
 			mctx,
@@ -599,7 +608,13 @@ func mergeDetails(
 			// Track how many entries we added so that we know if we got them all when
 			// we're done.
 			addedEntries++
+			manifestAddedEntries++
 		}
+
+		logger.Ctx(mctx).Infow(
+			"merged details with base manifest",
+			"base_item_count_unfiltered", len(baseDeets.Items()),
+			"base_item_count_added", manifestAddedEntries)
 	}
 
 	if addedEntries != len(shortRefsFromPrevBackup) {

src/internal/operations/manifests.go

@@ -91,7 +91,7 @@ func produceManifestsAndMetadata(
 			return nil, nil, false, err
 		}
 
-		mctx = clues.Add(mctx, "manifest_backup_id", man.ID)
+		mctx = clues.Add(mctx, "manifest_backup_id", bID)
 
 		bup, err := gb.GetBackup(mctx, model.StableID(bID))
 		// if no backup exists for any of the complete manifests, we want