Got an odd one where Duplicati leaves its log-file
open, then on future run complains that it’s open – then manages to write complaint to log-file anyway.
Process Monitor view:
12:39:16.5194862 PM Duplicati.GUI.TrayIcon.exe 37540 17764 CreateFile C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log SHARING VIOLATION 0.0000992 12:39:16.5195854 PM Desired Access: Generic Write, Read Attributes, Disposition: OpenIf, Options: Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: 0
12:39:16.5202490 PM Duplicati.GUI.TrayIcon.exe 37540 17764 WriteFile C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log SUCCESS 0.0000175 12:39:16.5202665 PM Offset: 5,009,703,650, Length: 1,661
12:39:16.6427156 PM Duplicati.GUI.TrayIcon.exe 37540 17764 WriteFile C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log SUCCESS 0.0000215 12:39:16.6427371 PM Offset: 5,009,705,311, Length: 217
12:39:16.6438987 PM Duplicati.GUI.TrayIcon.exe 37540 17764 WriteFile C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log SUCCESS 0.0000138 12:39:16.6439125 PM Offset: 5,009,705,528, Length: 229
12:39:16.8416895 PM Duplicati.GUI.TrayIcon.exe 37540 17764 WriteFile C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log SUCCESS 0.0000139 12:39:16.8417034 PM Offset: 5,009,705,757, Length: 161
12:39:16.8417709 PM Duplicati.GUI.TrayIcon.exe 37540 17764 WriteFile C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log SUCCESS 0.0000051 12:39:16.8417760 PM Offset: 5,009,705,918, Length: 173
Resource Monitor view of Duplicati when this job is not in progress. Seems wrong.
There were some mishaps before the first failure, such as a source file missing, however the last job run before the error seemingly ended normally, looking like
This Duplicati started at 8:02:41 PM 3/23/2025, and I’m trying a new setup with personal account as an Administrator instead of having to change for elevation.
Converting database permissions was required for some other jobs but not this.
I have a feeling that restarting Duplicati will clear the open file. I’ll wait a little bit.
EDIT 1:
The result of the writes seen by Process Monitor are probably:
2025-03-24 12:39:16 -04 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Test has failed with error: The process cannot access the file 'C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log' because it is being used by another process.
System.IO.IOException: The process cannot access the file 'C:\Duplicati\duplicati-2.1.0.111_canary_2025-03-15-win-x64-gui\RUN\HP4 clone 12 Backblaze B2 Profiling.log' because it is being used by another process.
at Microsoft.Win32.SafeHandles.SafeFileHandle.CreateFile(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options)
at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
at System.IO.Strategies.OSFileStreamStrategy..ctor(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
at System.IO.Strategies.FileStreamHelpers.ChooseStrategyCore(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access)
at Duplicati.Library.Logging.StreamLogDestination..ctor(String filename)
at Duplicati.Library.Main.Controller.SetupCommonOptions(ISetCommonOptions result, String[]& paths, IFilter& filter)
at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Func`3 method)
2025-03-24 12:39:16 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Operation" ORDER BY "Timestamp" DESC LIMIT 1
2025-03-24 12:39:16 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "ID", "Timestamp" FROM "Operation" ORDER BY "Timestamp" DESC LIMIT 1 took 0:00:00:00.001
2025-03-24 12:39:16 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize
2025-03-24 12:39:16 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000
EDIT 2:
Found a clue in the server log from another job that uses the same log and failed:
Mar 23, 2025 9:15 PM: Failed while executing ListRemote "HP4 clone 12 Backblaze B2 from sync2" (id: 3)
code = CantOpen (14), message = System.Data.SQLite.SQLiteException (0x800007FF): unable to open database file
at System.Data.SQLite.SQLite3.Open(String strFilename, String vfsName, SQLiteConnectionFlags connectionFlags, SQLiteOpenFlagsEnum openFlags, Int32 maxPoolSize, Boolean usePool)
at System.Data.SQLite.SQLiteConnection.Open()
at Duplicati.Library.SQLiteHelper.SQLiteLoader.OpenSQLiteFile(IDbConnection con, String path)
at Duplicati.Library.SQLiteHelper.SQLiteLoader.LoadConnection(String targetpath)
at Duplicati.Library.Main.Database.LocalDatabase.CreateConnection(String path)
at Duplicati.Library.Main.Database.LocalDatabase..ctor(String path, String operation, Boolean shouldclose)
at Duplicati.Library.Main.Controller.<ListRemote>b__31_0(ListRemoteResults result, IBackendManager backendManager)
at Duplicati.Library.Utility.Utility.Await(Task task)
at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Func`3 method)
at Duplicati.Library.Main.Controller.RunAction[T](T result, Func`3 method)
at Duplicati.Library.Main.Controller.ListRemote()
at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)
I wasn’t able to get missing source to leave a log-file open, but maybe above did.
EDIT 3:
On a different job, I changed permissions to deny DB access, tried a backup, and wound up with another open log-file after the error. I don’t know if other operations could also cause this sort of thing, but finding one is a good start on fixing the bug.