Hey everyone, same issue here.
I made a huge backup set of all my local drives, which totals to about 8TB of data in 2 million files (I’m guessing that was big a mistake, would splitting each drive into a set make things take less time in total?). By this point I’ve tried setting up backups in different ways in multiple versions of Duplicati, and run into a few problems each time (VSS breaking, IO bottlenecks, backing up through SMB eventually locking my server up, etc…).
Right now I’m using 2.0.4.4_canary_2018-11-14 on a 7700k with 16GB of ram running Windows 7 x64, with the database on an SSD and the temp folder on a mechanical disk.
Settings
--tempdir=N:\Duplicati\Temp
--asynchronous-upload-limit=1
--thread-priority=belownormal
--use-background-io-priority=true
--use-block-cache=true
--disable-file-scanner=true
--synchronous-upload=true
--disable-filelist-consistency-checks=true
--log-file=N:\Duplicati\log.txt
--log-file-log-level=Profiling
--backup-name=Full
--dbpath=C:\Users\Daniel\AppData\Roaming\Duplicati\NNHNWSPLGF.sqlite
--encryption-module=aes
--compression-module=zip
--dblock-size=5GB
--snapshot-policy=Required
--default-filters=Windows
--no-backend-verification=false
--disable-module=console-password-input
--exclude=D:\snapraid.content
--exclude=E:\Uplay\
--exclude=E:\Bethesda\
--exclude=E:\Battle.net\
--exclude=E:\Epic Games\
--exclude=E:\Steam\
--exclude=I:\snapraid.content
--exclude=E:\snapraid.content
--exclude=P:\snapraid.parity
--exclude=P:\snapraid.content
Duplicati Profiling info
(after 3 days on “Verifying backend data…”)
Dec 8, 2018 1:03 PM: Cannot open WMI provider \\localhost\root\virtualization. Hyper-V is probably not installed.
Dec 8, 2018 1:03 PM: Cannot find any MS SQL Server instance. MS SQL Server is probably not installed.
Dec 8, 2018 1:03 PM: Using WMI provider \\localhost\root\virtualization
Dec 6, 2018 11:54 PM: Starting - ExecuteReader: SELECT "A"."Hash", "C"."Hash" FROM (SELECT "BlocklistHash"."BlocksetID", "Block"."Hash", * FROM "BlocklistHash","Block" WHERE "BlocklistHash"."Hash" = "Block"."Hash" AND "Block"."VolumeID" = 732) A, "BlocksetEntry" B, "Block" C WHERE "B"."BlocksetID" = "A"."BlocksetID" AND "B"."Index" >= ("A"."Index" * 3200) AND "B"."Index" < (("A"."Index" + 1) * 3200) AND "C"."ID" = "B"."BlockID" ORDER BY "A"."BlocksetID", "B"."Index"
Dec 6, 2018 11:54 PM: ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = 732 took 0:00:00:00.002
Dec 6, 2018 11:54 PM: Starting - ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = 732
Backup log
MainOperation: Repair
RecreateDatabaseResults: null
ParsedResult: Warning
Version: 2.0.4.4 (2.0.4.4_canary_2018-11-14)
EndTime: 25/11/2018 05:03:59 (1543129439)
BeginTime: 25/11/2018 04:40:33 (1543128033)
Duration: 00:23:26.4120000
Messages: [
2018-11-25 04:40:33 -02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
2018-11-25 04:41:16 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-11-25 04:41:24 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (169 bytes),
2018-11-25 04:41:24 -02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-20181121T053703Z.dlist.zip.aes,
2018-11-25 04:41:25 -02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-20181122T224135Z.dlist.zip.aes,
...
]
Warnings: [
2018-11-25 04:40:33 -02 - [Warning-Duplicati.Library.Main.Controller-UnsupportedOption]: The supplied option --default-filters is not supported and will be ignored
]
Errors: []
BackendStatistics:
RemoteCalls: 1
BytesUploaded: 0
BytesDownloaded: 0
FilesUploaded: 0
FilesDownloaded: 0
FilesDeleted: 0
FoldersCreated: 0
RetryAttempts: 0
UnknownFileSize: 0
UnknownFileCount: 0
KnownFileCount: 169
KnownFileSize: 451490351253
LastBackupDate: 01/01/0001 00:00:00 (-62135589600)
BackupListCount: 0
TotalQuotaSpace: 17433015040055
FreeQuotaSpace: 6437898762295
AssignedQuotaSpace: -1
ReportedQuotaError: False
ReportedQuotaWarning: False
ParsedResult: Warning
Version: 2.0.4.4 (2.0.4.4_canary_2018-11-14)
Messages: [
2018-11-25 04:40:33 -02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
2018-11-25 04:41:16 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-11-25 04:41:24 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (169 bytes),
2018-11-25 04:41:24 -02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-20181121T053703Z.dlist.zip.aes,
2018-11-25 04:41:25 -02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-20181122T224135Z.dlist.zip.aes,
...
]
Warnings: [
2018-11-25 04:40:33 -02 - [Warning-Duplicati.Library.Main.Controller-UnsupportedOption]: The supplied option --default-filters is not supported and will be ignored
]
Errors: []
Full report of the steps I took
Maybe (just maybe) I’m being overly verbose here, but since I don’t know what caused this, might aswell right?
I started the backup for the first time and it was running fine for a day or two. I then had to reboot my computer for an unrelated reason. Before doing so, I clicked on “stop after upload”, but it kept going for a few hours longer than I could wait, so I clicked “stop now” and after it actually stopped I closed Duplicati through the tray icon. After the reboot, when trying to start the backup again, it failed with this error:
Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 1: 21/11/2018 03:37:03 (database id: 2), found 516559 entries, but expected 582184
em Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)
em Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass32_0.<VerifyConsistencyAsync>b__0()
em Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.<RunOnMain>b__0()
em Duplicati.Library.Main.Operation.Common.SingleRunner.<DoRunOnMain>d__2`1.MoveNext()
--- Fim do rastreamento de pilha do local anterior onde a exceção foi gerada ---
em System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
em System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
em System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
em Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__19.MoveNext()
--- Fim do rastreamento de pilha do local anterior onde a exceção foi gerada ---
em CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)
em Duplicati.Library.Main.Controller.<>c__DisplayClass13_0.<Backup>b__0(BackupResults result)
em Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)
em Duplicati.Library.Main.Controller.Backup(String[] inputsources, IFilter filter)
em Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)
Then, I clicked on “Repair Database” and after that the backup started again. This time, the “Verifying backend files…” part took about 24 hours, but after that it started backing up again. Not sure if this is relevant to this issue, but it was showing negative files and bytes in the progress bar, probably due to --disable-file-scanner=true.
The problem is, 8TB is a lot of data, and something will probably go wrong in the process of uploading all that. I had a power outage after about 1 week and 2TB uploaded, and now when starting the backup Duplicati got stuck on “Verifying backend files…” for 3 days, using 13% of CPU (1 full core). It was definetly doing something (or at least trying), as I could see activity on the db file in Resource Monitor. I tried opening the database in DB Browser after I stopped the backup to manually run that query, but it says its encrypted and my backup key doesn’t seem to be the same key for the database.
I’ve since set --no-backend-verification=true and tried again, but it seems stuck on that same query.
Server state properties
profiling-log.zip (3.0 KB)
lastEventId : 22
lastDataUpdateId : 5
lastNotificationUpdateId : 0
estimatedPauseEnd : 0001-01-01T00:00:00
activeTask : {"Item1":3,"Item2":"3"}
programState : Running
lastErrorMessage :
connectionState : connected
xsfrerror : false
connectionAttemptTimer : 0
failedConnectionAttempts : 0
lastPgEvent : {"BackupID":"3","TaskID":3,"BackendAction":"Delete","BackendPath":"duplicati-bed7b0f009ef5455187881debe4895f2d.dblock.zip.aes","BackendFileSize":-1,"BackendFileProgress":0,"BackendSpeed":-1,"BackendIsBlocking":false,"CurrentFilename":null,"CurrentFilesize":0,"CurrentFileoffset":0,"Phase":"Backup_PreBackupVerify","OverallProgress":0,"ProcessedFileCount":0,"ProcessedFileSize":0,"TotalFileCount":1606917,"TotalFileSize":2273880812063,"StillCounting":false}
updaterState : Waiting
updatedVersion :
updateReady : false
updateDownloadProgress : 0
proposedSchedule : [{"Item1":"3","Item2":"2018-12-17T10:00:00Z"}]
schedulerQueueIds : []
pauseTimeRemain : 0
Is this “verification” step something that will be performed every time or something that happens only in specific cases like this?
Also, would setting a bigger block size help?