Problems with repair


#1

Hi,

I’ve just finished a very long upload to S3. At the end of it, it turned out that one or two volume files had problems - no doubt due to our slightly unreliable internet connection. IIRC duplicati reported something about invalid headers for those files. Foolishly, I thought the best thing to do would be to delete them manually from S3 and then rerun. Obviously this caused an error in duplicati and prompted me to repair to fix the “missing remote file”. I tried this, but the repair failed and just reported the missing remote file again. So then I progressed to running recreate, but this fails with exactly the same error. I’m puzzled because I thought the whole point of repair/recreate was to fix these problems! What do I do now? I don’t have to have to upload all 180GB over our shakey Wimax connection again!

Here’s the result of the recreate operation:

MainOperation: Repair
RecreateDatabaseResults:
MainOperation: Repair
ParsedResult: Error
EndTime: 09/04/2018 08:05:08 (1523253908)
BeginTime: 09/04/2018 07:39:43 (1523252383)
Duration: 00:25:25.1435990
Messages: [
    2018-04-09 07:39:43 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
    2018-04-09 07:39:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-04-09 07:39:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6.12 KB),
    2018-04-09 07:40:40 +02 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 3 filelists,
    2018-04-09 07:40:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180106T133944Z.dlist.zip.aes (765 bytes),
...
]
Warnings: []
Errors: [
    2018-04-09 08:00:53 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-bec141752409545c1b6bd36f65f734722.dblock.zip.aes, but not found in list, registering a missing remote file
]
BackendStatistics:
    RemoteCalls: 3136
    BytesUploaded: 0
    BytesDownloaded: 125242963
    FilesUploaded: 0
    FilesDownloaded: 3135
    FilesDeleted: 0
    FoldersCreated: 0
    RetryAttempts: 0
    UnknownFileSize: 0
    UnknownFileCount: 0
    KnownFileCount: 0
    KnownFileSize: 0
    LastBackupDate: 01/01/0001 01:00:00 (-62135596800)
    BackupListCount: 0
    TotalQuotaSpace: 0
    FreeQuotaSpace: 0
    AssignedQuotaSpace: 0
    ReportedQuotaError: False
    ReportedQuotaWarning: False
    ParsedResult: Error
    Messages: [
        2018-04-09 07:39:43 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
        2018-04-09 07:39:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-04-09 07:39:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6.12 KB),
        2018-04-09 07:40:40 +02 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 3 filelists,
        2018-04-09 07:40:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180106T133944Z.dlist.zip.aes (765 bytes),
...
    ]
    Warnings: []
    Errors: [
        2018-04-09 08:00:53 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-bec141752409545c1b6bd36f65f734722.dblock.zip.aes, but not found in list, registering a missing remote file
    ]
ParsedResult: Error
EndTime: 09/04/2018 08:05:09 (1523253909)
BeginTime: 09/04/2018 07:39:43 (1523252383)
Duration: 00:25:25.8491800
Messages: [
2018-04-09 07:39:43 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
2018-04-09 07:39:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
2018-04-09 07:39:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6.12 KB),
2018-04-09 07:40:40 +02 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 3 filelists,
2018-04-09 07:40:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180106T133944Z.dlist.zip.aes (765 bytes),
...
]
Warnings: []
Errors: [
    2018-04-09 08:00:53 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-    MissingFileDetected]: Remote file referenced as duplicati-bec141752409545c1b6bd36f65f734722.dblock.zip.aes, but not found in list, registering a missing remote file
]

#2

Do you recall with what error the repair failed?

There have been a few reports lately of database recreates NOT actually solving a missing file issue, but I’m pretty sure all the successful database REPAIRS have handled it correctly.

Did you try a repair again after the recreate finished? Hopefully that will do the trick. (And yes, we realize this isn’t the best user experience - once we can pin down the exact cause of the issue we’ll hopefully be able to fix it.)


#3

Hi,

Unhelpfully the repair just fails with an “error” but records nothing in the log - whether or not I run the recreate first. However when I turn on verbose logging to a file, I get this from the repair operation:

2018-04-11 08:30:58 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started
2018-04-11 08:30:58 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2018-04-11 08:31:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6.12 KB)
2018-04-11 08:31:05 +02 - [Error-Duplicati.Library.Main.Operation.RepairHandler-CleanupMissingFileError]: Failed to perform cleanup for missing file: duplicati-bec141752409545c1b6bd36f65f734722.dblock.zip.aes, message: Unexpected empty block volume: duplicati-bec141752409545c1b6bd36f65f734722.dblock.zip.aes
System.Exception: Unexpected empty block volume: duplicati-bec141752409545c1b6bd36f65f734722.dblock.zip.aes
  at Duplicati.Library.Main.Database.LocalRepairDatabase+MissingBlockList..ctor (System.String volumename, System.Data.IDbConnection connection, System.Data.IDbTransaction transaction) [0x000ac] in <3ff9b0af6fdf48d2af885dde3389fb14>:0 
  at Duplicati.Library.Main.Database.LocalRepairDatabase.CreateBlockList (System.String volumename, System.Data.IDbTransaction transaction) [0x00000] in <3ff9b0af6fdf48d2af885dde3389fb14>:0 
  at Duplicati.Library.Main.Operation.RepairHandler.RunRepairRemote () [0x00bb9] in <3ff9b0af6fdf48d2af885dde3389fb14>:0

Any ideas how I sort this out?


#4

Unfortunately, I haven’t run into this error before…and while I see it in the code, but it’s not an area I’ve worked on before. Perhaps @kenkendk will have a suggestion…


#5

This happens because the file in question appears to have no content, which should not happen (meaning, Duplicati should not create such a file).

Does the file exist on S3?
If yes, what size is it? What happens if you remove it from S3 (please keep a copy elsewhere)?
If no, I think the problem is that Duplicati somehow “knows” that the file should be there even though it is not. When it then tries to figure out what contents are in that file, it fails (should be fixed in code then).


#6

Hi @kenkendk,

The file did exist, and was causing errors - I think something about a bad header but I’m afraid I don’t remember exactly. On inspection it turned out that the file was significantly smaller than any of the other volumes - possibly zero bytes, but again I’m afraid I don’t remember exactly. I decided to just delete it in the hope that duplicati would work out what would need re-uploading afterwards. Since then I’ve been getting the errors mentioned in this thread. Right now, the file does not exist on S3 according to the AWS web interface. I don’t have S3 versioning turned on so I can’t see any reason why S3 should report it as present even when it has been deleted. The files are all stored with the “infrequent access” policy if that makes a difference.

Let me know if there’s anything else I can do to help debug this.

Cheers,


#7

Sorry to bump @kenkendk, but is there any chance of some advice on what to do next on this? I have a non-functional backup right now that will take a month to recreate if I have to delete and start again. Should I raise a bug for this or would you prefer it handled on here? I’m just keen that it doesn’t end up getting lost because right now I’m totally stuck :frowning:

Thanks,