New backup to Wasabi stuck at "Waiting for upload to finish ..."

Support
1

I just installed 2.0.4.15_canary_2019-02-06 on my new Raspberry Pi, and it seems to be working except for one thing. My backup to Wasabi, I’m using the new EU datacentre, never seems to complete according to the GUI and stays showing “Waiting for upload to finish …”.

The log for the job looks like it did finish

{
  "DeletedFiles": 0,
  "DeletedFolders": 0,
  "ModifiedFiles": 9,
  "ExaminedFiles": 1067,
  "OpenedFiles": 15,
  "AddedFiles": 6,
  "SizeOfModifiedFiles": 2023553,
  "SizeOfAddedFiles": 91762,
  "SizeOfExaminedFiles": 14850357,
  "SizeOfOpenedFiles": 2115584,
  "NotProcessedFiles": 0,
  "AddedFolders": 3,
  "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.15 (2.0.4.15_canary_2019-02-06)",
    "EndTime": "2019-03-01T11:02:55.882578Z",
    "BeginTime": "2019-03-01T11:02:55.744289Z",
    "Duration": "00:00:00.1382890",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 8,
      "BytesUploaded": 280663,
      "BytesDownloaded": 280663,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 0,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 6,
      "KnownFileSize": 4104366,
      "LastBackupDate": "2019-03-01T12:02:41+01:00",
      "BackupListCount": 2,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2019-03-01T11:02:40.484329Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "DeleteResults": {
    "DeletedSetsActualLength": 0,
    "DeletedSets": [],
    "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.15 (2.0.4.15_canary_2019-02-06)",
      "EndTime": "2019-03-01T11:02:55.882578Z",
      "BeginTime": "2019-03-01T11:02:55.744289Z",
      "Duration": "00:00:00.1382890",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null,
      "BackendStatistics": {
        "RemoteCalls": 8,
        "BytesUploaded": 280663,
        "BytesDownloaded": 280663,
        "FilesUploaded": 3,
        "FilesDownloaded": 3,
        "FilesDeleted": 0,
        "FoldersCreated": 0,
        "RetryAttempts": 0,
        "UnknownFileSize": 0,
        "UnknownFileCount": 0,
        "KnownFileCount": 6,
        "KnownFileSize": 4104366,
        "LastBackupDate": "2019-03-01T12:02:41+01:00",
        "BackupListCount": 2,
        "TotalQuotaSpace": 0,
        "FreeQuotaSpace": 0,
        "AssignedQuotaSpace": -1,
        "ReportedQuotaError": false,
        "ReportedQuotaWarning": false,
        "MainOperation": "Backup",
        "ParsedResult": "Success",
        "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
        "EndTime": "0001-01-01T00:00:00",
        "BeginTime": "2019-03-01T11:02:40.484329Z",
        "Duration": "00:00:00",
        "MessagesActualLength": 0,
        "WarningsActualLength": 0,
        "ErrorsActualLength": 0,
        "Messages": null,
        "Warnings": null,
        "Errors": null
      }
    },
    "ParsedResult": "Success",
    "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
    "EndTime": "2019-03-01T11:02:55.883389Z",
    "BeginTime": "2019-03-01T11:02:55.489191Z",
    "Duration": "00:00:00.3941980",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 8,
      "BytesUploaded": 280663,
      "BytesDownloaded": 280663,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 0,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 6,
      "KnownFileSize": 4104366,
      "LastBackupDate": "2019-03-01T12:02:41+01:00",
      "BackupListCount": 2,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2019-03-01T11:02:40.484329Z",
      "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-20190301T110241Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-i628f4a97107e4c6786d8e6da2ed690de.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-b43ff8e6058cb40879146700379d42609.dblock.zip.aes",
        "Value": []
      }
    ],
    "ParsedResult": "Success",
    "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
    "EndTime": "2019-03-01T11:02:56.331811Z",
    "BeginTime": "2019-03-01T11:02:56.013116Z",
    "Duration": "00:00:00.3186950",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 8,
      "BytesUploaded": 280663,
      "BytesDownloaded": 280663,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 0,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 6,
      "KnownFileSize": 4104366,
      "LastBackupDate": "2019-03-01T12:02:41+01:00",
      "BackupListCount": 2,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2019-03-01T11:02:40.484329Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "ParsedResult": "Success",
  "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
  "EndTime": "2019-03-01T11:02:56.367057Z",
  "BeginTime": "2019-03-01T11:02:40.484292Z",
  "Duration": "00:00:15.8827650",
  "MessagesActualLength": 24,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 0,
  "Messages": [
    "2019-03-01 12:02:40 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2019-03-01 12:02:41 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2019-03-01 12:02:41 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (3 bytes)",
    "2019-03-01 12:02:54 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b43ff8e6058cb40879146700379d42609.dblock.zip.aes (160.20 KB)",
    "2019-03-01 12:02:54 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b43ff8e6058cb40879146700379d42609.dblock.zip.aes (160.20 KB)",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i628f4a97107e4c6786d8e6da2ed690de.dindex.zip.aes (2.86 KB)",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i628f4a97107e4c6786d8e6da2ed690de.dindex.zip.aes (2.86 KB)",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20190301T110241Z.dlist.zip.aes (111.03 KB)",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20190301T110241Z.dlist.zip.aes (111.03 KB)",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 31.00:00:00 / 7.00:00:00, 1095.00:00:00 / 31.00:00:00",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 01/03/2019 11:16:08",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: ",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: No remote filesets were deleted",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2019-03-01 12:02:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6 bytes)",
    "2019-03-01 12:02:56 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190301T110241Z.dlist.zip.aes (111.03 KB)",
    "2019-03-01 12:02:56 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20190301T110241Z.dlist.zip.aes (111.03 KB)"
  ],
  "Warnings": [],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 8,
    "BytesUploaded": 280663,
    "BytesDownloaded": 280663,
    "FilesUploaded": 3,
    "FilesDownloaded": 3,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 6,
    "KnownFileSize": 4104366,
    "LastBackupDate": "2019-03-01T12:02:41+01:00",
    "BackupListCount": 2,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Backup",
    "ParsedResult": "Success",
    "Version": "2.0.4.15 (2.0.4.15_canary_2019-02-06)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2019-03-01T11:02:40.484329Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}

Any idea why it’s just sitting there not telling the system it’s done? I’ve checked the bucket and there are files there, and “verify” and “repair” show no problems.

2

I’ve noticed that the scheduled job continues to run regardless all the time the GUI is showing “Waiting for upload…” and I also see the CPU is being hammered by the process. Restarting the service brings it back to normal until the next time the job is run.

4

I have been seeing this exact issue on a number of computers. I cannot say what part of this is fixing it. But this has worked for me.

  1. Stop the backup.
    (Following 2 steps I have to do because the database gets locked after stopping it)
  2. Exit Duplicati and rerun it (or stop then start the serivce if you have it setup that way)
  3. Repair Database.
  4. I add the following switches to the settings area but you can add them to just the job options. Use the menu button to go into edit mode and paste in the following…

–auto-cleanup=true
–usn-policy=Auto
–retry-delay=60s
–thread-priority=highest
–concurrency-max-threads=1

5

Thanks, but it has made no difference and the “usn-policy” caused an error I’m assuming because it’s Linux and not Windows NTFS - I have kept the “concurrency-max-threads” option set to 1 as I think this will help the Pi anyway.

6

I found the problem - I spotted in the live log set to profiling that even after the successful backup that there was an error that only appeared once I killed the backup job:

6 Mar 2019 09:29: OnFinish callback True failed:
6 Mar 2019 09:29: Failed to send message: System.Threading.ThreadAbortException:
6 Mar 2019 09:29: Whole SMTP communication: Connected to smtp://mail.mydomain.com:25/?starttls=when-available S: 220-mydomain.com ESMTP Wed, 06 Mar 2019 09:29:33 +0100 S: 220-* S: 220-* This site does not authorise the use of its proprietary computers S: 220-* and computer network to accept, transmit or distribute unsolicited S: 220-* bulk email, phishing or malware from the Internet. S: 220-* S: 220-* Failure to abide by the above statement will result in your server S: 220-* being permanently banned from connecting in the future. S: 220-* S: 220-* Please report any other problems to postmaster@mydomain.com S: 220 * C: EHLO [192.168.1.9] S: 250-mydomain.com Hello [192.168.1.9] [192.168.1.9], pleased to meet you S: 250-ETRN S: 250-8BITMIME S: 250-ENHANCEDSTATUSCODES S: 250-STARTTLS S: 250 SIZE 40960000 C: STARTTLS S: 220 2.7.0 Ready to start TLS

So I disabled STARTTLS which I don’t mind seeing as it’s a local mail server, and the job now completes fully.

The SMTP settings I use are the same for the other 6 machines I use, so I don’t know why the Pi doesn’t like it. Perhaps I’m missing a package or there’s a bug in the Debian version. I will keep looking.

7

I am using those options on Windows computers and backing up to linux computers or USB Drives.

I am glad you got it sorted. I think it is strange that a mail server setting was causing that problem. This issue makes me nervous because I get no EMail notifying me of a failure because it is hung up and never times out.

As to mail… here are my mail settings…

–send-mail-level=Error,Fatal
--send-mail-from=user@blahblah.com
--send-mail-to=user@blahblah.com
--send-mail-username=user@blahblah.com
–send-mail-password=******
–send-mail-subject=Duplicati Backup: COMPUTERNAMEHERE
–send-mail-url=smtp://mail.mailserver.com:587/?starttls=when-available

8

The change I made was:

–send-mail-url=smtp://mail.mydomain.com:25/?starttls=never

As it’s my own internal mail server I can allow an unauthenticated connection so I don’t have clear-text credentials.

9

I just checked my mail log and can see these failures:

Wed 2019-03-06 08:45:39.815: 02: [479312] ← EHLO [192.168.1.9]
Wed 2019-03-06 08:45:39.815: 03: [479312] → 250-mydomain.com Hello [192.168.1.9] [192.168.1.9], pleased to meet you
Wed 2019-03-06 08:45:39.815: 03: [479312] → 250-ETRN
Wed 2019-03-06 08:45:39.815: 03: [479312] → 250-8BITMIME
Wed 2019-03-06 08:45:39.815: 03: [479312] → 250-ENHANCEDSTATUSCODES
Wed 2019-03-06 08:45:39.815: 03: [479312] → 250-STARTTLS
Wed 2019-03-06 08:45:39.815: 03: [479312] → 250 SIZE 40960000
Wed 2019-03-06 08:45:39.816: 02: [479312] ← STARTTLS
Wed 2019-03-06 08:45:39.816: 03: [479312] → 220 2.7.0 Ready to start TLS
Wed 2019-03-06 08:45:39.823: 04: [479312] * SSL error 0x80090331 The client and server cannot communicate, because they do not possess a common algorithm.
Wed 2019-03-06 08:45:39.823: 04: [479312] SMTP session terminated (Bytes in/out: 120/685)