Failed: Invalid header marker

herbert · November 18, 2019, 12:06pm

@ts678
Thanks for everything, I decided to try everything you mentioned to figure this out. But because I lost a little track of what I did, or did not do I created an article which summarizes my steps

https://www.feutl.com/blog/duplicati-issue-failed-invalid-header-marker

Anyhow, I started to generate the “extended” logs first to see what they can reveal. This gonna take some days to figure things out, but if you have any advice not said yet, let me know I add it to my list.

I keep you updated.

ts678 · November 18, 2019, 10:20pm

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

EDIT Changed forum source to use triple instead of single backticks to keep command backticks visible.

which is the same plan – the header must be correct or you’ll hear. If you get a bad header, what was it?

herbert · November 19, 2019, 9:08am

I am going to test the find statement as one of the next things, but first this is the output of my last backup. I removed some lines because they were just repeated with other dblocks or dlists
Both files throwing the error still exist on the system.

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

herbert · November 19, 2019, 9:15am

This throws an error and because I am not fully understanding what this script does, I cannot fix it on my own

bash: -c: Zeile 0: conditional binary operator expected
bash: -c: Zeile 0: Syntaxfehler beim unerwarteten Wort `-plain'
bash: -c: Zeile 0: `[[ xxd -plain -l 5 ./duplicati-b02ac2b3df2ab426ea03948e12f2ccb15.dblock.zip.aes == 4145530200 ]]'
./duplicati-b02ac2b3df2ab426ea03948e12f2ccb15.dblock.zip.aes

ts678 · November 19, 2019, 1:05pm

Sorry. Forum software ate some backticks that were supposed to be around the xxd portion of the line.
You can cut-and-paste the fixed version, and see if it does better. Here’s the general plan of the script:

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

Even though we didn’t get a file audit, we now have one bad file actually named in the post just earlier.

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

herbert · November 21, 2019, 8:24am

Seems there are only 3 files with a broken header - which is good, but still no clue why.
Also those files are quite old, the most properly hold information which gut de-duplicated, and did not get deleted therefor.
Anyhow, is there a way to resolve the issue somehow, after we have found the bad ones

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

ts678 · November 21, 2019, 1:16pm

Is 250 MB the right remote volume size for what you had configured back then (the default is 50 MB)?

On those bad files, you’ve clearly got large runs of NUL (00) characters where the header ought to be. Checking for others might find other runs, which I think would be very unexpected on an encrypted file.
Instead of piping to head try pipe to grep '00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00'

Adding and checking Advanced option –upload-verification-file can upload a duplicati-verification.json
How to verify duplicati-verification.json? shows how to do a more thorough file verification of expected sha256 hash and file length versus what’s actually found. If you don’t have Python, you can try testing by finding the filename (the three known bad ones at least) in that file, then doing sha256sum on them.

Try a good file too to check that the procedure is working right. The idea is that mismatch suggests the problem was on upload or during storage, while match suggests file was bad at an earlier process time. Running the verification script will do a better job of this same theory, so hopefully you do have Python.

To find out which files from the backup a broken dblock file affects, you can use the affected command, probably most easily run from Commandline by replacing the source paths with those dblock filenames.

herbert · November 21, 2019, 2:53pm

Yes this is the right size of the file before I changed to 50MB

I do not really get which command I should use with grep, especially if I need to check all my files, I would need to run that in a loop. So perhaps you can get a little more detailed.

I switched on the parameter right now, the backup got started. Just needs some time to finish

I am able to use python and/or install everything on the destination I need. It is a system owned by me, so this should be fine.

# mono /opt/duplicati/Duplicati.CommandLine.exe affected "ssh://xxx" /share/Nextcloud/duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes --dbpath=/data/Duplicati/66858766816685668781.sqlite
No files are affected
Found 0 related log messages (use --full-result to see the data)

# mono /opt/duplicati/Duplicati.CommandLine.exe affected "ssh://xxx" /share/Nextcloud/duplicati-bfcc04033b8f54b61a1c91d24fa04fb17.dblock.zip.aes --dbpath=/data/Duplicati/66858766816685668781.sqlite
No files are affected
Found 0 related log messages (use --full-result to see the data)

# mono /opt/duplicati/Duplicati.CommandLine.exe affected "ssh://xxx" /share/Nextcloud/duplicati-b3ab98cd26a2e469fa0c8262c7b96ff87.dblock.zip.aes --dbpath=/data/Duplicati/66858766816685668781.sqlite

No files are affected
Found 0 related log messages (use --full-result to see the data)

Edit: Added the results of the affected command.

ts678 · November 21, 2019, 3:21pm

on the three known broken files becomes

hexdump -C duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes | grep '00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00'

and you look to see if there are several runs of those NULs. Repeated lines of the same data show as *, however just searching for that might find repetitions of something else (which would be informative too).

If you have man pages installed, just type man hexdump if that’s easier than following the link I provided.

This is a closer look at files you already identified.

The find command is the loop in the original test. The left side does search, and right side does action. You could probably adapt it to scan for runs of NULs if you wanted, but my plan was a study, not survey. Survey would be done using the verification file. If need be, we can invent another survey, but let’s wait.

What will take time is the duplicati-verification.json run, as it needs to read all of the files The good part about that is it’s very thorough, and will even find things like unreadable files due to low-level problems.

The affected command should be faster because it just looks in the database info. Duplicati has to keep track of what dblock files have pieces of what source files in order to do restore, so this test just looks in the other direction, starting with a dblock file, and then looking to see what source files have blocks in it.

Disaster Recovery has a lab example of recovery from intentionally corrupting a backup. Some of that’s possibly applicable after you find how much was affected and whether it’s important or not so important.

How the backup process works
How the restore process works
can give some background info.

herbert · November 22, 2019, 7:46am

In my previous post I have added the outcome of the affected command on the identified files.
I also have run the grep command searching for the zero patterns but nothing really suspicious was shown. I also made the pattern a little shorter, in the hope to find a little more information.

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

Right now I am running the python script to verify the created json file from the last backup. I must assume this is going to take a while

herbert · November 27, 2019, 7:55am

@ts678
The verification script is still processing files
What I figured out is, that I am not sure if the file writes a log file afterwards, as far as I am able to understand the pyhton script it does not. It just summarizes, at the end, that there was an error or not.

Is this correct, because if this is correct, I most properly need to restart that whole thing. I started the script with screen but the stdout is limit with the buffer of screen. I am not thought about this until today
Next time I start this with at least screen -L to get the output logged into a file.

ts678 · November 27, 2019, 12:59pm

It looks like a file that’s damaged (compared to Duplicati’s record) is printed right after its filename.

github.com

duplicati/duplicati/blob/d071d1b4da0b5dc176de7d61900e7ee9f9153633/Tools/Verification/DuplicatiVerify.py#L54-L60


print "Verifying file ", filename

hashalg = sha256()

for b in bytes_from_file(fullpath):

    hashalg.update(b)

hashval =  base64.b64encode(hashalg.digest())

if hashval != hash:

    print "*** Hash check failed for file: ", fullpath

Looking at some other print statements in there (which possibly you care about), perhaps the best plan to make sure you miss nothing is to write to a log file, look for items of interest, and see if you found all.

grep -v 'Verifying file' on the log file would filter out that line which is probably most of the lines.

herbert · December 3, 2019, 6:52pm

Well, after quite some time the job is finished, took quite some time and I could not pause the backups during this time. I restarted the process again, because the screen buffer was not big enough.
So what I found is most properly just a small piece of everything, but this time screen logs everything in a file thanks to screen -L

Anyhow, this is what I found the last time the command finished

File missing:  /mnt/backup/nextcloud-data/duplicati-bbea7096a37924c578bc791eccd6e4f7f.dblock.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-i98ccd558cee3454793f453ca4d5badb7.dindex.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-b7e0ac38039a94e59a9013f9ff6a45169.dblock.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-i36f5e8ebfd10416683c67414dd8b9efa.dindex.zip.aes 

File missing:  /mnt/backup/nextcloud-data/duplicati-bfb45bb5c518742b792347d010ac8774a.dblock.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-i01e28b337aac4d8b965a5800a5fe19bd.dindex.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-b9e7b84bdcc46428ea9c88b1fd89d6cd3.dblock.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-i94358d9b516c42b79dee052ba239e7d7.dindex.zip.aes  

File missing:  /mnt/backup/nextcloud-data/duplicati-ba4aece6f8f7345539d318f7f32d6f85c.dblock.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-i81793d1a6b5c4099903d7673436976a3.dindex.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-b651dfc7aedd04c049886b59f987f47f7.dblock.zip.aes                                           
File missing:  /mnt/backup/nextcloud-data/duplicati-ib4b35e35b8bd4a4396516579cced061d.dindex.zip.aes

But I assume this are the files which got removed by the backups happening during this time.

ts678 · December 3, 2019, 8:04pm

The good news on your full verification is it didn’t find much. The bad news is: what about bad files?
Are those three previously bad files still hanging around, bad, and listed in duplicati-verification.json, possibly meaning that Duplicati put up some bad files? Sometimes people have wondered whether something like /tmp filling up could cause that, but I don’t think anybody has had a reliable test case.

Running true command line commands needs some extra work to get all the options that may apply.
Using the Command line tools from within the Graphical User Interface and adjusting is a safer way.
Export As Command-line is a way to export all the options you need for use on a true command line.
Basically, I’m not sure the empty result from the affected command is really right. It seems unlikely.

herbert · December 4, 2019, 7:50am

I did not know this option exists. This is the thing with software and it enormous potential and options. Thanks
I am running the affected command again from the GUI. This all is going to take some time, THANKS.

herbert · December 14, 2019, 8:18pm

@ts678
I am looking forward to what is next

*** Hash check failed for file:  /mnt/backup/nextcloud-data/duplicati-b3ab98cd26a2e469fa0c8262c7b96ff87.dblock.zip.aes
*** Hash check failed for file:  /mnt/backup/nextcloud-data/duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes
*** Hash check failed for file:  /mnt/backup/nextcloud-data/duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes
*** Hash check failed for file:  /mnt/backup/nextcloud-data/duplicati-bfcc04033b8f54b61a1c91d24fa04fb17.dblock.zip.aes

I hope I got all of them, this whole thing took ages.
I decided, besides going on with this investigation, to split this backup into smaller parts instead of having one big 2TB backup

ts678 · December 14, 2019, 9:10pm

Is the time stamp of duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes recent, meaning it didn’t exist for the previous search for files with long runs of NUL characters? Can you hexdump, and if there isn’t such a run, what does the start of the file look like in hexdump? Expected first 5 bytes above.

What are the lengths of the 4 files? Sometimes a length that’s too binary-even might be from filesystem. Alternatively, previous throttling might have done some damage, although the NUL runs look different…

Regardless, damaged dblock files mean some data is gone, and I’m glad it looks like there were only 4 files. Inventory of files that are going to be corrupted shows how to use the affected command linked earlier to figure out what source files those damaged dblock files would impact. The easiest way to run the command is probably in web UI Commandline, changing Command dropdown at top to affected, and replacing the Commandline arguments box with the simple filename (no path prefix) of the dblock. You can try one first, or put all four in at once on different lines. Then go to the bottom to run command. You can look over the results to see whether or not the files that used the damaged dblock were critical.

There are a lot of ways that things could go depending on what shows up, ranging from trying recovery methods to starting over again, which is often the easiest thing, but has some definite drawbacks to it…

Ideally we’d also work out what went wrong sometime to cause 4 possibly damaged files on destination.

herbert · December 18, 2019, 1:16pm

The timestamp for duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes is:

 ls -la duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes
-rwxrwx--- 1 backup backup 262060045 Aug  5  2018 duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes

The hexdump of the above mentioned file:

hexdump -C duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.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 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  |................|
*
000000a0  00 00 00 00 00 00 00 00  00 00 00 00 35 74 05 c9  |............5t..|
000000b0  7d 96 98 60 e8 83 c6 73  c7 1c 67 0c eb 6c fa 18  |}..`...s..g..l..|
000000c0  6a fb 03 93 87 f5 1c 78  e5 b5 2a 95 a4 88 a0 4a  |j......x..*....J|
000000d0  23 c0 d6 d6 74 63 af a8  ac 11 4d 22 04 ca 0a 96  |#...tc....M"....|
000000e0  98 24 d5 1f 88 bc 61 9f  bf ca c5 53 8c 28 22 e6  |.$....a....S.(".|


hexdump -C duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes | grep '00 00 00 00 00 00 00 00'
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 35 74 05 c9  |............5t..|
04d00000  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|

For me it would be interesting to figure out why this happened and fix the error, even if this means I do lose some data, but the backup should finish successfully at the end and be consistent again Which it is not - right now.
Is there a way to remove that blocks to get a consistent backup set again, because this would fix everything, and I assume not only for me

I already started to split this big backup set into multiple smaller ones to avoid the impact for this problem in the future. If this happens again, it will only affect a smaller part of this 2TB backup
Those smaller backups already went through its first few rounds, so my actual data is saved.

ts678 · December 18, 2019, 2:34pm

So duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes looks like a 2018 file that passed the first scan for NUL rows, but now has a few, and also a bad hash? The header at least looks right though.

If the above is true, maybe the file grew an error somehow. You can check time stamps further, e.g. both ls -l and ls -lc for hints that a program changed it. If not, does QNAP have the smartctl command to check how healthy your drives look, or other metrics? A NAS often has redundancy, but does it log when such redundancy actually has to be used? Linux systems may also log I/O problems to the system logs.

The affected command run as mentioned earlier should be able to tell you the losses of deleted dblocks, and Disaster Recovery as mentioned earlier gives steps for recovery from removal. I suggest you move the dblocks to a different folder just in case something goes wrong and we wind up wanting them again, although the three with the bad header are probably lost. If you like, try manual decrypt and unzip of the one with the good header but bad hash (and small run of NULs) to see whether there’s anything left of it. You can run SharpAESCrypt under mono from the Duplicati install folder. Help text for that is found here. AES Crypt is another option, but you might have to move the bad file to some other system to decrypt it.

herbert · December 19, 2019, 9:55am

Well, I ran the command from the previous post again, just to verify Invalid header markers again. Nothing changed, so the new file which popped up using the verification process (duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes) does not have an invalid header, and was therefor not caught previously.

# ls -l duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes
-rwxrwx--- 1 backup backup 262060045 Aug  5  2018 duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes
# ls -lc duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes
-rwxrwx--- 1 backup backup 262060045 Nov 22  2018 duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes

SmartCTL is not an option on that setup, the Raspi hosting the USB disk does not support S.M.A.R.T. information for that disks/usb controller. I try to figure something out for this situation, because this is for sure not optimal. Anyhow, if the disk would start failing, why is the data all from 2018 and one file per month. Disks failing would be more random, so I must conclude this is not the reason. And I am doing backups every day, not on a “monthly” basis.

# ls -l /mnt/backup/nextcloud-data/duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes
-rwxrwx--- 1 backup backup 262060045 Aug  5  2018 /mnt/backup/nextcloud-data/duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes
# ls -l /mnt/backup/nextcloud-data/duplicati-bfcc04033b8f54b61a1c91d24fa04fb17.dblock.zip.aes
-rwxrwx--- 1 backup backup 261810285 Sep 13  2018 /mnt/backup/nextcloud-data/duplicati-bfcc04033b8f54b61a1c91d24fa04fb17.dblock.zip.aes
# ls -l /mnt/backup/nextcloud-data/duplicati-b3ab98cd26a2e469fa0c8262c7b96ff87.dblock.zip.aes
-rwxrwx--- 1 backup backup 261920237 Okt  3  2018 /mnt/backup/nextcloud-data/duplicati-b3ab98cd26a2e469fa0c8262c7b96ff87.dblock.zip.aes
# ls -l /mnt/backup/nextcloud-data/duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes
-rwxrwx--- 1 backup backup 261947757 Nov  7  2018 /mnt/backup/nextcloud-data/duplicati-bd742daac0957402f81e85c35a5be6662.dblock.zip.aes

The affected command for duplicati-bd2d9bf5f4fa54ee4a3d280718c7c8aed.dblock.zip.aes showed three files are affected, two videos and a picture. All three files still exist in their source location and are not corrupt and therefor functional.

Right now I am downloading the 4 files which we have identified during this process to test if they can still be decrytped manually.

Also one thing, which came into my mind, I used “Smart Backup retention” during this time period. This would also explain the why those files are roughly a month apart. I switched away from the “Smart Backup retention” because I have not fully understood how it merges data after some time and a 6 month backup retention is actually ok for my use case.