Duplicati initial backup finished, then starts again

brettyj · August 27, 2017, 10:29pm

Hi Folks,

Just started using Duplicati with Backblaze B2, it spent 3 days backing up 50GB of data, it finally finished and then it seems to be backing up another 50GB…?

It’s running on Windows Server 2016 backing up a folder on a ReFS drive.

The error messages are of these ilk:

Error reported while accessing file: D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2\
System.UnauthorizedAccessException: Access to the path 'D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2' is denied.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileSystemEnumerableIterator`1.CommonInit()
   at System.IO.Directory.GetFiles(String path)
   at Duplicati.Library.Snapshots.NoSnapshotWindows.ListFiles(String folder)
   at Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__22.MoveNext()

Failed to process metadata for "D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2\", storing empty metadata
System.UnauthorizedAccessException: Attempted to perform an unauthorized operation.
   at System.Security.AccessControl.Win32.GetSecurityInfo(ResourceType resourceType, String name, SafeHandle handle, AccessControlSections accessControlSections, RawSecurityDescriptor& resultSd)
   at System.Security.AccessControl.NativeObjectSecurity.CreateInternal(ResourceType resourceType, Boolean isContainer, String name, SafeHandle handle, AccessControlSections includeSections, Boolean createByName, ExceptionFromErrorCode exceptionFromErrorCode, Object exceptionContext)
   at System.Security.AccessControl.FileSystemSecurity..ctor(Boolean isContainer, String name, AccessControlSections includeSections, Boolean isDirectory)
   at System.Security.AccessControl.DirectorySecurity..ctor(String name, AccessControlSections includeSections)
   at Duplicati.Library.Snapshots.SystemIOWindows.GetAccessControlDir(String path)
   at Duplicati.Library.Snapshots.SystemIOWindows.GetMetadata(String path, Boolean isSymlink, Boolean followSymlink)
   at Duplicati.Library.Main.Operation.BackupHandler.GenerateMeta

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 18289
OpenedFiles: 18289
AddedFiles: 18278
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 61460771057
SizeOfExaminedFiles: 61460771057
SizeOfOpenedFiles: 61460771057
NotProcessedFiles: 0
AddedFolders: 1677
TooLargeFiles: 0
FilesWithError: 11
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults: null
DeleteResults:
    DeletedSets: []
    Dryrun: False
    MainOperation: Delete
    CompactResults: null
    ParsedResult: Success
    EndTime: 27/08/2017 13:14:48
    BeginTime: 27/08/2017 13:14:43
    Duration: 00:00:05.4448338
    BackendStatistics:
        RemoteCalls: 2159
        BytesUploaded: 56298045089
        BytesDownloaded: 54256023
        FilesUploaded: 2149
        FilesDownloaded: 3
        FilesDeleted: 0
        FoldersCreated: 0
        RetryAttempts: 5
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 2149
        KnownFileSize: 56298045089
        LastBackupDate: 23/08/2017 18:45:14
        BackupListCount: 1
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ParsedResult: Success
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20170823T174514Z.dlist.zip.aes
        Value: [],
        Key: duplicati-i37115728cf9d45d5b4ab9d787a24cd15.dindex.zip.aes
        Value: [],
        Key: duplicati-b9d1f1af1bdc54759855c285dcdf9d255.dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    EndTime: 27/08/2017 13:16:38
    BeginTime: 27/08/2017 13:15:23
    Duration: 00:01:15.4604669
ParsedResult: Error
EndTime: 27/08/2017 13:16:38
BeginTime: 23/08/2017 17:45:14
Duration: 3.19:31:23.9927161
Messages: [
    Renaming "duplicati-iedc7df7c421949cdbc91fc5b26e1eff3.dindex.zip.aes" to "duplicati-ib1dc2f050b98487cb0da3478fae43f79.dindex.zip.aes",
    Renaming "duplicati-b0a46cd4d76964904b413713246a2c464.dblock.zip.aes" to "duplicati-bc53646fc2f04444388c4fe7d844b306e.dblock.zip.aes",
    Renaming "duplicati-ba6764df2933d4daeb9aa5d9120bb8d7a.dblock.zip.aes" to "duplicati-bee9903efd36446839d0774e0ca5851c7.dblock.zip.aes",
    Renaming "duplicati-bf285c972b7dc405089d99c4e9b92f8bc.dblock.zip.aes" to "duplicati-b18b88a6f63d745958212c8c75d723cd6.dblock.zip.aes",
    Renaming "duplicati-i663144296ab2467e8690af26fccb35eb.dindex.zip.aes" to "duplicati-id5ec4c0e1ffb4dbbaf9fe1ab667edc93.dindex.zip.aes",
...
]
Warnings: [
    Failed to process metadata for "D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2\", storing empty metadata => Attempted to perform an unauthorized operation.,
    Error reported while accessing file: D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2\ => Access to the path 'D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2' is denied.,
    Error reported while accessing file: D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2\ => Access to the path 'D:\Important Files\Shared\.TemporaryItems\folders.1033397298\Cleanup At Startup\.BAH.HIiu2' is denied.,
    Failed to process metadata for "D:\Important Files\Home\.DS_Store", storing empty metadata => Attempted to perform an unauthorized operation.,
    Failed to process path: D:\Important Files\Home\.DS_Store => Access to the path 'D:\Important Files\Home\.DS_Store' is denied.,
...
]
Errors: []

removing file listed as Deleting: duplicati-i663144296ab2467e8690af26fccb35eb.dindex.zip.aes

I suspect I shouldn’t be too worried about the 11 files error? But can anyone explain why it’s started backing up another 50GB when most of this data (if not all) wouldn’t have changed?

Thanks

kenkendk · August 28, 2017, 9:40am

It should not be uploading the 50GB again.
The message displayed is the scanning process where it looks through the 50GB to see if anything has changed.

tophee · August 28, 2017, 11:12am

I edited your post to improve the formating. (Just added ~~~ before and after the output you pasted, see here for details).

brettyj · August 28, 2017, 12:11pm

It’s definitely uploading something. It’s maxing out my upload speed and my b2 bucket now has 60gb of data in, bearing in mind this data is rarely changed

kenkendk · August 28, 2017, 5:07pm

If you go to the “Log” area, then choose the “Live” tab and set the level to “Profiling” you should see what files it is processing.

brettyj · August 31, 2017, 9:56am

Hi,

Sorry for late reply, been busy - it’s definitely uploading, it’s maxing out my connection and the “to go” is going down slowly. The profiling live log shows it is doing "put"s - although it’s not telling me which files (the filenames are encrypted)

Thanks

kenkendk · September 1, 2017, 10:52am

I don’t know why it happens, but maybe you can look at the backups after it completed and see what has changed.

Since you see encrypted filenames, could it be that you are uploading both an encrypted and non-encrypted copy of the same files?

drakar2007 · September 1, 2017, 4:34pm

FWIW, it looks to me like the “error messages” generated here are not actual issues in any real sense - all of the files listed look to me like they’re temporary system files currently open and in use by some application or OS process, and to be honest you probably should be filtering those out on a directory level to prevent duplicati from even trying to back them up (as they would probably be worthless in a restore).

Also if your inital backup took 3 days, and you have your backup frequency set to anything less than 3 days, the reason it’s running again right away is because (seemingly) it will queue all “missed” backup timeslots and run them immediately upon completion of the previous backup job. I find myself wishing that it would schedule a bit more smartly than this, but since I’m in my initial bulk backup phase too, for now I’ve just disabled the scheduler and start backup jobs manually between adding new chunks of files to my backup set - that way I don’t get the scheduler tripping over itself because of the fact that it doesn’t know to ignore or supersede scheduled jobs when the previous job is still running.

About the “re upload” thing - and this is only guesswork -
From the log file you posted, it appears as if your 3 day upload examined 61460771057 bytes and uploaded 56298045089 (which Duplicati will display as 52GB since it uses Gibibytes instead of Gigabytes). When the upload starts again, if any files have changed or been added to the backup set, Duplicati seems to start the countdown at “full size” when the backup begins, skips everything that’s already been uploaded, but then when the new content is being uploaded, the “Remaining…” number will reflect BOTH the amount of new data to be uploaded, PLUS the amount of already-uploaded data it still has to iterate through during that backup set.

For instance if I add 10 new GB worth of data to a set where I’ve already backed up 100, and it falls exactly in the “middle” (i’m not sure how or why, but i’ve observed that it acts this way as far as I can tell) - when it’s uploading the 10 new GB it will say “60 GB to go…” and count down from ~60 to ~50, and after it’s uploaded all the new stuff, the last 50 will go by very quickly again as it detects that it’s all been uploaded already.

I’m not sure if I’ve gotten all the technical details correct here, but from what I’ve been able to gather so far in backing up ~300gb on my PC, this is pretty close.

Edited to add: To support my above assumptions, I just edited my backup set on my main PC to include my Blu-Ray rips folder (96 gigabytes even), then started a new backup cycle. It is currently uploading, claiming “183.72GB to go” - yet I already know that no more than 96GB of that is new stuff to be uploaded.

At this point I only wish there was some way (like in the Information-level logs at least) to see which file is currently being worked on - if nothing other than out of curiosity.

kenkendk · September 4, 2017, 10:32am

Yes, but Duplicati cannot know which files are changed and which are not. It scans ahead to find the full size of files. The number reported is the size of the files it has not yet examined. Some of the remaining files may turn out to not be modified, but there is not way to guess that in advance. The stalling happens because the upload is active and too much work is in the upload queue.

I am looking into a better way to see how to communicate this.

If you choose “Log” in the menu on the right, and then choose “Live” and set the level to “Profiling” it will show the filenames. But we could also show a tooltip or similar with more information, like the name of the current file, how far in the file etc.

drakar2007 · September 4, 2017, 12:01pm

This is what I suspected I guess - though i’m a little surprised there’s no way to put the scan for changes more up-front in the operation. I think I mentioned in another thread, a reasonable workaround for me would be to at least have an indicator of “total bytes uploaded so far this session” - so if I know how much I added (which is sometimes), I can at least be aware of how close the current backup run is to being complete.

The problem with the Profiling log level is, it spams the log view with so much info as to be nearly unusable (and makes the browser unresponsive it seems). I find myself wanting maybe an additional log level between “profiling” and “information” which would show mostly just the stuff in “information”, but also which filename(s) were most recently grabbed.

I like this idea too

ttfn · September 18, 2017, 8:32pm

that seems to be exactly the behaviour I am now seeing having taken about 6 days for my initial backup. My schedule was to backup every 6 hours. So I guess I have about 24 queued backups! Is there any way to kill these without loosing the backup and starting again?

kees-z · September 19, 2017, 7:52am

AFAIK, Duplicati will not queue more than one backup for each job. So if you missed 10 backup operations, one backup will be started to catch up all missed backups.