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!