2.0.4.21_experimental_2019-06-28: Delete operation failed for... with FileNotFound, listing contents

For a while, the latest experimental was working nicely for me, and I’ve not seen this error previously in any version I’ve used… but I’ve now seen the error listed in the subject line twice.

Maybe there’s nothing really wrong, but if so, then it shouldn’t be warning me, right?

I’m attaching the log below.

{
  "DeletedFiles": 77,
  "DeletedFolders": 0,
  "ModifiedFiles": 98,
  "ExaminedFiles": 92151,
  "OpenedFiles": 155,
  "AddedFiles": 57,
  "SizeOfModifiedFiles": 239645789,
  "SizeOfAddedFiles": 17217956,
  "SizeOfExaminedFiles": 578199727380,
  "SizeOfOpenedFiles": 257067375,
  "NotProcessedFiles": 0,
  "AddedFolders": 0,
  "TooLargeFiles": 0,
  "FilesWithError": 0,
  "ModifiedFolders": 0,
  "ModifiedSymlinks": 0,
  "AddedSymlinks": 0,
  "DeletedSymlinks": 0,
  "PartialBackup": false,
  "Dryrun": false,
  "MainOperation": "Backup",
  "CompactResults": {
    "DeletedFileCount": 0,
    "DownloadedFileCount": 0,
    "UploadedFileCount": 0,
    "DeletedFileSize": 0,
    "DownloadedFileSize": 0,
    "UploadedFileSize": 0,
    "Dryrun": false,
    "MainOperation": "Compact",
    "ParsedResult": "Success",
    "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
    "EndTime": "2019-07-23T07:19:31.742996Z",
    "BeginTime": "2019-07-23T07:19:02.980891Z",
    "Duration": "00:00:28.7621050",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 12,
      "BytesUploaded": 42803517,
      "BytesDownloaded": 61454482,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 1,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 19623,
      "KnownFileSize": 508357235329,
      "LastBackupDate": "2019-07-23T03:13:01-04:00",
      "BackupListCount": 18,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2019-07-23T07:13:00.038294Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "DeleteResults": {
    "DeletedSetsActualLength": 2,
    "DeletedSets": [
      {
        "Item1": 1,
        "Item2": "2019-07-22T12:50:07-04:00"
      },
      {
        "Item1": 7,
        "Item2": "2019-07-16T03:13:00-04:00"
      }
    ],
    "Dryrun": false,
    "MainOperation": "Delete",
    "CompactResults": {
      "DeletedFileCount": 0,
      "DownloadedFileCount": 0,
      "UploadedFileCount": 0,
      "DeletedFileSize": 0,
      "DownloadedFileSize": 0,
      "UploadedFileSize": 0,
      "Dryrun": false,
      "MainOperation": "Compact",
      "ParsedResult": "Success",
      "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
      "EndTime": "2019-07-23T07:19:31.742996Z",
      "BeginTime": "2019-07-23T07:19:02.980891Z",
      "Duration": "00:00:28.7621050",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null,
      "BackendStatistics": {
        "RemoteCalls": 12,
        "BytesUploaded": 42803517,
        "BytesDownloaded": 61454482,
        "FilesUploaded": 3,
        "FilesDownloaded": 3,
        "FilesDeleted": 2,
        "FoldersCreated": 0,
        "RetryAttempts": 1,
        "UnknownFileSize": 0,
        "UnknownFileCount": 0,
        "KnownFileCount": 19623,
        "KnownFileSize": 508357235329,
        "LastBackupDate": "2019-07-23T03:13:01-04:00",
        "BackupListCount": 18,
        "TotalQuotaSpace": 0,
        "FreeQuotaSpace": 0,
        "AssignedQuotaSpace": -1,
        "ReportedQuotaError": false,
        "ReportedQuotaWarning": false,
        "MainOperation": "Backup",
        "ParsedResult": "Success",
        "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
        "EndTime": "0001-01-01T00:00:00",
        "BeginTime": "2019-07-23T07:13:00.038294Z",
        "Duration": "00:00:00",
        "MessagesActualLength": 0,
        "WarningsActualLength": 0,
        "ErrorsActualLength": 0,
        "Messages": null,
        "Warnings": null,
        "Errors": null
      }
    },
    "ParsedResult": "Success",
    "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
    "EndTime": "2019-07-23T07:19:31.742998Z",
    "BeginTime": "2019-07-23T07:17:52.032858Z",
    "Duration": "00:01:39.7101400",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 12,
      "BytesUploaded": 42803517,
      "BytesDownloaded": 61454482,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 1,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 19623,
      "KnownFileSize": 508357235329,
      "LastBackupDate": "2019-07-23T03:13:01-04:00",
      "BackupListCount": 18,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2019-07-23T07:13:00.038294Z",
      "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-20190722T071300Z.dlist.zip.gpg",
        "Value": []
      },
      {
        "Key": "duplicati-ied77073cbfe84f458490e133fed2e2b9.dindex.zip.gpg",
        "Value": []
      },
      {
        "Key": "duplicati-b192493c425c7490896994277e1790a36.dblock.zip.gpg",
        "Value": []
      }
    ],
    "ParsedResult": "Success",
    "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
    "EndTime": "2019-07-23T07:20:50.193581Z",
    "BeginTime": "2019-07-23T07:20:01.689393Z",
    "Duration": "00:00:48.5041880",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 12,
      "BytesUploaded": 42803517,
      "BytesDownloaded": 61454482,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 1,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 19623,
      "KnownFileSize": 508357235329,
      "LastBackupDate": "2019-07-23T03:13:01-04:00",
      "BackupListCount": 18,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2019-07-23T07:13:00.038294Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "ParsedResult": "Warning",
  "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
  "EndTime": "2019-07-23T07:20:50.201935Z",
  "BeginTime": "2019-07-23T07:13:00.038289Z",
  "Duration": "00:07:50.1636460",
  "MessagesActualLength": 37,
  "WarningsActualLength": 1,
  "ErrorsActualLength": 0,
  "Messages": [
    "2019-07-23 03:13:00 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2019-07-23 03:13:49 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2019-07-23 03:14:19 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (19.16 KB)",
    "2019-07-23 03:16:31 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b3e04c347e26c4a36b97d3a175d2471f2.dblock.zip.gpg (31.45 MB)",
    "2019-07-23 03:16:36 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20190723T071300Z.dlist.zip.gpg (9.27 MB)",
    "2019-07-23 03:17:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-20190723T071300Z.dlist.zip.gpg (9.27 MB)",
    "2019-07-23 03:17:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20190723T071300Z.dlist.zip.gpg (9.27 MB)",
    "2019-07-23 03:17:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20190723T071301Z.dlist.zip.gpg (9.27 MB)",
    "2019-07-23 03:17:17 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming \"duplicati-20190723T071300Z.dlist.zip.gpg\" to \"duplicati-20190723T071301Z.dlist.zip.gpg\"",
    "2019-07-23 03:17:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20190723T071301Z.dlist.zip.gpg (9.27 MB)",
    "2019-07-23 03:17:19 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b3e04c347e26c4a36b97d3a175d2471f2.dblock.zip.gpg (31.45 MB)",
    "2019-07-23 03:17:19 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i8c5db7a1a2c248d1b08988e70d67ffc5.dindex.zip.gpg (104.89 KB)",
    "2019-07-23 03:17:22 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i8c5db7a1a2c248d1b08988e70d67ffc5.dindex.zip.gpg (104.89 KB)",
    "2019-07-23 03:17:52 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20190723T071301Z.dlist.zip.gpg (9.27 MB)",
    "2019-07-23 03:17:52 -04 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed",
    "2019-07-23 03:17:52 -04 - [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",
    "2019-07-23 03:17:52 -04 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 7/22/2019 12:50:07 PM, 7/22/2019 3:13:00 AM, 7/20/2019 3:13:02 AM, 7/19/2019 3:13:00 AM, 7/18/2019 3:13:00 AM, 7/17/2019 3:13:00 AM, 7/16/2019 3:13:00 AM, 7/12/2019 6:25:06 AM, 7/5/2019 3:13:00 AM, 6/27/2019 10:23:01 PM, 6/6/2019 3:13:01 AM, 5/1/2019 3:13:01 AM, 3/27/2019 3:13:01 AM, 2/20/2019 2:13:01 AM, 1/16/2019 2:13:01 AM, 12/11/2018 2:13:01 AM, 11/3/2018 3:13:04 AM, 9/28/2018 3:13:01 AM, 8/21/2018 9:05:12 AM",
    "2019-07-23 03:17:52 -04 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
    "2019-07-23 03:17:52 -04 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: 7/22/2019 12:50:07 PM, 7/16/2019 3:13:00 AM",
    "2019-07-23 03:17:52 -04 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 2 remote fileset(s) ..."
  ],
  "Warnings": [
    "2019-07-23 03:18:33 -04 - [Warning-Duplicati.Library.Main.BackendManager-DeleteRemoteFileFailed]: Delete operation failed for duplicati-20190723T071300Z.dlist.zip.gpg with FileNotFound, listing contents"
  ],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 12,
    "BytesUploaded": 42803517,
    "BytesDownloaded": 61454482,
    "FilesUploaded": 3,
    "FilesDownloaded": 3,
    "FilesDeleted": 2,
    "FoldersCreated": 0,
    "RetryAttempts": 1,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 19623,
    "KnownFileSize": 508357235329,
    "LastBackupDate": "2019-07-23T03:13:01-04:00",
    "BackupListCount": 18,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Backup",
    "ParsedResult": "Success",
    "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2019-07-23T07:13:00.038294Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}

might be an upload attempt failing. The failed file is deleted (which might be the error, if nothing transferred), and a retry is done under a different filename (I think to make extra sure the new file isn’t confused with old).

I’m not sure if this behavior has changed, but there seem to be more reports. What destination type is this?

I did notice that when this happened there were retries logged… The destination type is B2.

B2: How many times does Duplicati try to get an Upload URL when something goes wrong? commented:

I’m sure hoping there’s not a delay (and plausibly there could be one) where an upload fails, Duplicati tries delete immediately, delete fails because the file’s not there, then the file shows up. B2 isn’t a simple write operation into a file (same might be true for other cloud services though). File needs to be processed first.

B2 Resiliency, Durability and Availability talks about this, and I suspect it all happens AFTER upload ends.

but how quickly the file actually shows up in the normal and failed cases might be hard to determine manually. I suppose with two computers, one could do a slightly throttled large upload, disconnect its Internet connection midway, and refresh B2 UI from another computer to see if anything shows up.

Delete by Duplicati from first computer can’t happen because it’s got no connection, but it might try. Logging would show that. So one could perhaps see it try the delete before B2 put the partial file up, however with most of these cloud services (too lazy to confirm B2) there’s info such as a hash that destination will check to make sure things arrived as intended. If not, I’d expect they’d discard the try.

This all makes me worried again whether the no-look delete is a good idea. I thought I saw deletions handled differently at the end of the backup, based on file listing, i.e. if file isn’t there, don’t try delete.