Working Theory: Rate limit metadata fetching about icloud-photos-sync

[steilerDev]

Is this happening consistently? - Can you try with docker:latest instead of nightly?

[player666au]

Yes, this has happened every time. 10 or more times.
I started with docker:latest and moved on to nightly, and then node installation in the lxc container.

[player666au]

In case this helps, the following is a snippet from the docker-compose.yml

version: '3.7'
services:
photos-sync:
image: steilerdev/icloud-photos-sync:nightly
container_name: photos-sync
user: 2002:2002
environment:
APPLE_ID_USER: ""
APPLE_ID_PWD: ""
TZ: "Australia/Sydney"
SCHEDULE: "* 2 * * *"
REMOTE_DELETE: "true"
ENABLE_CRASH_REPORTING: "true"
volumes:
- /q/media/pix/photos:/opt/icloud-photos-library

[AgainstGreaterOdds]

I have the same issue with slightly different error code:

Experienced fatal error at 13/02/2023, 13:20:43: SyncError (FATAL): Sync failed caused by iCloudError (FATAL): Unable to fetch records for album 'All photos' caused by getaddrinfo ENOTFOUND p101-ckdatabasews.icloud.com (Error Code: f265381c-ee58-42f6-b26f-d546708345ba) ---------------------------------------------

Is this related with the Shared iCloud Library? (I have it on)

[steilerDev]

@AgainstGreaterOdds Shared Photo Library is currently not yet supported - the tool will always only sync your personal account and this might be the reason for the error.

However I think both - @player666au 's socket hangup error and your ENOTFOUND are both related to the iCloud API and not necessarily a bug in this sync program's logic...unless you have a reliable way to reproduce and debug this, I'll have a hard time figuring out what's happening here, sorry! :/

PS: The error code is always a unique string

[AgainstGreaterOdds]

Thanks for the reply, @steilerDev. I will wait until the iCloud Shared Library is supported. Great work so far!

[steilerDev]

@player666au I worked on this a little bit, could you please pull the latest nightly build, enable debug logging and crash reporting and report back?

[player666au]

Sorry, but things do not look any better:

---

Welcome to icloud-photos-sync, v.v1.0.2-beta!
Made with <3 by steilerDev

Authenticating user...
Device trusted
Sign in successful!
iCloud connection established!

Starting sync at 2/19/2023, 11:19:56 AM

Loading local & fetching remote iCloud Library state...
iCloudPhotosError (WARN): Ignoring unknown album (6)
context:{"record.fields":{"recordModificationDate":{"value":1665365549346,"type":"TIMESTAMP"},"sortAscending":{"value":1,"type":"INT64"},"sortType":{"value":0,"type":"INT64"},"albumType":{"value":6,"type":"INT64"},"albumNameEnc":{"value":"Y2Ftcw==","type":"ENCRYPTED_BYTES"},"position":{"value":1048576,"type":"INT64"},"sortTypeExt":{"value":0,"type":"INT64"},"queryParamsEnc":{"value":"YnBsaXN0MDDRAQJddXNlclF1ZXJ5RGF0YU8QFRABKhEIrQIQAxoIRE1DLVRaMzAoFAgLGQAAAAAAAAEBAAAAAAAAAAMAAAAAAAAAAAAAAAAAAAAx","type":"ENCRYPTED_BYTES"}}}
iCloudPhotosError (WARN): Ignoring unknown album (6)
context:{"record.fields":{"recordModificationDate":{"value":1665085855840,"type":"TIMESTAMP"},"sortAscending":{"value":1,"type":"INT64"},"sortType":{"value":1,"type":"INT64"},"albumType":{"value":6,"type":"INT64"},"albumNameEnc":{"value":"U2xpZGVzaG93cw==","type":"ENCRYPTED_BYTES"},"position":{"value":1085440,"type":"INT64"},"sortTypeExt":{"value":0,"type":"INT64"},"queryParamsEnc":{"value":"YnBsaXN0MDDRAQJddXNlclF1ZXJ5RGF0YU8QFhAAKhII9AMQAxoJc2xpZGVzaG93KBYICxkAAAAAAAABAQAAAAAAAAADAAAAAAAAAAAAAAAAAAAAMg==","type":"ENCRYPTED_BYTES"}}}
iCloudPhotosError (WARN): Ignoring unknown album (6)
context:{"record.fields":{"recordModificationDate":{"value":1665085855840,"type":"TIMESTAMP"},"sortAscending":{"value":1,"type":"INT64"},"sortType":{"value":1,"type":"INT64"},"albumType":{"value":6,"type":"INT64"},"albumNameEnc":{"value":"bm8gYWxidW0=","type":"ENCRYPTED_BYTES"},"position":{"value":1086464,"type":"INT64"},"sortTypeExt":{"value":0,"type":"INT64"},"queryParamsEnc":{"value":"YnBsaXN0MDDRAQJddXNlclF1ZXJ5RGF0YUgQACoECGQoMggLGQAAAAAAAAEBAAAAAAAAAAMAAAAAAAAAAAAAAAAAAAAi","type":"ENCRYPTED_BYTES"}}}

Experienced fatal error at 2/19/2023, 11:21:13 AM: AppError (FATAL): Sync failed caused by iCloudPhotosError (FATAL): Unable to fetch records (album 'All photos') caused by socket hang up (Error Code: 41762cd7-6934-4168-9d3e-cac5ba849d15)
context:{}

Are there any known issues with the number of albums? How many photos in an album?
There are almost 63,000 photos and vids in my library, is that too much?

[steilerDev]

There is no known issue regarding library size so far :D

My library only has about 8k fotos and I don't have a large library to test this agains, however I think I know which part of the program might be causing this: I currently don't limit any requests while fetching the metadata, maybe you are getting rate limited Apple, due to your libraries size.

This fix might not be trivial, but I'll consider it soon

[player666au]

Thanks for persisting with this!

[maxsz]

I've just tested the latest nightly version. My library has ~52k photos. On sync I run into the following error, not sure if it's related. Let me know if I can somehow help with logs/testing.

Error-Handler: AppError (FATAL): Sync failed caused by iCloudPhotosError (FATAL): Unable to fetch records (album 'All photos') caused by Request failed with status code 500 (Error Code: 9f26d835-57d7-4387-af53-fc2a8c443674)

[steilerDev]

@maxsz yeah - you might be the top user so far and testing the limitations of the tool :D

However status code 500 indicates an error on the iCloud side - when you try again, does the error happen consistently?

Long term, I'll need to also implement a retry functionality for metadata fetching (not only a rate/concurrency limiter), did not run into issues with my 10k library :D

[steilerDev]

@player666au it might have been easier that I though - obviously can't test it :D

Could you pull the latest nightly and play around with the newly added --metadata-threads/METADATA_THREADS option and see if this changes anything? I'd try small and see if the sync progresses to the next stage.

[player666au]

It's looking good. After a rocky start ...
I tried this several times:

docker exec -t photos-sync icloud-photos-sync -l trace --metadata-threads 2 --force sync

But errored with a message which included: 'caused by getaddrinfo EAI_AGAIN p48-ckdatabasews.icloud.com'

It's always DNS??

I changed my pfsense firewall box to start logging DNS queries to see if the problem was there.

Of course this error has not repeated !!

There are now a stream or messages like this:
iCloudPhotosError (WARN): Error processing asset caused by iCloudPhotosError (WARN): Ignoring unwanted record type (CPLContainerRelation)
context:{}

Is this a normal first sync starting up?

Anyway, photos have now started to download.

Thank you very much!

[steilerDev]

Yeah getaddrinfo EAI_AGAIN p48-ckdatabasews.icloud.com basically means that the tool is unable to resolve DNS - unless your DNS query log reveals something unexpected, I don't think there is anything I can do...

Ah yes, I need to add Ignoring unwanted record type to the common warnings. This is expected and just logged for your information. There is --surpress-warnings in case you want to hide those.

I'm currently changing the logic of rate limiting from concurrency to a rate - will keep you posted and would appreciate if you could experiment which rate I should recommend to other users.

[steilerDev]

538b9e3 introduces --metadata-rate which will allow you to specify the rate of requests instead of the concurrency.

You will be able to specify this like 1/20, which means One request per 20 milliseconds.

Could you play around with this option to see at which rate you star observing 'socket hangup' errors again?

This only applies to the Fetch'n'load state - so once the files start downloading this setting is no longer relevant - would appreciate your experience here so I can provide guidance to the other users.

[player666au]

I am now using:

docker exec -t photos-sync icloud-photos-sync -l debug --metadata-rate 1/20 --force --suppress-warnings sync

This aways gets through the metadata retrieval phase.

Looks like this issue is fixed for me.

Thank you very much!

[steilerDev]

Great news! Thanks for confirming @player666au

[steilerDev]

Closed by b75ffe1