Skip to content

Index: More accurate and resilient handling of related files and photo stacks #1823

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
inthreedee opened this issue Dec 19, 2021 · 26 comments
Closed
Assignees
Labels
bug Something isn't working released Available in the stable release

Comments

@inthreedee
Copy link

inthreedee commented Dec 19, 2021

What does not work as expected?

Background
When capturing an HDR image, my iPhone captures both the HDR version and standard version at the same time as two separately named HEIC photos with otherwise identical metadata.

Bug
When these two photos are uploaded, jpegs are generated in the sidecar directory but only one of those jpegs gets shown in the Photoprism files UI. I have prepared a set of files to reproduce this (see the repro steps below for the download).

Workaround
Re-index with a "Complete re-scan" two times (re-indexing without a complete re-scan does nothing). The first re-index will generate a yml file for the jpeg that is missing from the UI, and the second re-index will finally cause the jpeg to show in the list.

Screenshots
Here is the files list after I upload and index the two photos the first time:
Screenshot from 2021-12-19 12-22-35

Here is the sidecar directory at this point, note the missing yml file:
Screenshot from 2021-12-19 12-23-07

After re-indexing with a complete re-scan, the files list in the UI has not changed, but the sidecar directory looks like this now:
Screenshot from 2021-12-19 12-26-06

Now, one more re-scan is required. After two complete scan re-indexes, the files list finally updates:
Screenshot from 2021-12-19 12-26-56

How can we reproduce it?

Steps to reproduce the behavior:

  1. Download the prepared photo set: photo-set.zip
  2. Upload them and have Photoprism index them
  3. Look at the files list, notice one missing jpg
  4. Look at the sidecar directory, notice the jpg is there but one yml file is missing
  5. Re-index with a complete rescan
  6. Look at the files list, notice nothing has changed
  7. Look at the sidecar directory, notice the missing yml file has been generated
  8. Re-index with a complete rescan
  9. Look at the files list, notice the jpg is there now

What behavior do you expect?

All sidecar files should be properly created and indexed with the first indexing.

What version you are using?

211215-93b26f19-Linux-aarch64

@inthreedee inthreedee added the bug Something isn't working label Dec 19, 2021
@inthreedee inthreedee changed the title Bug: Sidecar jpgs not showing in files tab Bug: Some sidecar jpgs not showing in files tab Dec 19, 2021
@lastzero lastzero self-assigned this Jan 2, 2022
@lastzero lastzero changed the title Bug: Some sidecar jpgs not showing in files tab Index: Additional sidecar JPEGs not visible in files tab Jan 2, 2022
@lastzero
Copy link
Member

lastzero commented Jan 3, 2022

I can't reproduce it locally 👀 The second JPEG sidecar is always visible! 👇

After indexing the test files once...

result

After uploading the test files...

upload

Trying again with only one worker to see if this makes a difference.

Edit: Yes! So it's some kind of timing issue (too).

yes

@lastzero
Copy link
Member

lastzero commented Jan 3, 2022

Seems related files were intentionally skipped to fix #394 two years ago.

@lastzero lastzero added the please-test Ready for acceptance test label Jan 3, 2022
@lastzero
Copy link
Member

lastzero commented Jan 3, 2022

Related files (e.g. JPEG, XMP, ...) should now be correctly added to existing stacks if the main file (e.g. HEIF, Video, RAW, ...) was stacked previously. Please help testing to make sure we did not forget to cover an edge case! 👍

@inthreedee
Copy link
Author

inthreedee commented Jan 3, 2022

For testing, I set the preview in my docker-compose and it pulled this version: 220103-1a4158c7-Linux-aarch64. I'm hosting on an RPi 4 and the number of workers is set to 2.

Unfortunately, it doesn't seem to have fully fixed it. After uploading the test photos and indexing, the jpg is still missing from the files list:
Screenshot from 2022-01-03 14-18-23

However, some progress has been made because the sidecar directory seems to have all the right files now:
Screenshot from 2022-01-03 14-19-17

The problem shows up in my logs. It seems to be marking the photo as deleted:
Screenshot from 2022-01-03 14-25-30

Additional re-indexes have the same result with the same message in my logs; the photo never gets added to the files list.

@lastzero
Copy link
Member

lastzero commented Jan 3, 2022

Did you previously add it, so that that the index already contains an entry? Logs say updated, not added.

@inthreedee
Copy link
Author

Sorry, that log is taken from the second indexing attempt, but these were freshly uploaded today for testing. Here's the initial upload, which shows basically the same thing:
Screenshot from 2022-01-03 15-06-07

@lastzero
Copy link
Member

lastzero commented Jan 3, 2022

Thanks for testing, looks like it's indexing with two workers this time. Concurrency is hard. Going to take another look tomorrow.

@lastzero lastzero added the in-progress Somebody is working on this label Jan 3, 2022
@lastzero
Copy link
Member

lastzero commented Jan 3, 2022

Tested again.... this is how it looks on my side with a clean index and existing sidecar JPEGs:

DEBU[2022-01-03T21:07:12Z] exiftool: extracting metadata from debug/IMG_4478.HEIC 
DEBU[2022-01-03T21:07:12Z] exiftool: extracting metadata from debug/IMG_4479.HEIC 
DEBU[2022-01-03T21:07:12Z] index: created d2b982a81ee64ff154f6a288de424ff99a1af2f3_exiftool.json 
DEBU[2022-01-03T21:07:12Z] index: created 61692e6d373af3273b61043c972adda41166c606_exiftool.json 
INFO[2022-01-03T21:07:12Z] index: debug/IMG_4479.HEIC has document_id 38e5ceed-13d1-49d2-8df2-ac2405962124 
INFO[2022-01-03T21:07:12Z] index: added main heif file debug/IMG_4479.HEIC 
INFO[2022-01-03T21:07:12Z] index: stacked main heif file debug/IMG_4478.HEIC 
INFO[2022-01-03T21:07:12Z] index: stacked main heif file debug/IMG_4478.HEIC has 1 related file
DEBU[2022-01-03T21:07:12Z] metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found 
DEBU[2022-01-03T21:07:12Z] metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found 
DEBU[2022-01-03T21:07:23Z] media: IMG_4478.HEIC.jpg has color profile 'Display P3' 
DEBU[2022-01-03T21:07:24Z] photo: uid pr55k00wnyvi0u3p has new title 'Debug / 2021' [1.560089ms] 
DEBU[2022-01-03T21:07:24Z] index: updated yaml file IMG_4478.yml        
DEBU[2022-01-03T21:07:25Z] media: IMG_4479.HEIC.jpg has color profile 'Display P3' 
DEBU[2022-01-03T21:07:25Z] photo: uid pr55k00wnyvi0u3p has new title 'Debug / 2021' [2.965242ms] 
DEBU[2022-01-03T21:07:25Z] index: updated yaml file IMG_4479.yml        
INFO[2022-01-03T21:07:26Z] media: created 6 thumbnails for IMG_4478 [2.40225934s] 
INFO[2022-01-03T21:07:26Z] index: added related jpg file IMG_4478.HEIC.jpg 
INFO[2022-01-03T21:07:28Z] media: created 6 thumbnails for IMG_4479 [2.149593942s] 
INFO[2022-01-03T21:07:28Z] index: added related jpg file IMG_4479.HEIC.jpg

The log message index: stacked main heif file debug/IMG_4478.HEIC has 1 related file is important here.

Once again with a clean index after removing the sidecar JPEGs:

DEBU[2022-01-03T21:13:04Z] exiftool: extracting metadata from debug/IMG_4478.HEIC 
DEBU[2022-01-03T21:13:04Z] exiftool: extracting metadata from debug/IMG_4479.HEIC 
DEBU[2022-01-03T21:13:05Z] index: created 61692e6d373af3273b61043c972adda41166c606_exiftool.json 
DEBU[2022-01-03T21:13:05Z] index: created d2b982a81ee64ff154f6a288de424ff99a1af2f3_exiftool.json 
INFO[2022-01-03T21:13:05Z] heif-convert: converting debug/IMG_4478.HEIC to jpg 
INFO[2022-01-03T21:13:05Z] heif-convert: converting debug/IMG_4479.HEIC to jpg 
INFO[2022-01-03T21:13:06Z] heif-convert: created IMG_4479.HEIC.jpg [1.744223911s] 
DEBU[2022-01-03T21:13:06Z] index: created IMG_4479.HEIC.jpg             
DEBU[2022-01-03T21:13:07Z] metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found 
INFO[2022-01-03T21:13:07Z] heif-convert: created IMG_4478.HEIC.jpg [1.812201305s] 
DEBU[2022-01-03T21:13:07Z] index: created IMG_4478.HEIC.jpg             
DEBU[2022-01-03T21:13:07Z] metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found 
INFO[2022-01-03T21:13:09Z] media: created 11 thumbnails for IMG_4479 [2.825341013s] 
INFO[2022-01-03T21:13:09Z] index: debug/IMG_4479.HEIC has document_id 38e5ceed-13d1-49d2-8df2-ac2405962124 
INFO[2022-01-03T21:13:09Z] media: created 11 thumbnails for IMG_4478 [2.808184521s] 
INFO[2022-01-03T21:13:09Z] index: debug/IMG_4478.HEIC has document_id 38e5ceed-13d1-49d2-8df2-ac2405962124 
DEBU[2022-01-03T21:13:09Z] photo: merging id 1 with 1 identical         
INFO[2022-01-03T21:13:09Z] index: merged one existing photo with debug/IMG_4478.HEIC 
INFO[2022-01-03T21:13:09Z] index: added main heif file debug/IMG_4478.HEIC 
INFO[2022-01-03T21:13:09Z] index: added main heif file debug/IMG_4479.HEIC 
DEBU[2022-01-03T21:13:16Z] media: IMG_4478.HEIC.jpg has color profile 'Display P3' 
DEBU[2022-01-03T21:13:16Z] photo: uid pr55k9x2sjf4y2qz has new title 'Debug / 2021' [1.404407ms] 
DEBU[2022-01-03T21:13:16Z] index: updated yaml file IMG_4478.yml        
DEBU[2022-01-03T21:13:16Z] media: created no new thumbnails for IMG_4478 [534.454µs] 
INFO[2022-01-03T21:13:16Z] index: added related jpg file IMG_4478.HEIC.jpg 
DEBU[2022-01-03T21:13:16Z] media: IMG_4479.HEIC.jpg has color profile 'Display P3' 
DEBU[2022-01-03T21:13:16Z] photo: uid pr55k9xuslz7jc24 has new title 'Debug / 2021' [1.105091ms] 
DEBU[2022-01-03T21:13:16Z] photo: merging id 1 with 1 identical         
INFO[2022-01-03T21:13:16Z] index: merged debug/IMG_4479.HEIC.jpg with existing photo id 1 
DEBU[2022-01-03T21:13:16Z] media: created no new thumbnails for IMG_4479 [161.762µs] 
INFO[2022-01-03T21:13:16Z] index: stacked related jpg file IMG_4479.HEIC.jpg

Whatever I do, there are 4 files visible in the files tab after initial indexing.

Can you repeat the test with debug mode enabled?

@lastzero lastzero added waiting Impediment / blocked / waiting and removed in-progress Somebody is working on this labels Jan 3, 2022
@lastzero
Copy link
Member

lastzero commented Jan 3, 2022

Another test with a clean index, --workers=1, and no pre-existing sidecar JPEGs or YAMLs:

DEBU[2022-01-03T21:29:58Z] exiftool: extracting metadata from debug/IMG_4478.HEIC 
DEBU[2022-01-03T21:29:59Z] index: created 61692e6d373af3273b61043c972adda41166c606_exiftool.json 
INFO[2022-01-03T21:29:59Z] heif-convert: converting debug/IMG_4478.HEIC to jpg 
INFO[2022-01-03T21:30:00Z] heif-convert: created IMG_4478.HEIC.jpg [1.609781956s] 
DEBU[2022-01-03T21:30:00Z] index: created IMG_4478.HEIC.jpg             
DEBU[2022-01-03T21:30:00Z] metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found 
INFO[2022-01-03T21:30:02Z] media: created 11 thumbnails for IMG_4478 [2.121555809s] 
INFO[2022-01-03T21:30:02Z] index: debug/IMG_4478.HEIC has document_id 38e5ceed-13d1-49d2-8df2-ac2405962124 
INFO[2022-01-03T21:30:02Z] index: added main heif file debug/IMG_4478.HEIC 
DEBU[2022-01-03T21:30:06Z] media: IMG_4478.HEIC.jpg has color profile 'Display P3' 
DEBU[2022-01-03T21:30:06Z] photo: uid pr55l22r0471f752 has new title 'Debug / 2021' [1.586412ms] 
DEBU[2022-01-03T21:30:06Z] index: updated yaml file IMG_4478.yml        
DEBU[2022-01-03T21:30:06Z] media: created no new thumbnails for IMG_4478 [110.519µs] 
INFO[2022-01-03T21:30:06Z] index: added related jpg file IMG_4478.HEIC.jpg 
DEBU[2022-01-03T21:30:06Z] exiftool: extracting metadata from debug/IMG_4479.HEIC 
DEBU[2022-01-03T21:30:06Z] index: created d2b982a81ee64ff154f6a288de424ff99a1af2f3_exiftool.json 
INFO[2022-01-03T21:30:06Z] heif-convert: converting debug/IMG_4479.HEIC to jpg 
INFO[2022-01-03T21:30:08Z] heif-convert: created IMG_4479.HEIC.jpg [1.561812319s] 
DEBU[2022-01-03T21:30:08Z] index: created IMG_4479.HEIC.jpg             
DEBU[2022-01-03T21:30:08Z] metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found 
INFO[2022-01-03T21:30:10Z] media: created 11 thumbnails for IMG_4479 [1.954822674s] 
INFO[2022-01-03T21:30:10Z] index: stacked main heif file debug/IMG_4479.HEIC 
INFO[2022-01-03T21:30:10Z] index: stacked main heif file debug/IMG_4479.HEIC has 1 related file 
DEBU[2022-01-03T21:30:10Z] media: IMG_4479.HEIC.jpg has color profile 'Display P3' 
DEBU[2022-01-03T21:30:10Z] media: created no new thumbnails for IMG_4479 [126.604µs] 
INFO[2022-01-03T21:30:10Z] index: added related jpg file IMG_4479.HEIC.jpg

Works every single time 🙄

@inthreedee
Copy link
Author

I deleted the photos/sidecar files, re-indexed, and performed the test again with debugging enabled:

photoprism_1  | time="2022-01-03T22:11:00Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-03T22:11:00Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-03T22:11:00Z" level=info msg="heif-convert: converting testing/IMG_4478.HEIC to jpg"
photoprism_1  | time="2022-01-03T22:11:00Z" level=info msg="heif-convert: converting testing/IMG_4479.HEIC to jpg"
photoprism_1  | time="2022-01-03T22:11:04Z" level=info msg="heif-convert: created IMG_4479.HEIC.jpg [4.335310355s]"
photoprism_1  | time="2022-01-03T22:11:04Z" level=debug msg="index: created IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-03T22:11:04Z" level=info msg="heif-convert: created IMG_4478.HEIC.jpg [4.34464752s]"
photoprism_1  | time="2022-01-03T22:11:04Z" level=debug msg="index: created IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-03T22:11:04Z" level=debug msg="media: created no new thumbnails for IMG_4479 [14.011238ms]"
photoprism_1  | time="2022-01-03T22:11:04Z" level=debug msg="media: created no new thumbnails for IMG_4478 [14.181884ms]"
photoprism_1  | time="2022-01-03T22:11:04Z" level=debug msg="index: IMG_4479.HEIC was modified (new size 313200, old size 313200, new timestamp 1641247858, old timestamp 1641237427)"
photoprism_1  | time="2022-01-03T22:11:04Z" level=debug msg="index: IMG_4478.HEIC was modified (new size 337133, old size 337133, new timestamp 1641247858, old timestamp 1641237427)"
photoprism_1  | time="2022-01-03T22:11:05Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-03T22:11:05Z" level=debug msg="index: IMG_4479.HEIC.jpg was modified (new size 804621, old size 804621, new timestamp 1641247863, old timestamp 1641237451)"
photoprism_1  | time="2022-01-03T22:11:05Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-03T22:11:05Z" level=debug msg="index: IMG_4478.HEIC.jpg was modified (new size 768364, old size 768364, new timestamp 1641247863, old timestamp 1641237451)"
photoprism_1  | time="2022-01-03T22:11:05Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-03T22:11:05Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-03T22:11:23Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-03T22:11:23Z" level=debug msg="media: created no new thumbnails for IMG_4479 [751.694µs]"
photoprism_1  | time="2022-01-03T22:11:23Z" level=info msg="index: updated related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="media: created no new thumbnails for IMG_4478 [1.02871ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="faces: found no orphan markers [13.64965ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="markers: found no invalid references [19.47369ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="markers: found no missing subjects [3.206499ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="faces: found no ambiguous subjects [34.045625ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="faces: found no clusters to be merged [2.685726ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="faces: found no new faces [6.407422ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [24.47763ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="counts: updated 1 place [66.010979ms]"
photoprism_1  | time="2022-01-03T22:11:24Z" level=debug msg="counts: updated 0 subjects [5.824781ms]"
photoprism_1  | time="2022-01-03T22:11:25Z" level=debug msg="counts: updated 0 labels [105.162099ms]"
photoprism_1  | time="2022-01-03T22:11:25Z" level=debug msg="covers: updated 1 folder [79.233746ms]"
photoprism_1  | time="2022-01-03T22:11:25Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-03T22:11:25Z" level=info msg="purge: flagged photo IMG_4479 as deleted"
photoprism_1  | time="2022-01-03T22:11:25Z" level=debug msg="index: found no photos without primary file [173.981434ms]"
photoprism_1  | time="2022-01-03T22:11:25Z" level=info msg="index: found no orphan files [111.77726ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="counts: updated 1 place [64.655829ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="counts: updated 0 subjects [6.531346ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="counts: updated 0 labels [104.004613ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="covers: updated 0 albums [62.641595ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="covers: updated 1 folder [78.415515ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="covers: updated 1 month [48.744207ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="covers: updated 0 labels [96.323798ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="covers: updated 0 subjects [4.152746ms]"
photoprism_1  | time="2022-01-03T22:11:32Z" level=info msg="removed 0 files and 1 photos"
photoprism_1  | time="2022-01-03T22:11:32Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-03T22:11:33Z" level=info msg="moments: 'December 2021' restored"
photoprism_1  | time="2022-01-03T22:11:35Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-03T22:11:35Z" level=info msg="indexing completed in 34 s"

This is a second indexing attempt with complete rescan checked:

photoprism_1  | time="2022-01-03T22:14:42Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-03T22:14:43Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-03T22:14:43Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-03T22:14:43Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-03T22:14:43Z" level=debug msg="index: IMG_4479.HEIC.jpg was missing"
photoprism_1  | time="2022-01-03T22:14:43Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-03T22:14:43Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="media: created no new thumbnails for IMG_4478 [1.50526ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="media: created no new thumbnails for IMG_4479 [1.571203ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=info msg="index: updated related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="faces: found no orphan markers [9.415368ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="markers: found no invalid references [19.745855ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="markers: found no missing subjects [2.757967ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="faces: found no ambiguous subjects [34.695601ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="faces: found no clusters to be merged [2.438915ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="faces: found no new faces [6.19811ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [23.673679ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="counts: updated 1 place [65.346417ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="counts: updated 0 subjects [6.438515ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="counts: updated 0 labels [104.117988ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="covers: updated 1 folder [80.083537ms]"
photoprism_1  | time="2022-01-03T22:14:46Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-03T22:14:46Z" level=info msg="purge: flagged photo IMG_4479 as deleted"
photoprism_1  | time="2022-01-03T22:14:47Z" level=debug msg="index: found no photos without primary file [167.403968ms]"
photoprism_1  | time="2022-01-03T22:14:47Z" level=info msg="index: found no orphan files [114.747824ms]"
photoprism_1  | time="2022-01-03T22:14:53Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-03T22:14:53Z" level=debug msg="counts: updated 1 place [64.053563ms]"
photoprism_1  | time="2022-01-03T22:14:53Z" level=debug msg="counts: updated 0 subjects [5.609062ms]"
photoprism_1  | time="2022-01-03T22:14:53Z" level=debug msg="counts: updated 0 labels [104.649241ms]"
photoprism_1  | time="2022-01-03T22:14:53Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-03T22:14:54Z" level=debug msg="covers: updated 0 albums [63.416256ms]"
photoprism_1  | time="2022-01-03T22:14:54Z" level=debug msg="covers: updated 1 folder [77.524383ms]"
photoprism_1  | time="2022-01-03T22:14:54Z" level=debug msg="covers: updated 0 months [46.364461ms]"
photoprism_1  | time="2022-01-03T22:14:54Z" level=debug msg="covers: updated 0 labels [95.528185ms]"
photoprism_1  | time="2022-01-03T22:14:54Z" level=debug msg="covers: updated 0 subjects [4.258283ms]"
photoprism_1  | time="2022-01-03T22:14:54Z" level=info msg="removed 0 files and 1 photos"
photoprism_1  | time="2022-01-03T22:14:54Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-03T22:14:57Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-03T22:14:57Z" level=info msg="indexing completed in 14 s"

I tried indexing two more times and got the same results. It keeps flagging the photo as deleted.

lastzero added a commit that referenced this issue Jan 5, 2022
This commit also adds initial HDR flag extraction from metadata.
@lastzero
Copy link
Member

lastzero commented Jan 5, 2022

If it does not work with this, I lose faith.

@lastzero
Copy link
Member

lastzero commented Jan 5, 2022

When unstacking, make sure the photo Name (see Settings tab in photo edit dialog) does not match the file Name of the file you want to unstack. It then does not get renamed and related files should now be unstacked together with it.

@lastzero
Copy link
Member

lastzero commented Jan 5, 2022

This change will also extract and index the HDR flag from HEIC files for easier debugging, see Files tab.

@lastzero lastzero removed the waiting Impediment / blocked / waiting label Jan 5, 2022
@lastzero lastzero changed the title Index: Additional sidecar JPEGs not visible in files tab Index: Improve indexing and unstacking of related files Jan 5, 2022
@inthreedee
Copy link
Author

I pulled version 220105-d67e3258-Linux-aarch64

And indexing now works properly; the extra file doesn't get marked for deletion anymore! 🎉 Hooray! I also see the HDR tag now, which is great. Is that tag searchable to quickly find all HDR photos?

And now for the bad news:

Since you made some updates to stacking, I thought I'd test that for you as well and I ran into a problem with re-stacking. Unstacking works as you describe, but when I tried to re-stack the photos, one of the photos went missing and I couldn't get it to re-appear despite multiple re-indexing attempts.

I'll walk you through everything with logs and screenshots. This is going to be quite thorough, bear with me. I've marked the broken restacking below in large text if you just want to scroll down to that.

Here's the log for the first indexing where everything seems to work perfectly
photoprism_1  | time="2022-01-05T17:43:38Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-05T17:43:38Z" level=info msg="classify: loading nasnet"
photoprism_1  | time="2022-01-05T17:43:50Z" level=info msg="classify: loading labels from labels.txt"
photoprism_1  | time="2022-01-05T17:43:51Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-05T17:43:51Z" level=info msg="heif-convert: converting testing/IMG_4478.HEIC to jpg"
photoprism_1  | time="2022-01-05T17:43:51Z" level=info msg="heif-convert: converting testing/IMG_4479.HEIC to jpg"
photoprism_1  | time="2022-01-05T17:43:55Z" level=info msg="heif-convert: created IMG_4478.HEIC.jpg [4.312070929s]"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="index: created IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="media: created no new thumbnails for IMG_4478 [13.458217ms]"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="index: IMG_4478.HEIC was modified (new size 337133, old size 337133, new timestamp 1641404614, old timestamp 1641247858)"
photoprism_1  | time="2022-01-05T17:43:55Z" level=info msg="heif-convert: created IMG_4479.HEIC.jpg [4.342005531s]"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="index: created IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="media: created no new thumbnails for IMG_4479 [14.498149ms]"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="index: IMG_4479.HEIC was modified (new size 313200, old size 313200, new timestamp 1641404614, old timestamp 1641247858)"
photoprism_1  | time="2022-01-05T17:43:55Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="index: IMG_4478.HEIC.jpg was modified (new size 768364, old size 768364, new timestamp 1641404633, old timestamp 1641247863)"
photoprism_1  | time="2022-01-05T17:43:55Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="index: IMG_4479.HEIC.jpg has new photo uid pr4dhce1yh4a2n8x"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="index: IMG_4479.HEIC.jpg was modified (new size 804621, old size 804621, new timestamp 1641404633, old timestamp 1641247863)"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T17:43:55Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-05T17:44:13Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T17:44:13Z" level=debug msg="media: created no new thumbnails for IMG_4478 [2.101254ms]"
photoprism_1  | time="2022-01-05T17:44:13Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="media: created no new thumbnails for IMG_4479 [1.198653ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=info msg="index: updated related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="faces: found no orphan markers [15.971835ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="markers: found no invalid references [20.37997ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="markers: found no missing subjects [3.023669ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="faces: found no ambiguous subjects [33.903149ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="faces: found no clusters to be merged [2.649785ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="faces: found no new faces [5.950414ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [22.906608ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="counts: updated 1 place [65.000553ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="counts: updated 0 subjects [6.14043ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="counts: updated 0 labels [110.970804ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="covers: updated 1 folder [78.260012ms]"
photoprism_1  | time="2022-01-05T17:44:14Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-05T17:44:15Z" level=debug msg="index: found no photos without primary file [166.340671ms]"
photoprism_1  | time="2022-01-05T17:44:15Z" level=info msg="index: found no orphan files [111.886812ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="counts: updated 0 places [61.417593ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="counts: updated 0 subjects [5.173774ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="counts: updated 0 labels [103.368242ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="covers: updated 0 albums [61.548703ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="covers: updated 0 folders [73.239328ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="covers: updated 1 month [47.026683ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="covers: updated 0 labels [97.802639ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="covers: updated 0 subjects [3.913011ms]"
photoprism_1  | time="2022-01-05T17:44:22Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-05T17:44:25Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-05T17:44:25Z" level=info msg="indexing completed in 46 s"

Afterwards, all files have been correctly indexed:
Screenshot from 2022-01-05 13-09-03

I noticed I only have one yml file in my sidecar directory instead of one for each photo. I assume this is the correct behavior at this point:
Screenshot from 2022-01-05 13-04-24

Up to this point, everything seems perfect.

Next, I went on to test stacking behavior. You said:

When unstacking, make sure the photo Name (see Settings tab in photo edit dialog) does not match the file Name of the file you want to unstack.

For my first test, I wanted to confirm that the renaming does happen as you described.

  • In the settings, I see the photo Name is set to IMG_4478.
  • I unstacked IMG_4478 to confirm the renaming.
Here's the log for the unstacking
photoprism_1  | time="2022-01-05T18:25:50Z" level=info msg="heif-convert: converting testing/IMG_4478.eb3c4882.heic to jpg"
photoprism_1  | time="2022-01-05T18:25:53Z" level=info msg="heif-convert: created IMG_4478.eb3c4882.heic.jpg [3.329272044s]"
photoprism_1  | time="2022-01-05T18:25:53Z" level=debug msg="index: created IMG_4478.eb3c4882.heic.jpg"
photoprism_1  | time="2022-01-05T18:25:53Z" level=debug msg="media: created no new thumbnails for IMG_4478.eb3c4882 [15.080075ms]"
photoprism_1  | time="2022-01-05T18:25:53Z" level=info msg="index: testing/IMG_4478.eb3c4882.heic has document_id 38e5ceed-13d1-49d2-8df2-ac2405962124"
photoprism_1  | time="2022-01-05T18:25:53Z" level=info msg="index: updated main heif file testing/IMG_4478.eb3c4882.heic"
photoprism_1  | time="2022-01-05T18:25:53Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T18:25:55Z" level=debug msg="media: IMG_4478.eb3c4882.heic.jpg has color profile 'Display P3' [348.274µs]"
photoprism_1  | time="2022-01-05T18:25:55Z" level=debug msg="photo: uid pr591v2van2qn3pq has new title 'Testing / 2021' [2.564401ms]"
photoprism_1  | time="2022-01-05T18:25:55Z" level=debug msg="index: updated yaml file IMG_4478.eb3c4882.yml"
photoprism_1  | time="2022-01-05T18:25:55Z" level=debug msg="media: created no new thumbnails for IMG_4478.eb3c4882 [1.382431ms]"
photoprism_1  | time="2022-01-05T18:25:55Z" level=info msg="index: stacked related jpg file IMG_4478.eb3c4882.heic.jpg"
photoprism_1  | time="2022-01-05T18:25:55Z" level=debug msg="media: replaced sidecar with originals path in related file matching pattern"
photoprism_1  | time="2022-01-05T18:25:55Z" level=info msg="index: updated main heif file testing/IMG_4478.eb3c4882.heic"
photoprism_1  | time="2022-01-05T18:25:55Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T18:25:57Z" level=debug msg="index: updated yaml file IMG_4478.eb3c4882.yml"
photoprism_1  | time="2022-01-05T18:25:57Z" level=debug msg="media: created no new thumbnails for IMG_4478.eb3c4882 [1.038101ms]"
photoprism_1  | time="2022-01-05T18:25:57Z" level=info msg="index: updated related jpg file IMG_4478.eb3c4882.heic.jpg"
photoprism_1  | time="2022-01-05T18:25:57Z" level=debug msg="photos: found 1 result for uid:pr591v2van2qn3pq merged:true [5.736463ms]"
photoprism_1  | time="2022-01-05T18:25:57Z" level=debug msg="photos: found 2 results for uid:pr4dhce1yh4a2n8x merged:true [5.85198ms]"
photoprism_1  | time="2022-01-05T18:25:57Z" level=info msg="file removed from stack"
photoprism_1  | time="2022-01-05T18:25:57Z" level=debug msg="http: POST /api/v1/photos/pr4dhce1yh4a2n8x/files/fr4dhky15jjehdk1/unstack (200) [7.491107772s]"

As expected, the file gets renamed:
Screenshot from 2022-01-05 13-29-27

But there is a leftover sidecar jpg in the original stack:
Screenshot from 2022-01-05 13-30-03

My question at this point is, why didn't it first switch that original stack's name over to IMG_4479 before unstacking IMG_4478? Would that avoid creating this mess? This is probably a separate, low priority issue that could be worked on at some point in the future, but it seems like the unstacking behavior could be made smarter. I don't think users are going to know to check the Name field first before unstacking their photos; they would expect this to be handled for them.

For my next test, let's start over and unstack it "correctly" to confirm that works:

  • In the settings, I see the photo Name is set to IMG_4478.
  • I unstack IMG_4479.
  • Everything worked properly and no renaming occured.
Unstack log
photoprism_1  | time="2022-01-05T18:48:53Z" level=info msg="index: testing/IMG_4479.HEIC has document_id 38e5ceed-13d1-49d2-8df2-ac2405962124"
photoprism_1  | time="2022-01-05T18:48:53Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-05T18:48:53Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-05T18:48:54Z" level=debug msg="photo: uid pr592xg2uj6tweik has new title 'Testing / 2021' [2.864136ms]"
photoprism_1  | time="2022-01-05T18:48:55Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T18:48:55Z" level=debug msg="media: created no new thumbnails for IMG_4479 [1.04797ms]"
photoprism_1  | time="2022-01-05T18:48:55Z" level=info msg="index: updated related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T18:48:55Z" level=debug msg="media: replaced sidecar with originals path in related file matching pattern"
photoprism_1  | time="2022-01-05T18:48:55Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T18:48:55Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T18:48:57Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-05T18:48:57Z" level=debug msg="media: created no new thumbnails for IMG_4478 [1.278449ms]"
photoprism_1  | time="2022-01-05T18:48:57Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T18:48:57Z" level=debug msg="photos: found 1 result for uid:pr592xg2uj6tweik merged:true [6.679632ms]"
photoprism_1  | time="2022-01-05T18:48:57Z" level=debug msg="photos: found 1 result for uid:pr4dhce1yh4a2n8x merged:true [4.96441ms]"
photoprism_1  | time="2022-01-05T18:48:57Z" level=info msg="file removed from stack"
photoprism_1  | time="2022-01-05T18:48:57Z" level=debug msg="http: POST /api/v1/photos/pr4dhce1yh4a2n8x/files/fr4dhky2j6k2bilc/unstack (200) [4.167685167s]"

I see two unstacked photos now:
Screenshot from 2022-01-05 14-13-20

And everything looks good in the sidecar directory too:
Screenshot from 2022-01-05 13-49-56

The broken re-stacking is here

Next, I tested what happens if I want to re-stack these photos. This results in a missing photo:

  • I open IMG_4479 and flip the Stackable switch in its settings to Yes, then re-index with a complete re-scan
Re-stacking log
photoprism_1  | time="2022-01-05T18:56:21Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T18:56:21Z" level=debug msg="counts: updated 1 place [65.271926ms]"
photoprism_1  | time="2022-01-05T18:56:21Z" level=debug msg="counts: updated 0 subjects [5.147611ms]"
photoprism_1  | time="2022-01-05T18:56:21Z" level=debug msg="counts: updated 0 labels [104.337412ms]"
photoprism_1  | time="2022-01-05T18:56:21Z" level=debug msg="photos: found 1 result for uid:pr592xg2uj6tweik merged:true [4.690783ms]"
photoprism_1  | time="2022-01-05T18:56:21Z" level=info msg="changes successfully saved"
photoprism_1  | time="2022-01-05T18:56:21Z" level=debug msg="photo: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T18:56:21Z" level=debug msg="http: PUT /api/v1/photos/pr592xg2uj6tweik (200) [564.938758ms]"
photoprism_1  | time="2022-01-05T18:57:14Z" level=info msg="settings saved"
photoprism_1  | time="2022-01-05T18:57:14Z" level=debug msg="http: POST /api/v1/settings (200) [256.454325ms]"
photoprism_1  | time="2022-01-05T18:57:15Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-05T18:57:15Z" level=info msg="classify: loading nasnet"
photoprism_1  | time="2022-01-05T18:57:28Z" level=info msg="classify: loading labels from labels.txt"
photoprism_1  | time="2022-01-05T18:57:28Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-05T18:57:28Z" level=debug msg="photo: merging id 9789 with 1 identical"
photoprism_1  | time="2022-01-05T18:57:28Z" level=info msg="index: merged one existing photo with testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T18:57:28Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T18:57:28Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-05T18:57:28Z" level=debug msg="index: IMG_4479.HEIC.jpg has new photo uid pr592xg2uj6tweik"
photoprism_1  | time="2022-01-05T18:57:28Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T18:57:28Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-05T18:57:47Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-05T18:57:47Z" level=debug msg="media: created no new thumbnails for IMG_4478 [1.945553ms]"
photoprism_1  | time="2022-01-05T18:57:47Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="media: created no new thumbnails for IMG_4479 [1.237228ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=info msg="index: updated related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="faces: found no orphan markers [9.579897ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="markers: found no invalid references [17.875344ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="markers: found no missing subjects [2.627102ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="faces: found no ambiguous subjects [39.095596ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="faces: found no clusters to be merged [2.816007ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="faces: found no new faces [6.624188ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [24.093277ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="counts: updated 1 place [65.70905ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="counts: updated 0 subjects [6.531244ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="counts: updated 0 labels [102.182749ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="covers: updated 0 folders [74.877766ms]"
photoprism_1  | time="2022-01-05T18:57:48Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-05T18:57:49Z" level=debug msg="index: found no photos without primary file [168.361739ms]"
photoprism_1  | time="2022-01-05T18:57:49Z" level=info msg="index: found no orphan files [111.037876ms]"
photoprism_1  | time="2022-01-05T18:57:55Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T18:57:55Z" level=debug msg="counts: updated 0 places [59.642338ms]"
photoprism_1  | time="2022-01-05T18:57:55Z" level=debug msg="counts: updated 0 subjects [5.494663ms]"
photoprism_1  | time="2022-01-05T18:57:55Z" level=debug msg="counts: updated 0 labels [103.202646ms]"
photoprism_1  | time="2022-01-05T18:57:55Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-05T18:57:55Z" level=debug msg="covers: updated 0 albums [64.307029ms]"
photoprism_1  | time="2022-01-05T18:57:55Z" level=debug msg="covers: updated 0 folders [72.068629ms]"
photoprism_1  | time="2022-01-05T18:57:55Z" level=debug msg="covers: updated 0 months [42.082805ms]"
photoprism_1  | time="2022-01-05T18:57:56Z" level=debug msg="covers: updated 0 labels [95.037826ms]"
photoprism_1  | time="2022-01-05T18:57:56Z" level=debug msg="covers: updated 0 subjects [4.146456ms]"
photoprism_1  | time="2022-01-05T18:57:56Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-05T18:57:58Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-05T18:57:58Z" level=info msg="indexing completed in 42 s"
photoprism_1  | time="2022-01-05T18:57:59Z" level=debug msg="http: POST /api/v1/index (200) [43.164870942s]"

The result is IMG_4479 has disappeared completely from the UI. It still exists in my originals and sidecar directories, but this is what I see in the UI now.
Only the one photo in the timeline:
Screenshot from 2022-01-05 13-59-53

And this is the files tab:
Screenshot from 2022-01-05 14-00-04

The files are still on the server though:
Screenshot from 2022-01-05 14-05-41
Screenshot from 2022-01-05 14-03-55

In the UI, IMG_4479 is nowhere to be found, despite multiple re-indexing attempts.

Re-index with complete re-scan
photoprism_1  | time="2022-01-05T19:01:02Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-05T19:01:02Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-05T19:01:02Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T19:01:02Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-05T19:01:02Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:01:02Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="media: created no new thumbnails for IMG_4478 [1.153802ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="media: created no new thumbnails for IMG_4479 [1.056303ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=info msg="index: updated related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="faces: found no orphan markers [10.127761ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="markers: found no invalid references [18.053749ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="markers: found no missing subjects [2.553361ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="faces: found no ambiguous subjects [42.37482ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="faces: found no clusters to be merged [3.861847ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="faces: found no new faces [6.675113ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [24.900694ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="counts: updated 0 places [60.804621ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="counts: updated 0 subjects [5.388312ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="counts: updated 0 labels [103.239014ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="covers: updated 0 folders [71.941241ms]"
photoprism_1  | time="2022-01-05T19:01:05Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-05T19:01:06Z" level=debug msg="index: found no photos without primary file [167.688023ms]"
photoprism_1  | time="2022-01-05T19:01:06Z" level=info msg="index: found no orphan files [111.018875ms]"
photoprism_1  | time="2022-01-05T19:01:12Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:01:12Z" level=debug msg="counts: updated 0 places [59.941186ms]"
photoprism_1  | time="2022-01-05T19:01:12Z" level=debug msg="counts: updated 0 subjects [5.499441ms]"
photoprism_1  | time="2022-01-05T19:01:13Z" level=debug msg="counts: updated 0 labels [104.413113ms]"
photoprism_1  | time="2022-01-05T19:01:13Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-05T19:01:13Z" level=debug msg="covers: updated 0 albums [64.762931ms]"
photoprism_1  | time="2022-01-05T19:01:13Z" level=debug msg="covers: updated 0 folders [73.490318ms]"
photoprism_1  | time="2022-01-05T19:01:13Z" level=debug msg="covers: updated 0 months [42.07449ms]"
photoprism_1  | time="2022-01-05T19:01:13Z" level=debug msg="covers: updated 0 labels [96.309645ms]"
photoprism_1  | time="2022-01-05T19:01:13Z" level=debug msg="covers: updated 0 subjects [4.548488ms]"
photoprism_1  | time="2022-01-05T19:01:13Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-05T19:01:16Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-05T19:01:16Z" level=info msg="indexing completed in 13 s"
photoprism_1  | time="2022-01-05T19:01:16Z" level=debug msg="http: POST /api/v1/index (200) [14.151485947s]"

I tested this four separate times, deleting and re-uploading the photos each time, and only once was the file correctly re-stacked.

Here's the log from the one time it correctly re-stacked
photoprism_1  | time="2022-01-05T19:15:15Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:15:15Z" level=debug msg="counts: updated 1 place [65.656975ms]"
photoprism_1  | time="2022-01-05T19:15:15Z" level=debug msg="counts: updated 0 subjects [5.177259ms]"
photoprism_1  | time="2022-01-05T19:15:15Z" level=debug msg="counts: updated 0 labels [103.998505ms]"
photoprism_1  | time="2022-01-05T19:15:15Z" level=debug msg="photos: found 1 result for uid:pr5941w1gow1ytk1 merged:true [4.494007ms]"
photoprism_1  | time="2022-01-05T19:15:15Z" level=info msg="changes successfully saved"
photoprism_1  | time="2022-01-05T19:15:16Z" level=debug msg="photo: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T19:15:16Z" level=debug msg="http: PUT /api/v1/photos/pr5941w1gow1ytk1 (200) [526.48001ms]"
photoprism_1  | time="2022-01-05T19:15:20Z" level=info msg="settings saved"
photoprism_1  | time="2022-01-05T19:15:20Z" level=debug msg="http: POST /api/v1/settings (200) [318.353557ms]"
photoprism_1  | time="2022-01-05T19:15:21Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-05T19:15:21Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-05T19:15:21Z" level=debug msg="photo: merging id 9789 with 1 identical"
photoprism_1  | time="2022-01-05T19:15:21Z" level=info msg="index: merged one existing photo with testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T19:15:21Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T19:15:21Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-05T19:15:21Z" level=debug msg="index: IMG_4479.HEIC.jpg has new photo uid pr5941w1gow1ytk1"
photoprism_1  | time="2022-01-05T19:15:21Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:15:21Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="photo: merging id 9789 with 1 identical"
photoprism_1  | time="2022-01-05T19:15:25Z" level=info msg="index: merged testing/IMG_4479.HEIC.jpg with existing photo id 9789"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="media: created no new thumbnails for IMG_4479 [2.480381ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=info msg="index: stacked related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="media: created no new thumbnails for IMG_4478 [1.089026ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="faces: found no orphan markers [9.977355ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="markers: found no invalid references [21.375676ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="markers: found no missing subjects [3.100744ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="faces: found no ambiguous subjects [43.744545ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="faces: found no clusters to be merged [3.323538ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="faces: found no new faces [7.128163ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [26.755433ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="counts: updated 1 place [69.343621ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="counts: updated 0 subjects [6.303598ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="counts: updated 0 labels [108.712972ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="covers: updated 0 folders [74.429603ms]"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-05T19:15:25Z" level=debug msg="index: found no photos without primary file [171.122445ms]"
photoprism_1  | time="2022-01-05T19:15:26Z" level=info msg="index: found no orphan files [114.614353ms]"
photoprism_1  | time="2022-01-05T19:15:32Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:15:32Z" level=debug msg="counts: updated 0 places [59.441471ms]"
photoprism_1  | time="2022-01-05T19:15:32Z" level=debug msg="counts: updated 0 subjects [5.211934ms]"
photoprism_1  | time="2022-01-05T19:15:32Z" level=debug msg="counts: updated 0 labels [102.795332ms]"
photoprism_1  | time="2022-01-05T19:15:32Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-05T19:15:32Z" level=debug msg="covers: updated 0 albums [62.602894ms]"
photoprism_1  | time="2022-01-05T19:15:33Z" level=debug msg="covers: updated 0 folders [73.335937ms]"
photoprism_1  | time="2022-01-05T19:15:33Z" level=debug msg="covers: updated 0 months [43.380727ms]"
photoprism_1  | time="2022-01-05T19:15:33Z" level=debug msg="covers: updated 0 labels [95.785254ms]"
photoprism_1  | time="2022-01-05T19:15:33Z" level=debug msg="covers: updated 0 subjects [3.868314ms]"
photoprism_1  | time="2022-01-05T19:15:33Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-05T19:15:36Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-05T19:15:36Z" level=info msg="indexing completed in 14 s"

@lastzero
Copy link
Member

lastzero commented Jan 5, 2022

OMG, this is starting to escalate! Taking a look tomorrow.

@lastzero
Copy link
Member

lastzero commented Jan 5, 2022

updated yaml file IMG_4479.yml doesn't look right for sure as related files should not be searched in the sidecar folder anymore with the most recent changes (you didn't use the latest development preview from what I see).

Does it work with a clean index and the latest preview image?

@inthreedee
Copy link
Author

Oh I see, a new preview image was released while I was in the middle of testing this. I'll pull it, try again, and report back.

@lastzero
Copy link
Member

lastzero commented Jan 5, 2022

It's expected that the PRIMARY files remains in the stack as you can't unstack it. Now if you unstack the HEIC file for it, this may cause a problem in that the newly created JPEG has the same hash as the one that remains in the stack because it's the primary. So the fix may simply be to disable the buttons. Somehow related to what I wrote in december as it's not really possible to know where a JPEG really originates from until after the fact (when you compare hashes for example). This is all getting super complicated now.

@lastzero
Copy link
Member

lastzero commented Jan 5, 2022

Am I right in thinking that the original problem - the second JPEG was not visible on the Files tab - is solved? Do you still need to unstack the other HEIC now?

@inthreedee
Copy link
Author

220105-c5301a68-Linux-aarch64

The first unstack/restack test worked fine.

Restack/reindex log
photoprism_1  | time="2022-01-05T19:57:55Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:57:55Z" level=debug msg="counts: updated 1 place [67.868656ms]"
photoprism_1  | time="2022-01-05T19:57:55Z" level=debug msg="counts: updated 0 subjects [5.583725ms]"
photoprism_1  | time="2022-01-05T19:57:56Z" level=debug msg="counts: updated 0 labels [107.935925ms]"
photoprism_1  | time="2022-01-05T19:57:56Z" level=debug msg="photos: found 1 result for uid:pr5963x1lu0igmwx merged:true [4.620053ms]"
photoprism_1  | time="2022-01-05T19:57:56Z" level=info msg="changes successfully saved"
photoprism_1  | time="2022-01-05T19:57:56Z" level=debug msg="photo: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T19:57:56Z" level=debug msg="http: PUT /api/v1/photos/pr5963x1lu0igmwx (200) [535.265475ms]"
photoprism_1  | time="2022-01-05T19:58:01Z" level=info msg="settings saved"
photoprism_1  | time="2022-01-05T19:58:01Z" level=debug msg="http: POST /api/v1/settings (200) [257.0374ms]"
photoprism_1  | time="2022-01-05T19:58:02Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-05T19:58:02Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-05T19:58:02Z" level=debug msg="photo: merging id 9789 with 1 identical"
photoprism_1  | time="2022-01-05T19:58:02Z" level=info msg="index: merged testing/IMG_4479.HEIC with existing photo id 9789"
photoprism_1  | time="2022-01-05T19:58:02Z" level=info msg="index: stacked main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-05T19:58:02Z" level=info msg="index: stacked main heif file testing/IMG_4479.HEIC has 1 related file"
photoprism_1  | time="2022-01-05T19:58:02Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T19:58:02Z" level=debug msg="index: IMG_4479.HEIC.jpg has new photo uid pr5963x1lu0igmwx"
photoprism_1  | time="2022-01-05T19:58:02Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:58:02Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="photo: merging id 9789 with 1 identical"
photoprism_1  | time="2022-01-05T19:58:05Z" level=info msg="index: merged testing/IMG_4479.HEIC.jpg with existing photo id 9789"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="media: created no new thumbnails for IMG_4479 [1.090783ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=info msg="index: stacked related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="media: created no new thumbnails for IMG_4478 [1.077542ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="faces: found no orphan markers [11.712907ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="markers: found no invalid references [18.131121ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="markers: found no missing subjects [2.51732ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="faces: found no ambiguous subjects [34.171807ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="faces: found no clusters to be merged [2.483135ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="faces: found no new faces [6.879191ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [23.516201ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="counts: updated 1 place [67.282608ms]"
photoprism_1  | time="2022-01-05T19:58:05Z" level=debug msg="counts: updated 0 subjects [5.47656ms]"
photoprism_1  | time="2022-01-05T19:58:06Z" level=debug msg="counts: updated 0 labels [106.621256ms]"
photoprism_1  | time="2022-01-05T19:58:06Z" level=debug msg="covers: updated 0 folders [74.063244ms]"
photoprism_1  | time="2022-01-05T19:58:06Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-05T19:58:06Z" level=debug msg="index: found no photos without primary file [172.557696ms]"
photoprism_1  | time="2022-01-05T19:58:06Z" level=info msg="index: found no orphan files [117.471507ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="counts: updated 0 places [61.658198ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="counts: updated 0 subjects [5.610095ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="counts: updated 0 labels [106.766403ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="covers: updated 0 albums [64.075963ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="covers: updated 0 folders [73.449696ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="covers: updated 0 months [43.167859ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="covers: updated 0 labels [97.221116ms]"
photoprism_1  | time="2022-01-05T19:58:13Z" level=debug msg="covers: updated 0 subjects [4.322334ms]"
photoprism_1  | time="2022-01-05T19:58:14Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-05T19:58:16Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-05T19:58:16Z" level=info msg="indexing completed in 14 s"

The second unstack/restack test, it broke again.

Restack/reindex log
photoprism_1  | time="2022-01-05T19:59:06Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:59:06Z" level=debug msg="counts: updated 1 place [67.806084ms]"
photoprism_1  | time="2022-01-05T19:59:06Z" level=debug msg="counts: updated 0 subjects [7.654236ms]"
photoprism_1  | time="2022-01-05T19:59:06Z" level=debug msg="counts: updated 0 labels [108.70099ms]"
photoprism_1  | time="2022-01-05T19:59:06Z" level=debug msg="photos: found 1 result for uid:pr5965vp2ggr2e4m merged:true [4.651663ms]"
photoprism_1  | time="2022-01-05T19:59:06Z" level=info msg="changes successfully saved"
photoprism_1  | time="2022-01-05T19:59:06Z" level=debug msg="photo: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T19:59:06Z" level=debug msg="http: PUT /api/v1/photos/pr5965vp2ggr2e4m (200) [548.651662ms]"
photoprism_1  | time="2022-01-05T19:59:11Z" level=info msg="indexing files in testing"
photoprism_1  | time="2022-01-05T19:59:11Z" level=info msg="index: found no .ppignore file"
photoprism_1  | time="2022-01-05T19:59:11Z" level=debug msg="photo: merging id 9789 with 1 identical"
photoprism_1  | time="2022-01-05T19:59:11Z" level=info msg="index: merged one existing photo with testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T19:59:11Z" level=info msg="index: updated main heif file testing/IMG_4478.HEIC"
photoprism_1  | time="2022-01-05T19:59:11Z" level=info msg="index: updated main heif file testing/IMG_4479.HEIC"
photoprism_1  | time="2022-01-05T19:59:11Z" level=debug msg="index: IMG_4479.HEIC.jpg has new photo uid pr5965vp2ggr2e4m"
photoprism_1  | time="2022-01-05T19:59:11Z" level=debug msg="metadata: 366d88a60bc0f515d213e2814bd51f1882889f47_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:59:11Z" level=debug msg="metadata: a10489183a36e73490276e920bb2a60b5e14ddc1_exiftool.json not found"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="index: updated yaml file IMG_4478.yml"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="media: created no new thumbnails for IMG_4478 [2.48919ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=info msg="index: updated related jpg file IMG_4478.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="index: updated yaml file IMG_4479.yml"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="media: created no new thumbnails for IMG_4479 [1.138356ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=info msg="index: updated related jpg file IMG_4479.HEIC.jpg"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="faces: found no orphan markers [10.197019ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="markers: found no invalid references [18.161491ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="markers: found no missing subjects [2.601504ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="faces: found no ambiguous subjects [34.679504ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="faces: found no clusters to be merged [2.411155ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="faces: skipped clustering"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="faces: found no new faces [6.147459ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="faces: found no unmatched markers"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [23.74168ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="counts: updated 1 place [67.419773ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="counts: updated 0 subjects [6.212051ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="counts: updated 0 labels [107.203379ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="covers: updated 0 folders [74.882382ms]"
photoprism_1  | time="2022-01-05T19:59:14Z" level=debug msg="removed folder:/:true:false from cache"
photoprism_1  | time="2022-01-05T19:59:15Z" level=debug msg="index: found no photos without primary file [169.555328ms]"
photoprism_1  | time="2022-01-05T19:59:15Z" level=info msg="index: found no orphan files [114.141662ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=info msg="index: updating counts"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="counts: updated 0 places [59.669465ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="counts: updated 0 subjects [5.395987ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="counts: updated 0 labels [104.126048ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=info msg="index: updating covers"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="covers: updated 0 albums [65.23145ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="covers: updated 0 folders [73.403735ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="covers: updated 0 months [44.248586ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="covers: updated 0 labels [98.724358ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="covers: updated 0 subjects [4.088892ms]"
photoprism_1  | time="2022-01-05T19:59:22Z" level=debug msg="moments: analyzing 7696 photos and 2034 videos, with threshold 14"
photoprism_1  | time="2022-01-05T19:59:25Z" level=debug msg="moments: 300 albums saved as yaml files"
photoprism_1  | time="2022-01-05T19:59:25Z" level=info msg="indexing completed in 14 s"

@inthreedee
Copy link
Author

Am I right in thinking that the original problem - the second JPEG was not visible on the Files tab - is solved? Do you still need to unstack the other HEIC now?

This original problem is indeed solved. Thanks so much for fixing that! This new stacking problem just came about because I thought I'd give stacking a thorough testing for you. My bad 😆

@inthreedee
Copy link
Author

It's expected that the PRIMARY files remains in the stack as you can't unstack it. Now if you unstack the HEIC file for it, this may cause a problem in that the newly created JPEG has the same hash as the one that remains in the stack because it's the primary. So the fix may simply be to disable the buttons.

This sounds like a reasonable solution to that problem. If the only one the user can unstack is the secondary photo, then they can't make that mistake anymore. 👍

@lastzero lastzero changed the title Index: Improve indexing and unstacking of related files Index: More accurate and resilient handling of related files and photo stacks Jan 6, 2022
@graciousgrey graciousgrey added released Available in the stable release and removed please-test Ready for acceptance test labels Jan 7, 2022
@inthreedee
Copy link
Author

@graciousgrey This problem with broken re-stacking, presumably created by the changes here, still exists: #1823 (comment)

If we need a separate issue for it, let me know and I'll create one.

@inthreedee
Copy link
Author

I see there were some commits yesterday. @lastzero If those were meant to address the broken re-stacking mentioned above, let me know and I'll give it another test.

@lastzero
Copy link
Member

lastzero commented Jan 7, 2022

Can you test with a clean index and today's stable release again?

If the issue persists, please create a new issue for it incl test files 👍

@inthreedee
Copy link
Author

Seems to be fixed 👍 The difference I noticed in this release is that both images were marked unstackable instead of just the one I unstacked. To re-stack them, I had to set both images back to stackable, and then they were properly stacked without one of them going missing like before. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working released Available in the stable release
Projects
Status: Release 🌈
Development

No branches or pull requests

3 participants