How to fix please verify the sha256 hash?

Support
1

I’ve noticed some warnings of one of my backups. See this piece of log:

LimitedMessages: [
    2022-01-07 23:12:29 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2022-01-07 23:12:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2022-01-07 23:12:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (824 bytes),
    2022-01-07 23:13:36 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b0e98b0ba5e8a4eb29f2adfe18b6cc320.dblock.zip.aes (499.99 MB),
    2022-01-07 23:16:43 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b0e98b0ba5e8a4eb29f2adfe18b6cc320.dblock.zip.aes (499.99 MB),
    2022-01-07 23:16:43 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc6f58e5d2e694e8c9fc2196362c3853f.dblock.zip.aes (499.99 MB),
    2022-01-07 23:16:43 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i5dc336fc045b476b9378428e4edf7007.dindex.zip.aes (272.01 KB),
    2022-01-07 23:16:43 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i5dc336fc045b476b9378428e4edf7007.dindex.zip.aes (272.01 KB),
    2022-01-07 23:19:40 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc6f58e5d2e694e8c9fc2196362c3853f.dblock.zip.aes (499.99 MB),
    2022-01-07 23:19:41 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-if5e49b5106d24166b13420d87582df92.dindex.zip.aes (372.20 KB),
...
]
LimitedWarnings: [
    2022-01-07 23:12:33 +01 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes is listed as Uploaded with size 461373440 but should be 524281805, please verify the sha256 hash "Q2zTgbSYAlxSYK22lDWPR6JvKRLioW/HFks5rO4o7TQ=",
    2022-01-08 01:09:46 +01 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes is listed as Uploaded with size 461373440 but should be 524281805, please verify the sha256 hash "Q2zTgbSYAlxSYK22lDWPR6JvKRLioW/HFks5rO4o7TQ="
]
LimitedErrors: []
Log data:
2022-01-07 23:12:33 +01 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes is listed as Uploaded with size 461373440 but should be 524281805, please verify the sha256 hash "Q2zTgbSYAlxSYK22lDWPR6JvKRLioW/HFks5rO4o7TQ="
2022-01-08 01:09:46 +01 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes is listed as Uploaded with size 461373440 but should be 524281805, please verify the sha256 hash "Q2zTgbSYAlxSYK22lDWPR6JvKRLioW/HFks5rO4o7TQ="

Allright something is wrong, so how to fix?
Restarting the backup → same error
Verify files → same error
Purge broken files → same error
Repair-> other error:

MainOperation: Repair
ParsedResult: Error
Version: 2.0.6.3 (2.0.6.3_beta_2021-06-17)
EndTime: 1/8/2022 5:31:08 PM (1641659468)
BeginTime: 1/8/2022 5:20:08 PM (1641658808)
Duration: 00:11:00.5223560
MessagesActualLength: 13
WarningsActualLength: 1
ErrorsActualLength: 1
LimitedMessages: [
    2022-01-08 17:20:08 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
    2022-01-08 17:20:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2022-01-08 17:20:09 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (897 bytes),
    2022-01-08 17:20:09 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes (),
    2022-01-08 17:22:13 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes (),
    2022-01-08 17:22:23 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes (),
    2022-01-08 17:24:27 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes (),
    2022-01-08 17:24:37 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes (),
    2022-01-08 17:26:41 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes (),
    2022-01-08 17:26:51 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes (),
...
]
LimitedWarnings: [
    2022-01-08 17:20:09 +01 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes is listed as Uploaded with size 461373440 but should be 524281805, please verify the sha256 hash "Q2zTgbSYAlxSYK22lDWPR6JvKRLioW/HFks5rO4o7TQ="
]
LimitedErrors: [
    2022-01-08 17:31:08 +01 - [Error-Duplicati.Library.Main.Operation.RepairHandler-RemoteFileVerificationError]: Failed to perform verification for file: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes, please run verify; message: File length is invalid
]
Log data:
2022-01-08 17:20:09 +01 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes is listed as Uploaded with size 461373440 but should be 524281805, please verify the sha256 hash "Q2zTgbSYAlxSYK22lDWPR6JvKRLioW/HFks5rO4o7TQ="
2022-01-08 17:31:08 +01 - [Error-Duplicati.Library.Main.Operation.RepairHandler-RemoteFileVerificationError]: Failed to perform verification for file: duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes, please run verify; message: File length is invalid
System.Security.Cryptography.CryptographicException: File length is invalid ---> System.IO.InvalidDataException: File length is invalid
  at SharpAESCrypt.SharpAESCrypt.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 count) [0x0032b] in <45c43198e80545aeabaa9b98839b4c7d>:0 
  at Duplicati.Library.Utility.Utility.CopyStream (System.IO.Stream source, System.IO.Stream target, System.Boolean tryRewindSource, System.Byte[] buf) [0x0003d] in <2a3ee711c7c04f6c957360f2cf183a7f>:0 
  at Duplicati.Library.Encryption.EncryptionBase.Decrypt (System.IO.Stream input, System.IO.Stream output) [0x00008] in <ecdfcb55bc4741b99f194bd4ca137df6>:0 
  at Duplicati.Library.Main.BackendManager+<>c__DisplayClass32_0.<coreDoGetPiping>b__0 () [0x00029] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at System.Threading.Tasks.Task.InnerInvoke () [0x0000f] in <254335e8c4aa42e3923a8ba0d5ce8650>:0 
  at System.Threading.Tasks.Task.Execute () [0x00000] in <254335e8c4aa42e3923a8ba0d5ce8650>:0 
   --- End of inner exception stack trace ---
  at Duplicati.Library.Main.BackendManager+FileEntryItem.Duplicati.Library.Main.BackendManager.IDownloadWaitHandle.Wait (System.String& hash, System.Int64& size) [0x0000e] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.BackendManager.GetWithInfo (System.String remotename, System.Int64& size, System.String& hash) [0x00045] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.RepairHandler.RunRepairRemote () [0x002eb] in <e60bc008dd1b454d861cfacbdd3760b9>:0

So, I’m not at a loss: how can I recover from this error? I did read something about manually removing the file but why can Duplicati not recover from this?

2

Hi @mattie and welcome to the forums.

I’m surprised purge broken files didn’t fix it but judging by the retries in your repair log you may have a connectivity issue to the destination or the destination has an issue, which would also explain why you got the hash error in the first place.

What is the remote destination and how long was it working for prior to this error?

3

Hi @JimboJones thank you! Really love using Duplicati it’s a great tool!

The destination is a (mounted) samba share over a VPN connection. So yes it might definably be possible there are connectivity issues. However I have 4 backup jobs to this remote samba endpoint and all are working fine. It also seem to run fine (the backup last night did upload the latest files without problem). So I guess it had a connectivity issue at some point but not at this moment? This happens to be a relatively new job that was only set up for 2 weeks, the other jobs have been running for months. This job backups large video files so it will run longer and might make it prone for network issues.

But just to confirm: does Duplicati recover automatically or do I need to trigger something manually?

4

Although I don’t think it’s documented, list-broken-files and purge-broken-files seem to need a file to actually be missing in order to conclude it’s “bad”. I can understand Duplicati not downloading an entire backup (too slow) for such an operation, but something like wrong size seems like it would be an easy sign of a bad file.

Speaking of size, 461373440 happens to be a nice even binary size of hexadecimal 1B800000 which to me suggest some sort of filesystem failure. Unfortunately, SMB seems to be particularly prone to these issues. Duplicati uses the operating system’s SMB. What OS is this? Linux also has some kernel bugs in its SMB.

Regardless, one can delete or hide bad file (move to another folder, or rename without duplicati- prefix).
Recovering by purging files is the rest, but it’s manual. One could check the timestamp on the bad file to try seeing if there’s anything special about it relative to the whole backup. Did one file in its middle just go bad?

For serious debug, one needs to set up extra logs, e.g. log-file=<path> and log-file-log-level=retry are good when there is a possible issue with destination file uploads. One can also look at the remote directory list attempting to see when the wrong-size file first got its wrong size. Was it at end of backup that uploaded it? Alternatively, did its size change later (somehow)? Job → Show log → Remote should have all the list data, however flipping though it is slow, and browsing the database or database bug report is technical but easier.

5

Allright, I will try to answer all your questions :slight_smile:

The file indeed is not missing, it does exists on the (remote) filesystem. I can also confirm it is 461.373.440 bytes (as reported by Windows).

The OS running Duplicati is kind of a hard question haha. I use this docker container Docker (Duplicati - 2.0.6.3_beta_2021-06-17)
That container runs on Unraid, and that OS handles the smb mount.
//xx.xx.xx.xx/mattie on /mnt/remotes/disk_at_remote type cifs (rw)

Just to confirm what Duplicati thinks of the OS:

APIVersion : 1
PasswordPlaceholder : **********
ServerVersion : 2.0.6.3
ServerVersionName : - 2.0.6.3_beta_2021-06-17
ServerVersionType : Beta
StartedBy : Server
BaseVersionName : 2.0.6.3_beta_2021-06-17
DefaultUpdateChannel : Beta
DefaultUsageReportLevel : Information
ServerTime : 2022-01-09T19:42:28.799153+01:00
OSType : Linux
DirectorySeparator : /
PathSeparator : :
CaseSensitiveFilesystem : true
MonoVersion : 5.20.1.34
MachineName : 3ab64c154307
UserName : abc
NewLine :
CLRVersion : 4.0.30319.42000
CLROSInfo : {"Platform":"Unix","ServicePack":"","Version":"5.10.28.0","VersionString":"Unix 5.10.28.0"}
ServerModules : []
UsingAlternateUpdateURLs : false
LogLevels : ["ExplicitOnly","Profiling","Verbose","Retry","Information","DryRun","Warning","Error"]
SuppressDonationMessages : true
SpecialFolders : [{"ID":"%MY_DOCUMENTS%","Path":"/config"},{"ID":"%HOME%","Path":"/config"}]
BrowserLocale : {"Code":"nl-NL","EnglishName":"Dutch (Netherlands)","DisplayName":"Nederlands (Nederland)"}
SupportedLocales : [{"Code":"bn","EnglishName":"Bangla","DisplayName":"বাংলা"},{"Code":"ca","EnglishName":"Catalan","DisplayName":"català"},{"Code":"cs","EnglishName":"Czech","DisplayName":"čeština"},{"Code":"da","EnglishName":"Danish","DisplayName":"dansk"},{"Code":"de","EnglishName":"German","DisplayName":"Deutsch"},{"Code":"en","EnglishName":"English","DisplayName":"English"},{"Code":"en-GB","EnglishName":"English (United Kingdom)","DisplayName":"English (United Kingdom)"},{"Code":"es","EnglishName":"Spanish","DisplayName":"español"},{"Code":"fi","EnglishName":"Finnish","DisplayName":"suomi"},{"Code":"fr","EnglishName":"French","DisplayName":"français"},{"Code":"fr-CA","EnglishName":"French (Canada)","DisplayName":"français (Canada)"},{"Code":"hu","EnglishName":"Hungarian","DisplayName":"magyar"},{"Code":"it","EnglishName":"Italian","DisplayName":"italiano"},{"Code":"ja-JP","EnglishName":"Japanese (Japan)","DisplayName":"日本語 (日本)"},{"Code":"ko","EnglishName":"Korean","DisplayName":"한국어"},{"Code":"lt","EnglishName":"Lithuanian","DisplayName":"lietuvių"},{"Code":"lv","EnglishName":"Latvian","DisplayName":"latviešu"},{"Code":"nl-NL","EnglishName":"Dutch (Netherlands)","DisplayName":"Nederlands (Nederland)"},{"Code":"pl","EnglishName":"Polish","DisplayName":"polski"},{"Code":"pt","EnglishName":"Portuguese","DisplayName":"português"},{"Code":"pt-BR","EnglishName":"Portuguese (Brazil)","DisplayName":"português (Brasil)"},{"Code":"ro","EnglishName":"Romanian","DisplayName":"română"},{"Code":"ru","EnglishName":"Russian","DisplayName":"русский"},{"Code":"sk","EnglishName":"Slovak","DisplayName":"slovenčina"},{"Code":"sk-SK","EnglishName":"Slovak (Slovakia)","DisplayName":"slovenčina (Slovensko)"},{"Code":"sv-SE","EnglishName":"Swedish (Sweden)","DisplayName":"svenska (Sverige)"},{"Code":"th","EnglishName":"Thai","DisplayName":"ไทย"},{"Code":"zh-CN","EnglishName":"Chinese (Simplified)","DisplayName":"中文 (中国)"},{"Code":"zh-HK","EnglishName":"Chinese (Traditional, Hong Kong SAR China)","DisplayName":"中文 (中国香港特别行政区)"},{"Code":"zh-TW","EnglishName":"Chinese (Traditional)","DisplayName":"中文 (台湾)"}]
BrowserLocaleSupported : true
backendgroups : {"std":{"ftp":null,"ssh":null,"webdav":null,"openstack":"OpenStack Object Storage / Swift","s3":"S3 Compatible","aftp":"FTP (Alternative)"},"local":{"file":null},"prop":{"s3":null,"azure":null,"googledrive":null,"onedrive":null,"onedrivev2":null,"sharepoint":null,"msgroup":null,"cloudfiles":null,"gcs":null,"openstack":null,"hubic":null,"b2":null,"mega":null,"box":null,"od4b":null,"mssp":null,"dropbox":null,"sia":null,"tardigrade":null,"jottacloud":null,"rclone":null,"cos":null}}
GroupTypes : ["Local storage","Standard protocols","Proprietary","Others"]
Backend modules: aftp azure b2 box cloudfiles dropbox ftp file googledrive gcs hubic jottacloud mega msgroup onedrivev2 sharepoint openstack rclone s3 ssh od4b mssp sia tahoe tardigrade cos webdav
Compression modules: zip 7z
Encryption modules: aes gpg

So yes, it might be connectivity, might be Linux kernel but I run Duplicati for quite some time and this did not happen before.

Where is the file located in the backup?

image
image877×325 16.2 KB

Extra logs

Do you want me to run the backup now with the extra logs enabled? I can do that if that is usefull (will take some time).

edit: I will do this tomorrow, tonight it will do a backup and if I do it tomorrow morning than it won’t have any new files saving resulting in a smaller log (I hope)

One can also look at the remote directory list attempting to see when the wrong-size file first got its wrong size.

Can you elaborate?

Was it at end of backup that uploaded it?

See screenshot above (in the middle)

Alternatively, did its size change later (somehow)? Job → Show log → Remote should have all the list data,

In case it might be useful here is the entire log for the backup operation that created this (wrong sized) file

{
  "DeletedFiles": 0,
  "DeletedFolders": 0,
  "ModifiedFiles": 0,
  "ExaminedFiles": 22,
  "OpenedFiles": 5,
  "AddedFiles": 5,
  "SizeOfModifiedFiles": 0,
  "SizeOfAddedFiles": 20020775436,
  "SizeOfExaminedFiles": 159805342725,
  "SizeOfOpenedFiles": 20020775436,
  "NotProcessedFiles": 0,
  "AddedFolders": 1,
  "TooLargeFiles": 0,
  "FilesWithError": 0,
  "ModifiedFolders": 0,
  "ModifiedSymlinks": 0,
  "AddedSymlinks": 0,
  "DeletedSymlinks": 0,
  "PartialBackup": false,
  "Dryrun": false,
  "MainOperation": "Backup",
  "CompactResults": null,
  "VacuumResults": null,
  "DeleteResults": null,
  "RepairResults": null,
  "TestResults": {
    "MainOperation": "Test",
    "VerificationsActualLength": 3,
    "Verifications": [
      {
        "Key": "duplicati-20220106T221131Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-ie7ff908629584c839ac0deba2cb6f09f.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-b99915886b0ba403492088859b794a354.dblock.zip.aes",
        "Value": []
      }
    ],
    "ParsedResult": "Success",
    "Version": "2.0.6.3 (2.0.6.3_beta_2021-06-17)",
    "EndTime": "2022-01-07T00:10:23.545799Z",
    "BeginTime": "2022-01-07T00:08:01.25963Z",
    "Duration": "00:02:22.2861690",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 84,
      "BytesUploaded": 20074982963,
      "BytesDownloaded": 524683143,
      "FilesUploaded": 79,
      "FilesDownloaded": 3,
      "FilesDeleted": 0,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 625,
      "KnownFileSize": 160097615776,
      "LastBackupDate": "2022-01-06T23:11:31+01:00",
      "BackupListCount": 7,
      "TotalQuotaSpace": 2000396742656,
      "FreeQuotaSpace": 819763777536,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.6.3 (2.0.6.3_beta_2021-06-17)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2022-01-06T22:11:31.885223Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "ParsedResult": "Warning",
  "Version": "2.0.6.3 (2.0.6.3_beta_2021-06-17)",
  "EndTime": "2022-01-07T00:10:23.604208Z",
  "BeginTime": "2022-01-06T22:11:31.88522Z",
  "Duration": "01:58:51.7189880",
  "MessagesActualLength": 169,
  "WarningsActualLength": 1,
  "ErrorsActualLength": 0,
  "Messages": [
    "2022-01-06 23:11:31 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2022-01-06 23:11:36 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2022-01-06 23:11:36 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (546 bytes)",
    "2022-01-06 23:12:38 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b3fd2ae43554440c1aa0224aec77ee6e2.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:12:38 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb039a40116fc4a4ebf9898b123449b14.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:16:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b3fd2ae43554440c1aa0224aec77ee6e2.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:16:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ibf93113a602140f29b935266c9850b36.dindex.zip.aes (372.14 KB)",
    "2022-01-06 23:17:49 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb039a40116fc4a4ebf9898b123449b14.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:17:49 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ibf93113a602140f29b935266c9850b36.dindex.zip.aes (372.14 KB)",
    "2022-01-06 23:17:49 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i87857d2c6b134f50ac2157bbeb135f00.dindex.zip.aes (272.01 KB)",
    "2022-01-06 23:17:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i87857d2c6b134f50ac2157bbeb135f00.dindex.zip.aes (272.01 KB)",
    "2022-01-06 23:18:45 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bec696254304141028dc2893c2eb63159.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:18:46 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bafc11226ea7d47a9855e1b1f3d2d6e24.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:22:07 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bec696254304141028dc2893c2eb63159.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:22:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i749393c01fac4ec8be0d8f0e1c8a94ab.dindex.zip.aes (319.67 KB)",
    "2022-01-06 23:23:49 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bafc11226ea7d47a9855e1b1f3d2d6e24.dblock.zip.aes (499.99 MB)",
    "2022-01-06 23:23:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i749393c01fac4ec8be0d8f0e1c8a94ab.dindex.zip.aes (319.67 KB)",
    "2022-01-06 23:23:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i6765cb90cfc54ed190f9b2d28a640f23.dindex.zip.aes (272.00 KB)",
    "2022-01-06 23:23:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i6765cb90cfc54ed190f9b2d28a640f23.dindex.zip.aes (272.00 KB)",
    "2022-01-06 23:24:45 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b206d109fe8b145dc9ce267294a83ec30.dblock.zip.aes (499.99 MB)"
  ],
  "Warnings": [
    "2022-01-07 01:08:01 +01 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes is listed as Uploaded with size 461373440 but should be 524281805, please verify the sha256 hash \"Q2zTgbSYAlxSYK22lDWPR6JvKRLioW/HFks5rO4o7TQ=\""
  ],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 84,
    "BytesUploaded": 20074982963,
    "BytesDownloaded": 524683143,
    "FilesUploaded": 79,
    "FilesDownloaded": 3,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 625,
    "KnownFileSize": 160097615776,
    "LastBackupDate": "2022-01-06T23:11:31+01:00",
    "BackupListCount": 7,
    "TotalQuotaSpace": 2000396742656,
    "FreeQuotaSpace": 819763777536,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Backup",
    "ParsedResult": "Success",
    "Version": "2.0.6.3 (2.0.6.3_beta_2021-06-17)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2022-01-06T22:11:31.885223Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}

SQLite database

So what would you like to see from this database? The data from RemoteOperation ?

Bugreport

This is ~440mb: https://home.mattie-systems.nl/temp/bugreport.zip
Or if you want this some other way please let me know.

6

This is most useful in preparation for next failure. Log can’t log history, but the database has some history, some of which is found in the GUI. Your 2022-01-07 01:08:01 +01 warning is from the list getting this:

{“Name”:“duplicati-bd293bcb44f2a4d2a8b11952894b47da0.dblock.zip.aes”,“LastAccess”:“2022-01-07T00:21:12.569017+01:00”,“LastModification”:“2022-01-07T00:17:54.388728+01:00”,“Size”:461373440,“IsFolder”:false},

and the short file upload looks from DB and your remote listing like it was right in the middle of the uploads.
Above list would probably be at January 7, 2022 01:07:59 AM if you’d really like to flip pages for it yourself.

On Windows, I’ve previously tried to trace driver-level activity with Sysinternals Process Monitor but it failed badly on the affected systems. The equivalent on Linux is to try to strace, but this is getting pretty low-level, and possibly even harder because on Windows I think the monitor has file offset. I’m not sure if Linux has it

While I would love to find out where the rest of the file got dropped, it may be hard. Network trace is another option but can also be hard. mount.cifs has options (e.g. cache) that might matter, but this is all speculative.

You presumably are telling Duplicati that it’s writing to a folder, and letting OS etc. run the rest of the magic.
Local folder or drive has an option that I’m not sure has been tried, but I don’t know if or why it would help…

--use-move-for-put When storing the file, the standard operation is to copy the file and delete the original. This sequence ensures that the operation can be retried if something goes wrong. Activating this option may cause the retry operation to fail. This option has no effect unless the --disable-streaming-transfers options is activated.

list-verify-uploads might let Duplicati spot short upload sooner. but I don’t know how much that would help.

Export As Command-line URL edited for an empty folder for Duplicati.CommandLine.BackendTester.exe would be one way to exercise SMB further, but if the problem is rare, there’s no telling if testing will hit it…

Possibly SMB is just not going to be reliable enough in all cases even though it apparently works for some.

7

Yeah so I’m not sure if enabling debug log is useful for now. I have a couple of other SMB jobs with no issues. So I think on manually removing the corrupted file, then run purge-missing-files and then run the backup again. That should at least make sure my backup is ok right?

If I do spot this again I can turn on the log but it might not happen for a long time. Ah well I might as wel turn the logging on and see how big the log files are going to be :slight_smile:

8

If it’s purely a bad file, then this should purge the broken parts and get you back in business. I suppose you could also see if the Repair button has anything to say. There is no perfect simple way to check for ok, but
it wouldn’t be a bad idea to sometimes run a Restore, especially a Direct restore from backup files .

I suppose you could look at the short file with hexdump or a better viewer. Format is described here but the data from original file will look like random data, so any goof would have to be major, e.g. a long run of NUL.

9

I recently started testing Duplicati with a mult-GB backup and have several of these file size errors on my system while backing up to a NAS file share. I looked through the source code and found that the FileBackend module uses a simple stream copy with no verification at all. For such an important operation, this seems like a huge oversight by the developer.

I was able to reproduce the issue by unplugging/plugging the network cable during backup. Sometimes this does not cause an issue, sometimes the file size is different, and sometimes the files does not get created at all. There are likely many ways this issue could occur but proving that something as simple as a network interruption can corrupt a backup set is unacceptable.

I am working on adding file size validation to the FileBackend module code that would detect and retry the file creation if the file is missing or the wrong size.

4 Likes
10

Thank you! From time to time I do have this issue. I usually either start over (small backup) or indeed find the file, remove it and then repair. If Duplicati knows the file is bad (or never uploaded correctly) then I think that would be good :slight_smile: Thanks for looking into this!

11

Hi MrWhite,

Just wondering if there has been any update on this. Is there a ticket to track the issue?

12

@Phil_R

This feature seems indeed to have been added to Duplicati:

commit 1cbe2643b14fcf84c5bd34082ff539d9f9b59418
Author: Doug Krahmer <doug.git@remhark.com>
Date:   Fri Mar 18 11:03:23 2022 -0700

    Add file size verification to FileBackend PutAsync()
1 Like
13

2.0.6.103_canary_2022-06-12, three Canary releases ago, and will be in next Beta:

Added check to detect partially written files on network drives, thanks @dkrahmer

1 Like
14

Thank you! I will try installing the latest Canary and see if it resolved the issue for me.

1 Like
15

I have the same message with the version 2.0.7.1_beta_2023-05-25.
My error messages are:

* 2024-03-03 11:16:43 +03 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-i378ef0b0d2ed41c5af7748b8b47d525a.dindex.zip.aes is listed as Verified with size 541 but should be 324157, please verify the sha256 hash "iZbGIp/Jr8h6UXiFtAasqXBWLZ8SiOqSKvnCohblDmI="
* 2024-03-03 11:16:43 +03 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteHash]: remote file duplicati-i5dca542a475d40e5b45088bf3167bdc0.dindex.zip.aes is listed as Verified with size 541 but should be 430541, please verify the sha256 hash "VWNQOFL/o6tPOSErRfgfUvgXmDF4B11SN+YyOqKqzGE="

This files have size 541 bytes.

What should I do? If I delete file I’m affraid of loosing some parts of backups.

16

When? What are you trying to do? What did you actually do?

Do you have easy access to files? If so, what are their dates?

This might be significant, and also say you’re in the wrong topic, but there’s little information yet.
541 byte files can happen if you manage to get just the manifest file without other needed data.

AES Crypt GUI tool or Duplicati SharpAESCrypt.exe CLI tool can decrypt, if you want to unzip it.
Possibly that’s premature, and should wait until after some general information about issue is in.

I’m not suggesting that so soon, but a dindex file does not contain your backup data. It’s an index.
Losing a dindex file can slow down database recreates because dblock files must be read directly.

17

Why? I see such a problem. But if it’s needed I may create a topic with my problem.

I backup my folder every week and every week I see this problem in logs.

I looked at backup folder and see many files with 541 bytes but only for two files I see such messages in log.

If there is no another solution I think this solution (removing) is good and scan two big (200Mb) files is not a such problem. But I’d be appreciated if you can help without it (and BTW I wrote my Powershell script for auto repairing backups and it’d be good if I add automatic solution for that).

18

Because size 541 is very different from topic discussions and the fix. Title alone doesn’t reveal that.
Might as well continue here, at least until things can be isolated a little further. Posts can be moved.

I have 17 and no complaints. Mine are Sep 4, 2023. Recently I’m on 2.0.7.100_canary_2023-12-27.

Fix missing file error caused by interrupted compact, thanks @Jojo-1000 and @warwickmm

The detailed story of my files is in the pull request:

Fix missing file error caused by interrupted compact #4967

After required Repair “replaced” 17 541-byte dindex.zip.aes files to replace those it thought were missing

Is this posted or described? Given that repair can create such files, it’d be good to know what it does.

There are also other unanswered questions, and now I’ll also ask if you’ve tested a Direct restore from backup files sometime after this began? Database recreate is also a good test, but save the current database before that because it has history and because the database recreate can go badly.

Watching About → Show log → Live → Verbose will be useful. You want dlist and dindex downloads, without any dblock downloads, which are (as mentioned) caused by insufficient information in dindex.

19

Sorry, missed this questions. Yes, I have. The date-time is the same for this files: 17.02.2024 23:20.

Also I decrypted this files and their manifest’s content are:

{"Version":2,"Created":"20240217T202026Z","Encoding":"utf8","Blocksize":102400,"BlockHash":"SHA256","FileHash":"SHA256","AppVersion":"2.0.7.1"}
&
{"Version":2,"Created":"20240217T202019Z","Encoding":"utf8","Blocksize":102400,"BlockHash":"SHA256","FileHash":"SHA256","AppVersion":"2.0.7.1"}

I’ll plan do write it after my test and cleaned dependences from my PS library).

I don’t undestand what better to test: full restore or post verbose log from backuping?

20

This doesn’t matter. The important thing is that if only the manifest is there, everything else is missing. There should be a vol folder which shows what’s in the indexed dblock, and maybe a list for speed.

These folders both index the dblock, so in the case of the dblock/dindex delete in interrupted compact, where dblock and dindex are deleted but the record of dindex deletion got lost in the database rollback, Repair tries to replace the missing dindex, but has no dblock known, so it can’t make those two folders.

Your situation may or may not be this. Do you recall getting a missing dindex error, and doing a repair?

This was not suggested. Direct restore from backup files (maybe even a small one) was suggested, and watch the Verbose live log while it’s building the partial temporary database that it needs for the restore.

If you have time and space, you can certainly do a full direct restore to simulate doing disaster recovery. Use a different machine or folder. You don’t want to overwrite your actual system with old restored data.