From a83f16c6e41a13fbb042cb090634d2acac039c90 Mon Sep 17 00:00:00 2001 From: Keepers Date: Fri, 10 Mar 2023 18:41:13 -0700 Subject: [PATCH] add logger CtxErr() qol func (#2599) ## Does this PR need a docs update or release note? - [x] :no_entry: No ## Type of change - [x] :broom: Tech Debt/Cleanup ## Issue(s) * #1970 ## Test Plan - [x] :zap: Unit test - [x] :green_heart: E2E --- src/cli/cli.go | 5 +---- src/cmd/factory/impl/exchange.go | 10 +++------- src/internal/common/crash/crash.go | 4 +--- src/internal/connector/exchange/attachment.go | 4 +--- .../connector/exchange/service_iterators.go | 4 ++-- .../connector/exchange/service_restore.go | 6 +++--- src/internal/connector/onedrive/collections.go | 8 ++------ src/internal/kopia/snapshot_manager.go | 15 +++------------ src/internal/kopia/upload.go | 2 +- src/internal/kopia/wrapper.go | 12 +++++++----- src/pkg/logger/example_logger_test.go | 16 ++++++++++++---- src/pkg/logger/logger.go | 8 ++++++++ 12 files changed, 44 insertions(+), 50 deletions(-) diff --git a/src/cli/cli.go b/src/cli/cli.go index d7e5a0da6..c04afc616 100644 --- a/src/cli/cli.go +++ b/src/cli/cli.go @@ -6,7 +6,6 @@ import ( "regexp" "strings" - "github.com/alcionai/clues" "github.com/spf13/cobra" "golang.org/x/exp/slices" @@ -155,9 +154,7 @@ func Handle() { }() if err := corsoCmd.ExecuteContext(ctx); err != nil { - logger.Ctx(ctx). - With("err", err). - Errorw("cli execution", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error("cli execution") os.Exit(1) } } diff --git a/src/cmd/factory/impl/exchange.go b/src/cmd/factory/impl/exchange.go index 67fa6f46a..c412ec253 100644 --- a/src/cmd/factory/impl/exchange.go +++ b/src/cmd/factory/impl/exchange.go @@ -1,7 +1,6 @@ package impl import ( - "github.com/alcionai/clues" "github.com/spf13/cobra" . "github.com/alcionai/corso/src/cli/print" @@ -78,9 +77,8 @@ func handleExchangeEmailFactory(cmd *cobra.Command, args []string) error { return Only(ctx, err) } - log := logger.Ctx(ctx) for _, e := range errs.Recovered() { - log.Errorw(e.Error(), clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error(e.Error()) } deets.PrintEntries(ctx) @@ -125,9 +123,8 @@ func handleExchangeCalendarEventFactory(cmd *cobra.Command, args []string) error return Only(ctx, err) } - log := logger.Ctx(ctx) for _, e := range errs.Recovered() { - log.Errorw(e.Error(), clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error(e.Error()) } deets.PrintEntries(ctx) @@ -177,9 +174,8 @@ func handleExchangeContactFactory(cmd *cobra.Command, args []string) error { return Only(ctx, err) } - log := logger.Ctx(ctx) for _, e := range errs.Recovered() { - log.Errorw(e.Error(), clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error(e.Error()) } deets.PrintEntries(ctx) diff --git a/src/internal/common/crash/crash.go b/src/internal/common/crash/crash.go index 2936c2efc..a35b93f87 100644 --- a/src/internal/common/crash/crash.go +++ b/src/internal/common/crash/crash.go @@ -45,9 +45,7 @@ func Recovery(ctx context.Context, r any) error { err = clues.Wrap(err, "panic recovery"+inFile). WithClues(ctx). With("stacktrace", string(debug.Stack())) - logger.Ctx(ctx). - With("err", err). - Errorw("backup panic", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error("backup panic") } return err diff --git a/src/internal/connector/exchange/attachment.go b/src/internal/connector/exchange/attachment.go index e21d739bb..9a293c7a0 100644 --- a/src/internal/connector/exchange/attachment.go +++ b/src/internal/connector/exchange/attachment.go @@ -69,9 +69,7 @@ func uploadAttachment( if attachmentType == models.ITEM_ATTACHMENTTYPE { a, err := support.ToItemAttachment(attachment) if err != nil { - logger.Ctx(ctx). - With("err", err). - Infow("item attachment restore not supported for this type. skipping upload.", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Info("item attachment restore not supported for this type. skipping upload.") return nil } diff --git a/src/internal/connector/exchange/service_iterators.go b/src/internal/connector/exchange/service_iterators.go index 106c70c8d..fb5fc5b79 100644 --- a/src/internal/connector/exchange/service_iterators.go +++ b/src/internal/connector/exchange/service_iterators.go @@ -93,7 +93,7 @@ func filterContainersAndFillCollections( if len(prevPathStr) > 0 { if prevPath, err = pathFromPrevString(prevPathStr); err != nil { - logger.Ctx(ctx).With("err", err).Errorw("parsing prev path", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error("parsing prev path") // if the previous path is unusable, then the delta must be, too. prevDelta = "" } @@ -175,7 +175,7 @@ func filterContainersAndFillCollections( prevPath, err := pathFromPrevString(p) if err != nil { // technically shouldn't ever happen. But just in case... - logger.Ctx(ctx).With("err", err).Errorw("parsing tombstone prev path", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error("parsing tombstone prev path") continue } diff --git a/src/internal/connector/exchange/service_restore.go b/src/internal/connector/exchange/service_restore.go index 294be3ec6..8fd17122c 100644 --- a/src/internal/connector/exchange/service_restore.go +++ b/src/internal/connector/exchange/service_restore.go @@ -276,9 +276,9 @@ func SendMailToBackStore( if ptr.Val(attachment.GetOdataType()) == "#microsoft.graph.itemAttachment" { name := ptr.Val(attachment.GetName()) - logger.Ctx(ctx). - With("err", err, "attachment_name", name). - Infow("mail upload failed", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err). + With("attachment_name", name). + Info("mail upload failed") continue } diff --git a/src/internal/connector/onedrive/collections.go b/src/internal/connector/onedrive/collections.go index 34dd40bce..ba01ef914 100644 --- a/src/internal/connector/onedrive/collections.go +++ b/src/internal/connector/onedrive/collections.go @@ -188,9 +188,7 @@ func deserializeMetadata( err = clues.Stack(err).WithClues(ictx) el.AddRecoverable(err) - logger.Ctx(ictx). - With("err", err). - Errorw("deserializing base backup metadata", clues.InErr(err).Slice()...) + logger.CtxErr(ictx, err).Error("deserializing base backup metadata") } } @@ -441,9 +439,7 @@ func (c *Collections) Get( // Technically it's safe to continue here because the logic for starting an // incremental backup should eventually find that the metadata files are // empty/missing and default to a full backup. - logger.Ctx(ctx). - With("err", err). - Infow("making metadata collection for future incremental backups", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Info("making metadata collection for future incremental backups") } else { collections = append(collections, metadata) } diff --git a/src/internal/kopia/snapshot_manager.go b/src/internal/kopia/snapshot_manager.go index 45b1ffabe..55d37891f 100644 --- a/src/internal/kopia/snapshot_manager.go +++ b/src/internal/kopia/snapshot_manager.go @@ -248,21 +248,12 @@ func fetchPrevSnapshotManifests( // we can pass in. Can be expanded to return more than the most recent // snapshots, but may require more memory at runtime. for _, reason := range reasons { - logger.Ctx(ctx).Infow( - "searching for previous manifests for reason", - "service", reason.Service.String(), - "category", reason.Category.String()) + 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) if err != nil { - logger.Ctx(ctx). - With( - "err", err, - "service", reason.Service.String(), - "category", reason.Category.String()). - Warnw( - "fetching previous snapshot manifests for service/category/resource owner", - clues.InErr(err).Slice()...) + logger.CtxErr(ictx, err).Info("fetching previous snapshot manifests for service/category/resource owner") // Snapshot can still complete fine, just not as efficient. continue diff --git a/src/internal/kopia/upload.go b/src/internal/kopia/upload.go index 2b82c804d..08064ad08 100644 --- a/src/internal/kopia/upload.go +++ b/src/internal/kopia/upload.go @@ -360,7 +360,7 @@ func collectionEntries( err = errors.Wrap(err, "getting full item path") progress.errs.AddRecoverable(err) - logger.Ctx(ctx).With("err", err).Errorw("getting full item path", clues.InErr(err).Slice()...) + logger.CtxErr(ctx, err).Error("getting full item path") continue } diff --git a/src/internal/kopia/wrapper.go b/src/internal/kopia/wrapper.go index bd4b5d4e0..8a404f3d5 100644 --- a/src/internal/kopia/wrapper.go +++ b/src/internal/kopia/wrapper.go @@ -237,8 +237,6 @@ func (w Wrapper) makeSnapshotWithRoot( OnUpload: bc.Count, }, func(innerCtx context.Context, rw repo.RepositoryWriter) error { - log := logger.Ctx(innerCtx) - si := snapshot.SourceInfo{ Host: corsoHost, UserName: corsoUser, @@ -253,10 +251,12 @@ func (w Wrapper) makeSnapshotWithRoot( IgnoreDirectoryErrors: &trueVal, }, } + policyTree, err := policy.TreeForSourceWithOverride(innerCtx, w.c, si, errPolicy) if err != nil { err = clues.Wrap(err, "get policy tree").WithClues(ctx) - log.With("err", err).Errorw("building kopia backup", clues.InErr(err).Slice()...) + logger.CtxErr(innerCtx, err).Error("building kopia backup") + return err } @@ -269,7 +269,8 @@ func (w Wrapper) makeSnapshotWithRoot( man, err = u.Upload(innerCtx, root, policyTree, si, prevSnaps...) if err != nil { err = clues.Wrap(err, "uploading data").WithClues(ctx) - log.With("err", err).Errorw("uploading kopia backup", clues.InErr(err).Slice()...) + logger.CtxErr(innerCtx, err).Error("uploading kopia backup") + return err } @@ -277,7 +278,8 @@ func (w Wrapper) makeSnapshotWithRoot( if _, err := snapshot.SaveSnapshot(innerCtx, rw, man); err != nil { err = clues.Wrap(err, "saving snapshot").WithClues(ctx) - log.With("err", err).Errorw("persisting kopia backup snapshot", clues.InErr(err).Slice()...) + logger.CtxErr(innerCtx, err).Error("persisting kopia backup snapshot") + return err } diff --git a/src/pkg/logger/example_logger_test.go b/src/pkg/logger/example_logger_test.go index 685dae2b4..7b9ef9146 100644 --- a/src/pkg/logger/example_logger_test.go +++ b/src/pkg/logger/example_logger_test.go @@ -102,24 +102,32 @@ func Example_logger_standards() { // ExampleLoggerCluesStandards reviews code standards around using the Clues package while logging. func Example_logger_clues_standards() { - log := logger.Ctx(context.Background()) + ctx := clues.Add(context.Background(), "foo", "bar") + log := logger.Ctx(ctx) // 1. Clues Ctx values are always added in .Ctx(); you don't // need to add them directly. // // preferred - ctx := clues.Add(context.Background(), "item_id", itemID) + ctx = clues.Add(ctx, "item_id", itemID) logger.Ctx(ctx).Info("getting item") + // // avoid - ctx = clues.Add(context.Background(), "item_id", itemID) + ctx = clues.Add(ctx, "item_id", itemID) logger.Ctx(ctx).With(clues.In(ctx).Slice()...).Info("getting item") // 2. Always extract structured data from errors. // // preferred - log.With("err", err).Errorw("getting item", clues.InErr(err).Slice()...) + log.With("error", err).Errorw("getting item", clues.InErr(err).Slice()...) + // // avoid log.Errorw("getting item", "err", err) + // + // you can use the logger helper CtxErr() for the same results. + // This helps to ensure all error values get packed into the logs + // in the expected format. + logger.CtxErr(ctx, err).Error("getting item") // TODO(keepers): PII // 3. Protect pii in logs. diff --git a/src/pkg/logger/logger.go b/src/pkg/logger/logger.go index a1c215927..db80f8421 100644 --- a/src/pkg/logger/logger.go +++ b/src/pkg/logger/logger.go @@ -280,6 +280,14 @@ func Ctx(ctx context.Context) *zap.SugaredLogger { return l.(*zap.SugaredLogger).With(clues.In(ctx).Slice()...) } +// CtxErr retrieves the logger embedded in the context +// and packs all of the structured data in the error inside it. +func CtxErr(ctx context.Context, err error) *zap.SugaredLogger { + return Ctx(ctx). + With("error", err). + With(clues.InErr(err).Slice()...) +} + // transforms the llevel flag value to a logLevel enum func levelOf(lvl string) logLevel { switch lvl {