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! 