From a1587364639c8c5ead66429a199fa80dd33a4a6d Mon Sep 17 00:00:00 2001 From: Michael Mayer Date: Thu, 2 Jul 2020 09:44:45 +0200 Subject: [PATCH] Backend: Improve logging Signed-off-by: Michael Mayer --- internal/classify/tensorflow.go | 2 +- internal/meta/exif.go | 27 ++++++++-------- internal/photoprism/index_mediafile.go | 44 +++++++++++++------------- internal/photoprism/moments.go | 16 +++++----- 4 files changed, 45 insertions(+), 44 deletions(-) diff --git a/internal/classify/tensorflow.go b/internal/classify/tensorflow.go index 9ab13f4f8..51bd315e8 100644 --- a/internal/classify/tensorflow.go +++ b/internal/classify/tensorflow.go @@ -98,7 +98,7 @@ func (t *TensorFlow) Labels(img []byte) (result Labels, err error) { result = t.bestLabels(output[0].Value().([][]float32)[0]) if len(result) > 0 { - log.Debugf("tensorflow: image classified as %+v", result) + log.Tracef("tensorflow: image classified as %+v", result) } return result, nil diff --git a/internal/meta/exif.go b/internal/meta/exif.go index a1ca4ad59..45cb96ee8 100644 --- a/internal/meta/exif.go +++ b/internal/meta/exif.go @@ -44,9 +44,10 @@ func (data *Data) Exif(fileName string) (err error) { var rawExif []byte var parsed bool - fileExtension := strings.ToLower(path.Ext(fileName)) + logName := txt.Quote(filepath.Base(fileName)) + ext := strings.ToLower(path.Ext(fileName)) - if fileExtension == fs.JpegExt || fileExtension == ".jpeg" { + if ext == fs.JpegExt || ext == ".jpeg" { jmp := jpegstructure.NewJpegMediaParser() sl, err := jmp.ParseFile(fileName) @@ -59,14 +60,14 @@ func (data *Data) Exif(fileName string) (err error) { if err != nil { if err.Error() == "no exif header" { - return fmt.Errorf("metadata: no exif header in %s", txt.Quote(filepath.Base(fileName))) + return fmt.Errorf("metadata: no exif header in %s", logName) } else { - log.Warnf("metadata: %s in %s (parse jpeg)", err, txt.Quote(filepath.Base(fileName))) + log.Warnf("metadata: %s in %s (parse jpeg)", err, logName) } } else { parsed = true } - } else if fileExtension == ".png" { + } else if ext == ".png" { pmp := pngstructure.NewPngMediaParser() cs, err := pmp.ParseFile(fileName) @@ -79,9 +80,9 @@ func (data *Data) Exif(fileName string) (err error) { if err != nil { if err.Error() == "file does not have EXIF" { - return fmt.Errorf("metadata: no exif header in %s", txt.Quote(filepath.Base(fileName))) + return fmt.Errorf("metadata: no exif header in %s", logName) } else { - log.Warnf("metadata: %s in %s (parse png)", err, txt.Quote(filepath.Base(fileName))) + log.Warnf("metadata: %s in %s (parse png)", err, logName) } } else { parsed = true @@ -95,7 +96,7 @@ func (data *Data) Exif(fileName string) (err error) { rawExif, err = exif.SearchFileAndExtractExif(fileName) if err != nil { - return fmt.Errorf("metadata: no exif header in %s (search and extract)", txt.Quote(filepath.Base(fileName))) + return fmt.Errorf("metadata: no exif header in %s (search and extract)", logName) } } @@ -132,7 +133,7 @@ func (data *Data) Exif(fileName string) (err error) { valueString, err = ite.FormatFirst() if err != nil { - log.Errorf("metadata: %s (exif)", err.Error()) + log.Errorf("metadata: %s in %s (exif)", err, logName) return nil } @@ -291,7 +292,7 @@ func (data *Data) Exif(fileName string) (err error) { data.Lng = float32(gi.Longitude.Decimal()) data.Altitude = gi.Altitude } else { - log.Warnf("metadata: %s (exif gps info)", err) + log.Warnf("metadata: %s in %s (exif gps info)", err, logName) } } @@ -324,14 +325,14 @@ func (data *Data) Exif(fileName string) (err error) { data.TakenAt = data.TakenAtLocal if loc, err := time.LoadLocation(data.TimeZone); err != nil { - log.Warnf("metadata: unknown time zone %s", data.TimeZone) + log.Warnf("metadata: unknown time zone %s in %s (exif)", data.TimeZone, logName) } else if tl, err := time.ParseInLocation("2006:01:02 15:04:05", takenAt, loc); err == nil { data.TakenAt = tl.Round(time.Second).UTC() } else { - log.Errorf("metadata: %s", err.Error()) // this should never happen + log.Errorf("metadata: %s in %s (exif)", err.Error(), logName) // this should never happen } } else { - log.Warnf("metadata: invalid time %s", takenAt) + log.Warnf("metadata: invalid time %s in %s (exif)", takenAt, logName) } } diff --git a/internal/photoprism/index_mediafile.go b/internal/photoprism/index_mediafile.go index 8bef0c3f0..079b120f5 100644 --- a/internal/photoprism/index_mediafile.go +++ b/internal/photoprism/index_mediafile.go @@ -70,7 +70,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( fileRoot, fileBase, filePath, fileName := m.PathNameInfo() - quotedName := txt.Quote(fileName) + logName := txt.Quote(fileName) fileSize, fileModified := m.Stat() fileHash := "" @@ -141,7 +141,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( if yamlName := fs.TypeYaml.FindFirst(m.FileName(), []string{Config().SidecarPath(), fs.HiddenPath}, Config().OriginalsPath(), stripSequence); yamlName != "" { if err := photo.LoadFromYaml(yamlName); err != nil { - log.Errorf("index: %s (restore from yaml) for %s", err.Error(), quotedName) + log.Errorf("index: %s (restore from yaml) for %s", err.Error(), logName) } else { log.Infof("index: restored from %s", txt.Quote(fs.Rel(yamlName, Config().OriginalsPath()))) } @@ -187,7 +187,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( case m.IsJpeg(): // Color information if p, err := m.Colors(Config().ThumbPath()); err != nil { - log.Errorf("index: %s for %s", err.Error(), quotedName) + log.Errorf("index: %s for %s", err.Error(), logName) } else { file.FileMainColor = p.MainColor.Name() file.FileColors = p.Colors.Hex() @@ -258,13 +258,13 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( } if metaData.HasDocumentID() && photo.UUID == "" { - log.Debugf("index: %s has document id %s", quotedName, txt.Quote(metaData.DocumentID)) + log.Debugf("index: %s has document id %s", logName, txt.Quote(metaData.DocumentID)) photo.UUID = metaData.DocumentID } if metaData.HasInstanceID() && file.UUID == "" { - log.Debugf("index: %s has instance id %s", quotedName, txt.Quote(metaData.InstanceID)) + log.Debugf("index: %s has instance id %s", logName, txt.Quote(metaData.InstanceID)) file.UUID = metaData.InstanceID } @@ -315,13 +315,13 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( } if metaData.HasDocumentID() && photo.UUID == "" { - log.Debugf("index: %s has document id %s", quotedName, txt.Quote(metaData.DocumentID)) + log.Debugf("index: %s has document id %s", logName, txt.Quote(metaData.DocumentID)) photo.UUID = metaData.DocumentID } if metaData.HasInstanceID() && file.UUID == "" { - log.Debugf("index: %s has instance id %s", quotedName, txt.Quote(metaData.InstanceID)) + log.Debugf("index: %s has instance id %s", logName, txt.Quote(metaData.InstanceID)) file.UUID = metaData.InstanceID } @@ -410,13 +410,13 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( } if metaData.HasDocumentID() && photo.UUID == "" { - log.Debugf("index: %s has document id %s", quotedName, txt.Quote(metaData.DocumentID)) + log.Debugf("index: %s has document id %s", logName, txt.Quote(metaData.DocumentID)) photo.UUID = metaData.DocumentID } if metaData.HasInstanceID() && file.UUID == "" { - log.Debugf("index: %s has instance id %s", quotedName, txt.Quote(metaData.InstanceID)) + log.Debugf("index: %s has instance id %s", logName, txt.Quote(metaData.InstanceID)) file.UUID = metaData.InstanceID } @@ -481,7 +481,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( if photoExists { if err := entity.UnscopedDb().Save(&photo).Error; err != nil { - log.Errorf("index: %s for %s", err.Error(), quotedName) + log.Errorf("index: %s for %s", err.Error(), logName) result.Status = IndexFailed result.Error = err return result @@ -526,7 +526,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( labels := photo.ClassifyLabels() if err := photo.UpdateTitle(labels); err != nil { - log.Warnf("%s for %s", err.Error(), quotedName) + log.Warnf("%s for %s", err.Error(), logName) } w := txt.Keywords(photo.Details.Keywords) @@ -544,26 +544,26 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( photo.Details.Keywords = strings.Join(txt.UniqueWords(w), ", ") if photo.Details.Keywords != "" { - log.Debugf("index: set keywords %s for %s", photo.Details.Keywords, quotedName) + log.Tracef("index: set keywords %s for %s", photo.Details.Keywords, logName) } else { - log.Debugf("index: no keywords for %s", quotedName) + log.Tracef("index: no keywords for %s", logName) } photo.PhotoQuality = photo.QualityScore() if err := entity.UnscopedDb().Save(&photo).Error; err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) result.Status = IndexFailed result.Error = err return result } if err := photo.SyncKeywordLabels(); err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) } if err := photo.IndexKeywords(); err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) } } else { if photo.PhotoQuality >= 0 { @@ -571,7 +571,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( } if err := entity.UnscopedDb().Unscoped().Save(&photo).Error; err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) result.Status = IndexFailed result.Error = err return result @@ -584,7 +584,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( file.UpdatedIn = int64(time.Since(start)) if err := entity.UnscopedDb().Save(&file).Error; err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) result.Status = IndexFailed result.Error = err return result @@ -593,7 +593,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( file.CreatedIn = int64(time.Since(start)) if err := entity.UnscopedDb().Create(&file).Error; err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) result.Status = IndexFailed result.Error = err return result @@ -608,7 +608,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( if (photo.PhotoType == entity.TypeVideo || photo.PhotoType == entity.TypeLive) && file.FilePrimary { if err := file.UpdateVideoInfos(); err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) } } @@ -622,7 +622,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( } if err := query.SetDownloadFileID(downloadedAs, file.ID); err != nil { - log.Errorf("index: %s for %s", err, quotedName) + log.Errorf("index: %s for %s", err, logName) } // Write YAML sidecar file (optional). @@ -630,7 +630,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName string) ( yamlFile := photo.YamlFileName(Config().OriginalsPath(), Config().SidecarPath()) if err := photo.SaveAsYaml(yamlFile); err != nil { - log.Errorf("index: %s (update yaml) for %s", err.Error(), quotedName) + log.Errorf("index: %s (update yaml) for %s", err.Error(), logName) } else { log.Infof("index: updated yaml file %s", txt.Quote(fs.Rel(yamlFile, Config().OriginalsPath()))) } diff --git a/internal/photoprism/moments.go b/internal/photoprism/moments.go index 0f9140be7..bb5b94b4c 100644 --- a/internal/photoprism/moments.go +++ b/internal/photoprism/moments.go @@ -79,9 +79,9 @@ func (m *Moments) Start() (err error) { if a := entity.FindAlbumBySlug(mom.Slug(), entity.AlbumFolder); a != nil { if a.DeletedAt != nil { // Nothing to do. - log.Debugf("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } else { - log.Debugf("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } } else if a := entity.NewFolderAlbum(mom.Title(), mom.Slug(), f.Serialize()); a != nil { a.AlbumYear = mom.FolderYear @@ -105,9 +105,9 @@ func (m *Moments) Start() (err error) { if a := entity.FindAlbumBySlug(mom.Slug(), entity.AlbumMonth); a != nil { if a.DeletedAt != nil { // Nothing to do. - log.Debugf("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } else { - log.Debugf("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } } else if a := entity.NewMonthAlbum(mom.Title(), mom.Slug(), mom.Year, mom.Month); a != nil { if err := a.Create(); err != nil { @@ -133,9 +133,9 @@ func (m *Moments) Start() (err error) { if a := entity.FindAlbumBySlug(mom.Slug(), entity.AlbumMoment); a != nil { if a.DeletedAt != nil { // Nothing to do. - log.Debugf("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } else { - log.Debugf("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } } else if a := entity.NewMomentsAlbum(mom.Title(), mom.Slug(), f.Serialize()); a != nil { a.AlbumYear = mom.Year @@ -164,9 +164,9 @@ func (m *Moments) Start() (err error) { if a := entity.FindAlbumBySlug(mom.Slug(), entity.AlbumState); a != nil { if a.DeletedAt != nil { // Nothing to do. - log.Debugf("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s was deleted (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } else { - log.Debugf("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) + log.Tracef("moments: %s already exists (%s)", txt.Quote(a.AlbumTitle), a.AlbumFilter) } } else if a := entity.NewStateAlbum(mom.Title(), mom.Slug(), f.Serialize()); a != nil { a.AlbumCountry = mom.Country