From 1aa315412a622bfb95c906601c6fa4104e489503 Mon Sep 17 00:00:00 2001 From: ashmrtn Date: Tue, 21 Mar 2023 15:33:19 -0700 Subject: [PATCH] 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? - [ ] :white_check_mark: Yes, it's included - [ ] :clock1: Yes, but in a later PR - [x] :no_entry: No #### Type of change - [ ] :sunflower: Feature - [x] :bug: Bugfix - [ ] :world_map: Documentation - [ ] :robot: Supportability/Tests - [ ] :computer: CI/Deployment - [ ] :broom: Tech Debt/Cleanup #### Test Plan - [x] :muscle: Manual - [ ] :zap: Unit test - [ ] :green_heart: E2E --- src/internal/connector/data_collections.go | 2 ++ src/internal/connector/graph/service.go | 8 ++++---- src/internal/kopia/snapshot_manager.go | 2 +- src/internal/model/model.go | 4 ++++ src/internal/operations/backup.go | 23 ++++++++++++++++++---- src/internal/operations/manifests.go | 2 +- 6 files changed, 31 insertions(+), 10 deletions(-) diff --git a/src/internal/connector/data_collections.go b/src/internal/connector/data_collections.go index 3a49a7ac3..ddf81672c 100644 --- a/src/internal/connector/data_collections.go +++ b/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 } diff --git a/src/internal/connector/graph/service.go b/src/internal/connector/graph/service.go index 435849c8c..79c36d202 100644 --- a/src/internal/connector/graph/service.go +++ b/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) diff --git a/src/internal/kopia/snapshot_manager.go b/src/internal/kopia/snapshot_manager.go index 55d37891f..6334af582 100644 --- a/src/internal/kopia/snapshot_manager.go +++ b/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") diff --git a/src/internal/model/model.go b/src/internal/model/model.go index ceecd18de..41b118a73 100644 --- a/src/internal/model/model.go +++ b/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 diff --git a/src/internal/operations/backup.go b/src/internal/operations/backup.go index f0d4d0f4f..675631b6f 100644 --- a/src/internal/operations/backup.go +++ b/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) { diff --git a/src/internal/operations/manifests.go b/src/internal/operations/manifests.go index 14d009024..a30819467 100644 --- a/src/internal/operations/manifests.go +++ b/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