Cleanup: Remove cached JSON files and further improve logs #2521

Signed-off-by: Michael Mayer <michael@photoprism.app>
This commit is contained in:
Michael Mayer 2022-07-22 19:18:42 +02:00
parent b7a0526d3f
commit cd9ec023d3
12 changed files with 213 additions and 135 deletions

View file

@ -2,6 +2,9 @@ package api
import (
"net/http"
"time"
"github.com/dustin/go-humanize/english"
"github.com/gin-gonic/gin"
"github.com/jinzhu/gorm"
@ -371,7 +374,8 @@ func BatchPhotosDelete(router *gin.RouterGroup) {
log.Infof("photos: deleting %s", clean.Log(f.String()))
// Fetch selection from index.
// Fetch selection from index and record time.
deleteStart := time.Now()
photos, err := query.SelectedPhotos(f)
if err != nil {
@ -381,15 +385,25 @@ func BatchPhotosDelete(router *gin.RouterGroup) {
var deleted entity.Photos
var numFiles = 0
// Delete photos.
for _, p := range photos {
if err = photoprism.DeletePhoto(p, true, true); err != nil {
n, err := photoprism.DeletePhoto(p, true, true)
numFiles += n
if err != nil {
log.Errorf("delete: %s", err)
} else {
deleted = append(deleted, p)
}
}
if numFiles > 0 {
log.Infof("delete: removed %s [%s]", english.Plural(numFiles, "file", "files"), time.Since(deleteStart))
}
// Any photos deleted?
if len(deleted) > 0 {
// Update precalculated photo and file counts.

View file

@ -15,6 +15,7 @@ import (
"github.com/photoprism/photoprism/internal/service"
)
// DeleteFile removes a file from storage.
// DELETE /api/v1/photos/:uid/files/:file_uid
//
// Parameters:
@ -41,42 +42,52 @@ func DeleteFile(router *gin.RouterGroup) {
file, err := query.FileByUID(fileUID)
// Found?
if err != nil {
log.Errorf("photo: %s (delete file)", err)
log.Errorf("files: %s (delete)", err)
AbortEntityNotFound(c)
return
}
// Primary file?
if file.FilePrimary {
log.Errorf("photo: cannot delete primary file")
log.Errorf("files: cannot delete primary file")
AbortDeleteFailed(c)
return
}
// Compose storage filename.
fileName := photoprism.FileName(file.FileRoot, file.FileName)
baseName := filepath.Base(fileName)
mediaFile, err := photoprism.NewMediaFile(fileName)
if err != nil {
log.Errorf("photo: %s (delete %s)", err, clean.Log(baseName))
log.Errorf("files: %s (delete %s)", err, clean.Log(baseName))
AbortEntityNotFound(c)
return
}
// Remove file from storage.
if err = mediaFile.Remove(); err != nil {
log.Errorf("photo: %s (delete %s from folder)", err, clean.Log(baseName))
log.Errorf("files: %s (delete %s from folder)", err, clean.Log(baseName))
} else {
log.Infof("files: deleted %s", clean.Log(baseName))
}
// Remove file from index.
if err = file.Delete(true); err != nil {
log.Errorf("photo: %s (delete %s from index)", err, clean.Log(baseName))
log.Errorf("files: %s (delete %s from index)", err, clean.Log(baseName))
AbortDeleteFailed(c)
return
} else {
log.Debugf("files: removed %s from index", clean.Log(baseName))
}
// Notify clients by publishing events.
PublishPhotoEvent(EntityUpdated, photoUID, c)
// Show translated success message.
event.SuccessMsg(i18n.MsgFileDeleted)
if p, err := query.PhotoPreloadByUID(photoUID); err != nil {

View file

@ -29,7 +29,7 @@ var cleanUpFlags = []cli.Flag{
// cleanUpAction removes orphaned index entries, sidecar and thumbnail files.
func cleanUpAction(ctx *cli.Context) error {
start := time.Now()
cleanupStart := time.Now()
conf := config.NewConfig(ctx)
service.SetConfig(conf)
@ -53,10 +53,11 @@ func cleanUpAction(ctx *cli.Context) error {
Dry: ctx.Bool("dry"),
}
if thumbs, orphans, err := w.Start(opt); err != nil {
// Start cleanup worker.
if thumbnails, _, sidecars, err := w.Start(opt); err != nil {
return err
} else {
log.Infof("removed %s and %s in %s", english.Plural(orphans, "index entry", "index entries"), english.Plural(thumbs, "thumbnail", "thumbnails"), time.Since(start))
} else if total := thumbnails + sidecars; total > 0 {
log.Infof("removed %s in %s", english.Plural(total, "file", "files"), time.Since(cleanupStart))
}
conf.Shutdown()

View file

@ -101,10 +101,11 @@ func indexAction(ctx *cli.Context) error {
Dry: false,
}
if thumbs, orphans, err := w.Start(opt); err != nil {
// Start cleanup worker.
if thumbnails, _, sidecars, err := w.Start(opt); err != nil {
return err
} else {
log.Infof("cleanup: removed %s and %s [%s]", english.Plural(orphans, "index entry", "index entries"), english.Plural(thumbs, "thumbnail", "thumbnails"), time.Since(cleanupStart))
} else if total := thumbnails + sidecars; total > 0 {
log.Infof("cleanup: removed %s in total [%s]", english.Plural(total, "file", "files"), time.Since(cleanupStart))
}
}

View file

@ -7,6 +7,7 @@ import (
"path/filepath"
"runtime/debug"
"strings"
"time"
"github.com/dustin/go-humanize/english"
@ -35,7 +36,7 @@ func NewCleanUp(conf *config.Config) *CleanUp {
}
// Start removes orphan index entries and thumbnails.
func (w *CleanUp) Start(opt CleanUpOptions) (thumbs int, orphans int, err error) {
func (w *CleanUp) Start(opt CleanUpOptions) (thumbs int, orphans int, sidecars int, err error) {
defer func() {
if r := recover(); r != nil {
err = fmt.Errorf("cleanup: %s (panic)\nstack: %s", r, debug.Stack())
@ -45,7 +46,7 @@ func (w *CleanUp) Start(opt CleanUpOptions) (thumbs int, orphans int, err error)
if err = mutex.MainWorker.Start(); err != nil {
log.Warnf("cleanup: %s (start)", err)
return thumbs, orphans, err
return thumbs, orphans, sidecars, err
}
defer mutex.MainWorker.Stop()
@ -54,20 +55,105 @@ func (w *CleanUp) Start(opt CleanUpOptions) (thumbs int, orphans int, err error)
log.Infof("cleanup: dry run, nothing will actually be removed")
}
// Find and remove orphan photo index entries.
cleanupStart := time.Now()
photos, err := query.OrphanPhotos()
if err != nil {
return thumbs, orphans, sidecars, err
}
var deleted []string
// Delete orphaned photos from the index and remaining sidecar files from storage, if any.
for _, p := range photos {
if mutex.MainWorker.Canceled() {
return thumbs, orphans, sidecars, errors.New("cleanup canceled")
}
if opt.Dry {
orphans++
log.Infof("cleanup: %s would be removed from index", p.String())
continue
}
// Deletes the index entry and remaining sidecar files outside the "originals" folder.
if n, err := DeletePhoto(p, true, false); err != nil {
sidecars += n
log.Errorf("cleanup: %s (remove orphans)", err)
} else {
orphans++
sidecars += n
deleted = append(deleted, p.PhotoUID)
log.Infof("cleanup: removed %s from index", p.String())
}
}
log.Infof("cleanup: removed %s and %s [%s]", english.Plural(orphans, "index entry", "index entries"), english.Plural(sidecars, "sidecar file", "sidecar files"), time.Since(cleanupStart))
// Remove orphan index entries.
if opt.Dry {
if files, err := query.OrphanFiles(); err != nil {
log.Errorf("index: %s (find orphan files)", err)
} else if l := len(files); l > 0 {
log.Infof("index: found %s", english.Plural(l, "orphan file", "orphan files"))
} else {
log.Infof("index: found no orphan files")
}
} else {
if err = query.PurgeOrphans(); err != nil {
log.Errorf("index: %s (purge orphans)", err)
}
}
// Remove thumbnail files.
thumbs, err = w.Thumbs(opt)
// Only update counts if anything was deleted.
if len(deleted) > 0 {
// Update precalculated photo and file counts.
if err = entity.UpdateCounts(); err != nil {
log.Warnf("index: %s (update counts)", err)
}
// Update album, subject, and label cover thumbs.
if err = query.UpdateCovers(); err != nil {
log.Warnf("index: %s (update covers)", err)
}
// Show success notification.
event.EntitiesDeleted("photos", deleted)
}
return thumbs, orphans, sidecars, err
}
// Thumbs removes orphan thumbnail files.
func (w *CleanUp) Thumbs(opt CleanUpOptions) (thumbs int, err error) {
cleanupStart := time.Now()
var fileHashes, thumbHashes query.HashMap
// Fetch existing media and thumb file hashes.
if fileHashes, err = query.FileHashMap(); err != nil {
return thumbs, orphans, err
return thumbs, err
} else if thumbHashes, err = query.ThumbHashMap(); err != nil {
return thumbs, orphans, err
return thumbs, err
}
// At least one SHA1 checksum found?
if len(fileHashes) == 0 {
log.Info("cleanup: empty index, aborting search for orphaned thumbnails")
return thumbs, err
}
// Thumbnails storage path.
thumbPath := w.conf.ThumbCachePath()
log.Info("cleanup: searching for orphaned thumbnails")
// Find and remove orphan thumbnail files.
if err := fastwalk.Walk(thumbPath, func(fileName string, info os.FileMode) error {
err = fastwalk.Walk(thumbPath, func(fileName string, info os.FileMode) error {
base := filepath.Base(fileName)
if info.IsDir() || strings.HasPrefix(base, ".") {
@ -86,7 +172,7 @@ func (w *CleanUp) Start(opt CleanUpOptions) (thumbs int, orphans int, err error)
if ok := fileHashes[hash]; ok {
// Do nothing.
} else if ok := thumbHashes[hash]; ok {
} else if ok = thumbHashes[hash]; ok {
// Do nothing.
} else if opt.Dry {
thumbs++
@ -95,78 +181,15 @@ func (w *CleanUp) Start(opt CleanUpOptions) (thumbs int, orphans int, err error)
log.Warnf("cleanup: %s in %s", err, logName)
} else {
thumbs++
log.Debugf("cleanup: removed thumbnail %s", logName)
log.Debugf("cleanup: removed thumbnail %s from cache", logName)
}
return nil
}); err != nil {
return thumbs, orphans, err
}
})
// Find and remove orphan photo index entries.
photos, err := query.OrphanPhotos()
log.Infof("cleanup: removed %s [%s]", english.Plural(thumbs, "thumbnail file", "thumbnail files"), time.Since(cleanupStart))
if err != nil {
return thumbs, orphans, err
}
var deleted []string
purgeOriginalSidecars := conf.OriginalsDeletable()
for _, p := range photos {
if mutex.MainWorker.Canceled() {
return thumbs, orphans, errors.New("cleanup canceled")
}
if opt.Dry {
orphans++
log.Infof("cleanup: %s would be removed from index", p.String())
continue
}
// Delete the photo from the index without removing remaining media files.
if err = DeletePhoto(p, true, purgeOriginalSidecars); err != nil {
log.Errorf("cleanup: %s (remove orphans)", err)
} else {
orphans++
deleted = append(deleted, p.PhotoUID)
log.Debugf("cleanup: removed %s from index", p.String())
}
}
// Remove orphan index entries.
if opt.Dry {
if files, err := query.OrphanFiles(); err != nil {
log.Errorf("index: %s (find orphan files)", err)
} else if l := len(files); l > 0 {
log.Infof("index: found %s", english.Plural(l, "orphan file", "orphan files"))
} else {
log.Infof("index: found no orphan files")
}
} else {
if err = query.PurgeOrphans(); err != nil {
log.Errorf("index: %s (purge orphans)", err)
}
}
// Only update counts if anything was deleted.
if len(deleted) > 0 {
// Update precalculated photo and file counts.
if err = entity.UpdateCounts(); err != nil {
log.Warnf("index: %s (update counts)", err)
}
// Update album, subject, and label cover thumbs.
if err = query.UpdateCovers(); err != nil {
log.Warnf("index: %s (update covers)", err)
}
// Show success notification.
event.EntitiesDeleted("photos", deleted)
}
return thumbs, orphans, nil
return thumbs, err
}
// Cancel stops the current operation.

View file

@ -10,31 +10,35 @@ import (
)
// DeletePhoto removes a photo from the index and optionally all related media files.
func DeletePhoto(p entity.Photo, mediaFiles bool, originals bool) error {
func DeletePhoto(p entity.Photo, mediaFiles bool, originals bool) (numFiles int, err error) {
yamlFileName := p.YamlFileName(Config().OriginalsPath(), Config().SidecarPath())
// Permanently remove photo from index.
files, err := p.DeletePermanently()
if err != nil {
return err
return 0, err
}
if mediaFiles {
DeleteFiles(files, originals)
numFiles = DeleteFiles(files, originals)
}
// Remove sidecar backup.
if fs.FileExists(yamlFileName) {
log.Debugf("media: removing yaml sidecar %s", clean.Log(filepath.Base(yamlFileName)))
logWarn("media", os.Remove(yamlFileName))
if !fs.FileExists(yamlFileName) {
return numFiles, nil
} else if err := os.Remove(yamlFileName); err != nil {
log.Warnf("files: failed deleting sidecar %s", clean.Log(filepath.Base(yamlFileName)))
} else {
numFiles++
log.Infof("files: deleted sidecar %s", clean.Log(filepath.Base(yamlFileName)))
}
return nil
return numFiles, nil
}
// DeleteFiles permanently deletes media and related sidecar files.
func DeleteFiles(files entity.Files, originals bool) {
func DeleteFiles(files entity.Files, originals bool) (numFiles int) {
for _, file := range files {
fileName := FileName(file.FileRoot, file.FileName)
@ -48,37 +52,53 @@ func DeleteFiles(files entity.Files, originals bool) {
// Log media file error if any.
if err != nil {
log.Debugf("media: %s not found", clean.Log(file.FileName))
log.Tracef("files: %s", err)
}
// Remove sidecar JSON files.
if sidecarJson := f.SidecarJsonName(); fs.FileExists(sidecarJson) {
log.Debugf("media: removing json sidecar %s", clean.Log(filepath.Base(sidecarJson)))
logWarn("delete", os.Remove(sidecarJson))
}
if exifJson, err := f.ExifToolJsonName(); err == nil && fs.FileExists(exifJson) {
log.Debugf("media: removing exiftool sidecar %s", clean.Log(filepath.Base(exifJson)))
logWarn("media", os.Remove(exifJson))
// Remove original JSON sidecar file, if any.
if jsonFile := f.FileName() + ".json"; !originals && f.Root() == entity.RootOriginals || !fs.FileExists(jsonFile) {
// Do nothing.
} else if err = os.Remove(jsonFile); err != nil {
log.Warnf("files: failed deleting sidecar %s", clean.Log(filepath.Base(jsonFile)))
} else {
numFiles++
log.Infof("files: deleted sidecar %s", clean.Log(filepath.Base(jsonFile)))
}
// Remove any other sidecar files.
logWarn("media", f.RemoveSidecars())
// Remove Exiftool JSON file in cache folder.
if exifJson, _ := ExifToolCacheName(file.FileHash); !fs.FileExists(exifJson) {
// Do nothing.
} else if err = os.Remove(exifJson); err != nil {
log.Warnf("files: failed deleting sidecar %s", clean.Log(filepath.Base(exifJson)))
} else {
numFiles++
log.Infof("files: deleted sidecar %s", clean.Log(filepath.Base(exifJson)))
}
// Remove any other files in the sidecar folder.
if n, _ := f.RemoveSidecarFiles(); n > 0 {
numFiles += n
}
// Continue if the media file does not exist or should be preserved.
if !fs.FileExists(fileName) {
continue
} else if !originals && f.Root() == entity.RootOriginals {
log.Debugf("media: skipped original %s", clean.Log(file.FileName))
continue
}
log.Debugf("media: removing %s", clean.Log(file.FileName))
// Remove media file.
if err = f.Remove(); err != nil {
log.Errorf("media: removed %s", clean.Log(file.FileName))
// Remove the original media file, if it exists and is allowed.
if relName := f.RootRelName(); relName == "" {
log.Warnf("files: relative filename of %s must not be empty - bug?", clean.Log(fileName))
continue
} else if !originals && f.Root() == entity.RootOriginals {
log.Debugf("files: skipped deleting %s", clean.Log(relName))
continue
} else if err = f.Remove(); err != nil {
log.Errorf("files: failed deleting %s", clean.Log(relName))
} else {
log.Infof("media: failed removing %s", clean.Log(file.FileName))
numFiles++
log.Infof("files: deleted %s", clean.Log(relName))
}
}
return numFiles
}

View file

@ -46,6 +46,11 @@ func CacheName(fileHash, namespace, cacheKey string) (cacheName string, err erro
return cacheName, nil
}
// ExifToolCacheName returns the ExifTool metadata cache file name.
func ExifToolCacheName(hash string) (string, error) {
return CacheName(hash, "json", "exiftool.json")
}
// RelName returns the relative filename.
func RelName(fileName, directory string) string {
return fs.RelName(fileName, directory)

View file

@ -107,7 +107,7 @@ func (ind *Index) MediaFile(m *MediaFile, o IndexOptions, originalName, photoUID
result.Status = IndexFailed
result.Err = fmt.Errorf("index: %s in %s (rename)", err, logName)
return result
} else if renamedSidecars, err := m.RenameSidecars(indFileName); err != nil {
} else if renamedSidecars, err := m.RenameSidecarFiles(indFileName); err != nil {
log.Errorf("index: %s in %s (rename sidecars)", err.Error(), logName)
fileRenamed = true

View file

@ -1106,8 +1106,8 @@ func (m *MediaFile) Orientation() int {
return 1
}
// RenameSidecars moves related sidecar files.
func (m *MediaFile) RenameSidecars(oldFileName string) (renamed map[string]string, err error) {
// RenameSidecarFiles moves related sidecar files.
func (m *MediaFile) RenameSidecarFiles(oldFileName string) (renamed map[string]string, err error) {
renamed = make(map[string]string)
sidecarPath := Config().SidecarPath()
@ -1130,9 +1130,9 @@ func (m *MediaFile) RenameSidecars(oldFileName string) (renamed map[string]strin
renamed[fs.RelName(srcName, sidecarPath)] = fs.RelName(destName, sidecarPath)
if err := os.Remove(srcName); err != nil {
log.Errorf("media: failed removing sidecar %s", clean.Log(fs.RelName(srcName, sidecarPath)))
log.Errorf("files: failed removing sidecar %s", clean.Log(fs.RelName(srcName, sidecarPath)))
} else {
log.Infof("media: removed sidecar %s", clean.Log(fs.RelName(srcName, sidecarPath)))
log.Infof("files: removed sidecar %s", clean.Log(fs.RelName(srcName, sidecarPath)))
}
continue
@ -1141,7 +1141,7 @@ func (m *MediaFile) RenameSidecars(oldFileName string) (renamed map[string]strin
if err := fs.Move(srcName, destName); err != nil {
return renamed, err
} else {
log.Infof("media: moved existing sidecar to %s", clean.Log(newName+filepath.Ext(srcName)))
log.Infof("files: moved existing sidecar to %s", clean.Log(newName+filepath.Ext(srcName)))
renamed[fs.RelName(srcName, sidecarPath)] = fs.RelName(destName, sidecarPath)
}
}
@ -1149,12 +1149,12 @@ func (m *MediaFile) RenameSidecars(oldFileName string) (renamed map[string]strin
return renamed, nil
}
// RemoveSidecars permanently removes related sidecar files.
func (m *MediaFile) RemoveSidecars() (err error) {
// RemoveSidecarFiles permanently removes related sidecar files.
func (m *MediaFile) RemoveSidecarFiles() (numFiles int, err error) {
fileName := m.FileName()
if fileName == "" {
return fmt.Errorf("empty filename")
return numFiles, fmt.Errorf("empty filename")
}
sidecarPath := Config().SidecarPath()
@ -1166,18 +1166,19 @@ func (m *MediaFile) RemoveSidecars() (err error) {
matches, err := filepath.Glob(regexp.QuoteMeta(globPrefix) + "*")
if err != nil {
return err
return numFiles, err
}
for _, sidecarName := range matches {
if err = os.Remove(sidecarName); err != nil {
log.Errorf("media: failed removing sidecar %s", clean.Log(fs.RelName(sidecarName, sidecarPath)))
log.Errorf("files: failed deleting sidecar %s", clean.Log(fs.RelName(sidecarName, sidecarPath)))
} else {
log.Infof("media: removed sidecar %s", clean.Log(fs.RelName(sidecarName, sidecarPath)))
numFiles++
log.Infof("files: deleted sidecar %s", clean.Log(fs.RelName(sidecarName, sidecarPath)))
}
}
return nil
return numFiles, nil
}
// ColorProfile returns the ICC color profile name.

View file

@ -37,7 +37,7 @@ func (m *MediaFile) ExifToolJsonName() (string, error) {
return "", fmt.Errorf("media: exiftool json files disabled")
}
return CacheName(m.Hash(), "json", "exiftool.json")
return ExifToolCacheName(m.Hash())
}
// NeedsExifToolJson tests if an ExifTool JSON file needs to be created.

View file

@ -2325,7 +2325,7 @@ func TestMediaFile_IsPlayableVideo(t *testing.T) {
})
}
func TestMediaFile_RenameSidecars(t *testing.T) {
func TestMediaFile_RenameSidecarFiles(t *testing.T) {
t.Run("success", func(t *testing.T) {
conf := config.TestConfig()
@ -2354,7 +2354,7 @@ func TestMediaFile_RenameSidecars(t *testing.T) {
t.Fatal(err)
}
if renamed, err := mf.RenameSidecars(filepath.Join(conf.OriginalsPath(), "foo/bar.jpg")); err != nil {
if renamed, err := mf.RenameSidecarFiles(filepath.Join(conf.OriginalsPath(), "foo/bar.jpg")); err != nil {
t.Fatal(err)
} else if len(renamed) != 1 {
t.Errorf("len should be 2: %#v", renamed)
@ -2375,7 +2375,7 @@ func TestMediaFile_RenameSidecars(t *testing.T) {
})
}
func TestMediaFile_RemoveSidecars(t *testing.T) {
func TestMediaFile_RemoveSidecarFiles(t *testing.T) {
t.Run("success", func(t *testing.T) {
conf := config.TestConfig()
@ -2399,10 +2399,12 @@ func TestMediaFile_RemoveSidecars(t *testing.T) {
t.Fatal(err)
}
if err := mf.RemoveSidecars(); err != nil {
if n, err := mf.RemoveSidecarFiles(); err != nil {
t.Fatal(err)
} else if fs.FileExists(sidecarName) {
t.Errorf("src file still exists: %s", sidecarName)
} else if n == 0 {
t.Errorf("number of files should be > 0: %s", sidecarName)
}
_ = os.Remove(sidecarName)

View file

@ -14,9 +14,9 @@ func PurgeOrphans() error {
if count, err := PurgeOrphanFiles(); err != nil {
return err
} else if count > 0 {
log.Warnf("purge: removed %d orphan files from index[%s]", count, time.Since(start))
log.Infof("index: removed %d orphan files [%s]", count, time.Since(start))
} else {
log.Infof("purge: found no orphan files in index [%s]", time.Since(start))
log.Debugf("index: found no orphan files [%s]", time.Since(start))
}
// Remove duplicates without an original file.