Removing source folder results in inaccessible UI and endless backup-loop

Support
1

I’ve had a weird problem and luckily was able to solve it:
Duplicati has been running for some years on my Netgear ReadyNAS, until last week.
After moving some source files around, I was not able to logon to the web UI. Sometimes the web page didn’t load at all, a few times I got a login screen that returned “Failed to get nonce” after entering the password.

Fortunately I was able to find the cause of this problem, because the Duplicati-Monitoring service is used for most of my backup jobs:

image
image718×591 31.2 KB

One of the source folders was indeed moved to another location, so this is a valid error message. However, the backup job was started again and again, resulting in thousands of log files:

image
image801×223 9.69 KB

To access my backups again, the only thing I had to do was creating an empty folder (the one that was missing according to the logs) and wait a few minutes.
The web UI became accessible again, I edited the backup job (removing non-existent source folder) and removed the temporary folder on my NAS.

This seems to be a nasty bug. I was not far away from reinstalling Duplicati and manually reconfiguring all backup jobs.

Advanced options used for this backup job:

--snapshot-policy=Auto
--send-mail-level=Warning,Error,Fatal
--send-mail-url=smtp://x.x.x.x
--send-mail-from=name@domain.tld
--send-mail-to=name@domain.tld
--send-mail-subject=%PARSEDRESULT%: Duplicati %OPERATIONNAME% report for %backup-name%
--send-mail-body=%RESULT%
--backup-test-samples=10
--tempdir=/<tempfolder>/
--no-local-blocks=true
--full-result=true
--asynchronous-upload-folder=/<foldername>/
--blocksize=50MB
--dblock-size=500MB
--send-http-url=<duplicati-monitoring-url>
2

If you haven’t manually restarted Duplicati, can you run ps to see if Duplicati start time is as expected?

It would be helpful to know if this is all one Duplicati, in a loop, versus some sort of crash-restart issue.

Duplicati requires mono --version to say at least version 5, or sometimes it may crash in odd places.

One of those might have been during reporting, but I don’t have any forum references handy to confirm.

Simplifying the issue as much as possible (little data, minimal options) would also help to isolate what’s going on here. Whatever it is, it’s working fine on a simple Windows backup. I have no ReadyNAS here.

It would also be useful to know if scheduler is involved. FWIW my test was on 2.0.5.107, which did have fixes for a scheduler issue. I hope nothing broke. What Duplicati version is running on your ReadyNAS?

When I force a missing folder, my Duplicati complains in web UI, then tries again at next scheduled time.

1 Like
3

This issue is reproducable. I created an empty folder, selected it as source folder and deleted the source folder before starting a backup.
After the backup was started, the web UI terminated almost immediately.

It looks like the Mono process crashes. When running ps -eo pid,start,cmd, 2 Duplicati.Server.exe processes disappear from the list (/usr/bin/mono /data/Duplicati/Duplicati/Duplicati.Server.exe and /usr/bin/mono-sgen /data/Duplicati/Duplicati/Duplicati.Server.exe.

So it looks like it’s a crash-restart issue.

My NAS is running Mono JIT compiler version 5.4.1.6 (tarball Wed Nov 8 20:37:24 UTC 2017)

Before I found out the real cause, I tried several other things. Duplicati v2.0.5.107 Canary was running on my NAS. Because I updated to this version recently, the first thing I tried was stopping the Duplicati service (sudo systemctl stop duplicati), extracting the files from duplicati-2.0.5.1_beta_2020-01-18.zip over the current installation and starting the service again, without any result of course. So I guess it’s not related to a specific Duplicati version.

In my situation, it’s starting the backup over and over again, due to the crashing Duplicati.Server.exe process, I guess.
Funny thing is that the backup completes successfully after I manually recreate the missing source folder, without restarting/resetting anything.
Also worth mentioning is that all other backups were completed successfully the last week, so the corrupt backup job did not have negative effects for the other backup jobs running on the same NAS.

4

You might be able to see whether there’s a Duplicati-crashlog.txt file in ~/.config/Duplicati.

You can also try to get a log view, e.g. Live log About --> Show log --> Live --> Information
Setting up a –log-file is possible, and allows higher logging, e.g. –log-file-log-level=verbose
Profiling is as high as logging will go, but files get big. You can see end with tail or less +G.

Filing a GitHub issue with very minimal steps to reproduce might get a Linux expert to help,
although it would help if the problem can be reproduced with a more available environment.

Another test might be Export As Command-line to run, and see if any error message show.
Such final words might be attempted in your background Duplicati, but have nowhere to go.
Actually, running Duplicati.GUI.TrayIcon.exe from command line might be another option…
Even under normal circumstances there’s quite a bit of messiness going to the terminal…

1 Like
5

There’s no Duplicati-crashlog.txt, Duplicati’s live log doesn’t reveal any information related to the crash.

Running the backup from the command line in a terminal window returns this:

Error.zip (7.3 KB)

I guess it’s a bug in Mono.

6

Quoting from attachment to make it findable by search (which found five previous, mostly fixed by mono upgrade, and some with unclear end, but none said they upgraded mono and the issue was NOT fixed):

Backup started at 6/16/2020 11:08:38 AM
* Assertion at local-propagation.c:562, condition `ins->opcode > MONO_CEE_LAST' not met

Stacktrace:

  at <unknown> <0xffffffff>
  at System.Collections.Generic.Dictionary`2<string, int>.TryInsert (string,int,System.Collections.Generic.InsertionBehavior) [0x00022] in <62f5937022004555807e6c57c33f6684>:0
  at System.Collections.Generic.Dictionary`2<string, int>.Add (string,int) [0x00000] in <62f5937022004555807e6c57c33f6684>:0
  at MimeKit.Utils.CharsetUtils.AddAliases (System.Collections.Generic.Dictionary`2<string, int>,int,int,string[]) [0x00011] in <e31da2413fc64d90b7499cd437f8d01a>:0
  at MimeKit.Utils.CharsetUtils..cctor () [0x0005f] in <e31da2413fc64d90b7499cd437f8d01a>:0
  at (wrapper runtime-invoke) object.runtime_invoke_void (object,intptr,intptr,intptr) [0x0001e] in <62f5937022004555807e6c57c33f6684>:0
  at <unknown> <0xffffffff>
  at (wrapper managed-to-native) object.__icall_wrapper_mono_generic_class_init (intptr) [0x00000] in <62f5937022004555807e6c57c33f6684>:0
  at MimeKit.ParserOptions..ctor () [0x0002b] in <e31da2413fc64d90b7499cd437f8d01a>:0
  at MimeKit.ParserOptions..cctor () [0x00018] in <e31da2413fc64d90b7499cd437f8d01a>:0
  at (wrapper runtime-invoke) object.runtime_invoke_void (object,intptr,intptr,intptr) [0x0001e] in <62f5937022004555807e6c57c33f6684>:0
  at <unknown> <0xffffffff>
  at Duplicati.Library.Modules.Builtin.SendMail.SendMessage (string,string) [0x00000] in <8062ce82a1f64108903ebe990014a0d1>:0
  at Duplicati.Library.Modules.Builtin.ReportHelper.OnFinish (object) [0x00135] in <8062ce82a1f64108903ebe990014a0d1>:0
  at Duplicati.Library.Main.Controller.OnOperationComplete (object) [0x0004f] in <80402d19122441e2bd57fbfcc5267c40>:0
  at Duplicati.Library.Main.Controller.RunAction<T_REF> (T_REF,string[]&,Duplicati.Library.Utility.IFilter&,System.Action`1<T_REF>) [0x0023a] in <80402d19122441e2bd57fbfcc5267c40>:0
  at Duplicati.Library.Main.Controller.Backup (string[],Duplicati.Library.Utility.IFilter) [0x00074] in <80402d19122441e2bd57fbfcc5267c40>:0
  at Duplicati.CommandLine.Commands.Backup

so possibly the setting --send-mail-level=Warning,Error,Fatal would have steered into fatal email attempt on anything making a warning or higher (and it’s not specifically related to missing source folder). Other reports that ended this way (and had enough of a stack trace) were also crashing in email sending.

Bug 60625 Summary: local-propagation.c:562, condition `ins->opcode > MONO_CEE_LAST’ not met
was seemingly not fixed before 11/16/2017, and was the closest to this I found during previous research.

Mono Releases suggests you may need a version released at least Feb 2018 to pick up the Nov 2017 fix, however I’m not an expert on mono release plans, just kind of looking at the Oct 2017 to Feb 2018 gap…

1 Like
7

Your assumption that sending the email caused the crash was probably right. I’ve removed all email related settings and started the backup again from the command line. Backup ends with

Backup started at 6/17/2020 5:39:01 PM

System.IO.IOException: The source folder /data/DeletedSourceFolder/ does not exist, aborting backup
  at Duplicati.Library.Main.Controller.ExpandInputSources (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x002c4] in <80402d19122441e2bd57fbfcc5267c40>:0
  at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0001d] in <80402d19122441e2bd57fbfcc5267c40>:0
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0026f] in <80402d19122441e2bd57fbfcc5267c40>:0
  at Duplicati.Library.Main.Controller.Backup (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x00074] in <80402d19122441e2bd57fbfcc5267c40>:0
  at Duplicati.CommandLine.Commands.Backup (System.IO.TextWriter outwriter, System.Action`1[T] setup, System.Collections.Generic.List`1[T] args, System.Collections.Generic.Dictionary`2[TKey,TValue] options, Duplicati.Library.Utility.IFilter filter) [0x00119] in <c47f7ad6ab9944308264c2287272a0ec>:0
  at (wrapper delegate-invoke) System.Func`6[System.IO.TextWriter,System.Action`1[Duplicati.Library.Main.Controller],System.Collections.Generic.List`1[System.String],System.Collections.Generic.Dictionary`2[System.String,System.String],Duplicati.Library.Utility.IFilter,System.Int32]:invoke_TResult_T1_T2_T3_T4_T5 (System.IO.TextWriter,System.Action`1<Duplicati.Library.Main.Controller>,System.Collections.Generic.List`1<string>,System.Collections.Generic.Dictionary`2<string, string>,Duplicati.Library.Utility.IFilter)
  at Duplicati.CommandLine.Program.ParseCommandLine (System.IO.TextWriter outwriter, System.Action`1[T] setup, System.Boolean& verboseErrors, System.String[] args) [0x00342] in <c47f7ad6ab9944308264c2287272a0ec>:0
  at Duplicati.CommandLine.Program.RunCommandLine (System.IO.TextWriter outwriter, System.IO.TextWriter errwriter, System.Action`1[T] setup, System.String[] args) [0x00002] in <c47f7ad6ab9944308264c2287272a0ec>:100:

After adding --allow-missing-source=true to the backup command, the backup completes successfully.

Next step is updating Mono, hopefully this will be the definitive fix for this crash.