Stuck on "Starting …"

Thank you!

I guess the checks are there for a reason? I’m a bit skeptical to disable all of the verifications, but I think something is off since it’s been “stuck” on “Verifying backend data …” for quite a while now.

 [B2017-09-15 12:47:34Z - Profiling: Starting - Running Backup
2017-09-15 12:47:34Z - Profiling: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES (?, ?); SELECT last_insert_rowid();
2017-09-15 12:47:35Z - Profiling: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES (?, ?); SELECT last_insert_rowid(); took 00:00:00.274
2017-09-15 12:47:35Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:47:35Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.059
2017-09-15 12:47:35Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:47:35Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.000
2017-09-15 12:47:35Z - Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" > ?
2017-09-15 12:51:43Z - Profiling: ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" > ? took 00:04:08.522
2017-09-15 12:51:50Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:51:50Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.000
2017-09-15 12:51:50Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:51:50Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.000
2017-09-15 12:51:50Z - Profiling: Starting - ExecuteReader: 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"
2017-09-15 12:52:38Z - Profiling: ExecuteReader: 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:00:48.508
2017-09-15 12:52:38Z - Profiling: Starting - ExecuteScalarInt64: SELECT Count(*) FROM "BlocklistHash"
2017-09-15 12:52:39Z - Profiling: ExecuteScalarInt64: SELECT Count(*) FROM "BlocklistHash" took 00:00:00.229
2017-09-15 12:52:39Z - Profiling: Starting - ExecuteScalarInt64: SELECT Count(*) FROM (SELECT DISTINCT "BlocksetID", "Index" FROM "BlocklistHash")
2017-09-15 12:52:39Z - Profiling: ExecuteScalarInt64: SELECT Count(*) FROM (SELECT DISTINCT "BlocksetID", "Index" FROM "BlocklistHash") took 00:00:00.013
2017-09-15 12:52:39Z - Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM (SELECT * FROM (SELECT "N"."BlocksetID", (("N"."BlockCount" + 3200 - 1) / 3200) AS "BlocklistHashCountExpected", CASE WHEN "G"."BlocklistHashCount" IS NULL THEN 0 ELSE "G"."BlocklistHashCount" END AS "BlocklistHashCountActual" FROM (SELECT "BlocksetID", COUNT(*) AS "BlockCount" FROM "BlocksetEntry" GROUP BY "BlocksetID") "N" LEFT OUTER JOIN (SELECT "BlocksetID", COUNT(*) AS "BlocklistHashCount" FROM "BlocklistHash" GROUP BY "BlocksetID") "G" ON "N"."BlocksetID" = "G"."BlocksetID" WHERE "N"."BlockCount" > 1) WHERE "BlocklistHashCountExpected" != "BlocklistHashCountActual")
2017-09-15 12:52:54Z - Profiling: ExecuteScalarInt64: SELECT COUNT(*) FROM (SELECT * FROM (SELECT "N"."BlocksetID", (("N"."BlockCount" + 3200 - 1) / 3200) AS "BlocklistHashCountExpected", CASE WHEN "G"."BlocklistHashCount" IS NULL THEN 0 ELSE "G"."BlocklistHashCount" END AS "BlocklistHashCountActual" FROM (SELECT "BlocksetID", COUNT(*) AS "BlockCount" FROM "BlocksetEntry" GROUP BY "BlocksetID") "N" LEFT OUTER JOIN (SELECT "BlocksetID", COUNT(*) AS "BlocklistHashCount" FROM "BlocklistHash" GROUP BY "BlocksetID") "G" ON "N"."BlocksetID" = "G"."BlocksetID" WHERE "N"."BlockCount" > 1) WHERE "BlocklistHashCountExpected" != "BlocklistHashCountActual") took 00:00:15.465
2017-09-15 12:52:54Z - Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "File" WHERE "BlocksetID" != ? AND "BlocksetID" != ? AND NOT "BlocksetID" IN (SELECT "BlocksetID" FROM "BlocksetEntry")
2017-09-15 12:52:57Z - Profiling: ExecuteScalarInt64: SELECT COUNT(*) FROM "File" WHERE "BlocksetID" != ? AND "BlocksetID" != ? AND NOT "BlocksetID" IN (SELECT "BlocksetID" FROM "BlocksetEntry") took 00:00:02.694
2017-09-15 12:52:57Z - Profiling: Starting - ExecuteReader: SELECT DISTINCT "Fileset"."ID", "Fileset"."Timestamp" FROM "Fileset", "RemoteVolume" WHERE "RemoteVolume"."ID" = "Fileset"."VolumeID" AND "Fileset"."ID" IN (SELECT "FilesetID" FROM "FilesetEntry")  AND ("RemoteVolume"."State" = "Uploading" OR "RemoteVolume"."State" = "Temporary")
2017-09-15 12:52:57Z - Profiling: ExecuteReader: SELECT DISTINCT "Fileset"."ID", "Fileset"."Timestamp" FROM "Fileset", "RemoteVolume" WHERE "RemoteVolume"."ID" = "Fileset"."VolumeID" AND "Fileset"."ID" IN (SELECT "FilesetID" FROM "FilesetEntry")  AND ("RemoteVolume"."State" = "Uploading" OR "RemoteVolume"."State" = "Temporary") took 00:00:00.163
2017-09-15 12:52:57Z - Profiling: Starting - ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ?
2017-09-15 12:52:57Z - Profiling: ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ? took 00:00:00.000
2017-09-15 12:52:57Z - Profiling: Starting - PreBackupVerify
2017-09-15 12:52:57Z - Profiling: Starting - RemoteOperationList
2017-09-15 12:52:57Z - Information: Backend event: List - Started:  ()
2017-09-15 13:00:56Z - Profiling: RemoteOperationList took 00:07:59.364
2017-09-15 13:00:56Z - Warning: Operation List with file  attempt 1 of 5 failed with message: The remote server returned an error: (403) Forbidden.
System.Net.WebException: The remote server returned an error: (403) Forbidden.
  at Duplicati.Library.Utility.AsyncHttpRequest+AsyncWrapper.GetResponseOrStream () <0x40d6b310 + 0x0010b> in <filename unknown>:0
  at Duplicati.Library.Utility.AsyncHttpRequest.GetResponse () <0x40da19a0 + 0x00163> in <filename unknown>:0
  at Duplicati.Library.JSONWebHelper.GetResponse (Duplicati.Library.Utility.AsyncHttpRequest req, System.Object requestdata) <0x40dcde70 + 0x0040f> in <filename unknown>:0
2017-09-15 13:00:56Z - Information: Backend event: List - Retrying:  ()
2017-09-15 13:01:06Z - Profiling: Starting - RemoteOperationList
2017-09-15 13:01:06Z - Information: Backend event: List - Started:  ()
2017-09-15 13:11:43Z - Information: Backend event: List - Completed:  (62.22 KB)
2017-09-15 13:11:43Z - Profiling: RemoteOperationList took 00:10:36.123
2017-09-15 13:11:45Z - Profiling: 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")
2017-09-15 13:11:46Z - Profiling: 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.911
2017-09-15 13:11:50Z - Information: removing file listed as Temporary: duplicati-20170914T221359Z.dlist.zip.aes
2017-09-15 13:11:51Z - Information: promoting uploaded complete file from Uploading to Uploaded: duplicati-b0ec2147ae2a34830a0ac6a2d7f629c67.dblock.zip.aes
2017-09-15 13:11:51Z - Information: removing incomplete remote file listed as Uploading: duplicati-i3c41e9488f6f408f9abd1102ca9c8d7c.dindex.zip.aes
2017-09-15 13:11:51Z - Profiling: Starting - RemoteOperationDelete
2017-09-15 13:11:51Z - Information: Backend event: Delete - Started: duplicati-i3c41e9488f6f408f9abd1102ca9c8d7c.dindex.zip.aes ()
2017-09-15 13:11:52Z - Information: Backend event: Delete - Completed: duplicati-i3c41e9488f6f408f9abd1102ca9c8d7c.dindex.zip.aes ()
2017-09-15 13:11:52Z - Profiling: RemoteOperationDelete took 00:00:00.526
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY) took 00:00:00.041
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:11:52Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.108
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ))
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )) took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ))
2017-09-15 13:11:54Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )) took 00:00:01.937
2017-09-15 13:11:54Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:09.066
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ))
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )) took 00:00:00.019
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"  took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66"
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66"  took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"
2017-09-15 13:12:05Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"  took 00:00:02.048
2017-09-15 13:12:05Z - Information: promoting uploaded complete file from Uploading to Uploaded: duplicati-bd2594082e8a24fb2abc6501ab015f1dd.dblock.zip.aes
2017-09-15 13:12:05Z - Information: removing incomplete remote file listed as Uploading: duplicati-if7a1207ad0f146c38f8b18a4ec8de45a.dindex.zip.aes
2017-09-15 13:12:05Z - Profiling: Starting - RemoteOperationDelete
2017-09-15 13:12:05Z - Information: Backend event: Delete - Started: duplicati-if7a1207ad0f146c38f8b18a4ec8de45a.dindex.zip.aes ()
2017-09-15 13:12:06Z - Information: Backend event: Delete - Completed: duplicati-if7a1207ad0f146c38f8b18a4ec8de45a.dindex.zip.aes ()
2017-09-15 13:12:06Z - Profiling: RemoteOperationDelete took 00:00:00.594
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:06Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.107
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ))
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )) took 00:00:00.000

(1/2)

(2/2)

2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ))
2017-09-15 13:12:08Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )) took 00:00:01.347
2017-09-15 13:12:08Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:09.088
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ))
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )) took 00:00:00.020
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"  took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B"
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B"  took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"
2017-09-15 13:12:19Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"  took 00:00:02.001
2017-09-15 13:12:19Z - Information: promoting uploaded complete file from Uploading to Uploaded: duplicati-b0206c2cc5365435f9579ab25682846ac.dblock.zip.aes
2017-09-15 13:12:19Z - Information: removing incomplete remote file listed as Uploading: duplicati-iff08a32994df4288a13e9bd440aa50e0.dindex.zip.aes
2017-09-15 13:12:19Z - Profiling: Starting - RemoteOperationDelete
2017-09-15 13:12:19Z - Information: Backend event: Delete - Started: duplicati-iff08a32994df4288a13e9bd440aa50e0.dindex.zip.aes ()
2017-09-15 13:12:20Z - Information: Backend event: Delete - Completed: duplicati-iff08a32994df4288a13e9bd440aa50e0.dindex.zip.aes ()
2017-09-15 13:12:20Z - Profiling: RemoteOperationDelete took 00:00:00.522
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:20Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.107
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ))
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ))
2017-09-15 13:12:22Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )) took 00:00:01.781
2017-09-15 13:12:22Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:07.901
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ))
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )) took 00:00:00.020
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62"
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62"  took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62"
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62"  took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-31787F989488844C8D115D04E0064C62"
2017-09-15 13:12:32Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-31787F989488844C8D115D04E0064C62"  took 00:00:02.035
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:32Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY) took 00:00:00.009
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:32Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.001
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:32Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.096
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ))
2017-09-15 13:12:35Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )) took 00:00:02.838
2017-09-15 13:12:35Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:35Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:35Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:35Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:35Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ))
2017-09-15 13:12:36Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )) took 00:00:01.717
2017-09-15 13:12:36Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:08.556
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ))
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )) took 00:00:02.139
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.003
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.007
2017-09-15 13:12:49Z - Profiling: PreBackupVerify took 00:19:52.382
2017-09-15 13:12:49Z - Profiling: Starting - ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ?
2017-09-15 13:12:49Z - Profiling: ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ? took 00:00:00.005
2017-09-15 13:12:49Z - Warning: Expected there to be a temporary fileset for synthetic filelist (3, duplicati-idfccf4b6966d401eb353cd093f91c8f6.dindex.zip.aes), but none was found?
2017-09-15 13:12:49Z - Profiling: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
2017-09-15 13:12:49Z - Profiling: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 00:00:00.000
2017-09-15 13:12:49Z - Profiling: Starting - ExecuteReader: SELECT "Name" FROM "RemoteVolume" WHERE "Type" = ? AND NOT "ID" IN (SELECT "BlockVolumeID" FROM "IndexBlockLink") AND "State" IN (?,?)
2017-09-15 13:12:52Z - Profiling: ExecuteReader: SELECT "Name" FROM "RemoteVolume" WHERE "Type" = ? AND NOT "ID" IN (SELECT "BlockVolumeID" FROM "IndexBlockLink") AND "State" IN (?,?) took 00:00:02.527
2017-09-15 13:12:52Z - Information: Re-creating missing index file for duplicati-b0ec2147ae2a34830a0ac6a2d7f629c67.dblock.zip.aes
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (?, ?, ?, ?, ?, ?, ?); SELECT last_insert_rowid();
2017-09-15 13:12:52Z - Profiling: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (?, ?, ?, ?, ?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.026
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteReader: SELECT "Name", "Hash", "Size" FROM "RemoteVolume" WHERE "Name" = ?
2017-09-15 13:12:52Z - Profiling: ExecuteReader: SELECT "Name", "Hash", "Size" FROM "RemoteVolume" WHERE "Name" = ? took 00:00:00.004
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:52Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ?
2017-09-15 13:12:52Z - Profiling: ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ? took 00:00:00.002
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteReader: SELECT "A"."Hash", "C"."Hash" FROM (SELECT "BlocklistHash"."BlocksetID", "Block"."Hash", * FROM  "BlocklistHash","Block" WHERE  "BlocklistHash"."Hash" = "Block"."Hash" AND "Block"."VolumeID" = ?) A,  "BlocksetEntry" B, "Block" C WHERE "B"."BlocksetID" = "A"."BlocksetID" AND  "B"."Index" >= ("A"."Index" * 3200) AND "B"."Index" < (("A"."Index" + 1) * 3200) AND "C"."ID" = "B"."BlockID"  ORDER BY "A"."BlocksetID", "B"."Index"

(This is the current log, the time is now 14:27)

Please let me know if there is any more data needed, or a better way to debug.

If it’s not costing you money, keeping veifications in is indeed good idea. (Well, it’s a good idea if it costs money, but…) :slight_smile:

I’m not proficient in reading the log stuff so this may not apply to you, but possible reasons for verifications taking “quite a while” could be due to settings such as:

  • how fast downloads are allowed --throttle-download (because the archives to be tested have to be downloaded the slowness could be just waiting for the archive file to be downloaded for testing)
  • archive (dblock) size --dblock-size (big archives means lots of data to test)
  • the number of samples being tested --backup-test-samples (lots of archives to test could take a while)

Thank you. I agree, I can live with it taking some time, but if it’s not supposed to, I would like to figure out why and fix it. :slight_smile:

Regarding your suggestions:

  • –throttle-download is not enabled.
  • –dblock-size is default, 50 mb.
  • –backup-test-samples is set to 3

So I don’t think that should influense this?

Agreed - those settings (might even be the defaults) shouldn’t be having this effect.

BTW: A good way of showing your appreciation for a post is to like it: just press the :heart: button under the post.

If you asked the original question, you can also mark an answer as the accepted answer which solved your problem using the tick-box button you see under each reply.

All of this also helps the forum software distinguish interesting from less interesting posts when compiling summary emails.

I also edited some of your posts to improve the formating. (Just added ~~~ before and after the output you pasted, see here for details).

1 Like

I don’t want to wander too much off topic, but I did the :heart: button too, and I genuinely say thank you to people who help me. Is that a bad thing here?

Anyhow, thank you (hope that’s okay saying that) for the editing (& tips for next time), I will try to use them from now on.

I thought I didn’t see any likes but I may have missed them. In that case my hint was of course superfluous. In any case, it was not meant as a criticism of saying thank you. So:

No, not at all. It’s much appreciated! Thank you for participating!

Great! :slight_smile:

I had :heart:'ed the few first posts from yesterday, but not todays (until you mentioned it). :slight_smile:

So, back to the topic, if anyone has the slightest idea of why “Verifying backend data …” is taking so long on a Ubuntu VM with G Suite/GDrive as backend, all input is greatly appreciated!

Thanks for the :heart:s!

NoLooseEnds, am I correct in thinking it the original “Stuck on starting” issue was actually related to the slow verification times? If so, maybe changing the Topic title would make sense.

It sounds like you’re using a cloud provider for the backend (sorry - kinda skimming here). If that’s the case do you have the time/space to try bring the backup files to a local machine or LAN destination and trying the verification process pointing at that local destination? That would help remove cloud and internet (and potentially LAN) bottlenecks from the scenario.

Alternatively, you could try setting up a pair of smaller test backups to the same cloud provider as your primary AND to somewhere local and seeing if the “verify backend data” step takes about the same time regardless of the “distance” to the destination.

1 Like

This looks like the source of the problems. Duplicati has detected that this file was not uploaded completely for some reason. It is then deleting the remote file and rebuilding it.

Did you kill the backup last it ran, or is there some issue with files going broken on the remote end?

1 Like

@JonMikelV
I do not have the HDD space to do a local backup to another machine on the LAN, but I could try with a smaller backup set.

@kenkendk
The backup was stopped, not killed. But I selected not to wait on the upload to complete. Does the "removing incomplete file … take such long time?

Anyhow. The VM ran out of space due to the logfile and maybe tmp over the weekend, so now I have set the log-file location and TMPDIR variable to an NFS share. So hopefully, this will remove all the space issues.

After setting --check-filetime-only the speed Duplicati to start Verifying backend data …, is much faster. The remaining problems is:

  • Using a long time (2 hours +) to verify the backend
  • Pretty slow going through existing files.

I made a video of the web interface when it’s processing files, and would appreciate if you could take a look and tell me if this is “normal” or extremely slow.

That operation should only delete the remote file(s) and as such be quite fast. It may take some time if one of the files to delete references local data. In such a case there are some collateral in the database that needs cleaning up.

That looks very slow, but it seems to “stop” so I am assuming it just keeps at it, but the message is the same.

I have uploaded a new canary build: Releases · duplicati/duplicati · GitHub

This new version has a new advanced option --use-block-cache, which can be used to speed up the lookups that are slow in your case. This does require some memory (>300mb of RAM pr. TB of data), but if you have a non-SSD disk, I think it could give some results.

1 Like

Thank you, I’ll give it a go after the initial backup is complete.

The VM is (unfortunately) not running from SSD. The datapool (that it connects to via internal ESXi network) consists of 6 x 4 TB in raidz2 (1 hot-spare) and a 120 GB SSD cache. It is starting to become a bit old, but it’s still chugging away happily.

kenkendk, in a “standard” backup report email I see some file stats like DeletedFiles, SizeOfModififiedFiles, etc. but the only time related are EndTime, BeginTime, and Duration.

Are there task specific performance stats available in some way?

I’m thinking of file processing stuff I’ve written that includes stats like time spend reading folder/file lists, time spent on specfic SQL tasks, etc I’ve even worked on some code where I know what “normal” task times look like and only inculde stats in the logs when things are outside that time.

I know there’s potential overhead associated with all this monitoring but it might help in identifying specific slow parts of the code when run in certain situations (aka on other people’s hardware).

1 Like

Actually, this would be really great if Duplicati could provide such detailed internal profiling data for all the stages of the operation… Just getting elapsed time will not incur an real overhead…

I like the idea, but it is not implemented currently. There are some general timing measures spread out in the code, but not like you suggest. I think this would be very easy to implement in the concurrent_processing branch, as each “process” there can time its “active” time and report that when it finishes.

So today was the day that the backup completed, I think. I got an I/O error upon completion. Not sure why, but at least I know that it has uploaded a couple of TB of data first.

I updated to the canary build mentioned above by @kenkendk, and added “–use-block-cache” (true) to the config. I also restarted both VMs involved (OmniOS serving the data, and a Ubuntu Server doing the backing up) for good measure.

Anyhow, I started the backup again – and it’s been sitting on “Verifying backend data …” for a few hours. Currently it is consuming 100 % CPU of one of the virtual CPU cores in the VM.

Also:

  • Logging is set to “Warning”, but I have “profiling” on in my browser – and it seems like the log file is getting the profiling information, because they are growing fast when stuff is happening. I have a 12 GB log file of the previous backup.
  • the “QZDJRHUBWM.sqlite” file is 5 GB
  • If I figured out this correctly, it’s 1.982.566 files in the directory that is getting backed up (minus a few that are excluded in the backup)

Is there a way I can try to debug why it is taking so long? Can I provide some specific data? Do a test? etc?

(I have been running this on an alternative system with a similar setup as well, but against a different backend – JottaCloud. A lot less data – a few 100 GB, not multiple TB. But I have had no problems. And it’s a lot faster)

EDIT:
It’s done verifying backend, and now I see a lot of:

Oct 2, 2017 11:32 AM: Checking file for changes /path/to/file.psd, new: True, timestamp changed: True, size changed: False, metadatachanged: False, 1/8/2013 12:30:04 PM vs 1/1/0001 12:00:00 AM

Where it says that the timestamp has changed, but it has not. And it is comparing the timestamp to “1/1/0001 12:00:00 AM”, and that makes Duplicati think that everything is new.

Both the Ubuntu VM (via NFS) and directly on the OmniOS VM says the file date is “Jan 8 2013”. The time/date on both systems are correct.

Does this make sense to any of you?

(Status as of now, reported by Duplicati, is: 273034 files (2.73 TB) to go at 1.06 KB/s – that is about 1/4th of the progressbar)

EDIT2:
I’ve tweaked my NFS mount, so I now get ~450 MB/s write, and around 1GB/s write. I tested the write/read with “dd” following this blog post.

Write:

$ sync; dd if=/dev/zero of=tempfile bs=1M count=1024; sync
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 2.40283 s, 447 MB/s

Read:

$ dd if=tempfile of=/dev/null bs=1M count=1024
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 1.03813 s, 1.0 GB/s

NFS mount options:

/datapool/Share from 192.168.20.15:/datapool/Share
Flags:	ro,noatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,acregmin=1800,acregmax=1800,acdirmin=1800,acdirmax=1800,hard,nolock,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=192.168.20.15,mountvers=3,mountport=47674,mountproto=udp,local_lock=all,addr=192.168.20.15

EDIT 3
After having a few issues with crashing Duplicati service, NFS locking up, etc. I finally completed a successfull backup.

  • It took quite a while, and it spent most of the time setting timestamps. Duplicati did it in bursts from 10-30 files at a time, then paused a bit (maybe CPU limit?), and continued.
  • I’m not sure what caused my NFS issues, but I solved with tweaking rsize/wsize and setting the MTU of the internal network to 9000.
  • The Duplicati crashes are random, not sure what is causing those. But when it works it works.
1 Like

The key is the “new” part. Duplicati thinks this file is new (it has not seen this path before), which is why it does not have a timestamp. Normally this only happens if the file has been moved or renamed.

Did anything like that happen?

No, it’s old files (2013), so they have been in the same structure since then.

Only thing I can think of must be that it did not complete properly due to I/O error (probably due to some NFS issue). That seems to be resolved now, and Duplicati no longer spends time checking “new old files”.

AFAIK everything seems to work fine. I had a few unexplained crashes, but upgraded to the latest canary build, and hope that solves that. Also set the service to restart on crash.

A backup now takes aprox 2 hours with few modified files to upload. Not sure if that is fast/slow.