Smart retention problem w Google Drive

1

Hi,
occasionally duplicati deletes the previous days backup on google drive.
I run backups every day at 05.00am.
I run 2.0.3.8 on macos but have seen this on previous versions and also on linux.
My retention settings: 1D:U,1W:1D,4W:1W,12M:1M
I also run the same job with B2 backend but has never seen the problem there.

This is part of the latest log (30 june 05.00) where it incorrectly deletes the previous day backup (29 june 05.00):

] 
Warnings: [] 
Errors: [] 
TaskReader: null 
DeleteResults: **
DeletedSets: [ 
	Item1: 1 
	Item2: 2018-06-29 05:00:01 ** (1530241201)
] Dryrun: False 
MainOperation: Delete 
ParsedResult: Success 
Version: 2.0.3.8 (2.0.3.8_canary_2018-06-28) 
EndTime: 2018-06-30 05:12:10 (1530328330) 
BeginTime: 2018-06-30 05:11:54 (1530328314) 
Duration: 00:00:15.8072080 
Messages: [ 
	2018-06-30 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started, 
	2018-06-30 05:04:39 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (), 
	2018-06-30 05:04:46 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (165 bytes), 
	2018-06-30 05:11:02 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b9df0f085712b4fb5ab6c5abd8d6173d3.dblock.zip.aes (49,91 MB), 
	2018-06-30 05:11:10 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b9df0f085712b4fb5ab6c5abd8d6173d3.dblock.zip.aes (49,91 MB), 
	...
2

The retention policy stuff seems like it should be simple, but it gets confusing quickly.

I’m not an expert, but I believe the 1D:U,1W:1D,4W:1W,12M:1M retention rule you’ve got breaks down like the following. Note that ALL times are relative to when a backup job runs and once a version is “claimed” by a rule, it is ignore in any following rules.

  • 1D:U = for 24 hours, keep unlimited backups
  • 1W:1D = for 168 hours, keep no more than 1 “unclaimed” backup in any 24 hours period
  • 4W:1W = for 672 hours, keep no more than 1 “unclaimed” backup in any 168 hour period
  • 12M:1M = for 8,760 hours, keep no more than 1 “unclaimed” backup in any 744 hour period

Is it possible the times when Duplicati deleted the previous day’s backup you might have done a manual backup causing TWO backups to exist in the day AFTER the first 24 hour “unlimited” period?

You might want to consider adding --full-result or --verbose to your job to try and get more detail in the “DeleteResults:” section of the Results.

If this gets too long in your emails, instead try using the --log-file parameter along with --log-file-log-level.

(By the way, I edited your post to make the log you shared more readable.)

3

Hi, thanks for ypur answer,

I have had the same problem when I just selected ‘Smart backup retention’ choice without manually specifying the retention policy.

I do not take manual backups between the scheduled ones (tried it once or twice)

I run the same settings with B2 backend without having ever seen this problem on that backend.

I’ll try the --full-result and see if I get more relevant information.

4

Thanks!

As I said before retention policy at first looks like it should be simple, but it really is quite complicated so it’s entirely possible you’ve found a bug that we missed in testing. I look forward to finding out if that’s the case! :slight_smile:

5

Hi,
today (5 jul) the prevoius days backup was deleted again.
Below is log with --full-results option:

6 
DeletedFiles: 87
DeletedFolders: 103
ModifiedFiles: 26
ExaminedFiles: 36791
OpenedFiles: 26
AddedFiles: 0
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 0
SizeOfExaminedFiles: 3230874275
SizeOfOpenedFiles: 362632701
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 22
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.3.7 (2.0.3.7_canary_2018-06-17)
    EndTime: 2018-07-05 05:09:26 (1530760166)
    BeginTime: 2018-07-05 05:09:20 (1530760160)
    Duration: 00:00:06.0196200
    Messages: [
        2018-07-05 05:00:03 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-05 05:03:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-05 05:03:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
        2018-07-05 05:08:21 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
        2018-07-05 05:08:29 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
    BackendStatistics:
        RemoteCalls: 12
        BytesUploaded: 100893985
        BytesDownloaded: 37172183
        FilesUploaded: 5
        FilesDownloaded: 3
        FilesDeleted: 2
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 161
        KnownFileSize: 3721925309
        LastBackupDate: 2018-07-05 05:00:03 (1530759603)
        BackupListCount: 11
        TotalQuotaSpace: 107374182400
        FreeQuotaSpace: 29552436738
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.3.7 (2.0.3.7_canary_2018-06-17)
        Messages: [
            2018-07-05 05:00:03 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-07-05 05:03:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-07-05 05:03:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
            2018-07-05 05:08:21 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
            2018-07-05 05:08:29 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
...
        ]
        Warnings: []
        Errors: []
        TaskReader: null
DeleteResults:
    DeletedSets: [
        Item1: 1
        Item2: 2018-07-04 05:00:00 (1530673200),
        Item1: 6
        Item2: 2018-06-28 05:00:04 (1530154804)
    ]
    Dryrun: False
    MainOperation: Delete
    ParsedResult: Success
    Version: 2.0.3.7 (2.0.3.7_canary_2018-06-17)
    EndTime: 2018-07-05 05:09:26 (1530760166)
    BeginTime: 2018-07-05 05:09:09 (1530760149)
    Duration: 00:00:16.8181700
    Messages: [
        2018-07-05 05:00:03 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-05 05:03:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-05 05:03:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
        2018-07-05 05:08:21 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
        2018-07-05 05:08:29 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20180705T030003Z.dlist.zip.aes
        Value: [],
        Key: duplicati-i232fd352e3874c4aa86d0b50e1818589.dindex.zip.aes
        Value: [],
        Key: duplicati-ba9924ac443cf41158dc38fc4d5fe8fef.dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    Version: 2.0.3.7 (2.0.3.7_canary_2018-06-17)
    EndTime: 2018-07-05 05:09:39 (1530760179)
    BeginTime: 2018-07-05 05:09:29 (1530760169)
    Duration: 00:00:10.2404680
    Messages: [
        2018-07-05 05:00:03 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-05 05:03:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-05 05:03:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
        2018-07-05 05:08:21 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
        2018-07-05 05:08:29 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
ParsedResult: Success
Version: 2.0.3.7 (2.0.3.7_canary_2018-06-17)
EndTime: 2018-07-05 05:09:39 (1530760179)
BeginTime: 2018-07-05 05:00:00 (1530759600)
Duration: 00:09:39.4554890
Messages: [
    2018-07-05 05:00:03 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-07-05 05:03:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-07-05 05:03:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
    2018-07-05 05:08:21 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
    2018-07-05 05:08:29 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bedc323e1378f4630af345c9ebfffc602.dblock.zip.aes (49,90 MB),
...
]
Warnings: []
Errors: []
TaskReader:
    ProgressAsync:
        Result: True
        Factory:
            CancellationToken:
                IsCancellationRequested: False
                CanBeCanceled: False
                WaitHandle:
                    Handle: 140229088394936
                    SafeWaitHandle:
                        IsInvalid: False
                        IsClosed: False
            Scheduler: null
            CreationOptions: None
            ContinuationOptions: None
        Id: 1
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        IsCompletedSuccessfully: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
    TransferProgressAsync:
        Result: True
        Id: 2
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        IsCompletedSuccessfully: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
7

Thanks for the detail!

While @renestach is probably the expert on this, what I think what might be happening is you’re getting a run (like on 06/28) that is just a little bit later than the rest (like 05:00:04 not exactly at 05:00:00). This causes that run to roll over to a different retention “bucket” which makes it do things you don’t expect.

Are you able to check logs or emails of the other ones that got deleted unexpectedly and see if they also were “next to” a run that didn’t have an exact 05:00:00 time on it?

If you notice they all do, perhaps tweaking your retention policy to start with something like 1445m:U instead of 1D:U will give you a 5 minute buffer to ignore jobs that run a little late.

Unfortunately the --full-results didn’t give what I was looking for so while we wait for renestach to hopefully have a chance to take a look at this we can try something else.

I tried running a backup using the “Commandline…” interface in the GUI and adding --dry-run=true and --console-log-level=Information to the options which gave me the results below where I can see which backups would be deleted due to my retention rules (if I weren’t running --dry-run-true), but not WHY they’re being deleted.

Backup started at 7/5/2018 2:17:28 PM
The operation Backup has started
Checking remote backup ...
Backend event: List - Started:  ()
  Listing remote folder ...
Backend event: List - Completed:  (51 bytes)
Scanning local files ...
  1 files need to be examined (0 bytes)
[Dryrun]: Would upload volume: duplicati-bffa2fab317b14ebbb4abf597bb566302.dblock.zip, size: 4.66 MB
[Dryrun]: Would upload volume: duplicati-ifb75b6f7315243cdb0c29690c05d5120.dindex.zip, size: 9.19 KB
  3542 files need to be examined (153.10 MB)
[Dryrun]: Would upload volume: duplicati-20180705T191728Z.dlist.zip, size: 363.91 KB
Start checking if backups can be removed
Time frames and intervals pairs: 31.00:00:00 / 1.00:00:00, 730.00:00:00 / Keep all, Unlimited / Keep all
Backups to consider: 6/28/2018 10:23:27 AM, 6/26/2018 10:33:29 AM, 6/25/2018 9:28:54 AM, 6/25/2018 9:18:48 AM, 6/22/2018 2:06:29 PM, 6/22/2018 11:30:03 AM, 6/22/2018 10:48:58 AM, 6/20/2018 10:26:15 PM, 6/19/2018 11:55:18 AM, 6/19/2018 11:48:31 AM, 5/11/2018 2:51:47 PM, 5/11/2018 2:47:59 PM, 5/10/2018 3:29:51 PM, 4/10/2018 3:58:30 PM, 4/4/2018 2:36:51 PM, 4/4/2018 1:15:41 PM
Backups outside of all time frames and thus getting deleted: 
------> All backups to delete: 6/25/2018 9:28:54 AM, 6/22/2018 2:06:29 PM, 6/22/2018 11:30:03 AM, 6/19/2018 11:55:18 AM
Deleting 4 remote fileset(s) ...
[Dryrun]: Would delete remote fileset: duplicati-20180619T165518Z.dlist.zip
[Dryrun]: Would delete remote fileset: duplicati-20180622T163003Z.dlist.zip
[Dryrun]: Would delete remote fileset: duplicati-20180622T190629Z.dlist.zip
[Dryrun]: Would delete remote fileset: duplicati-20180625T142854Z.dlist.zip
[Dryrun]: 4 remote fileset(s) would be deleted
[Dryrun]: Remove --dry-run to actually delete files
Compacting because there are 1 fully deletable volume(s)
[Dryrun]: Would delete remote file: duplicati-b206dbd683f4048b1a137c3804f27d9c1.dblock.zip, size: 3.94 MB
[Dryrun]: Would delete remote file: duplicati-ia98238a0dc404cb1b96b5c313a81abc4.dindex.zip, size: 9.75 KB
[Dryrun]: Would delete 2 files, which would reduce storage by 3.95 MB
[Dryrun]: Would upload verification file: duplicati-verification.json, size: 23.90 KB
Email sent successfully using server: 
  0 files need to be examined (0 bytes)
  Duration of backup: 00:03:55
  Remote files: 49
  Remote size: 244.98 MB
  Total remote quota: 195.54 GB
  Available remote quota: 41.52 GB
  Files added: 0
  Files deleted: 0
  Files changed: 92
  Data uploaded: 0 bytes
  Data downloaded: 0 bytes
Backup completed successfully!
Return code: 1
8

hi, thanks for your answer, below is the log from 4 jul which got deleted.
about tweaking the retention policy, wouldn’t the set just get deleted on the following run?
I also find it interesting that I only have seen this on Google Drive and not on B2 which runs half an hour later.

9 
DeletedFiles: 2
DeletedFolders: 0
ModifiedFiles: 226
ExaminedFiles: 36878
OpenedFiles: 412
AddedFiles: 186
SizeOfModifiedFiles: 197960444
SizeOfAddedFiles: 2101619
SizeOfExaminedFiles: 3227136044
SizeOfOpenedFiles: 203040985
NotProcessedFiles: 0
AddedFolders: 90
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 68
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.3.8 (2.0.3.8_canary_2018-06-28)
    EndTime: 2018-07-04 05:06:19 (1530673579)
    BeginTime: 2018-07-04 05:06:13 (1530673573)
    Duration: 00:00:06.6796760
    Messages: [
        2018-07-04 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-04 05:01:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-04 05:01:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
        2018-07-04 05:05:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
        2018-07-04 05:05:57 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
    BackendStatistics:
        RemoteCalls: 11
        BytesUploaded: 45201111
        BytesDownloaded: 52591191
        FilesUploaded: 3
        FilesDownloaded: 3
        FilesDeleted: 3
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 158
        KnownFileSize: 3627972966
        LastBackupDate: 2018-07-04 05:00:00 (1530673200)
        BackupListCount: 12
        TotalQuotaSpace: 107374182400
        FreeQuotaSpace: 29449717986
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.3.8 (2.0.3.8_canary_2018-06-28)
        Messages: [
            2018-07-04 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-07-04 05:01:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-07-04 05:01:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
            2018-07-04 05:05:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
            2018-07-04 05:05:57 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
...
        ]
        Warnings: []
        Errors: []
        TaskReader: null
DeleteResults:
    DeletedSets: [
        Item1: 2
        Item2: 2018-07-03 05:00:00 (1530586800),
        Item1: 3
        Item2: 2018-07-02 08:04:48 (1530511488),
        Item1: 8
        Item2: 2018-06-27 05:00:03 (1530068403)
    ]
    Dryrun: False
    MainOperation: Delete
    ParsedResult: Success
    Version: 2.0.3.8 (2.0.3.8_canary_2018-06-28)
    EndTime: 2018-07-04 05:06:19 (1530673579)
    BeginTime: 2018-07-04 05:06:02 (1530673562)
    Duration: 00:00:16.9830650
    Messages: [
        2018-07-04 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-04 05:01:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-04 05:01:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
        2018-07-04 05:05:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
        2018-07-04 05:05:57 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20180704T030000Z.dlist.zip.aes
        Value: [],
        Key: duplicati-i3ee47fb9d78443d181f2e3010f2d2c34.dindex.zip.aes
        Value: [],
        Key: duplicati-b0d71d57a2b884ed3a65048b50f0362f6.dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    Version: 2.0.3.8 (2.0.3.8_canary_2018-06-28)
    EndTime: 2018-07-04 05:06:35 (1530673595)
    BeginTime: 2018-07-04 05:06:22 (1530673582)
    Duration: 00:00:12.3628410
    Messages: [
        2018-07-04 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-04 05:01:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-04 05:01:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
        2018-07-04 05:05:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
        2018-07-04 05:05:57 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
ParsedResult: Success
Version: 2.0.3.8 (2.0.3.8_canary_2018-06-28)
EndTime: 2018-07-04 05:06:35 (1530673595)
BeginTime: 2018-07-04 05:00:00 (1530673200)
Duration: 00:06:35.1494710
Messages: [
    2018-07-04 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-07-04 05:01:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-07-04 05:01:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (158 bytes),
    2018-07-04 05:05:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
    2018-07-04 05:05:57 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b1a91eb952028433586c93dacfb201dd0.dblock.zip.aes (39,65 MB),
...
]
Warnings: []
Errors: []
TaskReader:
    ProgressAsync:
        Result: True
        Factory:
            CancellationToken:
                IsCancellationRequested: False
                CanBeCanceled: False
                WaitHandle:
                    Handle: 140289822027512
                    SafeWaitHandle:
                        IsInvalid: False
                        IsClosed: False
            Scheduler: null
            CreationOptions: None
            ContinuationOptions: None
        Id: 21
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        IsCompletedSuccessfully: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
    TransferProgressAsync:
        Result: True
        Id: 22
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        IsCompletedSuccessfully: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
10

deleted backup happened today again, what can I do to investigate this further?

11

Another log where previous days backup was deleted.

DeletedFiles: 4
DeletedFolders: 0
ModifiedFiles: 76
ExaminedFiles: 36710
OpenedFiles: 78
AddedFiles: 2
SizeOfModifiedFiles: 365600190
SizeOfAddedFiles: 19448832
SizeOfExaminedFiles: 3275782017
SizeOfOpenedFiles: 385231552
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
    DeletedFileCount: 32
    DownloadedFileCount: 16
    UploadedFileCount: 4
    DeletedFileSize: 677412240
    DownloadedFileSize: 675676288
    UploadedFileSize: 54162371
    Dryrun: False
    MainOperation: Compact
    ParsedResult: Success
    Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
    EndTime: 2018-07-15 05:10:55 (1531624255)
    BeginTime: 2018-07-15 05:08:27 (1531624107)
    Duration: 00:02:28.1182120
    Messages: [
        2018-07-15 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-15 05:02:42 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-15 05:02:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (172 bytes),
        2018-07-15 05:07:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
        2018-07-15 05:07:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
    BackendStatistics:
        RemoteCalls: 64
        BytesUploaded: 148539045
        BytesDownloaded: 717968359
        FilesUploaded: 9
        FilesDownloaded: 19
        FilesDeleted: 34
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 147
        KnownFileSize: 3371376679
        LastBackupDate: 2018-07-15 05:00:00 (1531623600)
        BackupListCount: 11
        TotalQuotaSpace: 107374182400
        FreeQuotaSpace: 29413976740
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
        Messages: [
            2018-07-15 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-07-15 05:02:42 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-07-15 05:02:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (172 bytes),
            2018-07-15 05:07:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
            2018-07-15 05:07:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
...
        ]
        Warnings: []
        Errors: []
        TaskReader: null
DeleteResults:
    DeletedSets: [
        Item1: 1
        Item2: 2018-07-14 05:00:03 (1531537203),
        Item1: 6
        Item2: 2018-07-08 05:00:01 (1531018801)
    ]
    Dryrun: False
    MainOperation: Delete
    ParsedResult: Success
    Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
    EndTime: 2018-07-15 05:10:55 (1531624255)
    BeginTime: 2018-07-15 05:08:17 (1531624097)
    Duration: 00:02:38.3084350
    Messages: [
        2018-07-15 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-15 05:02:42 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-15 05:02:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (172 bytes),
        2018-07-15 05:07:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
        2018-07-15 05:07:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20180715T030000Z.dlist.zip.aes
        Value: [],
        Key: duplicati-i9745e1742147471aaad2c341b308ee69.dindex.zip.aes
        Value: [],
        Key: duplicati-b827aa0c5d68e46078096e7ad3c99a957.dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
    EndTime: 2018-07-15 05:11:09 (1531624269)
    BeginTime: 2018-07-15 05:10:58 (1531624258)
    Duration: 00:00:10.6035430
    Messages: [
        2018-07-15 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-15 05:02:42 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-15 05:02:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (172 bytes),
        2018-07-15 05:07:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
        2018-07-15 05:07:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
ParsedResult: Success
Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
EndTime: 2018-07-15 05:11:09 (1531624269)
BeginTime: 2018-07-15 05:00:00 (1531623600)
Duration: 00:11:09.0393580
Messages: [
    2018-07-15 05:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-07-15 05:02:42 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-07-15 05:02:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (172 bytes),
    2018-07-15 05:07:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
    2018-07-15 05:07:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bffadae93e87f424bab6aa58b3ca1bfbf.dblock.zip.aes (49,91 MB),
...
]
Warnings: []
Errors: []
TaskReader:
    ProgressAsync:
        Result: True
        Factory:
            CancellationToken:
                IsCancellationRequested: False
                CanBeCanceled: False
                WaitHandle:
                    Handle: 140424073337160
                    SafeWaitHandle:
                        IsInvalid: False
                        IsClosed: False
            Scheduler: null
            CreationOptions: None
            ContinuationOptions: None
        Id: 7
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        IsCompletedSuccessfully: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
    TransferProgressAsync:
        Result: True
        Id: 8
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        IsCompletedSuccessfully: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
12

really would appreciate if any developer could have a look at this issue.

13

some info from file log

2018-07-15 05:08:17 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed
2018-07-15 05:08:17 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 1.00:00:00 / Keep all, 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00
2018-07-15 05:08:17 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 2018-07-14 05:00:03, 2018-07-13 07:27:54, 2018-07-12 05:00:04, 2018-07-11 05:00:00, 2018-07-09 05:00:01, 2018-07-08 05:00:01, 2018-07-03 07:04:04, 2018-06-26 05:00:01, 2018-06-18 07:23:47, 2018-06-03 05:00:00, 2018-04-26 05:00:01, 2018-03-18 11:24:38
2018-07-15 05:08:17 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted:
2018-07-15 05:08:17 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: 2018-07-14 05:00:03, 2018-07-08 05:00:01
2018-07-15 05:08:17 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 2 remote fileset(s) …
2018-07-15 05:08:26 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20180708T030001Z.dlist.zip.aes (3,33 MB)
2018-07-15 05:08:26 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20180708T030001Z.dlist.zip.aes (3,33 MB)
2018-07-15 05:08:26 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20180714T030003Z.dlist.zip.aes (3,33 MB)
2018-07-15 05:08:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20180714T030003Z.dlist.zip.aes (3,33 MB)
2018-07-15 05:08:27 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: Deleted 2 remote fileset(s)

14

Are you still using your original retention rules or did you try adjusting any of the timeframes?

I’ve already ‘pinged’ the main developer of the retention rules but it appears he ether hasn’t seen it or had time to look into your issue.

Until he becomes available, I’d suggest you consider simplifying your retention policy until the issue goes away. That will help isolate which section is causing the behavior. Personally, my guess is the 1W:1D section is the problem - what happens if you change that to 1W:U?

Remember, this affects when existing backups are deleted - not when the backups are made. So you can always make a timeframe SMALLER at some point in the future to clean things up once we’ve pinned down the actual issue.

15

I’m currently running 1D:U,1W:1D,4W:1W,12M:1M
Changing now to 1D:U,1W:U,4W:1W,12M:1M
will see what happens.

Would a github issue be appropriate?
I don’t want this issue to be forgotten.

16

Adding this to GitHub would make sense once we’ve confirmed the source of the issue.

I think a fair number of users are using this feature but you’re only the second one I can recall having this issue, so a generic “it doesn’t work” post would likely just cause potential developers to test it and say “it works for me”.

Thanks for testing and letting us know how the 1W:U change affects things!

17

I’ve been running 1D:U,1W:U,4W:1W,12M:1M for a week now and no new missing backups.
While I can live with this there must be a bug somewhere.
Would be good to get this investigated further.

18

Hi @Mikael_Andersson,

I haven’t tried retention before, but I did today, and looked at history, and even took a stab at a code peek.

Thank you for the file log. It may explain the last deletion. We didn’t get enough version info for the others.

Retention Policy Algorithm

Initial Code

Current Code
(and it looks like you can get more verbose description of what it’s doing if you’re willing to file log at profile)

At 2018-07-15 05:08:17 after a backup, Duplicati thinned out versions by placing backup versions into time buckets, then thinned those when versions were too close. The thing that might be surprising is it keeps the oldest version in a bucket, which might be a good thing in itself, but also means the deletion of versions too close together runs from oldest to newest. Something’s got to go, and it might be the newest. A scan going newest to oldest might keep the newest one, then confuse people differently by deleting an older neighbor.

“Backups to consider: 2018-07-14 05:00:03, 2018-07-13 07:27:54, 2018-07-12 05:00:04, 2018-07-11 05:00:00, 2018-07-09 05:00:01, 2018-07-08 05:00:01, 2018-07-03 07:04:04, 2018-06-26 05:00:01, 2018-06-18 07:23:47, 2018-06-03 05:00:00, 2018-04-26 05:00:01, 2018-03-18 11:24:38” turns into

1W:1D bucket
2018-07-14 05:00:03, 2018-07-13 07:27:54, 2018-07-12 05:00:04, 2018-07-11 05:00:00, 2018-07-09 05:00:01
Delete 2018-07-14 05:00:03 because it’s less than a day since the delayed 2018-07-13 07:27:54

4W:1W bucket
2018-07-08 05:00:01, 2018-07-03 07:04:04, 2018-06-26 05:00:01, 2018-06-18 07:23:47, 2018-06-03 05:00:00, 2018-04-26 05:00:01, 2018-03-18 11:24:38
Delete 2018-07-08 05:00:01 because it’s less than a week since the older 2018-07-03 07:04:04

This feature has generated an amazing amount of interest, discussion, and unfortunately confusion.
Possibly the question of which direction version thinning should go in should be discussed in forum?

Retention Policy like Time Machine [$50] #2084

New retention policy deletes old backups in a smart way

19

thanks for looking into this.

If I understand correctly, if a scheduled backup is slightly delayed for some reason it will get deleted on the next run?

I understand the logic but it is certainly not what I would expect.
When running daily backups I would expect one backup per day to be kept.

20

I think it would be more like if a scheduled backup runs too soon after the one before it, it will be dropped when it ages into the thinned week after the initial day. Think of it as limited admission to control spacing,
With that model the natural processing order for thinning is oldest to newest, i.e. in the order of creation.

You might have noticed that thinning happens after backup, so I don’t think you can control timing tightly.

If you prefer versions to be very close to 1 day apart, make a lot and let those be thinned after initial day.
The problem there is that there’s nothing to keep the time of day of the finally-saved version from drifting.
You might also have more confidence in versions taken at off-hours, or not want to add load at peak time.

The reason version spacing looks so odd is because the only choices are to keep or delete any version, therefore the space between versions in the rest of the first week has to be either about 1 day or 2 days, given versions aging out at 1 day intervals give-or-take some amount. It’s sort of a worst-case scenario…

You can let the unavoidable timing variation be tolerated by allowing a closer spacing than exactly 1 day.
One can actually specify hours (h) minutes (m) and seconds (s) in combination with the larger time units.

The U you specified in 1W:U actually means zero time spacing, so maybe something like 1W:12h will do, however the result is the same unless ever actually take backups that get closer than the minimum time.

Having said all this, I’m new to it so possibly someone more expert will chime in. Try your own testing too.

Thanks!