Recreating database/downloading blocks for days

algebro · July 27, 2019, 9:52pm

So I finally managed to get my backup into B2 without errors, but within a couple of days my nightly backup got stuck at “waiting for upload to finish”. I watched the network traffic in ksysguard and there was no evidence that anything was actually being uploaded, and the live log didn’t indicate any activity either. After about 12 hours I stopped the backup and tried to repair the database to make sure there weren’t any issues, and this ended up triggering a recreate for some reason.

The problem now is that it’s been recreating the database for a few days, it’s just constantly downloading dblocks and doesn’t seem to be making any real progress. Now that ACD is shutting down and I’m using B2 this is concerning since I’m paying for this download bandwidth. The whole backup is only 150gb so I don’t quite understand why it’s downloading so much data to recreate the db.

Has anyone run into this and been able to fix it? I’m not really sure what to do at this point, but I’ve been running into nonstop issues with duplicati + B2 and am at the point where I’m beginning to look at other solutions.

Thanks!

algebro · July 28, 2019, 3:02am

I just checked again, and oddly enough after 3 days it just appears to be hanging again on the recreating db phase. Last entry in the live log was a GET 4 hours ago, but it appears to have stalled with no network activity in the system monitor.

ts678 · July 29, 2019, 6:42pm

What Duplicati version is this? There’s a bug in the current beta (fixed in canary and experimental) that might explain those dblock downloads. Empty source file can make Recreate download all dblock files fruitlessly with huge delay #3747. For hangs, do you have any sense of how well B2 is working for you?

Here is a sampling of errors I was having on B2, but it’s hard to know what’s B2, and what’s the network. Backup log will show you “RetryAttempts” in “BackendStatistics”. Retries can cover problems up to their limit which could be raised by –number-of-retries and –retry-delay to try to ride through troubled periods.

I haven’t tested it, but it might be possible to put a safety timer with –http-operation-timeout at something longer than your network will ever normally take to upload or download a remote volume (50 MB default).

algebro · July 29, 2019, 6:58pm

I’m currently using 2.0.4.22 canary.

B2 is…ok. I see periodic retries but no serious indications from the live logs that there are any major problems. I’m on day 3 of a db repair now and I haven’t seen any hangs, so that could’ve been a freak accident. The bigger problem is the recreate operation has already downloaded well over 100gb of a ~150gb backup set, but I’m trying to let it finish for science, since I’m curious to see if it can fix itself after all that.

alsoeric · July 30, 2019, 3:42am

I’m having a similar problem with Duplicati - 2.0.4.23_beta_2019-07-14 on server 2016 standard and server 2008r2. It looks like it takes about 5 minutes between blocks. cpu is low, disk and network are moderately busy. looks like the network activity is mostly smb and rdp with a bunch between firefox and the Duplicati.GUI.traylcon.

disk io varies with a lot of traffic on:
C:\Users\aoxford\AppData\Local\Temp\3etilqs_teO5vPUeSIUHTt1
C:\Users\aoxford\AppData\Local\Temp\3etilqs_NsTcaaf8eYpqTFG
C:\Users\aoxford\AppData\Local\Temp\3\etilqs_IJT6npwD4PfYejL|0
C:\Users\aoxford\AppData\Roaming\Mozilla\Firefox\Profiles\0e584ul9.default\cookies.sqlite-wal

Remote storage is WD MyCloud EX4100 box, 1gb ethernet.

suggestions on what to look at would be helpful

drwtsn32 · July 30, 2019, 4:46am

Unfortunately that version suffers from the bug @ts678 is talking about a couple posts up. That version is basically identical to 2.0.4.5 with a warning about Amazon Cloud Drive.

That particular bug was presumably fixed in later Canary builds. One thing you could try is switching to version 2.0.4.22 and try to recreate again. Hopefully your recreate will be faster. (Note that 2.0.4.22 is a canary version so in some other ways it MAY be less reliable than a beta version, but in my experience this particular canary version is pretty solid.)

alsoeric · July 30, 2019, 12:03pm

ok, thanks. That explains why I was having the same problem with v2.0.4.5-2.0.4.5_beta_2018-11-28. I was rebuilding the database because because I was seeing “Detected non-empty blocksets with no associated blocks!” errors.

shalmirane · July 30, 2019, 1:23pm

I got some suggestions to same problem in Database repair - taking days thread, have to yet explore all links posted there. Maybe it will help you (or your investigations will help me ) too.

alsoeric · July 30, 2019, 11:04pm

I’ll help where I can. The change to 2.0.4.22 seemed promising at first but now it is back to the “stuck at 90%” level processing one block every five minutes. I’ll investigate more later and see what I come up with.

ts678 · July 31, 2019, 1:05am

The false-positive empty-file bug was fixed in v2.0.4.18-2.0.4.18_canary_2019-05-12 and so should be in 2.0.4.22 canary and also v2.0.4.21-2.0.4.21_experimental_2019-06-28 for those who think canary is risky (which would be accurate – or at least it’s very raw and unpredictable – I agree 2.0.4.22 is behaving well).

If you’re in the 90% to 100% range, and still looking for dblocks, some other information might be missing.

drwtsn32 · July 31, 2019, 1:14am

I agree try to give it more time if you’re at 90%… It may only need to download a small number of blocks. Actually I believe the live log will show how many it needs to download…

shalmirane · July 31, 2019, 5:22am

Unfortunately it doesn’t - you get the number of the blocks and then individual get/completed lines, but you have to count them by yourself somewhere else.

[Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingAllBlocklistVolumes]: Processing all of the 4054 volumes for blocklists
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b0016694892b841eeba63a1f669dd2929.dblock.zip.aes (127.98 MB)
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b0016694892b841eeba63a1f669dd2929.dblock.zip.aes (127.98 MB)
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b00294df02ade49f2a8121e4f29ff2256.dblock.zip.aes (127.91 MB)
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b00294df02ade49f2a8121e4f29ff2256.dblock.zip.aes (127.91 MB)

drwtsn32 · July 31, 2019, 9:13pm

You’re right. I’m doing a recreate now and it said it has to download 150 files to get some missing info. Would be nice if it included “X of Y” for each of the download lines.

Sucks that your recreate says it has to download ALL volumes.

shalmirane · July 31, 2019, 10:04pm

Yeah, I would kinda think that dlist / dindex files contain all necessary data and dblock only actual binary blobs… Have to download some of them manually to actually check for that

There was also pause 14-18 minutes between Completed of one dblock and Started another dblock, probably related to some done with dblock mentioned above.

drwtsn32 · July 31, 2019, 10:12pm

I’m not super familiar with how the database recreate process works, but from what I understand it SHOULD only need dindex and dlist files. If Duplicati detects some info missing from those two types of files (not sure what kind of missing info), it will grab some dblocks.

I do remember seeing a special case in the code where Duplicati decides it has to download ALL dblocks. I don’t remember the circumstances.

Mine is taking 2-3 minutes after dblock download to process it before moving to the next dblock. (My dblocks are 50MB.) So… 20-30 per hour will take 5-7 hours to rebuild. If you have over 4000 blocks and they are taking 14-18 minutes each… well, yikes.

ts678 · August 1, 2019, 8:38pm

Lead author says it should just need dlist and dindex, but code is apparently in should-not-happen work.

github.com

duplicati/duplicati/blob/cd27a175000932209d6af415000493d9c4af68cb/Duplicati/Library/Main/Operation/RecreateDatabaseHandler.cs#L419-L439


// Grab the list matching the pass type

var lst = restoredb.GetMissingBlockListVolumes(i, m_options.Blocksize, hashsize).ToList();

if (lst.Count > 0)

{

    var fullist = ": " + string.Join(", ", lst.Select(x => x.Name));

    switch (i)

    {                                

        case 0:

            Logging.Log.WriteVerboseMessage(LOGTAG, "ProcessingRequiredBlocklistVolumes", "Processing required {0} blocklist volumes{1}", lst.Count, fullist);

            Logging.Log.WriteInformationMessage(LOGTAG, "ProcessingRequiredBlocklistVolumes", "Processing required {0} blocklist volumes{1}", lst.Count, m_options.FullResult ? fullist : string.Empty);

            break;

        case 1:

            Logging.Log.WriteVerboseMessage(LOGTAG, "ProbingCandicateBlocklistVolumes", "Probing {0} candidate blocklist volumes{1}", lst.Count, fullist);

            Logging.Log.WriteInformationMessage(LOGTAG, "ProbingCandicateBlocklistVolumes", "Probing {0} candidate blocklist volumes{1}", lst.Count, m_options.FullResult ? fullist : string.Empty);

            break;

        default:

            Logging.Log.WriteVerboseMessage(LOGTAG, "ProcessingAllBlocklistVolumes", "Processing all of the {0} volumes for blocklists{1}", lst.Count, fullist);

            Logging.Log.WriteVerboseMessage(LOGTAG, "ProcessingAllBlocklistVolumes", "Processing all of the {0} volumes for blocklists{1}", lst.Count, m_options.FullResult ? fullist : string.Empty);

            break;

    }

}

ProcessingAllBlockListVolumes is the 90%-100% final measure. Earlier were 70%-80% and 80%-90%.
Keeping a log might show how much the first two passes tried. The third pass can get large, I suspect.

algebro · August 2, 2019, 7:00pm

Thanks for all the information guys. At this point after wrestling with Duplicati and corrupt DB’s for close to a month, I’ve decided to abandon it and try out Duplicacy. Feel free to keep discussing in this thread.

Thanks again!