From cc9ded05a3a241692c3ac0877f6c1b3a3ad49bb3 Mon Sep 17 00:00:00 2001 From: DingDongSoLong4 <99329275+DingDongSoLong4@users.noreply.github.com> Date: Fri, 26 May 2023 01:49:00 +0200 Subject: [PATCH] Error logging improvements (#3768) * Improve auto-tag error messages * Ignore another context canceled error * Ignore more graphql context canceled errors --- internal/api/error.go | 38 +++--- internal/manager/task_autotag.go | 199 +++++++++++++++++------------- pkg/scraper/stashbox/stash_box.go | 2 +- 3 files changed, 136 insertions(+), 103 deletions(-) diff --git a/internal/api/error.go b/internal/api/error.go index 208b2521c..5b30a8c12 100644 --- a/internal/api/error.go +++ b/internal/api/error.go @@ -11,27 +11,29 @@ import ( ) func gqlErrorHandler(ctx context.Context, e error) *gqlerror.Error { - // log all errors - for now just log the error message - // we can potentially add more context later - fc := graphql.GetFieldContext(ctx) - if fc != nil && !errors.Is(e, context.Canceled) { - logger.Errorf("%s: %v", fc.Path(), e) + if !errors.Is(ctx.Err(), context.Canceled) { + // log all errors - for now just log the error message + // we can potentially add more context later + fc := graphql.GetFieldContext(ctx) + if fc != nil { + logger.Errorf("%s: %v", fc.Path(), e) - // log the args in debug level - logger.DebugFunc(func() (string, []interface{}) { - var args interface{} - args = fc.Args + // log the args in debug level + logger.DebugFunc(func() (string, []interface{}) { + var args interface{} + args = fc.Args - s, _ := json.Marshal(args) - if len(s) > 0 { - args = string(s) - } + s, _ := json.Marshal(args) + if len(s) > 0 { + args = string(s) + } - return "%s: %v", []interface{}{ - fc.Path(), - args, - } - }) + return "%s: %v", []interface{}{ + fc.Path(), + args, + } + }) + } } // we may also want to transform the error message for the response diff --git a/internal/manager/task_autotag.go b/internal/manager/task_autotag.go index 0dfe59dd3..273e65f28 100644 --- a/internal/manager/task_autotag.go +++ b/internal/manager/task_autotag.go @@ -37,7 +37,7 @@ func (j *autoTagJob) Execute(ctx context.Context, progress *job.Progress) { j.autoTagSpecific(ctx, progress) } - logger.Infof("Finished autotag after %s", time.Since(begin).String()) + logger.Infof("Finished auto-tag after %s", time.Since(begin).String()) } func (j *autoTagJob) isFileBasedAutoTag(input AutoTagMetadataInput) bool { @@ -84,32 +84,34 @@ func (j *autoTagJob) autoTagSpecific(ctx context.Context, progress *job.Progress if performerCount == 1 && performerIds[0] == wildcard { performerCount, err = performerQuery.Count(ctx) if err != nil { - return fmt.Errorf("error getting performer count: %v", err) + return fmt.Errorf("getting performer count: %v", err) } } if studioCount == 1 && studioIds[0] == wildcard { studioCount, err = studioQuery.Count(ctx) if err != nil { - return fmt.Errorf("error getting studio count: %v", err) + return fmt.Errorf("getting studio count: %v", err) } } if tagCount == 1 && tagIds[0] == wildcard { tagCount, err = tagQuery.Count(ctx) if err != nil { - return fmt.Errorf("error getting tag count: %v", err) + return fmt.Errorf("getting tag count: %v", err) } } return nil }); err != nil { - logger.Error(err.Error()) + if !job.IsCancelled(ctx) { + logger.Errorf("auto-tag error: %v", err) + } return } total := performerCount + studioCount + tagCount progress.SetTotal(total) - logger.Infof("Starting autotag of %d performers, %d studios, %d tags", performerCount, studioCount, tagCount) + logger.Infof("Starting auto-tag of %d performers, %d studios, %d tags", performerCount, studioCount, tagCount) j.autoTagPerformers(ctx, progress, input.Paths, performerIds) j.autoTagStudios(ctx, progress, input.Paths, studioIds) @@ -142,7 +144,7 @@ func (j *autoTagJob) autoTagPerformers(ctx context.Context, progress *job.Progre PerPage: &perPage, }) if err != nil { - return fmt.Errorf("error querying performers: %w", err) + return fmt.Errorf("querying performers: %w", err) } } else { performerIdInt, err := strconv.Atoi(performerId) @@ -167,11 +169,10 @@ func (j *autoTagJob) autoTagPerformers(ctx context.Context, progress *job.Progre for _, performer := range performers { if job.IsCancelled(ctx) { - logger.Info("Stopping due to user request") return nil } - if err := func() error { + err := func() error { r := j.txnManager if err := tagger.PerformerScenes(ctx, performer, paths, r.Scene); err != nil { return fmt.Errorf("processing scenes: %w", err) @@ -184,8 +185,14 @@ func (j *autoTagJob) autoTagPerformers(ctx context.Context, progress *job.Progre } return nil - }(); err != nil { - return fmt.Errorf("error auto-tagging performer '%s': %s", performer.Name, err.Error()) + }() + + if job.IsCancelled(ctx) { + return nil + } + + if err != nil { + return fmt.Errorf("tagging performer '%s': %s", performer.Name, err.Error()) } progress.Increment() @@ -193,8 +200,12 @@ func (j *autoTagJob) autoTagPerformers(ctx context.Context, progress *job.Progre return nil }); err != nil { - logger.Error(err.Error()) - continue + logger.Errorf("auto-tag error: %v", err) + } + + if job.IsCancelled(ctx) { + logger.Info("Stopping performer auto-tag due to user request") + return } } } @@ -225,17 +236,17 @@ func (j *autoTagJob) autoTagStudios(ctx context.Context, progress *job.Progress, PerPage: &perPage, }) if err != nil { - return fmt.Errorf("error querying studios: %v", err) + return fmt.Errorf("querying studios: %v", err) } } else { studioIdInt, err := strconv.Atoi(studioId) if err != nil { - return fmt.Errorf("error parsing studio id %s: %s", studioId, err.Error()) + return fmt.Errorf("parsing studio id %s: %s", studioId, err.Error()) } studio, err := studioQuery.Find(ctx, studioIdInt) if err != nil { - return fmt.Errorf("error finding studio id %s: %s", studioId, err.Error()) + return fmt.Errorf("finding studio id %s: %s", studioId, err.Error()) } if studio == nil { @@ -247,11 +258,10 @@ func (j *autoTagJob) autoTagStudios(ctx context.Context, progress *job.Progress, for _, studio := range studios { if job.IsCancelled(ctx) { - logger.Info("Stopping due to user request") return nil } - if err := func() error { + err := func() error { aliases, err := r.Studio.GetAliases(ctx, studio.ID) if err != nil { return fmt.Errorf("getting studio aliases: %w", err) @@ -268,8 +278,14 @@ func (j *autoTagJob) autoTagStudios(ctx context.Context, progress *job.Progress, } return nil - }(); err != nil { - return fmt.Errorf("error auto-tagging studio '%s': %s", studio.Name.String, err.Error()) + }() + + if job.IsCancelled(ctx) { + return nil + } + + if err != nil { + return fmt.Errorf("tagging studio '%s': %s", studio.Name.String, err.Error()) } progress.Increment() @@ -277,8 +293,12 @@ func (j *autoTagJob) autoTagStudios(ctx context.Context, progress *job.Progress, return nil }); err != nil { - logger.Error(err.Error()) - continue + logger.Errorf("auto-tag error: %v", err) + } + + if job.IsCancelled(ctx) { + logger.Info("Stopping studio auto-tag due to user request") + return } } } @@ -308,28 +328,27 @@ func (j *autoTagJob) autoTagTags(ctx context.Context, progress *job.Progress, pa PerPage: &perPage, }) if err != nil { - return fmt.Errorf("error querying tags: %v", err) + return fmt.Errorf("querying tags: %v", err) } } else { tagIdInt, err := strconv.Atoi(tagId) if err != nil { - return fmt.Errorf("error parsing tag id %s: %s", tagId, err.Error()) + return fmt.Errorf("parsing tag id %s: %s", tagId, err.Error()) } tag, err := tagQuery.Find(ctx, tagIdInt) if err != nil { - return fmt.Errorf("error finding tag id %s: %s", tagId, err.Error()) + return fmt.Errorf("finding tag id %s: %s", tagId, err.Error()) } tags = append(tags, tag) } for _, tag := range tags { if job.IsCancelled(ctx) { - logger.Info("Stopping due to user request") return nil } - if err := func() error { + err := func() error { aliases, err := r.Tag.GetAliases(ctx, tag.ID) if err != nil { return fmt.Errorf("getting tag aliases: %w", err) @@ -346,8 +365,14 @@ func (j *autoTagJob) autoTagTags(ctx context.Context, progress *job.Progress, pa } return nil - }(); err != nil { - return fmt.Errorf("error auto-tagging tag '%s': %s", tag.Name, err.Error()) + }() + + if job.IsCancelled(ctx) { + return nil + } + + if err != nil { + return fmt.Errorf("tagging tag '%s': %s", tag.Name, err.Error()) } progress.Increment() @@ -355,8 +380,12 @@ func (j *autoTagJob) autoTagTags(ctx context.Context, progress *job.Progress, pa return nil }); err != nil { - logger.Error(err.Error()) - continue + logger.Errorf("auto-tag error: %v", err) + } + + if job.IsCancelled(ctx) { + logger.Info("Stopping tag auto-tag due to user request") + return } } } @@ -488,11 +517,13 @@ func (t *autoTagFilesTask) getCount(ctx context.Context, r Repository) (int, err return sceneCount + imageCount + galleryCount, nil } -func (t *autoTagFilesTask) processScenes(ctx context.Context, r Repository) error { +func (t *autoTagFilesTask) processScenes(ctx context.Context, r Repository) { if job.IsCancelled(ctx) { - return nil + return } + logger.Info("Auto-tagging scenes...") + batchSize := 1000 findFilter := models.BatchFindFilter(batchSize) @@ -506,12 +537,16 @@ func (t *autoTagFilesTask) processScenes(ctx context.Context, r Repository) erro scenes, err = scene.Query(ctx, r.Scene, sceneFilter, findFilter) return err }); err != nil { - return fmt.Errorf("querying scenes: %w", err) + if !job.IsCancelled(ctx) { + logger.Errorf("error querying scenes for auto-tag: %w", err) + } + return } for _, ss := range scenes { if job.IsCancelled(ctx) { - return nil + logger.Info("Stopping auto-tag due to user request") + return } tt := autoTagSceneTask{ @@ -541,15 +576,15 @@ func (t *autoTagFilesTask) processScenes(ctx context.Context, r Repository) erro } } } - - return nil } -func (t *autoTagFilesTask) processImages(ctx context.Context, r Repository) error { +func (t *autoTagFilesTask) processImages(ctx context.Context, r Repository) { if job.IsCancelled(ctx) { - return nil + return } + logger.Info("Auto-tagging images...") + batchSize := 1000 findFilter := models.BatchFindFilter(batchSize) @@ -563,12 +598,16 @@ func (t *autoTagFilesTask) processImages(ctx context.Context, r Repository) erro images, err = image.Query(ctx, r.Image, imageFilter, findFilter) return err }); err != nil { - return fmt.Errorf("querying images: %w", err) + if !job.IsCancelled(ctx) { + logger.Errorf("error querying images for auto-tag: %w", err) + } + return } for _, ss := range images { if job.IsCancelled(ctx) { - return nil + logger.Info("Stopping auto-tag due to user request") + return } tt := autoTagImageTask{ @@ -598,15 +637,15 @@ func (t *autoTagFilesTask) processImages(ctx context.Context, r Repository) erro } } } - - return nil } -func (t *autoTagFilesTask) processGalleries(ctx context.Context, r Repository) error { +func (t *autoTagFilesTask) processGalleries(ctx context.Context, r Repository) { if job.IsCancelled(ctx) { - return nil + return } + logger.Info("Auto-tagging galleries...") + batchSize := 1000 findFilter := models.BatchFindFilter(batchSize) @@ -620,12 +659,16 @@ func (t *autoTagFilesTask) processGalleries(ctx context.Context, r Repository) e galleries, _, err = r.Gallery.Query(ctx, galleryFilter, findFilter) return err }); err != nil { - return fmt.Errorf("querying galleries: %w", err) + if !job.IsCancelled(ctx) { + logger.Errorf("error querying galleries for auto-tag: %w", err) + } + return } for _, ss := range galleries { if job.IsCancelled(ctx) { - return nil + logger.Info("Stopping auto-tag due to user request") + return } tt := autoTagGalleryTask{ @@ -655,8 +698,6 @@ func (t *autoTagFilesTask) processGalleries(ctx context.Context, r Repository) e } } } - - return nil } func (t *autoTagFilesTask) process(ctx context.Context) { @@ -668,35 +709,19 @@ func (t *autoTagFilesTask) process(ctx context.Context) { } t.progress.SetTotal(total) - logger.Infof("Starting autotag of %d files", total) + logger.Infof("Starting auto-tag of %d files", total) return nil }); err != nil { - logger.Errorf("error getting count for autotag task: %v", err) + if !job.IsCancelled(ctx) { + logger.Errorf("error getting file count for auto-tag task: %v", err) + } return } - logger.Info("Autotagging scenes...") - if err := t.processScenes(ctx, r); err != nil { - logger.Errorf("error processing scenes: %w", err) - return - } - - logger.Info("Autotagging images...") - if err := t.processImages(ctx, r); err != nil { - logger.Errorf("error processing images: %w", err) - return - } - - logger.Info("Autotagging galleries...") - if err := t.processGalleries(ctx, r); err != nil { - logger.Errorf("error processing galleries: %w", err) - return - } - - if job.IsCancelled(ctx) { - logger.Info("Stopping due to user request") - } + t.processScenes(ctx, r) + t.processImages(ctx, r) + t.processGalleries(ctx, r) } type autoTagSceneTask struct { @@ -721,23 +746,25 @@ func (t *autoTagSceneTask) Start(ctx context.Context, wg *sync.WaitGroup) { if t.performers { if err := autotag.ScenePerformers(ctx, t.scene, r.Scene, r.Performer, t.cache); err != nil { - return fmt.Errorf("error tagging scene performers for %s: %v", t.scene.DisplayName(), err) + return fmt.Errorf("tagging scene performers for %s: %v", t.scene.DisplayName(), err) } } if t.studios { if err := autotag.SceneStudios(ctx, t.scene, r.Scene, r.Studio, t.cache); err != nil { - return fmt.Errorf("error tagging scene studio for %s: %v", t.scene.DisplayName(), err) + return fmt.Errorf("tagging scene studio for %s: %v", t.scene.DisplayName(), err) } } if t.tags { if err := autotag.SceneTags(ctx, t.scene, r.Scene, r.Tag, t.cache); err != nil { - return fmt.Errorf("error tagging scene tags for %s: %v", t.scene.DisplayName(), err) + return fmt.Errorf("tagging scene tags for %s: %v", t.scene.DisplayName(), err) } } return nil }); err != nil { - logger.Error(err.Error()) + if !job.IsCancelled(ctx) { + logger.Errorf("auto-tag error: %v", err) + } } } @@ -758,23 +785,25 @@ func (t *autoTagImageTask) Start(ctx context.Context, wg *sync.WaitGroup) { if err := t.txnManager.WithTxn(ctx, func(ctx context.Context) error { if t.performers { if err := autotag.ImagePerformers(ctx, t.image, r.Image, r.Performer, t.cache); err != nil { - return fmt.Errorf("error tagging image performers for %s: %v", t.image.DisplayName(), err) + return fmt.Errorf("tagging image performers for %s: %v", t.image.DisplayName(), err) } } if t.studios { if err := autotag.ImageStudios(ctx, t.image, r.Image, r.Studio, t.cache); err != nil { - return fmt.Errorf("error tagging image studio for %s: %v", t.image.DisplayName(), err) + return fmt.Errorf("tagging image studio for %s: %v", t.image.DisplayName(), err) } } if t.tags { if err := autotag.ImageTags(ctx, t.image, r.Image, r.Tag, t.cache); err != nil { - return fmt.Errorf("error tagging image tags for %s: %v", t.image.DisplayName(), err) + return fmt.Errorf("tagging image tags for %s: %v", t.image.DisplayName(), err) } } return nil }); err != nil { - logger.Error(err.Error()) + if !job.IsCancelled(ctx) { + logger.Errorf("auto-tag error: %v", err) + } } } @@ -795,22 +824,24 @@ func (t *autoTagGalleryTask) Start(ctx context.Context, wg *sync.WaitGroup) { if err := t.txnManager.WithTxn(ctx, func(ctx context.Context) error { if t.performers { if err := autotag.GalleryPerformers(ctx, t.gallery, r.Gallery, r.Performer, t.cache); err != nil { - return fmt.Errorf("error tagging gallery performers for %s: %v", t.gallery.DisplayName(), err) + return fmt.Errorf("tagging gallery performers for %s: %v", t.gallery.DisplayName(), err) } } if t.studios { if err := autotag.GalleryStudios(ctx, t.gallery, r.Gallery, r.Studio, t.cache); err != nil { - return fmt.Errorf("error tagging gallery studio for %s: %v", t.gallery.DisplayName(), err) + return fmt.Errorf("tagging gallery studio for %s: %v", t.gallery.DisplayName(), err) } } if t.tags { if err := autotag.GalleryTags(ctx, t.gallery, r.Gallery, r.Tag, t.cache); err != nil { - return fmt.Errorf("error tagging gallery tags for %s: %v", t.gallery.DisplayName(), err) + return fmt.Errorf("tagging gallery tags for %s: %v", t.gallery.DisplayName(), err) } } return nil }); err != nil { - logger.Error(err.Error()) + if !job.IsCancelled(ctx) { + logger.Errorf("auto-tag error: %v", err) + } } } diff --git a/pkg/scraper/stashbox/stash_box.go b/pkg/scraper/stashbox/stash_box.go index 713265e7c..1a83c1ab6 100644 --- a/pkg/scraper/stashbox/stash_box.go +++ b/pkg/scraper/stashbox/stash_box.go @@ -664,7 +664,7 @@ func performerFragmentToScrapedScenePerformer(p graphql.PerformerFragment) *mode func getFirstImage(ctx context.Context, client *http.Client, images []*graphql.ImageFragment) *string { ret, err := fetchImage(ctx, client, images[0].URL) - if err != nil { + if err != nil && !errors.Is(err, context.Canceled) { logger.Warnf("Error fetching image %s: %s", images[0].URL, err.Error()) }