After updating to 2.0.3.5 canary I did some more testing on this and have come up with the following:
I’m getting this LZMA based fatal error - yes, I started with 7zip but then changed to zip (which should be defaulting to deflate)
2018-04-16 22:59:34 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
SharpCompress.Compressors.LZMA.DataErrorException: Data Error
at SharpCompress.Compressors.LZMA.LzmaStream.Read(Byte[] buffer, Int32 offset, Int32 count)
at Duplicati.Library.Utility.Utility.ForceStreamRead(Stream stream, Byte[] buf, Int32 count)
at Duplicati.Library.Main.Volumes.BlockVolumeReader.ReadBlock(String hash, Byte[] blockbuffer)
at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend)
at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBacked, Boolean forceCompact, BackendManager sharedManager)
at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize)
at Duplicati.Library.Main.Operation.BackupHandler.Run(String[] sources, IFilter filter)
When that error happens to me the job seems to run the whole way through (including “Completing backup”) and I end up with:
a. NO entry for ANY of the job run in the job General log (not even a “job started”)
b. expected entries in the job Remote log
c. a SINGLE Failed while executing "Backup" with id: entry in the global Stored log
d. plenty of expected entries in the global Live log
e. an email of the job failure DOES get sent
f. main job GUI does NOT report the job as having completed successfully
g. the run DOES show up in the RESTORE list (even though the GUI doesn’t consider it successful)
Setting --no-backend-verification=true does NOT resolve the issue.
So the issues are:
Why am I getting the LZMA error even though I’m using zip (which should be defaulting to deflate)? (My guess is it’s the retention cleanup trying to handle the old 7-zip files, but the log doesn’t report which file had the LZMA error so I’m not sure how to verify that.)
Why do the job summary and General job report the backup as if it never even started?
I tried the job with a “Keep all” retention policy and the LZMA errors seem to have stopped, though now I’m getting a Found 10 files that are missing from the remote storage, please run repair fatal error.
I’ll try the repair with the “Keep all” policy and see what happens. (I’m still loving the “Repair” button added to that alert, thanks!)
Well, I’ve now had a successful run after the database repair but with the “Keep all” policy. (Though the GUI display showed a 4 second run duration while the summary report showed 4 hours…:
Last successful run: Yesterday at 9:19 PM (took 00:00:04)
Anyway, I’m pretty confident that the issue is related to problems compacting the older 7zip files (that I USED to use - I switched to zip after reading about the possible issues with 7z files) during the retention policy cleanup.
After a few more (expected successful) test runs, I’ll flip back to using a retention policy at which point I expect I will again:
have LZMA errors during post-backup compacting
have the jobs treated as FAILED due to the post-backup compacting errors
have “Found n files that are missing …” errors if I again switch to a “Keep all” retention policy
have working backups if I do a database repair to resolve the missing files errors and stay with the “Keep all” policy
If all that goes as expected, I may try Duplicati.RecoveryTool.exe recompress (as described below) just to see what happens.
As expected the LZMA errors came back when a non-“Keep all” retention policy was used…but also when I switched back to “Keep all”, so there may be multiple causes of the issue (such as normal compacting).
The most recent specific error is below. What I’m not yet sure about is what Duplicati is doing to cause the LZMA error since duplicati-b172f35a4e7c64fbca0614a0ee02cd6af.dblock.7z.aes is reported as already downloaded AND decrypted.
On the plus side, this seems pretty repeatable so maybe I can add some more debugging to track down what’s going on.
2018-04-23 08:20:22 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2018-04-23 08:20:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b172f35a4e7c64fbca0614a0ee02cd6af.dblock.7z.aes (20.26 MB)
2018-04-23 08:20:29 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 20.26 MB in 00:00:07.2031520, 2.81 MB/s
2018-04-23 08:20:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b172f35a4e7c64fbca0614a0ee02cd6af.dblock.7z.aes (20.26 MB)
2018-04-23 08:20:29 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:07.203
2018-04-23 08:20:33 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
SharpCompress.Compressors.LZMA.DataErrorException: Data Error
at SharpCompress.Compressors.LZMA.LzmaStream.Read(Byte[] buffer, Int32 offset, Int32 count)
at Duplicati.Library.Utility.Utility.ForceStreamRead(Stream stream, Byte[] buf, Int32 count)
at Duplicati.Library.Main.Volumes.BlockVolumeReader.ReadBlock(String hash, Byte[] blockbuffer)
at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend)
at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBacked, Boolean forceCompact, BackendManager sharedManager)
at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize)
at Duplicati.Library.Main.Operation.BackupHandler.Run(String[] sources, IFilter filter)
Also odd is that even though I switched to a zip file format about 3 weeks ago, I’m seeing 7z files as recently as 6 days ago.
In fact, my last full set (dindex, dlist, dblock) of 7zip files is from April 2, but there are 24 zip dindex (and ONLY dindex) files since then.
@kenkendk, are dindex files “updated” with “to be deleted” status before the dblock and dlist files are actually compacted? If so, is it expected that they stay in the same compression format as their related dlist / dblocks?
Well, at least 1 test with a custom retention policy of 7D:U,4W:1D,U:U (putting cleanup OUTSIDE of the dates during which I used 7zip files) ran without issues. Yay!
Oddly, a test restore of a PDF from the time when I was using 7zip files worked fine, but I still get the “Data Error” messages during retention policy based cleanup. I’m not sure if it’s due to different files involved (some 7z files may be good) or different code…
In either case, it sure would be nice if I could do a custom retention policy based on an absolute date instead of relative. For example, I switched from 7z to zip on 03/14/2018 so being able to do a custom retention policy like 7D:U,4W:1D,2018-03-14:U (meaning unlimited backups for 2018-03-14 and older) would be great for my needs in this test scenario.
The compact first writes the new volumes, and then it marks all the unwanted volumes as “deleting”. This ensures that if the program is killed, no data is lost.
