How to recover a backup set after hw failure?

Support
1

I have looked for information on my problem from the forum, and found similar symptoms, but could not find instructions on how to recover.

I have two backup sets scheduled to run so early in the morning that they kick off immediately when I open my laptop for the first time every day. This morning, I noticed that the extrenal USB disk had gotten unconnected, and I realized the backup would fail. I reconnected the disk and waited for the two backup jobs to finish. Turned out that the second job succeeded, and only the first one failed.

The warnings I got were all about files that had been “listed as Uploaded with size 0”, and the errors referred to the same thing. Unfortunately, I do not have the original wordings, because the UI shows only a limited range of logs, even from one single day. Anyway, the files mentioned in the messages were all marked as “remote file” and their extensions are “.dlist.zip.aes”, “.dblock.zip.aes” and “.dindex.zip.aes”. The warnings only list on file of each type. And indeed, the three files on the external drive are empty.

When I ran the backup again, I got the same warnings, but no errors anymore. To get rid of the warnings too, I decided to try and repair the local database. The operation gave the same warnings, plus error messages of “Invalid header marker” type. Of course the header markers are invalid, if the remote files are empty. After the repair, I tried running the backup again, and again it gave warnings, but no errors.

I pondered whether rebuilding the local database would help, since the empty files were remote ones. Running out of options, however, I decided to run the rebuild, and that was a mistake. After taking quite a while, the rebuild resulted in a failure. The browser UI was not even able to show me any “result” entries anymore, just messages.

Fortunately, the other backup that had succeeded in the morning was of my home directory (and the failed of a data partition), so I was able to restore the local database form backup.

Running local database repair on the restored local database file still fails, and running the backup again succeeds with warnings only. What can I do to get this situation properly resolved?

This log is from the latest repair:

MainOperation: Repair
RecreateDatabaseResults: null
ParsedResult: Error
EndTime: 20.5.2018 12:36:20 (1526808980)
BeginTime: 20.5.2018 12:34:11 (1526808851)
Duration: 00:02:08.8806970
Messages: [
    ignoring remote file listed as Deleted: duplicati-20180219T050028Z.dlist.zip.aes,
    ignoring remote file listed as Deleted: duplicati-20180219T175110Z.dlist.zip.aes
]
Warnings: [
    remote file duplicati-20180520T032906Z.dlist.zip.aes is listed as Uploaded with size 0 but should be 377469, please verify the sha256 hash "2V6/+jDHxcLbx+l6UKolfBQ1VwO/zA/woX3oe9Nkxek=",
    remote file duplicati-b1e6bc61726b243d19ad513f06bc0d636.dblock.zip.aes is listed as Uploaded with size 4194304 but should be 10960045, please verify the sha256 hash "NdMz6iz6/XopE/hipmE5EWz/sHXrtgWrTLeyUinx/KA=",
    remote file duplicati-i672488a1535041cdae235a1b50b74945.dindex.zip.aes is listed as Uploaded with size 0 but should be 36621, please verify the sha256 hash "YtSd9vMkpvGyRIzjQ90R3UWt07uvafLJPmkglnF9scg="
]
Errors: [
    Failed to perform verification for file: duplicati-20180520T032906Z.dlist.zip.aes, please run verify; message: Invalid header marker => Invalid header marker,
    Failed to perform verification for file: duplicati-b1e6bc61726b243d19ad513f06bc0d636.dblock.zip.aes, please run verify; message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.,
    Failed to perform verification for file: duplicati-i672488a1535041cdae235a1b50b74945.dindex.zip.aes, please run verify; message: Invalid header marker => Invalid header marker,
    Failed to accept new index file: duplicati-i2a343c9112b64780a60d1dc34eba5dcc.dindex.zip.aes, message: Volume duplicati-b8ec7f819fdfc41659d94886007abeb27.dblock.zip.aes has local state Deleting => Volume duplicati-b8ec7f819fdfc41659d94886007abeb27.dblock.zip.aes has local state Deleting,
    Failed to accept new index file: duplicati-i7bd434485c0f486c8ea88e69abb6607a.dindex.zip.aes, message: Volume duplicati-b2caa2fbff3904d08bb95214328fc5cad.dblock.zip.aes has local state Deleting => Volume duplicati-b2caa2fbff3904d08bb95214328fc5cad.dblock.zip.aes has local state Deleting
]
BackendStatistics:
    RemoteCalls: 25
    BytesUploaded: 489341
    BytesDownloaded: 41930
    FilesUploaded: 1
    FilesDownloaded: 2
    FilesDeleted: 6
    FoldersCreated: 0
    RetryAttempts: 12
    UnknownFileSize: 0
    UnknownFileCount: 0
    KnownFileCount: 812
    KnownFileSize: 13222677365
    LastBackupDate: 20.5.2018 11:20:10 (1526804410)
    BackupListCount: 170
    TotalQuotaSpace: 492217737216
    FreeQuotaSpace: 415482322944
    AssignedQuotaSpace: -1
    ReportedQuotaError: False
    ReportedQuotaWarning: False
    ParsedResult: Success

This log is from the latest backup:

DeletedFiles: 1
DeletedFolders: 0
ModifiedFiles: 31
ExaminedFiles: 4967
OpenedFiles: 45
AddedFiles: 14
SizeOfModifiedFiles: 43217794
SizeOfAddedFiles: 167404
SizeOfExaminedFiles: 3156682084
SizeOfOpenedFiles: 43707274
NotProcessedFiles: 0
AddedFolders: 5
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 1
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
    EndTime: 20.5.2018 12:43:31 (1526809411)
    BeginTime: 20.5.2018 12:43:19 (1526809399)
    Duration: 00:00:12.3842340
    BackendStatistics:
        RemoteCalls: 9
        BytesUploaded: 6101063
        BytesDownloaded: 52877399
        FilesUploaded: 3
        FilesDownloaded: 3
        FilesDeleted: 1
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 809
        KnownFileSize: 13218913358
        LastBackupDate: 20.5.2018 12:42:46 (1526809366)
        BackupListCount: 169
        TotalQuotaSpace: 492217737216
        FreeQuotaSpace: 415486091264
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
DeleteResults:
    DeletedSets: [
        Item1: 167
        Item2: 20.2.2018 6:47:46 (1519102066)
    ]
    Dryrun: False
    MainOperation: Delete
    ParsedResult: Success
    EndTime: 20.5.2018 12:43:31 (1526809411)
    BeginTime: 20.5.2018 12:43:14 (1526809394)
    Duration: 00:00:16.8943840
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20180520T035609Z.dlist.zip.aes
        Value: [],
        Key: duplicati-iae985c25691540208d25ed7d57438789.dindex.zip.aes
        Value: [],
        Key: duplicati-b7abd16bf7f4d41f7b142dea8e8c7c056.dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    EndTime: 20.5.2018 12:43:34 (1526809414)
    BeginTime: 20.5.2018 12:43:32 (1526809412)
    Duration: 00:00:01.8155420
ParsedResult: Warning
EndTime: 20.5.2018 12:43:34 (1526809414)
BeginTime: 20.5.2018 12:42:45 (1526809365)
Duration: 00:00:48.5627860
Messages: [
    ignoring remote file listed as Deleted: duplicati-20180219T050028Z.dlist.zip.aes,
    ignoring remote file listed as Deleted: duplicati-20180219T175110Z.dlist.zip.aes,
    Deleting 1 remote fileset(s) ...,
    Deleted 1 remote fileset(s),
    Compacting not required,
...
]
Warnings: [
    remote file duplicati-20180520T032906Z.dlist.zip.aes is listed as Uploaded with size 0 but should be 377469, please verify the sha256 hash "2V6/+jDHxcLbx+l6UKolfBQ1VwO/zA/woX3oe9Nkxek=",
    remote file duplicati-b1e6bc61726b243d19ad513f06bc0d636.dblock.zip.aes is listed as Uploaded with size 4194304 but should be 10960045, please verify the sha256 hash "NdMz6iz6/XopE/hipmE5EWz/sHXrtgWrTLeyUinx/KA=",
    remote file duplicati-i672488a1535041cdae235a1b50b74945.dindex.zip.aes is listed as Uploaded with size 0 but should be 36621, please verify the sha256 hash "YtSd9vMkpvGyRIzjQ90R3UWt07uvafLJPmkglnF9scg=",
    remote file duplicati-20180520T032906Z.dlist.zip.aes is listed as Uploaded with size 0 but should be 377469, please verify the sha256 hash "2V6/+jDHxcLbx+l6UKolfBQ1VwO/zA/woX3oe9Nkxek=",
    remote file duplicati-b1e6bc61726b243d19ad513f06bc0d636.dblock.zip.aes is listed as Uploaded with size 4194304 but should be 10960045, please verify the sha256 hash "NdMz6iz6/XopE/hipmE5EWz/sHXrtgWrTLeyUinx/KA=",
...
]
Errors: []
2

Hi @AimoE, welcome to the forum!

What version of Duplicati are you running and on what OS?

Just to make sure I’m following things, of your two backups only one was affected by the drive disconnect issue and that one is now running (doing backups) but always reporting warnings about many files being smaller than expected (are they always either 0 or 4194304 aka 4k)?

3

Oh, sorry I forgot to mention the version. It is Duplicati - 2.0.3.3_beta_2018-04-02 (on Ubuntu).

The warnings are always about the same zero size files; the same file names, the same expected size, the same 0 as the actual size. Since my original post, I have noticed that sometimes I also get an occasional error too, but always from these same three files, and always the main page reports the latest backup as the latest successful backup (the exact wording is in Finnish, so I hope I guessed the wording right).

I do not depend on Duplicati2 alone for my backups; I am running it alongside Déjà Dup (and on my Windows machine, alongside the old Duplicati version). I have been running it on both machines for several months now, and I am very happy with it. Those few times when I have had a need to restore files, I always prefer doing it with Duplicati2, on both machines.

The only thing that I wish to see some improvement on is the UI. Probably you’ll need to have one for ordinary users, and another for power users. But that is not an urgent need at this point.

4

Just to isolate the issue, could you try enabling–no-backend-verification to see if the warnings go away?

--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”

If they do, then you might want to turn the backend verification back on and do a run with --verbose enabled so you can get a list of all the affected files rather than the first 5.

5

Enabling –no-backend-verification did indeed make the warnings go away. And then, with that one disabled again, and running with --verbose, I still get the exact same set of warnings, nothing added to it.

6

Odd. Usually the “…” at the end of the Warnings block indicates there were more warnings to be seen.

If you look in the job log for the test run do you see more files listed there?

7

You mean the actual log file? I haven’t been able to locate one.

8

If you’re using the web GUI you should be able to expand the job “menu” and find a “Show log…” link just above the “Last successful run” line.

Once you’ve click on that you should get a list of log entries like this:
image

Clicking on one of them should expand it to show more results:
image

If you’re using the command line, then we’ll probably just want to add --log-file to the job and look at the resulting text file.

Though honestly you could just do that with the GUI as well. :slight_smile:

9

I don’t know how to quote a posting on this kind of forum, but I have used the UI method you describe, and it really does not show any more warnings, and yet ends with the three dots.

10

I tried adding the --log-file with a filename, but got an empty file. I also noticed that when I get the pop-up about the warnings, it says 6 warnings, but the log only contains 5 of them. Always.

11

Highlight the text you want to quite and a “quote” button should magically appear. :slight_smile:

Yep - I realized right after I posted that the the job log is pretty much the same as the email summary.

You could use the --log-file=\<path to file> parameter along with --log-file-log-level=profiling (or --log-level=profiling for pre-2.0.3.2).

Or I believe you can use use the global log then click the “Live” button and select an appropriate level such as Warning (should be enough) or Profiling (should be EVERYTHING).

12

OK, but the notice says there are 6 warnings, and I see 5 in the log. Two of them are repetitions, so I assume the missing one, the sixth, is also a repetition.

13

Sorry - I forgot to mention you probably need the --log-file-log-level=profiling parameter as well.

14

The UI shows it as --log-level. I tried it, and “profiling” together with --verify produced too much information to read. So I dropped out --verify and chose --log-level=warning and then realized that the log file is appended, not re-created. Blaah.

Finally, I just had --log-level=warning, without --verify, and got a log file that only has the six messages that the notification tells me about. And they are what I expected: there are these three files I get the warnings about, and each warning is doubled once.

I am tempted to move away the three files and then rebuild the local database, but I’ll wait for more informed advice.

15

BTW. It seems that the log file shows all timestamps in UTC, not in my local time zone. Since I use a local USB drive, not a cloud service, I kind of would prefer the local time zone.

Also, in the UI screen capture above, you had only Result lines listed. I very much would prefer to see only Result lines, but instead, I have lots of Message lines between the Result lines. I don’t know how to add a screen capture here, but I can tell that when I open these Message lines, they show individual messages that I also see embedded in the Result contents. Not just the warnings, but also other type of messages. If I could choose, I would like to see only Result lines, and all messages embedded in the contents that open up when I click on the result. I don’t need the separate Messages in the UI, they just distract me and make browsing more cumbersome.

16

From what I can tell the 3 files likely are a complete set (one each of dblock, dindex, dlist).

remote file duplicati-20180520T032906Z.dlist.zip.aes is listed as Uploaded with size 0 but should be 377469, please verify the sha256 hash "2V6/+jDHxcLbx+l6UKolfBQ1VwO/zA/woX3oe9Nkxek=",
remote file duplicati-b1e6bc61726b243d19ad513f06bc0d636.dblock.zip.aes is listed as Uploaded with size 4194304 but should be 10960045, please verify the sha256 hash "NdMz6iz6/XopE/hipmE5EWz/sHXrtgWrTLeyUinx/KA=",
remote file duplicati-i672488a1535041cdae235a1b50b74945.dindex.zip.aes is listed as Uploaded with size 0 but should be 36621, please verify the sha256 hash "YtSd9vMkpvGyRIzjQ90R3UWt07uvafLJPmkglnF9scg="

While deleting the files then rebuilding the database would make warnings go away, you would be removing part of your backups older versions of files. Of course if the remote files really are size 0 and 4194304 then their contents are probably invalid anyway.

A database rebuild can take quite a while depending on how much data you’ve got in your destination - a faster (though harder to implement) solution would be to use the list-broken-files (see what files would be removed) and purge-broken-files (actually remove files) commands.

The reason my screenshot only showed Results entries is because I’m not having an warnings / errors in my backups - there is currently no way to filter the GUI based logs to specific message types OTHER than in the global “Live” log. And you already figured out how to adjust what gets written to the text log.

Sorry about that - there was a change in parameters right around your version of Duplicati and I used the wrong one. I’m glad you figured out what I meant. :+1:

The newer parameters support even more filter levels (both in Live and text logs) as well as the ability to filter for specific message type text.

17

Thank you, this is the kind of advice I came here for. I will try those.

Edit: I already noticed the comment on list-broken-files and purge-broken being commands, not options.

Rest of the discussion in this thread I will try to summarize for feedback on user experience. For example, it is frustrating that I had to run the backup several times to get to the log file. When I run to a problem, I want to get the original log opened up properly. When I have to run a new backup, the log I get is not from the same run - bad logic. That sort of things I will try to summarize once I get rid of the warnings.

Well, as I told, they are not all that remote to me, as they are on my external USB drive, so I know for sure they are zero size.

18

Running list-broken-files has taken more than an hour now, and still continues. Is the purge command going to take as much time? I would very much appreciate a progress indicator with such slow operations.

19

Duration varies a lot based on system resources, bandwidth (local USB for you), sqlite databse size, and destination file size so it’s hard to say what’s expected.

Yes - some of the progress bars are not optimized for these operations so when a single step (or set of steps between log updates) takes a long time there is no progress bar update. Until that is address the best way to know what’s going on to look at the global “About” page and select one of these:

  • “Show log” page and select the “Live” button and “Profiling” filter
  • “System info” button, scroll down to the “Server state properties” section, and watch what appears in the “lastPgEvent” line (it will update with each command processed)
20

Yesterday I had to abort the listing. Today I started it again.

Neither of these show any kind of activity from yesterday or now, as I am running list-broken-files again. Yet top and htop (the Ubuntu/Linux monitoring tools) both show the process “mono-sgen” hogging about 100% of cpu.

That answr does not match what I see. On my windows machine, I see only Result lines for all my backup sets, but on the Ubuntu machine, I always see multiple Message lines between the Result lines. If there are no problems in the run, and I open the messages to see what they signify, I see the same messages that I see in the log, for example:

Messages: [ 
  Deleting 2 remote fileset(s) ..., 
  Deleted 2 remote fileset(s), 
  Compacting because there are 3 fully deletable volume(s), 
  Deleted 6 files, which reduced storage by 124,16 MT, 
  removing file listed as Temporary: duplicati-b663de174a7084e9cbcd2e4cbee6aad79.dblock.zip.aes, 
... ]

except the Message lines between Result lines show these messages in reverse order.

I there were warnings or errors in the run, they appear merged with the other messages, apparently in the (reversed) chronological order. Yet they are all are labelled Message. Listing the messages listing would be a bit more helpful if the warnings were labelled Warning and errors Error, but no, they all show up as Message in the list.

I have different version of Duplicati2 on my Windows machine, by the way. The latest beta version either didn’t install properly or just didn’t work, I cannot remember which, but anyway, I then installed the latest canary (Duplicati - 200.3.4_canary_2018-04-02), and that one seems to be working fine.