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.