PASSWORD_MISSING Authorization Failure

JosephBanass · 10 November 2017 22:12

Hi,

When Duplicacy runs as a service, I get:

2017-11-10 16:09:03.786 INFO STORAGE_SET Storage set to b2://{{REPOSITORY}}
2017-11-10 16:09:03.789 INFO PASSWORD_MISSING b2_id is not found in Keychain/Keyring
2017-11-10 16:09:03.790 INFO PASSWORD_MISSING b2_key is not found in Keychain/Keyring
2017-11-10 16:09:04.159 ERROR STORAGE_CREATE Failed to load the Backblaze B2 storage at b2://{{REPOSITORY}}: Authorization failure [16:09:04] Backup operation returned an error:
ERROR Failed to load the Backblaze B2 storage at b2://{{REPOSITORY}}: Authorization failure

However, when I run it from the GUI, it backs up successfully. I also verified that a b2_id and b2_key exist inside the keyring file in the repository.

gchen · 11 November 2017 02:37

Did you run the GUI as administrator? The credentials stored in the keyring file are encrypted/decrypted by the Windows crypto API which can be account sensitive.

JosephBanass · 13 November 2017 12:44

Yes, the GUI was ran as administrator, which judging by your comment is why it worked.

The windows service, however, keeps failing.

gchen · 13 November 2017 17:00

Can you enable the verbose logging option in the GUI (when ran as administrator) and then exit the GUI and restart the service? This could give more information why the service fails to read the keyring passwords.

JosephBanass · 13 November 2017 18:17

I ran the backup with verbose logging enabled, and restarted the service.

I received this in the log. It appears to have included no extra info:

Log file: E:.duplicacy\logs\backup-log-20171113-121600

2017-11-13 12:16:00.283 INFO STORAGE_SET Storage set to b2://{REPOSITORY}
2017-11-13 12:16:00.287 INFO PASSWORD_MISSING b2_id is not found in Keychain/Keyring
2017-11-13 12:16:00.290 INFO PASSWORD_MISSING b2_key is not found in Keychain/Keyring
2017-11-13 12:16:00.676 ERROR STORAGE_CREATE Failed to load the Backblaze B2 storage at b2://{REPOSITORY}: Authorization failure [12:16:00] Backup operation returned an error:
ERROR Failed to load the Backblaze B2 storage at b2://{REPOSITORY}: Authorization failure

JosephBanass · 13 November 2017 19:40

Well, I’m confused.

The backup ran a second time without me scheduling it, and it completed successfully. It also had a verbose log.

I reopened the gui as administrator, scheduled the next backup to be five minutes later, closed it and restarted the service.

It ran, and failed. The log it presented was like the one above.

gchen · 13 November 2017 19:40

It looks like the verbose setting wasn’t made persistent on restart…

You can get around this issue by using the pre-command scripts. Create a file pre-backup.bat under .duplicacy/scripts that has the following line:

"c:\Program Files (x86)\Duplicacy\duplicacy_win_x64_2.0.9.exe" -d -no-script backup -stats

This runs the backup command with debug-level logging so hopefully there will be more information. The -no-script is important because it avoids calling the backup command in an infinite loop.

You can test this first in the GUI to make sure it works before switch to the service.

JosephBanass · 13 November 2017 19:50

2017-11-13 13:49:00.650 INFO SCRIPT_RUN Running script E:\.duplicacy\scripts/pre-backup.bat
2017-11-13 13:49:00.765 INFO SCRIPT_OUTPUT E:\>"C:\Program Files (x86)\Duplicacy\duplicacy_win_x64_2.0.9.exe" -d -no-script backup-stats
2017-11-13 13:49:00.765 INFO SCRIPT_OUTPUT No help topic for 'backup-stats'
2017-11-13 13:49:00.765 INFO STORAGE_SET Storage set to b2://{REPOSITORY}
2017-11-13 13:49:00.767 INFO PASSWORD_MISSING b2_id is not found in Keychain/Keyring
2017-11-13 13:49:00.768 INFO PASSWORD_MISSING b2_key is not found in Keychain/Keyring
2017-11-13 13:49:01.182 ERROR STORAGE_CREATE Failed to load the Backblaze B2 storage at b2://{REPOSITORY}: Authorization failure
[13:49:01] Backup operation returned an error:
ERROR Failed to load the Backblaze B2 storage at b2://{REPOSITORY}: Authorization failure

Output from the service with the pre-backup script with Verbose also on.

gchen · 13 November 2017 20:07

There is a space between backup and -stats.

JosephBanass · 13 November 2017 21:50

Apologies. Here’s the log output:

Log file: E:\.duplicacy\logs\backup-log-20171113-154803

2017-11-13 15:48:03.438 INFO SCRIPT_RUN Running script E:\.duplicacy\scripts/pre-backup.bat
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT E:\>"C:\Program Files (x86)\Duplicacy\duplicacy_win_x64_2.0.9.exe" -d -no-script backup -stats
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Storage set to b2://{REPOSITORY}
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Reading the environment variable DUPLICACY_B2_ID
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Failed to decrypt the value: Key not valid for use in specified state.
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Enter Backblaze Account ID:Reading the environment variable DUPLICACY_B2_KEY
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Failed to decrypt the value: Key not valid for use in specified state.
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Enter Backblaze Application Key:URL request 'https://api.backblazeb2.com/b2api/v1/b2_authorize_account' returned status code 401
2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Failed to load the Backblaze B2 storage at b2://{REPOSITORY}: Authorization failure
2017-11-13 15:48:03.894 WARN SCRIPT_ERROR Failed to run script: exit status 100
2017-11-13 15:48:03.894 INFO STORAGE_SET Storage set to b2://{REPOSITORY}
2017-11-13 15:48:03.896 INFO PASSWORD_MISSING b2_id is not found in Keychain/Keyring
2017-11-13 15:48:03.897 INFO PASSWORD_MISSING b2_key is not found in Keychain/Keyring
2017-11-13 15:48:04.265 ERROR STORAGE_CREATE Failed to load the Backblaze B2 storage at b2://{REPOSITORY}: Authorization failure [15:48:04] Backup operation returned an error:
ERROR Failed to load the Backblaze B2 storage at b2://{REPOSITORY}: Authorization failure

gchen · 14 November 2017 00:55

Is the service running as Local System account (check it in Windows Services Manager, right click the service, select Properties and then switch to ‘Log On’)? What if you run the service as local administrator?

JosephBanass · 14 November 2017 16:53

Yes, the Duplicacy service is running as local system (as are the other 4 instances we have of Duplicacy). I’ll try changing the logon account and rerunning backup

JosephBanass · 14 November 2017 17:22

Just ran a backup on the affected server running under local administrator. It finished successfully.

gchen · 14 November 2017 19:32

There must be something in your Windows security settings that prevents the local system account from decrypting passwords saved by the local administrator. This log line:

2017-11-13 15:48:03.894 INFO SCRIPT_OUTPUT Failed to decrypt the value: Key not valid for use in specified state.

means CryptUnprotectData returns an error.

JosephBanass · 14 November 2017 19:40

So I’m assuming that modifying the security permissions for the key objects would correct this?

gchen · 15 November 2017 01:14

I think I know what happened. When the GUI version saves the passwords, it calls the CryptProtectData function with the CRYPTPROTECT_LOCAL_MACHINE flag, meaning every account on the same machine can decrypt the passwords. However, the CLI version doesn’t set this flag. You probably ran the CLI version first so the passwords it saved can only be read by the same account.

If you reconfigure the same storage again with the GUI version and re-enter those passwords they should be readable by the service.

JosephBanass · 15 November 2017 14:38

That sounds correct, as I did run a pre-2.0.10 CLI build to fix a restore issue.

I’ll perform the reconfiguration and report back with the results.

JosephBanass · 15 November 2017 14:52

Thank you so much for the assistance on this problem! Your suggestion worked! The service is now backing up normally under the local system account.