Duplicati UI stuck at Completing previous backup

Support
1

I’m a new user and scratching my head trying to understand what state Duplicati is in and how to complete one of my backup jobs. It’s been 24 hours and the UI right now says Completing previous backup... (a previous backup job was hung and I restarted the process). The process is spinning on the CPU doing unknown work.

Duplicati 2.0.7.1_beta_2023-05-25
Backend: Backblaze B2
Remote volume size: 500MB

From the verbose logs:

Sep 25, 2023 10:02 PM: Uploading filelist from previous interrupted backup
Sep 25, 2023 10:02 PM: promoting uploaded complete file from Uploading to Uploaded: duplicati-[redacted].dindex.zip.aes
Sep 25, 2023 10:02 PM: promoting uploaded complete file from Uploading to Uploaded: duplicati-[redacted].dblock.zip.aes 
...

From the profiling logs:


Sep 25, 2023 10:02 PM: ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") SELECT 6 AS "FilesetID", "FileID", "Lastmodified" FROM (SELECT DISTINCT "FilesetID", "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 5 AND "FileID" NOT IN (SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 6)) took 0:00:00:04.625
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") SELECT 6 AS "FilesetID", "FileID", "Lastmodified" FROM (SELECT DISTINCT "FilesetID", "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 5 AND "FileID" NOT IN (SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 6))
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Fileset" WHERE "Timestamp" < 1695588507 AND "ID" != 6 ORDER BY "Timestamp" DESC took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Fileset" WHERE "Timestamp" < 1695588507 AND "ID" != 6 ORDER BY "Timestamp" DESC
Sep 25, 2023 10:02 PM: ExecuteNonQuery: UPDATE "Fileset" SET "VolumeID" = 1489 WHERE "ID" = 6 took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: UPDATE "Fileset" SET "VolumeID" = 1489 WHERE "ID" = 6
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: INSERT INTO "Fileset" ("OperationID", "Timestamp", "VolumeID", "IsFullBackup") VALUES (4, 1695588507, 1489, 0); SELECT last_insert_rowid(); took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: INSERT INTO "Fileset" ("OperationID", "Timestamp", "VolumeID", "IsFullBackup") VALUES (4, 1695588507, 1489, 0); SELECT last_insert_rowid();
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (4, "duplicati-20230924T204827Z.dlist.zip.aes", "Files", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (4, "duplicati-20230924T204827Z.dlist.zip.aes", "Files", "Temporary", -1, 0, 0); SELECT last_insert_rowid();
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-20230924T204827Z.dlist.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-20230924T204827Z.dlist.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
Sep 25, 2023 10:02 PM: Uploading filelist from previous interrupted backup 
...
2

Hello

it’s a bit difficult to evaluate a situation where your system is stuck at something for hours and you are quoting what happens during ONE minute. There is nothing that stands out in this tiny amount of time.
Also how to know what kind of system you have ? You seem to want to backup about half a TB of data (at least 1489 blocks / 2 => 700 * 500 MB), that can be quite ordinary on a high end system and totally mad on a slow system, if the latter no wonder if it’s long, especially if you have crashed the system.

3

Hey there! Thanks for the quick reply and apologies for the lack of log data. I’m a developer and appreciate how frustrating it is to receive vague reports. I’m just not sure what other data I can present. Those lines are from SEP 25 10PM PST. It is now SEP 26 1PM PST.

The only new log entry for today is:

Sep 26, 2023 11:53 AM: Cannot find any MS SQL Server instance. MS SQL Server is probably not installed.

This is running on an Intel Xeon E-2224 3.4ghz CPU w/ various attached disks. Overall CPU usage is at about 35%, memory usage at about 50%. Regardless of performance, I’d expect the process to complete but in this case it appears Duplicati is hung on something.

4

Taking another look, I can see Duplicati is still hammering the SQLite database (main thread stack without symbols below) so perhaps there’s no issue here and it’s just slow. I’ll let it keep running for a bit, hope it’s not stuck in a loop.

ntdll.dll!ZwReadFile+0x14
KERNELBASE.dll!ReadFile+0x108
SQLite.Interop.dll!sqlite3_os_init+0x3502
SQLite.Interop.dll!sqlite3_enable_shared_cache+0x879e
SQLite.Interop.dll!sqlite3_enable_shared_cache+0x6176
SQLite.Interop.dll!sqlite3_backup_init+0xbec5
SQLite.Interop.dll!sqlite3_backup_init+0x8387
SQLite.Interop.dll!sqlite3_blob_open+0x4aa4
SQLite.Interop.dll!sqlite3_step+0x30b
SQLite.Interop.dll!sqlite3_step+0xfb
0x0000000000000000
[Native Frame: IL Method without Metadata]
[Managed to Unmanaged Transition]
C:\Program Files\Duplicati 2\SQLite\win64\System.Data.SQLite.dll!System.Data.SQLite.SQLite3.Step+0x2f9
C:\Program Files\Duplicati 2\SQLite\win64\System.Data.SQLite.dll!System.Data.SQLite.SQLiteDataReader.NextResult+0xe4
C:\Program Files\Duplicati 2\SQLite\win64\System.Data.SQLite.dll!System.Data.SQLite.SQLiteDataReader..ctor+0x13d
C:\Program Files\Duplicati 2\SQLite\win64\System.Data.SQLite.dll!System.Data.SQLite.SQLiteCommand.ExecuteReader+0x3c
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Database.LocalDatabase.WriteFileset+0x3d9
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!<>c__DisplayClass3_0.<RunOnMain>b__0+0x12
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!<DoRunOnMain>d__2`1.MoveNext+0x1a6
C:\WINDOWS\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.Start+0x80
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Operation.Common.SingleRunner.DoRunOnMain+0x53
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!<<Run>b__0>d.MoveNext+0x1153
C:\WINDOWS\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start+0x80
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!<>c__DisplayClass1_0.<Run>b__0+0x5c
C:\Program Files\Duplicati 2\CoCoL.dll!<RunTask>d__10`1.MoveNext+0x9f
C:\WINDOWS\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start+0xa4
C:\Program Files\Duplicati 2\CoCoL.dll!CoCoL.AutomationExtensions.RunTask+0x9d
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!<RunAsync>d__20.MoveNext+0xaa5
C:\WINDOWS\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start+0x80
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Operation.BackupHandler.RunAsync+0x6f
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!<>c__DisplayClass14_0.<Backup>b__0+0x88
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Controller.RunAction+0x43e
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Controller.Backup+0x153
C:\Program Files\Duplicati 2\Duplicati.Server.exe!Duplicati.Server.Runner.Run+0x8a5
C:\Program Files\Duplicati 2\Duplicati.Library.Utility.dll!Duplicati.Library.Utility.WorkerThread`1.Runner+0x227
5

So this line is the last before the cannot find any MS SQL Server (that appears when Duplicati starts normally) ?

6

Here’s the entire log shown in About > Show Log > Live (verbose and profiling). I can’t seem to access any more log data.

Verbose 
Sep 26, 2023 11:53 AM: Cannot find any MS SQL Server instance. MS SQL Server is probably not installed.
Sep 25, 2023 10:02 PM: Uploading filelist from previous interrupted backup
Sep 25, 2023 10:02 PM: promoting uploaded complete file from Uploading to Uploaded: duplicati-iac618e27f2a4406a985277cac33eb00d.dindex.zip.aes
Sep 25, 2023 10:02 PM: promoting uploaded complete file from Uploading to Uploaded: duplicati-b393c81637cf042a69937d9f6d80c10bd.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i988d4974675e457db70e559877fa3c56.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b129376d8f6734e55817212997309c626.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-be87382e8debd4983b8698eaa723458e6.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-id78633cf5d824253995be20716478d9c.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-ie1ba6d4a34124c30822923f25223734f.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bc2a7a941668446fa8efd14d20f3211bb.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b2dc9a74cf98e4d8f91449feb2ac2b021.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b2ebafae6d74e4442ad55e6cc6285f1c4.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i7340a43dcc134d6fb2380cb73b990079.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b2dfd434091a848afb59bbb1ee8e55138.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b23503476409a499584a40a32a8cdb63f.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-ic51170db657d45f6820dfa79aa6a017d.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i2ffdbaa07b1c498085322fdd53a094c5.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b09a4391f7a1f4c27a7c0241d0f4a1442.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b3f293ec7830648c79d0567e6ce17d255.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bf9c891a6c64b4b8496d9e763e9a3831a.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b7f88795f75f949d88fc52821b025b390.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b84efc97eed444e3d87a2a828041e9df4.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-icc85903e7dab42b9a075f35e5c1d114b.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-ib157bba5a14942c9857e7ead3704f50d.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bb3d74236b91b4788a965b13f61f625b2.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b7dd4d6135e8443b2bdfc4529556fdc6a.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i4f66deca5ad64a1a9802a388d1504121.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b0ac716e3483f42a6a4528921355a1791.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b2d26629826614685970edb7ea68eab8e.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b5218f2b6bdc342c6b760008d7c5bd77a.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b9ddbbd9730ad4f0eb1c025d392f6a845.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b3d390747fcf74013a1e7f07fb75b5365.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b032f67acfc494d71afee8cc34c94d3a7.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-ia2420ccaf3cc40888c62a5e205d0c147.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i983875e15c3f48d0ad0147248df33e09.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b0e6c6920315b4324aece660a4cd576d6.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bd4cf671167964e6da393861c879ac256.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b7c037b2a3dc24ec2ae67a5113fd415ec.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bd860f9748bbe4794bef30c29ae59c5ea.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bff1f22a9f7704c3281ee7f773e5b2792.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i8c2914b2609849fab8ff00dad60c50c5.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-be158eaf838f94f59b48d05cf4016e811.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b4a1b2fdee11e42eea3ab9f81a00c6ced.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bb603aaa741664d7b9acea597a16ea148.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-id02c471cdcd24e068405a6461a416299.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b661b53b3daad4fdca58e1b045d1ef0af.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bd2829fc9d70f40399a2ba8fbc2d9f20b.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-be46fef000b3b46b08943d9ed4eb70167.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-if3926cb94e6b4148a78a1b4697723873.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b99635c49dae542c79a241d9b42e3bb23.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-ib488c472f88c4fb69931f1f0dae322ca.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-iba177cf0607e41bebc05e178ed616fb1.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-ia735441ff58a4ffbb1cb9d37d570ea5d.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bbd45705e440d4d649c7292420b84190c.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-ic17aa1a65bae4b8aa1c9baab1a333a6e.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b0726769037534941bb7b7458fab52015.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b44de02fa643942b288f659ceb501d3e2.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bd56d32b3b57046408d694daadb0368d6.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b458dc7ffb0e04178976a4ae26308550b.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i2a4e9b129d7f4ff19ab1ce9f0b2f2486.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bf179f19e091e4d89b72a48bd3363b84e.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-b75c7571348fd498e9638ccda69a85060.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i2f5c84ecb3a847d1b89deeb40d2ff0b1.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i950612b348904e7daefd5d965ed0ebe8.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i6a23212c7dfb4e979dc354cd3c042641.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i88dee02266c347ecb0aeb090158cc9e0.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i1d581b712b564359a17c6a4aec9db645.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i6670edde89e74a9384a3d06d27836c5b.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-babb6d17e1e754a1196bf972ff65e79ce.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i11e490ff55874d198806564008e5fd8f.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-i3c59fed1a74f423fb8827a498b4bbd3b.dindex.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-beca584b4970441a3a3f80adfe43cb074.dblock.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Deleting: duplicati-bf37ab2bee2ef4bb6aedfebdd89fb226b.dblock.zip.aes
Sep 25, 2023 10:02 PM: keeping protected incomplete remote file listed as Temporary: duplicati-20230924T204826Z.dlist.zip.aes
Sep 25, 2023 10:02 PM: scheduling missing file for deletion, currently listed as Uploading: duplicati-20230924T195442Z.dlist.zip.aes
Sep 25, 2023 10:02 PM: removing file listed as Temporary: duplicati-20230924T195441Z.dlist.zip.aes
Sep 25, 2023 10:02 PM: Backend event: List - Completed: (1.37 KB)
Sep 25, 2023 10:02 PM: Backend event: List - Started: ()
Profiling 

Sep 26, 2023 11:53 AM: Using WMI provider \\localhost\root\virtualization\v2
Sep 26, 2023 11:53 AM: Cannot find any MS SQL Server instance. MS SQL Server is probably not installed.
Sep 25, 2023 10:02 PM: ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") SELECT 6 AS "FilesetID", "FileID", "Lastmodified" FROM (SELECT DISTINCT "FilesetID", "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 5 AND "FileID" NOT IN (SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 6)) took 0:00:00:04.625
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") SELECT 6 AS "FilesetID", "FileID", "Lastmodified" FROM (SELECT DISTINCT "FilesetID", "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 5 AND "FileID" NOT IN (SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 6))
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Fileset" WHERE "Timestamp" < 1695588507 AND "ID" != 6 ORDER BY "Timestamp" DESC took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Fileset" WHERE "Timestamp" < 1695588507 AND "ID" != 6 ORDER BY "Timestamp" DESC
Sep 25, 2023 10:02 PM: ExecuteNonQuery: UPDATE "Fileset" SET "VolumeID" = 1489 WHERE "ID" = 6 took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: UPDATE "Fileset" SET "VolumeID" = 1489 WHERE "ID" = 6
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: INSERT INTO "Fileset" ("OperationID", "Timestamp", "VolumeID", "IsFullBackup") VALUES (4, 1695588507, 1489, 0); SELECT last_insert_rowid(); took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: INSERT INTO "Fileset" ("OperationID", "Timestamp", "VolumeID", "IsFullBackup") VALUES (4, 1695588507, 1489, 0); SELECT last_insert_rowid();
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (4, "duplicati-20230924T204827Z.dlist.zip.aes", "Files", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (4, "duplicati-20230924T204827Z.dlist.zip.aes", "Files", "Temporary", -1, 0, 0); SELECT last_insert_rowid();
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-20230924T204827Z.dlist.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-20230924T204827Z.dlist.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
Sep 25, 2023 10:02 PM: Uploading filelist from previous interrupted backup
Sep 25, 2023 10:02 PM: 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 0:00:00:00.156
Sep 25, 2023 10:02 PM: 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")
Sep 25, 2023 10:02 PM: PreSyntheticFilelist took 0:00:00:00.062
Sep 25, 2023 10:02 PM: Starting - PreSyntheticFilelist
Sep 25, 2023 10:02 PM: ExecuteReader: SELECT "RemoteVolume"."ID", "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume", "Fileset" WHERE "Fileset"."VolumeID" = "RemoteVolume"."ID" AND "Fileset"."ID" = 5 took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteReader: SELECT "RemoteVolume"."ID", "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume", "Fileset" WHERE "Fileset"."VolumeID" = "RemoteVolume"."ID" AND "Fileset"."ID" = 5
Sep 25, 2023 10:02 PM: PreBackupVerify took 0:00:00:25.804
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DROP TABLE IF EXISTS "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4"
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4"
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4"
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4"
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4"
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM Fileset WHERE Fileset.ID IN (SELECT DISTINCT FilesetID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4") AND Fileset.ID NOT IN (SELECT DISTINCT FilesetID FROM FilesetEntry) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM Fileset WHERE Fileset.ID IN (SELECT DISTINCT FilesetID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4") AND Fileset.ID NOT IN (SELECT DISTINCT FilesetID FROM FilesetEntry)
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetID IN (SELECT ID FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )) took 0:00:00:00.124
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetID IN (SELECT ID FROM Fileset WHERE VolumeID IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ))
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "ChangeJournalData" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "ChangeJournalData" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ))
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.750
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "BlocklistHash"."BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.015
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "BlocklistHash"."BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "FileLookup" WHERE "BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.156
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "FileLookup" WHERE "BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) took 0:00:00:00.109
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM FileLookup WHERE FileLookup.MetadataID IN (SELECT MetadataID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4") took 0:00:00:00.140
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM FileLookup WHERE FileLookup.MetadataID IN (SELECT MetadataID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4")
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetEntry.FileID IN ( SELECT ID FROM FileLookup WHERE FileLookup.BlocksetID IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )) took 0:00:00:00.234
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetEntry.FileID IN ( SELECT ID FROM FileLookup WHERE FileLookup.BlocksetID IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ))
Sep 25, 2023 10:02 PM: ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetEntry.FilesetID IN (SELECT DISTINCT FilesetID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4") AND FilesetEntry.FileID IN ( SELECT FilesetEntry.FileID FROM FilesetEntry INNER JOIN FileLookup ON FileLookup.ID = FilesetEntry.FileID WHERE FileLookup.MetadataID IN (SELECT MetadataID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4")) took 0:00:00:00.125
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: DELETE FROM FilesetEntry WHERE FilesetEntry.FilesetID IN (SELECT DISTINCT FilesetID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4") AND FilesetEntry.FileID IN ( SELECT FilesetEntry.FileID FROM FilesetEntry INNER JOIN FileLookup ON FileLookup.ID = FilesetEntry.FileID WHERE FileLookup.MetadataID IN (SELECT MetadataID FROM "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4"))
Sep 25, 2023 10:02 PM: ExecuteNonQuery: INSERT OR IGNORE INTO "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" (MetadataID, FilesetID) SELECT Metadataset.ID, FilesetEntry.FilesetID FROM Metadataset INNER JOIN FileLookup ON FileLookup.MetadataID = Metadataset.ID INNER JOIN FilesetEntry ON FilesetEntry.FileID = FileLookup.ID WHERE Metadataset.BlocksetID IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) OR Metadataset.ID IN (SELECT MetadataID FROM FileLookup WHERE BlocksetID IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )) took 0:00:00:01.437
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" (MetadataID, FilesetID) SELECT Metadataset.ID, FilesetEntry.FilesetID FROM Metadataset INNER JOIN FileLookup ON FileLookup.MetadataID = Metadataset.ID INNER JOIN FilesetEntry ON FilesetEntry.FileID = FileLookup.ID WHERE Metadataset.BlocksetID IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) OR Metadataset.ID IN (SELECT MetadataID FROM FileLookup WHERE BlocksetID IN (SELECT DISTINCT "ID" FROM "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ))
Sep 25, 2023 10:02 PM: ExecuteNonQuery: CREATE TEMP TABLE "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" (MetadataID INTEGER PRIMARY KEY, FilesetID INTEGER) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelMetadataFilesetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" (MetadataID INTEGER PRIMARY KEY, FilesetID INTEGER)
Sep 25, 2023 10:02 PM: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ("ID") SELECT DISTINCT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block" WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) UNION ALL SELECT DISTINCT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" )) took 0:00:00:21.614
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ("ID") SELECT DISTINCT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block" WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ) UNION ALL SELECT DISTINCT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ))
Sep 25, 2023 10:02 PM: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ("ID" INTEGER PRIMARY KEY) took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-7BAA8E25C97D1E4C9655A4E0453B48C4" ("ID" INTEGER PRIMARY KEY)
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-i988d4974675e457db70e559877fa3c56.dindex.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-i988d4974675e457db70e559877fa3c56.dindex.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b129376d8f6734e55817212997309c626.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b129376d8f6734e55817212997309c626.dblock.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-be87382e8debd4983b8698eaa723458e6.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-be87382e8debd4983b8698eaa723458e6.dblock.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-id78633cf5d824253995be20716478d9c.dindex.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-id78633cf5d824253995be20716478d9c.dindex.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-ie1ba6d4a34124c30822923f25223734f.dindex.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-ie1ba6d4a34124c30822923f25223734f.dindex.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-bc2a7a941668446fa8efd14d20f3211bb.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-bc2a7a941668446fa8efd14d20f3211bb.dblock.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b2dc9a74cf98e4d8f91449feb2ac2b021.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b2dc9a74cf98e4d8f91449feb2ac2b021.dblock.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b2ebafae6d74e4442ad55e6cc6285f1c4.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b2ebafae6d74e4442ad55e6cc6285f1c4.dblock.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-i7340a43dcc134d6fb2380cb73b990079.dindex.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-i7340a43dcc134d6fb2380cb73b990079.dindex.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b2dfd434091a848afb59bbb1ee8e55138.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b2dfd434091a848afb59bbb1ee8e55138.dblock.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b23503476409a499584a40a32a8cdb63f.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b23503476409a499584a40a32a8cdb63f.dblock.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-ic51170db657d45f6820dfa79aa6a017d.dindex.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-ic51170db657d45f6820dfa79aa6a017d.dindex.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-i2ffdbaa07b1c498085322fdd53a094c5.dindex.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-i2ffdbaa07b1c498085322fdd53a094c5.dindex.zip.aes"
Sep 25, 2023 10:02 PM: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b09a4391f7a1f4c27a7c0241d0f4a1442.dblock.zip.aes" took 0:00:00:00.000
Sep 25, 2023 10:02 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b09a4391f7a1f4c27a7c0241d0f4a1442.dblock.zip.aes"
7

Hmm this is not looking so good. I can’t understand why you have nothing in the log for one day.

how did you stop Duplicati exactly ? I know of at least of one case where you can use the Windows service manager to stop Duplicati (if it’s installed as a service) and the Windows service manager don’t complain, shows the service as stopped, but the Duplicati server process is still running (this is very bad of course). So did you use a civilized method (good from you but unfortunately can fail in at least one case) or did you kill the task with the task manager ?

8

I killed it with Task Manager previously. Please don’t hit me too hard.

9

well, you are supposed to ask Duplicati nicely to interrupt itself, but there are cases where it is not really useful unfortunately. So when did you kill it exactly? was it in this interval between the 2 first lines and the following:

Sep 26, 2023 11:53 AM: Using WMI provider \\localhost\root\virtualization\v2
Sep 26, 2023 11:53 AM: Cannot find any MS SQL Server instance. MS SQL Server is probably not installed.
Sep 25, 2023 10:02 PM: ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") SELECT 6 AS "FilesetID", "FileID", "Lastmodified" FROM (SELECT DISTINCT "FilesetID", "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 5 AND "FileID" NOT IN (SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 6)) took 0:00:00:04.625
Sep 25, 2023 10:02 PM: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") SELECT 6 AS "FilesetID", "FileID", "Lastmodified" FROM (SELECT DISTINCT "FilesetID", "FileID", "Lastmodified" FROM "FilesetEntry" WHERE "FilesetID" = 5 AND "FileID" NOT IN (SELECT "FileID" FROM "FilesetEntry" WHERE "FilesetID" = 6))
S
10

Process was killed via Task Manager then started via desktop shortcut at SEP 25, 2023 at approx. 02:38 PM PST. I then started the large backup job again and walked away.

Some other observations:

  • I see two instances of Duplicati.GUI.TrayIcon.exe running
  • I don’t have a Duplicati Windows Service
11

So if I understand correctly,between the backup start and the log end on SEP 25 10:02, there was about 7h30’ ? Does it seem likely for the backup to work for all this time (given the size you expect) ?

You did not delete the db at some point ?

When you run Duplicati as an user, it is normal.

12

hello

getting offline for a few hours now.

13

Thanks, no rush and appreciate the quick responses!

7 hours 30 minutes sounds right to me. It seems like the majority of the backup completed and uploaded to Backblaze very quickly. When I killed it, it was stuck on only a handful of tiny files for some reason. I killed Duplicati, deleted those files from the source, then restarted Duplicati and started the backup job again. The job then ran and seemed to finish very quickly, but is now busy at this last phase… not sure what it’s doing. Re-indexing perhaps? Repairing?

I can leave it running for a few days and see what happens.

14

Update: Duplicati no longer at “Completing previous backup”. It’s now at [Backup Job Name] 376 files (2.21 GB) to go at 56 bytes/s.

Not sure what’s up with that status but the CPU is still spinning so I’ll just leave it alone for another day. Verbose logs are now empty, seems Duplicati’s log system only keeps messages around for a small window of time?

15

I don’t know the live log internal workings, but FWIW I’ve been having some flakiness at Verbose level where there are gaps (a clear example is watching a DB recreate, which outputs a number sequence). Somehow switching to Profiling sees things (it’s harder to see gaps though, due to the massive output. Advanced options to log to a file seems best, but it’s not something one can set up in middle of a run…

The status bar tries to put a bunch of info into one line. The bytes/s shows up once uploads begin, and fluctuates because uploads are bundled in dblock files. About → System info → Server state properties → lastPgEvent shows details. It’s not a human-friendly display, but has info if other things are not going.

Although busy CPU is more suggestive of some SQL running (which Profiling log might show), bytes/s sags when nothing’s uploading, because it’s an average. lastPgEvent has bytes details that may clarify.

16

Update: Backup completed with ~300 minor file warnings. And subsequent runs are normal/fast. Glad I waited.