Logs: Tweak messages and log levels for improved readability

photoprism · Oct 2, 2021 · 9a88d7f · 9a88d7f
1 parent 8ebedf2
commit 9a88d7f
Show file tree

Hide file tree

Showing 32 changed files with 123 additions and 116 deletions.
diff --git a/internal/api/album.go b/internal/api/album.go
@@ -526,10 +526,10 @@ func DownloadAlbum(router *gin.RouterGroup) {
 				}
 				log.Infof("download: added %s as %s", txt.Quote(file.FileName), txt.Quote(alias))
 			} else {
-				log.Errorf("download: file %s is missing", txt.Quote(file.FileName))
+				log.Errorf("download: failed finding %s", txt.Quote(file.FileName))
 			}
 		}
 
-		log.Infof("download: album zip %s created in %s", txt.Quote(zipFileName), time.Since(start))
+		log.Infof("download: created %s in %s", txt.Quote(zipFileName), time.Since(start))
 	})
 }
diff --git a/internal/api/api.go b/internal/api/api.go
@@ -49,6 +49,12 @@ func logError(prefix string, err error) {
 	}
 }
 
+func logWarn(prefix string, err error) {
+	if err != nil {
+		log.Warnf("%s: %s", prefix, err.Error())
+	}
+}
+
 func UpdateClientConfig() {
 	conf := service.Config()
 

diff --git a/internal/api/batch.go b/internal/api/batch.go
@@ -66,10 +66,10 @@ func BatchPhotosArchive(router *gin.RouterGroup) {
 		}
 
 		// Update precalculated photo and file counts.
-		logError("photos", entity.UpdatePhotoCounts())
+		logWarn("index", entity.UpdateCounts())
 
 		// Update album, subject, and label cover thumbs.
-		logError("photos", query.UpdateCovers())
+		logWarn("index", query.UpdateCovers())
 
 		UpdateClientConfig()
 
@@ -128,10 +128,10 @@ func BatchPhotosRestore(router *gin.RouterGroup) {
 		}
 
 		// Update precalculated photo and file counts.
-		logError("photos", entity.UpdatePhotoCounts())
+		logWarn("index", entity.UpdateCounts())
 
 		// Update album, subject, and label cover thumbs.
-		logError("photos", query.UpdateCovers())
+		logWarn("index", query.UpdateCovers())
 
 		UpdateClientConfig()
 
@@ -264,7 +264,7 @@ func BatchPhotosPrivate(router *gin.RouterGroup) {
 		}
 
 		// Update precalculated photo and file counts.
-		logError("photos", entity.UpdatePhotoCounts())
+		logWarn("index", entity.UpdateCounts())
 
 		if photos, err := query.PhotoSelection(f); err == nil {
 			for _, p := range photos {
@@ -382,7 +382,7 @@ func BatchPhotosDelete(router *gin.RouterGroup) {
 		// Any photos deleted?
 		if len(deleted) > 0 {
 			// Update precalculated photo and file counts.
-			logError("photos", entity.UpdatePhotoCounts())
+			logWarn("index", entity.UpdateCounts())
 
 			UpdateClientConfig()
 

diff --git a/internal/api/import.go b/internal/api/import.go
@@ -113,7 +113,7 @@ func StartImport(router *gin.RouterGroup) {
 
 		// Update album, label, and subject cover thumbs.
 		if err := query.UpdateCovers(); err != nil {
-			log.Errorf("import: %s (update covers)", err)
+			log.Warnf("index: %s (update covers)", err)
 		}
 
 		c.JSON(http.StatusOK, i18n.Response{Code: http.StatusOK, Msg: msg})

diff --git a/internal/api/zip.go b/internal/api/zip.go
@@ -126,7 +126,7 @@ func CreateZip(router *gin.RouterGroup) {
 
 		elapsed := int(time.Since(start).Seconds())
 
-		log.Infof("download: zip %s created in %s", txt.Quote(zipBaseName), time.Since(start))
+		log.Infof("download: created %s in %s", txt.Quote(zipBaseName), time.Since(start))
 
 		c.JSON(http.StatusOK, gin.H{"code": http.StatusOK, "message": i18n.Msg(i18n.MsgZipCreatedIn, elapsed), "filename": zipBaseName})
 	})

diff --git a/internal/commands/cleanup.go b/internal/commands/cleanup.go
@@ -4,6 +4,8 @@ import (
 	"context"
 	"time"
 
+	"github.com/dustin/go-humanize/english"
+
 	"github.com/urfave/cli"
 
 	"github.com/photoprism/photoprism/internal/config"
@@ -55,9 +57,7 @@ func cleanUpAction(ctx *cli.Context) error {
 	if thumbs, orphans, err := w.Start(opt); err != nil {
 		return err
 	} else {
-		elapsed := time.Since(start)
-
-		log.Infof("cleanup: removed %d index entries and %d orphan thumbnails in %s", orphans, thumbs, elapsed)
+		log.Infof("cleanup: removed %s and %s [%s]", english.Plural(orphans, "index entry", "index entries"), english.Plural(thumbs, "thumbnail", "thumbnails"), time.Since(start))
 	}
 
 	conf.Shutdown()

diff --git a/internal/commands/faces.go b/internal/commands/faces.go
@@ -6,6 +6,8 @@ import (
 	"strings"
 	"time"
 
+	"github.com/dustin/go-humanize/english"
+
 	"github.com/manifoldco/promptui"
 	"github.com/urfave/cli"
 
@@ -270,13 +272,13 @@ func facesIndexAction(ctx *cli.Context) error {
 		if files, photos, err := w.Start(opt); err != nil {
 			log.Error(err)
 		} else if len(files) > 0 || len(photos) > 0 {
-			log.Infof("purge: removed %d files and %d photos", len(files), len(photos))
+			log.Infof("purge: removed %s and %s", english.Plural(len(files), "file", "files"), english.Plural(len(photos), "photo", "photos"))
 		}
 	}
 
 	elapsed := time.Since(start)
 
-	log.Infof("indexed %d files in %s", len(indexed), elapsed)
+	log.Infof("indexed %d files [%s]", len(indexed), elapsed)
 
 	conf.Shutdown()
 
@@ -341,7 +343,7 @@ func facesOptimizeAction(ctx *cli.Context) error {
 	} else {
 		elapsed := time.Since(start)
 
-		log.Infof("%d face clusters merged in %s", res.Merged, elapsed)
+		log.Infof("%d face clusters merged [%s]", res.Merged, elapsed)
 	}
 
 	conf.Shutdown()

diff --git a/internal/commands/index.go b/internal/commands/index.go
@@ -6,6 +6,8 @@ import (
 	"strings"
 	"time"
 
+	"github.com/dustin/go-humanize/english"
+
 	"github.com/urfave/cli"
 
 	"github.com/photoprism/photoprism/internal/config"
@@ -78,6 +80,7 @@ func indexAction(ctx *cli.Context) error {
 	}
 
 	if w := service.Purge(); w != nil {
+		purgeStart := time.Now()
 		opt := photoprism.PurgeOptions{
 			Path:   subPath,
 			Ignore: indexed,
@@ -86,11 +89,12 @@ func indexAction(ctx *cli.Context) error {
 		if files, photos, err := w.Start(opt); err != nil {
 			log.Error(err)
 		} else if len(files) > 0 || len(photos) > 0 {
-			log.Infof("purge: removed %d files and %d photos", len(files), len(photos))
+			log.Infof("purge: removed %s and %s [%s]", english.Plural(len(files), "file", "files"), english.Plural(len(photos), "photo", "photos"), time.Since(purgeStart))
 		}
 	}
 
 	if ctx.Bool("cleanup") {
+		cleanupStart := time.Now()
 		w := service.CleanUp()
 
 		opt := photoprism.CleanUpOptions{
@@ -100,13 +104,13 @@ func indexAction(ctx *cli.Context) error {
 		if thumbs, orphans, err := w.Start(opt); err != nil {
 			return err
 		} else {
-			log.Infof("cleanup: removed %d index entries and %d orphan thumbnails", orphans, thumbs)
+			log.Infof("cleanup: removed %s and %s [%s]", english.Plural(orphans, "index entry", "index entries"), english.Plural(thumbs, "thumbnail", "thumbnails"), time.Since(cleanupStart))
 		}
 	}
 
 	elapsed := time.Since(start)
 
-	log.Infof("indexed %d files in %s", len(indexed), elapsed)
+	log.Infof("indexed %d files [%s]", len(indexed), elapsed)
 
 	conf.Shutdown()
 

diff --git a/internal/commands/index_test.go b/internal/commands/index_test.go
@@ -49,9 +49,8 @@ func TestIndexCommand(t *testing.T) {
 		assert.Contains(t, output, "indexing originals")
 		assert.Contains(t, output, "classify: loading labels")
 		assert.Contains(t, output, "index: no .ppignore file found")
-		assert.Contains(t, output, "searching index for unassigned primary files")
-		assert.Contains(t, output, "searching index for hidden media files")
-		assert.Contains(t, output, "updating photo counts")
+		assert.Contains(t, output, "index: updating primary files")
+		assert.Contains(t, output, "index: flagging hidden files")
 	} else {
 		t.Fatal("log output missing")
 	}

diff --git a/internal/commands/migrate.go b/internal/commands/migrate.go
@@ -35,7 +35,7 @@ func migrateAction(ctx *cli.Context) error {
 
 	elapsed := time.Since(start)
 
-	log.Infof("database migration completed in %s", elapsed)
+	log.Infof("database migration completed [%s]", elapsed)
 
 	conf.Shutdown()
 

diff --git a/internal/commands/purge.go b/internal/commands/purge.go
@@ -6,6 +6,8 @@ import (
 	"strings"
 	"time"
 
+	"github.com/dustin/go-humanize/english"
+
 	"github.com/urfave/cli"
 
 	"github.com/photoprism/photoprism/internal/config"
@@ -76,7 +78,7 @@ func purgeAction(ctx *cli.Context) error {
 	} else {
 		elapsed := time.Since(start)
 
-		log.Infof("purge: removed %d files and %d photos in %s", len(files), len(photos), elapsed)
+		log.Infof("purge: removed %s and %s [%s]", english.Plural(len(files), "file", "files"), english.Plural(len(photos), "photo", "photos"), elapsed)
 	}
 
 	conf.Shutdown()

diff --git a/internal/commands/resample.go b/internal/commands/resample.go
@@ -46,7 +46,7 @@ func resampleAction(ctx *cli.Context) error {
 
 	elapsed := time.Since(start)
 
-	log.Infof("thumbnails created in %s", elapsed)
+	log.Infof("thumbnails created [%s]", elapsed)
 
 	return nil
 }
diff --git a/internal/commands/reset.go b/internal/commands/reset.go
@@ -57,7 +57,7 @@ func resetAction(ctx *cli.Context) error {
 			entity.Admin.InitPassword(conf.AdminPassword())
 		}
 
-		log.Infof("database reset completed in %s", time.Since(start))
+		log.Infof("database reset completed [%s]", time.Since(start))
 	} else {
 		log.Infof("keeping index database")
 	}
@@ -89,7 +89,7 @@ func resetAction(ctx *cli.Context) error {
 
 			fmt.Println("")
 
-			log.Infof("removed json files in %s", time.Since(start))
+			log.Infof("removed json files [%s]", time.Since(start))
 		} else {
 			log.Infof("no json files found")
 		}
@@ -124,7 +124,7 @@ func resetAction(ctx *cli.Context) error {
 
 			fmt.Println("")
 
-			log.Infof("removed files in %s", time.Since(start))
+			log.Infof("removed files [%s]", time.Since(start))
 		} else {
 			log.Infof("no metadata backups found for removal")
 		}
@@ -159,7 +159,7 @@ func resetAction(ctx *cli.Context) error {
 
 			fmt.Println("")
 
-			log.Infof("removed files in %s", time.Since(start))
+			log.Infof("removed files [%s]", time.Since(start))
 		} else {
 			log.Infof("no album backups found for removal")
 		}

diff --git a/internal/commands/restore.go b/internal/commands/restore.go
@@ -212,7 +212,7 @@ func restoreAction(ctx *cli.Context) error {
 
 	elapsed := time.Since(start)
 
-	log.Infof("backup restored in %s", elapsed)
+	log.Infof("backup restored [%s]", elapsed)
 
 	conf.Shutdown()
 

diff --git a/internal/entity/photo_counts.go → internal/entity/counts.go b/internal/entity/photo_counts.go → internal/entity/counts.go
@@ -46,8 +46,8 @@ func LabelCounts() LabelPhotoCounts {
 	return result
 }
 
-// UpdatePlacesPhotoCounts updates the places photo counts.
-func UpdatePlacesPhotoCounts() (err error) {
+// UpdatePlacesCounts updates the places photo counts.
+func UpdatePlacesCounts() (err error) {
 	start := time.Now()
 
 	// Update places.
@@ -62,7 +62,7 @@ func UpdatePlacesPhotoCounts() (err error) {
 		return res.Error
 	}
 
-	log.Debugf("counts: %s updated [%s]", english.Plural(int(res.RowsAffected), "place", "places"), time.Since(start))
+	log.Debugf("counts: updated %s [%s]", english.Plural(int(res.RowsAffected), "place", "places"), time.Since(start))
 
 	return nil
 }
@@ -114,13 +114,13 @@ func UpdateSubjectCounts() (err error) {
 		return res.Error
 	}
 
-	log.Debugf("counts: %s updated [%s]", english.Plural(int(res.RowsAffected), "subject", "subjects"), time.Since(start))
+	log.Debugf("counts: updated %s [%s]", english.Plural(int(res.RowsAffected), "subject", "subjects"), time.Since(start))
 
 	return nil
 }
 
-// UpdateLabelPhotoCounts updates the label photo counts.
-func UpdateLabelPhotoCounts() (err error) {
+// UpdateLabelCounts updates the label photo counts.
+func UpdateLabelCounts() (err error) {
 	start := time.Now()
 	var res *gorm.DB
 	if IsDialect(MySQL) {
@@ -166,14 +166,16 @@ func UpdateLabelPhotoCounts() (err error) {
 		return res.Error
 	}
 
-	log.Debugf("counts: %s updated [%s]", english.Plural(int(res.RowsAffected), "label", "labels"), time.Since(start))
+	log.Debugf("counts: updated %s [%s]", english.Plural(int(res.RowsAffected), "label", "labels"), time.Since(start))
 
 	return nil
 }
 
-// UpdatePhotoCounts updates precalculated photo and file counts.
-func UpdatePhotoCounts() (err error) {
-	if err = UpdatePlacesPhotoCounts(); err != nil {
+// UpdateCounts updates precalculated photo and file counts.
+func UpdateCounts() (err error) {
+	log.Info("index: updating counts")
+
+	if err = UpdatePlacesCounts(); err != nil {
 		if strings.Contains(err.Error(), "Error 1054") {
 			log.Errorf("counts: failed updating places, potentially incompatible database version")
 			log.Errorf("%s see https://jira.mariadb.org/browse/MDEV-25362", err)
@@ -193,7 +195,7 @@ func UpdatePhotoCounts() (err error) {
 		return err
 	}
 
-	if err = UpdateLabelPhotoCounts(); err != nil {
+	if err = UpdateLabelCounts(); err != nil {
 		return err
 	}
 

diff --git a/internal/entity/photo_counts_test.go → internal/entity/counts_test.go b/internal/entity/photo_counts_test.go → internal/entity/counts_test.go
@@ -17,7 +17,7 @@ func TestLabelCounts(t *testing.T) {
 }
 
 func TestUpdatePhotoCounts(t *testing.T) {
-	err := UpdatePhotoCounts()
+	err := UpdateCounts()
 
 	if err != nil {
 		t.Fatal(err)

diff --git a/internal/entity/file.go b/internal/entity/file.go
@@ -262,7 +262,7 @@ func (m *File) ReplaceHash(newHash string) error {
 		if res := UnscopedDb().Model(entity).Where("thumb = ?", oldHash).UpdateColumn("thumb", newHash); res.Error != nil {
 			return res.Error
 		} else if res.RowsAffected > 0 {
-			log.Infof("%s: %s updated [%s]", name, english.Plural(int(res.RowsAffected), "cover", "covers"), time.Since(start))
+			log.Infof("%s: updated %s [%s]", name, english.Plural(int(res.RowsAffected), "cover", "covers"), time.Since(start))
 		}
 	}
 

diff --git a/internal/entity/photo.go b/internal/entity/photo.go
@@ -187,8 +187,8 @@ func SavePhotoForm(model Photo, form form.Photo) error {
 	}
 
 	// Update precalculated photo and file counts.
-	if err := UpdatePhotoCounts(); err != nil {
-		log.Errorf("photo: %s", err)
+	if err := UpdateCounts(); err != nil {
+		log.Warnf("index: %s (update counts)", err)
 	}
 
 	return nil
@@ -315,8 +315,8 @@ func (m *Photo) SaveLabels() error {
 	}
 
 	// Update precalculated photo and file counts.
-	if err := UpdatePhotoCounts(); err != nil {
-		log.Errorf("photo: %s", err)
+	if err := UpdateCounts(); err != nil {
+		log.Warnf("index: %s (update counts)", err)
 	}
 
 	return nil
@@ -1041,8 +1041,8 @@ func (m *Photo) Approve() error {
 	}
 
 	// Update precalculated photo and file counts.
-	if err := UpdatePhotoCounts(); err != nil {
-		log.Errorf("photo: %s", err)
+	if err := UpdateCounts(); err != nil {
+		log.Warnf("index: %s (update counts)", err)
 	}
 
 	event.Publish("count.review", event.Data{