Previous volume not finished, call FinishVolume before starting a new volume

**archbishop** · April 29, 2018, 7:46pm

Without changing any settings (still at 50mb), last night’s scheduled backup failed:

System.InvalidOperationException: Previous volume not finished, call FinishVolume before starting a new volume
  at Duplicati.Library.Main.Volumes.IndexVolumeWriter.StartVolume (System.String filename) [0x00010] in <ae134c5a9abb455eb7f06c134d211773>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.UpdateIndexVolume () [0x00043] in <ae134c5a9abb455eb7f06c134d211773>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.FinalizeRemoteVolumes (Duplicati.Library.Main.BackendManager backend) [0x0016b] in <ae134c5a9abb455eb7f06c134d211773>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x008e0] in <ae134c5a9abb455eb7f06c134d211773>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass17_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00036] in <ae134c5a9abb455eb7f06c134d211773>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0014b] in <ae134c5a9abb455eb7f06c134d211773>:0 
  at Duplicati.Library.Main.Controller.Backup (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x00068] in <ae134c5a9abb455eb7f06c134d211773>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00494] in <670b0e4a9ae144208688fcb192d20146>:0

**JonMikelV** · April 30, 2018, 7:12pm

Darn.

It sounds like whatever is failing is less likely to fail on smaller volumes, but it still can happen.

**archbishop** · May 4, 2018, 4:33pm

At this point it’s running every night, and has failed four of the past five days. Is there additional logging or something I can turn on to diagnose this, so it can get fixed for real?

**JonMikelV** · May 7, 2018, 1:26am

Probably the easiest way to approach this is to generate a log file (for your version I think you’d use --log-file=<path> and --log-level=profiling) then attach it to a post.

**archbishop** · May 13, 2018, 2:35am

The profiling logs helped. The error (not in the logs, but in the generated email body):

C: Failed: Found inconsistency in the following files while validating database:
C: /private/var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/T/ProductMetadata.plist, actual size 1120007, dbsize 0, blocksetid: 490127
C: .. Run repair to fix it.

The query which seems to generate this, from the logs:

SELECT "CalcLen", "Length", "A"."BlocksetID", "File"."Path" FROM (
SELECT
    "A"."ID" AS "BlocksetID",
    IFNULL("B"."CalcLen", 0) AS "CalcLen",
    "A"."Length"
FROM
    "Blockset" A
LEFT OUTER JOIN
    (
        SELECT
            "BlocksetEntry"."BlocksetID",
            SUM("Block"."Size") AS "CalcLen"
        FROM
            "BlocksetEntry"
        LEFT OUTER JOIN
            "Block"
        ON
            "Block"."ID" = "BlocksetEntry"."BlockID"
        GROUP BY "BlocksetEntry"."BlocksetID"
    ) B
ON
    "A"."ID" = "B"."BlocksetID"

) A, "File" WHERE "A"."BlocksetID" = "File"."BlocksetID" AND "A"."CalcLen" != "A"."Length"  took 00:01:10.704

So I started poking into the sqlite db:

sqlite> select * from File where Path = '/private/var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/T/ProductMetadata.plist';
192852|/private/var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/T/ProductMetadata.plist|118275|30435
570675|/private/var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/T/ProductMetadata.plist|118275|97969
572932|/private/var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/T/ProductMetadata.plist|490127|98805

sqlite> select * from Blockset where ID in (118275, 490127);
118275|1120009|mM3nZjV9aw/nk2nAZkqn/aMT1kzzY6Z9rHpwK5O0u6Q=
490127|1120007|ucXqV2XWpYqD7bGTnI99H80oPIlqG9HS8EpPpCq3E+A=

sqlite> select * from BlocksetEntry where BlocksetID in (118275, 490127);
118275|0|211318
118275|1|211319
118275|2|211320
118275|3|211321
118275|4|211322
118275|5|211323
118275|6|211324
118275|7|211325
118275|8|211326
118275|9|211327
118275|10|211328

Oh look. There appear to be no blockset entries for BlocksetID 490127.

I ran repair, as suggested. After, there are still no blockset entries for this BlocksetID. So the DB is corrupt, and repair doesn’t repair it.

**kenkendk** · May 15, 2018, 8:57am

That error is removed in the latest canary build AFAIK

If you have the original database (not the recreated one), can you perhaps see when the empty blockset is created?

It could happen if there was some weird hash collision, I guess, but more likely something else has happened.

If you just want to recover, you should be able to just use purge to remove the file, and then run the backup again, but I would really like if we could zoom in and find the cause of the empty set.

**archbishop** · May 15, 2018, 4:03pm

I do have the original database. But I’m not sure how to see when the empty blockset was created. The BlockSet table doesn’t seem to have any kind of timestamp column. What should I look for?

**archbishop** · May 28, 2018, 12:38am

I tried to use purge to remove the broken file using the cli, but now I get this:

/Applications/Duplicati.app/Contents/MacOS/duplicati-cli purge 'b2://...' /private/var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/T/ProductMetadata.plist --dry-run --dbpath=/var/root/.config/Duplicati/WCTNTGAABX.sqlite

Enter encryption passphrase:
No certificates found, you can install some with one of these commands:
    cert-sync /etc/ssl/certs/ca-certificates.crt #for Debian based systems
    cert-sync /etc/pki/tls/certs/ca-bundle.crt #for RedHat derivatives
Read more: http://www.mono-project.com/docs/about-mono/releases/3.12.0/#cert-sync
Starting purge operation

Unable to start the purge process as there are 527 orphan file(s)
Update "2.0.3.3_beta_2018-04-02" detected

I searched in the forum and see some very old reports about orphan files and the cleanup command, but there is no such command in my cli. I tried adding --auto-cleanup=true to my command line, but that didn’t help.

I don’t know if it’s related, but I notice the output says there’s an update available. When I run duplicati-cli help, it says at the end Version: - 2.0.2.1_beta_2017-08-01 which is surprising since the web UI says You are currently running Duplicati - 2.0.3.3_beta_2018-04-02. I ran duplicati-cli test --auto-update=true which fetched the update. And coincidentally, this happened:

  Listing remote folder ...
  Downloading file (8.48 MB) ...
  Downloading file (202.98 KB) ...
  Downloading file (249.92 MB) ...
duplicati-20180429T194526Z.dlist.zip.aes: 64 errors
	Missing: /private/tmp/
	Missing: /private/var/agentx/
	Missing: /private/var/at/
	Missing: /private/var/at/at.deny
	Missing: /private/var/at/spool/
	Missing: /private/var/at/tabs/
	Missing: /private/var/at/tmp/
	Missing: /private/var/audit/
	Missing: /private/var/audit/20180429201646.not_terminated
	Missing: /private/var/audit/current
	... and 54 more

So there seems to be a problem with the upstream files, too. This is all feeling a lot like at some point, a backup was interrupted, and duplicati did not recover well at all.

What do you recommend I do next?

**archbishop** · May 29, 2018, 2:50am

Since I figured I was likely to just have to start all over again, I took a look at the code. I think the sanity checks in the repair logic were keeping the code from actually repairing my damaged database, so I downloaded the dlist file above, deleted it from b2, moved my sqlite file out of the way, then did repair. I did it from the cli, which gives a little more detailed status output. This forced a much longer repair process than I’ve observed before, different from what the UI “recreate” process seems to do:

Rebuild database started, downloading 3 filelists
  Downloading file (8.48 MB) ...
  Downloading file (40.60 MB) ...
  Downloading file (40.61 MB) ...
Mismatching number of blocklist hashes detected on blockset 488284. Expected 0 blocklist hashes, but found 1
Mismatching number of blocklist hashes detected on blockset 488453. Expected 0 blocklist hashes, but found 1
Filelists restored, downloading 707 index files
  Downloading file (339.56 KB) ...
  Downloading file (255.95 KB) ...
  Downloading file (171.62 KB) ...
  Downloading file (140.06 KB) ...
...
Recreate completed, verifying the database consistency
Recreate completed, and consistency checks completed, marking database as complete

After this, I let the normal nightly backup run, and it completed successfully (with a few warnings) for the first time in almost a month. I’m hopeful it will complete tonight as well.

My take-away is that the tools need a way to force various kinds of checks and recovery, since not all the consistency checks run at the same time everywhere.

As one very concrete example, I was in a catch-22 where I couldn’t purge due to orphans, but I couldn’t clean up the orphans because of a validation failure due to the file I needed to purge. PreBackupVerify is responsible for cleaning up orphans, but the failure at VerifyConsistencyAsync meant I had no way to get there, which is why I forced the system to recreate the db from scratch.

**archbishop** · May 30, 2018, 4:42am

Failed again

Failed: Previous volume not finished, call FinishVolume before starting a new volume
Details: System.InvalidOperationException: Previous volume not finished, call FinishVolume before starting a new volume
  at Duplicati.Library.Main.Volumes.IndexVolumeWriter.StartVolume (System.String filename) [0x00010] in <ae134c5a9abb455eb7f06c134d211773>:0
  at Duplicati.Library.Main.Operation.BackupHandler.UpdateIndexVolume () [0x00043] in <ae134c5a9abb455eb7f06c134d211773>:0
  at Duplicati.Library.Main.Operation.BackupHandler.FinalizeRemoteVolumes (Duplicati.Library.Main.BackendManager backend) [0x0016b] in <ae134c5a9abb455eb7f06c134d211773>:0
  at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x008e0] in <ae134c5a9abb455eb7f06c134d211773>:0
  at Duplicati.Library.Main.Controller+<>c__DisplayClass17_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00036] in <ae134c5a9abb455eb7f06c134d211773>:0
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00072] in <ae134c5a9abb455eb7f06c134d211773>:0

**JonMikelV** · May 30, 2018, 7:30pm

Since you’re still using 2.0.3.3 beta you may run into this error.

Unfortunately, the fix for it currently only exists in 2.0.3.6 canary which is not a version I’d recommend you update to at this time.

So I guess the best we can do is try to come up with a process to allow pre-2.0.3.6 users to recover from the error.

**archbishop** · June 4, 2018, 4:12am

I deleted the backup set, deleted the databases, deleted the files on B2, restarted duplicati, created a new backup by hand, and the backup failed with the “Previous volume…” error the very first time through. So we can be sure, at least, the issue isn’t corruption or inconsistency from a previous backup.

Can you say what causes this error?

**JonMikelV** · June 5, 2018, 8:48pm

I believe this is a bit of a catch-all error were something else goes bad but that error isn’t caught which causes THIS to go bad, where the error is caught.

Are you still using the 50MB upload volume size? It should’t be needed (I know some people have gone up to 1GB) but it seemed to resolve the issue for you last time…

In the past, it sounded like one of the sources of this error was a “dinosaur” file - though this should have been fixed long before 2.0.3.3 beta… though it’s possible this specific bug snuck back in…

**conrad** · June 30, 2018, 4:12pm

I’m observing the same “call FinishVolume” issue here: after a downgrade (including database schema changes) from canary to beta, every backup produces these four errors (or similar):

30 Jun 2018 06:14: Message
Expected there to be a temporary fileset for synthetic filelist (106, duplicati-b00913e73e805478e8ae9e019c14f67c7.dblock.zip.aes), but none was found?
30 Jun 2018 06:13: Message
scheduling missing file for deletion, currently listed as Uploading: duplicati-ie8bc4ccd0031487aa7807fe78e42c81d.dindex.zip.aes
30 Jun 2018 06:13: Message
scheduling missing file for deletion, currently listed as Uploading: duplicati-b2772ab46f2ea4fe49c87efc604c4f236.dblock.zip.aes
30 Jun 2018 06:13: Message
removing file listed as Temporary: duplicati-20180629T132605Z.dlist.zip.aes

While it’s running I frequently can’t view the logs because “the database is locked” (or similar).

Oddly, it also claims that the backup has succeeded, until quite some time after it has finished. So for example on today’s run, while it was still going, Duplicati said that the last successful backup was yesterday (which failed), and while it was tidying up it I think it said today’s was the last successful backup, but it’s now saying that the last successful run was in May. Is there anything I could do to help dig into the cause of this?

**JonMikelV** · July 2, 2018, 4:32am

I’d suggest you first try a restore and see if the any of the “failed” backups are actually available for restoring. I suspect what’s happening is that the backup part of the job runs just fine, but them something catastrophic happens during a later step like retention or compacting.

Beyond that, since this involves a database downgrade I’m going to see if maybe @Pectojin has any thoughts.

**conrad** · July 5, 2018, 11:14pm

Only the most recent failed backup ever seems to be available to restore, but there is always very little material contained within it. Therein lies a clue: I had moved my server directory away from a too-small partition a while back, as a possible solution to problems I was encountering, and the only contents of these ephemeral failed backups were a couple of files from the Duplicati server directory. As it turns out, I’d foolishly moved the server directory to a partition which was getting backed up. Backing up the 9GB backup database, with all its churn (and perhaps also file locks?) might be the problem. Retrying with revised configuration now.

Given that the consensus elsewhere seems to be against including the server directory in backups, this might be worth warning about/protecting against?

Will report back on progress of retry.

EDIT: Retry #1 appears to have produced a complete error-free backup…

**JonMikelV** · July 8, 2018, 11:26pm

Thanks for taking the time to let us know what actions resolved the issue for you.

I do recall some discussion about automatically excluding the sqlite database from backups, but I’m not sure anything got decided or implemented.

**conrad** · July 8, 2018, 11:59pm

Heh; three more successful backups does suggest that excluding the server directory has solved my problem, so +1 on that automatic exclusion!

**kenkendk** · July 11, 2018, 9:07am

@conrad Glad to hear that you sorted it out. Is this the beta build? I would like to believe that the problem is fixed in the canary, but if you see the problem there, I need to do more digging…

**conrad** · July 11, 2018, 10:21am

Hi Ken, no, that’s the April beta still, so not canary & nothing to worry about.

I did try running canary on this backup, but it seemed to have extreme database performance issues with my 9GB database: my backups on canary back in March were taking ~6h, on April’s beta they’re now ~13h, but canary (would’ve been April-era, with version 5 database) failed to complete one backup in three weeks: it was backing up new files (mainly photos around 10MB) at a rate of only a few per day.