Video keeps being exported on every run even with seemly no changes. Adding suffix "(1)" and deleting the origin file in cycle. #695

oPromessa · 2022-05-19T14:03:51Z

Describe the bug
A Video MVI_2452.MOV file keeps being exported on every run even with seemly no changes. Adding suffix "(1)" and deleting the origin file in cycle.
Each run either generated the "(1)" file or deletes it.

I've looked for JSON changes in the file attributes in between runs but there are not.

I was trying to debug it with but the breakpoint (from other issues) does not seem to work. Which function should I debug with?

osxphotos export X --exportdb Logs/.osxphotos_export.db --name "MVI_2452" --load-config Apps/colibri.toml --breakpoint osxphotos.photoexporter.PhotoExporter._should_update_photo

To Reproduce
Steps to reproduce the behavior:

What' the full command line you used with osxphotos?2.
What was the error output?

Expected behavior
Not to be re-exported.

Screenshots

## RUN 1
2022-05-18 06:13:41.213373 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (65496/84990)
2022-05-18 06:13:41.230449 -- Writing metadata with exiftool for MVI_2452 (1).MOV
2022-05-18 06:13:45.708574 -- Exported new file /Volumes/photo-1/(...)/MVI_2452 (1).MOV
2022-05-18 06:13:45.709553 -- Touched date on file /Volumes/photo-1/(...)/MVI_2452 (1).MOV
2022-05-18 06:59:34.066710 -- Deleting /Volumes/photo-1/(...)/MVI_2452.MOV

## RUN 2

2022-05-19 05:45:12.048207 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (53069/84990)
2022-05-19 05:45:12.051214 -- Writing metadata with exiftool for MVI_2452.MOV
2022-05-19 05:45:16.914429 -- Exported new file /Volumes/photo-1/(...)/MVI_2452.MOV
2022-05-19 05:45:16.919108 -- Touched date on file /Volumes/photo-1/(...)/MVI_2452.MOV
2022-05-19 06:59:53.336335 -- Deleting /Volumes/photo-1/(...)/MVI_2452 (1).MOV

Desktop (please complete the following information):

OS: [e.g. which version of macOS]: MacOS 12.3.1
osxphotos version (osxphotos --version): osxphotos, version 0.49.0

Additional context
N/A

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

RhetTbull · 2022-05-19T14:36:03Z

You were on the right track with --breakpoint and _should_update_photo is the right method. That will work but --watch is easier in this case. Use this instead of your --breakpoint

--watch osxphotos.photoexporter.PhotoExporter._should_update_photo

This will show all calls to the function listing values of input arguments and the return value.

So in an example where I touched the destination file to change the signature, I got this:

2022-05-19T07:31:37.539560 _should_update_photo returned: ShouldUpdate.DEST_SIG_DIFFERENT, elapsed time: 0.0018706660000002984 sec

And from DEST_SIG_DIFFERENT as the return value, I can see it was updated because the signature was different.

The possible return values of _should_update_photo are:

class ShouldUpdate(Enum):
    NOT_IN_DATABASE = 1
    HARDLINK_DIFFERENT_FILES = 2
    NOT_HARDLINK_SAME_FILES = 3
    DEST_SIG_DIFFERENT = 4
    EXPORT_OPTIONS_DIFFERENT = 5
    EXIFTOOL_DIFFERENT = 6
    EDITED_SIG_DIFFERENT = 7
    DIGEST_DIFFERENT = 8

So add a watch to your export and then try to re-export just that photo (maybe using --selected or --name MVI_2452.MOV and see what the return value is and we can go from there.

You could have done this with breakpoint but it's less convenient. The way osxphotos implements --breakpoint, the function is wrapped in a breakpoint so the break happens right before the function call so you have to s (step) into the actual function then you can use n (next) to step through each line. Or if you just use n (next) as soon as the breakpoint happens you actually step over the function but it shows the return value like this:

[16] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/debug.py(47)debug_breakpoint()-><ShouldUpdate..._DIFFERENT: 4>

In this case you can see the return value is 4 (unfortunately the enum name is truncated) but 4 is "DEST_SIG_DIFFERENT" and in my test, I had touched the destination file so it's signature was different and this is what's expected.

oPromessa · 2022-05-21T11:03:53Z

Running with --watch osxphotos.photoexporter.PhotoExporter._should_update_photo It seems the function is never called!!!

I've ran with --watch osxphotos.photoexporter.PhotoExporter and output indicates and references export_photo_to_directory

2022-05-21T11:25:49.780738 PhotoExporter called from export_photo_to_directory with args: (osxphotos.PhotoInfo(db=osxphotos.PhotosDB(dbfile='/Users/
(...)
uuid='F4A5369A-6553-4933-8805-273F0004A46C', info={'_uuid': 'F4A5369A-6553-4933-8805-273F0004A46C', 'modelID': None, 'masterUuid': None,
'masterFingerprint': 'Ac/xxuGD/BYcjTNbdwjgCy5LNcRF', 'name': None, 'lastmodifieddate_timestamp': None, 'lastmodifieddate': None, 'imageTimeZoneOffsetSeconds': 3600, 
'imageDate_timestamp': 516229342, 'imageDate': datetime.datetime(2017, 5, 11, 22, 2, 22, tzinfo=datetime.timezone(datetime.timedelta(seconds=3600))), 'hidden': 0, 'favorite': 0, 
'originalFilename': 'MVI_2452.MOV', 'filename': 'MVI_2452.MOV',
(...)
hasPersons': 1, 'persons': [3275, 4176, 
4177], 'albums': ['94EA7400-75FE-4E02-BEAF-FB894969B817'], 'hasAlbums': 1}),) and kwargs: {}
2022-05-21T11:25:49.780738 PhotoExporter returned: <osxphotos.photoexporter.PhotoExporter object at 0x157cf2a60>, elapsed time: 1.4356000001214397e-05 sec

But I understand export_photo_to_directory will perform the actual copy of the file.

I believe I need to find which function and how to watch where the pics selection process is done. Would it be here

osxphotos/osxphotos/cli/export.py

Line 1388 in 8e9f279

photos = photosdb.query(query_options)

oPromessa · 2022-05-21T12:03:48Z

Traced it down up to the following code.

I believe it is in a loop when it it checks if destination file exists... dest_exists = dest.exists()
as the file to be exported "MVI_2452" does not exist as the file exported is "MVI_2452 (1)"
dest_exists is false and it exports the file.

Note: Must still debug when the actual file exported is "MVI_2452" without "(1)"

osxphotos/osxphotos/photoexporter.py

Lines 1078 to 1093 in 8e9f279

    
           dest_str = str(dest) 
        
           dest_exists = dest.exists() 
        
           fileutil = options.fileutil 
        
           export_db = options.export_db 
        
           if options.update or options.force_update:  # updating 
        
               if dest_exists: 
        
                   if self._should_update_photo(src, dest, options): 
        
                       update_updated_files.append(dest_str) 
        
                   else: 
        
                       update_skipped_files.append(dest_str) 
        
               else: 
        
                   # update, destination doesn't exist (new file) 
        
                   update_new_files.append(dest_str) 
        
           else:

oPromessa · 2022-05-21T12:23:53Z

Yup, I think that's the issue. Now why only with this file!!!

Maybe because the .osxphotos_export.db database strangely has two entries for MVI_2452 with different uuids but with the same digest?

sqlite> select id, filepath_normalized, uuid, digest  from export_data where filepath like "%MVI_2452%";
26569|(...)/mvi_2452.mov|828CCC89-AE80-4DD5-B8A1-124C2C30352C|7473cdd72e3ce53d0677e52a08025d51f32bd14c
86041|(...)/mvi_2452 (1).mov|F4A5369A-6553-4933-8805-273F0004A46C|7473cdd72e3ce53d0677e52a08025d51f32bd14c

Querying Photos for the uuids only one is valid:

13:18:56 MSP ~[1998]> osxphotos query --uuid 828CCC89-AE80-4DD5-B8A1-124C2C30352C
Using last opened Photos library: /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary
uuid,filename,original_filename,date,description,title,keywords,albums,persons,path,ismissing,hasadjustments,external_edit,favorite,hidden,shared,latitude,longitude,path_edited,isphoto,ismovie,uti,burst,live_photo,path_live_photo,iscloudasset,incloud,date_modified,portrait,screenshot,slow_mo,time_lapse,hdr,selfie,panorama,has_raw,uti_raw,path_raw,intrash
(venv) 
Donald#~>
13:19:53 MSP ~[1999]> osxphotos query --uuid F4A5369A-6553-4933-8805-273F0004A46C
Using last opened Photos library: /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary
uuid,filename,original_filename,date,description,title,keywords,albums,persons,path,ismissing,hasadjustments,external_edit,favorite,hidden,shared,latitude,longitude,path_edited,isphoto,ismovie,uti,burst,live_photo,path_live_photo,iscloudasset,incloud,date_modified,portrait,screenshot,slow_mo,time_lapse,hdr,selfie,panorama,has_raw,uti_raw,path_raw,intrash
F4A5369A-6553-4933-8805-273F0004A46C,MVI_2452.MOV,MVI_2452.MOV,2017-05-11T22:02:22+01:00,,,(...), _UNKNOWN_, _UNKNOWN_",/Users/Shared/Pictures/Pictures/iPhoto/2017-06-11-1727-00/MVI_2452.MOV,False,False,False,False,False,False,,,,False,True,com.apple.quicktime-movie,False,False,,False,,,False,False,False,False,False,False,False,False,,,False

Will delete .osxphotos_export.dband see what happens.

RhetTbull · 2022-05-21T14:11:27Z

The duplicate name with wrong UUID would definitely cause the file to be exported with the (1) increment. What I don't understand is why it would be re-exported. The next time you run --update, the -_should_update_photo method should be called to check if it should be updated. Unless at some point later in the export the database is getting corrupted.

You can see more information about the mystery uuid using this query:

osxphotos exportdb --export-dir /path/to/export Logs/.osxphotos_export.db --sql "select photoinfo from photoinfo where uuid = '828CCC89-AE80-4DD5-B8A1-124C2C30352C'"

RhetTbull · 2022-05-21T14:13:13Z

You could also delete the mystery record without deleting the whole database using:

sqlite3 Logs/.osxphotos_export.db "delete from export_data where uuid = '828CCC89-AE80-4DD5-B8A1-124C2C30352C'"

RhetTbull · 2022-05-21T15:23:53Z

In v0.49.3 I've added two new options to the exportdb command that should help debug things like this issue:

osxphotos exportdb --export-dir /path/to/export Logs/.osxphotos_export.db --uuid-info 828CCC89-AE80-4DD5-B8A1-124C2C30352C

prints out the JSON PhotoInfo record for the UUID so you can find out more about which photo it is

osxphotos exportdb --export-dir /path/to/export Logs/.osxphotos_export.db --uuid-files 828CCC89-AE80-4DD5-B8A1-124C2C30352C

Prints out list of all exported files associated with the UUID.

oPromessa · 2022-05-21T15:54:54Z

The duplicate name with wrong UUID would definitely cause the file to be exported with the (1) increment. What I don't understand is why it would be re-exported. The next time you run --update, the -_should_update_photo method should be called to check if it should be updated. Unless at some point later in the export the database is getting corrupted.

I guess... what happens is that with the "delete" option osxphotos deletes original file. So it resets it and it's back to the same issue.

With a clean .osxphotos_export.db.. It seems to have done the trick on my test export folder.

1st run

2022-05-21 13:25:24.076444 -- Processed: 1 photo, exported: 1, updated: 0, skipped: 0, updated EXIF data: 1, missing: 0, error: 0, touched date: 0

2nd run

2022-05-21 13:26:26.369238 -- Processed: 1 photo, exported: 0, updated: 0, skipped: 1, updated EXIF data: 0, missing: 0, error: 0, touched date: 0

I'm running now the global export (~85K pics so it takes 3.5 hours...) to check.

RhetTbull · 2022-05-21T16:15:26Z

Are you using --cleanup?

oPromessa · 2022-05-21T16:18:22Z

Yes...

RUN 1

> 2022-05-18 06:13:41.213373 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (65496/84990)
> 2022-05-18 06:13:41.230449 -- Writing metadata with exiftool for MVI_2452 (1).MOV
> 2022-05-18 06:13:45.708574 -- Exported new file /Volumes/photo-1/(...)/MVI_2452 (1).MOV
> 2022-05-18 06:13:45.709553 -- Touched date on file /Volumes/photo-1/(...)/MVI_2452 (1).MOV
> 2022-05-18 06:59:34.066710 -- Deleting /Volumes/photo-1/(...)/MVI_2452.MOV

RUN 2

> 2022-05-19 05:45:12.048207 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (53069/84990)
> 2022-05-19 05:45:12.051214 -- Writing metadata with exiftool for MVI_2452.MOV
> 2022-05-19 05:45:16.914429 -- Exported new file /Volumes/photo-1/(...)/MVI_2452.MOV
> 2022-05-19 05:45:16.919108 -- Touched date on file /Volumes/photo-1/(...)/MVI_2452.MOV
> 2022-05-19 06:59:53.336335 -- Deleting /Volumes/photo-1/(...)/MVI_2452 (1).MOV

RhetTbull · 2022-05-21T16:30:29Z

If you have the full logs for both those runs would be useful to see if any other file with the same name was exported.

for example: grep MVI_2452 logfile.log

oPromessa · 2022-05-21T20:10:53Z

Sure... up to 2022.03.05 with osxphotos version 0.74.4 was Skipped up to date file MVI_2452 (1).MOV [curious it was (1) suffixed].

I could try to recover the exportdb file from March 5th / March 6th from TimeMachine to see what happened

It seems I have a version from March 3rd and from March 10th... will have to check in more detail.

From that date onwards it started the loop!

I know for a fact I played quiet a lot with exiftool to:

set all dates on this Video files to make sure all dates (QuickTimeUTC and etc.included ) were set correctly.
and deleted/re-uploaded into Photos
But this was back in January 2022 I believe!

It's possible such changes prompted the wrong entry on the database!

I tag in the log with [notice] the Start and end of each run. I've egreped MVI_2452 and a few other control lines like osxphotos version.

BTW... Waiting for my test to finish!

934791 [notice] --- Start Sat 5 Mar 2022 03:13:00 WET p= 1 LONG=
2022-03-05 03:13:26.791842 -- osxphotos version 0.47.4
         Exporting 84831 photos to /Volumes/photo-1/Family.Photos...
         2022-03-05 03:57:03.825547 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (8121/84831)
         2022-03-05 03:57:03.986972 -- Skipped up to date file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         Processed: 84831 photos, exported: 7, updated: 2379, skipped: 83806, updated EXIF data: 2386, missing: 13, error: 0, touched date: 2386
         Elapsed time: 3:25:01
1119787 [notice] --- End Sat 5 Mar 2022 07:02:39 WET p.end= 0
(...)
1124860 [notice] --- Start Sat 5 Mar 2022 16:28:00 WET p= 1 LONG=
2022-03-05 16:28:02.272965 -- osxphotos version 0.47.4
         Exporting 84818 photos to /Volumes/photo-1/Family.Photos...
         2022-03-05 19:43:00.254763 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (60185/84818)
         2022-03-05 19:43:00.402055 -- Skipped up to date file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         Processed: 84818 photos, exported: 0, updated: 693, skipped: 85499, updated EXIF data: 693, missing: 0, error: 0, touched date: 719
         Elapsed time: 3:13:31
         2022-03-05 20:41:10.103843 -- Deleting /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV
         Deleted: 4 files, 1 directory
1305962 [notice] --- End Sat 5 Mar 2022 20:47:10 WET p.end= 0
1305963 [notice] --- Start Sun 6 Mar 2022 16:28:00 WET p= 1 LONG=
2022-03-06 16:28:03.322688 -- osxphotos version 0.47.4
         Exporting 84818 photos to /Volumes/photo-1/Family.Photos...
         2022-03-06 19:13:13.095921 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (64353/84818)
         2022-03-06 19:13:13.098112 -- Writing metadata with exiftool for MVI_2452.MOV
         2022-03-06 19:13:17.918678 -- Exported new file /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV
         2022-03-06 19:13:17.919041 -- Touched date on file /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV
         Processed: 84818 photos, exported: 1, updated: 989, skipped: 85202, updated EXIF data: 989, missing: 0, error: 0, touched date: 1016
         Elapsed time: 3:31:39
         2022-03-06 20:03:38.687133 -- Deleting /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         Deleted: 1 file, 0 directories
1487694 [notice] --- End Sun 6 Mar 2022 20:10:18 WET p.end= 0
1487695 [notice] --- Start Mon 7 Mar 2022 13:32:00 WET p= 1 LONG=
2022-03-07 13:32:02.412506 -- osxphotos version 0.47.4
         Exporting 84818 photos to /Volumes/photo-1/Family.Photos...
         2022-03-07 13:37:23.222391 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (1927/84818)
         2022-03-07 13:37:23.241301 -- Writing metadata with exiftool for MVI_2452 (1).MOV
         2022-03-07 13:37:27.804058 -- Exported new file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         2022-03-07 13:37:27.806655 -- Touched date on file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         Processed: 84818 photos, exported: 1, updated: 974, skipped: 85217, updated EXIF data: 974, missing: 0, error: 0, touched date: 1001
         Elapsed time: 3:16:40
         2022-03-07 16:51:11.283669 -- Deleting /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV
         Deleted: 1 file, 0 directories
1669397 [notice] --- End Mon 7 Mar 2022 16:58:17 WET p.end= 0
(...)
6103875 [notice] --- Start Fri 20 May 2022 03:44:00 WEST p= 1 LONG=
2022-05-20 03:44:03.378218 -- osxphotos version 0.49.0
         2022-05-20 03:45:05.094638 -- Exporting 84990 photos to /Volumes/photo-1/Family.Photos...
         2022-05-20 06:08:21.748926 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (55309/84990)
         2022-05-20 06:08:21.785689 -- Writing metadata with exiftool for MVI_2452 (1).MOV
         2022-05-20 06:08:26.754378 -- Exported new file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         2022-05-20 06:08:27.427575 -- Touched date on file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         Exporting 84990 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
         2022-05-20 07:28:07.059193 -- Processed: 84990 photos, exported: 1, updated: 260, skipped: 86102, updated EXIF data: 260, missing: 1, error: 0, touched date: 287
         2022-05-20 07:28:07.059932 -- Elapsed time: 3:43:02
         2022-05-20 07:30:02.000024 -- Deleting /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV
         2022-05-20 07:36:44.364708 -- Deleted: 1 file, 0 directories
6369535 [notice] --- End Fri 20 May 2022 07:37:20 WEST p.end= 0
6369536 [notice] --- Start Sat 21 May 2022 03:44:00 WEST p= 1 LONG=
2022-05-21 03:44:02.443207 -- osxphotos version 0.49.0
         2022-05-21 03:45:03.056813 -- Exporting 84990 photos to /Volumes/photo-1/Family.Photos...
         2022-05-21 03:46:08.768378 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV (400/84990)
         2022-05-21 03:46:08.769519 -- Writing metadata with exiftool for MVI_2452.MOV
         2022-05-21 03:46:13.358193 -- Exported new file /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV
         2022-05-21 03:46:13.358628 -- Touched date on file /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV
         Exporting 84990 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
         2022-05-21 07:27:44.521930 -- Processed: 84990 photos, exported: 1, updated: 236, skipped: 86126, updated EXIF data: 236, missing: 1, error: 0, touched date: 263
         2022-05-21 07:27:44.522639 -- Elapsed time: 3:42:41
         2022-05-21 07:29:37.423443 -- Deleting /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV
         2022-05-21 07:35:27.570016 -- Deleted: 1 file, 0 directories
6635147 [notice] --- End Sat 21 May 2022 07:36:10 WEST p.end= 0

RhetTbull · 2022-05-21T20:28:56Z

Thanks. Nothing jumps out here but I'll look at 0.47.4 and see if anything changed that points to this issue. In research this I did discover another bug? that occurs if you have two files with the same name in the same folder and then delete one. osxphotos can in that instance end up exporting the deleted file over top the one that's still there, then see the uuid is wrong on the next photo and re-export over top again. This is fixed with a subsequent export which correctly sees the the existing file and adds (1) to the second file. I'm not sure how to easily fix this as it's a "feature" of how the export database works.

osxphotos export ~/Desktop/export --name wedding --verbose --update --exiftool --cleanup --skip-edited
osxphotos version 0.49.4
exiftool path: /usr/local/bin/exiftool
Using last opened Photos library: /Users/rhet/Pictures/Test-10.15.7.photoslibrary
Using export database /Users/rhet/Desktop/export/.osxphotos_export.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/photos.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/Photos.sqlite
Database locked, creating temporary copy.
Processing database.
Database version: 6000, 5.
Processing persons in photos.
Processing detected faces in photos.
Processing albums.
Processing keywords.
Processing photo details.
Processing import sessions.
Processing additional photo details.
Processing face details.
Processing photo labels.
Processing EXIF details.
Processing computed aesthetic scores.
Processing comments and likes for shared photos.
Processing moments.
Done processing details from Photos library.
Exporting 2 photos to /Users/rhet/Desktop/export...
Exporting wedding.jpg (E9BC5C36-7CD1-40A1-A72B-8B8FAC227D51.jpeg) as wedding.jpg (1/2)
Skipped up to date file /Users/rhet/Desktop/export/wedding (1).jpg
Exporting wedding.jpg (2D8B229F-9C7D-42E5-80B3-4B84CEA60F06.jpeg) as wedding.jpg (2/2)
Skipped up to date file /Users/rhet/Desktop/export/wedding.jpg
Exporting 2 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
Processed: 2 photos, exported: 0, updated: 0, skipped: 2, updated EXIF data: 0, missing: 0, error: 0
Elapsed time: 0:00:00
Cleaning up /Users/rhet/Desktop/export
Deleted: 0 files, 0 directories

rm /Users/rhet/Desktop/export/wedding.jpg

osxphotos export ~/Desktop/export --name wedding --verbose --update --exiftool --cleanup --skip-edited
osxphotos version 0.49.4
exiftool path: /usr/local/bin/exiftool
Using last opened Photos library: /Users/rhet/Pictures/Test-10.15.7.photoslibrary
Using export database /Users/rhet/Desktop/export/.osxphotos_export.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/photos.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/Photos.sqlite
Database locked, creating temporary copy.
Processing database.
Database version: 6000, 5.
Processing persons in photos.
Processing detected faces in photos.
Processing albums.
Processing keywords.
Processing photo details.
Processing import sessions.
Processing additional photo details.
Processing face details.
Processing photo labels.
Processing EXIF details.
Processing computed aesthetic scores.
Processing comments and likes for shared photos.
Processing moments.
Done processing details from Photos library.
Exporting 2 photos to /Users/rhet/Desktop/export...
Exporting wedding.jpg (E9BC5C36-7CD1-40A1-A72B-8B8FAC227D51.jpeg) as wedding.jpg (1/2)
Writing metadata with exiftool for wedding.jpg
Exported new file /Users/rhet/Desktop/export/wedding.jpg
Exporting wedding.jpg (2D8B229F-9C7D-42E5-80B3-4B84CEA60F06.jpeg) as wedding.jpg (2/2)
Writing metadata with exiftool for wedding.jpg
Exported updated file /Users/rhet/Desktop/export/wedding.jpg
Exporting 2 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
Processed: 2 photos, exported: 1, updated: 1, skipped: 0, updated EXIF data: 2, missing: 0, error: 0
Elapsed time: 0:00:01
Cleaning up /Users/rhet/Desktop/export
Deleting /Users/rhet/Desktop/export/wedding (1).jpg
Deleted: 1 file, 0 directories

osxphotos export ~/Desktop/export --name wedding --verbose --update --exiftool --cleanup --skip-edited
osxphotos version 0.49.4
exiftool path: /usr/local/bin/exiftool
Using last opened Photos library: /Users/rhet/Pictures/Test-10.15.7.photoslibrary
Using export database /Users/rhet/Desktop/export/.osxphotos_export.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/photos.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/Photos.sqlite
Database locked, creating temporary copy.
Processing database.
Database version: 6000, 5.
Processing persons in photos.
Processing detected faces in photos.
Processing albums.
Processing keywords.
Processing photo details.
Processing import sessions.
Processing additional photo details.
Processing face details.
Processing photo labels.
Processing EXIF details.
Processing computed aesthetic scores.
Processing comments and likes for shared photos.
Processing moments.
Done processing details from Photos library.
Exporting 2 photos to /Users/rhet/Desktop/export...
Exporting wedding.jpg (E9BC5C36-7CD1-40A1-A72B-8B8FAC227D51.jpeg) as wedding.jpg (1/2)
Writing metadata with exiftool for wedding (1).jpg
Exported new file /Users/rhet/Desktop/export/wedding (1).jpg
Exporting wedding.jpg (2D8B229F-9C7D-42E5-80B3-4B84CEA60F06.jpeg) as wedding.jpg (2/2)
Skipped up to date file /Users/rhet/Desktop/export/wedding.jpg
Exporting 2 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
Processed: 2 photos, exported: 1, updated: 0, skipped: 1, updated EXIF data: 1, missing: 0, error: 0
Elapsed time: 0:00:01
Cleaning up /Users/rhet/Desktop/export
Deleted: 0 files, 0 directories

osxphotos export ~/Desktop/export --name wedding --verbose --update --exiftool --cleanup --skip-edited
osxphotos version 0.49.4
exiftool path: /usr/local/bin/exiftool
Using last opened Photos library: /Users/rhet/Pictures/Test-10.15.7.photoslibrary
Using export database /Users/rhet/Desktop/export/.osxphotos_export.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/photos.db
Processing database /Users/rhet/Pictures/Test-10.15.7.photoslibrary/database/Photos.sqlite
Database locked, creating temporary copy.
Processing database.
Database version: 6000, 5.
Processing persons in photos.
Processing detected faces in photos.
Processing albums.
Processing keywords.
Processing photo details.
Processing import sessions.
Processing additional photo details.
Processing face details.
Processing photo labels.
Processing EXIF details.
Processing computed aesthetic scores.
Processing comments and likes for shared photos.
Processing moments.
Done processing details from Photos library.
Exporting 2 photos to /Users/rhet/Desktop/export...
Exporting wedding.jpg (2D8B229F-9C7D-42E5-80B3-4B84CEA60F06.jpeg) as wedding.jpg (1/2)
Skipped up to date file /Users/rhet/Desktop/export/wedding.jpg
Exporting wedding.jpg (E9BC5C36-7CD1-40A1-A72B-8B8FAC227D51.jpeg) as wedding.jpg (2/2)
Skipped up to date file /Users/rhet/Desktop/export/wedding (1).jpg
Exporting 2 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
Processed: 2 photos, exported: 0, updated: 0, skipped: 2, updated EXIF data: 0, missing: 0, error: 0
Elapsed time: 0:00:00
Cleaning up /Users/rhet/Desktop/export
Deleted: 0 files, 0 directories

RhetTbull · 2022-05-21T21:13:01Z

0.47.4 added --tmpdir and I don't see any way this change could cause the problem. 0.46.0 did have some big changes to the export database so possible something got corrupted that way but I've not been able to pinpoint anything.

and deleted/re-uploaded into Photos But this was back in January 2022 I believe!

This would cause the UUID to change so that's possibly where the phantom UUID in the export database came from. I'm still not sure why that would cause the cyclical export though.

Ideally there would never be duplicate file names in a directory when exported. I've tried to handle all edge cases but it is a tricky problem to track which filename goes with which uuid.

oPromessa · 2022-05-23T12:06:14Z

So I did some forensics investigation:

After migration from iPhoto to Photos and OS Monterey I started using osxphotos (Jan 6th or whereabouts)
The MVI_2452.MOV was and edited movie file within Photos (the beginning was cut)
Export of the edited file failed over and over...

[notice] --- Start
Sat  8 Jan 2022 21:50:00 WET
Edited file for MVI_2452.MOV is missing, exporting original
Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV
Skipped up to date exiftool metadata for /Volumes/photo-1/Family.Photos/(...)MVI_2452.MOV

Until Jan 29th when I believe I've reverted the editions I've done on the video version. Although oddly enough there were errors exporting the file. The UUID is in fact the one we later on found out to be incorrect and deleted the entry in the .osxphotos_export.db.

[notice] --- Start Sat 29 Jan 2022 12:28:00 WET
Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV
Error exporting photo (828CCC89-AE80-4DD5-B8A1-124C2C30352C: MVI_2452.MOV) as MVI_2452.MOV: float division by zero 
Retrying export for photo (828CCC89-AE80-4DD5-B8A1-124C2C30352C: MVI_2452.MOV)
Error exporting photo (828CCC89-AE80-4DD5-B8A1-124C2C30352C: MVI_2452.MOV) as MVI_2452.MOV: float division by zero 
Retrying export for photo (828CCC89-AE80-4DD5-B8A1-124C2C30352C: MVI_2452.MOV)
Error exporting photo (828CCC89-AE80-4DD5-B8A1-124C2C30352C: MVI_2452.MOV) as MVI_2452.MOV: float division by zero 
(...)
Deleting /Volumes/photo-1/Family.Photos/(...)/MVI_2452.MOV

And then it stop giving the error on the export (I believe at this time around version 0.45.3 there was a refactoring of the export functionality) and started the looping.

2022-02-01 04:00:47.863490 -- Exporting MVI_2452.MOV (MVI_2452.MOV) as MVI_2452.MOV
2022-02-01 04:00:47.882670 -- Writing metadata with exiftool for MVI_2452 (1).MOV 
2022-02-01 04:01:18.597722 -- Exported new file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV 
2022-02-01 04:01:18.599593 -- Touched date on file /Volumes/photo-1/Family.Photos/(...)/MVI_2452 (1).MOV

The databases contents from Jan 19th and Feb 3rd (only backups I have) reflect the start of the duplicate entre of the files table.

13:02:02 MSP INVESTIGATION[2331]> sqlite3 .osxphotos_export.20220119.db  "select * from files  where filepath like '%MVI_2452%';"
26616|(...)/MVI_2452.MOV|(...)/mvi_2452.mov|828CCC89-AE80-4DD5-B8A1-124C2C30352C|32768|314223950|1641699976.0|32768|314224767|1641699976.0
(venv) 
13:02:15 MSP INVESTIGATION[2332]> sqlite3 .osxphotos_export.20220203.db  "select * from files  where filepath like '%MVI_2452%';"
26616|(...)/MVI_2452.MOV|(...)/mvi_2452.mov|828CCC89-AE80-4DD5-B8A1-124C2C30352C|32768|314223950|1643860548.0|32768|314224767|1494536542.0
86126|(...)/MVI_2452 (1).MOV|(...)/mvi_2452 (1).mov|F4A5369A-6553-4933-8805-273F0004A46C|32768|314223950|1643839208.0|32768|314224767|1494536542.0
(venv)

I guess I'd still have to test osxphotos behaviour with edited MOVIES.

RhetTbull · 2022-05-23T13:28:46Z

Thanks, I'll take a look at this. Since you deleted the backup database and re-exported, has the problem persisted? Is the file being handled correctly or is it still in a loop?

RhetTbull · 2022-05-23T13:48:37Z

Getting somewhere....used your config file from #654, created two videos with same name, exported, edited 1 then re-exported and now I've got a loop similar to your situation. Now that I have a test config that can recreate a similar situation I'll see if I can track this down any further.

oPromessa · 2022-05-23T14:11:05Z

Thanks, I'll take a look at this. Since you deleted the backup database and re-exported, has the problem persisted? Is the file being handled correctly or is it still in a loop?

Sorry I ended up not updating you.

Deleting the database would make osxphotos export (1) for all the pics.. so I canelled that...
Recovered the db and deleted just the wrong entry. It solved the issue. YAY.
- only detail is that on the export_db the filname_normalized entry refers to the (1) file when the actual file exported was the without it. Not serious.. will investigate further on that, later on.

Side note: Just updated to the latest osxphotos 0.49.6 version Next run will be with this version!

osxphotos exportdb .osxphotos_export.db --sql "select * from export_data where filepath like '%MVI_2452%'"
(
    86041,
    '(...)/mvi_2452 (1).mov',
    '(...)/MVI_2452 (1).MOV',
    'F4A5369A-6553-4933-8805-273F0004A46C',
    32768,
    314223950,
    1494536542.0,
    32768,
    314226926,
    1494536542.0,
    '7473cdd72e3ce53d0677e52a08025d51f32bd14c',
    '[{"EXIF:ImageDescription": "(...)", (...) QuickTime:CreationDate": "2017:05:11 22:02:22+01:00", "QuickTime:CreateDate": "2017:05:11 21:02:22", 
"QuickTime:ModifyDate": "2017:05:11 21:02:22"}]',
    2,
    None
)
(
    88345,
    '(...)/mvi_2452.mov',
    '(...)/MVI_2452.MOV',
    'F4A5369A-6553-4933-8805-273F0004A46C',
    32768,
    314223950,
    1494536542.0,
    32768,
    314227519,
    1494536542.0,
    '68df2be7ed859855a0313fe382559b7b20f7cc47',
    '[{"EXIF:ImageDescription": (...) "QuickTime:CreationDate": "2017:05:11 22:02:22+01:00", "QuickTime:CreateDate": "2017:05:11 21:02:22", "QuickTime:ModifyDate": "2017:05:11 21:02:22"}]',
    2,
    None
)

15:29:54 MSP Logs[2358]>  osxphotos exportdb .osxphotos_export.db --sql "select photoinfo from photoinfo where uuid = 'F4A5369A-6553-4933-8805-273F0004A46C'"
(
    '{"albums": [(...) "uuid": 
"E9961FDE-CCC9-4CD5-9769-E4997849B19A", "yaw": 0.0}], "favorite": false, "filename": "MVI_2452.MOV", "folders": (...)(...)
"uuid": "F4A5369A-6553-4933-8805-273F0004A46C", "width": 1920}',
)

RhetTbull · 2022-05-23T15:28:49Z

Found the problem! Will describe more when I have a chance and work on a solution.

RhetTbull · 2022-05-24T02:45:59Z

For this issue to occur, there must be two files with the same name exported to the same directory and at some point one of them must change names or get deleted. And the order matters...you have a 50/50 chance this will occur in the event there are two files with the same name, one of them is deleted or edited (causing name change), and you're using --cleanup. I think that's what happened to you even though you can find only one file now, there must have been at one time a second file called MVI_2452.MOV with UUID 828CCC89-AE80-4DD5-B8A1-124C2C30352C -- maybe a duplicate that got deleted? Another possibility is you rebuilt the database with Repair Library option in Photos which can lead to different UUIDs. Or you edited the file outside Photos and re-imported:

I know for a fact I played quiet a lot with exiftool to:
set all dates on this Video files to make sure all dates (QuickTimeUTC and etc.included ) were set correctly.
and deleted/re-uploaded into Photos
But this was back in January 2022 I believe!

This:

Maybe because the .osxphotos_export.db database strangely has two entries for MVI_2452 with different uuids but with the same digest?

leads me to believe they were the same file (a duplicate that got deleted) or it was a result of you editing the file with exiftool then re-importing.

Here's what I think is going on. This condition only happens with --cleanup. --skip-original-if-edited satisfies the "one file changed name" criteria but there are other ways a name change could occur (anything that caused the --filename template to produce a different name).

Two files, both with same name, end up in the same directory.

run osxphotos export:

UUID_A: file.mov  --> file.mov
UUID_B: file.mov  --> file (1).mov

ExportDB (export_data table) now looks like:

filepath_normalized, filepath, uuid
file.mov, file.mov, UUID_A
file (1).mov, file (1).mov, UUID_B

Edit the file associated with UUID_A then run osxphotos export --update --skip-original-if-edited --cleanup:

UUID_A: file.mov  --> file_edited.mov

cleanup now deletes file.mov so export directory looks like:

UUID_A: file.mov  --> file_edited.mov
UUID_B: file.mov  --> file (1).mov

ExportDB (export_data table) now looks like:

filepath_normalized, filepath, uuid
file.mov, file.mov, UUID_A
file (1).mov, file (1).mov, UUID_B
file_edited.mov, file_edited.mov, UUID_A

Run osxphotos export --update --skip-original-if-edited --cleanup:

UUID_A: file.mov  --> file_edited.mov (skipped)
UUID_B: file.mov --> file.mov (this file doesn't exist anymore so the code that checks filename against UUID doesn't run)

cleanup now deletes file (1).mov

Run osxphotos export --update --skip-original-if-edited --cleanup:

UUID_A: file.mov  --> file_edited.mov (skipped)
UUID_B: file.mov  --> file (1).mov

Because file.mov exists, the code checks to see if it's the right UUID. It's not (it's UUID_A) so the code increments the file name.

cleanup now deletes file.mov and the cycle starts over

RhetTbull · 2022-05-24T02:54:31Z

I'm still trying to figure out a fix that handles all the edge cases. In this simple case, I could just check the database even if the file is missing from the export directory to see if the target filename is already associated with a UUID and if so, increment the filename. But this fails for the case where you have more than two files in this situation as we'd have to check every permutation of the file (file.mov, file (1).mov, file (2).mov, etc.) to see if another UUID is associated with it. And of course, if you have a file that was originally called file (1).mov, it gets even more complicated.

I think a better solution is to add a new table to the database that is a mapping of (uuid, desired target file name) --> actual target file name.

For example:

uuid, desired_target, actual_target
UUID_A, file.mov, file.mov
UUID_B, file.mov, file (1).mov
UUID_A, file_edited.mov, file_edited.mov

In this case, when file.mov was deleted by --cleanup because it was replaced with file_edited.mov, the code would query the database for the tuple (UUID_B, file.mov) which would return file (1).mov and so that file would be used. The export directory would thus look like:

UUID_A: file.mov --> file_edited.mov
UUID_B: file.mov --> file (1). mov

This means that once a photo is associated with an increment, it would also keep that increment even if the conflicting filename no longer exists in the database.

RhetTbull · 2022-05-24T05:26:23Z

I think I found a way to fix this without creating a new table. I implemented a function that searches through the export database for all possible matches of the file (incrementing the file counter) to see if it has been previously associated with the UUID in question and if so, uses the previously used filename. This results in preserving the mapping of UUID -> filename even if other files are added or deleted, so a file exported as file (2).mov will always be exported that way even if file (1).mov was deleted from the export set.

As an aside, I think this is going to result in faster exports where there are file conflicts because the code first checks the database, then checks to see if the target file exists instead of what the current code does which is list the files in the directory and listing directories is always slower than checking if a single file exists.

RhetTbull · 2022-05-24T06:35:28Z

Give 0.49.8 a try and let me know if it fixes the problem. It might take two runs to synch the current export dir with the database but then should stop doing the cyclical update.

oPromessa · 2022-05-27T15:13:53Z

Hi @RhetTbull

did't test 0.49.8 yet! Still on 0.49.6
I wanted to make sure I was able to reproduce the issue in a slight different scenario from the one you described above (the looping export/delete)
- In this case there are not two pics/two UUIDs in Photos but only one pic/uuid which is deleted/re-uploaded with the same filename and into the same album.
If you can review and see if 0.49.8 also covers this case

Moment 0
Photos:UUID_A: file.mov
osxphotos export: UUID_A --> file.mov

Moment 1
Photos:delete UUID_A: file.mov
Photos:upload UUID_B: file.mov 
osxphotos export: UUID_B --> file (1).mov
osxphotos cleanup: UUID_A --> DELETE file.mov [So far so good!]

Moment 2 run export
osxphotos export: UUID_B --> file.mov
osxphotos cleanup: UUID_B --> DELETE file (1).mov

Moment 3 run export
osxphotos export: UUID_B --> file (1).mov
osxphotos cleanup: UUID_B --> DELETE file.mov

...and so on

and checking .osxphotos_export.db we have two entries:

21984|(...)/img_2126.jpg|(...)/IMG_2126.JPG|F3070D03-8D56-4575-AA2D-DCCDB3038233|(...)|2|2022-05-26 05:26:22.774
88422|(...)/img_2126 (1).jpg|(...)/IMG_2126 (1).JPG|0EADC2C2-A36F-44CE-A1A6-859B25DBB41E|32768|(...)|2022-05-27 05:23:12.068

and querying Photos with the two UUIDs...one is found and another one not:

$ osxphotos query --uuid 0EADC2C2-A36F-44CE-A1A6-859B25DBB41E
Using last opened Photos library: /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary
uuid,filename,original_filename,date,description,title,keywords,albums,persons,path,ismissing,hasadjustments,external_edit,favorite,hidden,shared,latitude,longitude,path_edited,isphoto,ismovie,uti,burst,live_photo,path_live_photo,iscloudasset,incloud,date_modified,portrait,screenshot,slow_mo,time_lapse,hdr,selfie,panorama,has_raw,uti_raw,path_raw,intrash
0EADC2C2-A36F-44CE-A1A6-859B25DBB41E,IMG_2126.JPG,IMG_2126.JPG,2017-03-31T14:00:09+01:00,                               (...)

$ osxphotos query --uuid F3070D03-8D56-4575-AA2D-DCCDB3038233
Using last opened Photos library: /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary
uuid,filename,original_filename,date,description,title,keywords,albums,persons,path,ismissing,hasadjustments,external_edit,favorite,hidden,shared,latitude,longitude,path_edited,isphoto,ismovie,uti,burst,live_photo,path_live_photo,iscloudasset,incloud,date_modified,portrait,screenshot,slow_mo,time_lapse,hdr,selfie,panorama,has_raw,uti_raw,path_raw,intrash

RhetTbull · 2022-05-27T19:13:29Z

@oPromessa yes, I believe this case will be covered by 0.49.8 -- what the code does now is create unique pairings of (UUID, exported file name) so in your example, UUID_B will always be exported as "file (1).mov" after the first time because that name will be associated with the UUID. The export database now is responsible for managing the pairings of UUID and filename instead of the export code trying to guess the right name. Once exported with a certain name, a given UUID will always use that same name when exported with --update and the same directory/filename templates

osxphotos/osxphotos/export_db.py

Line 217 in 999b16e

def get_target_for_file(

oPromessa · 2022-05-27T22:30:49Z

Thanks! Will try the new version tonight.

I should maybe delete the double entry in the DB
Food for thought... maybe one could run the --cleanup option on its own prior to the export as to keep the file name for UUID_B to file.mov ? Would like to reduce "(1)" entries to a minimum.
- Hmmm... Doesn't seem to make sense.. without export osxphotos wouldn't know what to delete... bummer!

Moment 0
Photos:UUID_A: file.mov
osxphotos export: UUID_A --> file.mov

Moment 1
Photos:delete UUID_A: file.mov
Photos:upload UUID_B: file.mov 
osxphotos NEW cleanup OPTION WITHOUT EXPORT: UUID_A --> DELETE file.mov

Moment 2
osxphotos export: UUID_B --> file.mov

RhetTbull · 2022-05-27T23:24:34Z

Food for thought... maybe one could run the --cleanup option on its own prior to the export as to keep the file name for UUID_B to file.mov ? Would like to reduce "(1)" entries to a minimum.

So you could do this: run with --cleanup --dry-run --report report.csv osxphotos would then not actually export anything but would tell you which files are going to get deleted. You could then write a script to delete those then run the export without --dry-run.

As of version 0.49.0, --report can write to csv, json, or sqlite so if you are able to write a script that reads one of those, you could delete any file with "cleanup_deleted_file": true

oPromessa · 2022-05-28T16:42:13Z

Thank you so much for the support. Sorry to be a pain!!!

A. Great tip on the "delete without export". Thanks.

B. Further testing with version 0.49.9 after deleting the duplicate entry on the export database: It ended up creating a second entry in the database with the same uuid and the loop is still there. Now with pic IMG_2126.

Just wanted to let you know.

88422|(...)/img_2126 (1).jpg|(...)/IMG_2126 (1).JPG|0EADC2C2-A36F-44CE-A1A6-859B25DBB41E|32768|4956254|1490965209.0|32768|4957659|1490965209.0|(...)
88423|(...)/img_2126.jpg|(...)/IMG_2126.JPG|0EADC2C2-A36F-44CE-A1A6-859B25DBB41E|32768|4956254|1490965209.0|32768|4957659|1490965209.0|(...)

C. For my "active" system I'll cleanup things:

Delete the exported file
delete the two entries on the the database
run an export and cleanup
it should fix

D. Will setup a small test for this scenario of replacing files. As I notice I do it on and off after reviewing some pics after loading.

RhetTbull · 2022-05-28T19:19:44Z

I'll take a look at the code and see if I can figure out a way to catch this. I can probably have the code that checks the file names always default to the version without (1)... if there's more than one record for a UUID

oPromessa · 2022-05-28T23:54:44Z

D. Will setup a small test for this scenario of replacing files. As I notice I do it on and off after reviewing some pics after loading.

Sequence:

1st export. Exports file. OK
2nd export. Skips file. OK
Delete file and re/upload in Photos. 3rd export. Exports "(1)" file. and Delete original file.
4th export. Indicates to export "IMG_2126" as "IMG_2126" but in reality the existing file is kept "(1)".
I've then added a new file named IMG_2126 to the same album. 5th export. Skips "(1)" and exports/creates "(2)". OK.
6th Re/ran export. Skips "(1)" and "(2)" but message still refers to original file. OK
- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG

1st export. Exports file. OK

$  osxphotos export X --exportdb X/.osxphotos_export.db --name "IMG_2126" --load-config Apps/colibri.toml 
2022-05-29 00:21:59.520221 -- Loaded options from file Apps/colibri.toml
2022-05-29 00:21:59.520790 -- osxphotos version 0.50.0
2022-05-29 00:21:59.544080 -- exiftool path: /usr/local/bin/exiftool
2022-05-29 00:21:59.561100 -- Created export database X/.osxphotos_export.db
(...)
)2022-05-29 00:22:32.505312 -- Exporting 4 photos to /Users/Shared/Pictures/X...
2022-05-29 00:22:33.838242 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (4/4)
2022-05-29 00:22:33.840243 -- Writing metadata with exiftool for IMG_2126.JPG
2022-05-29 00:22:34.233573 -- Exported new file (...)/IMG_2126.JPG
Exporting 4 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
2022-05-29 00:22:34.238355 -- Processed: 4 photos, exported: 4, updated: 0, skipped: 0, updated EXIF data: 4, missing: 0, error: 0, touched date: 2
2022-05-29 00:22:34.238901 -- Elapsed time: 0:00:01
2022-05-29 00:22:34.239291 -- Cleaning up /Users/Shared/Pictures/X
2022-05-29 00:22:34.240042 -- Deleting /Users/Shared/Pictures/X/2017-05-11 16 Anos Joana/MVI_2452.MOV
2022-05-29 00:22:34.243080 -- Deleted: 1 file, 1 directory

2nd export. Skips file. OK

$ osxphotos export X --exportdb X/.osxphotos_export.db --name "IMG_2126" --load-config Apps/colibri.toml 
2022-05-29 00:23:43.201950 -- Loaded options from file Apps/colibri.toml
2022-05-29 00:23:43.202510 -- osxphotos version 0.50.0
2022-05-29 00:23:43.220616 -- exiftool path: /usr/local/bin/exiftool
2022-05-29 00:23:43.224274 -- Using export database X/.osxphotos_export.db
2022-05-29 00:24:11.648873 -- Exporting 4 photos to /Users/Shared/Pictures/X...
2022-05-29 00:24:11.652699 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (1/4)
2022-05-29 00:24:12.043388 -- Skipped up to date file (...)/IMG_2126.JPG
Exporting 4 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
2022-05-29 00:24:12.448174 -- Processed: 4 photos, exported: 0, updated: 0, skipped: 4, updated EXIF data: 0, missing: 0, error: 0, touched date: 0
2022-05-29 00:24:12.448804 -- Elapsed time: 0:00:00
2022-05-29 00:24:12.449241 -- Cleaning up /Users/Shared/Pictures/X
2022-05-29 00:24:12.450507 -- Deleted: 0 files, 0 directories

Delete file and re/upload in Photos. 3rd export. Exports "(1)" file. and Delete original file.

$ osxphotos export X --exportdb X/.osxphotos_export.db --name "IMG_2126" --load-config Apps/colibri.toml 
2022-05-29 00:25:05.221959 -- Loaded options from file Apps/colibri.toml
2022-05-29 00:25:05.222513 -- osxphotos version 0.50.0
2022-05-29 00:25:05.240595 -- exiftool path: /usr/local/bin/exiftool
2022-05-29 00:25:05.244442 -- Using export database X/.osxphotos_export.db
2022-05-29 00:25:33.782620 -- Exporting 4 photos to /Users/Shared/Pictures/X...
2022-05-29 00:25:33.786039 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (1/4)
2022-05-29 00:25:33.788371 -- Writing metadata with exiftool for IMG_2126 (1).JPG
2022-05-29 00:25:34.429398 -- Exported new file (...)/IMG_2126 (1).JPG
Exporting 4 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
2022-05-29 00:25:34.843780 -- Processed: 4 photos, exported: 1, updated: 0, skipped: 3, updated EXIF data: 1, missing: 0, error: 0, touched date: 0
2022-05-29 00:25:34.844292 -- Elapsed time: 0:00:01
2022-05-29 00:25:34.844661 -- Cleaning up /Users/Shared/Pictures/X
2022-05-29 00:25:34.845350 -- Deleting (...)/IMG_2126.JPG
2022-05-29 00:25:34.846399 -- Deleted: 1 file, 0 directories

4th export. Indicates to export "IMG_2126" as "IMG_2126" but in reality the existing file is kept "(1)".

$ osxphotos export X --exportdb X/.osxphotos_export.db --name "IMG_2126" --load-config Apps/colibri.toml 
2022-05-29 00:25:50.488409 -- Loaded options from file Apps/colibri.toml
2022-05-29 00:25:50.488976 -- osxphotos version 0.50.0
2022-05-29 00:25:50.507316 -- exiftool path: /usr/local/bin/exiftool
2022-05-29 00:25:50.511461 -- Using export database X/.osxphotos_export.db
2022-05-29 00:26:18.879500 -- Exporting 4 photos to /Users/Shared/Pictures/X...
2022-05-29 00:26:19.245373 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (2/4)
2022-05-29 00:26:19.397235 -- Skipped up to date file (...)/IMG_2126 (1).JPG
Exporting 4 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
2022-05-29 00:26:19.644178 -- Processed: 4 photos, exported: 0, updated: 0, skipped: 4, updated EXIF data: 0, missing: 0, error: 0, touched date: 0
2022-05-29 00:26:19.644682 -- Elapsed time: 0:00:00
2022-05-29 00:26:19.645052 -- Cleaning up /Users/Shared/Pictures/X
2022-05-29 00:26:19.646254 -- Deleted: 0 files, 0 directories
2022-05-29 00:26:19.646648 -- Wrote export report to /Users/Shared/Pictures/Logs/colibri.csv
2022-05-29 00:26:19.647104 -- Writing export database changes back to X/.osxphotos_export.db

$ ls X/(...))/IMG_2126*
X/(...))/IMG_2126 (1).JPG

I've then added a new file named IMG_2126 to the same album. 5th export. Skips "(1)" and exports/creates "(2)". OK.

$ osxphotos export X --exportdb X/.osxphotos_export.db --name "IMG_2126" --load-config Apps/colibri.toml 
2022-05-29 00:43:24.173040 -- Loaded options from file Apps/colibri.toml
2022-05-29 00:43:24.173652 -- osxphotos version 0.50.0
2022-05-29 00:43:24.193525 -- exiftool path: /usr/local/bin/exiftool
2022-05-29 00:43:24.198791 -- Using export database X/.osxphotos_export.db
2022-05-29 00:43:55.839815 -- Done processing details from Photos library.
2022-05-29 00:43:56.790162 -- Exporting 5 photos to /Users/Shared/Pictures/X...
2022-05-29 00:43:57.422427 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (3/5)
2022-05-29 00:43:57.578603 -- Skipped up to date file (...)IMG_2126 (1).JPG
2022-05-29 00:43:57.706541 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (5/5)
2022-05-29 00:43:57.723639 -- Writing metadata with exiftool for IMG_2126 (2).JPG
2022-05-29 00:43:58.056187 -- Exported new file (...)IMG_2126 (2).JPG
Exporting 5 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
2022-05-29 00:43:58.060349 -- Processed: 5 photos, exported: 1, updated: 0, skipped: 4, updated EXIF data: 1, missing: 0, error: 0, touched date: 0
2022-05-29 00:43:58.060877 -- Elapsed time: 0:00:01
2022-05-29 00:43:58.061306 -- Cleaning up /Users/Shared/Pictures/X
2022-05-29 00:43:58.062510 -- Deleted: 0 files, 0 directories
2022-05-29 00:43:58.062867 -- Wrote export report to /Users/Shared/Pictures/Logs/colibri.csv
2022-05-29 00:43:58.063315 -- Writing export database changes back to X/.osxphotos_export.db

$ ls X/(...))/*
X/(...)/IMG_2126 (1).JPG
X/(...)/IMG_2126 (2).JPG

6th Re/ran export. Skips "(1)" and "(2)" but message still refers to original file. OK

$ osxphotos export X --exportdb X/.osxphotos_export.db --name "IMG_2126" --load-config Apps/colibri.toml 
2022-05-29 00:49:06.611644 -- Loaded options from file Apps/colibri.toml
2022-05-29 00:49:06.612215 -- osxphotos version 0.50.0
2022-05-29 00:49:06.630690 -- exiftool path: /usr/local/bin/exiftool
2022-05-29 00:49:06.635478 -- Using export database X/.osxphotos_export.db
2022-05-29 00:49:34.472174 -- Done processing details from Photos library.
2022-05-29 00:49:35.191061 -- Exporting 5 photos to /Users/Shared/Pictures/X...
2022-05-29 00:49:35.194644 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (1/5)
2022-05-29 00:49:35.545926 -- Skipped up to date file (...)IMG_2126 (2).JPG
2022-05-29 00:49:35.854458 -- Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (4/5)
2022-05-29 00:49:36.013949 -- Skipped up to date file (...)IMG_2126 (1).JPG
Exporting 5 photos ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00
2022-05-29 00:49:36.171588 -- Processed: 5 photos, exported: 0, updated: 0, skipped: 5, updated EXIF data: 0, missing: 0, error: 0, touched date: 0
2022-05-29 00:49:36.172160 -- Elapsed time: 0:00:00
2022-05-29 00:49:36.172562 -- Cleaning up /Users/Shared/Pictures/X
2022-05-29 00:49:36.173862 -- Deleted: 0 files, 0 directories
2022-05-29 00:49:36.174239 -- Wrote export report to /Users/Shared/Pictures/Logs/colibri.csv
2022-05-29 00:49:36.174672 -- Writing export database changes back to X/.osxphotos_export.db

RhetTbull · 2022-05-29T00:25:41Z

As best as I can tell, this indicates osxphotos is working as expected. When you deleted the original, it had been "reserved" in the database with the first UUID so any subsequent file with the same name (which will have a different UUID), will get a new file name with (1), (2), and so on. The only issue is the Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126.JPG (1/4) message which is not clear. That message is printed before the actual target name is known (it's printed using the rendered filename template assuming that target file is available). I'll take a look and see if the message can be printed after the target file name is known so it instead says Exporting IMG_2126.JPG (IMG_2126.JPG) as IMG_2126 (1).JPG (1/4), etc.

I've tried to re-create the issue of osxphotos entering a loop and so far I'm not able to.

oPromessa · 2022-05-29T00:33:11Z

Yes, I believe with 0.50 version the loop no longer occurs.

A final run tonight will take place with the fixed entries on my active database and will let you know the result tomorrow.

RhetTbull · 2022-05-29T02:06:19Z

v0.50.1 improves the verbose message to be more clear. It now does the following when the file already exists for a different UUID and a (1) needs to be added:

Exporting AAF035.jpg (2DFD33F1-A5D8-486F-A3A9-98C07995535A.jpeg) (17/22)
Exported AAF035.jpg to /Users/rhet/Desktop/export/AAF035 (1).jpg
Exported new file /Users/rhet/Desktop/export/AAF035 (1).jpg

Also, in v0.50.1 I've added two new exportdb commands that will be helpful when needed to cleanup the database:

  --delete-uuid UUID           Delete all data associated with UUID from the
                               database.
  --delete-file FILE_PATH      Delete all data associated with FILE_PATH from
                               the database; does not delete the actual
                               exported file if it exists, only the data in
                               the database.

So for your example, you'd do something like this:

osxphotos exportdb --path/to/exportdb --export-dir /path/to/export-dir --delete-file /path/to/export/IMG_2126.JPG

oPromessa · 2022-05-29T21:42:38Z

Yes, I believe with 0.50 version the loop no longer occurs.

A final run tonight will take place with the fixed entries on my active database and will let you know the result tomorrow.

Th final run on IMG_2126 with the deleted exported file and deleting the exportdb entries worked fine! Thanks

RhetTbull added the bug Something isn't working label May 23, 2022

RhetTbull added a commit that referenced this issue May 24, 2022

Bug fix, #695

e9cc6ce

RhetTbull added a commit that referenced this issue May 24, 2022

Bug fix, #695

7926c8d

oPromessa closed this as completed Jun 3, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Video keeps being exported on every run even with seemly no changes. Adding suffix "(1)" and deleting the origin file in cycle. #695

Video keeps being exported on every run even with seemly no changes. Adding suffix "(1)" and deleting the origin file in cycle. #695

oPromessa commented May 19, 2022 •

edited

RhetTbull commented May 19, 2022

oPromessa commented May 21, 2022 •

edited

oPromessa commented May 21, 2022

oPromessa commented May 21, 2022

RhetTbull commented May 21, 2022

RhetTbull commented May 21, 2022 •

edited

RhetTbull commented May 21, 2022

oPromessa commented May 21, 2022 •

edited

RhetTbull commented May 21, 2022

oPromessa commented May 21, 2022

RhetTbull commented May 21, 2022

oPromessa commented May 21, 2022 •

edited

RhetTbull commented May 21, 2022

RhetTbull commented May 21, 2022

oPromessa commented May 23, 2022 •

edited

RhetTbull commented May 23, 2022

RhetTbull commented May 23, 2022

oPromessa commented May 23, 2022 •

edited

RhetTbull commented May 23, 2022

RhetTbull commented May 24, 2022

RhetTbull commented May 24, 2022

RhetTbull commented May 24, 2022

RhetTbull commented May 24, 2022

oPromessa commented May 27, 2022 •

edited

RhetTbull commented May 27, 2022

oPromessa commented May 27, 2022 •

edited

RhetTbull commented May 27, 2022

oPromessa commented May 28, 2022 •

edited

RhetTbull commented May 28, 2022

oPromessa commented May 28, 2022

RhetTbull commented May 29, 2022

oPromessa commented May 29, 2022

RhetTbull commented May 29, 2022

oPromessa commented May 29, 2022

Video keeps being exported on every run even with seemly no changes. Adding suffix "(1)" and deleting the origin file in cycle. #695

Video keeps being exported on every run even with seemly no changes. Adding suffix "(1)" and deleting the origin file in cycle. #695

Comments

oPromessa commented May 19, 2022 • edited

RhetTbull commented May 19, 2022

oPromessa commented May 21, 2022 • edited

oPromessa commented May 21, 2022

oPromessa commented May 21, 2022

RhetTbull commented May 21, 2022

RhetTbull commented May 21, 2022 • edited

RhetTbull commented May 21, 2022

oPromessa commented May 21, 2022 • edited

RhetTbull commented May 21, 2022

oPromessa commented May 21, 2022

RUN 1

RUN 2

RhetTbull commented May 21, 2022

oPromessa commented May 21, 2022 • edited

RhetTbull commented May 21, 2022

RhetTbull commented May 21, 2022

oPromessa commented May 23, 2022 • edited

RhetTbull commented May 23, 2022

RhetTbull commented May 23, 2022

oPromessa commented May 23, 2022 • edited

RhetTbull commented May 23, 2022

RhetTbull commented May 24, 2022

RhetTbull commented May 24, 2022

RhetTbull commented May 24, 2022

RhetTbull commented May 24, 2022

oPromessa commented May 27, 2022 • edited

RhetTbull commented May 27, 2022

oPromessa commented May 27, 2022 • edited

RhetTbull commented May 27, 2022

oPromessa commented May 28, 2022 • edited

RhetTbull commented May 28, 2022

oPromessa commented May 28, 2022

1st export. Exports file. OK

2nd export. Skips file. OK

Delete file and re/upload in Photos. 3rd export. Exports "(1)" file. and Delete original file.

4th export. Indicates to export "IMG_2126" as "IMG_2126" but in reality the existing file is kept "(1)".

I've then added a new file named IMG_2126 to the same album. 5th export. Skips "(1)" and exports/creates "(2)". OK.

6th Re/ran export. Skips "(1)" and "(2)" but message still refers to original file. OK

RhetTbull commented May 29, 2022

oPromessa commented May 29, 2022

RhetTbull commented May 29, 2022

oPromessa commented May 29, 2022

oPromessa commented May 19, 2022 •

edited

oPromessa commented May 21, 2022 •

edited

RhetTbull commented May 21, 2022 •

edited

oPromessa commented May 21, 2022 •

edited

oPromessa commented May 21, 2022 •

edited

oPromessa commented May 23, 2022 •

edited

oPromessa commented May 23, 2022 •

edited

oPromessa commented May 27, 2022 •

edited

oPromessa commented May 27, 2022 •

edited

oPromessa commented May 28, 2022 •

edited