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.