Backup failure: Detected files associated with non-existing blocksets

I have a daily backup running that has started throw this error: Detected files associated with non-existing blocksets!

I am running 2.0.4.5 (2.0.4.5_beta_2018-11-28) on macOS High Sierra

Full error:

Failed: Detected files associated with non-existing blocksets!
Details: System.Exception: Detected files associated with non-existing blocksets!
at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (System.Int64 blocksize, System.Int64 hashsize, System.Boolean verifyfilelists, System.Data.IDbTransaction transaction) [0x001b7] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass32_0.<VerifyConsistencyAsync>b__0 () [0x00000] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass3_0.<RunOnMain>b__0 () [0x00000] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.Common.SingleRunner.DoRunOnMain[T] (System.Func`1[TResult] method) [0x000b0] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x01031] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <6973ce2780de4b28aaa2c5ffc59993b1>:0 
at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x00008] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Controller+<>c__DisplayClass13_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00035] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0011d] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 

Log data:
2019-08-01 11:47:26 +02 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Exception: Detected files associated with non-existing blocksets!
at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (System.Int64 blocksize, System.Int64 hashsize, System.Boolean verifyfilelists, System.Data.IDbTransaction transaction) [0x001b7] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass32_0.<VerifyConsistencyAsync>b__0 () [0x00000] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass3_0.<RunOnMain>b__0 () [0x00000] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.Common.SingleRunner.DoRunOnMain[T] (System.Func`1[TResult] method) [0x000b0] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 
at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x003d6] in <c6c6871f516b48f59d88f9d731c3ea4d>:0

Before I start groping about, what does this problem mean and what can/should I do about it?

Nobody?

I really need to find out and the manual is silent about it.I had a look in the code to find the string and it seems to have to do with a corruption in the local database. And given that it isn’t supposed to happen, might this be a duplicati bug?

Seems reasonable by definition, but it’s also a rarely seen bug, and these are often extremely hard to find. Only report in forum or issues appears to be this, and your Backup failure: Detected files associated with non-existing blocksets #3850. Have you found others? In the source of VerifyConsistency, this self-check appears just below another that’s seen more often, but still has never been reproducible reliably by either users or developers. I can point to some debug methods. Long and latest is below, but there were others:

Fatal error: Detected non-empty blocksets with no associated blocks

Can you inspect and post the default backup log from the last seemingly successful backup or operation? Because the database is verified before further use, the verification sometimes finds errors added earlier. Ideally preparing for analysis of a problem would have copies of the database before and after corruption, along with hugely detailed logfile, but that’s too heavy to be done routinely unless one is chasing an issue.

You could consider posting a link to a database bug report which is pretty well sanitized for path names in 2.0.4.5 or 2.0.4.23 beta (basically the same), but less so in some other canary and experimental releases. Possibly that would offer some slight clues on how things got how they are, but there’s often no substitute for being able to reproduce the problem on a developer’s system where they can examine it as they wish. This is really what a GitHub issue would prefer in “Steps to reproduce” – how to reproduce it from scratch.

Can you inspect and post the default backup log from the last seemingly successful backup or operation?

Sure, I’m happy to help (in fact, unless this is solved and the performance problems I’m having, I’m afraid to move fully to Duplicati and will have to keep CrashPlan around).

But what exactly do you mean by “default backup log from the last seemingly successful backup”? Exactly what file am I looking for?

I’ll try to create a database bug report.

How long is a debug run supposed to run? A normal run for that backup is around 9 minutes. Currently, mono-sgen has been running at 100% of a core for almost 60 minutes while the UI says “Creating bug report”.

It takes longer because it is sanitizing file path information and then it also vacuums the database.

A backup (and most other operations) leave a log in the Reporting → Show log menu of backup GUI. One can also have such logs emailed, and I think you sometimes get a more detailed set of lines on any errors. Emailed reports (like other things that might help) must be set in advance. I’m now looking for what exists.

What I’m looking for is at least one log before the problem was noticed, because that may be where it may have been seeded. So for example, a Tuesday backup log might provide clues about an error Wednesday. These would most easily be had by copy-and-paste from the browser. Putting three tildes before and after will help keep the line-oriented format more legible (not all run together in a word-wrap style like other text).

Unless you can figure out what happened and how to reproduce it (ideal), collecting afterwards is the plan.

I let the database debug run but while it was running my Mac paniced. Reason yet unknown, I will have to investigate.

The log of the last successful backup is:

DeletedFiles: 15
DeletedFolders: 0
ModifiedFiles: 121
ExaminedFiles: 216437
OpenedFiles: 140
AddedFiles: 19
SizeOfModifiedFiles: 204677483
SizeOfAddedFiles: 1519808
SizeOfExaminedFiles: 17666966535
SizeOfOpenedFiles: 206247307
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
    DeletedFileCount: 0
    DownloadedFileCount: 0
    UploadedFileCount: 0
    DeletedFileSize: 0
    DownloadedFileSize: 0
    UploadedFileSize: 0
    Dryrun: False
    MainOperation: Compact
    ParsedResult: Success
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    EndTime: 7/31/2019 10:36:31 AM (1564562191)
    BeginTime: 7/31/2019 10:36:18 AM (1564562178)
    Duration: 00:00:12.5053110
    Messages: [
        2019-07-31 10:27:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2019-07-31 10:28:11 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-07-31 10:28:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (404 bytes),
        2019-07-31 10:35:16 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
        2019-07-31 10:35:30 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
...
    ]
    Warnings: []
    Errors: []
    BackendStatistics:
        RemoteCalls: 9
        BytesUploaded: 20813671
        BytesDownloaded: 20715703
        FilesUploaded: 3
        FilesDownloaded: 3
        FilesDeleted: 1
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 406
        KnownFileSize: 9363578046
        LastBackupDate: 7/31/2019 10:27:00 AM (1564561620)
        BackupListCount: 12
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
        Messages: [
            2019-07-31 10:27:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2019-07-31 10:28:11 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2019-07-31 10:28:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (404 bytes),
            2019-07-31 10:35:16 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
            2019-07-31 10:35:30 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
...
        ]
        Warnings: []
        Errors: []
DeleteResults:
    DeletedSets: [
        Item1: 1
        Item2: 7/31/2019 9:27:00 AM (1564558020)
    ]
    Dryrun: False
    MainOperation: Delete
    ParsedResult: Success
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    EndTime: 7/31/2019 10:36:31 AM (1564562191)
    BeginTime: 7/31/2019 10:36:04 AM (1564562164)
    Duration: 00:00:26.4805850
    Messages: [
        2019-07-31 10:27:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2019-07-31 10:28:11 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-07-31 10:28:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (404 bytes),
        2019-07-31 10:35:16 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
        2019-07-31 10:35:30 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
...
    ]
    Warnings: []
    Errors: []
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20190731T082700Z.dlist.zip.aes
        Value: [],
        Key: duplicati-ice3730ea6dd24330b63cef37884615f2.dindex.zip.aes
        Value: [],
        Key: duplicati-ba6ed4da4f1f444e89bfde716007d36bd.dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    EndTime: 7/31/2019 10:36:52 AM (1564562212)
    BeginTime: 7/31/2019 10:36:38 AM (1564562198)
    Duration: 00:00:14.3614110
    Messages: [
        2019-07-31 10:27:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2019-07-31 10:28:11 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-07-31 10:28:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (404 bytes),
        2019-07-31 10:35:16 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
        2019-07-31 10:35:30 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
...
    ]
    Warnings: []
    Errors: []
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 7/31/2019 10:36:52 AM (1564562212)
BeginTime: 7/31/2019 10:27:00 AM (1564561620)
Duration: 00:09:52.3065040
Messages: [
    2019-07-31 10:27:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2019-07-31 10:28:11 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2019-07-31 10:28:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (404 bytes),
    2019-07-31 10:35:16 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
    2019-07-31 10:35:30 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b78cf3cfe23d44e0a8cb77125bcd75cf9.dblock.zip.aes (2.08 MB),
...
]
Warnings: []
Errors: []

This backup runs every hour.

That log looks fine at first glance. Didn’t see special things like errors or warnings or retries or a compact.

I am returning to this backup issue (there are now so many of my test backup machines in trouble that I am starting to worry about duplicati). What should I do in case of Detected files associated with non-existing blocksets!?

I have upgraded to 2.0.4.34_canary and tried a repair database, which returned quickly and solved nothing. This corruption may even be a bigger issue than my other one.

Log data:

System.Exception: Detected files associated with non-existing blocksets!
  at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (System.Int64 blocksize, System.Int64 hashsize, System.Boolean verifyfilelists, System.Data.IDbTransaction transaction) [0x001b6] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass34_0.<VerifyConsistencyAsync>b__0 () [0x00000] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass3_0.<RunOnMain>b__0 () [0x00000] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Library.Main.Operation.Common.SingleRunner.DoRunOnMain[T] (System.Func`1[TResult] method) [0x000b0] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x01033] in <759bd83d98134a149cdf84e129a07d38>:0 
  at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <9a758ff4db6c48d6b3d4d0e5c2adf6d1>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00009] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0004b] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0026f] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Library.Main.Controller.Backup (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x00074] in <759bd83d98134a149cdf84e129a07d38>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00349] in <63a01150aadd4a64a4d7c359bdc1e45d>:0

CheckingErrorsForIssue1400 and FoundIssue1400Error test case, analysis, and proposal #3868 describes an issue where a backup of a file that is growing at the time can pick up a momentary file ending, record it as a short file block, then get confused when the file later has more data to record.

v2.0.4.24-2.0.4.24_canary_2019-09-02

Fixed sporadic issue with backups of files being written, thanks @BlueBlock

If Repair isn’t able to fix this, then it’s possibly going to need some extensive manual database work, because the error message doesn’t give specifics. If bad file is identifiable, possibly it can be purged.

DB Browser for SQLite can open the database, then the starter SQL is given in this profling level log:

2019-11-24 08:30:50 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "CalcLen", "Length", "A"."BlocksetID", "File"."Path" FROM (
SELECT 
    "A"."ID" AS "BlocksetID", 
    IFNULL("B"."CalcLen", 0) AS "CalcLen", 
    "A"."Length"
FROM
    "Blockset" A
LEFT OUTER JOIN
    (
        SELECT 
            "BlocksetEntry"."BlocksetID",
            SUM("Block"."Size") AS "CalcLen"
        FROM
            "BlocksetEntry"
        LEFT OUTER JOIN
            "Block"
        ON
            "Block"."ID" = "BlocksetEntry"."BlockID"
        GROUP BY "BlocksetEntry"."BlocksetID"
    ) B
ON
    "A"."ID" = "B"."BlocksetID"

) A, "File" WHERE "A"."BlocksetID" = "File"."BlocksetID" AND "A"."CalcLen" != "A"."Length" 

VerifyConsistency looks like it uses above to find a problem list, then looks into them more, including:

EDIT: Corrected to point slightly lower to correct message, where it’s unclear it’s fixed, but it might be.

where that COUNT(*) waters things down to just a count. Running it by hand as * might get us further.
This is all untested territory for me though, so it could take some doing and might still come up empty.

Less precise options include assuming new problem is in the latest version (–version=0), so delete it.

There’s a chance Recreate might fix things, depending on whether the issue has gotten into backend.

Ultimate solution is to start new backup, and probably stay on 2.0.4.34 Canary, and avoid Stop button.
Change Settings back to Beta if you like, or just stay on Canary and help test a bleeding-edge release.

I was able to get this repaired (I think delete and recreate). Surprisingly, I’ve got all my test backups running again after 4-5 months not having enough time to spend on it and with a move to canary.