Backups fail with error: Object reference not set to an instance of an object


#13

If you get email notifications of your backups then the version should be in there, otherwise the Duplicati logs are stored in the databases - “global” errors in the main db and job specific ones in the job dbs.

For job logs, open the job menu and click “Show log”. In there you should see timestamps with a one or two word summary - click on one of them to expand for details. Here’s what it looks like expanded:
image

Global logs can be found on themain menu -> About -> Show log page.


#14

It appears that I had good backups from at least 27 Nov through 30 Nov with 30 Nov being the last successful backup. I’m still not sure what day I updated to 2.0.4.5_beta_2018-11-28 because my “global” log appears to only go back to 1 December.


#15

I think the About --> Show log page is mainly for issues that arise, so sometimes nothing there is good news. Backup job logs happen even if all goes well, and newer Duplicati versions include a Version field, such as:

ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 12/11/2018 7:19:14 PM (1544573954)
BeginTime: 12/11/2018 7:15:21 PM (1544573721)
Duration: 00:03:53.3900462

This should help you figure out what backups were on 2.0.4.5, and get summary information on their results. Debugging a specific problem like the “Object reference” one may need much more. Stack trace was a start. Sometimes setting up extremely heavy logging like –log-file-log-level=Profiling (or Information for less) helps. Reproducible small test cases are best, because then maybe some developer can take a really close look…


#16

Thank you @ts678 for the tips.

My latest successful backup is from 30 Nov and does not have a version listed.

    ParsedResult: Success
    EndTime: 11/30/2018 1:47:11 AM (1543564031)
    BeginTime: 11/30/2018 1:23:29 AM (1543562609)
    Duration: 00:23:42.6879820

So I am assuming that I have never successfully backed up using version 2.0.4.5_beta_2018-11-28

I’m a little embarrassed that I don’t remember which version I was using prior to 2.0.4.5_beta_2018-11-28, but I think it was 2.0.3.3

I’m not sure I understand your suggestion about stack trace or heavy logging. Are you suggesting I try a new separate backup with a smaller payload in order to somehow troubleshoot my existing situation?

I appreciate the help, but I’m just not sure what is being suggested as a next step!


#17

Do you have any logs in the per-job log area (where that log came from) that came from a failure (or at all)?

Seeing 2.0.4.5 fail on its first run would confirm the introduction date, and possibly provide more information, however logs at this summarized level only go so far. A simple-to-setup next-level set of logs will be to see if live logging at About --> Show log --> Live --> Information shows any interesting lead-up to the failure. Stack traces provide good snapshots at moment of failure, but are not good at the time-sequence that led there…

Sometimes logs will show both the sequence (such as what processing was happening) and the final ending. Let’s try something relatively light first, like the Information level live log above (it can use a different browser tab), to see if that helps get context, then go from there. There is no exact recipe to progressing to answers.

Ordinarily I would prefer not trying to solve problems on systems I’ve never used, but with the others who’ve been in this, maybe progress can be made. Sometimes much can be gained from experimentation by those reporting the problem, and setting up the simplest possible scenario that fails would possibly enable a deep analysis by the right parties that would lead to a bug fix. Getting a well-written issue filed in GitHub with exact steps is a good way to ensure an issue is tracked, and get it in line for the actual code fix by the developers. Forum support tends to look less at code, and more at seeing if there’s any other way to get things running.

Please post a sample of the ordinary highly-summarized job logs after failure began, meaning after 30 Nov.
Let’s try live log at Information level too. Feel free to look at other levels, but Profiling can be overwhelming. Please see if you can find a simple test case of tiny backup to the same system, with minimal extra options.


#18

Thanks @ts678 for the info.

I kicked off another backup job and collected the following live log at informational level

  • Dec 16, 2018 4:14 PM: The operation Backup has started
  • Dec 16, 2018 4:14 PM: Fatal error
{"ClassName":"Duplicati.Library.Interface.UserInformationException","Message":"Unexpected difference in fileset version 73: 4/6/2018 6:25:30 AM (database id: 2), found 295603 entries, but expected 295604","InnerException":null,"HelpURL":null,"StackTraceString":" at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction) <0x4165d020 + 0x010a7> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass32_0.<VerifyConsistencyAsync>b__0 () <0x4165cec0 + 0x0003b> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass3_0.<RunOnMain>b__0 () <0x4165ce40 + 0x00019> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.Common.SingleRunner+<DoRunOnMain>d__2`1[T].MoveNext () <0x4165c510 + 0x003ff> in <filename unknown>:0 \n--- End of stack trace from previous location where exception was thrown ---\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f6648c016d0 + 0x00029> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x7f6648bff6b0 + 0x000a7> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x7f6648bff630 + 0x0006b> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) <0x7f6648bff5e0 + 0x0003a> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.GetResult () <0x7f6648bff5c0 + 0x00012> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () <0x415c2000 + 0x01256> in <filename unknown>:0 \n--- End of stack trace from previous location where exception was thrown ---\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f6648c016d0 + 0x00029> in <filename unknown>:0 \n at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) <0x414b6af0 + 0x000e2> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, IFilter filter) <0x415bb760 + 0x0001f> in <filename unknown>:0 \n at Duplicati.Library.Main.Controller+<>c__DisplayClass13_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) <0x415b4880 + 0x000af> in <filename unknown>:0 \n at Duplicati.Library.Main.Controller.RunAction[T] (Duplicati.Library.Main.T result, System.String[]& paths, IFilter& filter, System.Action`1 method) <0x41516600 + 0x00597> in <filename unknown>:0 ","RemoteStackTraceString":null,"RemoteStackIndex":0,"HResult":-2146233088,"Source":"mscorlib","ExceptionMethod":null,"Data":null}
  • Dec 16, 2018 4:14 PM: The operation Backup has failed with error: Unexpected difference in fileset version 73: 4/6/2018 6:25:30 AM (database id: 2), found 295603 entries, but expected 295604
{"ClassName":"Duplicati.Library.Interface.UserInformationException","Message":"Unexpected difference in fileset version 73: 4/6/2018 6:25:30 AM (database id: 2), found 295603 entries, but expected 295604","InnerException":null,"HelpURL":null,"StackTraceString":" at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction) <0x4165d020 + 0x010a7> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.Backup.BackupDatabase+<>c__DisplayClass32_0.<VerifyConsistencyAsync>b__0 () <0x4165cec0 + 0x0003b> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.Common.SingleRunner+<>c__DisplayClass3_0.<RunOnMain>b__0 () <0x4165ce40 + 0x00019> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.Common.SingleRunner+<DoRunOnMain>d__2`1[T].MoveNext () <0x4165c510 + 0x003ff> in <filename unknown>:0 \n--- End of stack trace from previous location where exception was thrown ---\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f6648c016d0 + 0x00029> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x7f6648bff6b0 + 0x000a7> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x7f6648bff630 + 0x0006b> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) <0x7f6648bff5e0 + 0x0003a> in <filename unknown>:0 \n at System.Runtime.CompilerServices.TaskAwaiter.GetResult () <0x7f6648bff5c0 + 0x00012> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () <0x415c2000 + 0x01256> in <filename unknown>:0 \n--- End of stack trace from previous location where exception was thrown ---\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f6648c016d0 + 0x00029> in <filename unknown>:0 \n at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) <0x414b6af0 + 0x000e2> in <filename unknown>:0 \n at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, IFilter filter) <0x415bb760 + 0x0001f> in <filename unknown>:0 \n at Duplicati.Library.Main.Controller+<>c__DisplayClass13_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) <0x415b4880 + 0x000af> in <filename unknown>:0 \n at Duplicati.Library.Main.Controller.RunAction[T] (Duplicati.Library.Main.T result, System.String[]& paths, IFilter& filter, System.Action`1 method) <0x41516600 + 0x00597> in <filename unknown>:0 ","RemoteStackTraceString":null,"RemoteStackIndex":0,"HResult":-2146233088,"Source":"mscorlib","ExceptionMethod":null,"Data":null}

Hopefully this is what you were suggesting!


#19

It’s a fine shot at the second item. I’m still looking forward to first (logs of original error) and third (test case). Actually, the surprising thing about what you posted is that this isn’t the original error. Did that also happen? “Unexpected difference in fileset” is being reported elsewhere but I’d prefer to look into the original problem, even though it seems to be far less seen (which is one reason I would like some experimentation for item 3).

One thing I was hoping for appears to be missing in the live log, and only present in --log-file logs. Example:

2018-12-16 18:02:34 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2018-12-16 18:02:34 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 0: 11/28/2018 12:04:56 PM (database id: 42), found 0 entries, but expected 1
   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__2`1.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 System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__19.MoveNext()
2018-12-16 18:02:36 -05 - [Information-Duplicati.Library.Modules.Builtin.SendMail-SendMailComplete]: Email sent successfully using server: smtp://smtpauth.earthlink.net:587/?starttls=always

in a --log-file log at --log-file-log-level=Information has prefixes after the time to say what’s going on, and also shows the actual detail of the stack trace. This gives me both the path leading to the error and the error itself. Live log has about the same number of steps, but without detail. I guess in the future I should ask for log-files.

* Dec 16, 2018 6:02 PM: The operation Backup has failed with error: Unexpected difference in fileset version 0: 11/28/2018 12:04:56 PM (database id: 42), found 0 entries, but expected 1

* Dec 16, 2018 6:02 PM: Email sent successfully using server: smtp://smtpauth.earthlink.net:587/?starttls=always

* Dec 16, 2018 6:02 PM: Fatal error

* Dec 16, 2018 6:02 PM: The operation Backup has started

Let me see if I can find anything more from what I have, while you work the other parts and comment on the live log post – does this have any relationship to the original problem? Is it happening before that one can? Typically people seem to either see this immediately on upgrade to 2.0.4.5 on some old version (your case), or get it on version 0 which is the one just made – and I have a test case on how that one can be recreated.


#20

I think this is what you mean (from Stored Logs)

Dec 1, 2018 12:47 AM: Failed while executing “Backup” with id: 1

Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 73: 4/6/2018 6:25:30 AM (database id: 2), found 295603 entries, but expected 295604 at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction) &lt;0x40a796e0 + 0x010a7&gt; in &lt;filename unknown&gt;:0 at Duplicati.Library.Main.Operation.Backup.BackupDatabase+&lt;&gt;c__DisplayClass32_0.&lt;VerifyConsistencyAsync&gt;b__0 () &lt;0x40a79660 + 0x0003b&gt; in &lt;filename unknown&gt;:0 at Duplicati.Library.Main.Operation.Common.SingleRunner+&lt;&gt;c__DisplayClass3_0.&lt;RunOnMain&gt;b__0 () &lt;0x40a79620 + 0x00019&gt; in &lt;filename unknown&gt;:0 at Duplicati.Library.Main.Operation.Common.SingleRunner+&lt;DoRunOnMain&gt;d__2`1[T].MoveNext () &lt;0x40a78e90 + 0x003ff&gt; in &lt;filename unknown&gt;:0 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () &lt;0x7f3120c016d0 + 0x00029&gt; in &lt;filename unknown&gt;:0 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) &lt;0x7f3120bff6b0 + 0x000a7&gt; in &lt;filename unknown&gt;:0 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) &lt;0x7f3120bff630 + 0x0006b&gt; in &lt;filename unknown&gt;:0 at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) &lt;0x7f3120bff5e0 + 0x0003a&gt; in &lt;filename unknown&gt;:0 at System.Runtime.CompilerServices.TaskAwaiter.GetResult () &lt;0x7f3120bff5c0 + 0x00012&gt; in &lt;filename unknown&gt;:0 at Duplicati.Library.Main.Operation.BackupHandler+&lt;RunAsync&gt;d__19.MoveNext () &lt;0x40a4c000 + 0x012f2&gt; in &lt;filename unknown&gt;:0 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () &lt;0x7f3120c016d0 + 0x00029&gt; in &lt;filename unknown&gt;:0 at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) &lt;0x408e6580 + 0x000e2&gt; in &lt;filename unknown&gt;:0 at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, IFilter filter) &lt;0x40a494c0 + 0x0001f&gt; in &lt;filename unknown&gt;:0 at Duplicati.Library.Main.Controller+&lt;&gt;c__DisplayClass13_0.&lt;Backup&gt;b__0 (Duplicati.Library.Main.BackupResults result) &lt;0x40a45bb0 + 0x000af&gt; in &lt;filename unknown&gt;:0 at Duplicati.Library.Main.Controller.RunAction[T] (Duplicati.Library.Main.T result, System.String[]&amp; paths, IFilter&amp; filter, System.Action`1 method) &lt;0x40a389e0 + 0x00597&gt; in &lt;filename unknown&gt;:0

#21

If I understand what you are asking for, I don’t have another example. I only have full system backups.

Would you like me to try a new backup job with a small set of files to be backed up?


#22

Yes please, and remove as many options as possible, and use a local file destination. Best would be if it’s simple and universal enough that any other person can reproduce it on any equipment to study it directly.

There’s also a chance you might remove the problem by simplification, thereby narrowing down its cause.

There’s also a chance no backup ever works on this installation, but that also helps determine next steps.


#23

Thanks @ts678 for your continued suggestions.

I attempted a simple backup test using version 2.0.4.5_beta_2018-11-28 that appears to have succeeded.

Here is the configuration

{
  "CreatedByVersion": "2.0.4.5",
  "Schedule": null,
  "Backup": {
    "ID": "3",
    "Name": "Simple Backup Test 2.0.4.5_beta_2018-11-28",
    "Description": "A simple backup testing Duplicati version 2.0.4.5_beta_2018-11-28",
    "Tags": [],
    "TargetURL": "file:///media/shared/temp/backups/",
    "DBPath": "/home/jake/.config/Duplicati/82786987818679897270.sqlite",
    "Sources": [
      "%MY_DOCUMENTS%/Downloads/"
    ],
    "Settings": [
      {
        "Filter": "",
        "Name": "encryption-module",
        "Value": "",
        "Argument": null
      },
      {
        "Filter": "",
        "Name": "compression-module",
        "Value": "zip",
        "Argument": null
      },
      {
        "Filter": "",
        "Name": "dblock-size",
        "Value": "50mb",
        "Argument": null
      },
      {
        "Filter": "",
        "Name": "--no-encryption",
        "Value": "true",
        "Argument": null
      }
    ],
    "Filters": [],
    "Metadata": {
      "LastBackupDate": "20181219T123849Z",
      "BackupListCount": "1",
      "TotalQuotaSpace": "2702091218944",
      "FreeQuotaSpace": "517687468032",
      "AssignedQuotaSpace": "-1",
      "TargetFilesSize": "41157743309",
      "TargetFilesCount": "1571",
      "TargetSizeString": "38.33 GB",
      "SourceFilesSize": "41788877727",
      "SourceFilesCount": "288",
      "SourceSizeString": "38.92 GB",
      "LastBackupStarted": "20181219T123846Z",
      "LastBackupFinished": "20181219T131814Z",
      "LastBackupDuration": "00:39:27.6756940"
    },
    "IsTemporary": false
  },
  "DisplayNames": {
    "/home/jake/Downloads/": "Downloads"
  }
}

And here is the log from the job

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 288
OpenedFiles: 288
AddedFiles: 288
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 41788877727
SizeOfExaminedFiles: 41788877727
SizeOfOpenedFiles: 41788877727
NotProcessedFiles: 0
AddedFolders: 3
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults: null
DeleteResults: null
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20181219T123849Z.dlist.zip
        Value: [],
        Key: duplicati-i8437d49f1ce34f9e9e09c089b3d5cd1b.dindex.zip
        Value: [],
        Key: duplicati-bc3ad7ce6d1ea4146962bced559fbb119.dblock.zip
        Value: []
    ]
    ParsedResult: Success
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    EndTime: 12/19/2018 7:18:14 AM (1545225494)
    BeginTime: 12/19/2018 7:18:13 AM (1545225493)
    Duration: 00:00:00.8786600
    Messages: [
        2018-12-19 06:38:46 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-12-19 06:38:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-12-19 06:38:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
        2018-12-19 06:38:54 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc146ba409459406cbca49a4610436059.dblock.zip (49.95 MB),
        2018-12-19 06:38:55 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc146ba409459406cbca49a4610436059.dblock.zip (49.95 MB),
...
    ]
    Warnings: []
    Errors: []
    BackendStatistics:
        RemoteCalls: 1576
        BytesUploaded: 41157743309
        BytesDownloaded: 52462392
        FilesUploaded: 1571
        FilesDownloaded: 3
        FilesDeleted: 0
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 1571
        KnownFileSize: 41157743309
        LastBackupDate: 12/19/2018 6:38:49 AM (1545223129)
        BackupListCount: 1
        TotalQuotaSpace: 2702091218944
        FreeQuotaSpace: 517687468032
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
        Messages: [
            2018-12-19 06:38:46 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-12-19 06:38:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-12-19 06:38:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
            2018-12-19 06:38:54 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc146ba409459406cbca49a4610436059.dblock.zip (49.95 MB),
            2018-12-19 06:38:55 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc146ba409459406cbca49a4610436059.dblock.zip (49.95 MB),
...
        ]
        Warnings: []
        Errors: []
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 12/19/2018 7:18:14 AM (1545225494)
BeginTime: 12/19/2018 6:38:46 AM (1545223126)
Duration: 00:39:27.6756940
Messages: [
    2018-12-19 06:38:46 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-12-19 06:38:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-12-19 06:38:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
    2018-12-19 06:38:54 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc146ba409459406cbca49a4610436059.dblock.zip (49.95 MB),
    2018-12-19 06:38:55 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc146ba409459406cbca49a4610436059.dblock.zip (49.95 MB),
...
]
Warnings: []
Errors: []

#24

So it appears that version 2.0.4.5_beta_2018-11-28 works with a fresh backup set. But I’m still stuck with my existing backup. Any thoughts on recovery, or should I just scrap it and start over?


#25

Hello, Duplicati community! I’m back again with one last request for help troubleshooting this backup set before I consider it lost.

Is it accurate that because I can’t continue with new backups that I should not consider it reliable for restoring too?

I’m thinking I’ll start over with a new backup set and delete this old corrupted one. It makes me uncomfortable to do that, and I hope that I can consider Duplicati stable enough to recommend to friends who aren’t very technical.

Thoughts?


#26

What problem are we chasing now? The “Object reference not set to an instance of an object” is so generic an error message that it means little in Duplicati terms without a solid understanding of the code area, and a reproducible test to look at. I lack the former (any readers know Duplicati/Server/WebServer/RESTMethods/CommandLine.cs and its WriteLine?). I set up a debugger, but was not even using that code on my backup.

If that problem has somehow vanished, the “Unexpected difference in fileset”, though of unclear origin, has a simple workaround to try, of deleting the troubled fileset (version of the backup) shown in the error message. Here is a recent report of success, however if the original “Object reference” still happens, I can’t help further without additional assistance from the community, or you being able to discover a way that I can reproduce it. Seeing a simple test succeed is encouraging, but the key is figuring out the difference between it and failure.

For additional information on how to use the delete command for the “Unexpected difference” error, see this, and please feel free to clarify the relationship between these two problems and which is the current problem.


#27

@ts678 Thanks for the clarification that the “Object reference” was not the relevant error. I’ll continue to pursue the “Unexpected difference in fileset” error to see if that leads to recovery.

I appreciate you linking to tips on deleting the unexpected difference. I’ll give that a shot.

Sorry if I’m unclear about the relationship between the two errors. Frankly, I don’t understand the underlying technology very well, so I’m trying to learn as I go. Thanks for your patience, everyone!

I’m traveling the next few days, so it might be a bit before I can report my progress.


#28

That is probably NOT accurate as Duplicati needs the local database to exist for backups, but can make a new/partial one for restores (using at least dlist files from the destination).

Sorry it you’ve already said this, but have you tried a restore? If a restore from the job menu doesn’t work (as it uses the local database) try they main menu Restore option and choose there one that says something like “Direct from destination”.

If the direct from destination restore works then you’ve got a viable restore source so you could start a fresh job but keep the old one around for historical restores if needed.

Once enough history has been built up in the new job then you can delete the “cold storage” one.

Safe travels!


#29

@JonMikelV Thanks for your reply. You are correct. I did try a test restore yesterday, and it was successful. I attempted to restore a single photo from my huge backup set. It took nearly two hours, but it did successfully restore the photo. So that is encouraging!

Is it normal that a restore of a single file would take that long with a backup set as large as mine (Backup: 1.34 TB / 74 Versions) ?


#30

Potentially - it depends on a lot of different things.

If you used the “restore direct from destination” option then Duplicati had to create a temporary mini-database to use to find all the file parts (blocks) needing to be re-assembled. That step can take a while, but we are hoping to optimize it at some point.

Once all the blocks for the file(s) needing to be restored have been identified then the dblock file(s) containing those blocks need to be downloaded.

Remember, your image (let’s say it’s 5MB in size) has been chopped into lots of small blocks (by default 100k so we’ll say that’s 52 blocks). Those blocks get added to a compressed archive dblock file (by default 50MB).

If all your blocks are in the same dblock file then you’ll need to download 50MB to be able to restore your 5M image. But if (worst case) each of your 52 blocks in in a different dblock archive you’d have to download 2.6G (52 x 50MB) to restore your 5M image.

Realistically, that’s unlikely to happen - most blocks are stored together in in as few archive files are possible, however as files are updated the update blocks are stored in new archives.

So if you’re restoring a file that’s been partially updated once since the original backup, you’ll likely have to download 2 dblock archives to restore the latest version of the file. If a different part of the file is then updated and backed up you’d have to download 3 dblock archives to restore the latest version of the file.

So unfortunately yes - it can take a while for restores. :frowning:


#31

Hello, Duplicati, community! I’m back with a report of success!

Big thanks to @ts678 who helped me see past the “Object reference” error to the true issue of “Unexpected difference in fileset"

I was able to delete the fileset that had the issue using the delete command last night.

I see after the delete my ailing backup job now reports a successful backup!

I appreciate all the assistance here. The community is the life-blood of an open-source project. And it is good to know we have a good one here!


#32

For rookies like me, here is what the delete command looked like for my situation:

My first attempts at running the command were flawed by the fact that I cleared out too many of the advanced options. I needed to keep in the dppath and passphrase options.

I also recommend using the --dry-run option first to make sure the command will delete what you think it will!

The command logs looked like this for anyone curious:

Jan 10, 2019 10:00 PM: Result
DeletedSets: [
    Item1: 73
    Item2: 4/6/2018 6:25:30 AM (1523013930)
]
Dryrun: False
MainOperation: Delete
CompactResults:
    DeletedFileCount: 2052
    DownloadedFileCount: 0
    UploadedFileCount: 0
    DeletedFileSize: 53796673940
    DownloadedFileSize: 0
    UploadedFileSize: 0
    Dryrun: False
    MainOperation: Compact
    ParsedResult: Success
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    EndTime: 1/10/2019 10:00:43 PM (1547179243)
    BeginTime: 1/10/2019 9:35:40 PM (1547177740)
    Duration: 00:25:02.7467920
    Messages: [
        2019-01-10 21:29:31 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Delete has started,
        2019-01-10 21:29:35 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-01-10 21:30:23 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (55.06 KB),
        2019-01-10 21:30:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 1 remote fileset(s) ...,
        2019-01-10 21:35:39 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20180406T112530Z.dlist.zip.aes (20.12 MB),
...
    ]
    Warnings: []
    Errors: []
    BackendStatistics:
        RemoteCalls: 2054
        BytesUploaded: 0
        BytesDownloaded: 0
        FilesUploaded: 0
        FilesDownloaded: 0
        FilesDeleted: 2053
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 20594688
        UnknownFileCount: 1
        KnownFileCount: 56380
        KnownFileSize: 1476753186748
        LastBackupDate: 11/30/2018 12:00:00 AM (1543557600)
        BackupListCount: 74
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
        Messages: [
            2019-01-10 21:29:31 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Delete has started,
            2019-01-10 21:29:35 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2019-01-10 21:30:23 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (55.06 KB),
            2019-01-10 21:30:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 1 remote fileset(s) ...,
            2019-01-10 21:35:39 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20180406T112530Z.dlist.zip.aes (20.12 MB),
...
        ]
        Warnings: []
        Errors: []
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 1/10/2019 10:00:43 PM (1547179243)
BeginTime: 1/10/2019 9:29:31 PM (1547177371)
Duration: 00:31:12.2504620
Messages: [
    2019-01-10 21:29:31 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Delete has started,
    2019-01-10 21:29:35 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2019-01-10 21:30:23 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (55.06 KB),
    2019-01-10 21:30:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 1 remote fileset(s) ...,
    2019-01-10 21:35:39 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20180406T112530Z.dlist.zip.aes (20.12 MB),
...
]
Warnings: []
Errors: []

Hopefully it helps someone!

Also, for the moderators here… Should I change the title of my thread to more accurately reflect the true root cause? The “Object reference” error was not the true source of the issue… Just curious about best practices on that part… Thanks