Stuck on "Starting …"

[NoLooseEnds]

Hi, recently installed Duplicati to test as an alternative til Crashplan (now that they are changing subscription model).

Info:

• ESXi VM running Ubuntu 16.04.3 LTS
• Backing up from NFS share
• Backing up to Google Drive (G Suite)
• Backed up ~2 TB of ~6 TB
• Update channel: Default (Beta) – Same as the base install version: 2.0.2.1_beta_2017-08-01

Background & problem

• Stopped backup to add logging features in the config, and to reboot VM due to software updates from Ubuntu.
• Duplicati service starts up fine, but when I start the backup it halts on “Starting …” for a very long time (hours)
• I’ve tried stopping the backup, but that does not seem to help. I’ve tried to restart the service, but still no go. Seems like it gets stuck on “Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM “Block” WHERE “Size” > ?”
• There is barely any network activity going on (see screenshot).

How long should this process take?

Log file:

2017-09-04 12:04:55Z - Profiling: Starting - Running Backup
2017-09-04 12:04:55Z - Profiling: Starting - ExecuteScalarInt64: INSERT INTO “Operation” (“Description”, “Timestamp”) VALUES (?, ?); SELECT last_insert_rowid();
2017-09-04 12:04:55Z - Profiling: ExecuteScalarInt64: INSERT INTO “Operation” (“Description”, “Timestamp”) VALUES (?, ?); SELECT last_insert_rowid(); took 00:00:00.002
2017-09-04 12:04:55Z - Profiling: Starting - ExecuteReader: SELECT “Key”, “Value” FROM “Configuration”
2017-09-04 12:04:55Z - Profiling: ExecuteReader: SELECT “Key”, “Value” FROM “Configuration” took 00:00:00.000
2017-09-04 12:04:55Z - Profiling: Starting - ExecuteReader: SELECT “Key”, “Value” FROM “Configuration”
2017-09-04 12:04:55Z - Profiling: ExecuteReader: SELECT “Key”, “Value” FROM “Configuration” took 00:00:00.000
2017-09-04 12:04:55Z - Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM “Block” WHERE “Size” > ?

This is the current status of Duplicati processes as of now:

EDIT:
Suddenly started “Verifying backend data …”, could be it’s just me who was to impatient, or that it “shook” loose from being restarted.

EDIT 2:
I got fatal error:

2017-09-04 12:44:43Z - Error: Found remote files reported as duplicates, either the backend module is broken or you need to manually remove the extra copies.
The following files were found multiple times: duplicati-i5824dbefe7454a04aeed3358acc6e886.dindex.zip.aes
2017-09-04 12:44:43Z - Profiling: PreBackupVerify took 00:11:05.267
2017-09-04 12:44:43Z - Error: Fatal error
Duplicati.Library.Interface.UserInformationException: Found remote files reported as duplicates, either the backend module is broken or you need to manually remove the extra copies.
The following files were found multiple times: duplicati-i5824dbefe7454a04aeed3358acc6e886.dindex.zip.aes
at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, IBackendWriter log, System.String protectedfile) <0x40dfcbd0 + 0x008ff> in :0
at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify (Duplicati.Library.Main.BackendManager backend, System.String protectedfile) <0x40dfc6a0 + 0x001af> in :0
2017-09-04 12:44:43Z - Profiling: Running Backup took 00:39:48.722

EDIT 3
I deleted “duplicati-i5824dbefe7454a04aeed3358acc6e886.dindex.zip.aes” (also from the trashcan) and started again. Seems to work, but now it halted on:

2017-09-04 14:26:12Z - Information: Backend event: Put - Started: duplicati-ib0c706f7803144248c01e2b8b81616ee.dindex.zip.aes (66.12 KB)
2017-09-04 14:26:15Z - Profiling: Uploaded 66.12 KB in 00:00:02.9072230, 22.74 KB/s
2017-09-04 14:26:15Z - Information: Backend event: Put - Completed: duplicati-ib0c706f7803144248c01e2b8b81616ee.dindex.zip.aes (66.12 KB)
2017-09-04 14:26:15Z - Profiling: RemoteOperationPut took 00:00:03.068

Duplicati has a process working in the background, but nothing is written to the log. So not sure whats going on. Status is “Verifying backend data …”

EDIT 4
Aaand, it looks like it’s back on track uploading the data.

[kenkendk]

@NoLooseEnds

How long should this process take?

It should be very fast, like a second or so.

@NoLooseEnds

Aaand, it looks like it’s back on track uploading the data.

Weeee

[NoLooseEnds]

It did not take a second, it took way longer. It took at least 2-3 hours from the initial log till it started backing up again (and that was after I restarted the whole thing after it hung for hours).

I just deleted the log file, since it took up a few GB so I can’t provide any more details (I have now added it to the log rotation settings, so should at least keep the latest from now on).

Anyhow, thanks for an awesome project.

[NoLooseEnds]

The saga sort of continues…

I got an error message saying that it failed due to disk space [Insertion failed because the database is full
database or disk is full] (I have a few gb available on the Ubuntu VM), but I googled and read that it could be the /tmp that became full, so I used the advanced option and moved the tmp directory to the same NAS that is backing up (via NFS, VM network – all on the same machine).

Now I started it up again and it takes forever, and the log does not show anything. The last time it took hours, and my guess is that it will take hours again.

BUT @kenkendk said it should take seconds. Any input on how to debug/figure out this?

EDIT:
Now it started to verify back end data. It took over 2 hours before anything happened. Please see this log excerpt, especially the timing entries.

From Duplicati start till “something happened”:

Sep 14, 2017 12:14 PM: ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" > ? **took 02:07:24.819**
Sep 14, 2017 10:04 AM: Server has started and is listening on 0.0.0.0, port 8200

From Verifiying Back End Data till starting backing up

Sep 14, 2017 2:28 PM: 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" **took 02:01:18.852**
Sep 14, 2017 12:27 PM: 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"

So in summary, it takes around 4 hours from it starts till it starts backing up. Any thing I can do to debug/speed it up?

EDIT 2:
Also, before the “out of disk space error” it was around 1,5 TB left. Now it says 3.5 TB – and are uploading. Some files should be new, but not 2+ TB worth. Should this worry me?

[kenkendk]

@NoLooseEnds

I got an error message saying that it failed due to disk space [Insertion failed because the database is full

database or disk is full] (I have a few gb available on the Ubuntu VM), but I googled and read that it could be the /tmp that became full, so I used the advanced option and moved the tmp directory to the same NAS that is backing up (via NFS, VM network – all on the same machine).

Please note that SQLite does not honor the hint to use a new tempfolder from the options. You need to set the environment variable TMPDIR to change the temporary folder.

@NoLooseEnds

So in summary, it takes around 4 hours from it starts till it starts backing up. Any thing I can do to debug/speed it up?

From what I can see in the code, the query you reported as taking 2 hours (wow!) is rebuilding missing index file(s). Do you have any idea why it would recreate the index file? Was it deleted? Any error messages?

@NoLooseEnds

Also, before the “out of disk space error” it was around 1,5 TB left. Now it says 3.5 TB – and are uploading. Some files should be new, but not 2+ TB worth. Should this worry me?

No worry, it just scans the files before it finds that they are not changed. It is also discussed here:

Rework "size remaining" indicator in the running backup status bar

…If possible? The issue I’ve noticed is that when new data is added to a backup set, and a job is run to get that new data uploaded (especially if there’s a lot), the backup engine isn’t especially thorough at figuring out in advance just how much of the pending job is already uploaded. I’m not sure it’s necessarily possible (though forgive me in advance for saying “but crashplan…”) - but it’s a tiny bit frustrating to add 10 GB more data to my backup set of ~400, and for the hour or so it tak…

[NoLooseEnds]

Thank you @kenkendk

SQLite/TMP
I saw that, but I figured the DB would prefer to be native (speed, etc.)

I checked the DB location (/root/.config/Duplicati), and this is all the files:

drwxr-xr-x 2 root root 4.0K Aug 23 09:58 control_dir_v2
-rw-r--r-- 1 root root  43K Sep 14 11:04 Duplicati-server.sqlite
-rw-r--r-- 1 root root  33K Aug 23 16:15 ERIQEJISDM.backup
-rw-r--r-- 1 root root  33K Aug 23 16:15 ERIQEJISDM.sqlite
-rw-r--r-- 1 root root 3.6G Sep 14 21:14 QZDJRHUBWM.sqlite
-rw-r--r-- 1 root root 2.5M Sep 14 21:13 QZDJRHUBWM.sqlite-journal

(also looks like there are two old files there – since they have not been updated since 23rd of August)

How large do they usually become? What is the backup size / db ratio?

And lets say I want to move the db. Can I just copy the directory, and use the “dbpath” setting? Or do I have to set the TMPDIR variable in Linux? I would prefer to have all settings in the config if possible (everything at one place).

Time spent
It was ~2 hours from start till it started verifying data, and then 2 more from verifying till actually backin up. ~4 hours in total.

No Worry
I think this also takes quite a bit of time. It started backing up again around 2-3 PM, and now it’s 10 PM, and it’s only progressed from from 3,5X TB to 3,4X TB.

[mohak]

It could be that the files duplicati started working on first were the new ones that it needed to upload. When it encounters previously uploaded files, you should see it progress pretty quickly.

[NoLooseEnds]

I think some of them were new, but it has not uploaded anything to the backend (G Suite Drive) in many hours. The last one was at 3:31 PM.

I’m also monitoring the bandwidth usage, and it’s idling at 30 KB/s atm. And it has transferred a total of 3,5 GB on that interface since around 10 AM today (and that is all traffic, also non Duplicati traffic – which is minimal, but still).

(It does not include the traffic from the NAS (Internal ESXi network on own nic), only the outbound traffic on the regular LAN.

[kenkendk]

@NoLooseEnds

How large do they usually become? What is the backup size / db ratio?

A hash (in base64 + \0) is 44 bytes, and with 100kb blocks, you need to store at least 44 bytes pr. 100kb, or 450kb pr GB of source data.
On top of that you need to store all the paths, in a rather crude manner where each folder and file path is stored in its full length, taking up a considerate amount of space for large backups.

@NoLooseEnds

And lets say I want to move the db. Can I just copy the directory, and use the “dbpath” setting?

Yes, it can be moved freely. But from the Web-UI you need to use the “Database” option for moving the database as it ignores the --dbpath advanced option.

@NoLooseEnds

I checked the DB location (/root/.config/Duplicati), and this is all the files:

Yes, but the file that SQLite creates is a temporary transaction file, which it places in TMPDIR.

[kenkendk]

@NoLooseEnds

I think some of them were new, but it has not uploaded anything to the backend (G Suite Drive) in many hours.

Then it is possible that it is just spending all its time in database lookups, trying to see if the file has changed or not. You can use --check-filetime-only to have this lookup done faster, if you know that your programs do not fiddle with the timestamps.

[NoLooseEnds]

Thank you again for good answers @kenkendk, much appreciated.

A few follow up questions:

• Why does the webui ignore the dbpath option?
• Does the temporary SQL file get very large? Or is it safe to leave it there if my /tmp has 4GB to spare?
• Could you please elaborate a bit on --check-filetime-only?

This flag instructs Duplicati to not look at metadata or filesize when deciding to scan a file for changes. Use this option if you have a large number of files and notice that the scanning takes a long time with unmodified files.

The files are on NAS that is shared in a small design studio (mac only), and used by a few people every day. As far as I know it’s no “fiddling” with timestamps, but files can change (as in any backup). But yes, it’s a lot of files – also a lot of duplicate files (typically images that is used in a lot of different projects).

(The NAS itself is run on OmniOS with ZFS, shared via CFS/SMB (mac clients) and NFS (ie. Ubuntu VM).)

And the current log file is full of:

Sep 14, 2017 11:30 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
Sep 14, 2017 11:30 PM: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 00:00:00.015

[kenkendk]

@NoLooseEnds

Why does the webui ignore the dbpath option?

Internally, the database path is stored in one place, and options in another. As many operations from the WebUI needs access to the database, it made sense to just hide the database things from the users.

I have been planning to fix this a bit by adding some logic that checks if the user has changed the --dbpath option and ask them how to handle it, but for now it is a bit obscure.

@NoLooseEnds

Does the temporary SQL file get very large? Or is it safe to leave it there if my /tmp has 4GB to spare?

That really depends on how much data you put in there. It should not grow larger than the size of the database itself (well, perhaps marginally if new data is added).

@NoLooseEnds

Could you please elaborate a bit on --check-filetime-only?

Duplicati compares: metadata, filesize, timestamp. If either of these values have changed, the file blocks will be scanned. The rationale is that hashing is an expensive operation, and can be avoided.

To get the previous values for this, it looks in the database and finds the previous values for the current file. Some users report that this lookup is slow. The --check-filetime-only makes a faster lookup, by only loading the previous timestamp, and ignoring the other values.

Some people are using programs that fiddle with the timestamps (i.e. TrueCrypt) and these files stay the same size and the same timestamp. You can use --disable-filetime-check to force scanning all the files regardless of their attributes.

@NoLooseEnds

And the current log file is full of:

Sep 14, 2017 11:30 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
Sep 14, 2017 11:30 PM: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 00:00:00.015

That is block lookups, it checks if it already knows the data that it found.

[NoLooseEnds]

Thank you.

I’ve now moved the DB (not the /tmp as of now). I also enabled “–check-filetime-only”.

So far it’s much faster starting up, but it looks like it spends a lot of time “Verifying backend data …”. Not sure if it’s possible to optimize any further?

[kenkendk]

@NoLooseEnds

So far it’s much faster starting up, but it looks like it spends a lot of time “Verifying backend data …”. Not sure if it’s possible to optimize any further?

The initial check is just a listing of the remote files, and should be pretty fast.

There is another verification at the end, where it downloads a random volume and checks it for consistency, which can be slow due to the network transfer.

There is more on how to fiddle with this here:

How often does duplicati test your backup archives?

Duplicati uses two levels of verification. Before doing anything, it lists all the remote files and checks that all files are found and have the correct size. It also checks that there are no new files. There is a feature request to also check the remote files against an MD5 or SHA-1 sum if the storage provider reports it. The second step is actually downloading a file and testing that it can be decrypted, decompressed and that its contents are as expected. This is done with a random sampling …

[kenkendk]

And I should add: you can disable all remote checks completely with --no-backend-verification.

[NoLooseEnds]

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)

[NoLooseEnds]

(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.

[JonMikelV]

@NoLooseEnds

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.

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…)

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)

[NoLooseEnds]

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.

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?

[JonMikelV]

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