Recovery not listing new backups

Support
1

Running Duplicati 2.0.4.4_canary_2018-11-14, for a specific backup that I checked, the latest backups are not selectable, although the backup jobs seem to have run successfully; some of the backups have recurring warnings, but that would be a separate issue.

I checked the logs, but cannot find anything that would hint a failure; the backup configuration json, however, looks a bit suspicious, especially the “Metadata” section:

"Metadata": {
      "LastErrorDate": "20180609T214626Z",
      "LastErrorMessage": "One or more errors occurred.",
      "LastDuration": "00:00:30.2144690",
      "LastStarted": "20180714T214500Z",
      "LastFinished": "20180714T214530Z",
      "LastBackupDate": "20180609T214543Z",
      "BackupListCount": "27",
      "TotalQuotaSpace": "0",
      "FreeQuotaSpace": "0",
      "AssignedQuotaSpace": "-1",
      "TargetFilesSize": "4727779737",
      "TargetFilesCount": "221",
      "TargetSizeString": "4.40 GB",
      "SourceFilesSize": "5124615252",
      "SourceFilesCount": "82",
      "SourceSizeString": "4.77 GB",
      "LastBackupStarted": "20181117T214523Z",
      "LastBackupFinished": "20181117T214841Z",
      "LastBackupDuration": "00:03:18.3358930"
    }

I created a bug report that I could share (with its ~6 MiB it exceeds the forum’s attachment limits).

With the backup configuration exported, and running a Duplicati instance on another machine, I get the same results, so I suspect the error is either due to the exported JSON, or the past backup jobs were indeed not successful and the data is missing in the remote storage (which is Amazon Cloud Drive, if that’s important to this issue).

Is there anything else that I can check?

2

When you say you check, do you mean see what’s listed in the restore process?

3

Exactly, I tried to restore files as check, and noticed that backups after a certain point in time are not listed in the dropdown. This is what I mean:

duplicati-selection-restore
duplicati-selection-restore.png628×542 33.6 KB

The backup runs weekly, so the entry unter Latest should be December 15, 2018, 10:50 PM.

This is what the last log for this backup looks like:

    DeletedFiles: 42
    DeletedFolders: 8
    ModifiedFiles: 1
    ExaminedFiles: 220
    OpenedFiles: 181
    AddedFiles: 180
    SizeOfModifiedFiles: 0
    SizeOfAddedFiles: 2165982056
    SizeOfExaminedFiles: 6693377950
    SizeOfOpenedFiles: 2165982134
    NotProcessedFiles: 0
    AddedFolders: 23
    TooLargeFiles: 0
    FilesWithError: 0
    ModifiedFolders: 0
    ModifiedSymlinks: 0
    AddedSymlinks: 0
    DeletedSymlinks: 0
    PartialBackup: False
    Dryrun: False
    MainOperation: Backup
    CompactResults: null
    DeleteResults: null
    RepairResults: null
    TestResults:
        MainOperation: Test
        Verifications: [
            Key: duplicati-20170527T214538Z.dlist.zip.aes
            Value: [],
            Key: duplicati-i95320da00877419192d59afa0ee37aad.dindex.zip.aes
            Value: [],
            Key: duplicati-b8de0a38ae3c64eb1a04e60377e3df20f.dblock.zip.aes
            Value: []
        ]
        ParsedResult: Success
        Version: 2.0.4.4 (2.0.4.4_canary_2018-11-14)
        EndTime: 12/15/2018 21:50:42 (1544910642)
        BeginTime: 12/15/2018 21:50:04 (1544910604)
        Duration: 00:00:38.4006930
        Messages: [
            2018-12-15 21:45:26 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet,
            2018-12-15 21:45:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-12-15 21:45:28 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (221 Bytes),
            2018-12-15 21:46:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc06d879c6c10428289da42c656641583.dblock.zip.aes (27,37 MB),
            2018-12-15 21:46:42 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bc06d879c6c10428289da42c656641583.dblock.zip.aes (27,37 MB),
    ...
        ]
        Warnings: []
        Errors: []
        BackendStatistics:
            RemoteCalls: 11
            BytesUploaded: 0
            BytesDownloaded: 52364471
            FilesUploaded: 0
            FilesDownloaded: 3
            FilesDeleted: 0
            FoldersCreated: 0
            RetryAttempts: 10
            UnknownFileSize: 0
            UnknownFileCount: 0
            KnownFileCount: 221
            KnownFileSize: 4727779737
            LastBackupDate: 06/09/2018 21:45:43 (1528580743)
            BackupListCount: 27
            TotalQuotaSpace: 0
            FreeQuotaSpace: 0
            AssignedQuotaSpace: -1
            ReportedQuotaError: False
            ReportedQuotaWarning: False
            ParsedResult: Success
            Version: 2.0.4.4 (2.0.4.4_canary_2018-11-14)
            Messages: [
                2018-12-15 21:45:26 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet,
                2018-12-15 21:45:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
                2018-12-15 21:45:28 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (221 Bytes),
                2018-12-15 21:46:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc06d879c6c10428289da42c656641583.dblock.zip.aes (27,37 MB),
                2018-12-15 21:46:42 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bc06d879c6c10428289da42c656641583.dblock.zip.aes (27,37 MB),
    ...
            ]
            Warnings: []
            Errors: []
    ParsedResult: Success
    Version: 2.0.4.4 (2.0.4.4_canary_2018-11-14)
    EndTime: 12/15/2018 21:50:43 (1544910643)
    BeginTime: 12/15/2018 21:45:26 (1544910326)
    Duration: 00:05:17.0644870
    Messages: [
        2018-12-15 21:45:26 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet,
        2018-12-15 21:45:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-12-15 21:45:28 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (221 Bytes),
        2018-12-15 21:46:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc06d879c6c10428289da42c656641583.dblock.zip.aes (27,37 MB),
        2018-12-15 21:46:42 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bc06d879c6c10428289da42c656641583.dblock.zip.aes (27,37 MB),
    ...
    ]
    Warnings: []
    Errors: []
4

Now that I look at it again, I never realized the lines with “Retrying” … would that be a hint somehow? [edit: fixed grammar]

Update: Checked the backend (Amazon Drive), and exceeded the quota :blush:, which would block additional put operations. This is totally my fault; however, in my defense, Duplicati did not warn me about this and acted as if everything was normal:

duplicati-overview

(Emphasis on Last successful backup, which dates to the last backup)

5

My original issue is solved, so I could mark this thread as solved.

However, I suspect there may be an issue lurking with respect to marking a backup failed / issueing an error when put operations to Amazon Drive are not successful. What’s the protocol here? Create a new thread as follow-up, or change this one to accomodate for the new insight?

6

There’s no hard rule so whatever works for you is fine. :slight_smile:

I’m surprised the “Put - Retrying:” events were not followed by put failures (then errors). It may have to do with the messages Amazon Drive returns (@kenkendk or @Pectojin might have a thought on that).

If you haven’t resolved the space issue yet, what happens if you are destination space parameter set to your storage size? (Sorry, don’t recall the parm now, will try to add later.)

Oh, and to show off a fun Discourse (our forum software) trick I added “~~~ json” and “~~~” around your log text. :slight_smile:

Edit:
I was thinking of these:

--quota-size
This value can be used to set a known upper limit on the amount of space a backend has. If the backend reports the size itself, this value is ignored
Default value: “”

--quota-warning-threshold
Sets a threshold for when to warn about the backend quota being nearly exceeded. It is given as a percentage, and a warning is generated if the amount of available quota is less that this percentage of the total backup size. If the backend does not report the quota information, this value will be ignored
Default value: “10”

7

This was a case where a backend failure wasn’t noticed at the time, and left a mess behind for the next run. Possibly the current article (even though it’s seemingly a different outcome) is suffering from a similar issue.