Backup results in access denied error

Hello,
my backup has a warning because of one file in the Firefox profile. I have 2 questions.

  1. Why is ParsedResult: Error in my report although there is only a warning. I use www.duplicati-monitoring.com and I always get thre reports marked as error. I think it should only be Warning.

2 Why do I get the error with this file? Duplicati runs as service and uses snapshots. So all files should be accessible.

I use Duplicati - 2.0.2.13_canary_2017-11-22 on Windows 10

Here is the report:

DeletedFiles: 252
DeletedFolders: 0
ModifiedFiles: 542
ExaminedFiles: 804982
OpenedFiles: 2905
AddedFiles: 2303
SizeOfModifiedFiles: 22864272258
SizeOfAddedFiles: 65632281
SizeOfExaminedFiles: 375270559972
SizeOfOpenedFiles: 22934019950
NotProcessedFiles: 0
AddedFolders: 2
TooLargeFiles: 0
FilesWithError: 1
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults: null
DeleteResults:
   DeletedSets: []
   Dryrun: False
   MainOperation: Delete
   CompactResults: null
   ParsedResult: Success
   EndTime: 04.12.2017 14:57:36 (1512395856)
   BeginTime: 04.12.2017 14:56:52 (1512395812)
   Duration: 00:00:44.5164979
   BackendStatistics:
       RemoteCalls: 10
       BytesUploaded: 322940113
       BytesDownloaded: 171231927
       FilesUploaded: 5
       FilesDownloaded: 3
       FilesDeleted: 0
       FoldersCreated: 0
       RetryAttempts: 0
       UnknownFileSize: 0
       UnknownFileCount: 0
       KnownFileCount: 247
       KnownFileSize: 281834053811
       LastBackupDate: 04.12.2017 14:39:41 (1512394781)
       BackupListCount: 11
       TotalQuotaSpace: 0
       FreeQuotaSpace: 0
       AssignedQuotaSpace: -1
       ParsedResult: Success
RepairResults: null
TestResults:
   MainOperation: Test
   Verifications: [
       Key: duplicati-20171204T110000Z.dlist.zip.aes
       Value: [],
       Key: duplicati-id6f0878c922148d685b18f7be074c651.dindex.zip.aes
       Value: [],
       Key: duplicati-b86107ef265bf4600bd62c85ae2eb59e6.dblock.zip.aes
       Value: []
   ]
   ParsedResult: Success
   EndTime: 04.12.2017 14:57:43 (1512395863)
   BeginTime: 04.12.2017 14:57:37 (1512395857)
   Duration: 00:00:05.4834672
ParsedResult: Error
EndTime: 04.12.2017 14:57:43 (1512395863)
BeginTime: 04.12.2017 14:39:41 (1512394781)
Duration: 00:18:02.2263007
Messages: [
   No remote filesets were deleted
]
Warnings: [
   Failed to process metadata for "C:\Daten\System\Firefox\Profiles\Jascha\cert8.dir\bx-POkXwcVopUOtD7K+FcKX85GHk=", storing empty metadata => (5) Zugriff verweigert: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5\Daten\System\Firefox\Profiles\Jascha\cert8.dir\bx-POkXwcVopUOtD7K+FcKX85GHk=],
   Failed to process path: C:\Daten\System\Firefox\Profiles\Jascha\cert8.dir\bx-POkXwcVopUOtD7K+FcKX85GHk= => (5) Zugriff verweigert: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5\Daten\System\Firefox\Profiles\Jascha\cert8.dir\bx-POkXwcVopUOtD7K+FcKX85GHk=]
]
Errors: []

Thank You

Generally the “storing empty metadata” and “Failed to process path” seem to come together and seem to be caused by a permissions issue rather than an in-use situation. So in this case I doubt snapshots has anything to do with the problem.

My first guess is it’s related to these possibly being temp files that Firefox is locking down permissions wise for general system security reasons.

What version of Firefox are you using?

I am using Firefox Version 57.0.1

I’m running that as well (64 bit on Windows 10) so I set up a test backup of just my Mozilla folders.

With Firefox running and no snapshot settings or --snapshot-policy set to Off I get " Failed to process path" errors, but no “Storing empty metadata” messages.

With --snapshot-policy set to Required, On, or Auto I get no errors at all. If you verify your --snapshot-policy is Required, On, or Auto then I’m pretty sure it’s a permissions issue.

Note that it looks like the folder structure you’re using isn’t the normal Windows one I’m used to where Firefox is a subfolder of a Mozilla folder. Are you using a custom version of FF in some way?

--snapshot-policy is set to on.
No custom FF version but I changed the path for my profile.

I tried it with a Testbackup only the FF profile and get the same error.

I get a message for the error looking like this:


Failed to process path: C:\Daten\System\Firefox\Profiles\Jascha\cert8.dir\bx-POkXwcVopUOtD7K+FcKX85GHk=
System.UnauthorizedAccessException: (5) Zugriff verweigert: [\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy2\Daten\System\Firefox\Profiles\Jascha\cert8.dir\bx-POkXwcVopUOtD7K+FcKX85GHk=]
bei Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
bei Alphaleonis.Win32.Filesystem.File.CreateFileCore(KernelTransaction transaction, String path, ExtendedFileAttributes attributes, FileSecurity fileSecurity, FileMode fileMode, FileSystemRights fileSystemRights, FileShare fileShare, Boolean checkPath, PathFormat pathFormat)
bei Alphaleonis.Win32.Filesystem.File.OpenCore(KernelTransaction transaction, String path, FileMode mode, FileSystemRights rights, FileShare share, ExtendedFileAttributes attributes, Nullable`1 bufferSize, FileSecurity security, PathFormat pathFormat)
bei Duplicati.Library.Snapshots.SystemIOWindows.FileOpenRead(String path)
bei Duplicati.Library.Snapshots.WindowsSnapshot.OpenRead(String file)
bei Duplicati.Library.Main.Operation.BackupHandler.HandleFilesystemEntry(ISnapshotService snapshot, BackendManager backend, String path, FileAttributes attributes)

It appears that the snapshot is in place (the \?\GLOBALROOT\... stuff), but still permission is denied.

I don’t know why this happens, but I think it is a general VSS issue. Googling the problem did not reveal anything, but maybe I hit the wrong keywords…

What is with my other point?
Why does this one file cause the global result in error and not in warning?

I guess it is a matter of preference when things are considered a warning and when it should be considered an error. When you have any files that caused errors, as indicated with FilesWithError: 1, then the status is reported as Error. But i agree that it does not make sense since the message is logged as a warning. We should go either one or the other.

Is there any progress with the error result? I have now several backups in my duplicati-monitoring.com and its nearly unusable, because most of them result in an error, because of one or two unimportant files that could not be backuped.

I have a similar problem but with a .ost file.
VSS is turned on.

My logfile:

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 1
ExaminedFiles: 13019
OpenedFiles: 1
AddedFiles: 0
SizeOfModifiedFiles: 7697556480
SizeOfAddedFiles: 0
SizeOfExaminedFiles: 27693399230
SizeOfOpenedFiles: 7697556480
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
ParsedResult: Warning
Version: 2.0.5.104 (2.0.5.104_canary_2020-03-25)
EndTime: 06.05.2020 22.27.41 (1588796861)
BeginTime: 06.05.2020 22.23.32 (1588796612)
Duration: 00:04:09.2814895
MessagesActualLength: 19
WarningsActualLength: 4
ErrorsActualLength: 0
LimitedMessages: [
    2020-05-06 22.23.32 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2020-05-06 22.23.58 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2020-05-06 22.24.01 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (923 bytes),
    2020-05-06 22.26.38 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b5f4018037fa64e3585c4ee0218517923.dblock.zip.aes (141,43 KB),
    2020-05-06 22.26.40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b5f4018037fa64e3585c4ee0218517923.dblock.zip.aes (141,43 KB),
    2020-05-06 22.26.54 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i730288ee97fd49eb88577e605e045e3c.dindex.zip.aes (101,17 KB),
    2020-05-06 22.26.55 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i730288ee97fd49eb88577e605e045e3c.dindex.zip.aes (101,17 KB),
    2020-05-06 22.26.55 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20200506T202332Z.dlist.zip.aes (1,31 MB),
    2020-05-06 22.26.58 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20200506T202332Z.dlist.zip.aes (1,31 MB),
    2020-05-06 22.27.02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: No remote filesets were deleted,
...
]
LimitedWarnings: [
    2020-05-06 22.23.55 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange o365.ost,
    2020-05-06 22.23.55 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange.ost,
    2020-05-06 22.24.01 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange o365.ost,
    2020-05-06 22.24.01 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange.ost
]
LimitedErrors: []
Log data:
2020-05-06 22.23.55 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange o365.ost
System.IO.FileNotFoundException: (2) Systemet finner ikke angitt fil: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy17\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange o365.ost]
   ved Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   ved Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   ved Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__20.MoveNext()
2020-05-06 22.23.55 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange.ost
System.IO.FileNotFoundException: (2) Systemet finner ikke angitt fil: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy17\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange.ost]
   ved Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   ved Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   ved Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__20.MoveNext()
2020-05-06 22.24.01 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange o365.ost
System.IO.FileNotFoundException: (2) Systemet finner ikke angitt fil: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy17\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange o365.ost]
   ved Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   ved Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   ved Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__20.MoveNext()
2020-05-06 22.24.01 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange.ost
System.IO.FileNotFoundException: (2) Systemet finner ikke angitt fil: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy17\Users\user\AppData\Local\Microsoft\Outlook\email@email.com - Exchange.ost]
   ved Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   ved Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   ved Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__20.MoveNext()

What exactly is your --snapshot-policy set to? If it’s set to “Auto” then it may be failing without you noticing. You can set it to “On” to trigger a more noticable warning when the snapshot fails.

Also, I would not bother backing up OST files. That’s an offline cache of your email data. If the file is lost or damaged the data will be re-downloaded from the email server automatically.

–snapshot-policy is set to “On”

Yeah I have seen comments about that OST files are not worth backing up. But duplicati is about keeping your own backup in your own system. So if I have trusted the email providers and other cloud providers I would not have bothered to backup anything.

Interesting that your log says “file not found” on those OSTs. Does this happen every time? Or just sometimes?

I have just tested this evening, and the last 5 times it happens every time. I have tried to close outlook with no improvement.

If Duplicati is successful in making a snapshot, then Outlook being open should not matter. I suspect it may still be failing to create a snapshot. Can you try setting --snapshot-policy to “Required” and running another backup? This will make it more obvious if the snapshot fails.

Tested now with the setting set to “Required”, but I still get the same error in the logs. (Exactly the same as my previous logs)

Running this as a windows service and the setting is set in the web interface on Settings.

Is it possible you are changing this at the global settings level, but the job has a different snapshot policy set? (You can set most/all options at the global level and at the job level. If undefined at the job level, it will use the global level settings.)

Could be, but then it would do that randomly. Cause when I first set up the job I did not use snapshot policy, and the I got the corresponding error to that. (Can not access file because locked by other process etc)
I have not touched the job level settings at any time. (Other than those that the “wizard” shows predefined)

Try this - go to the Duplicati web UI, click your backup job, and click Export.
On the next screen click “As Command-line” and uncheck the “Export passwords” box.
Click Export, then copy and paste the results here (sanitized of any sensitive info). Alternatively, instead of pasting here, you can look through the text for --snapshot-policy and confirm the setting.

Thanks!

Thank you for all your help and input!

I exported it and there was nothing about --snapshot-policy.

Just for fun, I created a new backup test and set the snapshot-policy in the job settings, but I got the same error.
I have also confirmed that the service is run as a local system account.

When I first set up the initial backup (without VSS) I saw that many files were not backuped. But when I enabled VSS there was only the OST file. Maybe it could be the size or the file name? (Just throwing out something) Since my OST file contains a dash (-) and also the file in question for the thread starter also contains a dash.