From e92cb1b62bb87f0624d474ccd9f9f42ef0659c23 Mon Sep 17 00:00:00 2001 From: Keepers Date: Thu, 15 Sep 2022 07:18:05 -0600 Subject: [PATCH] extend logging support for testing (#850) ## Description Updating logging to help display/control within testing envs. Restore error tracking within gc iterators. ## Type of change - [x] :bug: Bugfix - [x] :robot: Test ## Issue(s) * #824 ## Test Plan - [ ] :muscle: Manual - [x] :zap: Unit test - [x] :green_heart: E2E --- src/cli/restore/exchange_integration_test.go | 3 + .../connector/exchange/iterators_test.go | 5 +- .../connector/exchange/service_iterators.go | 82 ++++++------------- .../connector/exchange/service_query.go | 6 +- src/internal/connector/graph_connector.go | 6 +- .../connector/graph_connector_test.go | 12 +++ src/pkg/logger/logger.go | 37 +++++++-- 7 files changed, 86 insertions(+), 65 deletions(-) diff --git a/src/cli/restore/exchange_integration_test.go b/src/cli/restore/exchange_integration_test.go index 587722255..edb72201d 100644 --- a/src/cli/restore/exchange_integration_test.go +++ b/src/cli/restore/exchange_integration_test.go @@ -14,6 +14,7 @@ import ( "github.com/alcionai/corso/src/internal/tester" "github.com/alcionai/corso/src/pkg/account" "github.com/alcionai/corso/src/pkg/control" + "github.com/alcionai/corso/src/pkg/logger" "github.com/alcionai/corso/src/pkg/repository" "github.com/alcionai/corso/src/pkg/selectors" "github.com/alcionai/corso/src/pkg/storage" @@ -127,6 +128,8 @@ func (suite *RestoreExchangeIntegrationSuite) TestExchangeRestoreCmd() { for _, set := range backupDataSets { suite.T().Run(set.String(), func(t *testing.T) { ctx := config.SetViper(tester.NewContext(), suite.vpr) + ctx, _ = logger.SeedLevel(ctx, logger.Development) + defer logger.Flush(ctx) cmd := tester.StubRootCmd( "restore", "exchange", diff --git a/src/internal/connector/exchange/iterators_test.go b/src/internal/connector/exchange/iterators_test.go index fc34fe55f..6ae0f14e4 100644 --- a/src/internal/connector/exchange/iterators_test.go +++ b/src/internal/connector/exchange/iterators_test.go @@ -168,12 +168,15 @@ func (suite *ExchangeIteratorSuite) TestIterativeFunctions() { // Create collection for iterate test collections := make(map[string]*Collection) var errs error + errUpdater := func(id string, err error) { + errs = support.WrapAndAppend(id, err, errs) + } // callbackFunc iterates through all models.Messageable and fills exchange.Collection.jobs[] // with corresponding item IDs. New collections are created for each directory callbackFunc := test.iterativeFunction( ctx, qp, - errs, + errUpdater, collections, nil) diff --git a/src/internal/connector/exchange/service_iterators.go b/src/internal/connector/exchange/service_iterators.go index 12f1ce1d5..b2a13be88 100644 --- a/src/internal/connector/exchange/service_iterators.go +++ b/src/internal/connector/exchange/service_iterators.go @@ -33,7 +33,7 @@ type displayable interface { type GraphIterateFunc func( ctx context.Context, qp graph.QueryParams, - errs error, + errUpdater func(string, error), collections map[string]*Collection, statusUpdater support.StatusUpdater, ) func(any) bool @@ -103,7 +103,7 @@ func resolveCollectionPath( func IterateSelectAllDescendablesForCollections( ctx context.Context, qp graph.QueryParams, - errs error, + errUpdater func(string, error), collections map[string]*Collection, statusUpdater support.StatusUpdater, ) func(any) bool { @@ -128,11 +128,7 @@ func IterateSelectAllDescendablesForCollections( } if r, err := maybeGetAndPopulateFolderResolver(ctx, qp, category); err != nil { - errs = support.WrapAndAppend( - "getting folder resolver for category "+category.String(), - err, - errs, - ) + errUpdater("getting folder resolver for category "+category.String(), err) } else { resolver = r } @@ -142,7 +138,7 @@ func IterateSelectAllDescendablesForCollections( entry, ok := pageItem.(descendable) if !ok { - errs = support.WrapAndAppendf(qp.User, errors.New("descendable conversion failure"), errs) + errUpdater(qp.User, errors.New("descendable conversion failure")) return true } @@ -156,8 +152,8 @@ func IterateSelectAllDescendablesForCollections( false, ) if err != nil { - errs = support.WrapAndAppend("converting to resource path", err, errs) - // This really shouldn't be happening unless we have a bad category. + // This really shouldn't happen unless we have a bad category. + errUpdater("converting to resource path", err) return true } @@ -173,7 +169,7 @@ func IterateSelectAllDescendablesForCollections( if err != nil { if !errors.Is(err, errNilResolver) { - errs = support.WrapAndAppend("", err, errs) + errUpdater("", err) } } else { dirPath = newPath @@ -181,7 +177,7 @@ func IterateSelectAllDescendablesForCollections( service, err := createService(qp.Credentials, qp.FailFast) if err != nil { - errs = support.WrapAndAppend(qp.User, err, errs) + errUpdater(qp.User, err) return true } @@ -208,7 +204,7 @@ func IterateSelectAllDescendablesForCollections( func IterateSelectAllEventsFromCalendars( ctx context.Context, qp graph.QueryParams, - errs error, + errUpdater func(string, error), collections map[string]*Collection, statusUpdater support.StatusUpdater, ) func(any) bool { @@ -219,21 +215,15 @@ func IterateSelectAllEventsFromCalendars( shell, ok := pageItem.(models.Calendarable) if !ok { - errs = support.WrapAndAppend( - qp.User, - errors.New("calendar event"), - errs) - + errUpdater(qp.User, errors.New("casting pageItem to models.Calendarable")) return true } service, err := createService(qp.Credentials, qp.FailFast) if err != nil { - errs = support.WrapAndAppend( + errUpdater( qp.User, - errors.Wrap(err, "unable to create service during IterateSelectAllEventsFromCalendars"), - errs, - ) + errors.Wrap(err, "creating service for IterateSelectAllEventsFromCalendars")) return true } @@ -243,11 +233,7 @@ func IterateSelectAllEventsFromCalendars( CalendarsById(*shell.GetId()). Events().Get() if err != nil { - errs = support.WrapAndAppend( - qp.User, - err, - errs, - ) + errUpdater(qp.User, err) } directory := shell.GetName() @@ -269,7 +255,7 @@ func IterateSelectAllEventsFromCalendars( if _, ok := collections[*directory]; !ok { service, err := createService(qp.Credentials, qp.FailFast) if err != nil { - errs = support.WrapAndAppend(qp.User, err, errs) + errUpdater(qp.User, err) return true } @@ -281,8 +267,8 @@ func IterateSelectAllEventsFromCalendars( false, ) if err != nil { - // This really shouldn't be happening. - errs = support.WrapAndAppend("converting to resource path", err, errs) + // we shouldn't ever hit this error + errUpdater("converting to resource path", err) return true } @@ -310,7 +296,7 @@ func IterateSelectAllEventsFromCalendars( func IterateAndFilterMessagesForCollections( ctx context.Context, qp graph.QueryParams, - errs error, + errUpdater func(string, error), collections map[string]*Collection, statusUpdater support.StatusUpdater, ) func(any) bool { @@ -325,7 +311,7 @@ func IterateAndFilterMessagesForCollections( statusUpdater, ) if err != nil { - errs = support.WrapAndAppend(qp.User, err, errs) + errUpdater(qp.User, err) return false } @@ -334,7 +320,7 @@ func IterateAndFilterMessagesForCollections( message, ok := messageItem.(descendable) if !ok { - errs = support.WrapAndAppend(qp.User, errors.New("message iteration failure"), errs) + errUpdater(qp.User, errors.New("casting messageItem to descendable")) return true } // Saving only messages for the created directories @@ -352,7 +338,7 @@ func IterateAndFilterMessagesForCollections( func IterateFilterFolderDirectoriesForCollections( ctx context.Context, qp graph.QueryParams, - errs error, + errUpdater func(string, error), collections map[string]*Collection, statusUpdater support.StatusUpdater, ) func(any) bool { @@ -363,22 +349,13 @@ func IterateFilterFolderDirectoriesForCollections( resolver, err := maybeGetAndPopulateFolderResolver(ctx, qp, path.EmailCategory) if err != nil { - errs = support.WrapAndAppend( - "getting folder resolver for category email", - err, - errs, - ) + errUpdater("getting folder resolver for category email", err) } return func(folderItem any) bool { folder, ok := folderItem.(displayable) if !ok { - errs = support.WrapAndAppend( - qp.User, - errors.New("unable to transform folderable item"), - errs, - ) - + errUpdater(qp.User, errors.New("casting folderItem to displayable")) return true } // Continue to iterate if folder name is empty @@ -399,8 +376,8 @@ func IterateFilterFolderDirectoriesForCollections( false, ) if err != nil { - // This really shouldn't be happening. - errs = support.WrapAndAppend("converting to resource path", err, errs) + // we shouldn't ever hit this error. + errUpdater("converting to resource path", err) return true } @@ -415,7 +392,7 @@ func IterateFilterFolderDirectoriesForCollections( if err != nil { if !errors.Is(err, errNilResolver) { - errs = support.WrapAndAppend("", err, errs) + errUpdater("", err) } } else { dirPath = p @@ -423,14 +400,9 @@ func IterateFilterFolderDirectoriesForCollections( service, err = createService(qp.Credentials, qp.FailFast) if err != nil { - errs = support.WrapAndAppend( + errUpdater( *folder.GetDisplayName(), - errors.Wrap( - err, - "unable to create service a folder query service for "+qp.User, - ), - errs, - ) + errors.Wrap(err, "creating service to iterate filterFolder directories for user: "+qp.User)) return true } diff --git a/src/internal/connector/exchange/service_query.go b/src/internal/connector/exchange/service_query.go index 3ba60cbb2..3f9b34de7 100644 --- a/src/internal/connector/exchange/service_query.go +++ b/src/internal/connector/exchange/service_query.go @@ -151,10 +151,14 @@ func CollectMailFolders( return errors.Wrap(err, "unable to create iterator during mail folder query service") } + errUpdater := func(id string, e error) { + err = support.WrapAndAppend(id, e, err) + } + callbackFunc := IterateFilterFolderDirectoriesForCollections( ctx, qp, - err, + errUpdater, collections, statusUpdater, ) diff --git a/src/internal/connector/graph_connector.go b/src/internal/connector/graph_connector.go index a1eb2f492..dd5c94ba5 100644 --- a/src/internal/connector/graph_connector.go +++ b/src/internal/connector/graph_connector.go @@ -370,10 +370,14 @@ func (gc *GraphConnector) createCollections( return nil, err } + errUpdater := func(id string, err error) { + errs = support.WrapAndAppend(id, err, errs) + } + // callbackFunc iterates through all M365 object target and fills exchange.Collection.jobs[] // with corresponding item M365IDs. New collections are created for each directory. // Each directory used the M365 Identifier. The use of ID stops collisions betweens users - callbackFunc := gIter(ctx, qp, errs, collections, gc.UpdateStatus) + callbackFunc := gIter(ctx, qp, errUpdater, collections, gc.UpdateStatus) iterateError := pageIterator.Iterate(callbackFunc) if iterateError != nil { diff --git a/src/internal/connector/graph_connector_test.go b/src/internal/connector/graph_connector_test.go index b977e27e9..1b0dfb549 100644 --- a/src/internal/connector/graph_connector_test.go +++ b/src/internal/connector/graph_connector_test.go @@ -270,6 +270,10 @@ func (suite *GraphConnectorIntegrationSuite) TestCreateAndDeleteMailFolder() { if aFolder != nil { err = exchange.DeleteMailFolder(suite.connector.Service(), suite.user, *aFolder.GetId()) assert.NoError(suite.T(), err) + + if err != nil { + suite.T().Log(support.ConnectorStackErrorTrace(err)) + } } } @@ -284,6 +288,10 @@ func (suite *GraphConnectorIntegrationSuite) TestCreateAndDeleteContactFolder() if aFolder != nil { err = exchange.DeleteContactFolder(suite.connector.Service(), suite.user, *aFolder.GetId()) assert.NoError(suite.T(), err) + + if err != nil { + suite.T().Log(support.ConnectorStackErrorTrace(err)) + } } } @@ -299,5 +307,9 @@ func (suite *GraphConnectorIntegrationSuite) TestCreateAndDeleteCalendar() { if calendar != nil { err = exchange.DeleteCalendar(service, suite.user, *calendar.GetId()) assert.NoError(suite.T(), err) + + if err != nil { + suite.T().Log(support.ConnectorStackErrorTrace(err)) + } } } diff --git a/src/pkg/logger/logger.go b/src/pkg/logger/logger.go index 0d3f84c7c..ebe57a9a4 100644 --- a/src/pkg/logger/logger.go +++ b/src/pkg/logger/logger.go @@ -38,11 +38,7 @@ func AddLogLevelFlag(parent *cobra.Command) { fs.StringVar(&llFlag, "log-level", "info", "set the log level to debug|info|warn|error") } -func singleton(level logLevel) *zap.SugaredLogger { - if loggerton != nil { - return loggerton - } - +func genLogger(level logLevel) (*zapcore.Core, *zap.SugaredLogger) { // when testing, ensure debug logging matches the test.v setting for _, arg := range os.Args { if arg == `--test.v=true` { @@ -68,7 +64,6 @@ func singleton(level logLevel) *zap.SugaredLogger { core := zapcore.NewTee( zapcore.NewCore(consoleEncoder, out, levelFilter), ) - logCore = &core // then try to set up a logger directly var ( @@ -96,7 +91,22 @@ func singleton(level logLevel) *zap.SugaredLogger { lgr = zap.New(*logCore) } - loggerton = lgr.Sugar() + return &core, lgr.Sugar() +} + +func singleton(level logLevel) *zap.SugaredLogger { + if loggerton != nil { + return loggerton + } + + if logCore != nil { + lgr := zap.New(*logCore) + loggerton = lgr.Sugar() + + return loggerton + } + + logCore, loggerton = genLogger(level) return loggerton } @@ -141,6 +151,14 @@ func Seed(ctx context.Context) (ctxOut context.Context, zsl *zap.SugaredLogger) return // return values handled in defer } +// SeedLevel embeds a logger into the context with the given log-level. +func SeedLevel(ctx context.Context, level logLevel) (context.Context, *zap.SugaredLogger) { + _, zsl := genLogger(level) + ctxWV := context.WithValue(ctx, ctxKey, zsl) + + return ctxWV, zsl +} + // Ctx retrieves the logger embedded in the context. func Ctx(ctx context.Context) *zap.SugaredLogger { l := ctx.Value(ctxKey) @@ -164,3 +182,8 @@ func levelOf(lvl string) logLevel { return Info } + +// Flush writes out all buffered logs. +func Flush(ctx context.Context) { + _ = Ctx(ctx).Sync() +}