Stuck on Verifying Backend

Support
1

I have 2 backups, both to Onedrive. One is ~30GB and works fine. The other is above 200GB and never completes.

Judging by the file size in Onedrive, the backup is complete, but the UI is stuck on verifying. I left it for 18 hours but there was no activity in the logs and the progress bar didn’t move (it is very close to the end).

The last log message in ‘general’ was:
Apr 22, 2018 2:04 AM: Message
Deleted 2 files, which reduced storage by 1.67 KB

The last remote log was:
Apr 22, 2018 2:04 AM: delete duplicati-id278848393dc427aa7ebf8ace6b35254.dindex.zip.aes

System wide logs (profiling level) the last was:
Apr 22, 2018 2:04 AM: Backend event: List - Started: ()

I am using Duplicati - 2.0.3.3_beta_2018-04-02 running as a service.

I had this problem earlier, and after repeatedly failing with ‘repair’ and ‘delete and repair’ I started again with a new backup (my internet is fairly speedy so no huge sacrifice). Unfortunately, this new backup isn’t working :frowning:

The UI shows ‘Last successful run:Never’.

What can I try?

What I have seen of Duplicati otherwise looks great, thank you very much.

2

Interesting. 36 hours later, something started to happen.

The following were added to the General log for the backup:
Apr 23, 2018 2:32 PM: Message
removing file listed as Temporary: duplicati-iadd765b35eea4d58886b43817e55deb7.dindex.zip.aes
Apr 23, 2018 2:32 PM: Message
removing file listed as Temporary: duplicati-bfb84341339a74f9691215b418b3e6519.dblock.zip.aes

And to the remote log:
Apr 23, 2018 2:32 PM: list

And to the application log (profiling):

Apr 23, 2018 2:32 PM: Backend event: Get - Started: duplicati-20180417T033005Z.dlist.zip.aes (3.11 MB)
Apr 23, 2018 2:32 PM: Starting - RemoteOperationGet
Apr 23, 2018 2:32 PM: ExecuteReader: SELECT “ID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE “Type” = ? AND “State” IN (?, ?) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteReader: SELECT “ID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE “Type” = ? AND “State” IN (?, ?)
Apr 23, 2018 2:32 PM: ExecuteReader: SELECT “ID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE “Type” = ? AND “State” IN (?, ?) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteReader: SELECT “ID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE “Type” = ? AND “State” IN (?, ?)
Apr 23, 2018 2:32 PM: ExecuteReader: SELECT “A”.“VolumeID”, “A”.“Name”, “A”.“Size”, “A”.“Hash”, “A”.“VerificationCount” FROM (SELECT “ID” AS “VolumeID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE “State” IN (?, ?)) A, “Fileset” WHERE “A”.“VolumeID” = “Fileset”.“VolumeID” ORDER BY “Fileset”.“Timestamp” took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteReader: SELECT “A”.“VolumeID”, “A”.“Name”, “A”.“Size”, “A”.“Hash”, “A”.“VerificationCount” FROM (SELECT “ID” AS “VolumeID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE “State” IN (?, ?)) A, “Fileset” WHERE “A”.“VolumeID” = “Fileset”.“VolumeID” ORDER BY “Fileset”.“Timestamp”
Apr 23, 2018 2:32 PM: ExecuteScalarInt64: SELECT MAX(“VerificationCount”) FROM “RemoteVolume” took 00:00:00.002
Apr 23, 2018 2:32 PM: Starting - ExecuteScalarInt64: SELECT MAX(“VerificationCount”) FROM “RemoteVolume”
Apr 23, 2018 2:32 PM: ExecuteReader: SELECT “ID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE (“State” = ? OR “State” = ?) AND (“Hash” = “” OR “Hash” IS NULL OR “Size” <= 0) took 00:00:00.001
Apr 23, 2018 2:32 PM: Starting - ExecuteReader: SELECT “ID”, “Name”, “Size”, “Hash”, “VerificationCount” FROM “Remotevolume” WHERE (“State” = ? OR “State” = ?) AND (“Hash” = “” OR “Hash” IS NULL OR “Size” <= 0)
Apr 23, 2018 2:32 PM: ExecuteReader: SELECT “ID”, “Timestamp” FROM “Fileset” ORDER BY “Timestamp” DESC took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteReader: SELECT “ID”, “Timestamp” FROM “Fileset” ORDER BY “Timestamp” DESC
Apr 23, 2018 2:32 PM: RemoteOperationTerminate took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - RemoteOperationTerminate
Apr 23, 2018 2:32 PM: AfterBackupVerify took 12:28:11.093
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DROP TABLE IF EXISTS “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689”
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DROP TABLE IF EXISTS “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689”
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689”
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689”
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “DeletedBlock” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “DeletedBlock” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “Block” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “Block” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “BlocklistHash” WHERE “Hash” IN (SELECT “Hash” FROM “Block” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” )) took 00:00:00.006
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “BlocklistHash” WHERE “Hash” IN (SELECT “Hash” FROM “Block” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ))
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “BlocksetEntry” WHERE “BlocksetID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “BlocksetEntry” WHERE “BlocksetID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “Blockset” WHERE “ID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “Blockset” WHERE “ID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “Metadataset” WHERE “BlocksetID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “Metadataset” WHERE “BlocksetID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “File” WHERE “BlocksetID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” ) OR “MetadataID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.115
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “File” WHERE “BlocksetID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” ) OR “MetadataID” IN (SELECT “ID” FROM “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteNonQuery: INSERT OR IGNORE INTO “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” (“ID”) SELECT “BlocksetEntry”.“BlocksetID” FROM “BlocksetEntry”, “Block” WHERE “BlocksetEntry”.“BlockID” = “Block”.“ID” AND “Block”.“VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) UNION ALL SELECT “BlocksetID” FROM “BlocklistHash” WHERE “Hash” IN (SELECT “Hash” FROM “Block” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” )) took 00:00:00.058
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” (“ID”) SELECT “BlocksetEntry”.“BlocksetID” FROM “BlocksetEntry”, “Block” WHERE “BlocksetEntry”.“BlockID” = “Block”.“ID” AND “Block”.“VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) UNION ALL SELECT “BlocksetID” FROM “BlocklistHash” WHERE “Hash” IN (SELECT “Hash” FROM “Block” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ))
Apr 23, 2018 2:32 PM: ExecuteNonQuery: CREATE TEMP TABLE “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” (“ID” INTEGER PRIMARY KEY) took 00:00:00.001
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: CREATE TEMP TABLE “DelBlockSetIds-196DB9530F6EE340BF350C348CCFF689” (“ID” INTEGER PRIMARY KEY)
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “Fileset” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “Fileset” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “FilesetEntry” WHERE “FilesetID” IN (SELECT “ID” FROM “Fileset” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” )) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “FilesetEntry” WHERE “FilesetID” IN (SELECT “ID” FROM “Fileset” WHERE “VolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ))
Apr 23, 2018 2:32 PM: ExecuteNonQuery: DELETE FROM “IndexBlockLink” WHERE “BlockVolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) OR “IndexVolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) took 00:00:00.003
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: DELETE FROM “IndexBlockLink” WHERE “BlockVolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” ) OR “IndexVolumeID” IN (SELECT “ID” FROM “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” )
Apr 23, 2018 2:32 PM: ExecuteScalarInt64: SELECT “ID” FROM “Remotevolume” WHERE “Name” = ? took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Remotevolume” WHERE “Name” = ?
Apr 23, 2018 2:32 PM: ExecuteScalarInt64: SELECT “ID” FROM “Remotevolume” WHERE “Name” = ? took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Remotevolume” WHERE “Name” = ?
Apr 23, 2018 2:32 PM: ExecuteNonQuery: CREATE TEMP TABLE “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” (“ID” INTEGER PRIMARY KEY) took 00:00:00.000
Apr 23, 2018 2:32 PM: Starting - ExecuteNonQuery: CREATE TEMP TABLE “DelVolSetIds-196DB9530F6EE340BF350C348CCFF689” (“ID” INTEGER PRIMARY KEY)
Apr 23, 2018 2:32 PM: removing file listed as Temporary: duplicati-iadd765b35eea4d58886b43817e55deb7.dindex.zip.aes
Apr 23, 2018 2:32 PM: removing file listed as Temporary: duplicati-bfb84341339a74f9691215b418b3e6519.dblock.zip.aes
Apr 23, 2018 2:32 PM: ExecuteReader: SELECT DISTINCT “Name”, “State” FROM “Remotevolume” WHERE “Name” IN (SELECT “Name” FROM “Remotevolume” WHERE “State” IN (“Deleted”, “Deleting”)) AND NOT “State” IN (“Deleted”, “Deleting”) took 00:00:00.060
Apr 23, 2018 2:32 PM: Starting - ExecuteReader: SELECT DISTINCT “Name”, “State” FROM “Remotevolume” WHERE “Name” IN (SELECT “Name” FROM “Remotevolume” WHERE “State” IN (“Deleted”, “Deleting”)) AND NOT “State” IN (“Deleted”, “Deleting”)
Apr 23, 2018 2:32 PM: RemoteOperationList took 12:28:05.820
Apr 23, 2018 2:32 PM: Backend event: List - Completed: (8.05 KB)

Interesting… The list backend took 30 hours to complete… I’m tempted to put the blame all on Onedrive.

It’s now apparently somewhat stuck on Verifying, let’s give it a week or two! :frowning:

3

Hi @jfield, welcome to the forum!

Is the Verifying step it’s getting stuck on part of the backup (can you tell if it’s at the beginning or the end?) or a manual Verify command?

4

Thanks @JonMikelV , it progressed from ‘Verifying backend’ in my first post (where it seemed stuck) to simply ‘Verifying’ in my second post, where it got stuck again, this time for real. This time I cancelled it after a few days and told it to run again.

I think it must have been at the end of the backup given that the files are visible in Onedrive on the web. It was an automatic verify, not manually initiated.

5

Something you could try as a test is to set --backup-test-samples=0.
(See Advanced Options - Duplicati 2 User's Manual for more detail.)

If that makes the issue go away then we’ve probably isolated the problem (but not actually resolved it, so don’t necessarily consider this a “fix”).

Oh, something else to consider is looking at your restore version list. You may find that even though the full job (including verification) doesn’t technically finish, the actual backup part may have completed.

So if some of the dates with runs that got “stuck” show up in the restore list then you can at least know that the backups themselves are happening.

6

Thank you.

It just completed today! (After almost a week of little activity.)

But even before it managed to verify it still appeared in restore.

7

Yay! Though the “almost a week” part is definitely something we are aware of and working to improve.

So at this point it’s working OK for your or is it still taking forever on verifying the backend in subsequent runs?

Oh, and did you try the --backup-test-samples=0 thing in my last post or was patience the trick that “made it work”?

8

It was patience… I was saving it for when it failed

9

Patience for the win!

Both in letting Duplicati finish it’s thing AND with us for waiting while we figure out why this is happening (and how to fix it). :slight_smile:

10

So the resolution is to wait for days? I have I believe this issue (stuck on Verifying…, Duplicati 2.0.3.3_beta_2018-04-02, backup about 10GB to Google Drive). Progress bar is already full and the backup is running for 12 hours with no progress in logs.

11

Which logs did you check?

12

Just the logs in the UI: backup name : Display log : General and Remote (The labels can differ slightly as I have them localized). Last entries are at 2018-06-28 21:02. Are there any other logs?