RhetTbull / osxphotos

Python app to work with pictures and associated metadata from Apple Photos on macOS. Also includes a package to provide programmatic access to the Photos library, pictures, and metadata.
MIT License
2.17k stars 100 forks source link

osxphotos export keeps exporting/updating some unchanged files! #654

Closed oPromessa closed 4 months ago

oPromessa commented 2 years ago

Again, GREEAAATTT JOB!!!!

Describe the bug

To Reproduce Steps to reproduce the behavior:

  1. What's the full command line you used with osxphotos?
    • Command line
      osxphotos export /Volumes/photo-1/(...) --exportdb ./.osxphotos_export.db --load-config ./colibri.toml
    • Contents of colibri.toml
      [export]
      cleanup = true
      db = "/Users/Shared/Pictures/iPhoto Shared Library.photoslibrary"
      description_template = "Album:{album,}{newline}Description:{descr,}"
      directory = "{album[/,.|:,.]}"
      #dry_run = true
      exiftool = true
      exiftool_merge_keywords = true
      exiftool_merge_persons = true
      keyword_template = [ "{keyword}", "{label}", "{searchinfo.activity?activity:{searchinfo.activity},}", "{searchinfo.venue_type?venue_type:{searchinfo.venue_type},}", ]
      not_hidden = true
      ramdb = true
      report = "/Users/Shared/Pictures/Logs/colibri.csv"
      retry = 2
      skip_bursts = true
      skip_live = true
      skip_original_if_edited = true
      strip = true
      timestamp = true
      touch_file = true
      update = true
      verbose = true
  2. What was the error output?
    • N/A

Expected behavior

Analysis

  1. Output of several runs. Total number of pics to export 84818 but then you have around 600-1000 always being updated.
    1305963 [notice] --- Start Sun 6 Mar 2022 16:28:00 WET 
    2022-03-06 16:28:03.322688 -- osxphotos version 0.47.4
         Exporting 84818 photos to /Volumes/photo-1/(...)...
         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
         Deleted: 1 file, 0 directories
    1487694 [notice] --- End Sun 6 Mar 2022 20:10:18 WET 
    1487695 [notice] --- Start Mon 7 Mar 2022 13:32:00 WET
    2022-03-07 13:32:02.412506 -- osxphotos version 0.47.4
         Exporting 84818 photos to /Volumes/photo-1/(...)...
         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
         Deleted: 1 file, 0 directories
    1669397 [notice] --- End Mon 7 Mar 2022 16:58:17 WET
    1669536 [notice] --- Start Mon 7 Mar 2022 21:35:00 WET
    2022-03-07 21:35:01.873164 -- osxphotos version 0.47.4
         Exporting 84818 photos to /Volumes/photo-1/(...)...
         Processed: 84818 photos, exported: 1, updated: 696, skipped: 85495, updated EXIF data: 697, missing: 0, error: 0, touched date: 723
         Elapsed time: 3:14:08
         Deleted: 1 file, 0 directories
    1850644 [notice] --- End Tue 8 Mar 2022 00:58:02 WET 
  2. filtering for pic 1969-11-09-1 on the csv files from the "last" and the "before last" run produce the same output: exported, updated, exif_updated
    2022-03-08 00:21:30.945869 -- Exporting 1969-11-09-1.jpg (1969-11-09-1.jpg) as 1969-11-09-1.jpg (72331/84818)
    2022-03-08 00:21:30.982339 -- Writing metadata with exiftool for 1969-11-09-1.jpg
    2022-03-08 00:21:31.168031 -- Exported updated file /Volumes/photo-1/(...)/1969-11-09-1.jpg
    2022-03-08 00:21:31.168633 -- Touched date on file /Volumes/photo-1/(...)/1969-11-09-1.jpg
    $ mlr -C --ojson --icsv grep 1969-11-09-1  colibri.csv
    [
    {
    "filename": "/Volumes/photo-1/(...)/1969-11-09-1.jpg",
    "exported": 1,
    "new": 0,
    "updated": 1,
    "skipped": 0,
    "exif_updated": 0,
    "touched": 1,
    (...)
    },
    {
    "filename": "/Volumes/photo-1/Family.Photos/1969-01-05 1969-72 Digitalizadas (Album 2)/1969-11-09-1.jpg",
    "exported": 0,
    "new": 0,
    "updated": 0,
    "skipped": 0,
    "exif_updated": 1,
    "touched": 0,
    (...)
  3. Selecting the export_data from db I get the same output for bnoth runs.
    • 1 = before last run
    • 2 = last run
      sqlite> .output 2.export
      sqlite> select *  from export_data
      ...> where filepath_normalized like "%1969-11-09-1%";
      diff -s 1.export 2.export
      Files 1.export and 2.export are identical
  4. Selecting the photoinfo from the db I also get the exact same output for both runs. last and before last.
    .output 1.phinfo
    select photoinfo.*  from export_data, photoinfo
    where photoinfo.uuid = export_data.uuid
    and filepath_normalized like "%1969-11-09-1%";
    $ cut -f 3 -d "|"  1.phinfo > 1.json
    $ cat 1.json
    {"albums": ["(...)"], "burst": false, "comments": [], "date": "1969-11-09T13:15:00+01:00", "date_modified": null, "description": null, "exif": {"aperture": null, "bit_rate": null, "camera_make": null, "camera_model": null, "codec": null, "duration": null, "exposure_bias": null, "flash_fired": false, "focal_length": null, "fps": null, "iso": null
    (...)
    $ diff -s 1.json 2.json
    Files 1.json and 2.json are identical
    (venv)
    $ md5 1.json 2.json
    MD5 (1.json) = 47582be389f25116a1b317ddefcca67b
    MD5 (2.json) = 47582be389f25116a1b317ddefcca67b

Desktop (please complete the following information):

Additional context Add any other context about the problem here.

RhetTbull commented 2 years ago

Great debug info -- thanks! My first guess would've been photoinfo was changing (labels are sometimes re-computed by Photos) but your step 6 above shows that's not the case.

Does the file 1969-11-09-1.jpg always get re-exported? If so, that'll make tracking this down easier.

How familiar are you with the python debugger? I've built debugger access into the current github version (not yet released) so if you're comfortable trying a bleeding edge feature, you can use your clone of osxphotos, do a git pull, then try the following:

OSXPHOTOS_IS_TESTING=1 python3 -m osxphotos export /Volumes/photo-1/(...) --exportdb ./.osxphotos_export.db --load-config ./colibri.toml --name "1969-11-09-1" --breakpoint osxphotos.photoexporter.PhotoExporter._should_update_photo

That will drop you into the debugger when osxphotos is about to call the _should_update_photo method to determine if the photo should be updated. Hit s to step into the the _should_update_photo then n to step through each of the tests to see which test is returning True. Here's an example where I added a keyword forcing the exiftool check to return True:

⇣41% [I] ➜ OSXPHOTOS_IS_TESTING=1 python3 -m osxphotos export ~/Desktop/export --exiftool --touch-file --update --name 3092 --breakpoint osxphotos.photoexporter.PhotoExporter._should_update_photo
Breakpoint added for osxphotos.photoexporter.PhotoExporter._should_update_photo
Using last opened Photos library: /Users/rhet/Pictures/Test-10.15.7.photoslibrary
Exporting 1 photo to /Users/rhet/Desktop/export...
[16] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/debug.py(48)debug_breakpoint()
-> return wrapped(*args, **kwargs)
(Pdb++) s
--Call--
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(681)_should_update_photo()
-> def _should_update_photo(
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(685)_should_update_photo()
-> export_db = options.export_db
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(686)_should_update_photo()
-> fileutil = options.fileutil
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(688)_should_update_photo()
-> file_record = export_db.get_file_record(dest)
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(690)_should_update_photo()
-> if not file_record:
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(694)_should_update_photo()
-> if options.export_as_hardlink and not dest.samefile(src):
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(698)_should_update_photo()
-> if not options.export_as_hardlink and dest.samefile(src):
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(702)_should_update_photo()
-> if not options.ignore_signature and not fileutil.cmp_file_sig(
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(703)_should_update_photo()
-> dest, file_record.dest_sig
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(702)_should_update_photo()
-> if not options.ignore_signature and not fileutil.cmp_file_sig(
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(708)_should_update_photo()
-> if file_record.export_options != options.bit_flags:
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(715)_should_update_photo()
-> if options.exiftool:
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(716)_should_update_photo()
-> current_exifdata = self._exiftool_json_sidecar(options=options)
(Pdb++) n
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(717)_should_update_photo()
-> return current_exifdata != file_record.exifdata
(Pdb++) n
--Return--
[17] > /Users/rhet/Dropbox/Code/osxphotos/osxphotos/photoexporter.py(717)_should_update_photo()->True

Notice that in step [17], _should_update_photo returned True and the test immediately preceding was return current_exifdata != file_record.exifdata showing the new exifdata differed from the old exifdata.

Update: You can then hit c to continue the program.

oPromessa commented 2 years ago
oPromessa commented 2 years ago
oPromessa commented 2 years ago
RhetTbull commented 2 years ago

A few thoughts/questions:

  1. What's the date on the photo in Photos? Is it possible there's an invalid date that is causing an overflow error on the NAS when touching the file? Does the date of the exported file on the NAS match the date in Photos?
  2. What's the result of running os.stat repeatedly on the file on the NAS? (e.g. does it always give the same result?)
  3. What's the output of the following command?

osxphotos exportdb ./.osxphotos_export.db --sql "select src_mtime, dest_mtime from export_data where filepath_normalized like '%1969-11-09-1%'"

oPromessa commented 2 years ago

A few thoughts/questions:

  1. What's the date on the photo in Photos? Is it possible there's an invalid date that is causing an overflow error on the NAS when touching the file? Does the date of the exported file on the NAS match the date in Photos?
    1969-11-09 13:15:00 (format YYYY-MM-DD HH:MM:SS)
  2. What's the result of running os.stat repeatedly on the file on the NAS? (e.g. does it always give the same result?)
    • Here I thought the negative in st_mtime was coming from the NAS (f2) but it's coming from the MAC disk (f1)!
      
      >> import os
      >> f1 = "/Volumes/photo-1/export/1969-11-09-1.jpg"

os.stat(f1) os.stat_result(st_mode=33216, st_ino=2793585, st_dev=922750909, st_nlink=1, st_uid=501, st_gid=20, st_size=73826, st_atime=1646773217, st_mtime=1646773217, st_ctime=1646773217) os.stat(f1) os.stat_result(st_mode=33216, st_ino=2793585, st_dev=922750909, st_nlink=1, st_uid=501, st_gid=20, st_size=73826, st_atime=1646773217, st_mtime=1646773217, st_ctime=1646773217) (...) os.stat(f1) os.stat_result(st_mode=33216, st_ino=2793585, st_dev=922750909, st_nlink=1, st_uid=501, st_gid=20, st_size=73826, st_atime=1646773217, st_mtime=1646773217, st_ctime=1646773217)

>>> f2 = "/Users/MSP/Documents/GitHub/osxphotos/export/1969-11-09-1.jpg"
>>> os.stat(f2)
os.stat_result(st_mode=33188, st_ino=19254388, st_dev=16777223, st_nlink=1, st_uid=501, st_gid=20, st_size=73826, st_atime=1646817645, st_mtime=-4535100, st_ctime=1646773275)
>>> os.stat(f2)
os.stat_result(st_mode=33188, st_ino=19254388, st_dev=16777223, st_nlink=1, st_uid=501, st_gid=20, st_size=73826, st_atime=1646817645, st_mtime=-4535100, st_ctime=1646773275)
>>> os.stat(f2)
os.stat_result(st_mode=33188, st_ino=19254388, st_dev=16777223, st_nlink=1, st_uid=501, st_gid=20, st_size=73826, st_atime=1646817645, st_mtime=-4535100, st_ctime=1646773275)
>>> os.stat(f2)
os.stat_result(st_mode=33188, st_ino=19254388, st_dev=16777223, st_nlink=1, st_uid=501, st_gid=20, st_size=73826, st_atime=1646817645, st_mtime=-4535100, st_ctime=1646773275)
(...)
>>> 
  1. What's the output of the following command?

osxphotos exportdb ./.osxphotos_export.db --sql "select src_mtime, dest_mtime from export_data where filepath_normalized like '%1969-11-09-1%'"

  • On the local MAC disk
    $ osxphotos exportdb ./.osxphotos_export.db --sql "select src_mtime, dest_mtime from export_data where filepath_normalized like '%1969-11-09-1%'"
    (1472486297.0, -4535100.0)
  • On the NAS Disk:
    $ osxphotos exportdb ./.osxphotos_export.db --sql "select src_mtime, dest_mtime from export_data where filepath_normalized like '%1969-11-09-1%'"
    (1472486297.0, 1646773217.0)
    1. Additionally see the output of exit tool for dates on the three fies: 5.
  • The original one: /Users/MSP/Pictures
  • The exported to the NAS: /Volumes/photo-1/
  • The exported locally: /Users/MSP/Documents/GitHub/osxphotos/export
$ alias exifviewdates='exiftool -a -G1 -s -api QuickTimeUTC=1 -time:all -api RequestAll=2'
$  exifviewdates "/Users/MSP/Pictures/(...)/1969-11-09-1.jpg"
[ExifTool]      Now                             : 2022:03:09 09:16:34+00:00
[System]        FileModifyDate                  : 2016:08:29 16:58:17+01:00
[System]        FileAccessDate                  : 2021:12:24 19:00:57+00:00
[System]        FileInodeChangeDate             : 2021:12:24 19:00:57+00:00
[MacOS]         FileCreateDate                  : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemContentCreationDate       : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemContentCreationDate_Ranking: 2016:08:29 01:00:00+01:00
[MacOS]         MDItemContentModificationDate   : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemContentModificationDate_Ranking: 2016:08:29 01:00:00+01:00
[MacOS]         MDItemDateAdded                 : 2021:12:24 19:00:57+00:00
[MacOS]         MDItemDateAdded_Ranking         : 2021:12:24 00:00:00+00:00
[MacOS]         MDItemFSContentChangeDate       : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemFSCreationDate            : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemInterestingDate_Ranking   : 2016:08:29 01:00:00+01:00
[IFD0]          ModifyDate                      : 1969:11:09 13:15:00
[ExifIFD]       DateTimeOriginal                : 1969:11:09 13:15:00
[ExifIFD]       CreateDate                      : 1969:11:09 13:15:00
$ exifviewdates /Volumes/photo-1/export/1969-11-09-1.jpg 
[ExifTool]      Now                             : 2022:03:09 09:17:50+00:00
[System]        FileModifyDate                  : 2022:03:08 21:00:17+00:00
[System]        FileAccessDate                  : 2022:03:08 21:00:17+00:00
[System]        FileInodeChangeDate             : 2022:03:08 21:00:17+00:00
[MacOS]         FileCreateDate                  : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemFSContentChangeDate       : 2022:03:08 21:00:17+00:00
[MacOS]         MDItemFSCreationDate            : 1970:01:01 00:00:00+00:00
[IFD0]          ModifyDate                      : 1969:11:09 13:15:00
[ExifIFD]       DateTimeOriginal                : 1969:11:09 13:15:00
[ExifIFD]       CreateDate                      : 1969:11:09 13:15:00
[ExifIFD]       OffsetTimeOriginal              : +01:00
[IPTC]          DateCreated                     : 1969:11:09
[IPTC]          TimeCreated                     : 13:15:00+01:00
[Composite]     SubSecDateTimeOriginal          : 1969:11:09 13:15:00+01:00
[Composite]     DateTimeCreated                 : 1969:11:09 13:15:00+01:00
$ exifviewdates /Users/MSP/Documents/GitHub/osxphotos/export/1969-11-09-1.jpg 
[ExifTool]      Now                             : 2022:03:09 09:18:33+00:00
[System]        FileModifyDate                  : 1969:11:09 13:15:00+01:00
[System]        FileAccessDate                  : 2022:03:09 09:18:32+00:00
[System]        FileInodeChangeDate             : 2022:03:08 21:01:15+00:00
[MacOS]         FileCreateDate                  : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemContentCreationDate       : 1969:11:09 13:15:00+01:00
[MacOS]         MDItemContentCreationDate_Ranking: 
[MacOS]         MDItemContentModificationDate   : 1969:11:09 13:15:00+01:00
[MacOS]         MDItemDateAdded                 : 2022:03:08 21:01:15+00:00
[MacOS]         MDItemDateAdded_Ranking         : 2022:03:08 00:00:00+00:00
[MacOS]         MDItemFSContentChangeDate       : 1969:11:09 13:15:00+01:00
[MacOS]         MDItemFSCreationDate            : 2016:08:29 16:58:17+01:00
[MacOS]         MDItemInterestingDate_Ranking   : 
[IFD0]          ModifyDate                      : 1969:11:09 13:15:00
[ExifIFD]       DateTimeOriginal                : 1969:11:09 13:15:00
[ExifIFD]       CreateDate                      : 1969:11:09 13:15:00
[ExifIFD]       OffsetTimeOriginal              : +01:00
[IPTC]          DateCreated                     : 1969:11:09
[IPTC]          TimeCreated                     : 13:15:00+01:00
[Composite]     SubSecDateTimeOriginal          : 1969:11:09 13:15:00+01:00
[Composite]     DateTimeCreated                 : 1969:11:09 13:15:00+01:00
  1. And the output of ls -lafor all 3 files also
    638354 144 -rw-r--r--@ 1 MSP  wheel    69K 29 Aug  2016 /Users/MSP/Pictures/(...)/1969-11-09-1.jpg
    2793585 146 -rwx------@ 1 MSP  staff    72K  8 Mar 21:00 /Volumes/photo-1/export/1969-11-09-1.jpg
    19254388 152 -rw-r--r--@ 1 MSP  staff    72K  9 Nov  1969 /Users/MSP/Documents/GitHub/osxphotos/export/1969-11-09-1.jpg
RhetTbull commented 2 years ago

Here I thought the negative in st_mtime was coming from the NAS (f2) but it's coming from the MAC disk (f1)!

unix dates start on 1-Jan-1970 and since this photo is taken from 1969, that's expected.

This is interesting:

On the NAS, the dates aren't getting set correctly for this pre-1970 date:

[System]        FileModifyDate                  : 2022:03:08 21:00:17+00:00     <---- should be 1969
[MacOS]         MDItemFSCreationDate            : 1970:01:01 00:00:00+00:00      <----- should be 1969

On the Mac:

[System]        FileModifyDate                  : 1969:11:09 13:15:00+01:00
[MacOS]         MDItemContentCreationDate       : 1969:11:09 13:15:00+01:00

Do all the files that keep getting re-exported have a date from before 1970? It looks like the NAS is not correctly setting the date for this file. osxphotos is using os.utime which is the system method that touch uses.

What happens if you try to use touch on the file? That is: touch /Volumes/photo-1/export/1969-11-09-1.jpg

Does it successfully update the file date/time?

oPromessa commented 2 years ago

Do all the files that keep getting re-exported have a date from before 1970? It looks like the NAS is not correctly setting the date for this file. osxphotos is using os.utime which is the system method that touch uses.

  • Yes. All pre-1970 files get re-exported. A few after 1970 (not always the same... so I'll look into them later).

What happens if you try to use touch on the file? That is: touch /Volumes/photo-1/export/1969-11-09-1.jpg

Does it successfully update the file date/time?

  • Touch seems to work and being able to set date/time prior to 1970.
    $ touch -d 1969-11-09T13:15:00 1969-11-09-1.jpg ;
    $ ls -lisahG -T 1969-11-09-1.jpg 
    2801415 146 -rwx------  1 MSP  staff    73K  9 Nov 13:15:00 1969 1969-11-09-1.jpg
  • os.stat produces the negative number... but it seems it is understood, at least by datetime.datetime.fromtimestamp() correctly. Still in the debugger...
    (Pdb++) f1
    PosixPath('/Volumes/photo-1/export/1969-01-05 1969-72 Digitalizadas (Album 2)/1969-11-09-1.jpg')
    (Pdb++) cls._sig(os.stat(f1))
    (32768, 74328, -4535100)
    (Pdb++) datetime.datetime.fromtimestamp(-4535100)
    datetime.datetime(1969, 11, 9, 13, 15)
oPromessa commented 2 years ago

.

RhetTbull commented 2 years ago

What I believe it seems to be happening: a subsequent run with os.stat gets mtime = exported time (s1)

I don't think this can happen in the code. See below -- the files are touched then after that call to _touch_files, the destination signature is updated in the database with a call to fileutil.file_sig:

https://github.com/RhetTbull/osxphotos/blob/2e501e6a9b517f8c520509053b3ffcd9d57f139f/osxphotos/photoexporter.py#L1158-L1179

Here's the code for _touch_files:

https://github.com/RhetTbull/osxphotos/blob/2e501e6a9b517f8c520509053b3ffcd9d57f139f/osxphotos/photoexporter.py#L600-L617

And here's file_sig which is calling os.stat on the destination file: https://github.com/RhetTbull/osxphotos/blob/2e501e6a9b517f8c520509053b3ffcd9d57f139f/osxphotos/fileutil.py#L195-L198

RhetTbull commented 2 years ago

Will test out also os.utime to double check its behaviour.

This looks like utime is not correctly setting the modification time on the NAS. If you can confirm that, one possible work around is to have a fallback to make subprocess call directly to touch. This would be definitely be much slower so would only want to use when needed.

oPromessa commented 2 years ago

The plot thickens!!! really weird!!!

RhetTbull commented 2 years ago

So the os.utime has some issue updating a remote file (via smb protocol) with dates prior to 1970!!!

I think you're right that this appears to be the problem.

oPromessa commented 2 years ago

Opened up a ticket with Synology. Let's see!

RhetTbull commented 2 years ago

I added a fix for this. It's a bit of a hack but should work: after using utime to touch the file time, the code will do a stat to verify the utime was successful. If not successful, it'll do a subprocess call to /usr/bin/touch to set the time. I was concerned the extra stat would slow things down but in my testing when exporting across the network, it added less than a millisecond. Try a git pull and see if this new version fixes the problem. (I've not yet created a new release)

https://github.com/RhetTbull/osxphotos/blob/8731e7d5bcae3e010956b4078c27045a8f2f6b4e/osxphotos/fileutil.py#L152-L164

oPromessa commented 2 years ago

I'm just concerned the end/result will be the same as the same issue occurs with /usr/bin/touch

It would have to be the touch command executed remotely on the NAS.

The hack I was thinking was to use .osxphotos_db to find files < 1970 and run touch directly in the NAS to make the change permanent!

I've tested if and it seems to work.

Of course is a mess of a hack. Or maybe I could use the --post-commandoption to run a rsh (remote shell) command.

2022-03-10 15:53:19.592341 -- Exporting 1 photo to /Volumes/photo-1/export...
2022-03-10 15:53:19.612506 -- 2022-03-10 15:53:19.612396 -- Exporting 1969-11-09-1.jpg (1969-11-09-1.jpg) as 1969-11-09-1.jpg (1/1)
[16] > /Users/MSP/Documents/GitHub/osxphotos/osxphotos/debug.py(48)debug_breakpoint()
-> return wrapped(*args, **kwargs)
(...)
(Pdb++) n
[18] > /Users/MSP/Documents/GitHub/osxphotos/osxphotos/fileutil.py(193)cmp_file_sig()
-> return s1 == s2
(Pdb++) s1
(32768, 74328, -4535100)
(Pdb++) s2
(32768, 74328, -4535100)
(Pdb++) s
--Return--
[18] > /Users/MSP/Documents/GitHub/osxphotos/osxphotos/fileutil.py(193)cmp_file_sig()->True
-> return s1 == s2
(Pdb++) c
2022-03-10 15:53:32.852227 -- 2022-03-10 15:53:32.851954 -- Skipped up to date file /Volumes/photo-1/export/1969-01-05 1969-72 Digitalizadas (Album 2)/1969-11-09-1.jpg
2022-03-10 15:53:32.853696 -- Processed: 1 photo, exported: 0, updated: 0, skipped: 1, updated EXIF data: 0, missing: 0, error: 0, touched date: 0
2022-03-10 15:53:32.854218 -- Elapsed time: 0:00:13
RhetTbull commented 2 years ago

but it then reverts back.

Ahh...I misunderstand your notes above then--I thought touch worked but utime didn't.

I'll take those changes out then as there's no added benefit.

I would use the --post-function instead of --post-command because you'll get the PhotoInfo object for the photo and from that you can grab the created time to run the rsh touch

RhetTbull commented 2 years ago

For your post function, there's an example here: https://github.com/RhetTbull/osxphotos/blob/master/examples/post_function.py

You could do something like this in your post function:

def post_function(
    photo: PhotoInfo, results: ExportResults, verbose: callable, **kwargs
):
    for filename in results.exported:
        if photo.date.year < 1970:
            touch_date = photo.date.strftime("%Y%m%d%H%M.%S") 
            # not sure what rsh command will be
            subprocess.run(f"rsh... touch {touch_date}")
RhetTbull commented 2 years ago

Any luck with this issue? As I recall, it was an issue with your NAS not osxphotos?

oPromessa commented 2 years ago

Thanks for the reminder. I've been living with this for some time now and was about to accept it.

But with your reminder I did some digging up...

As we know he have two angles on this:

  1. Pics after 1970. re-exported with date taken after 1970 seems to be dropping. Will run one more cycle.
    • Possibly related with metadata information (faces, categories, etc) Photos does/updates with classifying pics. On another thread we've debated on how to confirm such changes. Will go that after...
  2. Pics taken before 1970! Related with epoch.
    • The issue is that touch command from MAC (where osxphotos runs) into a Synology NAS server does not really update the mtime of the file.
    • Solution: Login directly on the NAS and execute the touch -d command directly on the file.
    • Side note: running remotely from a "post.py" function directly from osxphotos has it challenges in terms of opening a secure connection via SSH into the NAS... so for now I'll be doing it manually.
    • It was still failing because a 1 hour out-of-sync occurred from MAC to NAS due to odd timezone settings (still to investigate!). Although MAC and NAS are on the same timezone.
    • One I've accounted for that difference within the touch -d command I ran locally on NAS, osxphotos no longer updates the file.
    • Only did one test file for now... will have to run a more complete thorough test.

So, I believe good news...

oPromessa commented 2 years ago

So I was expecting this to work on other files.

To allow cmp_file_sig to do the correct comparison and mtime would be the same for file and record db. But found two issues:

https://github.com/RhetTbull/osxphotos/blob/d8802368fcf39a704e545327b4562ca1c4c7a439/osxphotos/fileutil.py#L177-L193

But now I found on some files that the mtime in the exportdb is incorrect for my test files.It is not taking the actually

On the debug I have for "sem título-2.jpg" the difference form the database and the os.stat:

739     
740  ->         if not options.ignore_signature and not fileutil.cmp_file_sig(
741                 dest, file_record.dest_sig
742             ):
743                 # destination file doesn't match what was last exported
744                 return ShouldUpdate.DEST_SIG_DIFFERENT
745     
(Pdb) dest
PosixPath('/Volumes/photo-1/Y/(...)/Sem título-2.jpg')
(Pdb) file_record.dest_sig
(32768, 787087, 1658667844)
(Pdb) os.stat(dest).st_mtime
-11955225.0

So I did a stat and an exiftool on the original files and some of the date entries are empty or void. that may scare things up a bit.

$ exif 1966-12-25-1.jpg Sem\ título-2.jpg  2>/dev/null
Directory|FileName|Make%MajorBrand|DateTimeOriginal|FileModifyDate|CreateDate|Keywords|Subject|ImageOrientation|Caption-Abstract|ModifyDate|Description|QuickTimeCreateDate|QuickTimeModifyDate|KeysCreationDate|RegionType|RegionName|
.|1966-12-25-1.jpg|-%-|1967:01:15 14:04:40|2015:09:01 12:17:03|1967:01:15 14:04:40|-|-|-|-|1967:01:15 14:04:40|-|-|-|-|-|-|
.|Sem título-2.jpg|-%-|1969:08:15 16:06:15|0000:00:00 00:00:00|1969:08:15 16:06:15|(...)|(...)|-|-|1969:08:15 16:06:15|-|-|-|-|-|-|

$ stat 1966-12-25-1.jpg Sem\ título-2.jpg 
16777223 638194 -rw-r--r-- 1 MSP wheel 0 120681 "Jul 24 13:44:58 2022" "Sep  1 12:17:03 2015" "Jul 24 13:44:58 2022" "Sep  1 12:17:03 2015" 4096 240 0 (...)/1966-12-25-1.jpg
16777223 603359 -rw-r--r-- 1 MSP wheel 0 786126 "Dec 24 17:45:28 2021" "Jan  1 01:00:00 1970" "Dec 24 17:45:28 2021" "Jan  1 01:00:00 1970" 4096 1536 0 (...) Sem título-2.jpg

I am going to expand my test cases and check the full flow:

Sorry to bother you with is... I'm using this thread to collect my thoughts!Possibly shoudn't! Will be doing more investigation on my end prior to my next post!

RhetTbull commented 2 years ago

It's odd you're getting a different result with os.stat and the database. The NAS must be doing something to change the time (or not propagate the changes made by osxphotos)The exportdb record is set with the following code:

https://github.com/RhetTbull/osxphotos/blob/79e4b333e93c1202ab11cbb1d3fbef9b3cd8bd79/osxphotos/export_db_utils.py#L86-L93

The file_sig method referenced in this code in turn uses os.stat to get the signature but converts mtime to int because the Mac doesn't always preserve the fractional portion of mtime when copying. However, the internal compare function (cmp_file_sig) also does this conversion to that shouldn't be the issue

https://github.com/RhetTbull/osxphotos/blob/84a96bd4d01d1fbe621a49a1c64a47d2dccff52b/osxphotos/fileutil.py#L195-L198

https://github.com/RhetTbull/osxphotos/blob/84a96bd4d01d1fbe621a49a1c64a47d2dccff52b/osxphotos/fileutil.py#L243-L250

https://github.com/RhetTbull/osxphotos/blob/84a96bd4d01d1fbe621a49a1c64a47d2dccff52b/osxphotos/fileutil.py#L176-L193

I wrap the os.stat and other os specific functions in the FileUtil class because this allows osxphotos to easily do dry-run mode using dependency injection with no other changes to the code (inject a no-op version of the FileUtil class when running --dry-run).

oPromessa commented 1 year ago

Just an update. It seems the latest versions of Synology NAS (I'm currently at 7.1.1-42962 Update 5) and connected via SMB (version 3) now correctly recognizes setting the files' date/time prior to 1970-01-01.

So osxphotos stopped touching such files.

Will keep monitoring to see if we can close this one!