Hard to read logs on Synology

lonevvolf commented 1 year ago

Describe the issue

This is a very minor issue, but just wanted to report it in case it's a simple fix. I am running the container on a Synology device, and when viewing the logs, they are showing some strange text which looks like encoding of special/non-printable characters on each line:

How to reproduce the behavior?

Run the container on a Synology.

Error Code

NA

Relevant log output

![image](https://github.com/steilerDev/icloud-photos-sync/assets/383469/21305de7-8512-4a0a-9146-3c8300335633)

Operating system

Synology

Execution environment

docker

icloud-photos-sync version

1.2.0, but this is in all versions

Checklist

[X] This is an issue and not a question or feature request
[X] The sync was performed a couple of times and the issue is persisting and consistent
[X] Checked out open and known issues
[X] Enabled crash and error reporting

steilerDev commented 1 year ago

Those are control characters that are used to style/color the text in the CLI.

You could combine --silent (which will suppress the colored output) and --log-to-cli to get unstyled log messages printed to the console.

Or see if there is a way to get Synology to respect those characters for some color output.

lonevvolf commented 1 year ago

Setting LOG_TO_CLI env variable results in an error on startup:

2023/10/07 23:23:22 | stdout | Node.js v18.17.1 -- | -- | -- 2023/10/07 23:23:22 | stdout | 2023/10/07 23:23:22 | stdout | } 2023/10/07 23:23:22 | stdout | code: [32m'ERR_INVALID_ARG_TYPE'[39m 2023/10/07 23:23:22 | stdout | at file:[90m//[39m/usr/local/lib/node_modules/[4micloud-photos-sync[24m/bin/main.js:17:23 { 2023/10/07 23:23:22 | stdout | at new LogInterface (file:[90m//[39m/usr/local/lib/node_modules/[4micloud-photos-sync[24m/bin/app/event/log.js:24:37) 2023/10/07 23:23:22 | stdout | [90m at Module.openSync (node:fs:595:10)[39m 2023/10/07 23:23:22 | stdout | TypeError [ERR_INVALID_ARG_TYPE]: The "path" argument must be of type string or an instance of Buffer or URL. Received undefined 2023/10/07 23:23:22 | stdout | 2023/10/07 23:23:22 | stdout | ^ 2023/10/07 23:23:22 | stdout | ErrorCaptureStackTrace(err); 2023/10/07 23:23:22 | stdout | node:internal/errors:496 2023/10/07 23:23:21 | stdout | (node:1) ExperimentalWarning: Importing JSON modules is an experimental feature and might change at any time 2023/10/07 23:23:21 | stdout | (Use `node --trace-warnings ...` to show where the warning was created) 2023/10/07 23:23:21 | stdout | (node:1) ExperimentalWarning: Import assertions are not a stable feature of the JavaScript language. Avoid relying on their current behavior and syntax as those might change in a future version of Node.js. 2023/10/07 23:22:50 | stdout | Node.js v18.17.1

steilerDev commented 1 year ago

Good catch - should be fixed in 1.3.0-nightly.9

steilerDev commented 1 year ago

@lonevvolf is this good to close?

lonevvolf commented 1 year ago

Well, it no longer crashes, so that's good. But the SILENT and LOG_TO_CLI options don't seem to have any effect at all.

steilerDev commented 1 year ago

Really? It should change the stdout output significantly.

How are you setting those options and what's your log output?

lonevvolf commented 1 year ago

Setting via env vars:

Output looks like this:

steilerDev commented 1 year ago

Okay - for some reason it seems chalk is not properly detecting that your environment does not support colour out. You should be able to overwrite this by setting the env variable FORCE_COLOR=0

steilerDev commented 1 year ago

Additionally, are you running this using tty: true and stdin_open: true?

Could you try checking if the same non-printable characters are displayed when running without this?

lonevvolf commented 1 year ago

Setting FORCE_COLOR=0 helps a bit, but not completely:

I'm not setting either of those variables - not sure what they are set to by default. I am running this in a Synology container instance, in case that helps at all.

steilerDev commented 1 year ago

Can you share your configuration please?

And also could you please enter your password and share the remaining logs?

steilerDev commented 1 year ago

Hey @lonevvolf , did you have try with the suggestions above and is this now more bearable?

lonevvolf commented 1 year ago

Sorry, I’m on vacation at the moment. And can’t really test. Will try to test when I get back home.

lonevvolf commented 1 year ago

Even when setting APPLE_ID_PWD, I still get the log message: "Please enter your iCloud password:"

steilerDev commented 1 year ago

That's odd - can you share your full configuration please?

lonevvolf commented 1 year ago

Removed username/pw from config, but otherwise this is it.

steilerDev commented 1 year ago

Hmm - that looks similar to mine - are you using the latest version (there was a bug in a previous one, where env settings were not picked up)?

lonevvolf commented 1 year ago

Current nightly build gives:

steilerDev commented 12 months ago

This is super weird - I'm using the same version and it's not giving me that.

Could you please access the container and verify that the env variable is set and the right icloud-photos-sync version is installed?

docker exec -it <container-name> /bin/sh
echo $APPLE_ID_PWD
icloud-photos-sync --version

lonevvolf commented 12 months ago

The echo of the password prints out my password. The version command gives: 1.3.1-nightly.8

Could it be an issue with special characters in the password?

steilerDev commented 11 months ago

This is really weird - I'm using the exact same setup and am not getting this behaviour.

It should only prompt for input, when the password is empty (special characters might lead to issues actually using the password).

After echoing the variable within the container (to validate they are present), what happens if you invoke icloud-photos-sync token?

lonevvolf commented 11 months ago

Doing that gives: `[2023-11-28T18:23:41.628Z] DEBUG EventManager: Registering listener for event log-info from source LogInterface

[2023-11-28T18:23:41.630Z] DEBUG EventManager: Registering listener for event log-warn from source LogInterface

[2023-11-28T18:23:41.630Z] DEBUG EventManager: Registering listener for event warn-count_mismatch from source LogInterface

[2023-11-28T18:23:41.630Z] DEBUG EventManager: Registering listener for event warn-filetype_error from source LogInterface

[2023-11-28T18:23:41.630Z] DEBUG EventManager: Registering listener for event warn-library_load_error from source LogInterface

[2023-11-28T18:23:41.630Z] DEBUG EventManager: Registering listener for event warn-extraneous_file from source LogInterface

[2023-11-28T18:23:41.631Z] DEBUG EventManager: Registering listener for event warn-icloud_load_error from source LogInterface

[2023-11-28T18:23:41.631Z] DEBUG EventManager: Registering listener for event warn-write_asset_error from source LogInterface

[2023-11-28T18:23:41.631Z] DEBUG EventManager: Registering listener for event warn-write_album_error from source LogInterface

[2023-11-28T18:23:41.631Z] DEBUG EventManager: Registering listener for event warn-link_error from source LogInterface

[2023-11-28T18:23:41.631Z] DEBUG EventManager: Registering listener for event warn-mfa_error from source LogInterface

[2023-11-28T18:23:41.632Z] DEBUG EventManager: Registering listener for event warn-resource_file_error from source LogInterface

[2023-11-28T18:23:41.632Z] DEBUG EventManager: Registering listener for event warn-archive_asset_error from source LogInterface

[2023-11-28T18:23:41.632Z] DEBUG EventManager: Registering listener for event sync-retry from source LogInterface

[2023-11-28T18:23:41.632Z] DEBUG EventManager: Registering listener for event log-error from source LogInterface

[2023-11-28T18:23:41.632Z] DEBUG EventManager: Registering listener for event error-handled from source LogInterface

[2023-11-28T18:23:41.635Z] DEBUG EventManager: Removed 1 listeners for source iCloud

[2023-11-28T18:23:41.635Z] DEBUG EventManager: Registering listener for event icloud-trusted from source TokenApp

[2023-11-28T18:23:41.638Z] DEBUG EventManager: Registering listener for event photos-ready from source iCloud

[2023-11-28T18:23:41.638Z] DEBUG EventManager: Registering listener for event mfa-not_provided from source iCloud

[2023-11-28T18:23:41.638Z] DEBUG EventManager: Registering listener for event icloud-error from source iCloud

[2023-11-28T18:23:41.638Z] DEBUG EventManager: Registering listener for event mfa-error from source iCloud

[2023-11-28T18:23:41.639Z] INFO iCloud: Authenticating user

[2023-11-28T18:23:41.686Z] INFO iCloud: Generating SRP challenge

[2023-11-28T18:23:42.624Z] DEBUG HeaderJar: Extracted scnt from response header with length 446

[2023-11-28T18:23:42.625Z] DEBUG HeaderJar: Extracted cookie from response header: dslang (domain apple.com) with length 5

[2023-11-28T18:23:42.626Z] DEBUG HeaderJar: Extracted cookie from response header: site (domain apple.com) with length 3

[2023-11-28T18:23:42.626Z] DEBUG HeaderJar: Extracted cookie from response header: aasp (domain idmsa.apple.com) with length 240

[2023-11-28T18:23:42.702Z] DEBUG ResourceManager: Reading resource file from /opt/icloud-photos-library/.icloud-photos-sync

[2023-11-28T18:23:44.074Z] DEBUG HeaderJar: Extracted scnt from response header with length 446

[2023-11-28T18:23:44.074Z] DEBUG HeaderJar: Extracted cookie from response header: dslang (domain apple.com) with length 5

[2023-11-28T18:23:44.075Z] DEBUG HeaderJar: Extracted cookie from response header: site (domain apple.com) with length 3

[2023-11-28T18:23:44.076Z] DEBUG HeaderJar: Extracted cookie from response header: acn01 (domain apple.com) with length 0

[2023-11-28T18:23:44.077Z] DEBUG NetworkManager: Setting session secret to REDACTED

[2023-11-28T18:23:44.080Z] DEBUG iCloud: Acquired signin secrets

[2023-11-28T18:23:44.080Z] DEBUG iCloud: Response status is 200, authentication successful - device trusted

[2023-11-28T18:23:44.080Z] DEBUG ResourceManager: Reading resource file from /opt/icloud-photos-library/.icloud-photos-sync

[2023-11-28T18:23:44.081Z] DEBUG NetworkManager: Settling rate limiter queue...

[2023-11-28T18:23:44.082Z] DEBUG NetworkManager: Queue has settled!

[2023-11-28T18:23:44.082Z] DEBUG NetworkManager: Settling CCY limiter queue...

[2023-11-28T18:23:44.082Z] DEBUG NetworkManager: Queue has settled!

[2023-11-28T18:23:44.082Z] DEBUG EventManager: Removed 3 listeners for source iCloudPhotos

[2023-11-28T18:23:44.083Z] DEBUG EventManager: No more listeners for source iCloudPhotos registered

[2023-11-28T18:23:44.083Z] DEBUG EventManager: Removed 11 listeners for source iCloud

[2023-11-28T18:23:44.083Z] DEBUG EventManager: No more listeners for source iCloud registered

[2023-11-28T18:23:44.099Z] DEBUG EventManager: Removed 1 listeners for source TokenApp

[2023-11-28T18:23:44.100Z] DEBUG EventManager: No more listeners for source TokenApp registered`

steilerDev commented 11 months ago

Oh - that's progress! The execution works and it's successfully authenticating using the stored trust token (the logs don't contain the actual token). Also, LOG_TO_CLI and SILENT are both picked up.

Which leads me to the question why running the container does not work - are you somewhere overriding the entrypoint in your docker configuration?

lonevvolf commented 11 months ago

I see this in the management UI:

steilerDev commented 11 months ago

All of this is really weird - and I don't know the docker management solution on Synology well enough - could you maybe fully remove your current installation and create a fresh one? Something is off with your current one.

lonevvolf commented 11 months ago

I've set it up from scratch again, but it seems to have the same behavior. There's a few weird things going on here, though. It seems that as long as I set the SILENT option, whether true or false, it stops the standard output (welcome message, etc.) from going to the log. If I remove the option completely the output returns.

steilerDev commented 11 months ago

Those boolean flags test the existence of the env variable and don't read its content - so even when setting it to "SILENT=false" will result in the silent option to be enabled. This is how commanderjs is handling it (which I'm using for parsing).

However this still does not explain, why it is not picking up your password....

lonevvolf commented 11 months ago

Interesting - this should probably be explained/updated here: https://icps.steiler.dev/user-guides/cli/

The doc seems to indicate that you can set it to true/false with default of false.

steilerDev commented 11 months ago

Hmm - that's a good point - what would you expect there? "Unset"?

lonevvolf commented 11 months ago

I would imagine the doc being similar to the git cli documentation, for instance. https://git-scm.com/docs/git

Just picking a random cli option without values/arguments:

-P --no-pager Do not pipe Git output into a pager.

In fact there is no argument listed, and therefore, no default value. Whereas options that take an argument specify the default as well:

--exec-path[=] Path to wherever your core Git programs are installed. This can also be controlled by setting the GIT_EXEC_PATH environment variable. If no path is given, git will print the current setting and then exit.

I like the easy to read overview of your documentation with env variable equivalent - it only seems to be missing a concession for options without arguments.

steilerDev / icloud-photos-sync