"Unexpected difference in fileset" errors [2.0.3.9]

In my testing of various scenarios in 2.0.3.9 canary I’ve managed to somehow / accidentally recreate the “Unexpected difference in fileset” error that some other users have run into. (Detailed error below.)

For most of them, a database recreate seemed to resolve the issue but I believe I have a secondary issue (missing file?) that is not allowing that resolution to work for me.

In the end, I believe I had to:

  1. do a database Repair (just to make sure DB was in good shape)
  2. delete all dlist files (because I couldn’t easily figure out which one belonged to fileset / backup #54)
  3. do a database Recreate (the lack of dlist files forced full downloads of all dblock files, but bandwidth isn’t an issue for me)
  4. do another database Repair

After all that, I had ONE backup run work correctly after which I noticed the “Restore from” list showed jobs NEWER than the job menu’s “Last successful backup” date, and further backups failed with “Unexpected number of remote volumes marked as deleted” global errors.

Those “…marked as deleted…” errors go away if I change from a custom --retention-policy to a “Backup retention” of “Keep all backups”. Putting the custom retention policy back in brings the “Unexpected number of remote volumes marked as deleted” error back, even after successful “Keep all backups” runs.

Oddly, the error even happens with a custom retention policy of U:U. :frowning:

Some other things I tried that did NOT resolve the original issue for me include:
  • A database Repair which finished with no errors
  • A database Recreate which finished with a “missing files” error
  • Rolling back to 2.0.3.7 (the oldest I could get to due to database version 8 vs 7 issues) - note that rolling back to 2.0.3.5 seemed to work for somebody
  • Deleting all the dindex files (in case they had an orphaned reference to a deleted file) followed by a database Rebuild, but it did not resolve the original issue. A subsequent database Recreate still reported the missing file and also did not resolve the original issue.
  • At one point @kenkendk suggested to another user to delete the troublesome version. In my case that’s version #54 but while the main job page says I have 54 versions, the (zero based) Restore page only shows 53 so I’m not sure if I’m supposed to be deleting version 53 or if there’s a phantom version 54 floating around somewhere.

The error:

System.AggregateException: One or more errors occurred.
---> System.AggregateException: Unexpected difference in fileset 54, found 13837 entries, but expected 13841
---> System.Exception: Unexpected difference in fileset 54, found 13837 entries, but expected 13841
  at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (System.Int64 blocksize, System.Int64 hashsize, System.Boolean verifyfilelists, System.Data.IDbTransaction transaction) [0x002bc] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass31_0.<VerifyConsistencyAsync>b__0 () [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass6_0.<RunOnMain>b__0 () [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass5_0`1+<<DoRunOnMain>b__1>d[T].MoveNext () [0x00038] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0003e] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in <a6f810169ec746eeb2789b925e2858c0>:0
  at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () [0x003c9] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of inner exception stack trace ---
  at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () [0x0102c] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of inner exception stack trace ---
  at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x0005d] in <6973ce2780de4b28aaa2c5ffc59993b1>:0
  at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x00008] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Controller+<>c__DisplayClass13_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00035] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0022e] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Controller.Backup (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x00068] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00335] in <8486dd191d20467cbf8d627f56ca2e90>:0
---> (Inner Exception #0) System.AggregateException: Unexpected difference in fileset 54, found 13837 entries, but expected 13841
---> System.Exception: Unexpected difference in fileset 54, found 13837 entries, but expected 13841
  at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (System.Int64 blocksize, System.Int64 hashsize, System.Boolean verifyfilelists, System.Data.IDbTransaction transaction) [0x002bc] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass31_0.<VerifyConsistencyAsync>b__0 () [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass6_0.<RunOnMain>b__0 () [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass5_0`1+<<DoRunOnMain>b__1>d[T].MoveNext () [0x00038] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0003e] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in <a6f810169ec746eeb2789b925e2858c0>:0
  at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () [0x003c9] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of inner exception stack trace ---
  at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () [0x0102c] in <0ce58d578b8642d49036dc15fbad38f1>:0
---> (Inner Exception #0) System.Exception: Unexpected difference in fileset 54, found 13837 entries, but expected 13841
  at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (System.Int64 blocksize, System.Int64 hashsize, System.Boolean verifyfilelists, System.Data.IDbTransaction transaction) [0x002bc] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass31_0.<VerifyConsistencyAsync>b__0 () [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass6_0.<RunOnMain>b__0 () [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass5_0`1+<<DoRunOnMain>b__1>d[T].MoveNext () [0x00038] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0003e] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in <a6f810169ec746eeb2789b925e2858c0>:0
  at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () [0x003c9] in <0ce58d578b8642d49036dc15fbad38f1>:0 <---
---> (Inner Exception #1) System.AggregateException: One or more errors occurred.
---> System.Exception: Unable to find log in lookup table, this may be caused by attempting to transport call contexts between AppDomains (eg. with remoting calls)
  at Duplicati.Library.Logging.Log.get_CurrentScope () [0x0004d] in <a0d17c5f1b8942efac55f621de8cc00b>:0
  at Duplicati.Library.Logging.Log.WriteMessage (Duplicati.Library.Logging.LogMessageType type, System.String tag, System.String id, System.Exception ex, System.String message, System.Object[] arguments) [0x0001e] in <a0d17c5f1b8942efac55f621de8cc00b>:0
  at Duplicati.Library.Logging.Log.WriteWarningMessage (System.String tag, System.String id, System.Exception ex, System.String message, System.Object[] arguments) [0x00000] in <a0d17c5f1b8942efac55f621de8cc00b>:0
  at Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess+<>c.<Run>b__1_3 (System.String rootpath, System.String errorpath, System.Exception ex) [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Utility.Utility+<EnumerateFileSystemEntries>d__23.MoveNext () [0x001d9] in <5336a8b903594fa5ae5a9692dae4b7fe>:0
  at System.Linq.Enumerable+SelectManySingleSelectorIterator`2[TSource,TResult].MoveNext () [0x0006f] in <abeb153532fb46718501a600866a8d76>:0
  at Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess+<ExpandWorkList>d__4.MoveNext () [0x000da] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess+<>c__DisplayClass1_0+<<Run>b__0>d.MoveNext () [0x00263] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0003e] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in <a6f810169ec746eeb2789b925e2858c0>:0
  at CoCoL.AutomationExtensions+<RunTask>d__10`1[T].MoveNext () [0x000cc] in <6973ce2780de4b28aaa2c5ffc59993b1>:0
 --- End of inner exception stack trace ---
---> (Inner Exception #0) System.Exception: Unable to find log in lookup table, this may be caused by attempting to transport call contexts between AppDomains (eg. with remoting calls)
  at Duplicati.Library.Logging.Log.get_CurrentScope () [0x0004d] in <a0d17c5f1b8942efac55f621de8cc00b>:0
  at Duplicati.Library.Logging.Log.WriteMessage (Duplicati.Library.Logging.LogMessageType type, System.String tag, System.String id, System.Exception ex, System.String message, System.Object[] arguments) [0x0001e] in <a0d17c5f1b8942efac55f621de8cc00b>:0
  at Duplicati.Library.Logging.Log.WriteWarningMessage (System.String tag, System.String id, System.Exception ex, System.String message, System.Object[] arguments) [0x00000] in <a0d17c5f1b8942efac55f621de8cc00b>:0
  at Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess+<>c.<Run>b__1_3 (System.String rootpath, System.String errorpath, System.Exception ex) [0x00000] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Utility.Utility+<EnumerateFileSystemEntries>d__23.MoveNext () [0x001d9] in <5336a8b903594fa5ae5a9692dae4b7fe>:0
  at System.Linq.Enumerable+SelectManySingleSelectorIterator`2[TSource,TResult].MoveNext () [0x0006f] in <abeb153532fb46718501a600866a8d76>:0
  at Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess+<ExpandWorkList>d__4.MoveNext () [0x000da] in <0ce58d578b8642d49036dc15fbad38f1>:0
  at Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess+<>c__DisplayClass1_0+<<Run>b__0>d.MoveNext () [0x00263] in <0ce58d578b8642d49036dc15fbad38f1>:0
 --- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0003e] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <a6f810169ec746eeb2789b925e2858c0>:0
  at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in <a6f810169ec746eeb2789b925e2858c0>:0
  at CoCoL.AutomationExtensions+<RunTask>d__10`1[T].MoveNext () [0x000cc] in <6973ce2780de4b28aaa2c5ffc59993b1>:0
<--- <--- <---
1 Like

Delete of the specific version using GUI Commandline option is what I’ve had to do, however I’ve only seen this at the time when I tried –skip-files-larger-than but received an unexpected mess. I couldn’t reproduce it, but seeing this new topic led me to summarize an Information-level log. Below is a writeup of that summary, condensed into operations and results, with odd results being supplemented by examples from the full log. I’ve been on canary (now 2.0.3.9), set no special metadata options, but do have --snapshot-policy=On

2018-07-19 13:59:46 Backup, normal

2018-07-19 14:19:58 Backup, unusual. Only Put a dblock and dindex
"removing file listed as Temporary" but didn't actually do Delete

2018-07-19 14:39:12 Backup, channel is retired, task was canceled
Also, most of the metadata processing was beyond the backup range

2018-07-19 14:43:42 Backup, Unexpected difference

2018-07-19 14:51:37 Repair

2018-07-19 14:51:56 Backup, channel is retired, UNIQUE constraint

2018-07-19 15:27:28 Backup, Unexpected difference

2018-07-19 15:30:58 Repair, Recreate

2018-07-19 15:33:13 Backup, Metadata was reported, channel is retired, UNIQUE constraint

2018-07-19 15:35:55 Backup, Unexpected difference

2018-07-19 15:49:59 Delete

2018-07-19 15:50:47 Backup, normal

2018-07-19 15:55:37 Backup, channel is retired, task was canceled

2018-07-20 09:57:29 Unexpected difference

Example of "channel is retired", "beyond the backup range", "task was canceled", and "Unexpected difference":

2018-07-19 14:39:55 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-ProcessingMetadataFailed]: Failed to process entry, path: C:\zFTPServer\CBB_HP4\C$\Users\Ted\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\https+++www.youtube.com\idb\3211250388sbwdpsunsohintoatciif.sqlite$\20170809230042\3211250388sbwdpsunsohintoatciif.sqlite
CoCoL.RetiredException: The channel is retired
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoCoL.Channel`1.<WriteAsync>d__30.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.<>c__DisplayClass2_0.<<Run>b__0>d.MoveNext()
2018-07-19 14:39:55 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b0acad27920b44394abc50c52e6e2b450.dblock.zip.aes (124.76 KB)
2018-07-19 14:39:59 -04 - [Information-Duplicati.Library.Modules.Builtin.SendMail-SendMailComplete]: Email sent successfully using server: smtp://smtpauth.earthlink.net:587/?starttls=always
2018-07-19 14:39:59 -04 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Backup has failed with error: A task was canceled.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)
   at Duplicati.Library.Main.Controller.<>c__DisplayClass13_0.<Backup>b__0(BackupResults result)
   at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)
2018-07-19 14:42:22 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2018-07-19 14:42:22 -04 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation List has completed
(six more pairs)
2018-07-19 14:43:42 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2018-07-19 14:44:21 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Exception: Unexpected difference in fileset 319, found 807 entries, but expected 808
   at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass31_0.<VerifyConsistencyAsync>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass6_0.<RunOnMain>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass5_0`1.<<DoRunOnMain>b__1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__19.MoveNext()

Example of "channel is retired" and "UNIQUE constraint":

2018-07-19 14:52:36 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-ProcessingMetadataFailed]: Failed to process entry, path: C:\Users\Ted\Documents\My Kindle Content\B002B55AEI_EBOK\CR!VC2GAHGBKX24V3AJ5VK3NF1PN9EN.azw.res
CoCoL.RetiredException: The channel is retired
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoCoL.Channel`1.<WriteAsync>d__30.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.<>c__DisplayClass2_0.<<Run>b__0>d.MoveNext()
2018-07-19 14:52:36 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc014ba9cccac45028b8d351c472830d9.dblock.zip.aes (1.90 KB)
2018-07-19 14:52:39 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Data.SQLite.SQLiteException (0x80004005): constraint failed
UNIQUE constraint failed: FilesetEntry.FilesetID, FilesetEntry.FileID
   at System.Data.SQLite.SQLite3.Reset(SQLiteStatement stmt)
   at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
   at System.Data.SQLite.SQLiteDataReader.NextResult()
   at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
   at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
   at Duplicati.Library.Main.Database.LocalBackupDatabase.AddUnmodifiedFile(Int64 fileid, DateTime lastmodified, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass6_0.<RunOnMain>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass5_0`1.<<DoRunOnMain>b__1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---

Example of "Metadata was reported", "channel is retired", and "UNIQUE constraint":

2018-07-19 15:33:57 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?
Hash: ff5/v9LfE0FV1mvtfS3NPuvO+eg5j5lB47OnboTj/X8=, Length: 137, ID: 88
2018-07-19 15:33:57 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-ProcessingMetadataFailed]: Failed to process entry, path: C:\Users\Ted\Documents\size test\short.txt
CoCoL.RetiredException: The channel is retired
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoCoL.Channel`1.<WriteAsync>d__30.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
...
2018-07-19 15:33:57 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-ProcessingMetadataFailed]: Failed to process entry, path: C:\Users\Ted\Documents\My Kindle Content\B002B55AEI_EBOK\CR!VC2GAHGBKX24V3AJ5VK3NF1PN9EN.azw.res
CoCoL.RetiredException: The channel is retired
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoCoL.Channel`1.<WriteAsync>d__30.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.<>c__DisplayClass2_0.<<Run>b__0>d.MoveNext()
2018-07-19 15:33:57 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb1f7dbf681fc44cd94a27a7ee4d0c988.dblock.zip.aes (1.92 KB)
2018-07-19 15:33:59 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Data.SQLite.SQLiteException (0x80004005): constraint failed
UNIQUE constraint failed: FilesetEntry.FilesetID, FilesetEntry.FileID
   at System.Data.SQLite.SQLite3.Reset(SQLiteStatement stmt)
   at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
   at System.Data.SQLite.SQLiteDataReader.NextResult()
   at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
   at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
   at Duplicati.Library.Main.Database.LocalBackupDatabase.AddUnmodifiedFile(Int64 fileid, DateTime lastmodified, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass6_0.<RunOnMain>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass5_0`1.<<DoRunOnMain>b__1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---

Across this four month log, I usually see some "Metadata was reported", and a few "UNIQUE constraint".
"channel is retired", "task was canceled", and "Unexpected difference" were only at the troubled time.

I can’t say what an older release would have done, because I’ve only seen the large-scale mess on 2.0.3.9.

I’m hoping some experts can sort out the chain-reaction effects from things that might share a single cause, however out of politeness to this topic, perhaps other topics can get talk that’s not “Unexpected difference”, where I’m contributing some cases plus some context that looks like it might possibly lead into that problem.

I was going to do that but when I went to look at the contents of the version listed in the error message (54) I got an error that it was an invalid version number. There was a version 53 that looked like it either was or was almost the initial backup, so I’m thinking maybe 54 got incompletely cleaned up during retention policy compacting.

Of course it doesn’t help that my current versions 31 and higher were done with 7zip, so that may be the underlying issue in my case.

Hello, I had this problem too and I hope this solution will help somebody:

Duplicati: 2.0.3.11_canary_2018-09-05
Error message probably after crash during backup:

Unexpected difference in fileset 387, found 28618 entries, but expected 28646

I tried:

  • Repair - nothing
  • Verify - nothing
  • Backup - errror message
  • Delete --version=387 - nothing
  • List - I had only 90 versions so I could not delete version 387
  • list-broken-files - some files were found
  • purge-broken-files -some files were deleted

Then I backed up my DB and start recreate. After recreate I can back up without error message.

Thanks for the suggestion, I’ll give it a try. I’m pretty sure I tried it before to no effect, but will message had actually progressed (or been covered up) by Unexpected number of remote volumes marked as deleted. now so hopefully a rebuild will do the trick this time.

Out of curiosity, did you also is 7z at some point in the job history? Hopefully not as that would mean the issue isn’t (just) 7z related.

Edit: Unfortunately it didn’t work. I think I may have somehow resolved the issue (perhaps as you did) but then ran into the ““Unexpected number of remote volumes marked as deleted” error” errors. :frowning:

I might have figured out why @JonMikelV and @mr-flibble had trouble getting the fileset number from their error message to match anything in the regular UI. See Backup failing due to unexpected difference in fileset.

By any chance do either of you have your broken database around? It might be useful to experiment with, but we’d probably want to keep testing from harming anything (including destination data) that’s now running well.

Mine is still erroring out every day. It’s a secondary backup so I figured I’d let it sit until somebody had an idea. :slight_smile:

What do you need from me?

See what you think of this idea, suggest any changes, prepare as needed, try it, and tell everyone if it works. Although this backup doesn’t sound too important, you could try to preserve it in case a next-idea is needed. Maybe it could even be used someday to try new Duplicati code to fix this so such manual work isn’t needed.
EDIT: or is it too late, i.e. has the database with “Unexpected difference in fileset” moved to a different error?

Thanks!

Shoot, you’re right - it has moved on to the unexpected number of remote volumes marked as deleted error. :frowning:

I may have backed up the version that failed with the fileset error. I’ll try to check, but it may take me a while to get to it (just had a drive report read errors on my array).

I just ran into the “unexpected difference in fileset” error today - i’m on the latest canary and have made no upgrades since the last working backup ran. The backup job’s destination in this case is Google Drive, and it started with an error message that I couldn’t make much sense of, which suggested running “repair”, then after I ran “repair” (successfully) I now get the “unexpected difference” error message every time I try to run the backup job. I haven’t tried a Recreate yet, but will probably try that next. First I’m trying to run “list broken files” which has been running for 20 minutes now and doesn’t seem to be doing anything (no new entries in the Profiling log in that timespan).

Before you go for recreate, maybe make a backup copy of the database, show us the exact (likely new) fileset message, and perhaps you can try doing a fileset deletion. The error message changed and should be easier.

I’m a little bad at making commandline type stuff work in Duplicati, so I request somewhat verbose directions if you’re willing :stuck_out_tongue:
image

This one looks like the most recent backup developed a problem. You can check that against the “Restore from” dropdown in the GUI for that job, to see if 0: and date match. If so, then backup the database (if you haven’t already), finding it by “Local database path” under the job Backup option. This copy is just-in-case.

Next step is The DELETE command which is probably most easily done using the job Commandline option. Change the command dropdown at screen top to delete, delete all the source paths from Commandline arguments box, Near bottom, Add advanced option of version, find it, set it to 0, then at bottom Run "delete" command now. This should delete your most recent backup. I’m assuming the database is still seemingly good except for the fileset error. If you know of other issues, then the plan should be rethought.

Being extra careful would have you first do a run using the –dry-run and review the output for any worries. Ordinarily, deletes occur all the time unless you’ve got Backup retention at Keep all backup. I guess might as well be cautious and at least see that delete wants to take out only a dlist of the right time along with whatever dblock and dindex files it might have added. That should take only a quick look at its output.

Using the Command line tools from within the Graphical User Interface gives further info on Commandline.

I’m currently trying this, and it’s doing nothing (with no output in the profiling-level log either). Did I do something wrong?
This is my second time trying. The first time, it stayed like this for around an hour with no changes. Pressing “stop now” didn’t work either; I eventually had to force quit Duplicati and manually re-launch it.
image

I was expecting some more action. Not sure why it’s not moving. Output when I delete version 0 looks like:

(below with no special logging settings)
  Listing remote folder ...
The following filesets would be deleted:
0: 11/22/2018 4:02:18 PM
Return code: 0

(below after adding --console-log-level=Information)
The operation Delete has started
Backend event: List - Started:  ()
  Listing remote folder ...
Backend event: List - Completed:  (20 bytes)
Deleting 1 remote fileset(s) ...
[Dryrun]: Would delete remote fileset: duplicati-20181122T210218Z.dlist.zip
[Dryrun]: 1 remote fileset(s) would be deleted
[Dryrun]: Remove --dry-run to actually delete files
Compacting because there are 1 fully deletable volume(s)
[Dryrun]: Would delete remote file: duplicati-b2f1fccd564444563b5e07efdfbeefcc6.dblock.zip, size: 699 bytes
[Dryrun]: Would delete remote file: duplicati-i18e930cc658e4935b2842d3f4fae2b75.dindex.zip, size: 607 bytes
[Dryrun]: Would delete 2 files, which would reduce storage by 1.28 KB
The following filesets would be deleted:
0: 11/22/2018 4:02:18 PM
Return code: 0

MENU --> About --> Show log --> Live --> Profiling set up in advance had a lot of output data written to it.
I’m not certain how good it is at picking up after the fact, but I’d hope any new operations would be there. Adding --console-log-level=Profiling right in the Commandline options would show you something I hope.
.
If you tire of this effort, you could go back to your original recreate plan, and see if that solves the issue, however recreates can be slow. If this backup is hundreds of GB (or more), maybe we can try more here.

It appears to be hanging. I have no idea why. It does the same thing if I try running the delete with or without dry-run, and it did it to me before when i tried the list-broken-files commandline. Pressing “stop now” does nothing, and if I exit Duplicati from the systray icon, it goes away but stays active in my task manager (until I forcefully close it from there and re-launch).

Luckily this backup set is only ~6 GB so recreate may be a reasonable plan of action from here. It’s a little frustrating that Duplicati isn’t better at error handling with this sort of stuff - I hate to imagine what would happen with my main PC’s backup (at ~800gb backed up to B2) if this sort of error crept in.

Fortunately this seems to have worked. The recreate only took a few minutes (i didn’t time it but it was on the order of 5 minutes overall), and afterwards a routine backup was run successfully.

1 Like

I also hit this problem on the one machine I upgraded so far from 2.0.3.3 to 2.0.4.5.

Failed: Unexpected difference in fileset version 67: 10/8/2018 3:00:00 PM (database id: 2348), found 2725 entries, but expected 2726

Will read through this thread more closely to see best way to fix…

My turn to stumble upon this. It’s just a tiny test backup, so the only support asked is if anybody can take my analysis and use it to either come up with an easier test case, or fix the code so we can have fewer of these.

Summary is that I ran my 1-file SFTP backup for some reason which I forget, while having another SFTP login from Linux which caused the Duplicati connection to be rejected due to the small server connection limit. This stopped upload of the dblock, even after 5 tries. The dindex wasn’t tried. I fixed SFTP overload, and the dlist made it, but from a destination file point of view a dlist with no dblock or dindex is bad news. From a database point of view, having an entry in the FilesetEntry table without a corresponding one in the File table might get:

2018-11-29 15:34:45 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 0: 11/28/2018 12:04:56 PM (database id: 42), found 0 entries, but expected 1
   at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass32_0.<VerifyConsistencyAsync>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.<RunOnMain>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<DoRunOnMain>d__2`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__19.MoveNext()

Everything seemed fine after the 12/28 12:04 backup, but a latent defect was created that caused the above. Looking more closely at the 12:04, one can see some smaller oddities like duplicati-verification.json uploaded before the database deletions to clean up from the failed uploads were done. Unfortunately FilesetEntry table changes appear to need --profile-all-database-queries (added in 2.0.3.10 canary) to log, so I didn’t get them.

This chronological log excerpt is from the glogg log explorer, which includes a regular expression filter. I used:

BackupMainOperation|VerifyConsistency|Backend event: Put|RemoteOperationPut|RetryPut|RemoteUnwantedMissingFile
2018-11-28 12:04:56 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.BackupHandler-BackupMainOperation]: Starting - BackupMainOperation
2018-11-28 12:04:56 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-BackupMainOperation]: BackupMainOperation took 0:00:00:00.050
2018-11-28 12:04:56 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.BackupHandler-VerifyConsistency]: Starting - VerifyConsistency
2018-11-28 12:04:56 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-VerifyConsistency]: VerifyConsistency took 0:00:00:00.000
2018-11-28 12:04:56 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip (700 bytes)
2018-11-28 12:04:57 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip attempt 1 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:04:57 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip (700 bytes)
2018-11-28 12:05:07 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip (700 bytes)
2018-11-28 12:05:07 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:07 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:08 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip attempt 2 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:08 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:18 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:18 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:18 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:20 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip attempt 3 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:20 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:33 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip attempt 4 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:33 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip (700 bytes)
2018-11-28 12:05:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip (700 bytes)
2018-11-28 12:05:47 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip attempt 5 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:47 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip (700 bytes)
2018-11-28 12:05:47 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20181128T170456Z.dlist.zip (538 bytes)
2018-11-28 12:05:47 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut
2018-11-28 12:05:47 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-verification.json (30.70 KB)
2018-11-28 12:05:52 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-20181128T170456Z.dlist.zip attempt 1 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-20181128T170456Z.dlist.zip (538 bytes)
2018-11-28 12:05:58 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:00:10.949
2018-11-28 12:05:58 -05 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-verification.json attempt 1 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:58 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170456Z.dlist.zip (538 bytes)
2018-11-28 12:06:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:08 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut
2018-11-28 12:06:08 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:09 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-20181128T170457Z.dlist.zip attempt 2 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:06:09 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:17 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:00:08.835
2018-11-28 12:06:17 -05 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-verification.json attempt 2 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:06:17 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:19 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:19 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:19 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:27 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut
2018-11-28 12:06:27 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:28 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:28 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-20181128T170458Z.dlist.zip attempt 3 of 5 failed with message: Object reference not set to an instance of an object.
2018-11-28 12:06:28 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:29 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:00:01.186
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-20181128T170456Z.dlist.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-20181128T170457Z.dlist.zip

which is pretty close to the database view except RemoteOperation table seems to show duplicati-verification.json uploading after the dlist file, instead of at the same time as the log seems to show.
Log has Object reference not set to an instance of an object. but the file uploaded.

From Operation table
Description     Timestamp
Backup          1543424696 November 28, 2018 12:04:56 PM
Backup          1543523685 November 29, 2018 3:34:45 PM

From RemoteOperation table
ID      Operation       Path                                                    Timestamp
390     put             duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip  1543424696 November 28, 2018 12:06:29 PM
391     put             duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip  1543424707 November 28, 2018 12:05:07 PM
392     put             duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip  1543424718 November 28, 2018 12:05:18 PM
393     put             duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip  1543424730 November 28, 2018 12:05:30 PM
394     put             duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip  1543424743 November 28, 2018 12:05:43 PM
395     put             duplicati-20181128T170456Z.dlist.zip                    1543424747 November 28, 2018 12:05:47 PM
396     put             duplicati-20181128T170457Z.dlist.zip                    1543424762 November 28, 2018 12:06:02 PM
397     put             duplicati-20181128T170458Z.dlist.zip                    1543424779 November 28, 2018 12:06:19 PM
398     put             duplicati-verification.json                             1543424789 November 28, 2018 12:06:29 PM
399     put             duplicati-verification.json                             1543424789 November 28, 2018 12:06:29 PM
400     put             duplicati-verification.json                             1543424789 November 28, 2018 12:06:29 PM

From RemoteVolume table
ID      Name
187     duplicati-b2dc362dd4f62431391091a117256c441.dblock.zip
188     duplicati-i257753298c614dfcb86a5cade4a7ecff.dindex.zip
189     duplicati-20181128T170458Z.dlist.zip

From Fileset table
ID      VolumeID        Timestamp
40      182             1539037173 October 8, 2018 6:19:33 PM
41      183             1543423077 November 28, 2018 11:37:57 AM
42      189             1543424696 November 28, 2018 12:04:56 PM

From FilesetEntry table
FilesetID       FileID
40              12074
41              12075
42              12076

From File table
ID
12074
12075
12076 does not exist

I mentioned a premature duplicati-verification.json upload earlier. As expected it’s very confused about things:

PS C:\Program Files\Duplicati 2\utility-scripts> .\DuplicatiVerify.ps1 "C:\zFTPServer\SFTP test 1"
Verifying file: duplicati-verification.json
Verifying file duplicati-20180829T163417Z.dlist.zip
Verifying file duplicati-20180906T152449Z.dlist.zip
Verifying file duplicati-20180909T125449Z.dlist.zip
Verifying file duplicati-20180912T222326Z.dlist.zip
Verifying file duplicati-20180912T222514Z.dlist.zip
Verifying file duplicati-20180913T174743Z.dlist.zip
Verifying file duplicati-20180913T184645Z.dlist.zip
Verifying file duplicati-20180917T135817Z.dlist.zip
Verifying file duplicati-20180924T194939Z.dlist.zip
Verifying file duplicati-20180926T180231Z.dlist.zip
Verifying file duplicati-20180926T182557Z.dlist.zip
Verifying file duplicati-20180926T190447Z.dlist.zip
Verifying file duplicati-20180926T190938Z.dlist.zip
Verifying file duplicati-20180930T182333Z.dlist.zip
Verifying file duplicati-20181008T221933Z.dlist.zip
Verifying file duplicati-20181128T163757Z.dlist.zip
File missing: duplicati-20181128T170456Z.dlist.zip
File missing: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip
Verifying file duplicati-b2dc362dd4f62431391091a117256c441.dblock.zip
File missing: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip
File missing: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip
File missing: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip
Verifying file duplicati-i257753298c614dfcb86a5cade4a7ecff.dindex.zip
Found extra file which is not in verification file: duplicati-20181128T170458Z.dlist.zip

Errors were found

STATISTICS:
        Temporary - Count 0, Size 0.0 GB
        Uploading - Count 0, Size 0.0 GB
        Uploaded - Count 0, Size 0.0 GB
        Verified - Count 18, Size 0.0 GB
        Deleting - Count 0, Size 0.0 GB
        Deleted - Count 167, Size 0.0 GB

        Blocks - Count 72, Size 0.0 GB
        Files - Count 41, Size 0.0 GB
        Index - Count 72, Size 0.0 GB

PS C:\Program Files\Duplicati 2\utility-scripts>

EDIT: 2.0.4.5 beta on Windows
EDIT 2: duplicati-b2dc362dd4f62431391091a117256c441.dblock.zip and duplicati-i257753298c614dfcb86a5cade4a7ecff.dindex.zip went up at 11:38:04 in the previous backup which I thought about showing further, but didn’t…
EDIT 3: Reproduced this again with FTP and Filezilla server, turning off Write permission to make the dblock upload fail, then turning it on again to let the dlist and duplicati-verification.json file uploads through. I’ve not been able to reproduce this when the dlist also fails, which means the test case may be awkward for awhile… Here is me doing a test on that broken backup to see if the improved error message aimed correctly at which version to delete, and in this test it did, however the version was 0 (but perhaps it always is for this problem). Although I haven’t written up a full test case procedure yet, if anyone is eager to try, set --retry-delay to some human-friendly value (e.g. 60 seconds) and you don’t need to keep --number-of-retries at its default value 5.

2 Likes

I suspect it’s not always the case, such as during retention cleanup (which is where I think I bumped into mine).

Awesome work tracking stuff down!

So does Duplicati know when the dblock upload fails or does it think it succeeded and continues sending files?

I’m guessing the former as otherwise we could replicate the issue with a simple dblock deletion…