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.