PASSWORD_MISSING Authorization Failure

Joseph Banass     Nov 10 5:12PM 2017 GUI

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    Nov 10 9:37PM 2017

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.


Joseph Banass    Nov 13 7:44AM 2017

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

The windows service, however, keeps failing.


gchen    Nov 13 12:00PM 2017

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.


Joseph Banass    Nov 13 1:17PM 2017

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


Joseph Banass    Nov 13 2:40PM 2017

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    Nov 13 2:40PM 2017

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.


Joseph Banass    Nov 13 2:50PM 2017

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    Nov 13 3:07PM 2017

There is a space between backup and -stats.


Joseph Banass    Nov 13 4:50PM 2017

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    Nov 13 7:55PM 2017

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?


Joseph Banass    Nov 14 11:53AM 2017

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


Joseph Banass    Nov 14 12:22PM 2017

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


gchen    Nov 14 2:32PM 2017

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.


Joseph Banass    Nov 14 2:40PM 2017

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


gchen    Nov 14 8:14PM 2017

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.


Joseph Banass    Nov 15 9:38AM 2017

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.


Joseph Banass    Nov 15 9:52AM 2017

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.