Running Duplicati 2.0.5.0 on Win 2019 as a service.
Backup never finishes, hangs for many hours (or days if I wait that long) at “Current action: Backup_ProcessingFiles”.
Last lines in log file (log level Profiling) are many UPDATE Block and about 15 DELETE SQL statements and then:
2020-01-07 23:23:56 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS “DelBlockSetIds-71CB9A7E7AB3464297C709B02C720F52”
2020-01-07 23:23:56 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS “DelBlockSetIds-71CB9A7E7AB3464297C709B02C720F52” took 0:00:00:00.000
2020-01-07 23:23:56 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS “DelVolSetIds-71CB9A7E7AB3464297C709B02C720F52”
2020-01-07 23:23:56 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS “DelVolSetIds-71CB9A7E7AB3464297C709B02C720F52” took 0:00:00:00.000
2020-01-07 23:23:57 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Fileset” WHERE “Timestamp” < 1578434400 AND “ID” != 15 ORDER BY “Timestamp” DESC
2020-01-07 23:23:57 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT “ID” FROM “Fileset” WHERE “Timestamp” < 1578434400 AND “ID” != 15 ORDER BY “Timestamp” DESC took 0:00:00:00.000
2020-01-07 23:23:57 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT
f.“Path”, fs.“FileID”, fs.“Lastmodified”, COALESCE(bs.“Length”, -1)
FROM ( SELECT DISTINCT “FileID”, “Lastmodified”
FROM “FilesetEntry”
WHERE “FilesetID” = 14
AND “FileID” NOT IN (
SELECT “FileID”
FROM “FilesetEntry”
WHERE “FilesetID” = 15
)) AS fs
LEFT JOIN “File” AS f ON fs.“FileID” = f.“ID”
LEFT JOIN “Blockset” AS bs ON f.“BlocksetID” = bs.“ID”;
2020-01-07 23:23:59 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT
f.“Path”, fs.“FileID”, fs.“Lastmodified”, COALESCE(bs.“Length”, -1)
FROM ( SELECT DISTINCT “FileID”, “Lastmodified”
FROM “FilesetEntry”
WHERE “FilesetID” = 14
AND “FileID” NOT IN (
SELECT “FileID”
FROM “FilesetEntry”
WHERE “FilesetID” = 15
)) AS fs
LEFT JOIN “File” AS f ON fs.“FileID” = f.“ID”
LEFT JOIN “Blockset” AS bs ON f.“BlocksetID” = bs.“ID”; took 0:00:00:02.609
2020-01-07 23:24:01 +01 - [Profiling-Duplicati.Library.Main.Operation.Backup.BackendUploader-UploadSpeed]: Uploaded 249.76 MB in 00:00:23.0331741, 10.84 MB/s
Since then (i.e. for over 22 hours) nothing in the log and Duplicati.Server.exe constantly at 25% CPU (on a 4-core VM).
Many thanks for any suggestions how to find out more and best regards,
This doesn’t happen at every backup run of this server. Some runs finish w/o errors, and some just hang as described.
The Duplicati process seems to be stuck somehow at 25% CPU i.e. 1 Core of the VM: If I click on “Stop running backup”, the UI changes to “Stopping after the current file” and stays there indefinitely (or at least for many hours). As mentioned, nothing is added to the log after it hangs.
Up till now I can’t see a pattern for the position in the backup where it hangs.
Last night the last log entries before it hung were these:
2020-01-14 23:27:37 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT “ID” FROM “Fileset” WHERE “Timestamp” < 1579039200 AND “ID” != 17 ORDER BY “Timestamp” DESC took 0:00:00:00.000
2020-01-14 23:27:37 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT
f.“Path”, fs.“FileID”, fs.“Lastmodified”, COALESCE(bs.“Length”, -1)
FROM ( SELECT DISTINCT “FileID”, “Lastmodified”
FROM “FilesetEntry”
WHERE “FilesetID” = 16
AND “FileID” NOT IN (
SELECT “FileID”
FROM “FilesetEntry”
WHERE “FilesetID” = 17
)) AS fs
LEFT JOIN “File” AS f ON fs.“FileID” = f.“ID”
LEFT JOIN “Blockset” AS bs ON f.“BlocksetID” = bs.“ID”;
2020-01-14 23:27:43 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT
f.“Path”, fs.“FileID”, fs.“Lastmodified”, COALESCE(bs.“Length”, -1)
FROM ( SELECT DISTINCT “FileID”, “Lastmodified”
FROM “FilesetEntry”
WHERE “FilesetID” = 16
AND “FileID” NOT IN (
SELECT “FileID”
FROM “FilesetEntry”
WHERE “FilesetID” = 17
)) AS fs
LEFT JOIN “File” AS f ON fs.“FileID” = f.“ID”
LEFT JOIN “Blockset” AS bs ON f.“BlocksetID” = bs.“ID”; took 0:00:00:05.622
This night the last log entries were these (path names shortened):
IncludingPath]: Including path as no filters matched: H:\Home\PE1209…
2020-01-15 01:15:59 +01 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: H:\Home\PE1209…
2020-01-15 01:15:59 +01 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: H:\Home\PE1209…
2020-01-15 01:15:59 +01 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: H:\Home\PE1209…
Sometimes it hangs after a block is successfully uploaded (as in my opening message), sometimes much earlier (like today).
Any suggestions how I could troubleshoot this further would be much appreciated!
Can you provide more details? What destination are you targeting? Has Duplicati ever worked for you, or is this your first time using it? Can you list any options you have customized?
I have used Duplicati quite successfully (backups and restores) on 9 servers with source sizes between several 100 GB and about 1.2 TB for years, all of them with the same destination (our own MinIO server).
Sure, there were problems, but I always had some errors and log content to go on, not like this where I’m stumped how to find out more about these hangs…
This (sometimes) hanging job is the largest so far with source size about 2.4 TB. Options for it are:
–snapshot-policy=On
–usn-policy=On
–number-of-retries=5
–symlink-policy=Follow
–allowed-ssl-versions=Tls12
–tempdir=G:\Temp
–blocksize=500KB
–auto-vacuum=true
–debug-output=true
–log-file=G:\Temp\duplicati.log
–log-file-log-level=Profiling
–use-block-cache=true
Remote volume size is 250 MB, custom backup retention is 3M:1D,1Y:1W,2Y:1M, temporary files excluded, custom exclude filter -[^~$.*]
I would be careful with this option. I believe it can cause infinite looping if a symlink points back to a parent folder. DId you intentionall set up junctions or symlinks in the data areas of your server (that you are trying to back up)? Or are you backing up C:\Users? Windows itself sets up this scenario inside AppData\Local.
No change, still hangs, last lines in the log this time around:
2020-01-16 21:19:02 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM “DelBlockSetIds-2DB603A797F61C4EB0ADC74E7CC20D9D” took 0:00:00:00.000
2020-01-16 21:19:02 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM “DelVolSetIds-2DB603A797F61C4EB0ADC74E7CC20D9D”
2020-01-16 21:19:02 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM “DelVolSetIds-2DB603A797F61C4EB0ADC74E7CC20D9D” took 0:00:00:00.000
2020-01-16 21:19:02 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS “DelBlockSetIds-2DB603A797F61C4EB0ADC74E7CC20D9D”
2020-01-16 21:19:02 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS “DelBlockSetIds-2DB603A797F61C4EB0ADC74E7CC20D9D” took 0:00:00:00.000
2020-01-16 21:19:02 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS “DelVolSetIds-2DB603A797F61C4EB0ADC74E7CC20D9D”
2020-01-16 21:19:02 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS “DelVolSetIds-2DB603A797F61C4EB0ADC74E7CC20D9D” took 0:00:00:00.000
2020-01-16 21:19:04 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Fileset” WHERE “Timestamp” < 1579204963 AND “ID” != 18 ORDER BY “Timestamp” DESC
2020-01-16 21:19:04 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT “ID” FROM “Fileset” WHERE “Timestamp” < 1579204963 AND “ID” != 18 ORDER BY “Timestamp” DESC took 0:00:00:00.000
2020-01-16 21:19:04 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT
f.“Path”, fs.“FileID”, fs.“Lastmodified”, COALESCE(bs.“Length”, -1)
FROM ( SELECT DISTINCT “FileID”, “Lastmodified”
FROM “FilesetEntry”
WHERE “FilesetID” = 17
AND “FileID” NOT IN (
SELECT “FileID”
FROM “FilesetEntry”
WHERE “FilesetID” = 18
)) AS fs
LEFT JOIN “File” AS f ON fs.“FileID” = f.“ID”
LEFT JOIN “Blockset” AS bs ON f.“BlocksetID” = bs.“ID”;
2020-01-16 21:19:09 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT
f.“Path”, fs.“FileID”, fs.“Lastmodified”, COALESCE(bs.“Length”, -1)
FROM ( SELECT DISTINCT “FileID”, “Lastmodified”
FROM “FilesetEntry”
WHERE “FilesetID” = 17
AND “FileID” NOT IN (
SELECT “FileID”
FROM “FilesetEntry”
WHERE “FilesetID” = 18
)) AS fs
LEFT JOIN “File” AS f ON fs.“FileID” = f.“ID”
LEFT JOIN “Blockset” AS bs ON f.“BlocksetID” = bs.“ID”; took 0:00:00:04.611
Sorry to jump in on this thread, but I’m experiencing similar problems on one Windows 10 machine that backs up to Wasabi. It runs for about 15min then simply stops and sits at the same point mentioned “Backup_ProcessingFiles”.
The last lines of the log after nearly two hours are:
* 4 May 2020 17:13: ExecuteReader: SELECT f."Path", fs."FileID", fs."Lastmodified", COALESCE(bs."Length", -1) FROM ( SELECT DISTINCT "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 381 AND "FileID" NOT IN ( SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 382 )) AS fs LEFT JOIN "File" AS f ON fs."FileID" = f."ID" LEFT JOIN "Blockset" AS bs ON f."BlocksetID" = bs."ID"; took 0:00:00:01.277
* 4 May 2020 17:13: Starting - ExecuteReader: SELECT f."Path", fs."FileID", fs."Lastmodified", COALESCE(bs."Length", -1) FROM ( SELECT DISTINCT "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 381 AND "FileID" NOT IN ( SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 382 )) AS fs LEFT JOIN "File" AS f ON fs."FileID" = f."ID" LEFT JOIN "Blockset" AS bs ON f."BlocksetID" = bs."ID";
* 4 May 2020 17:13: ExecuteScalarInt64: SELECT "ID" FROM "Fileset" WHERE "Timestamp" < 1588604400 AND "ID" != 382 ORDER BY "Timestamp" DESC took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Fileset" WHERE "Timestamp" < 1588604400 AND "ID" != 382 ORDER BY "Timestamp" DESC
* 4 May 2020 17:13: ExecuteNonQuery: DROP TABLE IF EXISTS "DelMetadataFilesetIds-6C040446C1EFD041B70A202BCB151D81" took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelMetadataFilesetIds-6C040446C1EFD041B70A202BCB151D81"
* 4 May 2020 17:13: ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81"
* 4 May 2020 17:13: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-6C040446C1EFD041B70A202BCB151D81" took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-6C040446C1EFD041B70A202BCB151D81"
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81"
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-6C040446C1EFD041B70A202BCB151D81" took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-6C040446C1EFD041B70A202BCB151D81"
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM Fileset WHERE Fileset.ID IN (SELECT DISTINCT FilesetID FROM "DelMetadataFilesetIds-6C040446C1EFD041B70A202BCB151D81") AND Fileset.ID NOT IN (SELECT DISTINCT FilesetID FROM FilesetEntry) took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM Fileset WHERE Fileset.ID IN (SELECT DISTINCT FilesetID FROM "DelMetadataFilesetIds-6C040446C1EFD041B70A202BCB151D81") AND Fileset.ID NOT IN (SELECT DISTINCT FilesetID FROM FilesetEntry)
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ) took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" )
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetID IN (SELECT ID FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" )) took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetID IN (SELECT ID FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ))
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM "ChangeJournalData" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" )) took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM "ChangeJournalData" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ))
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ) took 0:00:00:01.197
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" )
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ) took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" )
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ) took 0:00:00:00.003
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-6C040446C1EFD041B70A202BCB151D81" )
* 4 May 2020 17:13: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "BlocklistHash"."BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-6C040446C1EFD041B70A202BCB151D81" ) took 0:00:00:00.000
* 4 May 2020 17:13: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "BlocklistHash"."BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-6C040446C1EFD041B70A202BCB151D81" )
The Duplicati.Server.exe process is still using CPU, around 12% but there is no file or network I/O happening, and no obvious data files are in use.
If I try to stop the job with the GUI it never stops even though it receives the commands according to the logs. I’m left with only killing the Duplicati processes and picking up the pieces by trying it again i.e. clean ups and the such.
