Backups not running/error out after update to 2.0.4.5_beta_2018-11-28:


#1

It appears my backups don’t appear to be running after updating Duplicati. Under the ExplicitOnly section, it constantly shows the error below. Under “Verbose” it says the backup is running, but on the main menu bar, it just shows the name of my backup job and isn’t showing any progress as usual. Can anyone please point me in the right direction:
Dec 3, 2018 6:20 PM: Failed to load assembly C:\Program Files\Duplicati 2\Microsoft.WindowsAzure.Storage.dll, error message: Could not load file or assembly ‘Microsoft.Data.Services.Client, Version=5.8.1.0, Culture=neutral, PublicKeyToken=35’ or one of its dependencies. The located assembly’s manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)
{“ClassName”:“System.IO.FileLoadException”,“Message”:"Could not load file or assembly 'Microsoft.Data.Services.Client, Version=5.8.1.0, Culture=neutral, PublicKeyToken=3
5’ or one of its dependencies. The located assembly’s manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)",“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:" at System.Reflection.RuntimeAssembly.GetExportedTypes(RuntimeAssembly assembly, ObjectHandleOnStack retTypes)\r\n at System.Reflection.RuntimeAssembly.GetExportedTypes()\r\n at Duplicati.Library.DynamicLoader.DynamicLoader`1.FindInterfaceImplementors(String additionalfolders)",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nGetExportedTypes\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b**********9\nSystem.Reflection.RuntimeAssembly\nVoid GetExportedTypes(System.Reflection.RuntimeAssembly, System.Runtime.CompilerServices.ObjectHandleOnStack)”,“HResult”:-2146234304,“Source”:“mscorlib”,“WatsonBuckets”:null,“FileLoad_FileName”:“Microsoft.Data.Services.Client, Version=5.8.1.0, Culture=neutral, PublicKeyToken=3**************5”,“FileLoad_FusionLog”:“WRN: Assembly binding logging is turned OFF.\r\nTo enable assembly bind failure logging, set the registry value [HKLM\Software\Microsoft\Fusion!EnableLog] (DWORD) to 1.\r\nNote: There is some performance penalty associated with assembly bind failure logging.\r\nTo turn this feature off, remove the registry value [HKLM\Software\Microsoft\Fusion!EnableLog].\r\n”}


#2

It’s also showing this error as well:
Dec 3, 2018 6:08 PM: Failed while executing “Backup” with id: 1

Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 2: 10/20/2018 1:42:58 PM (database id: 2), found 42195 entries, but expected 42570 at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction) at Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass32_0.<VerifyConsistencyAsync>b__0() at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.<RunOnMain>b__0() at Duplicati.Library.Main.Operation.Common.SingleRunner.<DoRunOnMain>d__21.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Duplicati.Library.Main.Operation.BackupHandler.&lt;RunAsync&gt;d__19.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task) at Duplicati.Library.Main.Controller.&lt;&gt;c__DisplayClass13_0.&lt;Backup&gt;b__0(BackupResults result) at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]&amp; paths, IFilter&amp; filter, Action1 method) at Duplicati.Library.Main.Controller.Backup(String inputsources, IFilter filter) at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)


#3

Notice here how it’s just sitting without any progress:

I tried deleting the database for the jobs, but it says "Failed to delete: The process cannot access the file ‘C:\Users\BackupUser\AppData\Local\Duplicati\LKOZPPCEMD.sqlite’ because it is being used by another process."Any help would be appreciated!


#4

I also have the issue of “Unexpected difference in fileset” after updating to 2.0.4.5_beta_2018-11-28, and it’s occurring on two of the computers I manage (the only two where I accepted the update, but there are other similarities between these two that I could mention if that would be helpful). Both find fewer entries than expected. The Repair option works on neither, though the report says “Success”.

A potentially related issue is that when I tried to do Configuration–Edit I got an error along the lines of “Failed to enumerate SQL databases” but that seems to have resolved itself with my only actions being multiple attempts to use the Repair option and run the backup. (Since that error no longer is happening I can’t copy it – it was a popup rather than in log). This was on both computers.

I’d be happy to copy whatever verbose output would be helpful to diagnose, I just am not experienced enough to know in advance what might help y’all who actually know about these things.


#5

I ended up deleting the database manually after stopping the Duplicati service. It seems to be recreating the database again so this should take some time (it’s been 2 days) before it starts working again.


#6

Both repairing and deleting the DB did nothing in the end. I had to erase my database and Duplicati entirely and start all the backups all over again. Does anyone know how to avoid this in the future?


#7

I think I am in a similar hole. I am now looking at the second computer today with the same error. Updated to v2.0.4.5 beta on a Windows 10 Pro PC running as a normal app (not service install, just running standard task tray exe)

Both of these examples are backing up to external USB drives.

I also get it as a pop-up telling me unexpected difference in fileset version 2. The number of files different are only very small.

On the first PC I gave up the repair and just deleted everything and started again.

On this second PC I am working through steps to attempt to restart it.

  • verify files - same error message pops up
  • repair database - no joy
  • delete and recreate database - attempting that now YAY!! THIS FIXED IT!! :grin:

I can’t get any log files as the database is being rebuilt.

I also can’t make any sense of what is going on as the error messages are too deep into lines of code and make it hard for me to make any sense of what the issue may be.

I tried reading some other older posts on similar issues - but was soon lost as it was talking about dlink files and assumed knowledge of the product.

I would like to try and find some way, any way, to resurrect this backup and get it working again. I don’t care if I loose a few older backups. I just don’t want to restart this one from scratch as it would take too long. (and I don’t like giving up)

Any info you need from me? Are there any logs I can rescue or are they all gone now the database is being rebuilt?

EDIT - HAHAH - Thanks to the Power of the Forum… I think you scared it back to life after I did the “delete and recreate database” option.:partying_face:

MainOperation: Repair RecreateDatabaseResults: MainOperation: Repair ParsedResult: Success Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28) EndTime: 13/12/2018 14:05:02 (1544709902) BeginTime: 13/12/2018 13:53:36 (1544709216) Duration: 00:11:26.1732966 Messages: [ 2018-12-13 13:53:36 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started, 2018-12-13 13:53:39 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (), 2018-12-13 13:53:40 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (2.21 KB), 2018-12-13 13:57:55 +00 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 6 filelists, 2018-12-13 13:57:55 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180718T182258Z.dlist.zip (8.13 MB), ... ] Warnings: [] Errors: [] BackendStatistics: RemoteCalls: 1138 BytesUploaded: 0 BytesDownloaded: 173064719 FilesUploaded: 0 FilesDownloaded: 1137 FilesDeleted: 0 FoldersCreated: 0 RetryAttempts: 0 UnknownFileSize: 0 UnknownFileCount: 0 KnownFileCount: 0 KnownFileSize: 0 LastBackupDate: 01/01/0001 00:00:00 (-62135596800) BackupListCount: 0 TotalQuotaSpace: 0 FreeQuotaSpace: 0 AssignedQuotaSpace: 0 ReportedQuotaError: False ReportedQuotaWarning: False ParsedResult: Success Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28) Messages: [ 2018-12-13 13:53:36 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started, 2018-12-13 13:53:39 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (), 2018-12-13 13:53:40 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (2.21 KB), 2018-12-13 13:57:55 +00 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 6 filelists, 2018-12-13 13:57:55 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180718T182258Z.dlist.zip (8.13 MB), ... ] Warnings: [] Errors: [] ParsedResult: Success Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28) EndTime: 13/12/2018 14:05:02 (1544709902) BeginTime: 13/12/2018 13:53:36 (1544709216) Duration: 00:11:26.7200638 Messages: [ 2018-12-13 13:53:36 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started, 2018-12-13 13:53:39 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (), 2018-12-13 13:53:40 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (2.21 KB), 2018-12-13 13:57:55 +00 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 6 filelists, 2018-12-13 13:57:55 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180718T182258Z.dlist.zip (8.13 MB), ... ] Warnings: [] Errors: []

Haha - that is also funny. I didn’t realise the error log was just one long line without any linefeeds in it.

Wish me luck - I am now running the backup… hoping for no errors now.

So my answer has been to “Delete and Repair Database”

(On a side note - have you thought about making a backup of that MYSQL file before the repair? That way it would be available for me to send in in case the log info is of us?)

Edit 2: Backup completed with six errors. I am now trying to read the report to see if these are relevant or I can ignore them. (files will have been “in use” during this backup)


DeletedFolders: 48

ModifiedFiles: 3260

ExaminedFiles: 115734

OpenedFiles: 65662

AddedFiles: 27163

SizeOfModifiedFiles: 8758235443

SizeOfAddedFiles: 1671062594

SizeOfExaminedFiles: 60026904043

SizeOfOpenedFiles: 27356082582

NotProcessedFiles: 0

AddedFolders: 78

TooLargeFiles: 0

FilesWithError: 0

ModifiedFolders: 0

ModifiedSymlinks: 0

AddedSymlinks: 0

DeletedSymlinks: 0

PartialBackup: False

Dryrun: False

MainOperation: Backup

CompactResults:

    DeletedFileCount: 8

    DownloadedFileCount: 0

    UploadedFileCount: 0

    DeletedFileSize: 209582046

    DownloadedFileSize: 0

    UploadedFileSize: 0

    Dryrun: False

    MainOperation: Compact

    ParsedResult: Error

    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)

    EndTime: 13/12/2018 15:02:45 (1544713365)

    BeginTime: 13/12/2018 15:02:37 (1544713357)

    Duration: 00:00:07.9046194

    Messages: [

        2018-12-13 14:11:01 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

        2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

        2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (2.21 KB),

        2018-12-13 14:16:45 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

        2018-12-13 14:16:51 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

...

    ]

    Warnings: [

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\NTUSER.DAT,

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG1,

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG2,

        2018-12-13 14:17:03 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\OneDrive - Steve\.86737393-D756-4E56-8D6E-7567889333456B,

        2018-12-13 14:24:28 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\Documents\Outlook Files\email.pst,

...

    ]

    Errors: [

        2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI=, size: 102400, blocksetid: 366402, ix: 237, fullhash: yC+RevErhrxFJtGT3YnejN2R0eYM4KQEPCzcxhU4XDg=, fullsize: 24558288,

        2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327139 and hash 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI= and size 67687,

        2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA=, size: 102400, blocksetid: 366404, ix: 445, fullhash: QxubdgaHZQJp7obNFrnXDmUzssiDlmiXnzK8pZ/6Jaw=, fullsize: 45842620,

        2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327593 and hash fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA= and size 62685,

        2018-12-13 15:00:32 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: xbfDKOQ3LWKHXs9Dal9ohIm+zzoxzHvhve8QtsH0jX8=, size: 86600, blocksetid: 418433, ix: 15, fullhash: Qbkga8NIV4MjLLRsdlVRjEvnrgL3J+0SUXpce0WN45I=, fullsize: 1622600,

...

    ]

    BackendStatistics:

        RemoteCalls: 77

        BytesUploaded: 1636406166

        BytesDownloaded: 63932327

        FilesUploaded: 63

        FilesDownloaded: 3

        FilesDeleted: 9

        FoldersCreated: 0

        RetryAttempts: 0

        UnknownFileSize: 0

        UnknownFileCount: 0

        KnownFileCount: 2322

        KnownFileSize: 60204975351

        LastBackupDate: 13/12/2018 14:11:01 (1544710261)

        BackupListCount: 6

        TotalQuotaSpace: 1000201224192

        FreeQuotaSpace: 881959137280

        AssignedQuotaSpace: -1

        ReportedQuotaError: False

        ReportedQuotaWarning: False

        ParsedResult: Error

        Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)

        Messages: [

            2018-12-13 14:11:01 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

            2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

            2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (2.21 KB),

            2018-12-13 14:16:45 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

            2018-12-13 14:16:51 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

...

        ]

        Warnings: [

            2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\NTUSER.DAT,

            2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG1,

            2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG2,

            2018-12-13 14:17:03 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\OneDrive - Steve\.xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxx,

            2018-12-13 14:24:28 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\Documents\Outlook Files\email.pst,

...

        ]

        Errors: [

            2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI=, size: 102400, blocksetid: 366402, ix: 237, fullhash: yC+RevErhrxFJtGT3YnejN2R0eYM4KQEPCzcxhU4XDg=, fullsize: 24558288,

            2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327139 and hash 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI= and size 67687,

            2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA=, size: 102400, blocksetid: 366404, ix: 445, fullhash: QxubdgaHZQJp7obNFrnXDmUzssiDlmiXnzK8pZ/6Jaw=, fullsize: 45842620,

            2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327593 and hash fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA= and size 62685,

            2018-12-13 15:00:32 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: xbfDKOQ3LWKHXs9Dal9ohIm+zzoxzHvhve8QtsH0jX8=, size: 86600, blocksetid: 418433, ix: 15, fullhash: Qbkga8NIV4MjLLRsdlVRjEvnrgL3J+0SUXpce0WN45I=, fullsize: 1622600,

...

        ]

DeleteResults:

    DeletedSets: [

        Item1: 1

        Item2: 30/11/2018 17:00:02 (1543597202)

    ]

    Dryrun: False

    MainOperation: Delete

    ParsedResult: Error

    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)

    EndTime: 13/12/2018 15:02:45 (1544713365)

    BeginTime: 13/12/2018 15:01:30 (1544713290)

    Duration: 00:01:15.4263950

    Messages: [

        2018-12-13 14:11:01 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

        2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

        2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (2.21 KB),

        2018-12-13 14:16:45 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

        2018-12-13 14:16:51 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

...

    ]

    Warnings: [

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\NTUSER.DAT,

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG1,

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG2,

        2018-12-13 14:17:03 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\OneDrive - Steve\.xxxxxxxx-xxxx-xxxx-8xxx-4xxxxxxxxxB,

        2018-12-13 14:24:28 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\Documents\Outlook Files\email.com.pst,

...

    ]

    Errors: [

        2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI=, size: 102400, blocksetid: 366402, ix: 237, fullhash: yC+RevErhrxFJtGT3YnejN2R0eYM4KQEPCzcxhU4XDg=, fullsize: 24558288,

        2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327139 and hash 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI= and size 67687,

        2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA=, size: 102400, blocksetid: 366404, ix: 445, fullhash: QxubdgaHZQJp7obNFrnXDmUzssiDlmiXnzK8pZ/6Jaw=, fullsize: 45842620,

        2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327593 and hash fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA= and size 62685,

        2018-12-13 15:00:32 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: xbfDKOQ3LWKHXs9Dal9ohIm+zzoxzHvhve8QtsH0jX8=, size: 86600, blocksetid: 418433, ix: 15, fullhash: Qbkga8NIV4MjLLRsdlVRjEvnrgL3J+0SUXpce0WN45I=, fullsize: 1622600,

...

    ]

RepairResults: null

TestResults:

    MainOperation: Test

    Verifications: [

        Key: duplicati-20181123T170003Z.dlist.zip

        Value: [],

        Key: duplicati-iec2938b2b5d049a3923ae0b05f6bdb90.dindex.zip

        Value: [],

        Key: duplicati-be9e22375397c4296ab65585b5d1443f9.dblock.zip

        Value: []

    ]

    ParsedResult: Error

    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)

    EndTime: 13/12/2018 15:02:58 (1544713378)

    BeginTime: 13/12/2018 15:02:56 (1544713376)

    Duration: 00:00:02.1463645

    Messages: [

        2018-12-13 14:11:01 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

        2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

        2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (2.21 KB),

        2018-12-13 14:16:45 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

        2018-12-13 14:16:51 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

...

    ]

    Warnings: [

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\NTUSER.DAT,

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG1,

        2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG2,

        2018-12-13 14:17:03 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\OneDrive - Steve\.xxxxxxxx-xxx-4xxx-xxxx-4xxxxxxxxxx,

        2018-12-13 14:24:28 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\Documents\Outlook Files\email.pst,

...

    ]

    Errors: [

        2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI=, size: 102400, blocksetid: 366402, ix: 237, fullhash: yC+RevErhrxFJtGT3YnejN2R0eYM4KQEPCzcxhU4XDg=, fullsize: 24558288,

        2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327139 and hash 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI= and size 67687,

        2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA=, size: 102400, blocksetid: 366404, ix: 445, fullhash: QxubdgaHZQJp7obNFrnXDmUzssiDlmiXnzK8pZ/6Jaw=, fullsize: 45842620,

        2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327593 and hash fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA= and size 62685,

        2018-12-13 15:00:32 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: xbfDKOQ3LWKHXs9Dal9ohIm+zzoxzHvhve8QtsH0jX8=, size: 86600, blocksetid: 418433, ix: 15, fullhash: Qbkga8NIV4MjLLRsdlVRjEvnrgL3J+0SUXpce0WN45I=, fullsize: 1622600,

...

    ]

ParsedResult: Error

Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)

EndTime: 13/12/2018 15:02:59 (1544713379)

BeginTime: 13/12/2018 14:11:01 (1544710261)

Duration: 00:51:57.7299832

Messages: [

    2018-12-13 14:11:01 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

    2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

    2018-12-13 14:11:09 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (2.21 KB),

    2018-12-13 14:16:45 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

    2018-12-13 14:16:51 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b6f70ed61db3d4783868ce3148d7e83d2.dblock.zip (49.98 MB),

...

]

Warnings: [

    2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\NTUSER.DAT,

    2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG1,

    2018-12-13 14:11:10 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\ntuser.dat.LOG2,

    2018-12-13 14:17:03 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\OneDrive - Steve\.xxxxxxx3-xxxx-4xxx-8xxx-4xxxxxxxxxx,

    2018-12-13 14:24:28 +00 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: C:\Users\Steve\Documents\Outlook Files\email.pst,

...

]

Errors: [

    2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI=, size: 102400, blocksetid: 366402, ix: 237, fullhash: yC+RevErhrxFJtGT3YnejN2R0eYM4KQEPCzcxhU4XDg=, fullsize: 24558288,

    2018-12-13 14:28:41 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327139 and hash 1lgAv19gvFx3xB401yEDiYHLP2ANtnGUhe3JUFNQRzI= and size 67687,

    2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA=, size: 102400, blocksetid: 366404, ix: 445, fullhash: QxubdgaHZQJp7obNFrnXDmUzssiDlmiXnzK8pZ/6Jaw=, fullsize: 45842620,

    2018-12-13 14:28:43 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1327593 and hash fHvVMNgSWTrvxpssb0cvlbDBp37ugEJpD9c2GAKssNA= and size 62685,

    2018-12-13 15:00:32 +00 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: xbfDKOQ3LWKHXs9Dal9ohIm+zzoxzHvhve8QtsH0jX8=, size: 86600, blocksetid: 418433, ix: 15, fullhash: Qbkga8NIV4MjLLRsdlVRjEvnrgL3J+0SUXpce0WN45I=, fullsize: 1622600,

...

]

Edit - so… I am not confused. Are those errors I should worry about? Or not?


#8

Just wanted to share my experience with the update.

I have 2 computers and 3 separate backup routines. Both computers are running Windows 10, one Home, one Professional.

After the update to 2.0.4.5 (not sure what I upgraded from) all 3 of my backups showed the ‘fileset unexpected difference.’

‘Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 8: 8/22/2018 12:00:00 AM (database id: 79), found 2397 entries, but expected 2399’

On one PC, after running the ‘Repair’ option ~5 times, it started working. On the other PC with 2 separate backup routines, no matter how many times I ran repair, the backup(s) kept giving me the same error.

So far, I have gotten one of the two backups fixed by doing the Delete/Recreate database option. The only issue was that the delete/recreate option took around 12 hours. I am still waiting for the other routine to finish the delete/recreate routine going on 10 hours or so. Hopefully that will fix the problem.


#9

Here are a couple of posts about the “Unexpected difference in fileset” problems, and a 2.0.4.5 procedure which has worked several times (but is failing on a system that perhaps has other problems), however you have to try this before deleting the database, unless you made a copy (or if “Delete” ever learns to offer to copy). Doing the version delete (if it works) has less time risk than Recreate, which sometimes is very slow.


#10

Here is my take to solve this issue. I’m on Windows 10. My server is SSH.

  1. export all backup configurations that cause problems. I have only one backup; if you have more, you may have to export all.
  2. uninstall duplicati.
  3. go in C:\Users\<Your User>\AppData\Local\ and rename Duplicati folder in Duplicati_Old.
  4. download latest duplicati version. Install. (Now duplicati should have recreated the just deleted folder.
  5. Reimport the backup configuration.
  6. Duplicati should understand by himself that there’s a problem in the database and should ask to repair the database.
  7. You could try to just repair; I wanted to be 100% sure that it was woring so I did a “delete and repair” database.

Now I finally see that Duplicati is recreating indexes and I’m happy.


#11

I wanted to make a second update on my initial post. So, my second Delete/Recreate database event is still running after 65 hours and it is up to 90%. This would be fine, and I would have another ~14 hours left IF the time taken was linear compared to progress. It is not.

Over the last 6 hours, progress has gone from 0.904520100 to 0.904742956, a gain of 2 ten thousandths of a percent. Unless it speeds up, this could take months.

Can anyone give me some advice on the best course of action on my options?

-Stop rebuild and try to restore a backup of the database?

-Restart the rebuild? (I kind of doubt this is a good idea)

-Give it more time? (I could give it a few more days, but my other backups are not running)

-Recreate the backup (Source is 190 GB and Backup is currently 312 GB)?


#12

I did run into the same issues and did a delete/recreate of the database.
It eventually finished after being between 90 and 9x% forever (ok, not forever, but around 72 hrs).
First 90 or so percent were done in about 4 hrs. So, after almost 4 days it was finally done.
But the next run after recreating did produce the same error again.
So i finally gave up, deleted the db AND backup files and did a complete restart (with the same old settings).
Source was/is around 400GB, but that was the only thing that worked in a “normal” manner for me…

Edit: Since this all happened on a fast system with potent cpu, ram, ssds and local 10GB Networks with almost no load on cpu or network it seems to be originated on the “organizing and checking” side…


#13

Thanks for the advice! I really hope this fixes the issue as I have already wasted enough time on the problem.
I still do not understand why it would take this long to recreate a couple megabyte database… There must be some really complex things happening. Its one thing if the program had to go online to get files or something but that is not the case on my network. Both my host drive and the backup drive are SSD’s and I am on a Gigabit LAN network between the two PC’s.
My guess is the recreate process is maxing out some type of SQL lite query execute buffer or a leak within its allocated resources, either of which would slow it to a crawl.
Does anyone know where I could read more about it? I am a SQL admin by profession and may be able to help.


#14

How are you guys able to see the percentage? All I see in the GUI is that the name of the backup is running, but it doesn’t indicate a percentage completed.


#15

If you want to see the SQL queries in all their too-much-for-me-but-maybe-you-can-follow-them glory they’re logged at Profiling log level (which also times them). The easy way to get a peek at this and other activity (or lack thereof) is About --> Show log --> Live --> Profiling, but for serious study you might want to use –log-file. SQL queries can be executed and timed in an SQLite browser such as DB Browser for SQLite, however the Windows database is weakly encrypted, and you must start TrayIcon or Server with --unencrypted-database.

Some of the slowdowns with large backups are believed to be a scaling problem, as rows increase. Applying Choosing sizes in Duplicati might help there. Even simple queries can grow slow, but it seems to me that the complex ones might benefit from expert reviews. How the backup process works can offer some background.


#16

Thanks ts678! I am going to take a look. I have seen some of the queries in the log and they look relatively simple. I am now curious how they are ordering/storing the libraries (not to mention i have never used sqllite) and will investigate.

waLIEN:
The way I am viewing the status of the recreate process is through About, System Info, Server State.
About halfway down it shows an action called lastPgEvent, which contains a value called: “OverallProgress”:0.905045331," which I am assuming means, in my case 90% (its been at 90% for about 12 hours).


#17

Most of the queries I’ve seen do look fairly simple - note that if you want to do timing on runs, what you’ll likely find with GUI logs is the queries with variable placeholders but if you use --log-file then in the file you should find the same queries but with ACTUAL values that you could turn around and run against your own database.

As I recall, most of the SQL calls are logged to text files with durations - so in theory you should be able to find a few from the beginning of the log and the same ones from the end of the log and see by how much their run times changed.

While the theory that for each hash we have to check if it already exists before we add it (thus, with each hash added subsequent checks get slower) is a good one, consider too that if we’re multi-threading we may be compounding the issue as two threads both hitting the database at the same time are likely MORE than twice as slow as a single thread hitting it twice.

Thanks, good luck with the research - please let us know what you find! :slight_smile:


#18

I assume others will have this same issue so I thought a final follow up was in order. After the delete/recreate ran for 11 days, and was at 91.17300510%, I woke up this morning to my Intel Nic driver being crashed (no network) and I ended up having to reboot, which killed the process.

From the point i started tracking the completion, in 9 days the recreate process completed .007% (90.45 too 91.17).

Obviously, I do not want to wait around another few weeks too try again so i have recreated the backup.

If you have this problem, my suggestion would be to try the delete/recreate, if it goes for more than 4 days, give up and recreate the backup plan.