Duplicati Database Recreate running for a week

SovereignEntity · August 12, 2023, 4:02pm

Running 2.0.7.1_beta_2023-05-25
Had an issue with the machine I run Duplicati on
I have a backup of the Backup Config from when I set up the job,and the files to date,but when importing the job and connecting it to the folder it gives an Out of Sync warning and repairing doesn’t want to proceed
Recreating the database is running for days now with no end in sight on 2 different test machines

ts678 · August 13, 2023, 12:03pm

Welcome to the forum @SovereignEntity

This description needs some clarification.

What are you watching (system performance?) to see it’s running and to predict (or not) the end?

There’s a progress bar that moves left to right. Last 30% is unusual. Last 10% is rather bad news.

About → Show log → Live → Verbose is a good way to see what’s going on if it’s actually running. Pushing level up to Profiling might show more if, for example, database action is part of slowdown.

Meaning it broke, so you moved to

to attempt recovery of system data?

How so, and which system(s) is this?

Please give some information on the backup, for example the size and what storage type it’s on.
Larger backups (over 100 GB) might benefit from larger blocksize, but too late to change it now.
Lots of versions can also add processing time, but you can see where you are from hints above.

SovereignEntity · August 14, 2023, 2:41am

Thanks for the response!

What are you watching (system performance?) to see it’s running and to predict (or not) the end?

Yes,resource monitor,I see the occasional CPU and Disk spikes and can see operations,but it’s intermittent

Meaning it broke, so you moved to

The host hypervisor broke

to attempt recovery of system data?

Attempting to rebuild duplicati database to resume backups while retaining the current blocks and history

How so, and which system(s) is this?

Recreating Database is stuck on the same position in the “Progress bar” for a week
Xeon 8 Core and a 8 Core I7,SSD Storage

Backup size total is around 400Gig compressed,block sizes were 50Mb I believe. Versions is on Smart versioning

Exerpt of the log on Profiling:

14 Aug 2023 10:36: Starting - ExecuteNonQuery: INSERT INTO “BlocksetEntry” (“BlocksetID”, “Index”, “BlockID”) SELECT DISTINCT “H”.“BlocksetID”, “H”.“Index”, “H”.“BlockID” FROM (SELECT “E”.“BlocksetID” AS “BlocksetID”, “D”.“FullIndex” AS “Index”, “F”.“ID” AS “BlockID” FROM ( SELECT “E”.“BlocksetID”, “F”.“Index” + (“E”.“BlocklistIndex” * 3200) AS “FullIndex”, “F”.“BlockHash”, MIN(102400, “E”.“Length” - ((“F”.“Index” + (“E”.“BlocklistIndex” * 3200)) * 102400)) AS “BlockSize”, “E”.“Hash”, “E”.“BlocklistSize”, “E”.“BlocklistHash” FROM ( SELECT * FROM ( SELECT “A”.“BlocksetID”, “A”.“Index” AS “BlocklistIndex”, MIN(3200 * 32, (((“B”.“Length” + 102400 - 1) / 102400) - (“A”.“Index” * (3200))) * 32) AS “BlocklistSize”, “A”.“Hash” AS “BlocklistHash”, “B”.“Length” FROM “BlocklistHash” A, “Blockset” B WHERE “B”.“ID” = “A”.“BlocksetID” ) C, “Block” D WHERE “C”.“BlocklistHash” = “D”.“Hash” AND “C”.“BlocklistSize” = “D”.“Size” ) E, “TempBlocklist-638D9A01EB1FB343B8A4C71E6E36EE70” F WHERE “F”.“BlocklistHash” = “E”.“Hash” ORDER BY “E”.“BlocksetID”, “FullIndex” ) D, “BlocklistHash” E, “Block” F, “Block” G WHERE “D”.“BlocksetID” = “E”.“BlocksetID” AND “D”.“BlocklistHash” = “E”.“Hash” AND “D”.“BlocklistSize” = “G”.“Size” AND “D”.“BlocklistHash” = “G”.“Hash” AND “D”.“Blockhash” = “F”.“Hash” AND “D”.“BlockSize” = “F”.“Size” UNION SELECT “Blockset”.“ID” AS “BlocksetID”, 0 AS “Index”, “Block”.“ID” AS “BlockID” FROM “Blockset”, “Block”, “TempSmalllist-701EAF39AB2460438656C429144C7567” S WHERE “Blockset”.“Fullhash” = “S”.“FileHash” AND “S”.“BlockHash” = “Block”.“Hash” AND “S”.“BlockSize” = “Block”.“Size” AND “Blockset”.“Length” = “S”.“BlockSize” AND “Blockset”.“Length” <= 102400 ) H WHERE (“H”.“BlocksetID” || ‘:’ || “H”.“Index”) NOT IN (SELECT (“ExistingBlocksetEntries”.“BlocksetID” || ‘:’ || “ExistingBlocksetEntries”.“Index”) FROM “BlocksetEntry” “ExistingBlocksetEntries” )
14 Aug 2023 10:36: ExecuteNonQuery: INSERT INTO “Block” (“Hash”, “Size”, “VolumeID”) SELECT “FullHash” AS “Hash”, “Length” AS “Size”, -1 AS “VolumeID” FROM (SELECT “A”.“FullHash”, “A”.“Length”, CASE WHEN “B”.“Hash” IS NULL THEN ‘’ ELSE “B”.“Hash” END AS “Hash”, CASE WHEN “B”.“Size” is NULL THEN -1 ELSE “B”.“Size” END AS “Size” FROM (SELECT DISTINCT “FullHash”, “Length” FROM (SELECT “BlockHash” AS “FullHash”, “BlockSize” AS “Length” FROM ( SELECT “E”.“BlocksetID”, “F”.“Index” + (“E”.“BlocklistIndex” * 3200) AS “FullIndex”, “F”.“BlockHash”, MIN(102400, “E”.“Length” - ((“F”.“Index” + (“E”.“BlocklistIndex” * 3200)) * 102400)) AS “BlockSize”, “E”.“Hash”, “E”.“BlocklistSize”, “E”.“BlocklistHash” FROM ( SELECT * FROM ( SELECT “A”.“BlocksetID”, “A”.“Index” AS “BlocklistIndex”, MIN(3200 * 32, (((“B”.“Length” + 102400 - 1) / 102400) - (“A”.“Index” * (3200))) * 32) AS “BlocklistSize”, “A”.“Hash” AS “BlocklistHash”, “B”.“Length” FROM “BlocklistHash” A, “Blockset” B WHERE “B”.“ID” = “A”.“BlocksetID” ) C, “Block” D WHERE “C”.“BlocklistHash” = “D”.“Hash” AND “C”.“BlocklistSize” = “D”.“Size” ) E, “TempBlocklist-638D9A01EB1FB343B8A4C71E6E36EE70” F WHERE “F”.“BlocklistHash” = “E”.“Hash” ORDER BY “E”.“BlocksetID”, “FullIndex” ) UNION SELECT “BlockHash”, “BlockSize” FROM “TempSmalllist-701EAF39AB2460438656C429144C7567” )) A LEFT OUTER JOIN “Block” B ON “B”.“Hash” = “A”.“FullHash” AND “B”.“Size” = “A”.“Length” ) WHERE “FullHash” != “Hash” AND “Length” != “Size” took 0:00:02:41.146
14 Aug 2023 10:33: Starting - ExecuteNonQuery: INSERT INTO “Block” (“Hash”, “Size”, “VolumeID”) SELECT “FullHash” AS “Hash”, “Length” AS “Size”, -1 AS “VolumeID” FROM (SELECT “A”.“FullHash”, “A”.“Length”, CASE WHEN “B”.“Hash” IS NULL THEN ‘’ ELSE “B”.“Hash” END AS “Hash”, CASE WHEN “B”.“Size” is NULL THEN -1 ELSE “B”.“Size” END AS “Size” FROM (SELECT DISTINCT “FullHash”, “Length” FROM (SELECT “BlockHash” AS “FullHash”, “BlockSize” AS “Length” FROM ( SELECT “E”.“BlocksetID”, “F”.“Index” + (“E”.“BlocklistIndex” * 3200) AS “FullIndex”, “F”.“BlockHash”, MIN(102400, “E”.“Length” - ((“F”.“Index” + (“E”.“BlocklistIndex” * 3200)) * 102400)) AS “BlockSize”, “E”.“Hash”, “E”.“BlocklistSize”, “E”.“BlocklistHash” FROM ( SELECT * FROM ( SELECT “A”.“BlocksetID”, “A”.“Index” AS “BlocklistIndex”, MIN(3200 * 32, (((“B”.“Length” + 102400 - 1) / 102400) - (“A”.“Index” * (3200))) * 32) AS “BlocklistSize”, “A”.“Hash” AS “BlocklistHash”, “B”.“Length” FROM “BlocklistHash” A, “Blockset” B WHERE “B”.“ID” = “A”.“BlocksetID” ) C, “Block” D WHERE “C”.“BlocklistHash” = “D”.“Hash” AND “C”.“BlocklistSize” = “D”.“Size” ) E, “TempBlocklist-638D9A01EB1FB343B8A4C71E6E36EE70” F WHERE “F”.“BlocklistHash” = “E”.“Hash” ORDER BY “E”.“BlocksetID”, “FullIndex” ) UNION SELECT “BlockHash”, “BlockSize” FROM “TempSmalllist-701EAF39AB2460438656C429144C7567” )) A LEFT OUTER JOIN “Block” B ON “B”.“Hash” = “A”.“FullHash” AND “B”.“Size” = “A”.“Length” ) WHERE “FullHash” != “Hash” AND “Length” != “Size”
14 Aug 2023 10:33: RemoteOperationGet took 0:00:00:00.651
14 Aug 2023 10:33: Backend event: Get - Completed: duplicati-b265527687e95414c9b062af60bc43fec.dblock.zip.aes (49.94 MB)

SovereignEntity · August 14, 2023, 2:42am

Next log section:

14 Aug 2023 10:41: Starting - ExecuteNonQuery: INSERT INTO “Block” (“Hash”, “Size”, “VolumeID”) SELECT “FullHash” AS “Hash”, “Length” AS “Size”, -1 AS “VolumeID” FROM (SELECT “A”.“FullHash”, “A”.“Length”, CASE WHEN “B”.“Hash” IS NULL THEN ‘’ ELSE “B”.“Hash” END AS “Hash”, CASE WHEN “B”.“Size” is NULL THEN -1 ELSE “B”.“Size” END AS “Size” FROM (SELECT DISTINCT “FullHash”, “Length” FROM (SELECT “BlockHash” AS “FullHash”, “BlockSize” AS “Length” FROM ( SELECT “E”.“BlocksetID”, “F”.“Index” + (“E”.“BlocklistIndex” * 3200) AS “FullIndex”, “F”.“BlockHash”, MIN(102400, “E”.“Length” - ((“F”.“Index” + (“E”.“BlocklistIndex” * 3200)) * 102400)) AS “BlockSize”, “E”.“Hash”, “E”.“BlocklistSize”, “E”.“BlocklistHash” FROM ( SELECT * FROM ( SELECT “A”.“BlocksetID”, “A”.“Index” AS “BlocklistIndex”, MIN(3200 * 32, (((“B”.“Length” + 102400 - 1) / 102400) - (“A”.“Index” * (3200))) * 32) AS “BlocklistSize”, “A”.“Hash” AS “BlocklistHash”, “B”.“Length” FROM “BlocklistHash” A, “Blockset” B WHERE “B”.“ID” = “A”.“BlocksetID” ) C, “Block” D WHERE “C”.“BlocklistHash” = “D”.“Hash” AND “C”.“BlocklistSize” = “D”.“Size” ) E, “TempBlocklist-638D9A01EB1FB343B8A4C71E6E36EE70” F WHERE “F”.“BlocklistHash” = “E”.“Hash” ORDER BY “E”.“BlocksetID”, “FullIndex” ) UNION SELECT “BlockHash”, “BlockSize” FROM “TempSmalllist-701EAF39AB2460438656C429144C7567” )) A LEFT OUTER JOIN “Block” B ON “B”.“Hash” = “A”.“FullHash” AND “B”.“Size” = “A”.“Length” ) WHERE “FullHash” != “Hash” AND “Length” != “Size”
14 Aug 2023 10:41: RemoteOperationGet took 0:00:00:00.680
14 Aug 2023 10:41: Backend event: Get - Completed: duplicati-b26564181a6f14715a46bf3fbdafd09ab.dblock.zip.aes (49.93 MB)
14 Aug 2023 10:41: Downloaded and decrypted 49.93 MB in 00:00:00.6801370, 73.41 MB/s
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “wjrxtCytBJcY7AbZG+ygiN9eVEebIf+xEFnp1p4IVHI=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “wjrxtCytBJcY7AbZG+ygiN9eVEebIf+xEFnp1p4IVHI=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “ms8pEyajdSoL9w9xo+PN854k4bbLo8f/VDF1Gvvj2PA=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “ms8pEyajdSoL9w9xo+PN854k4bbLo8f/VDF1Gvvj2PA=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “9G3246n4lV3oLC6j5xGVnmuifCi2eWpPOowQrEdd8xg=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “9G3246n4lV3oLC6j5xGVnmuifCi2eWpPOowQrEdd8xg=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “uvcgqVeUgjUJ222jXBzuOP18VvQR9nOj+lM8qBBqhro=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “uvcgqVeUgjUJ222jXBzuOP18VvQR9nOj+lM8qBBqhro=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “qn5DeBP8JV39jWQFOZb0jWhuFcgdnKOpvy+vEdHTw/E=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “qn5DeBP8JV39jWQFOZb0jWhuFcgdnKOpvy+vEdHTw/E=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “F8SnLCJyhMDYG5yySH+t2ytsR+y7f1G6RuoR2CfYBvk=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “F8SnLCJyhMDYG5yySH+t2ytsR+y7f1G6RuoR2CfYBvk=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “XvWZI3G4SyMQqvJs8dDF7lLTDVy0HREi086GHJ95oP4=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “XvWZI3G4SyMQqvJs8dDF7lLTDVy0HREi086GHJ95oP4=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “XJHYlTp6yLEpkeg8oRBNyQ0tSwlqVb/DQsXsuW+gfW4=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “XJHYlTp6yLEpkeg8oRBNyQ0tSwlqVb/DQsXsuW+gfW4=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “tQI6ZRM5mgfqG4X1kuQc7zez/XR4u+q6xMjmBLY8/MI=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “tQI6ZRM5mgfqG4X1kuQc7zez/XR4u+q6xMjmBLY8/MI=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “71xvb61vq6Gfj/SQtBYjjsR//XWmRNsxOPPHSPyb+kk=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “71xvb61vq6Gfj/SQtBYjjsR//XWmRNsxOPPHSPyb+kk=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “NWGHvV+sV+/rsfSUhxpK6zqV6ORlwxLkgYs49IB089A=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “NWGHvV+sV+/rsfSUhxpK6zqV6ORlwxLkgYs49IB089A=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “lg9O1AmDFU7X7EHeg9uZ6KTVvzcHFwgsSYQRmNRijds=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “lg9O1AmDFU7X7EHeg9uZ6KTVvzcHFwgsSYQRmNRijds=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “OJQ8rUMqz7HVrtEBmO1qVrh3uTUvCySL8OQVtET5/ng=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “OJQ8rUMqz7HVrtEBmO1qVrh3uTUvCySL8OQVtET5/ng=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “62c2JK6r2/9/bpEwzti2QCLslOWTn8k5afEFKT9dYz0=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “62c2JK6r2/9/bpEwzti2QCLslOWTn8k5afEFKT9dYz0=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “iXG0qzlqV5vosh85Lub2ao+95HY7f2MXMasoaQ7Yr2Y=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “iXG0qzlqV5vosh85Lub2ao+95HY7f2MXMasoaQ7Yr2Y=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “nvLAt+RGuW7DYg9bf0hGpQIOX2TbQ0JG0CP33ADMZs0=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “nvLAt+RGuW7DYg9bf0hGpQIOX2TbQ0JG0CP33ADMZs0=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “t5B3QCrNyFZctZxMFqwyRZ02WQuhWhzv/QapAFdlv5A=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “t5B3QCrNyFZctZxMFqwyRZ02WQuhWhzv/QapAFdlv5A=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “xCdmJM0PDyA52Jn26vYaITLYhMbNjn79jqORPVqAg3k=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “xCdmJM0PDyA52Jn26vYaITLYhMbNjn79jqORPVqAg3k=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “b64GTGvth90LwLpC/HoWuXmBRJZUJLrv2O3U1zLqBik=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “b64GTGvth90LwLpC/HoWuXmBRJZUJLrv2O3U1zLqBik=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “1rW81WAt2iHUKXMVTQMY9HyjtfMkz3ZfunBElVKPWEQ=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “1rW81WAt2iHUKXMVTQMY9HyjtfMkz3ZfunBElVKPWEQ=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “m96S38dKDukf68+aoFAMhUd03eMxuaYfLcMAx5lLVmQ=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “m96S38dKDukf68+aoFAMhUd03eMxuaYfLcMAx5lLVmQ=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “qGien0owjOZpXVGEy4d5VLhS7Z3SSZKoPIDylKS2yio=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “qGien0owjOZpXVGEy4d5VLhS7Z3SSZKoPIDylKS2yio=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “UUdtmnPslobylKpBn0Gpdz6Gyr5RRPKh6r8ZHaU5I4M=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “UUdtmnPslobylKpBn0Gpdz6Gyr5RRPKh6r8ZHaU5I4M=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “5+2w++L4Cq8UGvaWqi1NfGPXKbaP0TCb6xLiQlSphKE=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “5+2w++L4Cq8UGvaWqi1NfGPXKbaP0TCb6xLiQlSphKE=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “OD5KMwFlX2X+0Yp7icyVDKfj1eGp0gU3wn/gT5dqLaI=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “OD5KMwFlX2X+0Yp7icyVDKfj1eGp0gU3wn/gT5dqLaI=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “7YgoHB2HuyJ3FPZ7CABmy+f4ISJAa6UjqG/2qtZ3Wqc=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “7YgoHB2HuyJ3FPZ7CABmy+f4ISJAa6UjqG/2qtZ3Wqc=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “r+sgGyJE/QupHTanM9K+fvlS16IBXoRZEudZyYdttsI=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “r+sgGyJE/QupHTanM9K+fvlS16IBXoRZEudZyYdttsI=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “ND3gnC9Yh7NQ7GW7q3iHFSiLdyLHzKliCf0O6cYioQ8=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “ND3gnC9Yh7NQ7GW7q3iHFSiLdyLHzKliCf0O6cYioQ8=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “OGYJyOlu4Jlj5yeLWnETTbpPeMw6UC3QjiP6sK3WpL8=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “OGYJyOlu4Jlj5yeLWnETTbpPeMw6UC3QjiP6sK3WpL8=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “Z72XDETZX4UuNsQCtXDbnnXQ6GDXDSMN/fmfEvkrY7I=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “Z72XDETZX4UuNsQCtXDbnnXQ6GDXDSMN/fmfEvkrY7I=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “/W4qoGm8Ys6KJuCzPi6J+Jf+p/bF9x/bSIwtdk0/OgA=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “/W4qoGm8Ys6KJuCzPi6J+Jf+p/bF9x/bSIwtdk0/OgA=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “S3INS3xgYiK0q7qxiC+EjHrMBvT+gy3SAe280+1nTrU=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “S3INS3xgYiK0q7qxiC+EjHrMBvT+gy3SAe280+1nTrU=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “1rfiY5i/vpYgN6eU5OFhhKymlAquon0Ukm4cQ5b7Dm8=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “1rfiY5i/vpYgN6eU5OFhhKymlAquon0Ukm4cQ5b7Dm8=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “hmfAmVVzi5YpoPTrocCWP6ngMDNadcJKiTTqJ5hPxKU=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “hmfAmVVzi5YpoPTrocCWP6ngMDNadcJKiTTqJ5hPxKU=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “Yk9zK8vPA/g/PH5CZMAm1UroWack3da88IGeI32QOX0=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “Yk9zK8vPA/g/PH5CZMAm1UroWack3da88IGeI32QOX0=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “ztghZcVdasYIHKj/S5dUKwHyj56ntNc6tEVqyKTDnAA=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “ztghZcVdasYIHKj/S5dUKwHyj56ntNc6tEVqyKTDnAA=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “VtCA1A58CYvQqt8E2+u6x5iGOQeZCMWHy9L0tGaLvxQ=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “VtCA1A58CYvQqt8E2+u6x5iGOQeZCMWHy9L0tGaLvxQ=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “CnLONOg6YYLkM+e2InOEt+GZH1HUMXhGGAbK3gke/6Y=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “CnLONOg6YYLkM+e2InOEt+GZH1HUMXhGGAbK3gke/6Y=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “/0BDqx2N7S2DDt7hcaWKaqv09j+IYjGt8mKAREEHidQ=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “/0BDqx2N7S2DDt7hcaWKaqv09j+IYjGt8mKAREEHidQ=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “/swdCFuR7qygMUxJMPxugACUUeRW89WUoZP8rV3DuXo=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “/swdCFuR7qygMUxJMPxugACUUeRW89WUoZP8rV3DuXo=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “JXuRMmG7nHodmrWM3pC2Gfax6FsoZHHhCfo+Z/u5DC4=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “JXuRMmG7nHodmrWM3pC2Gfax6FsoZHHhCfo+Z/u5DC4=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “0uu/VwPAo/S9tjRCuOGEL066L/wYHD/JnR2crNgwc38=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “0uu/VwPAo/S9tjRCuOGEL066L/wYHD/JnR2crNgwc38=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “zF2LjtKfeRKgD3u7ERGGsl35VguRduIZj0MpR4WU5xU=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “zF2LjtKfeRKgD3u7ERGGsl35VguRduIZj0MpR4WU5xU=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “RFqK0scoVYdCyM4mlJhYWzwzKmWp2aP33/fLjRHDBw0=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “RFqK0scoVYdCyM4mlJhYWzwzKmWp2aP33/fLjRHDBw0=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “iSFtFHPsF4OXVKFWBSKH2olMi5FgjbdFP3D7dAwsx3o=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “iSFtFHPsF4OXVKFWBSKH2olMi5FgjbdFP3D7dAwsx3o=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “LbFdBNgJcFemVYigCyj0XadZ1Z4mhuhz20d/dYrExrY=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “LbFdBNgJcFemVYigCyj0XadZ1Z4mhuhz20d/dYrExrY=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “8cckffL5O7MFo+tfQ1NX9hEjzy98D32Wg0wo9+Hfm0c=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “8cckffL5O7MFo+tfQ1NX9hEjzy98D32Wg0wo9+Hfm0c=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “gI/j4auoP2DMbXsNfrZ6tHKbV4E//QNAaqIV+SDLrFE=” AND “Size” = 102400 took 0:00:00:00.000
14 Aug 2023 10:41: Starting - ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “gI/j4auoP2DMbXsNfrZ6tHKbV4E//QNAaqIV+SDLrFE=” AND “Size” = 102400
14 Aug 2023 10:41: ExecuteScalarInt64: SELECT “VolumeID” FROM “Block” WHERE “Hash” = “rTtY3x3r+HXL0udpGzvSHBG9zbYWVzgjLZDSDcUrG2I=” AND “Size” = 102400 took 0:00:00:00.000

gpatel-fr · August 14, 2023, 9:07am

there is not much description of the backup provided, the only factual basis is that you ‘connected to the folder’ so I’m going to assume that you are backuping to a disk, not a cloud server.

To assess the damage on your backend, can you give us the count for the different file types on the backend, say, something like

dir *.dlist.* | find /v /c ""
dir *.dblock.* | find /v /c ""
dir *.dindex.* | find /v /c ""

this is for Windows, if you are using another kind of operating system, replace dir by ls and find /v /c “” by wc -l

SovereignEntity · August 14, 2023, 9:26am

Source data is mixed files large and small,using Smart Retention. Yeah backup is to disk folder for ease of attaching and responsiveness

File list:

dir .dlist. | find /v /c “”
28

dir .dblock. | find /v /c “”
7489

dir .dindex. | find /v /c “”
7496

gpatel-fr · August 14, 2023, 2:05pm

Having more index files than block seems to show that there were some crashes at some time.
Since the db is locked while recreating, it’s not possible to connect to it to explore the details. The only way to see the advancement is to watch for messages such as ‘Processing blocklist volume xx of yy…’ at the Verbose level.

SovereignEntity · August 14, 2023, 4:06pm

Thanks! That got me closer to a “progress status” at least,we’re at 1246 blocks out of 7481
It’s taking about 8-20minutes per block,so at worst 2000hours to go - only 86 days

ts678 · August 14, 2023, 5:35pm

What is the position? I would guess it’s at bad news last 10% where it’s hard to notice tiny motion.

What does the message around the numbers say? The final three 10% on progress bar are below:

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Main/Operation/RecreateDatabaseHandler.cs#L438-L449


      
          case 0:

              Logging.Log.WriteVerboseMessage(LOGTAG, "ProcessingRequiredBlocklistVolumes", "Processing required {0} blocklist volumes{1}", lst.Count, fullist);

              Logging.Log.WriteInformationMessage(LOGTAG, "ProcessingRequiredBlocklistVolumes", "Processing required {0} blocklist volumes{1}", lst.Count, m_options.FullResult ? fullist : string.Empty);

              break;

          case 1:

              Logging.Log.WriteVerboseMessage(LOGTAG, "ProbingCandicateBlocklistVolumes", "Probing {0} candidate blocklist volumes{1}", lst.Count, fullist);

              Logging.Log.WriteInformationMessage(LOGTAG, "ProbingCandicateBlocklistVolumes", "Probing {0} candidate blocklist volumes{1}", lst.Count, m_options.FullResult ? fullist : string.Empty);

              break;

          default:

              Logging.Log.WriteVerboseMessage(LOGTAG, "ProcessingAllBlocklistVolumes", "Processing all of the {0} volumes for blocklists{1}", lst.Count, fullist);

              Logging.Log.WriteVerboseMessage(LOGTAG, "ProcessingAllBlocklistVolumes", "Processing all of the {0} volumes for blocklists{1}", lst.Count, m_options.FullResult ? fullist : string.Empty);

              break;

If it’s the last of the three blocklist volume steps (please check), it’s going to look at all not yet read.
This doesn’t guarantee that missing data it’s searching hard for will be found, but one never knows.

I wrote a Python script that looks at dlist (says which blocks are needed) and dindex (location) files, attempting to forecast gaps that would cause dblock file search. As files are encrypted, decrypt first, however decrypting dblock files is only needed if we get more ambitious in investigating block issue.

This won’t directly solve the recreate, but it might give a clue as to the situation in a fairly small time. Attempting to look at things that go wrong is also a useful step towards changes meant to avoid that.

This does need a successful database recreate. If you just wanted restore, some other options exist.

SovereignEntity · August 14, 2023, 6:28pm

What is the position? I would guess it’s at bad news last 10% where it’s hard to notice tiny motion.

I’ll be hard pressed to give a % guess,maybe 10%? Empty space on the progress bar is almost a square around the cancel cross

What does the message around the numbers say? The final three 10% on progress bar are below:
None of those 3,“Processing blocklist volume”

15 Aug 2023 02:23: Backend event: Get - Completed: duplicati-b2aa1e2669b764c628ada1089ef36f479.dblock.zip.aes (49.98 MB)
15 Aug 2023 02:23: Pass 3 of 3, processing blocklist volume 1264 of 7481
15 Aug 2023 02:23: Backend event: Get - Started: duplicati-b2aa1e2669b764c628ada1089ef36f479.dblock.zip.aes (49.98 MB)
15 Aug 2023 02:15: Backend event: Get - Completed: duplicati-b2a941ec6e7684509b6d1c1cb3b9d3b40.dblock.zip.aes (49.92 MB)
15 Aug 2023 02:15: Pass 3 of 3, processing blocklist volume 1263 of 7481
15 Aug 2023 02:15: Backend event: Get - Started: duplicati-b2a941ec6e7684509b6d1c1cb3b9d3b40.dblock.zip.aes (49.92 MB)
15 Aug 2023 02:07: Backend event: Get - Completed: duplicati-b2a91f4457b3e4e6381cbb2afc239733a.dblock.zip.aes (49.99 MB)
15 Aug 2023 02:07: Pass 3 of 3, processing blocklist volume 1262 of 7481
15 Aug 2023 02:07: Backend event: Get - Started: duplicati-b2a91f4457b3e4e6381cbb2afc239733a.dblock.zip.aes (49.99 MB)
15 Aug 2023 01:59: Backend event: Get - Completed: duplicati-b2a8921d68251430fa7ae628fd02d2ff2.dblock.zip.aes (49.97 MB)
15 Aug 2023 01:59: Pass 3 of 3, processing blocklist volume 1261 of 7481

Attempting a “Restore” direct from the destination folder takes about an hour to get to a state of being able to select files from the backups,so the content isn’t particularly challenging from that perspective

ts678 · August 14, 2023, 8:19pm

That was an easier clue. It’s in the third pass, 90%+ on bar, searching in every dblock not checked.

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Main/Operation/RecreateDatabaseHandler.cs#L470-L471


      
          m_result.OperationProgressUpdater.UpdateProgress((((float)progress / lst.Count) * 0.1f) + 0.7f + (i * 0.1f));

          Logging.Log.WriteVerboseMessage(LOGTAG, "ProcessingBlocklistVolumes", "Pass {0} of 3, processing blocklist volume {1} of {2}", (i + 1), progress, lst.Count);

This is sometimes a way to avoid slow DB recreates, as it makes a partial temporary database after file selection. IIRC (and others might be more familiar) it’s a two step database build. Above is just the first, however if you can then follow through restore all files, then perhaps that backup version has no issues.

Recreating the whole database means that all versions of all files have to have data found, and figuring out which files or backup versions has the problem would be by trial and error. Even the script I thought maybe you’d run is mostly just a checker, but can produce more detailed output by uncommenting lines.

It’s kind of up to you on how to go. If you have space, you could even make a fresh start (preferably with something like a 500 KB or maybe 1 MB blocksize to speed future processing) while working on old DB, which would give you your history. That way you’d at least have some protection against a new disaster.

If you decide to abandon the recreate, that would unlock the database so possibly we can examine it via Creating a bug report and you posting a link to wherever you’re sharing it from. I think I can spot signs of Duplicati not knowing where a block is. Or you can look using DB Browser for SQLite and suggestions.

Jojo-1000 · August 14, 2023, 8:47pm

Recreate when searching missing blocks always takes way too long to be useful in any circumstance, except a tiny backup. I feel like there should be a way to disable the 3rd pass of downloading everything and just get a working database with broken files (that should even be the default IMO).

Has anyone ever figured out how these blocks go missing in the first place? Are they only missing in the dindex files, or are they completely gone?

SovereignEntity · August 14, 2023, 8:50pm

Thank you,i’ll definitely look into this more indepth when I have more time to fuss about,it’s been very educational. As I’ve already resumed backups and have a copy of this history to restore from the priority is low from an urgency standpoint and I get the feeling this is going to take some time to delve deeper

ts678 · August 14, 2023, 9:29pm

End users typically will not investigate and will not provide data, but I’m still asking for that here. Sometimes the data just doesn’t exist, e.g. the ancient history that got the excess dindex files…

I don’t think any developer has found a recipe yet. I’m looking (and have lots of data collections).
What I’d like would be to find a way to find impending problem before user hits it when in need…

The answer to your question in this case will be to wait a long time for outcome, or try a shortcut.
Shortcut is only possible with user help and maybe more help after some clues emerge from this.

The first two passes aren’t too bad. I don’t recall the exact pass definitions. Third one is the biggie.

Making it the default would avoid the problem of how to ask the user, especially from a CLI script…
I’m not sure I like forever-broken files. RecoveryTool can make partial files, but DB recreate should provide some tool to purge broken files (in this sense of broken, although current code might have abilities that could be leveraged, and if not, maybe code from the purge command could also help).

Thanks!

If you saved partial DB, you can force it into any Duplicati dummy job just to get a bug report made.
That would give some daring devs something to ponder (unless transaction chopped off too much).

gpatel-fr · August 16, 2023, 10:55pm

not sure it needs to be so long.

See my branch that I updated just now to preview a solution to this problem. It still need more thought and tests but so far it has withstood what I have thrown at it.
The basic idea comes from this thread. I have always suspected that this kind of problem could come from a backend bug or even a basic misstep from users, massively deleting index files. However this thread shows that actually the problem can occur with more index files that data files. So I have searched instead in the direction ‘can an invalid index file create this situation’. And bingo, I have found a way to generate this problem. Now I don’t know at all how Duplicati could do that. Maybe it’s not the same kind of invalid index file in this thread. Possibly this is a race condition, probably in compact (because it seems just the more dangerous operation, especially if it crashes at the wrong time).
IMO it does not matter. Whatever the reason, if there is a way to make this process faster it is a bug fix in its own right.

So the idea: basically the main reason this stuff is slow is that there is a massively expensive query running for every block file. I have searched to accelerate it (it is the first part of my branch). This was moderately successful, but it was a drop in the ocean. Reducing a query from 2’ to 1’50 does not count for much when it is run 20000 times.

So I have considered, given the new information that a single invalid index file can generate a massive test of all block files, that it is not very appropriate to run it for every block file. Indeed, when one index file is invalid out of 20000, we have 19999 valid block files already correctly handled by the previous index files scanning. So it makes sense to try to check if the block file handling has not produced any new information and if yes, skip the query that is supposed to update the tables based on the new information. The fastest query is the one that does not run. This is the most important change in the update to my branch today (there are other minor changes also but are just details in comparison).

here is the relevant part:

github.com

duplicati/duplicati/blob/32fcab927685d11c760c1260962eac4894977511/Duplicati/Library/Main/Operation/RecreateDatabaseHandler.cs#L510


      
                                                  if (restoredb.AddTempBlockListHash(blocklisthash, rd.ReadBlocklist(blocklisthash, hashsize), tr)) {
                                                      anyChange = true;
                                                  }
                                              }
          

                                              // Update tables if necessary (if no block or hash have been changed by a data volume
          				    // there is no need to run expensive queries - most data volumes have been
          				    // managed successfully by correct index volumes), so we know if we are done
          				    // if any change, add to the block and blocksetentry tables the references found in
                                              // the block lists of the volume saved in the temp blocklisthash table by AddTempBLockListHash
                                              if (anyChange) {
                                                  if (i == 2) {
                                                      Logging.Log.WriteWarningMessage(LOGTAG, "UpdatingTables", null, "Unexpected changes caused by block {0}", sf.Name);
                                                  }
                                                  if (expRecreateDb)
                                                      restoredb.AddBlockAndBlockSetEntryFromTemp(hashsize, m_options.Blocksize, tr, false);
                                                  else
                                                      restoredb.FindMissingBlocklistHashes(hashsize, m_options.Blocksize, tr);

                                              }
          
                                              using (new Logging.Timer(LOGTAG, "CommitRestoredBlocklist", "CommitRestoredBlocklist"))

for your (and @ts678) viewing and comment (I have serious concerns about changing this part of the code…)

me neither, I would massively prefer to avoid it.

in my rebuild branch, I have actually added an option to force the dblock handling, since I have seen a case of broken index file (I have generated 2 different cases) where the badness was not detected at first (so no dblock handling), but at the end, so the rebuild was a failure. Forcing dblock handling can fix it. Execution time is similar to a full backend test (that is, slow as in hours, not slow as in days).

I could create a build of the branch for you if you can take the time to test it on the original problem backend, it would be much appreciated. Thanks anyway for posting the information you did, it was very instructive.

SovereignEntity · August 16, 2023, 11:12pm

Hi there!
Sure I can spin up an azure resource to give it a run if it’ll be a day or 2 use. Glad to give it a go

Point me at a windows build and what I need to toggle and I’ll give it a bash on the weekend

Re: the how,yes. This situation is vexing as we’ve just been running it a few years (identical job since 2021) with next to no user-input required as it’s been running its smart-retention backup with no quibbles and the odd failure (network folder unavailable)

SovereignEntity · August 16, 2023, 11:23pm

Oh,come to think of it,could the numerous index files have come from this:
There was a period initially where I used a folder destination for Duplicati,which was also a Onedrive path that applied files-on-demand - duplicati had some oddities running and complaining about issues with missing files due to this so I disabled the files-on-demand and resynced and repaired to clear out the cobwebs back then

ts678 · August 17, 2023, 1:04am

The extras can be duplicates, but the existence of such extras doesn’t mean there aren’t missing too.

How are they made invalid? Does the Python script dindex checker mentioned earlier notice the issue?

gpatel-fr · August 17, 2023, 7:09am

download the windows artifact (if you don’t have a github login I can export the result somewhere publicly accessible), install the 64 bit version from the zip, then you can run it from the command line (preferred, it gives information that is easier to follow) with something along the lines of:

Duplicati.CommandLine.exe repair "your-connection-string" --dbpath=path/to/db.sqlite --options

you can get the connection string and the options by exporting the job as command line.
It should run in less than one day I think, hopefully less than half a day.

Note that the repair should trigger a full block verification given what has happened so far, so the (new) switch --repair-force-block-use should not be necessary.

If the repair fails, then that would mean that repair is not powerful enough. At least we would know that it is so.

If the repair complete without saying it fails, you can use ‘test’ command with the ‘all’ parameter and the switches --full-remote-verification=true and --full-block-verification=true to do the most complete check that Duplicati can do in its current shape.
If the test detects a bad index file, it’s not a problem (bad index files are regenerated after a backup).
Actually detecting a bad index file would be nice since it could allow for more detective work (finding how it has happened maybe).

gpatel-fr · August 17, 2023, 7:22am

first method, remove a block ref in the json file NOT a special blocklist hash block. Your script catches it. This is the method that is caught as well by my change.

second method, remove a block ref that IS a special blocklist hash block, AND the block itself in the vol/ subdir. Your script does not catch it. That is the problem that has made me add the --repair-force-block-use switch, because Duplicati does not trigger a block repair as well, however if the block repair runs it fixes it.

I had to fiddle a bit with your script since open(“rb”) was not accepted - replies that is should be “r” or “w”. Not sure why, looking at the official doc, “rb” was never considered valid for Python 3 zipfile implementation - maybe it was ignored at some point and caught at a later stage ? I have python 3.8 on this server, maybe you are using a very old Python version ?