Message has been altered, do not trust content

Support
1

Dear all,

I use Duplicati on a Docker instance (version 2.0.6.3_beta_2021-06-17) and I experience the “Message has been altered, do not trust content” error from time to time. When this happens, the only workaround I’ve found is to recreate the backup which is basically not the best option.
I’ve seen this issue has already been reported by some users, but I did not see any solution so far. As explained the only one being to recreate the backup.

Here are the log content :

Failed: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
Details: System.Security.Cryptography.CryptographicException: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content ---> SharpAESCrypt.SharpAESCrypt+HashMismatchException: Message has been altered, do not trust content
 at SharpAESCrypt.SharpAESCrypt.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 count) [0x00405] 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 
  --- End of inner exception stack trace ---
 at Duplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile.get_TempFile () [0x00008] in <e60bc008dd1b454d861cfacbdd3760b9>: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) [0x00259] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.DeleteHandler.DoRun (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Data.IDbTransaction& transaction, System.Boolean hasVerifiedBackend, System.Boolean forceCompact, Duplicati.Library.Main.BackendManager sharedManager) [0x003a2] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired (Duplicati.Library.Main.BackendManager backend, System.Int64 lastVolumeSize) [0x000a5] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x01048] in <e60bc008dd1b454d861cfacbdd3760b9>: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 <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0004b] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0011c] in <e60bc008dd1b454d861cfacbdd3760b9>:0 

Log data:
2021-09-24 13:15:57 +02 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Security.Cryptography.CryptographicException: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content ---> SharpAESCrypt.SharpAESCrypt+HashMismatchException: Message has been altered, do not trust content
 at SharpAESCrypt.SharpAESCrypt.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 count) [0x00405] 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 
  --- End of inner exception stack trace ---
 at Duplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile.get_TempFile () [0x00008] in <e60bc008dd1b454d861cfacbdd3760b9>: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) [0x00259] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.DeleteHandler.DoRun (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Data.IDbTransaction& transaction, System.Boolean hasVerifiedBackend, System.Boolean forceCompact, Duplicati.Library.Main.BackendManager sharedManager) [0x003a2] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired (Duplicati.Library.Main.BackendManager backend, System.Int64 lastVolumeSize) [0x000a5] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00da9] in <e60bc008dd1b454d861cfacbdd3760b9>:0

Any insight would be so helpful !

Cheers

2

Where is Duplicati saving data (what back end are you using)?

3

Dear Rod,

Thank you for your answer. Actually it is a SFTP server. As explained, everything works like a charm, and suddenly after several versions, this problem occurs. This issue did occur as well on an other SFTP server, so we can exclude any problem with the server itself.

What I did is I removed manually the last backup files, rebuild the database and then restarted a backup manually, which succeeded.

Looks quite strange…

Have a nice WE

4

Did you also record the duplicati-* file name from red popup error message or the old backup log?
This would not be the temporary file name (dup-*), but the name of the possibly damaged remote file.

If it always happens at CompactHandler as in this log (any idea?) it’s Compacting files at the backend, which (I think) only happens when you get enough versions that your Options screen retention deletes.

Was the other SFTP server a different backup, or the Destination for older versions of current backup?
If the latter, was move to current server done by copying files? If so, that could have copied bad ones…

This would be unusual, but did you watch About → Show log → Live → Verbose to see what files it got?
Ideally, it gets files with dlist in the name, then dindex, then needs few-to-none of the big dblock files.
What this means is that it has no way to get a close look at them, so a damaged one might stay hidden.

If you don’t want to wait until normal compact kicks in, you can use the Compact now button, and maybe whatever file-with-wasted-space existed before will show up and break things again. If so, note its name.

If you do want to wait, you can check your job logs to see if running the initial Compact is when it breaks.

Another option (if you have the time and network capacity to download the whole backup) is to run The TEST command in Commandline. Change the Command to test and Commandline arguments to all.

If the SFTP server is on a box with PowerShell or Python available, there’s a local way to test all files…

5

Dear TS678,

Many thanks for your answer, this is much appreciated.

Yes I did, since the problem occurred again last night. Here is the output of the red popup:

2021-09-27 02:17:05 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes

Honestly I don’t know but I guess so. I’m not that much familiar with Duplicati, I will have a look at the link you provided. So far I noticed, the error message is always the same.

Actually it was a totally different backup, even on another Docker instance of Duplicati.

One of the SFTP server is a Raspberry Pi 4 with SSD drive. The other is a Synology. So for the first one, there is an option for Python.

I will try to have a look on live logs.

I the meantime, hereinafter is also what I got in logs this morning, as you can see, complaining about fingerprint mismatch:

{
  "DeletedFiles": 1,
  "DeletedFolders": 1,
  "ModifiedFiles": 38,
  "ExaminedFiles": 6682,
  "OpenedFiles": 38,
  "AddedFiles": 0,
  "SizeOfModifiedFiles": 5092884405,
  "SizeOfAddedFiles": 0,
  "SizeOfExaminedFiles": 6290552402,
  "SizeOfOpenedFiles": 5092884405,
  "NotProcessedFiles": 0,
  "AddedFolders": 0,
  "TooLargeFiles": 0,
  "FilesWithError": 0,
  "ModifiedFolders": 0,
  "ModifiedSymlinks": 0,
  "AddedSymlinks": 0,
  "DeletedSymlinks": 0,
  "PartialBackup": false,
  "Dryrun": false,
  "MainOperation": "Backup",
  "CompactResults": null,
  "VacuumResults": null,
  "DeleteResults": {
    "DeletedSetsActualLength": 0,
    "DeletedSets": [],
    "Dryrun": false,
    "MainOperation": "Delete",
    "CompactResults": null,
    "ParsedResult": "Success",
    "Version": "2.0.6.3 (2.0.6.3_beta_2021-06-17)",
    "EndTime": "2021-09-27T00:16:05.988142Z",
    "BeginTime": "2021-09-27T00:16:02.978912Z",
    "Duration": "00:00:03.0092300",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 12,
      "BytesUploaded": 74444439,
      "BytesDownloaded": 349973835,
      "FilesUploaded": 3,
      "FilesDownloaded": 7,
      "FilesDeleted": 0,
      "FoldersCreated": 0,
      "RetryAttempts": 4,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 42,
      "KnownFileSize": 2379017106,
      "LastBackupDate": "2021-09-27T02:07:20+02:00",
      "BackupListCount": 6,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "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": "2021-09-27T00:07:15.30392Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "RepairResults": null,
  "TestResults": {
    "MainOperation": "Test",
    "VerificationsActualLength": 3,
    "Verifications": [
      {
        "Key": "duplicati-20210922T000059Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-ifb49befcc9664bd0a9ce9ab93e0bcacc.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes",
        "Value": [
          {
            "Key": "Error",
            "Value": "Discordance d'empreinte dans le fichier \"/tmp/dup-de5199f7-6a58-4eed-be46-15e6051e2f4c\", empreinte enregistrée: fBRgvBesxnNLoXS8TR/SP7go9iU9RuRmyfKfs9LnaZ8=, empreinte réelle 24ZGtYOvGmQ7+U6BLll0/L4cgaAYtPH5RskLFlPWkfM="
          }
        ]
      }
    ],
    "ParsedResult": "Success",
    "Version": "2.0.6.3 (2.0.6.3_beta_2021-06-17)",
    "EndTime": "2021-09-27T00:17:05.968733Z",
    "BeginTime": "2021-09-27T00:16:07.035434Z",
    "Duration": "00:00:58.9332990",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 12,
      "BytesUploaded": 74444439,
      "BytesDownloaded": 349973835,
      "FilesUploaded": 3,
      "FilesDownloaded": 7,
      "FilesDeleted": 0,
      "FoldersCreated": 0,
      "RetryAttempts": 4,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 42,
      "KnownFileSize": 2379017106,
      "LastBackupDate": "2021-09-27T02:07:20+02:00",
      "BackupListCount": 6,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "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": "2021-09-27T00:07:15.30392Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "ParsedResult": "Error",
  "Version": "2.0.6.3 (2.0.6.3_beta_2021-06-17)",
  "EndTime": "2021-09-27T00:17:14.659992Z",
  "BeginTime": "2021-09-27T00:07:15.303915Z",
  "Duration": "00:09:59.3560770",
  "MessagesActualLength": 38,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 1,
  "Messages": [
    "2021-09-27 02:07:19 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: L'opération Backup a débuté",
    "2021-09-27 02:07:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2021-09-27 02:07:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (39 octets)",
    "2021-09-27 02:07:40 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-be094bd58068f4003952fdb033de37ad2.dblock.zip.aes",
    "2021-09-27 02:07:40 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-i25e604ad17a649e2becd6f56f92f3512.dindex.zip.aes",
    "2021-09-27 02:15:52 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b6c6165ff3818425393b3d52bc775ddb2.dblock.zip.aes (69,51 MB)",
    "2021-09-27 02:15:59 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b6c6165ff3818425393b3d52bc775ddb2.dblock.zip.aes (69,51 MB)",
    "2021-09-27 02:16:00 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-id7c2b406e0f2447fa6b36eb7cfec41d4.dindex.zip.aes (1,10 MB)",
    "2021-09-27 02:16:00 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-id7c2b406e0f2447fa6b36eb7cfec41d4.dindex.zip.aes (1,10 MB)",
    "2021-09-27 02:16:01 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20210927T000720Z.dlist.zip.aes (396,47 KB)",
    "2021-09-27 02:16:02 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20210927T000720Z.dlist.zip.aes (396,47 KB)",
    "2021-09-27 02:16:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed",
    "2021-09-27 02:16:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00",
    "2021-09-27 02:16:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 9/26/2021 2:01:11 AM, 9/24/2021 2:50:00 PM, 9/22/2021 2:00:59 AM, 9/21/2021 2:00:49 AM, 9/14/2021 8:05:42 AM",
    "2021-09-27 02:16:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
    "2021-09-27 02:16:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: ",
    "2021-09-27 02:16:05 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: No remote filesets were deleted",
    "2021-09-27 02:16:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2021-09-27 02:16:06 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (42 octets)",
    "2021-09-27 02:16:07 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20210922T000059Z.dlist.zip.aes (396,45 KB)"
  ],
  "Warnings": [],
  "Errors": [
    "2021-09-27 02:17:05 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes"
  ],
  "BackendStatistics": {
    "RemoteCalls": 12,
    "BytesUploaded": 74444439,
    "BytesDownloaded": 349973835,
    "FilesUploaded": 3,
    "FilesDownloaded": 7,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 4,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 42,
    "KnownFileSize": 2379017106,
    "LastBackupDate": "2021-09-27T02:07:20+02:00",
    "BackupListCount": 6,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "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": "2021-09-27T00:07:15.30392Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}
6

I just ran the backup manually, but this time no error apparently, and the number of versions was incremented correctly…

Let’s wait the next scheduled job this night …

7

The challenge is that the logs give you a one-line summary without going into the details, but the error with
duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes was in "MainOperation": "Test" so was Verifying backend files. The original post looked like it was in Compacting files at the backend. Either would raise an error if a damaged file got downloaded. Backup itself is uploads, but Restore is downloads, so any damaged files ideally are noticed fast enough (as here) that they can be dealt with. See Disaster Recovery.

You possibly have some damaged files. You could see if the file is decryptable with AES Crypt if you install that somewhere. If you would rather use a Duplicati CLI tool, there’s SharpAESCrypt.exe in Duplicati install which needs to run under mono. Some systems can automatically figure that out, otherwise say it explicitly.

You also may have the test command option and the ocal access option, if a full survey looks appropriate.

but waiting a bit also works.

8

Stil have the same issue this morning :sob:

Failed: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
Details: System.Security.Cryptography.CryptographicException: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content ---> SharpAESCrypt.SharpAESCrypt+HashMismatchException: Message has been altered, do not trust content
 at SharpAESCrypt.SharpAESCrypt.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 count) [0x00405] 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 
  --- End of inner exception stack trace ---
 at Duplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile.get_TempFile () [0x00008] in <e60bc008dd1b454d861cfacbdd3760b9>: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) [0x00259] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.DeleteHandler.DoRun (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Data.IDbTransaction& transaction, System.Boolean hasVerifiedBackend, System.Boolean forceCompact, Duplicati.Library.Main.BackendManager sharedManager) [0x003a2] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired (Duplicati.Library.Main.BackendManager backend, System.Int64 lastVolumeSize) [0x000a5] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x01048] in <e60bc008dd1b454d861cfacbdd3760b9>: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 <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0004b] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0011c] in <e60bc008dd1b454d861cfacbdd3760b9>:0 

Log data:
2021-09-28 02:13:27 +02 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Security.Cryptography.CryptographicException: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content ---> SharpAESCrypt.SharpAESCrypt+HashMismatchException: Message has been altered, do not trust content
 at SharpAESCrypt.SharpAESCrypt.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 count) [0x00405] 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 
  --- End of inner exception stack trace ---
 at Duplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile.get_TempFile () [0x00008] in <e60bc008dd1b454d861cfacbdd3760b9>: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) [0x00259] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.DeleteHandler.DoRun (Duplicati.Library.Main.Database.LocalDeleteDatabase db, System.Data.IDbTransaction& transaction, System.Boolean hasVerifiedBackend, System.Boolean forceCompact, Duplicati.Library.Main.BackendManager sharedManager) [0x003a2] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired (Duplicati.Library.Main.BackendManager backend, System.Int64 lastVolumeSize) [0x000a5] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00da9] in <e60bc008dd1b454d861cfacbdd3760b9>:0

I will now give a try without intelligent retention activated, just see if it helps…

9

Trying to investigate a little bit more, I manually launched the Compact Now option as you stated… and the operation actually fails here. I put below the output of the direct logs that I gathered:

28 sept. 2021 12:40: L'opération Compact a échoué avec l'erreur : Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
28 sept. 2021 12:40: Backend event: Get - Retrying: duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes (66,48 MB)
28 sept. 2021 12:40: Operation Get with file duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes attempt 1 of 5 failed with message: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
28 sept. 2021 12:40: Backend event: Get - Started: duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes (66,48 MB)
28 sept. 2021 12:40: Backend event: Get - Failed: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:40: Operation Get with file duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes attempt 5 of 5 failed with message: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
28 sept. 2021 12:40: Backend event: Get - Started: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:39: Backend event: Get - Retrying: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:39: Operation Get with file duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes attempt 4 of 5 failed with message: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
28 sept. 2021 12:39: Backend event: Get - Started: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:39: Backend event: Get - Retrying: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:39: Operation Get with file duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes attempt 3 of 5 failed with message: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
28 sept. 2021 12:39: Backend event: Get - Started: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:39: Backend event: Get - Retrying: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:39: Operation Get with file duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes attempt 2 of 5 failed with message: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
28 sept. 2021 12:39: Backend event: Get - Started: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:38: Backend event: Get - Retrying: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:38: Operation Get with file duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes attempt 1 of 5 failed with message: Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content
28 sept. 2021 12:38: Backend event: Get - Started: duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes (72,64 MB)
28 sept. 2021 12:38: Backend event: Get - Completed: duplicati-bc0fff1fe0fcf4dd392e2701b5a57088f.dblock.zip.aes (50,33 MB)
28 sept. 2021 12:38: Backend event: Get - Started: duplicati-bc0fff1fe0fcf4dd392e2701b5a57088f.dblock.zip.aes (50,33 MB)
28 sept. 2021 12:38: removing file listed as Temporary: duplicati-ie2bf3ebb159745989ca97af26e48494c.dindex.zip.aes
28 sept. 2021 12:38: removing file listed as Temporary: duplicati-b7d7a7c16f8284caab4296462bba4cd27.dblock.zip.aes
28 sept. 2021 12:38: Backend event: List - Completed: (49 octets)
28 sept. 2021 12:38: Backend event: List - Started: ()
28 sept. 2021 12:38: Compacting because there are 463,16 MB in small volumes and the volume size is 300,00 MB
28 sept. 2021 12:38: Found 9 volume(s) with a total of 12.12% wasted space (892,73 MB of 7,19 GB)
28 sept. 2021 12:38: Found 11 small volumes(s) with a total size of 463,16 MB
28 sept. 2021 12:38: Found 0 fully deletable volume(s)
28 sept. 2021 12:38: L'opération Compact a débuté

Looks like the process fails on duplicati-bed19e05f0d784109bb58281eb621d91e.dblock.zip.aes:

{"ClassName":"System.Security.Cryptography.CryptographicException","Message":"Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content","Data":null,"InnerException":{"ClassName":"SharpAESCrypt.SharpAESCrypt+HashMismatchException","Message":"Message has been altered, do not trust content","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":"  at SharpAESCrypt.SharpAESCrypt.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 count) [0x00405] in <45c43198e80545aeabaa9b98839b4c7d>:0 \n  at Duplicati.Library.Utility.Utility.CopyStream (System.IO.Stream source, System.IO.Stream target, System.Boolean tryRewindSource, System.Byte[] buf) [0x0003d] in <2a3ee711c7c04f6c957360f2cf183a7f>:0 \n  at Duplicati.Library.Encryption.EncryptionBase.Decrypt (System.IO.Stream input, System.IO.Stream output) [0x00008] in <ecdfcb55bc4741b99f194bd4ca137df6>:0 ","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":null,"HResult":-2146233296,"Source":"SharpAESCrypt"},"HelpURL":null,"StackTraceString":"  at Duplicati.Library.Main.BackendManager.coreDoGetPiping (Duplicati.Library.Main.BackendManager+FileEntryItem item, Duplicati.Library.Interface.IEncryption useDecrypter, System.Int64& retDownloadSize, System.String& retHashcode) [0x002b1] in <e60bc008dd1b454d861cfacbdd3760b9>:0 \n  at Duplicati.Library.Main.BackendManager.DoGet (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x002ff] in <e60bc008dd1b454d861cfacbdd3760b9>:0 \n  at Duplicati.Library.Main.BackendManager.ThreadRun () [0x000ff] in <e60bc008dd1b454d861cfacbdd3760b9>:0 ","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":null,"HResult":-2146233296,"Source":"Duplicati.Library.Main"}

But also on duplicati-b740af9f5199147a9a98bf51510a174f3.dblock.zip.aes:

{"ClassName":"System.Security.Cryptography.CryptographicException","Message":"Échec du déchiffrement des données (phrase de passe invalide ?) : Message has been altered, do not trust content","Data":null,"InnerException":{"ClassName":"SharpAESCrypt.SharpAESCrypt+HashMismatchException","Message":"Message has been altered, do not trust content","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":"  at SharpAESCrypt.SharpAESCrypt.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 count) [0x00405] in <45c43198e80545aeabaa9b98839b4c7d>:0 \n  at Duplicati.Library.Utility.Utility.CopyStream (System.IO.Stream source, System.IO.Stream target, System.Boolean tryRewindSource, System.Byte[] buf) [0x0003d] in <2a3ee711c7c04f6c957360f2cf183a7f>:0 \n  at Duplicati.Library.Encryption.EncryptionBase.Decrypt (System.IO.Stream input, System.IO.Stream output) [0x00008] in <ecdfcb55bc4741b99f194bd4ca137df6>:0 ","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":null,"HResult":-2146233296,"Source":"SharpAESCrypt"},"HelpURL":null,"StackTraceString":"  at Duplicati.Library.Main.BackendManager.coreDoGetPiping (Duplicati.Library.Main.BackendManager+FileEntryItem item, Duplicati.Library.Interface.IEncryption useDecrypter, System.Int64& retDownloadSize, System.String& retHashcode) [0x002b1] in <e60bc008dd1b454d861cfacbdd3760b9>:0 \n  at Duplicati.Library.Main.BackendManager.DoGet (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x002ff] in <e60bc008dd1b454d861cfacbdd3760b9>:0 \n  at Duplicati.Library.Main.BackendManager.ThreadRun () [0x000ff] in <e60bc008dd1b454d861cfacbdd3760b9>:0 ","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":null,"HResult":-2146233296,"Source":"Duplicati.Library.Main"}
10

More information there:

I’ve taken a little bit time to test AESCrypt and the error message is the following when trying to decrypt .aes files:

Error: Message has been altered and should not be trusted (255)

I’m not an expert, but I do suppose it means files are corrupted. Next question is why?

11

What are the sizes and times of any bad files on the SFTP server?

These encrypted files are hard to study manually, but format is here.
If you like, you can head from od -c or hexdump -C to sanity check.
You can probably even open files in an editor or less to look for AES.
I suspect if header was very wrong, the message would be different.

The message source may be below, but I’m not sure what it’s doing:

You could certainly test SFTP transfers Duplicati-style to see if they appear OK. Take the target URL from Export As Command-line, edit for an empty folder, and mono Duplicati.CommandLine.BackendTester.exe.

It’s hard (but possible, if that becomes necessary) to grab the intermediate dup-* files from the tmp folder, but it would be good to make sure it’s not full (when viewed from Docker). If need be, move it with tempdir.

12

That’s indeed the weird thing. The altered files are old files, not the latest ones. Not the oldest but those at the middle I would say. Nothing strange about size.

Remember this happens after 6 or 7 backup version only. If a re-create new jobs, it will work until there.

I’m not a developper so it’s just at the border of my competencies :cold_sweat:

What about trying a more basic option for retention, based on the number of versions and not on intelligent retention?

13

In terms of compacting files, the ones that are read would not be the latest (those would be the writes).
There has to be enough churn (e.g. deletions of old versions) to cause wasted space and do compact.
Maybe the really old files are ones with stabler source, therefore there’s no wasted space for compact.

Backup Test block selection logic describes that. I’d have thought post-backup test would get new files, however maybe those happen to be good. It sounds pretty odd, but maybe a pattern will emerge later…

Developers sometimes work there too. Duplicati has many technologies, so it’s a lot of ground to cover.
Being willing to give something a shot is great though.

Sure. That would make any pattern easier to see without having to look at the logs (which do show this).