Verifying backend data forever

Hello,

I have an UnRaid server and have installed Duplicati to perform backup tasks. I have two backup configurations:- Photographs, and Documents. It’s the Photographs one I am discussing here. It’s backing up a directory approximately 1Tb in size to a USB external disk also attached to the server. It did perform the initial backup ok quite a while back but recently when I start the backup job running it just sits on " Photographs: Verifying backend data" . I thought i’d leave it overnight last night and it made no difference. It’s still sat verifying backend data this morning. Will it ever finish? What is it actually doing? Is it actually doing anything? Does it have to do this everytime?

I’m wondering if this is happening as I don’t leave the server turned on all the time. I just switch it on on an as needed basis.

Anyone have any ideas how I can fix this?

Thanks,
Neil

After each backup, Duplicati will download a few files from the destination to check the integrity of the backup. If you haven’t changed the default block size, then this should amount to around 50 MB being downloaded.

What version of Duplicati are you running? Also, can I ask why you’re backing up to an external USB disk and not to a drive in the array? I’m also backing up to an UnRaid server and am curious about the pros and cons of different configurations.

I’ll have to check what the block size is set to as I may have changed it initially. I’ll also come back and post the version but I did update Duplicati this morning. I’m using Duplicati to back up a directory on the array to an external USB disk connected to the UnRaid server just as another place to have it backed up. Once I have this backup running and running reliably I want to duplicate it as an offsite backup using Backblaze B2. That’s the eventual goal.

Hello @rctneil, welcome to the forum!

I’m also running Dupliacti on unRAID (official Docker container) but am not backing up to USB (just an array disk and cloud storage).

Depending on what version of Duplicati you were using, you may have been bumping into a bug where the progress bar wasn’t being updated correctly even though the backup had progressed past the verification.

Note that while warwickmm is correct about the end-of-backup “can I download and verify a file” tests, I believe the issue you’re facing is the pre-backup “does the destination have all the files I think it should have” check.

If updating to a newer version of Duplicati doesn’t resolve the issue, consider TESTIGN with this parameter - if it resolves it, then we’ve isolated the issue and can move forward from there:

--no-backend-verification
If this flag is set, the local database is not compared to the remote filelist on startup. The intended usage for this option is to work correctly in cases where the filelisting is broken or unavailable.
Default value: “false”

Thankyou, I will most likely be able to test this tommorrow. Appreciate your reply!

Neil

I don;t think it is this issue as the backup has been in progress since 8am this morning and when I check in About it shows: “Phase”:“Backup_PreBackupVerify”.

I have enabled that flag option too but obviously it is not making any difference. I’m running version Duplicati - 2.0.3.3_beta_2018-04-02

Hmmm…does About -> Show Log -> Live (choose Profiling) seem to be getting updated (or have a recent timestamp)?

If we can look at the last logged item it might give a hint as to what it’s getting stuck on.

Right now, the entirety of the profiling log is this:

  • Nov 20, 2018 9:20 AM: Fatal error

  • Nov 20, 2018 9:20 AM: Server has started and is listening on 0.0.0.0, port 8200

Clicking on a bulleted timestamp should expand to show details (if there are any).

Stupid me, missed that. Sorry.

Fatal error details:

{“ClassName”:“Duplicati.Library.Interface.CancelException”,
“Message”:“Cancelled”,
“Data”:null,
“InnerException”:null,
“HelpURL”:null,
“StackTraceString”:"
 at Duplicati.Library.Main.BasicResults.TaskControlRendevouz () [0x00038] in <ae134c5a9abb455eb7f06c134d211773>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.RunMainOperation (Duplicati.Library.Snapshots.ISnapshotService snapshot, Duplicati.Library.Main.BackendManager backend) [0x00154] in <ae134c5a9abb455eb7f06c134d211773>:0 
 at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String sources, Duplicati.Library.Utility.IFilter filter) [0x008e0] in <ae134c5a9abb455eb7f06c134d211773>:0 
 at Duplicati.Library.Main.Controller+<>c__DisplayClass17_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00036] in <ae134c5a9abb455eb7f06c134d211773>:0 
 at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0014b] in <ae134c5a9abb455eb7f06c134d211773>:0 
 at Duplicati.Library.Main.Controller.Backup (System.String inputsources, Duplicati.Library.Utility.IFilter filter) [0x00068] in <ae134c5a9abb455eb7f06c134d211773>:0 
 at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00494] in <670b0e4a9ae144208688fcb192d20146>:0 ",
“RemoteStackTraceString”:null,
“RemoteStackIndex”:0,
“ExceptionMethod”:null,
“HResult”:-2146233088,
“Source”:“Duplicati.Library.Main”}

As far as I can tell it looks like Duplicati isn’t actually doing anything - in fact, it looks like maybe something was cancelled.

Is the progress bar still showing that it’s verifying backend data?

If you go to About -> “System info” then scroll down to “Server state properties” do you see anything next to “lastPgEvent”?

I’m wondering if it crashed but didn’t update the progress bar correctly. Or I could just be making assumptions about what you’re seeing at your end. :slight_smile:

(BTW - I edited your post by adding line feeds and wrapping your message in “~~~ json” and '~~~" to make it easier to read.)

Ok, here’s the lastpgevent info:

{"BackupID":"2",
"TaskID":4,
"BackendAction":"Delete",
"BackendPath":"duplicati-i49f8c37a24dc4d1fa5cf9c138e93216a.dindex.zip",
"BackendFileSize":-1,
"BackendFileProgress":0,
"BackendSpeed":-1,
"BackendIsBlocking":false,
"CurrentFilename":null,
"CurrentFilesize":0,
"CurrentFileoffset":0,
"Phase":"Backup_PreBackupVerify",
"OverallProgress":0,
"ProcessedFileCount":0,
"ProcessedFileSize":0,
"TotalFileCount":162097,
"TotalFileSize":1156251943186,
"StillCounting":false}

and yes, it still says that

Perfect - thanks!

Unfortunately, that page does indeed seem to imply it’s still verifying but has no progress for some reason. (Of course I haven’t had much experience with 1TB backups, so this could be normal?)

Hopefully @Pectojin has a moment to take a look and give his opinion.

I’m a little confused by that last log. It’s deleting a dindex file, so perhaps there’s an inconsistency between the DB and the index? I’m honestly not sure if that’s something that the verification process deals with.

Maybe here? duplicati/TestHandler.cs at master · duplicati/duplicati · GitHub

Backup_PreBackupVerify and Backup_PostBackupVerify both say Verifying backend data ..., but they’re different verifications. The Phase from lastPgEvent, combined with failure Fatal error at the same minute as Server has started suggest this is the early test which may delete remote volumes in odd states such as Temporary, Deleting, or Uploading. There are Information-level log messages around that explain actions, so probably the next backup test should set –log-level=Information or higher, and either use –log-file or Commandline (web version is fine) to get a better view. We may also catch a Delete sequence. An example:

2018-11-16 06:54:00 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-i2f2cc2876b90437991b00e44bcd98180.dindex.zip.aes (9.18 KB) 2018-11-16 06:54:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-i2f2cc2876b90437991b00e44bcd98180.dindex.zip.aes (9.18 KB) 2018-11-16 06:54:01 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: RemoteOperationDelete took 0:00:00:00.202

PreBackupVerify runs code in https://github.com/duplicati/duplicati/blob/master/Duplicati/Library/Main/Operation/FilelistProcessor.cs

I don’t know how the final failure happens, but at least we can see if we can get a better idea of other events. Perhaps @rctneil can see if duplicati-i49f8c37a24dc4d1fa5cf9c138e93216a.dindex.zip is on the USB drive.

@ts678 Just done a search in the file listing for that file and it was not found.

What should I try next? Just be aware i’m very new to my Unraid server and Duplicati.

Personally, I’d try again for a log view. I’m not sure why your last one had so little, but maybe it was timing, so please open a second browser tab for MENU --> About --> Show log --> Live --> Information then try backup from the first tab. If you don’t like browser studying, you can instead use the --log-file and --log-level options, however my file seemed to ignore Information and go for the even-more-wordy Profiling which is even better, however you probably want to turn that off when you’re not chasing an issue (or at least trim it occasionally).

@ts678 Nothing seemed to be making any difference so I told it to delete and recreate the database. This seems to have made a difference and the current progress says:

Current action: Backup_ProcessingFiles

I will update here if it completes successfully.

Ok, The result of the backup is below: Does it look ok to you?

Dec 2, 2018 11:12 AM: Result
DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 162240
OpenedFiles: 162240
AddedFiles: 162240
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 1156760384827
SizeOfExaminedFiles: 1156760384827
SizeOfOpenedFiles: 1156760384827
NotProcessedFiles: 0
AddedFolders: 839
TooLargeFiles: 0
FilesWithError: 0
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
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 12/2/2018 11:12:57 AM (1543749177)
BeginTime: 12/2/2018 11:11:42 AM (1543749102)
Duration: 00:01:15.4128610
Messages: [
2018-12-01 14:42:29 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-12-01 14:47:26 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bf03f0e5b0e8f43359dbae85a5afe82fb.dblock.zip (2.00 GB),
2018-12-01 14:47:37 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bf03f0e5b0e8f43359dbae85a5afe82fb.dblock.zip (2.00 GB),
2018-12-01 14:47:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i4673d366abea4676851f160da9859cbe.dindex.zip (1.40 MB),
2018-12-01 14:47:39 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i4673d366abea4676851f160da9859cbe.dindex.zip (1.40 MB),

]
Warnings:
Errors:
BackendStatistics:
RemoteCalls: 1047
BytesUploaded: 1122542034171
BytesDownloaded: 0
FilesUploaded: 1047
FilesDownloaded: 0
FilesDeleted: 0
FoldersCreated: 0
RetryAttempts: 0
UnknownFileSize: 0
UnknownFileCount: 0
KnownFileCount: 1047
KnownFileSize: 1122542034171
LastBackupDate: 12/1/2018 2:42:29 PM (1543675349)
BackupListCount: 1
TotalQuotaSpace: 2999127797760
FreeQuotaSpace: 759400058880
AssignedQuotaSpace: -1
ReportedQuotaError: False
ReportedQuotaWarning: False
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
Messages: [
2018-12-01 14:42:29 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-12-01 14:47:26 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bf03f0e5b0e8f43359dbae85a5afe82fb.dblock.zip (2.00 GB),
2018-12-01 14:47:37 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bf03f0e5b0e8f43359dbae85a5afe82fb.dblock.zip (2.00 GB),
2018-12-01 14:47:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i4673d366abea4676851f160da9859cbe.dindex.zip (1.40 MB),
2018-12-01 14:47:39 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i4673d366abea4676851f160da9859cbe.dindex.zip (1.40 MB),

]
Warnings:
Errors:
RepairResults: null
TestResults: null
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 12/2/2018 11:12:57 AM (1543749177)
BeginTime: 12/1/2018 2:42:29 PM (1543675349)
Duration: 20:30:28.3308700
Messages: [
2018-12-01 14:42:29 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-12-01 14:47:26 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bf03f0e5b0e8f43359dbae85a5afe82fb.dblock.zip (2.00 GB),
2018-12-01 14:47:37 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bf03f0e5b0e8f43359dbae85a5afe82fb.dblock.zip (2.00 GB),
2018-12-01 14:47:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i4673d366abea4676851f160da9859cbe.dindex.zip (1.40 MB),
2018-12-01 14:47:39 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i4673d366abea4676851f160da9859cbe.dindex.zip (1.40 MB),

]
Warnings:
Errors:

Looks mostly reasonable assuming the plan progressed from “delete and recreate the database” to a new backup. You can get a file count and size from your OS tools, but here the average source file size is 7MB (plausible for photos, for some cameras), and surprising average destination dblock file size is 2GB, which presumably was a manual setting but seems high. I’d worry about loss of a backup file losing many photos.

ExaminedFiles: 162,240
OpenedFiles: 162,240
AddedFiles: 162,240
SizeOfAddedFiles: 1,156,760,384,827
SizeOfExaminedFiles: 1,156,760,384,827
SizeOfOpenedFiles: 1,156,760,384,827

BytesUploaded: 1,122,542,034,171
KnownFileCount: 1047
KnownFileSize: 1,122,542,034,171

Choosing sizes in Duplicati
Remote Volume Size

Backup by default will do some sampled verification of the destination files after the backup runs, configurable by –backup-test-samples and with the meaning of a sample explained in The TEST command, so using a 2GB –dblock-size will probably mean a bit of a slowdown there even if the number of new photos uploaded is small.