Unexpected number of remote volumes marked as deleted

Support
1

Hi there,
Since 4 days I get his message while daily backup:

Error while running Tagessicherung
Unexpected number of remote volumes marked as deleted. Found 4 filesets, but 3 volumes

The protocol reports:

  1. Aug. 2021 11:12: Failed while executing “Backup” with id: 1
    System.Exception: Unexpected number of remote volumes marked as deleted. Found 4 filesets, but 3 volumes
    bei Duplicati.Library.Main.Database.LocalDeleteDatabase.d__5.MoveNext()
    bei System.Linq.Buffer1..ctor(IEnumerable1 source)
    bei System.Linq.Enumerable.ToArray[TSource](IEnumerable1 source) bei Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBackend, Boolean forceCompact, BackendManager sharedManager) bei Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize) bei Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() --- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde --- bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() bei CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task) bei Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result) bei Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action1 method)
    bei Duplicati.Library.Main.Controller.Backup(String inputsources, IFilter filter)
    bei Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)

The existing topics don’t help me.
My current version is 2.0.6.3_beta_2021-06-17.

Any ideas are welcome.

best regards
Emanuel

2

Are you just reading or have you tried things? If so, what?

3

I didn’t try anything because I didn’t find the cause of this error.

4

It’s strange…
After 5 days failing daily backup, today the daily backup ran trough without problems.
Just a duplicati hickup?

5

This is an internal self-check seen here complaining about two SQL table operations not giving identical results unexpectedly when some versions were deleted. If it tried this many at once, perhaps you are on Smart backup retention or Custom backup retention? You can see table changes in log files, e.g.:

2021-08-30 09:43:03 -04 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: 8/29/2021 9:40:04 AM, 8/23/2021 9:40:00 AM
2021-08-30 09:43:03 -04 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 2 remote fileset(s) ...
2021-08-30 09:43:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "Timestamp" IN (1630244404,1629726000) 
2021-08-30 09:43:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "Timestamp" IN (1630244404,1629726000)  took 0:00:00:00.018
2021-08-30 09:43:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" NOT IN (SELECT DISTINCT "ID" FROM "Fileset")
2021-08-30 09:43:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" NOT IN (SELECT DISTINCT "ID" FROM "Fileset") took 0:00:00:00.165
2021-08-30 09:43:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "ChangeJournalData" WHERE "FilesetID" NOT IN (SELECT DISTINCT "ID" FROM "Fileset")
2021-08-30 09:43:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "ChangeJournalData" WHERE "FilesetID" NOT IN (SELECT DISTINCT "ID" FROM "Fileset") took 0:00:00:00.000
2021-08-30 09:43:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "FileLookup" WHERE "ID" NOT IN (SELECT DISTINCT "FileID" FROM "FilesetEntry") 
2021-08-30 09:43:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "FileLookup" WHERE "ID" NOT IN (SELECT DISTINCT "FileID" FROM "FilesetEntry")  took 0:00:00:00.027
2021-08-30 09:43:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "ID" NOT IN (SELECT DISTINCT "MetadataID" FROM "FileLookup") 
2021-08-30 09:43:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "ID" NOT IN (SELECT DISTINCT "MetadataID" FROM "FileLookup")  took 0:00:00:00.015
2021-08-30 09:43:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" NOT IN (SELECT DISTINCT "BlocksetID" FROM "FileLookup" UNION SELECT DISTINCT "BlocksetID" FROM "Metadataset") 
2021-08-30 09:43:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" NOT IN (SELECT DISTINCT "BlocksetID" FROM "FileLookup" UNION SELECT DISTINCT "BlocksetID" FROM "Metadataset")  took 0:00:00:00.076
2021-08-30 09:43:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" NOT IN (SELECT DISTINCT "ID" FROM "Blockset") 
2021-08-30 09:43:05 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" NOT IN (SELECT DISTINCT "ID" FROM "Blockset")  took 0:00:00:01.150
2021-08-30 09:43:05 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "BlocksetID" NOT IN (SELECT DISTINCT "ID" FROM "Blockset") 
2021-08-30 09:43:05 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "BlocksetID" NOT IN (SELECT DISTINCT "ID" FROM "Blockset")  took 0:00:00:00.024
2021-08-30 09:43:05 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "DeletedBlock" ("Hash", "Size", "VolumeID") SELECT "Hash", "Size", "VolumeID" FROM "Block" WHERE "ID" NOT IN (SELECT DISTINCT "BlockID" AS "BlockID" FROM "BlocksetEntry" UNION SELECT DISTINCT "ID" FROM "Block", "BlocklistHash" WHERE "Block"."Hash" = "BlocklistHash"."Hash") 
2021-08-30 09:43:05 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "DeletedBlock" ("Hash", "Size", "VolumeID") SELECT "Hash", "Size", "VolumeID" FROM "Block" WHERE "ID" NOT IN (SELECT DISTINCT "BlockID" AS "BlockID" FROM "BlocksetEntry" UNION SELECT DISTINCT "ID" FROM "Block", "BlocklistHash" WHERE "Block"."Hash" = "BlocklistHash"."Hash")  took 0:00:00:00.712
2021-08-30 09:43:05 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "ID" NOT IN (SELECT DISTINCT "BlockID" FROM "BlocksetEntry" UNION SELECT DISTINCT "ID" FROM "Block", "BlocklistHash" WHERE "Block"."Hash" = "BlocklistHash"."Hash") 
2021-08-30 09:43:19 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Block" WHERE "ID" NOT IN (SELECT DISTINCT "BlockID" FROM "BlocksetEntry" UNION SELECT DISTINCT "ID" FROM "Block", "BlocklistHash" WHERE "Block"."Hash" = "BlocklistHash"."Hash")  took 0:00:00:13.174
2021-08-30 09:43:19 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "State" = "Deleting" WHERE "Type" = "Files" AND "State" IN ("Uploaded", "Verified", "Temporary") AND "ID" NOT IN (SELECT "VolumeID" FROM "Fileset") 
2021-08-30 09:43:19 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "State" = "Deleting" WHERE "Type" = "Files" AND "State" IN ("Uploaded", "Verified", "Temporary") AND "ID" NOT IN (SELECT "VolumeID" FROM "Fileset")  took 0:00:00:00.014

A fairly light log (at Information level) shows the decision to delete two filesets (backup versions), then at profiling level note the DELETE FROM "Fileset" WHERE "Timestamp" IN (1630244404,1629726000). At the end, the UPDATE "RemoteVolume" SET "State" = "Deleting" presumably updated two rows in the RemoteVolume table, otherwise a message like yours would have been seen. Finding a cause is often difficult unless one has logs, e.g. log-file=<path> with log-file-log-level=Information (and ideally far higher).
A database bug report (posted for exam) or exam by you would help. Even better is a time-series of them.

Typically nobody has kept enough information to find cause, but you might consider at least keeping a log. Sometimes people are less interested in finding cause (great if you can find it), and just want to get going.

At least one person was able to do a database Recreate, and suspected issue was related to destination having had some communication errors (which you might see in your log, especially if it was Retry level).