Duplicati 2.0 - Free backup software to store encrypted backups online
This are my findings for an issue I was not able to resolve yet, but with this article I am going to write down my findings and hopefully this helps me to find a way to get rid of it. This problem popped up some time ago, it is not happening with every backup which is done, but happens more frequently the last few weeks.
TLDR; After spending quite some time testing and figuring out the root cause, we did not succeed in finding it. The good news: We fixed the backup at the end. We found the broken dblock files, we were able to verify which files affected by the broken dblock files and in my case they were still on my filesystem. This allowed me to use the Disaster Recovery Guide. I deleted the affected dblock files from the backup set, ran the purge-broken-files command and after many hours and days I was able to start a normal backup. Because the files were still on the filesytem, affected by the broken files, they got re-added to the backup. Thanks to ts678 for the help.
There is a discussion on the duplicati forum which is the reason I am creating this article to keep an overview.
The error I do get with my backups
Failed: Invalid header marker
The information in About > Show log > Stored > Failed while executing "Backup" with id: 1
System.Security.Cryptography.CryptographicException: Invalid header marker ---> System.IO.InvalidDataException: Invalid header marker
at SharpAESCrypt.SharpAESCrypt.ReadEncryptionHeader (System.String password, System.Boolean skipFileSizeCheck) [0x0004b] in <45c43198e80545aeabaa9b98839b4c7d>:0
at SharpAESCrypt.SharpAESCrypt..ctor (System.String password, System.IO.Stream stream, SharpAESCrypt.OperationMode mode, System.Boolean skipFileSizeCheck) [0x0018a] in <45c43198e80545aeabaa9b98839b4c7d>:0
at (wrapper remoting-invoke-with-check) SharpAESCrypt.SharpAESCrypt..ctor(string,System.IO.Stream,SharpAESCrypt.OperationMode,bool)
at Duplicati.Library.Encryption.AESEncryption.Decrypt (System.IO.Stream input) [0x00000] in <a3217bd0ca2d4a6bb2457ef1971c41fc>:0
at Duplicati.Library.Encryption.EncryptionBase.Decrypt (System.IO.Stream input, System.IO.Stream output) [0x00000] in <a3217bd0ca2d4a6bb2457ef1971c41fc>:0
at Duplicati.Library.Main.BackendManager+<>c__DisplayClass36_0.<coreDoGetPiping>b__0 () [0x00029] in <759bd83d98134a149cdf84e129a07d38>:0
at System.Threading.Tasks.Task.InnerInvoke () [0x0000f] in <3833a6edf2074b959d3dab898627f0ac>:0
at System.Threading.Tasks.Task.Execute () [0x00000] in <3833a6edf2074b959d3dab898627f0ac>:0
--- End of inner exception stack trace ---
at Duplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile.get_TempFile () [0x00008] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.CompactHandler.DoCompact (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Boolean hasVerifiedBackend, System.Data.IDbTransaction& transaction, Duplicati.Library.Main.BackendManager sharedBackend) [0x00264] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.DeleteHandler.DoRun (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Data.IDbTransaction& transaction, System.Boolean hasVerifiedBacked, System.Boolean forceCompact, Duplicati.Library.Main.BackendManager sharedManager) [0x00397] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired (Duplicati.Library.Main.BackendManager backend, System.Int64 lastVolumeSize) [0x000a5] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x01033] in <759bd83d98134a149cdf84e129a07d38>:0
at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <9a758ff4db6c48d6b3d4d0e5c2adf6d1>:0
at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00009] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0004b] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0026f] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Controller.Backup (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x00074] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00349] in <63a01150aadd4a64a4d7c359bdc1e45d>:0 This is a summary of the setup I am running right now. I removed all sensitive data.
CLI command
mono /opt/duplicati/Duplicati.CommandLine.exe backup
"ssh://192.168.21.4:22/mnt/backup/?auth-username=xxx&ssh-fingerprint=xxx" /share/Nextcloud/
--backup-name="data [remote]"
--dbpath=/data/Duplicati/66858766816685668781.sqlite
--encryption-module=aes
--compression-module=zip
--dblock-size=50MB
--keep-time=6M
--skip-files-larger-than=4GB
--blocksize=500KB
--backup-test-samples=5
--disable-file-scanner=true
--aes-set-threadlevel=2
--exclude-files-attributes=temporary
--disable-module=console-password-input
--exclude="*.part"
--exclude="*Recycle*/"
--exclude="*trashbin*/"This notes could be useful for the investigation to resolve the proble, but could also be totally useless.
I moved the backup set quite some time from one provider to another, first running it locally to an external harddisk. Afterwards moving the same backup set to Backblaze and last and hopefully least, I moved again to an on-premise solutation. This solution is located somewhere else, running a Raspberry Pi 1 with an USB Harddisk attached. The machine is reachable via a site to site VPN and I am using SSH to transfer the data.
With the last move of the backup set I also decreased the "Remote Volume Size" from 250MB back to the default of 50MB. This should be possible due to the documentation and in my case it is a better fit for the destination I am using it right now.
This is a lose collections of the different approache I tried to resolve the issue. Some of them took / take multiple days to get an outcome and still after some days it is always unclear if this was enough time to test the solution properly.
This approach did not change anything but gave us a starting point.
I set the retention time to Keep all backups Lets see whats happening over the next couple of days. I cannot keep this settting for too long, because I have limited space on the destination drive.
After many days, the backup has still not generated the error. This let me conclude that the error is generated while deleting old backups and using the compact operation to reduce dblocks. Therefor the backup itself is working, but not the deletion of old data based on the retention time.
This approach did not change anything
I restarted Duplicati and did the backup again, which worked. It also worked without restarting Duplicati itself, but restart the backup job.
I think, that because I restarted the backup on the same day the failing backup ended, that the retention policy was not triggered and therefor the backup was just working fine.
This approach did not change anything
ts678 is a very helpful source to work through the issue, and one of the problems pointed out was traffic throttling.
let me ask if anybody is using any sort of speed throttle on upload or download, e.g. from –throttle-upload, –throttle-download or the GUI throttle button at the top of the page? Upload throttle corrupts backup, especially OneDrive. Analyzed, with code proposed. #3787 (the OneDrive comment just means it was the worst of the several tested – there could easily be more)
I have no throttling configured on Duplicati itself. I do have some sort of traffic shaping configured on the site to site VPN tunnel. This avoids some communication to be thwarted but this traffic does not consume lots of bandwidth at all nor does it show up over night. Therefor throttling cannot be the issue, also I assume that this issue would have been seen by others as well while using SSH to the destination.
This approach was not tested
ts678 mentioned
Determining the nature of the corruption would help, but may involve looking in SQLite databases (not so difficult, but probably needs DB Browser for SQLite or similar installed).
ts678 mentioned
Some simpler tests are to check size of the corrupted file, convert to hexadecimal, and see if it looks too round. That might be an FS error. –upload-verification-file will make a text file duplicati-verification.json that describes expected remote files. Running DuplicatiVerify.* from the Duplicati utility-scripts folder can test destination files look as expected, assuming you can either get that sort of destination access, or are willing to get the files more accessible, however if doing a complete download is required, you might just as well run the test command over
all. That should do a hash check of all remote files, but you can also do your own simple manual checking of some particular file by looking it up in duplicati-verification.json to at least see if actual size is as expected.
With the last backup run, I added the switch to create the verfication file. This file was created successfully. Using wget https://raw.githubusercontent.com/duplicati/duplicati/master/Tools/Verification/DuplicatiVerify.py on the machine the backup is stored, I downloaded the python script which is used to run the verificaton process.
The process itself was started within screen, this allows me to close my SSH session and come back again withouth losing information. The command I used to start the process: python DuplicatiVerify.py /mnt/backup/nextcloud-data/
Because of the limited screen buffer, you need to start screen with its build in logging functionality screen -L otherwise you lose information which is crucial.
I found 4 files which could not be verified successfully. Using the affected command I could investigate which files were affected by that dblock files. Luckily the files were still existing on the system which gave me some space to move an play around.
Internal log files are configured
ts678 mentioned
Stepping back to more ordinary steps, logs can be good to see what led up to the problem, however with problems with older files (how old is the bad file based on remote info?), you can’t get details retroactively. Sometimes one might get lucky, and find relevant info in default job logs or About --> Show log --> Stored. Beyond that, use –log-file with –log-file-log-level=retry (reasonable compromise, but other levels may do).
I added log-file: /data/logs/nextcloud-data.log which is a directory I have mounted to my docker container for restoring files. This directory has read/write permissions. I also set the log-file-log-level to Retry like mentioned in the comment from ts678
Log Information from the last run with Invalid header marker error, I investigated the files existence and they still exist
2019-11-18 21:00:01 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2019-11-18 22:35:12 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()
2019-11-18 22:37:16 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (23.50 KB)
2019-11-18 22:39:58 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8e36b4cc806744528068136de4468f9b.dblock.zip.aes (49.80 MB)
2019-11-18 22:40:54 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8e36b4cc806744528068136de4468f9b.dblock.zip.aes (49.80 MB)
<...omitted...>
2019-11-19 00:39:14 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20191118T210001Z.dlist.zip.aes (62.31 MB)
2019-11-19 00:40:11 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20191118T210001Z.dlist.zip.aes (62.31 MB)
<...omitted...>
2019-11-19 03:29:24 +00 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there are 5 fully deletable volume(s)
2019-11-19 03:29:28 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-b8226c47f8aee4f08ae3b7dd32afd72d3.dblock.zip.aes (249.62 MB)
2019-11-19 03:29:34 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-b8226c47f8aee4f08ae3b7dd32afd72d3.dblock.zip.aes (249.62 MB)
<...omitted...>
2019-11-19 03:31:20 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd72accde1ec049dc99bc453d7d9e92cf.dblock.zip.aes (249.96 MB)
2019-11-19 03:38:59 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-bd72accde1ec049dc99bc453d7d9e92cf.dblock.zip.aes (249.96 MB)
2019-11-19 03:38:59 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes (249.81 MB)
2019-11-19 03:46:36 +00 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes attempt 1 of 5 failed with message: Invalid header marker
<...omitted...>
2019-11-19 04:10:07 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes (249.81 MB)
2019-11-19 04:10:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes (249.81 MB)
2019-11-19 04:18:00 +00 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes attempt 5 of 5 failed with message: Invalid header marker
System.Security.Cryptography.CryptographicException: Invalid header marker ---> System.IO.InvalidDataException: Invalid header marker
at SharpAESCrypt.SharpAESCrypt.ReadEncryptionHeader (System.String password, System.Boolean skipFileSizeCheck) [0x0004b] in <45c43198e80545aeabaa9b98839b4c7d>:0
at SharpAESCrypt.SharpAESCrypt..ctor (System.String password, System.IO.Stream stream, SharpAESCrypt.OperationMode mode, System.Boolean skipFileSizeCheck) [0x0018a] in <45c43198e80545aeabaa9b98839b4c7d>:0
at (wrapper remoting-invoke-with-check) SharpAESCrypt.SharpAESCrypt..ctor(string,System.IO.Stream,SharpAESCrypt.OperationMode,bool)
at Duplicati.Library.Encryption.AESEncryption.Decrypt (System.IO.Stream input) [0x00000] in <a3217bd0ca2d4a6bb2457ef1971c41fc>:0
at Duplicati.Library.Encryption.EncryptionBase.Decrypt (System.IO.Stream input, System.IO.Stream output) [0x00000] in <a3217bd0ca2d4a6bb2457ef1971c41fc>:0
at Duplicati.Library.Main.BackendManager+<>c__DisplayClass36_0.<coreDoGetPiping>b__0 () [0x00029] in <759bd83d98134a149cdf84e129a07d38>:0
at System.Threading.Tasks.Task.InnerInvoke () [0x0000f] in <3833a6edf2074b959d3dab898627f0ac>:0
at System.Threading.Tasks.Task.Execute () [0x00000] in <3833a6edf2074b959d3dab898627f0ac>:0
--- End of inner exception stack trace ---
at Duplicati.Library.Main.BackendManager.coreDoGetPiping (Duplicati.Library.Main.BackendManager+FileEntryItem item, Duplicati.Library.Interface.IEncryption useDecrypter, System.Int64& retDownloadSize, System.String& retHashcode) [0x002d3] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.BackendManager.DoGet (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x002ff] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.BackendManager.ThreadRun () [0x000ff] in <759bd83d98134a149cdf84e129a07d38>:0
<...omitted...>
2019-11-19 04:20:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd743e3577a764e6eabba37e83ec36cac.dblock.zip.aes (249.59 MB)
2019-11-19 04:20:28 +00 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-bd743e3577a764e6eabba37e83ec36cac.dblock.zip.aes attempt 1 of 5 failed with message: Thread was being aborted.
System.Threading.ThreadAbortException: Thread was being aborted.
at (wrapper managed-to-native) System.Threading.Monitor.Monitor_wait(object,int)
at System.Threading.Monitor.ObjWait (System.Boolean exitContext, System.Int32 millisecondsTimeout, System.Object obj) [0x0002f] in <3833a6edf2074b959d3dab898627f0ac>:0
at System.Threading.Monitor.Wait (System.Object obj, System.Int32 millisecondsTimeout, System.Boolean exitContext) [0x0000e] in <3833a6edf2074b959d3dab898627f0ac>:0
at System.Threading.Monitor.Wait (System.Object obj) [0x00000] in <3833a6edf2074b959d3dab898627f0ac>:0
at Renci.SshNet.Sftp.SftpFileReader.Read () [0x0004f] in <c60291af03764e69b153abec058a6ec5>:0
at Renci.SshNet.SftpClient.InternalDownloadFile (System.String path, System.IO.Stream output, Renci.SshNet.Sftp.SftpDownloadAsyncResult asyncResult, System.Action`1[T] downloadCallback) [0x00078] in <c60291af03764e69b153abec058a6ec5>:0
at Renci.SshNet.SftpClient.DownloadFile (System.String path, System.IO.Stream output, System.Action`1[T] downloadCallback) [0x00006] in <c60291af03764e69b153abec058a6ec5>:0
at Duplicati.Library.Backend.SSHv2.Get (System.String remotename, System.IO.Stream stream) [0x00012] in <40ac48623b834b889568d306e7f7925b>:0
at Duplicati.Library.Main.BackendManager.coreDoGetPiping (Duplicati.Library.Main.BackendManager+FileEntryItem item, Duplicati.Library.Interface.IEncryption useDecrypter, System.Int64& retDownloadSize, System.String& retHashcode) [0x00262] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.BackendManager.DoGet (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x002ff] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.BackendManager.ThreadRun () [0x000ff] in <759bd83d98134a149cdf84e129a07d38>:0
2019-11-19 04:20:28 +00 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Security.Cryptography.CryptographicException: Invalid header marker ---> System.IO.InvalidDataException: Invalid header marker
at SharpAESCrypt.SharpAESCrypt.ReadEncryptionHeader (System.String password, System.Boolean skipFileSizeCheck) [0x0004b] in <45c43198e80545aeabaa9b98839b4c7d>:0
at SharpAESCrypt.SharpAESCrypt..ctor (System.String password, System.IO.Stream stream, SharpAESCrypt.OperationMode mode, System.Boolean skipFileSizeCheck) [0x0018a] in <45c43198e80545aeabaa9b98839b4c7d>:0
at (wrapper remoting-invoke-with-check) SharpAESCrypt.SharpAESCrypt..ctor(string,System.IO.Stream,SharpAESCrypt.OperationMode,bool)
at Duplicati.Library.Encryption.AESEncryption.Decrypt (System.IO.Stream input) [0x00000] in <a3217bd0ca2d4a6bb2457ef1971c41fc>:0
at Duplicati.Library.Encryption.EncryptionBase.Decrypt (System.IO.Stream input, System.IO.Stream output) [0x00000] in <a3217bd0ca2d4a6bb2457ef1971c41fc>:0
at Duplicati.Library.Main.BackendManager+<>c__DisplayClass36_0.<coreDoGetPiping>b__0 () [0x00029] in <759bd83d98134a149cdf84e129a07d38>:0
at System.Threading.Tasks.Task.InnerInvoke () [0x0000f] in <3833a6edf2074b959d3dab898627f0ac>:0
at System.Threading.Tasks.Task.Execute () [0x00000] in <3833a6edf2074b959d3dab898627f0ac>:0
--- End of inner exception stack trace ---
at Duplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile.get_TempFile () [0x00008] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.CompactHandler.DoCompact (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Boolean hasVerifiedBackend, System.Data.IDbTransaction& transaction, Duplicati.Library.Main.BackendManager sharedBackend) [0x00264] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.DeleteHandler.DoRun (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Data.IDbTransaction& transaction, System.Boolean hasVerifiedBacked, System.Boolean forceCompact, Duplicati.Library.Main.BackendManager sharedManager) [0x00397] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired (Duplicati.Library.Main.BackendManager backend, System.Int64 lastVolumeSize) [0x000a5] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00d9f] in <759bd83d98134a149cdf84e129a07d38>:0 This approach was not tested
Because of the recurring error, I need to know if the backup is still working and valid. I restored some files during the whole process of this investigation, but once again ts678 made a valid point in how restores are handled with Duplicati.
How are you testing restore? It’s unfortunately not very meaningful if to the same system with the original files still around, because original files will be checked and used for restore material that’s relevant to the requested restore – using local data blocks will run faster than downloading blocks.
–no-local-blocks added and checkboxed in Advanced options on job screen 5 Options will disable optimization of this sort. Direct restore from backup files to another machine won’t have this issue.
We need to find out better how badly your backup might be damaged. Ideally you would be able to direct restore all of it to a different system, which simulates recovery from disaster loss of originals. I’m not sure what constraints you have on disk space, bandwidth, or metered service that interfere. What level of access do you have to the SFTP server? Can you directly access files? Run scripts? Do you know what SFTP server you have, and what access you have to examine the files closely?
This could figured out
ts678 mentioned
There was a theory earlier that compact runs and hits some bad old files. Verifying backend files after backup seems more likely because compact likely won’t run every time.
EDIT: Viewing the log files of a backup job will showCompactResultsfrom compact run if it did run.RetryAttemptsbeing non-zero would be expected in a failure case because it retries before it fails.In Advanced options, adding and checking –no-auto-compact can avoid its downloads. Adding and setting to 0 –backup-test-samples can prevent the downloads after backup. These are only for tests because they hide the issue, however they do help confirm or refute that you have some bad files…
If you have enough bad files, starting over anew is probably the best plan, if that would be an option.
Another piece of the puzzle, but not really a break through.
ts678 mentioned
AES File Format is what’s expected as .aes file header, otherwise you get “Invalid header marker” error.
3 Octets - 'AES' 1 Octet - 0x02 (Version) 1 Octet - Reserved (set to 0x00)If your Raspberry Pi has these typical commands, you can cd to your backup and survey for bad files by
find . -type f \( -execdir bash -c '[[ `xxd -plain -l 5 {}` == '4145530200' ]]' \; -or -print \)Backticks cause the string between them to be run, and the output to be returned. In this case, it uses xxd to dump the first five characters as numbers which should be
4145530200which is compared (==) against that string simply hardcoded into the script. This is done inside a bash expression ([[ and ]]) and result is returned. If true (i.e. got what was expected), the expression in find has a known result without evaluating the -or, so the print is not done. If it got something other than the expected header, the -or is evaluated to see if the expression might actually be true, and evaluating the -print prints the path of file.That’s much like Duplicati’s check, and I had described it as “the header must be correct or you’ll hear”.
After finding the "broken" files we verify the beginning of the files to see what could be the issue
So what does the file look like in terms of things like length and header? Run xxd as above if you like, however hexdump -C on the file will make a more human friendly display. A longer header will be like:
00000000 41 45 53 02 00 00 21 43 52 45 41 54 45 44 5f 42 |AES...!CREATED_B| 00000010 59 00 53 68 61 72 70 41 45 53 43 72 79 70 74 20 |Y.SharpAESCrypt | 00000020 76 31 2e 33 2e 31 2e 30 00 80 00 00 00 00 00 00 |v1.3.1.0........| 00000030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|For anything but a very short file, you probably want to pipe (| which is veritical bar) output into head:
hexdump -C duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes | headFor more serious review (if it comes to that), you can pipe into less, or redirect into a file for an editor. If the issue turns out to be an empty file, you can quickly audit using something like
ls -lSr | head
Based on the detected files, we ran additional tests. The idea is to find some pattern in the files. The amount of zeros looked quite suspecious. I used grep '00 00 00 00 00 00 00 00' on those files to find some patterns.
This are the files, based on the above command:
At least one file matches the information of the log file I got with the extended logging turned on. The outcome of the head information on a broken file and another random file
Broken ones
# hexdump -C duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes | head
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
02cfb6e0 01 0d c6 32 79 2f 36 61 ef 11 79 5c 6a 72 76 b6 |...2y/6a..y\jrv.|
02cfb6f0 e3 9d a8 b2 b3 da a9 78 c3 8b 66 76 05 1c 0b fc |.......x..fv....|
02cfb700 92 84 82 d9 ab 99 18 82 92 24 bc 3e f6 ce 19 df |.........$.>....|
02cfb710 64 56 c7 5b 4d 52 1f c4 c5 87 dc 85 29 66 85 25 |dV.[MR......)f.%|
02cfb720 7d e8 13 c7 e3 a9 9b dc 2f ee 8e 23 34 32 c7 6f |}......./..#42.o|
02cfb730 e2 15 7f 45 63 07 39 17 5e 28 2f 7a 7e 15 b6 b3 |...Ec.9.^(/z~...|
02cfb740 24 83 86 0e 9d b4 8d 66 88 df 9a b5 6f 2e 0c fb |$......f....o...|
02cfb750 70 c6 d9 f6 8a 89 77 ac bd ab 22 d5 29 75 9f b2 |p.....w...".)u..|
# hexdump -C duplicati-bfcc04033b8f54b61a1c91d24fa04fb17.dblock.zip.aes | head
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00037fa0 00 00 00 00 00 a6 e6 14 97 72 db 12 92 3c ad ea |.........r...<..|
00037fb0 2c 6e 84 0d 47 4f ac 1e 4c 8d 00 38 41 83 e7 35 |,n..GO..L..8A..5|
00037fc0 45 3e b0 88 2c 0d d6 b7 3f 01 ee f4 2a 5e c6 09 |E>..,...?...*^..|
00037fd0 99 6f 85 f5 0f ba 3f 13 b3 87 c5 54 0d f8 92 84 |.o....?....T....|
00037fe0 be ba de ea 27 f5 05 0b 66 f7 83 9b 2b 09 08 eb |....'...f...+...|
00037ff0 a7 ce 5c 50 76 5d 2d 13 68 d8 fe 53 09 c9 01 61 |..\Pv]-.h..S...a|
00038000 58 0f 2a 12 80 40 70 3d 15 5d 85 fe bf 87 d2 59 |X.*..@p=.].....Y|
00038010 f5 ec 0c 1c 78 a2 84 27 4e fe 77 46 4a 26 c1 bd |....x..'N.wFJ&..|
# hexdump -C duplicati-b3ab98cd26a2e469fa0c8262c7b96ff87.dblock.zip.aes | head
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
0503fd80 00 00 00 00 00 00 00 00 00 00 00 8b 7e 30 3b f0 |............~0;.|
0503fd90 97 1b dd 32 76 59 66 f1 a7 bc 76 f6 7a 78 65 41 |...2vYf...v.zxeA|
0503fda0 26 8c c5 fe 58 e0 7c 6e 9d 5b e4 d1 2c 98 31 22 |&...X.|n.[..,.1"|
0503fdb0 f3 0a 62 9a 70 ad 18 4d c7 09 f5 52 f2 ff b0 9c |..b.p..M...R....|
0503fdc0 d7 37 bf b7 ae 3f b7 eb 7d e9 fa 67 b3 7b e7 aa |.7...?..}..g.{..|
0503fdd0 c3 a5 62 de f1 93 60 d9 51 b9 cb 90 33 4e 09 50 |..b...`.Q...3N.P|
0503fde0 e2 40 12 ae 9a c6 f0 27 89 18 5f a9 bb cc 4b 25 |.@.....'.._...K%|
0503fdf0 d5 3c c5 7b 1c cd 10 d0 5c 64 ec a7 69 32 93 20 |.<.{....\d..i2. |Good one
# hexdump -C duplicati-bf6a3048f8e9a44aca242f02ff5c887a4.dblock.zip.aes | head
00000000 41 45 53 02 00 00 21 43 52 45 41 54 45 44 5f 42 |AES...!CREATED_B|
00000010 59 00 53 68 61 72 70 41 45 53 43 72 79 70 74 20 |Y.SharpAESCrypt |
00000020 76 31 2e 33 2e 33 2e 30 00 80 00 00 00 00 00 00 |v1.3.3.0........|
00000030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
000000a0 00 00 00 00 00 00 00 00 00 00 00 00 13 05 52 17 |..............R.|
000000b0 ce fc 96 11 b4 1b b7 97 03 ce f9 76 bc ec 8e 81 |...........v....|
000000c0 67 33 4f da b7 67 8f 0f c4 4f 35 27 4e ed 21 bc |g3O..g...O5'N.!.|
000000d0 c4 a1 49 28 f0 a9 86 c3 bb e0 26 e6 37 f1 46 41 |..I(......&.7.FA|
000000e0 43 8c e4 1b 27 28 e7 b4 cd 15 15 ba 76 6d 70 c4 |C...'(......vmp.|Looking for zero patterns, but nothing suspecious showed up
# hexdump -C duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes | grep '00 00 00 00 00 00 00 00'
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
# hexdump -C duplicati-bfcc04033b8f54b61a1c91d24fa04fb17.dblock.zip.aes | grep '00 00 00 00 00 00 00 00'
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
# hexdump -C duplicati-b3ab98cd26a2e469fa0c8262c7b96ff87.dblock.zip.aes | grep '00 00 00 00 00 00 00 00'
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
0503fd80 00 00 00 00 00 00 00 00 00 00 00 8b 7e 30 3b f0 |............~0;.|