Disk full during restore

gdassieu · July 21, 2025, 12:46pm

Hi Everyone,

It’s me again !!

I’m redoing my DRP tests on 2.1.0.125_canary inside a virtual machine (to simulate a real full disaster condition), and I notice the restore process seems to fail (hang, actually) due to disk full. I had made the same operation on an older version and this problem did not occur.

You can find the log extract at the bottom.

There seem to be two problems:

It hangs rather than failing.
The disk was not supposed to get full, since I had ~50GB more free space than required for the restore. Judging by below screenshot, I am guessing the “cache” files are not deleted fast enough (or at all).

Summarized (and anonymized) log extract here. The last message with the “1, 1, 1” seems to go on forever

2025-07-21 04:48:02 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.FileProcessor-RestoredFile]: Restored file C:\Restore\<ANONYMIZED>
2025-07-21 04:48:02 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.FileProcessor-RestoredFile]: Restored file C:\Restore\<ANONYMIZED>
2025-07-21 04:48:02 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.FileProcessor-RestoredFile]: Restored file C:\Restore\<ANONYMIZED>
2025-07-21 04:48:02 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.FileProcessor-RestoredFile]: Restored file C:\Restore\<ANONYMIZED>
2025-07-21 04:48:02 +09 - [Retry-Duplicati.Library.Main.Backend.Handler-RetryGet]: Operation Get with file duplicati-<ANONYMIZED>.dblock.zip.aes attempt 1 of 5 failed with message: There is not enough space on the disk. : 'C:\Users\Test\AppData\Local\Temp\dup-<ANONYMIZED>'
System.IO.IOException: There is not enough space on the disk. : 'C:\Users\Test\AppData\Local\Temp\dup-<ANONYMIZED>'
   at System.IO.Strategies.BufferedFileStreamStrategy.WriteSpan(ReadOnlySpan`1 source, ArraySegment`1 arraySegment)
   at System.IO.Stream.<>c.<BeginWriteInternal>b__52_0(Object <p0>)
   at System.Threading.Tasks.Task`1.InnerInvoke()
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Duplicati.StreamUtil.ThrottleEnabledStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at Duplicati.Library.Utility.ProgressReportingStream.WriteImplAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at Duplicati.Library.Utility.Utility.CopyStreamAsync(Stream source, Stream target, Boolean tryRewindSource, CancellationToken cancelToken, Byte[] buf)
   at Duplicati.Library.Utility.Utility.CopyStreamAsync(Stream source, Stream target, CancellationToken cancelToken)
   at Duplicati.Library.Backend.GoogleCloudStorage.GoogleCloudStorage.GetAsync(String remotename, Stream stream, CancellationToken cancelToken)
   at Duplicati.Library.Main.Backend.BackendManager.GetOperation.DoGetFileAsync(IBackend backend, CancellationToken cancelToken)
   at Duplicati.Library.Main.Backend.BackendManager.GetOperation.ExecuteAsync(IBackend backend, CancellationToken cancelToken)
   at Duplicati.Library.Main.Backend.BackendManager.Handler.Execute[TResult](PendingOperation`1 op, CancellationToken cancellationToken)
   at Duplicati.Library.Main.Backend.BackendManager.Handler.Execute(PendingOperationBase op, CancellationToken cancellationToken)
   at Duplicati.Library.Main.Backend.BackendManager.Handler.ExecuteWithRetry(PendingOperationBase op, CancellationToken cancellationToken)
2025-07-21 04:48:02 +09 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-<ANONYMIZED>.dblock.zip.aes (49.93 MiB)
2025-07-21 04:48:02 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.BlockManager-RetiredProcess]: BlockManager Block handler retired
2025-07-21 04:48:02 +09 - [Error-Duplicati.Library.Main.Operation.Restore.FileProcessor-FileProcessingError]: Error during file processing
System.IO.IOException: There is not enough space on the disk. : '\\?\C:\Restore\<ANONYMIZED>'
   at System.IO.RandomAccess.<>c.<WriteAtOffsetAsync>b__21_0(ValueTuple`4 state)
   at System.Threading.AsyncOverSyncWithIoCancellation.InvokeAsync[TState](Action`1 action, TState state, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
   at Duplicati.Library.Main.Operation.Restore.FileProcessor.<>c__DisplayClass4_0.<<Run>b__0>d.MoveNext()
2025-07-21 04:48:02 +09 - [Retry-Duplicati.Library.Main.Backend.Handler-RetryGet]: Operation Get with file duplicati-<ANONYMIZED>.dblock.zip.aes attempt 1 of 5 failed with message: There is not enough space on the disk. : 'C:\Users\Test\AppData\Local\Temp\dup-<ANONYMIZED>'
[...]
2025-07-21 04:48:56 +09 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Failed: duplicati-<ANONYMIZED>.dblock.zip.aes (49.93 MiB)
2025-07-21 04:48:56 +09 - [Error-Duplicati.Library.Main.Operation.Restore.VolumeDownloader-DownloadError]: Error during download
System.IO.IOException: There is not enough space on the disk. : 'C:\Users\Test\AppData\Local\Temp\dup-<ANONYMIZED>'
   at System.IO.Strategies.OSFileStreamStrategy.Write(ReadOnlySpan`1 buffer)
   at System.IO.Strategies.BufferedFileStreamStrategy.FlushWrite()
   at System.IO.Strategies.BufferedFileStreamStrategy.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at Duplicati.Library.Main.Backend.BackendManager.GetOperation.DoGetFileAsync(IBackend backend, CancellationToken cancelToken)
   at Duplicati.Library.Main.Backend.BackendManager.GetOperation.ExecuteAsync(IBackend backend, CancellationToken cancelToken)
   at Duplicati.Library.Main.Backend.BackendManager.Handler.Execute[TResult](PendingOperation`1 op, CancellationToken cancellationToken)
   at Duplicati.Library.Main.Backend.BackendManager.Handler.Execute(PendingOperationBase op, CancellationToken cancellationToken)
   at Duplicati.Library.Main.Backend.BackendManager.Handler.ExecuteWithRetry(PendingOperationBase op, CancellationToken cancellationToken)
   at Duplicati.Library.Main.Backend.BackendManager.GetDirectAsync(String remotename, String hash, Int64 size, CancellationToken cancelToken)
   at Duplicati.Library.Main.Operation.Restore.VolumeDownloader.<>c__DisplayClass1_0.<<Run>b__0>d.MoveNext()
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.VolumeDecryptor-RetiredProcess]: Volume decryptor retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.VolumeDecryptor-RetiredProcess]: Volume decryptor retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.VolumeDecryptor-RetiredProcess]: Volume decryptor retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.VolumeManager-RetiredProcess]: Volume manager retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.VolumeDecompressor-RetiredProcess]: Volume decompressor retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.VolumeDecompressor-RetiredProcess]: Volume decompressor retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.VolumeDecompressor-RetiredProcess]: Volume decompressor retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.BlockManager-RetiredProcess]: BlockManager Volume consumer retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.FileProcessor-RetiredProcess]: File processor retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.BlockManager-RetiredProcess]: BlockManager Block handler retired
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.FileProcessor-RetiredProcess]: File processor retired
2025-07-21 04:48:56 +09 - [Error-Duplicati.Library.Main.Operation.Restore.FileLister-FileListerError]: Error during file listing
CoCoL.RetiredException: The channel "" is retired
   at CoCoL.Channel`1.WriteAsync(T value, ITwoPhaseOffer offer)
   at Duplicati.Library.Main.Operation.Restore.FileLister.<>c__DisplayClass1_0.<<Run>b__0>d.MoveNext()
2025-07-21 04:48:56 +09 - [Verbose-Duplicati.Library.Main.Operation.Restore.BlockManager-RetiredProcess]: BlockManager Block handler retired
2025-07-21 04:48:56 +09 - [Warning-Duplicati.Library.Main.Operation.Restore.BlockManager-BlockCountError]: Block count in SleepableDictionarys block table is not zero: 752484

2025-07-21 04:48:56 +09 - [Warning-Duplicati.Library.Main.Operation.Restore.BlockManager-BlockCountError]: There are still 19 files being read by 19 readers
2025-07-21 04:48:56 +09 - [Warning-Duplicati.Library.Main.Operation.Restore.BlockManager-VolumeCountError]: Volume count in SleepableDictionarys volume table is not zero: 752484
Volumes: 1424, 3276, 2546, 414, 1096, 870, 1190, 1060, 1536, 2096, 1468, 1473, 3031, 379, 1437, 2614, 774, 2706, 2998, 3257, 2448, 623, 511, 2450, 937, 1330, 93, 801, 782, 1291, 3283, 1519, 2206, 762, 2445, 2613, -1, 1141, 633, 3020, 587, 2634, 126, 1094, 1307, 2028, 2080, 1548, 2254, 1655, 1606, 1148, 2496, 2999, 2883, 372, 2068, 1541, 2570, 2421, 1506, 634, 2584, 3225, 488, 2312, 1139, 848, 700, 847, 2307, 1354, 1368, 2241, 2067, 2134, 2351, 2525, 3102, 2251, 198, 2650, 248, 761, 2125, 899, 1448, 2903, 1252, 1999, 2897, 584, 1033, 1406, 2607, 102, 727, 1166, 3138, 321, 339, 2963, 709, 1464, 1770, 263, 2103, 2012, 2281, 1934, 2736, 2123, 738, 1119, 1463, 132, 3254, 1016, 559, 1455, 2683, 582, 2826, 3182, 2465, 2620, 2881, 1171, 818, 3167, 1233, 365, 2274, 1586, 1112, 1316, 2352, 2747, 3041, 1924, 2452, 758, 2263, 2302, 1085, 650, 1496, 2955, 1692, 2026, 258, 2451, 2625, 2687, 1680, 1262, 2416, 2746, 1255, 1670, 1471, 99, 1238, 2262, 3261, 3029, 453, 2923, 730, 42, 1077, 218, 1346, 2973, 1003, 1677, 1741, 2480, 2591, 1632, 193, 2862, 2343, 2283, 3210, 1767, 1108, 3071, 2345, 2575, 1412, 1732, 2557, 205, 107, 2226, 2829, 486, 3118, 1560, 471, 2163, 2010, 953, 1102, 1588, 1674, 2155, 779, 2819, 2426, 2413, 305, 630, 938, 2992, 2895, 3141, 342, 1334, 2446, 523, 2655, 2027, 1873, 3164, 2435, 2267, 2222, 81, 109, 2663, 1766, 2429, 960, 110, 166, 2121, 1886, 2845, 1337, 2224, 1237, 535, 1103, 257, 3013, 2810, 685, 2467, 1688, 1722, 635, 118, 2084, 640, 2872, 2991, 170, 2994, 2904, 156, 3275, 729, 2310, 1828, 2657, 3161, 1158, 2398, 2685, 1288, 1245, 358, 1179, 164, 1931, 2176, 133, 2259, 188, 2250, 1528, 1163, 2643, 1423, 2804, 2757, 2721, 1032, 1950, 897, 3113, 3069, 1263, 517, 902, 1355, 2789, 646, 2612, 1807, 2503, 2036, 1283, 2056, 3057, 403, 3085, 396, 2959, 1304, 1332, 1654, 1088, 201, 669, 3272, 2005, 2173, 1483, 788, 787, 146, 2128, 54, 1566, 3144, 1312, 1890, 2764, 2792, 918, 563, 3266, 426, 38, 885, 1524, 1702, 1800, 1978, 2654, 1150, 422, 990, 2225, 1025, 1393, 1069, 676, 1377, 1322, 2111, 1568, 2841, 3263, 3202, 381, 1939, 1401, 1553, 1324, 2512, 3074, 1840, 131, 3119, 3244, 2725, 1628, 2930, 387, 2380, 1854, 2034, 2812, 1848, 2759, 2045, 1092, 3213, 2013, 290, 119, 1583, 2303, 348, 1213, 813, 1344, 1381, 3034, 144, 1192, 74, 2348, 2856, 2371, 1837, 2093, 1775, 1038, 536, 1879, 492, 217, 2937, 871, 1169, 2440, 3134, 1849, 273, 2943, 2791, 3048, 1989, 1243, 1870, 1609, 1808, 699, 1650, 854, 602, 1796, 104, 72, 1146, 1459, 867, 3090, 238, 418, 2324, 2513, 2541, 1652, 45, 1786, 869, 2000, 1563, 2476, 2162, 103, 1757, 1390, 2594, 473, 1684, 2569, 1603, 2147, 1052, 3185, 2515, 1745, 327, 573, 2730, 1099, 991, 2916, 543, 605, 3151, 1502, 352, 120, 2227, 66, 2268, 2373, 1957, 3061, 2981, 3175, 1491, 2954, 2651, 1862, 2432, 1168, 2540, 2799, 223, 1983, 1428, 3065, 1844, 655, 2082, 1864, 2996, 2566, 3066, 1347, 2911, 2798, 2548, 1985, 901, 1484, 838, 987, 586, 2389, 2153, 2795, 2329, 2453, 2486, 2948, 1575, 1814, 1695, 2919, 2828, 1872, 308, 1006, 2447, 2851, 1823, 1900, 3269, 23, 3184, 2917, 3170, 1712, 1375, 2632, 2813, 661, 1880, 2133, 2030, 642, 973, 1402, 1365, 2626, 1987, 1529, 968, 236, 608, 1748, 956, 513, 300, 2456, 2086, 2672, 1549, 1509, 2956, 1493, 648, 424, 1495, 1602, 1645, 2385, 1251, 378, 1173, 2580, 357, 69, 1011, 2072, 1925, 2073, 1408, 2645, 1643, 2394, 76, 939, 598, 857, 1743, 2339, 728, 1140, 2969, 2624, 831, 1133, 2309, 3140, 105, 2823, 36, 992, 3093, 665, 2201, 2892, 82, 311, 1036, 302, 1580, 1579, 2653, 2662, 1959, 846, 856, 1215, 2801, 2689, 873, 1699, 2305, 3240, 2722, 35, 2341, 3176, 2844, 1492, 1429, 1240, 98, 2207, 789, 3224, 359, 2079, 1861, 2652, 1897, 226, 173, 278, 2777, 2800, 1681, 431, 1700, 2582, 2149, 1946, 73, 2048, 595, 2578, 470, 2631, 435, 1592, 1865, 651, 3045, 303, 3191, 1274, 1705, 361, 416, 2248, 449, 2502, 2696, 2830, 2592, 656, 441, 2441, 1555, 2658, 1200, 1379, 406, 2113, 231, 610, 2106, 1485, 1153, 2831, 2806, 87, 1842, 680, 1248, 1630, 1756, 2794, 497, 1306, 2848, 541, 2519, 1446, 1791, 423, 326, 1847, 1177, 262, 624, 589, 2021, 1212, 169, 1918, 2675, 2532, 483, 280, 2517, 1226, 63, 2436, 1384, 2697, 1803, 1778, 1943, 575, 3152, 3106, 2608, 843, 1030, 1358, 180, 3193, 3080, 1809, 29, 1621, 1909, 1945, 1231, 2484, 1142, 2545, 141, 3006, 276, 1963, 1671, 1366, 3131, 2784, 2966, 592, 2936, 721, 538, 1930, 1936, 388, 599, 475, 514, 2839, 2640, 57, 2340, 578, 2543, 2500, 1115, 1907, 2710, 2639, 2043, 3215, 806, 562, 1100, 1012, 2550, 1239, 1790, 420, 1544, 2179, 2388, 2138, 1009, 1971, 961, 1911, 1045, 2712, 145, 1600, 1308, 294, 469, 2265, 3130, 2327, 905, 1362, 596, 136, 1481, 439, 179, 2158, 3077, 1817, 1835, 306, 1919, 1798, 2016, 2573, 1789, 479, 1691, 2402, 2156, 979, 2238, 2913, 2083, 3025, 1753, 1813, 1109, 2023, 3036, 2770, 2095, 2220, 2213, 723, 2246, 2003, 591, 1747, 3040, 309, 2129, 3055, 1236, 1881, 167, 2174, 792, 2239, 1640, 1641, 446, 2684, 1107, 1284, 2431, 346, 364, 1972, 931, 887, 673, 1729, 2366, 2890, 645, 2418, 2805, 401, 3208, 600, 43, 1081, 810, 41, 693, 1884, 1228, 934, 2126, 2228, 1349, 2208, 65, 2523, 1410, 3143, 484, 1626, 1234, 1345, 297, 2414, 1612, 2499, 719, 101, 2107, 829, 2367, 395, 243, 1279, 883, 1646, 1622, 1816, 942, 748, 1335, 70, 3037, 2745, 1676, 390, 59, 2742, 560, 1783, 821, 2514, 2835, 1194, 3271, 314, 320, 3155, 3015, 2403, 1961, 1614, 1518, 494, 67, 2876, 811, 687, 312, 2015, 2555, 1871, 2332, 340, 1516, 3149, 1531, 2586, 2864, 1801, 949, 2148, 1113, 1040, 1159, 2567, 2989, 3190, 3241, 1242, 913, 912, 1422, 2561, 568, 1089, 666, 2825, 2230, 1084, 3067, 1343, 1556, 3177, 128, 1380, 2769, 1787, 980, 2909, 237, 839, 1573, 2601, 1298, 1093, 3054, 2477, 1034, 75, 1539, 287, 684, 2627, 2622, 1893, 1397, 2597, 2485, 2990, 1281, 1538, 55, 1512, 1001, 1759, 154, 1703, 1198, 2797, 1596, 2581, 717, 1928, 1209, 2182, 2152, 2637, 2006, 855, 3075, 281, 2847, 807, 3166, 2136, 2078, 2144, 140, 2986, 3022, 2659, 184, 632, 832, 1530, 1499, 915, 214, 713, 3216, 1958, 194, 2863, 47, 2460, 1488, 2127, 1613, 1533, 1201, 2379, 1617, 2164, 2901, 2564, 1376, 1666, 1447, 465, 253, 2408, 2879, 1637, 1117, 521, 52, 242, 2752, 3188, 1269, 657, 994, 691, 404, 2549, 2729, 2376, 3237, 1476, 2765, 663, 1733, 2404, 705, 3060, 28, 1135, 1292, 1180, 1467, 1657, 2430, 1937, 2255, 1682, 1300, 519, 2728, 3105, 1737, 1341, 2272, 419, 2660, 1160, 1853, 1567, 382, 1913, 1450, 545, 1878, 769, 2200, 58, 1184, 828, 3098, 2199, 228, 1542, 1227, 64, 924, 344, 3050, 310, 1889, 432, 1895, 667, 2724, 2964, 872, 2295, 447, 783, 1765, 2410, 747, 1504, 2715, 2282, 1370, 2299, 2473, 697, 2395, 2886, 751, 638, 2495, 969, 2378, 2387, 2300, 884, 2335, 1241, 3068, 1314, 1832, 1151, 1829, 2018, 2681, 472, 898, 2667, 819, 2705, 1002, 3286, 3008, 478, 3238, 2276, 2595, 1087, 2606, 1210, 1035, 178, 603, 765, 1739, 1727, 1752, 1838, 2779, 455, 2615, 851, 548, 2824, 1126, 3196, 718, 2790, 2716, 3088, 1022, 2568, 3027, 2596, 2709, 1738, 2623, 3016, 2494, 1489, 2468, 1199, 2490, 3123, 643, 3120, 908, 830, 437, 1475, 1806, 1188, 3017, 2361, 1843, 1648, 1486, 3186, 1293, 1272, 129, 2686, 1273, 2211, 1984, 2870, 215, 114, 323, 1986, 2740, 3168, 445, 412, 2256, 531, 1647, 2291, 2940, 750, 2399, 230, 203, 1535, 349, 2618, 1024, 504, 1469, 797, 737, 2168, 2528, 505, 3197, 2542, 1514, 636, 2372, 1445, 978, 92, 1578, 677, 2938, 1820, 2793, 37, 2145, 522, 2091, 2811, 3087, 1901, 389, 2029, 528, 1740, 1941, 2524, 1948, 547, 2240, 2670, 704, 1175, 2197, 316, 1302, 1374, 2278, 1768, 1073, 153, 1303, 3148, 544, 499, 3278, 425, 3047, 229, 450, 2509, 612, 2478, 163, 2172, 219, 1442, 1047, 2617, 2058, 1317, 2358, 489, 3108, 1058, 1178, 1155, 1323, 261, 2357, 2425, 3135, 1894, 3246, 970, 1479, 2470, 61, 1742, 1218, 112, 1728, 3127, 2001, 903, 2219, 1824, 1618, 433, 1590, 2761, 1143, 1830, 2562, 881, 2521, 3064, 3049, 658, 2433, 2444, 32, 880, 3214, 1869, 2383, 1582, 2786, 1101, 1318, 757, 3160, 833, 3243, 127, 3227, 3139, 3126, 2198, 246, 1403, 2809, 2202, 2212, 1127, 1855, 2921, 955, 159, 791, 2232, 895, 1859, 356, 1310, 2151, 1195, 268, 2481, 313, 814, 976, 2375, 2914, 1075, 2334, 3150, 739, 1353, 637, 784, 1564, 570, 2464, 1858, 2737, 2488, 1409, 2296, 2635, 2047, 77, 849, 1280, 2273, 1546, 2386, 1427, 2323, 604, 2771, 2551, 2676, 773, 190, 335, 2553, 695, 2120, 1751, 2880, 577, 1938, 914, 1438, 1472, 508, 852, 2100, 367, 1599, 891, 1644, 2827, 726, 2915, 1836, 2755, 2059, 3009, 1301, 1361, 1821, 1399, 2115, 2286, 3056, 1132, 160, 2939, 206, 318, 249, 3165, 3004, 1933, 2947, 1863, 1979, 1371, 2758, 1942, 2157, 688, 1707, 2469, 706, 3072, 674, 2122, 2159, 1792, 2160, 2166, 2231, 2344, 3001, 1029, 1480, 556, 2396, 1152, 139, 130, 682, 1929, 1746, 2720, 319, 272, 530, 189, 3023, 115, 250, 731, 2750, 3058, 2536, 429, 452, 977, 3281, 3097, 1259, 1268, 2671, 2867, 2933, 2877, 436, 1419, 24, 1000, 330, 1633, 2233, 2459, 675, 668, 618, 18, 2756, 2065, 2931, 1275, 1342, 2349, 84, 2995, 496, 2311, 827, 1398, 2167, 415, 1118, 2869, 498, 51, 526, 3129, 532, 2215, 2181, 2069, 2178, 2277, 1794, 347, 2439, 2359, 1565, 800, 2071, 2193, 1916, 1594, 185, 3044, 485, 2427, 195, 822, 2711, 2112, 233, 1736, 799, 2547, 780, 1407, 947, 241, 1131, 2154, 2782, 2817, 380, 2285, 694, 3270, 2929, 2053, 1258, 2796, 2896, 2760, 2229, 1053, 974, 62, 1947, 2455, 601, 2962, 2857, 812, 1105, 2674, 1336, 3024, 351, 3282, 1725, 1357, 708, 1607, 2070, 1719, 2970, 927, 2556, 1815, 2616, 2308, 1015, 244, 2454, 1595, 3268, 2342, 1254, 896, 266, 176, 1257, 1914, 778, 1954, 329, 2932, 1668, 1678, 2891, 192, 271, 298, 2471, 1121, 922, 3159, 2768, 2301, 1693, 1235, 1585, 1774, 2353, 2169, 3094, 1154, 959, 3042, 1147, 2899, 2968, 260, 2171, 83, 2679, 1382, 2735, 1818, 1547, 2355, 1822, 3035, 790, 2075, 858, 1247, 3228, 639, 94, 1876, 561, 1418, 3187, 1846, 1777, 1501, 2822, 3199, 1793, 48, 1276, 454, 501, 2649, 1010, 746, 60, 2139, 1219, 1396, 3239, 3203, 2630, 1470, 2656, 2987, 2983, 3012, 1561, 247, 1782, 520, 2017, 999, 945, 1908, 1771, 2204, 689, 1372, 1624, 3180, 1721, 1042, 2320, 30, 1124, 1405, 1351, 629, 3222, 615, 26, 1388, 39, 2976, 2085, 2603, 95, 106, 2590, 983, 1967, 2849, 1581, 2902, 221, 2119, 2214, 1261, 1051, 557, 2907, 2559, 2183, 171, 2319, 733, 781, 936, 3073, 834, 837, 702, 2723, 2647, 293, 549, 1008, 362, 265, 696, 2297, 981, 2666, 2980, 2336, 2703, 1378, 566, 1839, 2704, 1214, 2063, 1217, 878, 1331, 2104, 2223, 722, 1474, 125, 1611, 2605, 1962, 2882, 785, 2977, 1882, 2842, 1995, 1267, 1896, 3156, 2941, 2475, 2035, 2491, 2175, 540
2025-07-21 04:48:56 +09 - [Warning-Duplicati.Library.Main.Operation.Restore.BlockManager-BlockCacheMismatch]: Internal Block cache is not empty: 77
2025-07-21 04:48:56 +09 - [Warning-Duplicati.Library.Main.Operation.Restore.BlockManager-BlockCacheMismatch]: Block counts in cache (667501): 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1730, 6, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 32, 35, 36, 1, 427, 63, 1, 11, 1, 1, 572, 42, 1, 5, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 2, 1, 1, 1, 1, 1, 2, 2, 2, 1, 1, 2, 2, 1, 1, 1, 1, 3, 3, 3, 1, 2, 2, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 2, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 2, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 2, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 31, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1
[...]

Of course I’ll retry with a larger disk, but I am guessing this is a bug and I’m hoping this helps pinpoint and improve the product!

Best,

Gaston

ts678 · July 22, 2025, 9:28pm

Blog post: Cut restore times by 3.8x - A deep dive into our new restore flow
talks about the new design. You can try to look at that while waiting for devs.

but Cache seems to only let one tune the block cache (memory), not the volume cache.

is another option. also mentioned in the 2.1.1.0 Experimental release notice, as in Canary.

gdassieu · July 25, 2025, 4:53pm

Thanks ts678

That article is super interesting!

And I see below:

However, these caches are only really utilized when there’s high deduplication between files, so the caches shouldn’t grow too large.

Future work will analyze block and volume deduplication across files to optimize cache utilization and maximize data reuse. The worst case can occur when the order of files is such that the caches don’t get auto evicted and the system runs out of memory or disk space. The aforementioned future work would alleviate this problem. However, our tests showed that this was rarely an issue, but that may be due to the test machines having a large amount of system memory.

I do not believe my files have a particularly high deduplication rate, since my backup size is on the same ballpark as my source data size. So I’m left to wonder if my files are in the “wrong order” as mentioned above, causing the caches not to get auto evicted? Or maybe we really hit a bug here…

In my case, after substantially increasing the disk size of the VM and retrying, the restore was successful, so I have found my workaround.

Nevertheless I’ll be happy to do some tests to help get to the bottom of this, but I’ll need some instructions

Cheers,

Gaston

kenkendk · August 5, 2025, 3:37pm

I think this is mostly caused by the cache being very eager to progress, when it could instead wait with downloading new files. I have registered an issue for limiting the size of temporary storage needed for restores.

gdassieu · August 9, 2025, 4:55am

Thanks Kenneth

During the restore from GCS to local disk, I monitored disk usage using Powershell on the restore folder and the cache folder. Please see below graph and find attached the CSV with the data, in case it helps (restore process ran from 09:32 PM until 06:13 AM).

Size.zip (1.5 KB)

Indeed, we need to find a good balance between consuming a lot of disk space (eager cache) and improving restore performance. I think one possible logic could be as follows, assuming there are 3 processes:

Producer (cache): Downloads ahead the blocks that will be needed for restore. Here we limit the to a few GB (say 5GB by default, can be changed by a parameter). The principle being that there’s no point of pre-downloading a lot of data, just enough to avoid the consumer having to wait for more blocks to be downloaded.
Consumer: The process that uses the downloaded blocks and restores the data.
Purger: The process that purges no longer needed blocks from the cache. It should essentially only purge blocks that are no longer needed, but with one exception: if the cache disk is getting full (say, <10GB free space), purge blocks that will be needed again anyway. The idea is that it’s preferrable to have to re-download one block rather than to fail the restore process due to disk full condition.

Thanks again for making such a great product. Let me know if you’d need me to make a test on a new version to compare the results.

For reference, here’s the script to monitor the size every ~10 minutes:

$RestoreFolder = 'C:\Restore'
$CacheFolder = 'C:\Users\Test\AppData\Local\Temp'

While($True)
{
  [pscustomobject]@{
    Date          = Get-Date
    RestoreSizeGB = (Get-ChildItem -Path $RestoreFolder -Force -File -Recurse | Measure-Object -Property Length -Sum).Sum / 1GB
    CacheSizeGB   = (Get-ChildItem -Path $CacheFolder -Force -File -Recurse | Measure-Object -Property Length -Sum).Sum / 1GB
  } | Export-CSV -Path size.csv -Append
  Start-Sleep 600
}

Cheers,

Gaston