Lately one of my jobs - randomly - terminates with a Warning
“Warnings”: [
“2024-04-14 18:04:22 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\fred\Documents\ClipCache\ClipCache.db”
],
The file is the DB of a clipboard extender, so the reason might be that the file is in use.
However I had this path included in the backup for a long time, an it never raised any warnng. If it was a matter of the file being in use, I had expected to see this warning occur randomly before.
The warning only occurred after I extended the source files by most of the files in C:\Users\fred\AppData (after removing folders that the process didn’t get access to). However this shouldn’t have mattered for the stuff in C:\Users\fred\Documents.
Not a big deal, as I don’t really care about the ClipCache.db being included, I’m just curious if there was anything I could do to find the reason for the warning. If not, I’ll just add it to the exclusions …
I never really understood how this About → Show log → Live → … worked.
It seems I have to refresh (F5) the page before and after I ever change the message level to get a new output. Either way - I don’t get any output for the Warning level and other levels don’t produce anything useful.
I looked at the log file and found the following:
2024-04-21 18:36:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b45cd21566c5943499d54137f31070670.dblock.zip.aes (49,92 MB)
2024-04-21 18:36:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b45cd21566c5943499d54137f31070670.dblock.zip.aes (49,92 MB)
2024-04-22 09:33:50 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\fred\Documents\ClipCache\ClipCache.db
System.IO.IOException: Der Prozess kann nicht auf die Datei zugreifen, da ein anderer Prozess einen Teil der Datei gesperrt hat.
bei System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
bei System.IO.FileStream.ReadCore(Byte buffer, Int32 offset, Int32 count)
bei System.IO.FileStream.Read(Byte array, Int32 offset, Int32 count)
bei System.IO.Stream.<>c.b__39_0(Object )
bei System.Threading.Tasks.Task`1.InnerInvoke()
bei System.Threading.Tasks.Task.Execute()
— Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde —
bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
…
So the “process can’t access the file as another process has locked a part of the file”, followed by a stacktrace and no further messages after the end of the trace info. I left the final messages from a successful run last night (2024-04-21 18:36:48) for illustration.
From the UI side the process starts and terminates normally (except for the warning) and the run is logged as
Last successful backup: Today at 9:34 AM (took 00:01:56)
This setting controls the usage of snapshots, which allows Duplicati to backup files that are locked by other programs.
followed by potentially annoying Windows restrictions. You must run as elevated administrator to use VSS.
Running as a Windows service as SYSTEM will also do it, but migration of existing backups is awkward…
That’s because you set it to the documented default of --snapshot-policy = off, so didn’t ask for a snapshot that would have solved the warning. This is not a mechanism that avoids locked files, but one that allows them. Volume Shadow Copy Service describes the problem that VSS is trying to solve as
The data usually needs to be backed up while the applications that produce the data are still running. This means that some of the data files might be open or they might be in an inconsistent state.
Ah - I see. I guess then I will just exclude this file from the backup. Although it’s still a mystery to me, why backups ran without complaints until early April. Maybe some connection with the latest MS patch day …