Duplicati Issue "Failed: Invalid header marker"

technology english backup duplicati

Duplicati 2.0 - Free backup software to store encrypted backups online

Work in Progress - Last Update: 03.12.2019

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.

I still think, it has something to do with the retention period and is perhaps connected with me changing the "Remote Volume Size" some month ago. But I have no proper evidence for this conclusion. The only thing I know, if I turn of the retention policy, the error disapears.

There is a discussion on the duplicati forum which is the reason I am creating this article to keep an overview.

Issue 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 

Setup Overview

This is a summary of the setup I am running right now. I removed all sensitive data.

  • Duplicati runs as a docker container
    • Image: duplicati/duplicati:canary from DockerHub
    • Volume mapping:
      • /data > /share/Container/data/duplicati (RW)
      • /share/Nextcloud/ > /share/Nextcloud (RO)
      • Network: bound to a network interface with a statically configured IP and MAC
      • Duplicati Version: 2.0.4.34_canary_2019-11-05
  • Schedule: daily at 10 pm
    • Backup takes around 4 to 5 hours, therefor ends on the next day in the morning.
  • Size: around 2TB
  • Encryption: AES-256, built in
  • Destination: remote machine via SSH with user authentication
  • Source: locally mounted into the docker container
    • There are some filters to exclude files and folders being configured
  • Optiones
    • Remote volume size 50MB
    • Backup retention: 6 Months
    • aes-set-threadlevel: 2
    • backup-test-samples: 5
    • blocksize:500 KBytes
    • disable-files-scanner: yes

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*/"

Notes

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.

  • Remote Volume Size of 50MB since 25.03.2019
  • Remote Volume Size of 250MB since 22.06.2018 - this is the last dblock file I have on my system by 18.11.2019

Steps taken to resolve the issue

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.

Turn of backup retention

This approach is still investigated, but is set to 6M again due to log file generation

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.

Summary

After xx days, the backup has still not generated the error. This let me conclude that the error is generated while deleting old backups. Therefor the backup itself is working, but not the deletion of old data based on the retention time.

Restart Duplicati / Restart the Backup job manually

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.

Summary

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.

Throtteling

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)

Summary

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.

Looking into the SQLite database

This approach was not tested yet

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).

Check the size of the corrupted file

The verification file was created and verification is in progress

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.

Summary

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.

Extend logging information

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).

Summary

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

  • -rwxrwx--- 1 250M Nov 7 2018 duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes
  • -rwxrwx--- 1 250M Jul 12 2018 duplicati-bd743e3577a764e6eabba37e83ec36cac.dblock.zip.aes
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 

Testing restore

This approach was not tested yet

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?

At what point do they fail?

This approach was not tested yet

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 show CompactResults from compact run if it did run. RetryAttempts being 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.

Verify if the AES file header is correct

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 4145530200 which 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 | head

For 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.

Summary

This are the files, based on the above command:

  • ./nextcloud-data/duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes
    • Date: 07.11.2018
    • Size: 250MB
  • ./nextcloud-data/duplicati-bfcc04033b8f54b61a1c91d24fa04fb17.dblock.zip.aes
    • Date: 13.09.2018
    • Size: 250MB
  • ./nextcloud-data/duplicati-b3ab98cd26a2e469fa0c8262c7b96ff87.dblock.zip.aes
    • Date: 03.10.2018
    • Size: 250MB

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;.|

Previous Post