Index: Automatically remove orphan file entries #1559

rickysarraf · 2021-09-27T11:20:16Z

I get a bunch of pictures/videos under Review. After examining them, I mark them as Approved. After a while, like say 15 minutes, they show up again under Review.

The logs do capture what I've described above. Is this a bug somewhere ?



photoprism_1  | time="2021-09-27T10:01:05Z" level=info msg="photos: approving pr02ffb10m2tcyc7, pr02e7h3rj47fqmh, pr02e7g1m3kgc1mh, pr02e7d27i6087he, pr02e7c10qbmdlyo, pr02e61jl5gcb1ru, pr02dzjxib21rz6u, pr02dy92z18ym4c1, pr02dun2m6hy7320, pr02cw53n73twzdt, pr02dsx29vc0q4m1, pr02drg17ikyhmy2,
 pr02dpb3n7xqy4gz, pr02dpomv5d10unj, pr02ecy19lcz7w7l, pr02e8mv1f2vushq, pr02dp4jwalx4868, pr02cuh38uvp31jm"                                                                                                                                                                                         

photoprism_1  | time="2021-09-27T10:16:56Z" level=info msg="photos: found 18 results for public:true dist:20 year:0 month:0 quality:3 review:true count:60 order:newest merged:true [170.798437ms]"                                                                                                  
photoprism_1  | time="2021-09-27T10:17:08Z" level=info msg="photos: approving pr02ffb10m2tcyc7, pr02e7h3rj47fqmh, pr02e7g1m3kgc1mh, pr02e7d27i6087he, pr02e7c10qbmdlyo, pr02e61jl5gcb1ru, pr02dzjxib21rz6u, pr02dy92z18ym4c1, pr02dun2m6hy7320, pr02cw53n73twzdt, pr02dsx29vc0q4m1, pr02drg17ikyhmy2,
 pr02dpb3n7xqy4gz, pr02dpomv5d10unj, pr02ecy19lcz7w7l, pr02e8mv1f2vushq, pr02dp4jwalx4868, pr02cuh38uvp31jm"                                                                                                                                                                                         

photoprism_1  | time="2021-09-27T10:29:21Z" level=info msg="photos: found 18 results for public:true dist:20 year:0 month:0 quality:3 review:true count:60 order:newest merged:true [76.883203ms]"                                                                                                   
photoprism_1  | time="2021-09-27T10:29:32Z" level=info msg="photos: approving pr02ffb10m2tcyc7, pr02e7h3rj47fqmh, pr02e7g1m3kgc1mh, pr02e7d27i6087he, pr02e7c10qbmdlyo, pr02e61jl5gcb1ru, pr02dzjxib21rz6u, pr02dy92z18ym4c1, pr02dun2m6hy7320, pr02cw53n73twzdt, pr02dsx29vc0q4m1, pr02drg17ikyhmy2,
 pr02dpb3n7xqy4gz, pr02dpomv5d10unj, pr02ecy19lcz7w7l, pr02e8mv1f2vushq, pr02dp4jwalx4868, pr02cuh38uvp31jm"                                                                                                                                                                                         

photoprism_1  | time="2021-09-27T11:15:22Z" level=info msg="photos: found 18 results for public:true dist:20 year:0 month:0 quality:3 review:true count:60 order:newest merged:true [76.882915ms]"
photoprism_1  | time="2021-09-27T11:15:55Z" level=info msg="photos: approving pr02ffb10m2tcyc7, pr02e7h3rj47fqmh, pr02e7g1m3kgc1mh, pr02e7d27i6087he, pr02e7c10qbmdlyo, pr02e61jl5gcb1ru, pr02dzjxib21rz6u, pr02dy92z18ym4c1, pr02dun2m6hy7320, pr02cw53n73twzdt, pr02dsx29vc0q4m1, pr02drg17ikyhmy2, pr02dpb3n7xqy4gz, pr02dpomv5d10unj, pr02ecy19lcz7w7l, pr02e8mv1f2vushq, pr02dp4jwalx4868, pr02cuh38uvp31jm"

Installation Details:

PhotoPrism Preview version from 27/09/2021
Locally built with the same docker recipe

The text was updated successfully, but these errors were encountered:

rickysarraf · 2021-09-27T11:23:01Z

And then the same also end up showing under Library => Hidden

May I ask what is the purpose of Hidden ? I didn't find any documentation of it. Also, how do I deal with the items under Hidden.

I may also have uncovered a bug in PhotoPrism. An item, that is marked Private, gets listed under Hidden.

lastzero · 2021-09-27T11:37:12Z

Seems more like an issue with the files. When photos are in review, they have their quality set to -1, same as for photos with indexing issues e.g. because the format is not properly supported and no thumbs could be created. May happen for new RAW formats Darktable and RawTherapee can't properly handle yet.

lastzero · 2021-09-27T11:38:38Z

You're welcome to send samples for testing as guessing what the issue might be takes too long (there are just too many possibilities what can go wrong with files): hello@photoprism.app

lastzero · 2021-09-27T11:40:04Z

Also please use the stable version, the last tag is 20210925 - there is no version from 27/09/2021, also no preview.

lastzero · 2021-09-27T11:49:32Z

Before debugging further, it would be best to check your error / warning logs e.g. https://demo.photoprism.org/library/errors

rickysarraf · 2021-09-27T11:59:00Z

Seems more like an issue with the files. When photos are in review, they have their quality set to -1, same as for photos with indexing issues e.g. because the format is not properly supported and no thumbs could be created. May happen for new RAW formats Darktable and RawTherapee can't properly handle yet.

May I ask what issues would those be ? I mean if I click on those files, the video is played proper.

Thumbnail creation has had another erratic behavior lately. See below image for example. Thumbnails end up showing in the main view on PhotoPrism (Under Review). This has been annoying as I have had to explicitly validate that they are thumbnails (looking at their file size) and delete them.

.

rickysarraf · 2021-09-27T12:01:46Z

Before debugging further, it would be best to check your error / warning logs e.g. https://demo.photoprism.org/library/errors

Under Errors, I get many such errors on first index run. On consecutive index run, those errors are not seen afaik.

And by preview, I meant that I'm using the stable version from the 25th of September. Yes. Just that I build the images locally.

lastzero · 2021-09-27T12:01:55Z

Exactly, videos would show under hidden when ffmpeg can't create a thumb as the assumption is that the files are broken.

lastzero · 2021-09-27T12:03:11Z

You deleted video JPEG previews manually? That would explain the issue.

lastzero · 2021-09-27T12:05:38Z

Are you using a case-insensitive file system?

lastzero · 2021-09-27T12:07:26Z

Errors look like the same files might exist multiple times, maybe with different capitalization... this shouldn't happen usually, never seen this. Any manual database changes?

rickysarraf · 2021-09-27T12:08:05Z

Are you using a case-insensitive file system?

No. I'm on btrfs.

I've triggered a full-index now. Please allow me to have it complete and then I'll share my findings on this issue.

rickysarraf · 2021-09-27T12:11:30Z

Errors look like the same files might exist multiple times, maybe with different capitalization... this shouldn't happen usually, never seen this. Any manual database changes?

No. Everything is as close to the docker-compose recipe you've prepared. I only rebuild locally. The only exception about database is that I had to manually docker pull the 10.5.12 version of mariadb because there was an issue with previous version uncovered this past week.

The instance I have running is:

rrs@lenovo:/media/SSHD/photoprism$ ./photoprism.sh                                                                                                                                                                                                                                                   
Starting photoprism_photoprism_1 ... done                                                                                                                                                                                                                                                            
Starting photoprism_mariadb_1    ... done                                                                                                                                                                                                                                                            
Attaching to photoprism_mariadb_1, photoprism_photoprism_1                                                                                                                                                                                                                                           
photoprism_1  | running as uid 1000                                                                                                                                                                                                                                                                  
photoprism_1  | photoprism start                                                                                                                                                                                                                                                                     
mariadb_1     | 2021-09-27 10:33:46+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.5.12+maria~focal started.                                                                                                                                                                   
mariadb_1     | 2021-09-27 10:33:47+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'                                                                                                                                                                                                   
mariadb_1     | 2021-09-27 10:33:47+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.5.12+maria~focal started.                                                                                                                                                                   
mariadb_1     | 2021-09-27 10:33:47 0 [Note] mysqld (mysqld 10.5.12-MariaDB-1:10.5.12+maria~focal) starting as process 1 ...                                                                                                                                                                         
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Uses event mutexes                                                                                                                                                                                                                              
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Compressed tables use zlib 1.2.11                                                                                                                                                                                                               
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Number of pools: 1                                                                                                                                                                                                                              
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions                                                                                                                                                                                                            
mariadb_1     | 2021-09-27 10:33:47 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)                                                                                                                                                                                  
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Using Linux native AIO                                                                                                                                                                                                                          
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728                                                                                                                                                                        
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Completed initialization of buffer pool                                                                                                                                                                                                         
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: 128 rollback segments are active.                                                                                                                                                                                                               
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Creating shared tablespace for temporary tables                                                                                                                                                                                                 
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...                                                                                                                                                        
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.                                                                                                                                                                                                              
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: 10.5.12 started; log sequence number 1142036002; transaction id 2981620                                                                                                                                                                         
mariadb_1     | 2021-09-27 10:33:47 0 [Note] Plugin 'FEEDBACK' is disabled.                                                                                                                                                                                                                          
mariadb_1     | 2021-09-27 10:33:47 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool                                                                                                                                                                                       
mariadb_1     | 2021-09-27 10:33:47 0 [Note] Server socket created on IP: '::'.                                                                                                                                                                                                                      
mariadb_1     | 2021-09-27 10:33:47 0 [Warning] 'proxies_priv' entry '@% root@0d07cfd31cf3' ignored in --skip-name-resolve mode.                                                                                                                                                                     
mariadb_1     | 2021-09-27 10:33:48 0 [Note] InnoDB: Buffer pool(s) load completed at 210927 10:33:48                                                                                                                                                                                                
mariadb_1     | 2021-09-27 10:33:48 0 [Note] Reading of all Master_info entries succeeded                                                                                                                                                                                                            
mariadb_1     | 2021-09-27 10:33:48 0 [Note] Added new Master_info '' to hash table                                                                                                                                                                                                                  
mariadb_1     | 2021-09-27 10:33:48 0 [Note] mysqld: ready for connections.                                                                                                                                                                                                                          
mariadb_1     | Version: '10.5.12-MariaDB-1:10.5.12+maria~focal'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution                                                                                                                                                     
photoprism_1  | time="2021-09-27T10:33:53Z" level=info msg="http: enabling gzip compression"                                                                                                                                                                                                         
photoprism_1  | time="2021-09-27T10:33:53Z" level=info msg="webdav: server disabled"                                                                                                                                                                                                                 
photoprism_1  | time="2021-09-27T10:33:53Z" level=info msg="http: starting web server at 0.0.0.0:2342"

rickysarraf · 2021-09-30T07:41:37Z

Today morning, magically, all those annoying thumbnails were gone.

After taking a closer look at the logs, I noticed that I have a scheduled job to run cleanup and purge once a day. That seems to have done the magic.

Sep 30 13:08:26 lenovo docker[519905]: time="2021-09-30T07:38:26Z" level=info msg="cleanup: updating photo counts"
Sep 30 13:08:28 lenovo docker[519905]: time="2021-09-30T07:38:28Z" level=info msg="cleanup: updating preview images"
Sep 30 13:08:34 lenovo docker[519905]: time="2021-09-30T07:38:34Z" level=info msg="cleanup: removed 502 index entries and 6071 orphan thumbnails in 3m11.642196034s"
Sep 30 13:08:34 lenovo docker[519905]: time="2021-09-30T07:38:34Z" level=info msg="closed database connection"
Sep 30 13:08:34 lenovo systemd[6958]: photoprism-cleanup.service: Succeeded.

lastzero · 2021-09-30T13:52:58Z

This commit will search for orphan rows in the files table and remove them after indexing, in case there are any inconsistencies from earlier issues.

rickysarraf · 2021-10-01T14:44:19Z

Tested with the latest changes from preview branch. They all look good now. Thank you 🙏🏽

Oct 01 20:04:36 lenovo systemd[6958]: Starting Trigger PhotoPrism Index update...
Oct 01 20:04:36 lenovo systemd[6958]: Started Trigger PhotoPrism Index update.
Oct 01 20:04:36 lenovo bash[2173951]: + /bin/systemctl --user is-active --quiet photoprism-index-all.service
Oct 01 20:04:36 lenovo bash[2173951]: + exit 0
Oct 01 20:04:42 lenovo docker[2173953]: time="2021-10-01T14:34:42Z" level=info msg="indexing originals in /photoprism/originals"
Oct 01 20:04:42 lenovo docker[2173953]: time="2021-10-01T14:34:42Z" level=info msg="classify: loading nasnet"
Oct 01 20:04:42 lenovo docker[2173953]: 2021-10-01 14:34:42.950272: I tensorflow/cc/saved_model/reader.cc:31] Reading SavedModel from: /photoprism/assets/nasnet
Oct 01 20:04:43 lenovo docker[2173953]: 2021-10-01 14:34:43.209783: I tensorflow/cc/saved_model/reader.cc:54] Reading meta graph with tags { photoprism }
Oct 01 20:04:43 lenovo docker[2173953]: 2021-10-01 14:34:43.897787: I tensorflow/cc/saved_model/loader.cc:202] Restoring SavedModel bundle.
Oct 01 20:04:46 lenovo docker[2173953]: 2021-10-01 14:34:46.129912: I tensorflow/cc/saved_model/loader.cc:311] SavedModel load for tags { photoprism }; Status: success. Took 3180189 microseconds.
Oct 01 20:04:46 lenovo docker[2173953]: time="2021-10-01T14:34:46Z" level=info msg="classify: loading labels from labels.txt"
Oct 01 20:04:52 lenovo docker[2173953]: time="2021-10-01T14:34:52Z" level=info msg="index: ignored \"Pictures/NTAP/Netapp_Hyd/Thumbs.db\""
Oct 01 20:04:52 lenovo docker[2173953]: time="2021-10-01T14:34:52Z" level=info msg="index: ignored \"Pictures/Nostalgia/Thumbs.db\""
Oct 01 20:04:52 lenovo docker[2173953]: time="2021-10-01T14:34:52Z" level=info msg="index: ignored \"Pictures/Thumbs.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/Tour De Ooty/'06_01_09_01/DCIM/101MSDCF/Thumbs.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/Tour De Ooty/Amresh/Thumbs.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/Tour De Ooty/Ravi's Camera/Thumbs.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/digikam4.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/exif-info.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/recognition.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/similarity.db\""
Oct 01 20:04:53 lenovo docker[2173953]: time="2021-10-01T14:34:53Z" level=info msg="index: ignored \"Pictures/thumbnails-digikam.db\""
Oct 01 20:04:55 lenovo docker[2173953]: time="2021-10-01T14:34:55Z" level=info msg="index: no new or modified files"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="purge: flagged photo PXL_20211001_065904401 as deleted"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="purge: flagged photo VID_20211001_070505 as deleted"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="purge: flagged photo VID_20211001_070854 as deleted"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="purge: flagged photo VID_20211001_071235 as deleted"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="searching index for unassigned primary files"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="photo: pr02fio1oqeoprrg has no jpeg"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="searching index for hidden media files"
Oct 01 20:05:00 lenovo docker[2173953]: time="2021-10-01T14:35:00Z" level=info msg="purge: no orphan files [36.021424ms]"
Oct 01 20:05:02 lenovo docker[2173953]: time="2021-10-01T14:35:02Z" level=info msg="updating photo counts"
Oct 01 20:05:04 lenovo docker[2173953]: time="2021-10-01T14:35:04Z" level=info msg="updating preview thumbs"
Oct 01 20:05:05 lenovo docker[2173953]: time="2021-10-01T14:35:05Z" level=info msg="purge: removed 0 files and 4 photos"
Oct 01 20:05:37 lenovo docker[2173953]: time="2021-10-01T14:35:37Z" level=info msg="purge: no orphan files [41.400574ms]"
Oct 01 20:05:37 lenovo docker[2173953]: time="2021-10-01T14:35:37Z" level=info msg="updating photo counts"
Oct 01 20:05:38 lenovo docker[2173953]: time="2021-10-01T14:35:38Z" level=info msg="updating preview thumbs"
Oct 01 20:05:39 lenovo docker[2173953]: time="2021-10-01T14:35:39Z" level=info msg="cleanup: removed 4 index entries and 33 orphan thumbnails"
Oct 01 20:05:39 lenovo docker[2173953]: time="2021-10-01T14:35:39Z" level=info msg="indexed 17124 files in 56.839987383s"
Oct 01 20:05:39 lenovo docker[2173953]: time="2021-10-01T14:35:39Z" level=info msg="closed database connection"
Oct 01 20:05:39 lenovo systemd[6958]: photoprism-index.service: Succeeded.

rickysarraf closed this as completed Sep 30, 2021

lastzero added a commit that referenced this issue Sep 30, 2021

Index: Purge orphan file entries #1559

0d772c4

lastzero changed the title ~~approved pictures show up again under review~~ Index: Automatically remove orphan file entries Sep 30, 2021

lastzero added a commit that referenced this issue Sep 30, 2021

Index: Improve comments and log messages #1559

0199cab

lastzero self-assigned this Sep 30, 2021

lastzero added enhancement Refactoring, improvement or maintenance task please-test Ready for acceptance test labels Sep 30, 2021

graciousgrey added released Available in the stable release and removed please-test Ready for acceptance test labels Oct 18, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Index: Automatically remove orphan file entries #1559

Index: Automatically remove orphan file entries #1559

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 30, 2021

lastzero commented Sep 30, 2021

rickysarraf commented Oct 1, 2021

Index: Automatically remove orphan file entries #1559

Index: Automatically remove orphan file entries #1559

Comments

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

lastzero commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 27, 2021

rickysarraf commented Sep 30, 2021

lastzero commented Sep 30, 2021

rickysarraf commented Oct 1, 2021