Backup fails because file can't be found

Caotenhoch2 commented 1 month ago

[x] I have searched open and closed issues for duplicates.
[x] I have searched the forum for related topics.

Environment info

Duplicati version: 2.0.8.1_beta_2024-05-07
Operating system: Windows 10
Backend: FTP (Alternative)

Description

I have scheduled a backup once every month that keeps 3 backups on my nas. When this backup ran, it threw the Error Code: 550 Message: Could not delete duplicati-20240801T160153Z.dlist.zip.aes: No such file or directory. Therefore, I checked whether that file actually did not exists, which was indeed the case. But there is a file called duplicati-20240801T160154Z.dlist.zip.aes. Now I am unsure what the problem might be. I would guess, that that number indicates the millisecond when the backup was run.

Steps to reproduce

I am not sure how to reproduce this, since my other backup (a smaller one) ran fine afterwards.

Actual result: Fatal error and unsuccessful backup
Expected result: Successful backup

Screenshots

/

Debug log

Live:

{"ClassName":"FluentFTP.Exceptions.FtpCommandException","Message":"Could not delete duplicati-20240801T160153Z.dlist.zip.aes: No such file or directory","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":"   bei Duplicati.Library.Main.BackendManager.WaitForEmpty(LocalDatabase db, IDbTransaction transation)\r\n   bei Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBackend, Boolean forceCompact, BackendManager sharedManager)\r\n   bei Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize)\r\n   bei Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext()\r\n--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---\r\n   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   bei CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)\r\n   bei Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result)\r\n   bei Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)\r\n   bei Duplicati.Library.Main.Controller.Backup(String[] inputsources, IFilter filter)\r\n   bei Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\nWaitForEmpty\nDuplicati.Library.Main, Version=2.0.8.1, Culture=neutral, PublicKeyToken=null\nDuplicati.Library.Main.BackendManager\nVoid WaitForEmpty(Duplicati.Library.Main.Database.LocalDatabase, System.Data.IDbTransaction)","HResult":-2146233088,"Source":"Duplicati.Library.Main","WatsonBuckets":null}

Stored:

FluentFTP.Exceptions.FtpCommandException: Code: 550 Message: Could not delete duplicati-20240801T160153Z.dlist.zip.aes: No such file or directory

   bei Duplicati.Library.Main.BackendManager.WaitForEmpty(LocalDatabase db, IDbTransaction transation)

   bei Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBackend, Boolean forceCompact, BackendManager sharedManager)

   bei Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize)

   bei Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext()

--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)

   bei Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result)

   bei Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)

   bei Duplicati.Library.Main.Controller.Backup(String[] inputsources, IFilter filter)

   bei Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)

ts678 commented 1 month ago

I would guess, that that number indicates the millisecond when the backup was run.

It's just HHMMSS (hours minutes seconds), but the non-obvious part is why seconds went up by 1 on 160154. The answer is sometimes that Duplicati tried to upload 160153, failed, then dummied up unique name 160154. For dblock and dindex files, the names are random, so upload retry gets a new random (not used before) name. For dlist files (which aren't random-name), it adds a second, which keeps time (which is in UTC) about the same.

You can look in your job log Complete log section to see what "RetryAttempts" is. Failed uploads are to be expected, especially over the Internet, but it's probably stranger if NAS is local (is it?). Got any logs on the NAS?

The exact status of failed uploads isn't always very obvious. I think the plan is to delete the partial file, if it exists. Possibly Duplicati decided to do that, while the NAS decided to delete a partial file (thereby having Duplicati fail).

Did you have an interrupted backup or other activity? That can sometimes get the records somewhat confused. You can look in your job logs to see if you got a full set, and About --> Show log --> Stored for any complaint.

You can scroll back in \ --> Show log --> Remote to see if you can see either of the dlist files mentioned. This is reverse-chronological, and usually the dlist for a backup (which lists its contents) is about the last upload. After that, the end is usually one set of three files (one per type), which are downloaded to see if they seem OK. Possibly yours downloaded duplicati-20240801T160154Z.dlist.zip.aes. The sampling favors files not yet verified.

Example ending of a backup I just did:

Aug 3, 2024 5:54 PM: get duplicati-bbdf141540a36480d8c45236bc25efcb0.dblock.zip
Aug 3, 2024 5:54 PM: get duplicati-ia7df604f7e104a188c6e3564d1859874.dindex.zip
Aug 3, 2024 5:54 PM: get duplicati-20240803T215435Z.dlist.zip
Aug 3, 2024 5:54 PM: list
Aug 3, 2024 5:54 PM: put duplicati-20240803T215435Z.dlist.zip

Caotenhoch2 commented 1 month ago

Okay, I looked under About --> Show log --> Stored for any complaints and the only one aside from the failed backup is the following error in updater:

System.Exception: Folder C:\ProgramData\Duplicati\updates\2.0.8.1\ is missing: changelog.txt

   bei Duplicati.Library.AutoUpdater.UpdaterManager.VerifyUnpackedFolder(String folder, UpdateInfo version)

Yes, the NAS is local, but no, I sadly do not have any logs

Now, under --> Show log --> Remote, there is nothing listed with the command list or get under the last backup, except one list at the beginning of the backup. But there seems to be a failed backup on the first of august. I added the screenshot of the log grafik grafik

Might the failed backup have caused this error?

duplicati / duplicati