Hard to read logs on Synology

Question

Hard to read logs on Synology

Opened this issue a year ago · 30 comments

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

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

Answer 1 · 2023-10-07T08:01:20.000Z

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.

Answer 2 · 2023-10-07T21:25:08.000Z

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

Answer 3 · 2023-10-09T17:37:21.000Z

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

Answer 4 · 2023-10-14T08:40:43.000Z

@lonevvolf is this good to close?

Answer 5 · 2023-10-14T15:31:52.000Z

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.

Answer 6 · 2023-10-15T12:57:04.000Z

Really? It should change the stdout output significantly.

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

Answer 7 · 2023-10-15T14:06:12.000Z

Setting via env vars:

Output looks like this:

date	stream	content
2023/10/14 17:31:33	stdout	�[32m?�[39m �[1mPlease enter your AppleID password�[22m�[0m �[0m�[37D�[37C

Answer 8 · 2023-10-15T14:14:08.000Z

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

Answer 9 · 2023-10-15T14:20:36.000Z

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?

Answer 10 · 2023-10-15T15:01:54.000Z

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

date	stream	content
2023/10/15 17:00:25	stdout	? Please enter your AppleID password �[37D�[37C

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.

Answer 11 · 2023-10-15T15:25:07.000Z

Can you share your configuration please?

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

Answer 12 · 2023-10-26T07:25:50.000Z

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

Answer 13 · 2023-10-26T11:01:16.000Z

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

Answer 14 · 2023-11-04T22:10:49.000Z

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

Answer 15 · 2023-11-05T12:59:05.000Z

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

Answer 16 · 2023-11-12T08:14:04.000Z

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

Answer 17 · 2023-11-13T07:41:12.000Z

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)?

Answer 18 · 2023-11-20T09:59:48.000Z

Current nightly build gives:

Answer 19 · 2023-11-24T16:16:02.000Z

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

Answer 20 · 2023-11-25T13:58:51.000Z

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?

Answer 21 · 2023-11-27T16:03:03.000Z

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?

Answer 22 · 2023-11-28T18:24:54.000Z

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`

Answer 23 · 2023-11-29T09:25:00.000Z

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?

Answer 24 · 2023-11-29T22:55:38.000Z

I see this in the management UI:

Answer 25 · 2023-11-30T12:56:09.000Z

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.

Answer 26 · 2023-12-10T10:09:42.000Z

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.

Answer 27 · 2023-12-14T07:26:56.000Z

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....

Answer 28 · 2023-12-14T09:05:50.000Z

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.

Answer 29 · 2023-12-15T08:24:36.000Z

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

Answer 30 · 2023-12-15T09:00:04.000Z

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.