Backup always errors, rebuild won't work to clear the error, missing file


#1

I’m backing up to B2. At some point apparently one backup file went missing and now it won’t complete the backup and always errors out. I’ve rebuilt the database. I’ve deleted and rebuilt the database. I’ve done this all numerous times. No dice.

Here are the error messages:

    MainOperation: Repair
RecreateDatabaseResults:
    MainOperation: Repair
    ParsedResult: Error
    EndTime: 2018-04-23 8:54:52 AM (1524495292)
    BeginTime: 2018-04-23 7:58:49 AM (1524491929)
    Duration: 00:56:03.1059480
    Messages: [
        2018-04-23 07:58:49 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
        2018-04-23 07:58:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-04-23 07:58:57 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (9.06 KB),
        2018-04-23 07:59:04 -06 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 7 filelists,
        2018-04-23 07:59:04 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180406T154233Z.dlist.zip.aes (2.46 MB),
...
    ]
    Warnings: []
    Errors: [
        2018-04-23 08:34:09 -06 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b6607fac64a8142abb19dc50b570b83a4.dblock.zip.aes, but not found in list, registering a missing remote file
    ]
    BackendStatistics:
        RemoteCalls: 4645
        BytesUploaded: 0
        BytesDownloaded: 523933828
        FilesUploaded: 0
        FilesDownloaded: 4644
        FilesDeleted: 0
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 0
        KnownFileSize: 0
        LastBackupDate: 0001-01-01 12:00:00 AM (-62135571600)
        BackupListCount: 0
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: 0
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Error
        Messages: [
            2018-04-23 07:58:49 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
            2018-04-23 07:58:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-04-23 07:58:57 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (9.06 KB),
            2018-04-23 07:59:04 -06 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 7 filelists,
            2018-04-23 07:59:04 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180406T154233Z.dlist.zip.aes (2.46 MB),
...
        ]
        Warnings: []
        Errors: [
            2018-04-23 08:34:09 -06 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b6607fac64a8142abb19dc50b570b83a4.dblock.zip.aes, but not found in list, registering a missing remote file
        ]
ParsedResult: Error
EndTime: 2018-04-23 8:54:57 AM (1524495297)
BeginTime: 2018-04-23 7:58:49 AM (1524491929)
Duration: 00:56:08.2585830
Messages: [
    2018-04-23 07:58:49 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
    2018-04-23 07:58:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-04-23 07:58:57 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (9.06 KB),
    2018-04-23 07:59:04 -06 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 7 filelists,
    2018-04-23 07:59:04 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180406T154233Z.dlist.zip.aes (2.46 MB),
...
]
Warnings: []
Errors: [
    2018-04-23 08:34:09 -06 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b6607fac64a8142abb19dc50b570b83a4.dblock.zip.aes, but not found in list, registering a missing remote file
]

39%20AM


#2

Anyone? Any ideas? I’ve tried everything short of starting over (I do not want to do that) but nothing seems to allow it to continue.


#3

Where you able to verify directly on B2 that b6607fac64a8142abb19dc50b570b83a4 does not exist?

Just as a test to help isolate the possible cause of the error did you try running a backup with --no-backend-verification enabled?

--no-backend-verification
If this flag is set, the local database is not compared to the remote filelist on startup. The intended usage for this option is to work correctly in cases where the filelisting is broken or unavailable.
Default value: “false”


#4

I haven’t done either of those things. I’ll look to see if it exists on B2 but I suspect that the software is giving a correct message.

If I run with --no-backend-verification set to “true” and run a backup, what happens when I re-set it back to false? Will that same missing file still cause problems? Once going to “true” must it stay “true” to backup without problem? Are there any other ramifications of doing this?


#5

You can toggle --no-backend-verification on and off with no long term effects.

All it does is determine if, for that specific job run, the list (and possibly size / dates) of files from the destination will be compared against Duplicati’s local database thinks should be there.

What sometimes happens is that when Duplicati asks a destination (in your case B2) for a list of all the files in the destination folder, what gets sent back isn’t correct. In the past we’ve seen this happen due to:

  • provider bugs not list some files
  • provider bugs listing files multiple times
  • HTTP / provider timeouts causing the list to be truncated or not returned at all
  • provider being slow to list very newly created files as existing

Of course I’m not saying that’s what’s happening for you - just that it’s a possibility and a manual check is an easy way to verify whether or not that’s the issue.


#6

Tacking on to Jon’s advice, my hope would be that a successful backup run using --no-backend-verification would result in a ‘repaired’ file list / db, as it were, and the error wouldn’t manifest in the future. I’d hope you can try and report back, as I feel this is something the devs need to tweak to make more robust, but they need data from exception cases like yours to be able to be sure.


#7

I checked and that file does not exist in the B2 bucket. I’ll run with the --no-backend-verification turned on and see what happens.

One thing that doesn’t jive with Jon’s explanation, though: I did a database delete and repair. Shouldn’t that grab the data from the backup location and rebuild based on that alone? If not, what does deleting and repairing do?

Thanks again.


#8

This is only a guess but the one thing I can think of is, your remote index files refer to a volume that doesn’t exist (like via an interrupted backup job or some other weirdness), and in that case a DB repair may have accidentally re-included that nonexistent volume by name from the incorrect index file. Or something like that.


#9

So it’s backing up with the --no-backend-verfification flag set right now.

When I set that flag back to false after this backup, is it going to go back to erroring out?


#10

I guess what I was trying to say previously was, “i hope the errors will go away after this but you’ll have to try and let us know”.
Out of curiosity - how big is your total backup set on B2?


#11

222.59 GB is the database size on B2.


#12

Now I’m getting a different warning regarding deletion of files:

DeletedFiles: 97
DeletedFolders: 54
ModifiedFiles: 412
ExaminedFiles: 493725
OpenedFiles: 622
AddedFiles: 210
SizeOfModifiedFiles: 1877245464
SizeOfAddedFiles: 4789971
SizeOfExaminedFiles: 312127240506
SizeOfOpenedFiles: 1896047536
NotProcessedFiles: 0
AddedFolders: 67
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 5
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
    DeletedFileCount: 2
    DownloadedFileCount: 0
    UploadedFileCount: 0
    DeletedFileSize: 1323066
    DownloadedFileSize: 0
    UploadedFileSize: 0
    Dryrun: False
    MainOperation: Compact
    ParsedResult: Warning
    EndTime: 2018-04-26 10:05:04 AM (1524758704)
    BeginTime: 2018-04-26 10:04:18 AM (1524758658)
    Duration: 00:00:46.1235660
    Messages: [
        2018-04-26 09:47:00 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes,
        2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes (),
        2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.BackendManager-DeleteRemoteFileSuccess]: Listing indicates file duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes is deleted correctly,
        2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes,
...
    ]
    Warnings: [
        2018-04-26 09:48:20 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes with FileNotFound, listing contents,
        2018-04-26 09:48:35 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes with FileNotFound, listing contents
    ]
    Errors: []
    BackendStatistics:
        RemoteCalls: 26
        BytesUploaded: 530233297
        BytesDownloaded: 0
        FilesUploaded: 21
        FilesDownloaded: 0
        FilesDeleted: 3
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 9474
        KnownFileSize: 239009551588
        LastBackupDate: 2018-04-26 9:47:00 AM (1524757620)
        BackupListCount: 4
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Warning
        Messages: [
            2018-04-26 09:47:00 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes,
            2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes (),
            2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.BackendManager-DeleteRemoteFileSuccess]: Listing indicates file duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes is deleted correctly,
            2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes,
...
        ]
        Warnings: [
            2018-04-26 09:48:20 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes with FileNotFound, listing contents,
            2018-04-26 09:48:35 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes with FileNotFound, listing contents
        ]
        Errors: []
DeleteResults:
    DeletedSets: [
        Item1: 1
        Item2: 2018-04-26 2:24:25 AM (1524731065)
    ]
    Dryrun: False
    MainOperation: Delete
    ParsedResult: Warning
    EndTime: 2018-04-26 10:05:04 AM (1524758704)
    BeginTime: 2018-04-26 10:03:20 AM (1524758600)
    Duration: 00:01:44.1386920
    Messages: [
        2018-04-26 09:47:00 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes,
        2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes (),
        2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.BackendManager-DeleteRemoteFileSuccess]: Listing indicates file duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes is deleted correctly,
        2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes,
...
    ]
    Warnings: [
        2018-04-26 09:48:20 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes with FileNotFound, listing contents,
        2018-04-26 09:48:35 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes with FileNotFound, listing contents
    ]
    Errors: []
RepairResults: null
TestResults: null
ParsedResult: Warning
EndTime: 2018-04-26 10:05:04 AM (1524758704)
BeginTime: 2018-04-26 9:47:00 AM (1524757620)
Duration: 00:18:03.8017810
Messages: [
    2018-04-26 09:47:00 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes,
    2018-04-26 09:48:11 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes (),
    2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.BackendManager-DeleteRemoteFileSuccess]: Listing indicates file duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes is deleted correctly,
    2018-04-26 09:48:28 -06 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemovingStaleFile]: Removing remote file listed as Deleting: duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes,
...
]
Warnings: [
    2018-04-26 09:48:20 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-b7707650f88a344d394eb83d08f2a7438.dblock.zip.aes with FileNotFound, listing contents,
    2018-04-26 09:48:35 -06 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-i8faf951b9d494d96a6f5c8853aa00a09.dindex.zip.aes with FileNotFound, listing contents
]
Errors: []

Repeated "Delete operation failed" due to file not found
#13

I think it’s a good sign that you’re getting only warnings and not errors; it implies to me at least that the backup job is finishing correctly, and just that Duplicati is still confused by some mismatch where it thinks there should be files present for deletion that don’t actually exist.


#14

Sure. But how do I get a warning free backup, now?


#15

I’m hoping Jon or one of the other devs will weigh in now, though I suspect that one of the “purge” type options might do something. Or if you want to just get rid of the warnings manually, i think you could create empty files that exactly match the “missing” names, upload them to your destination, and let the backup job delete them next time around. I’d be curious to know how to get Duplicati to get there internally without such a manual workaround, but if you’re hungrier for the result than the “how” that might be the fastest bet.


#16

Unfortunately, the --no-backend-verification just disables the step that is throwing the errors, it doesn’t actually do anything to resolve it.


You are correct, a database repair alone should resolve such “files that are missing from the remote storage” type issues. I’m not really sure why it didn’t for you - and I know a few other people have reported this happening as well.

My guess is either:

  1. The real error is something else but getting caught / reported as a “missing files” problem (thus a repair / recreate isn’t fixing something that isn’t broken)

  2. There’s another issue on top of the “missing files” problem that causes the repair / recreate to not work correctly.

  3. There’s an edge case bug in the repair / recreate process that isn’t being properly identified and handled.


I ran into this situation last month when doing some simulated failure recoveries. In my case a Repair (not recreate) was all that was needed to resolve that issue, though I did suggest a warning resulting from failing to delete a file that couldn’t be found is OK to show ONCE but the file should then be considered deleted.


If @ksignorini is willing to test, it would be interesting to find out if this works. I’m torn on whether it will resolve the issue or move to a different set of warnings about the file sizes or dates being wrong.


#17

After rebuilding a few times, it finally resolved itself. That is to say, I still get occasional file not found warnings though when Duplicati tries to remove remote files, but at least they’re not errors. Weird.

At least it’s not erroring and the backup seems to complete.


#18

That’s odd, but it makes me wonder if the repair process can only handle one “layer” of issues at a time.

I suspect the “file not found” warnings are unrelated to the database stuff, though I could be wrong. If you care enough to look into it I’d suggest opening another ticket (if you haven’t already).

At least it’s working for you now. :slight_smile:

I went ahead and flagged your post as the “solution” - let me know if you disagree.