Backup hangs, nothing in log

Hi,

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,

Frank

Hi,

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!

Thank you and best regards,

Frank

Hi Frank, welcome to the forum!

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?

Thanks

Hi,

Thanks for the welcome :slight_smile:

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 -[^~$.*]

Thanks a lot and best regards,

Frank

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.

We have no intentional symlinks, so I removed the option.

Did it make any difference for your hang problem?

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