Error with no log (Failed to decrypt data) when running on schedule but not manually

Support
1

Hi everyone,

I’m running Duplicati - 2.0.5.114_canary_2021-03-10 on windows 10.
I’m getting an error with a backup when it’s run by the scheduler, but not when I launch it manually.
That error is displayed at the bottom of the web interface, but can’t be found in the logs.
The message is: “Failed to decrypt data (invalid passphrase?): Message has been altered, do not trust content”.
The backup is not reported as done.
The destination is accessed via sftp, auth by a rsa keyfile.
I was on a previous canary version when that message has started appearing. I have updated to the latest canary but it’s still manifesting.

2

I would fully expect this to be a bug with a difference happening between manual and auto usage. It could be however that something else not related happens with auto that somehow causes it.

Its obviously failing to decrypt. Since it happens on one way and not on the other then there should be a difference happening that should be the fault of the application.

If it was running at least one backup successfully then it would be intermittent but it sounds like it is failing hard and not running any if I understand what you said.

The only thing I can think of that should work (that you can do) is to use a different connection method which may produce a different result depending on where the issue resides. eg move away from ftp.

Foreground/background, application user, etc shouldn’t affect this since it should be relatively the same eg same system user for the application. So my final opinion is bug.

3

Does that mean you’ll pursue it?

1 Like
4

I said there was no logs when the backup fails. That’s not entirely true.
The remote logs has some messages with no errors.

  • Mar 12, 2021 1:02 AM: delete duplicati-20210311T080534Z.dlist.zip.aes
  • Mar 12, 2021 1:02 AM: delete duplicati-20210305T000000Z.dlist.zip.aes
  • Mar 12, 2021 1:02 AM: put duplicati-20210312T000000Z.dlist.zip.aes
  • Mar 12, 2021 1:02 AM: put duplicati-i10dd52abf303420db7a9af182a6df950.dindex.zip.aes
  • Mar 12, 2021 1:02 AM: put duplicati-bf09b2bff811a432d89608fd37cc35d68.dblock.zip.aes
  • Mar 12, 2021 1:00 AM: list

I have another backup running at 12am from the same computer to the same server that is working without problems.
But after checking, I have a backup from another server to that same exact server at the same time (1 AM). That may explain why one backup fails but not the other. I’m going to change the run time of the failing backup.

5

And I said the backup failed, but it seems to be ok. New files are on the destination and the “restore files” proposes the latest scheduled backup.
The problems are the general log missing and getting the error message.

6

I don’t think that one has errors. It’s more a (not very user-oriented) transcript of actions done to remote.

Errors on backup often mean that the general log gets no entry (possibly because entry shows results of the backup, and there aren’t any – that’s a guess), so also try server log at About → Show log → Stored.

Occasionally, live server log at About → Show log → Live → <some level> shows better details of errors.
Your issue could probably benefit from a look at Retry level if you want to see the default 5 retries it does. Unlike network issues though, it might always say the same thing, so Information level may be enough.

If you can find affected remote files in logs, you can then test the files with other tools such as AES Crypt. Matching exact error wordings would require CLI SharpAESCrypt.exe which is in Duplicati’s install folder, however your main interest is probably just to detect whether the files are bad or passphrase is confused.

Do you know what Canary? If you have a date, you might be able to match to a download or update folder.

2.0.5.112_canary_2021-01-20

Fixed password manager autofill, thanks @drwtsn32x

Fixed a problem hitting a lot of people who let their browser (pretty much any modern browser) or added password manager fill in a hidden field on a restore screen, thereby breaking restore thus causing alarm.

I don’t know how this would fit into this case unless your password fill was helping you and now it’s gone.

To avoid GUI does Export As Command-line do backup fine (or not) when run from a Command Prompt?

EDIT:

I’m not too clear on where things stand. Did changing the time solve the original issue somehow, and you want some idea how (plus other lingering questions)? Unfortunately, debug may need getting issue again.

7

So, even when changing the schedule to only get one backup at once, I’m getting the error.
I found the previous version used in the log: 2.0.5.112 (2.0.5.112_canary_2021-01-20)
The last time the schedule version works was 2021-03-08 01:00:00 (UTC+1) (if it’s date related ??)
I will try using a ssh mountpoint in windows next (using nsoftware sftp drive) to see if the problem is ssh related or not. I will also try scheduling during the day. I will update this thread once I have further informations (Monday I think).

The full error is:
System.Security.Cryptography.CryptographicException: Failed to decrypt data (invalid passphrase?): Message has been altered, do not trust content —> SharpAESCrypt.SharpAESCrypt+HashMismatchException: Message has been altered, do not trust content
at SharpAESCrypt.SharpAESCrypt.Read(Byte buffer, Int32 offset, Int32 count)
at Duplicati.Library.Utility.Utility.CopyStream(Stream source, Stream target, Boolean tryRewindSource, Byte buf)
at Duplicati.Library.Encryption.EncryptionBase.Decrypt(Stream input, Stream output)
— End of inner exception stack trace —
at Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.AsyncDownloadedFile.get_TempFile()
at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend)
at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBackend, Boolean forceCompact, BackendManager sharedManager)
at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize)
at Duplicati.Library.Main.Operation.BackupHandler.d__20.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)
at Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.b__0(BackupResults result)
at Duplicati.Library.Main.Controller.RunAction[T](T result, String& paths, IFilter& filter, Action`1 method)
at Duplicati.Library.Main.Controller.Backup(String inputsources, IFilter filter)
at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)

When running manually, the result is:
{
“DeletedFiles”: 16,
“DeletedFolders”: 0,
“ModifiedFiles”: 81,
“ExaminedFiles”: 182089,
“OpenedFiles”: 108,
“AddedFiles”: 27,
“SizeOfModifiedFiles”: 1973005291,
“SizeOfAddedFiles”: 7971668,
“SizeOfExaminedFiles”: 88468752400,
“SizeOfOpenedFiles”: 1981136933,
“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.5.114 (2.0.5.114_canary_2021-03-10)”,
“EndTime”: “2021-03-13T10:59:51.6334646Z”,
“BeginTime”: “2021-03-13T10:59:42.9434122Z”,
“Duration”: “00:00:08.6900524”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 8,
“BytesUploaded”: 49437335,
“BytesDownloaded”: 76818583,
“FilesUploaded”: 3,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 3641,
“KnownFileSize”: 93668922181,
“LastBackupDate”: “2021-03-13T11:57:02+01:00”,
“BackupListCount”: 18,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.114 (2.0.5.114_canary_2021-03-10)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2021-03-13T10:57:02.1024173Z”,
“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-20210313T010000Z.dlist.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ida06e8e87c0340b0af8fb0787f78b8ef.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-b5581930138374abbb649aec086995c39.dblock.zip.aes”,
“Value”:
}
],
“ParsedResult”: “Success”,
“Version”: “2.0.5.114 (2.0.5.114_canary_2021-03-10)”,
“EndTime”: “2021-03-13T10:59:56.2074125Z”,
“BeginTime”: “2021-03-13T10:59:52.3064493Z”,
“Duration”: “00:00:03.9009632”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 8,
“BytesUploaded”: 49437335,
“BytesDownloaded”: 76818583,
“FilesUploaded”: 3,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 3641,
“KnownFileSize”: 93668922181,
“LastBackupDate”: “2021-03-13T11:57:02+01:00”,
“BackupListCount”: 18,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.114 (2.0.5.114_canary_2021-03-10)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2021-03-13T10:57:02.1024173Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“ParsedResult”: “Success”,
“Version”: “2.0.5.114 (2.0.5.114_canary_2021-03-10)”,
“EndTime”: “2021-03-13T10:59:56.235414Z”,
“BeginTime”: “2021-03-13T10:57:02.1024173Z”,
“Duration”: “00:02:54.1329967”,
“MessagesActualLength”: 25,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: [
“2021-03-13 11:57:02 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started”,
“2021-03-13 11:57:30 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2021-03-13 11:57:30 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (3.55 KB)”,
“2021-03-13 11:57:30 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-beb770bbabac74a39a7ded8293b953848.dblock.zip.aes”,
“2021-03-13 11:57:30 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-iba2cf0f2e9034fda9094410e45857867.dindex.zip.aes”,
“2021-03-13 11:59:26 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bf1620861a42f444ca1009d8447bf18cd.dblock.zip.aes (23.38 MB)”,
“2021-03-13 11:59:29 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bf1620861a42f444ca1009d8447bf18cd.dblock.zip.aes (23.38 MB)”,
“2021-03-13 11:59:37 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i27a30b696c2c4845bfa410caf5aecec4.dindex.zip.aes (539.79 KB)”,
“2021-03-13 11:59:37 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i27a30b696c2c4845bfa410caf5aecec4.dindex.zip.aes (539.79 KB)”,
“2021-03-13 11:59:41 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20210313T105702Z.dlist.zip.aes (23.24 MB)”,
“2021-03-13 11:59:42 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20210313T105702Z.dlist.zip.aes (23.24 MB)”,
“2021-03-13 11:59:42 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed”,
“2021-03-13 11:59:42 +01 - [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-03-13 11:59:42 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 13/03/2021 02:00:00, 12/03/2021 01:00:00, 11/03/2021 01:00:00, 10/03/2021 01:00:00, 09/03/2021 01:00:00, 08/03/2021 01:00:00, 07/03/2021 01:00:00, 27/02/2021 01:00:01, 19/02/2021 03:51:08, 04/02/2021 01:00:00, 27/01/2021 11:56:53, 13/01/2021 08:23:34, 29/12/2020 01:00:00, 24/11/2020 01:00:00, 19/10/2020 02:00:00, 13/09/2020 02:00:00, 06/08/2020 16:24:42”,
"2021-03-13 11:59:42 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
"2021-03-13 11:59:42 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: ",
“2021-03-13 11:59:51 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: No remote filesets were deleted”,
“2021-03-13 11:59:51 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2021-03-13 11:59:52 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (3.56 KB)”,
“2021-03-13 11:59:52 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20210313T010000Z.dlist.zip.aes (23.23 MB)”
],
“Warnings”: ,
“Errors”: ,
“BackendStatistics”: {
“RemoteCalls”: 8,
“BytesUploaded”: 49437335,
“BytesDownloaded”: 76818583,
“FilesUploaded”: 3,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 3641,
“KnownFileSize”: 93668922181,
“LastBackupDate”: “2021-03-13T11:57:02+01:00”,
“BackupListCount”: 18,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.114 (2.0.5.114_canary_2021-03-10)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2021-03-13T10:57:02.1024173Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
}

8

Probably not this one though it is interesting. Right now I’m injured but soon might go after some bounty problems and maybe some non-bounty ones :slight_smile:

@clavelm80 I think the Failed to decrypt data (invalid passphrase?) could be a bit of a throw off as HashMismatchException happens. The invalid passphrase? is definitely a throw off here.

Don’t know why there would be a mismatch only on automatic though. That also shouldn’t happen.

I see ts678 has previous knowledge of HashMismatchException’s with Duplicati.

9

So, I’ve tested using a windows mountpoint instead of sftp, and scheduling the day with sftp,
Always the same problem only on that backup.
What info can I give to help track the bug?

10

Is “that backup” the scheduled sftp? Is mountpoint (folder?) backup manual or scheduled?
What is its relationship to the sftp, or is it unrelated? What works or not on mountpoint job?

What I would prefer is a simple backup (ideally from scratch) that can reproduce the issue.
This is also the ideal way to do a Duplicati GitHub Issue. What are steps anybody can run?

Do you have enough local space to make a new job much like failing one to see if it works?

11

I have 2 backups of differents files from my laptop running on schedule.
These 2 backups are saving on the same server on my lan, in different folders, using sftp.
One of the backup starts sending Failed to decrypt data (invalid passphrase?).
The backup is not logged as successfully finished, but it is successful.
When launching the backup manually, it succeeds without error.
I try changing parameters of the backup to see if the error disappears.
I did:

  • scheduling the day instead of the night (as manual test backups were launch the day). Ok manually, error on schedule.
  • using a system file access instead of the sftp connection. I used nsoftware sftp drive to mount my server on the windows drive Z. Backup is working manually, but is erroneous on schedule.
  • I was having a duplicati backup from another computer via sftp at the same time the night that the one with the error. I changed the scheduled time to have only one backup at a time. It did not solved the problem.
  • I was on 2.0.5.112 (2.0.5.112_canary_2021-01-20 when the problem has started manifesting, without changing anything. I updated to 2.0.5.114_canary_2021-03-10 but the problem has not been solved.

I can try to create the most simple backup with the same problem, but as I have a really similar backup (same destination server, different destination folder, different source folders, same sftp access (same user/rsa key), same encryption password, running on schedule just an hour later) without the problem, I’m not sure I will succeed.

I think the error message Failed to decrypt data (invalid passphrase?) might be inaccurate, as the decryption works. The backup files are created, I can access my backup files through restore.
What other causes can throw that error? What core differences are there between manual and schedule launch of the same backup that can explain getting that error only on schedule?

12

Now the scheduled backup has failed with a missing file, and after repair, event launching it manually has the Failed to decrypt data (invalid passphrase?) error.
I’ve moved the old backup folder to keep the history, removed the backup and imported the saved backup config file to start anew.