Duplicati server stops without explanation

Stephen · February 14, 2018, 3:42pm

I am using duplicati on windows 10. I’ve just found that it is stopping without explanation. It was working fine for the last few days and even earlier today. When it stops, the trayicon goes away too. I can start it again but it stops again after less than a minute. I’m not really sure how to debug it or get logs on what is happening. I tried to look at the logs from the duplicati web gui but it isn’t logging this shutdown event (yes I did get access long enough to see this!).

I am using the most recent beta version of duplicati.

If anyone has suggestions how I can check this further I would welcome them. Thanks

Pectojin · February 14, 2018, 3:49pm

I haven’t had this happen, it really sounds weird.

I think if you set --log-file to a place on disk you’d like the log file and then set --log-level=informational, on the Duplicati executeable, then it should start up and log to that output file so you can get an idea of what’s actually happening.

Edit: alternatively, if you can get into the server for a little while you can add it on the settings page at the bottom Add advanced option

JonMikelV · February 15, 2018, 4:00am

If things aren’t stable enough to try @Pectojin’s suggestion, you could try running Duplicati from the command line with the --verbose=true parameter added. This should give extra info about what Duplicati is doing when the crash occurs.

Note that it might make a difference whether your running Duplicati as a service or just the tray-icon.

Stephen · February 15, 2018, 9:29am

Thanks guys for your advice. I’ll try this as soon as I can and report back. In the meantime here is what the windows event viewer reports about it. I’m not sure if it helps.

Fault bucket , type 0
Event Name: CLR20r3
Response: Not available
Cab Id: 0

Problem signature:
P1: Duplicati.GUI.TrayIcon.exe
P2: 2.0.2.1
P3: 5980511c
P4: mscorlib
P5: 4.7.2600.0
P6: 59d78a65
P7: 40cd
P8: 18
P9: System.InvalidOperationException
P10:

Analysis symbol:
Rechecking for solution: 0
Report Id: b89dce29-0976-4498-868d-7b3080016e1e
Report Status: 32780
Hashed bucket:

Stephen · February 15, 2018, 9:34am

@Pectojin
Thanks. I tried setting it from the command line but couldn’t make it work, so thanks for the steps to get to it quickly from the web gui! I had enough time to make one setting at a time before it crashed.

Unfortunately this is as informative as it is:
2018-02-15 14:02:24Z - Information: Backend event: List - Started: ()
2018-02-15 14:02:24Z - Information: Backend event: List - Completed: (581 bytes)

A little later, I noticed that when starting the trayicon the web gui was reporting that it was counting something to do with the backup task in the information at the top. So I aborted that and got this in the log. However, even after aborting that, the duplicati server still died.
2018-02-15 14:02:24Z - Information: Backend event: List - Started: ()
2018-02-15 14:02:24Z - Information: Backend event: List - Completed: (581 bytes)
2018-02-15 14:07:44Z - Information: Backend event: List - Started: ()
2018-02-15 14:07:44Z - Information: Backend event: List - Completed: (581 bytes)
2018-02-15 14:17:18Z - Information: Backend event: List - Started: ()
2018-02-15 14:17:18Z - Information: Backend event: List - Completed: (581 bytes)
2018-02-15 14:20:41Z - Information: Backend event: List - Started: ()
2018-02-15 14:20:41Z - Information: Backend event: List - Completed: (581 bytes)
2018-02-15 14:20:52Z - Error: Fatal error
System.Threading.ThreadAbortException: Thread was being aborted.
at System.Threading.Thread.AbortInternal()
at System.Threading.Thread.Abort()
at Duplicati.Library.Main.BasicResults.TaskControlRendevouz()
at Duplicati.Library.Main.Operation.BackupHandler.RunMainOperation(ISnapshotService snapshot, BackendManager backend)
at Duplicati.Library.Main.Operation.BackupHandler.Run(String[] sources, IFilter filter)

Stephen · February 15, 2018, 9:36am

@JonMikeIV

Thanks. That gave two results - one at the command line and one as a gui.

C:\Program Files\Duplicati 2>duplicati.gui.trayicon --verbose=true

C:\Program Files\Duplicati 2>Server has started and is listening on 127.0.0.1, port 8200

Unhandled Exception: System.InvalidOperationException: An attempt was made to transition a task to a final state when it had already completed.
   at System.Threading.Tasks.TaskCompletionSource`1.SetResult(TResult result)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

Unhandled Exception: System.InvalidOperationException: An attempt was made to transition a task to a final state when it had already completed.
   at System.Threading.Tasks.TaskCompletionSource`1.SetResult(TResult result)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

I am not sure what it is doing. I didn’t do anything other than start duplicati. I didn’t even open the webgui. It just happily dies after a short while on its own.

The Windows GUI error that popped up was this:

WINDOW TITLE: Duplicati.GUI.TrayIcon
TEXT TITLE: Duplicati.GUI.TrayIcon has stopped working
TEXT: A problem caused the program to stop working correctly. Windows will close the program and notify you if a solution is available.

I’m guessing that this GUI error is generic from Windows itself and not useful, but thought I should report it to you for completeness.
Thanks!

And @JonMikelV, I’m running duplicati as a trayicon not a service.

JonMikelV · February 15, 2018, 3:15pm

Thanks for the details! I went ahead and edited your post by putting “~~~” around the command line stuff and “>” before the GUI text to make them easier to read.

It sounds like you’re running into the same issue as mentioned in these topics:

github.com/duplicati/duplicati

Usage statistics causes Duplicati2 to crash when behind a proxy using authentication.

opened 06:51PM - 08 Feb 18 UTC

drsox

bug

- [x] I have searched open and closed issues for duplicates. ----------------…------------------------ ## Environment info - **Duplicati version**: 2.0.2.1_beta_2017-08-01 - **Operating system**: Windows 7 - **Backend**: N/A ## Description When the Usage statistics function is set and the system has a proxy enabled.. the proxy sending "HTTP/1.1 407 Proxy Authentication Required" causes Duplicati.GUI.TrayIcon to crash and, if running, abort any backup that is running. ## Steps to reproduce 1. Set an http proxy in Internet Explorer / system settings 2. Make sure that the proxy has authentication enabled. 3. Load Duplicati2 and hope that it tries to send usage statistics. 4. Duplicati2 crashes. - **Actual result**: ~60 CONNECT requests are attempted to usage-reporter.duplicati.com on port 443, each are responded to with a "407" status and Duplicati2 never retries with authentication credentials. Duplicati2 then crashes. - **Expected result**: Either a silent failure / graceful handling of the unexpected HTTP response and continuation of normal program functions.. or handle proxy authentication so that normal program functions _and_ usage statistics both work. ## Screenshots ![duplicati2crashproxyauth](https://user-images.githubusercontent.com/761083/35991996-e1ed5386-0d00-11e8-8781-a2d05c9bc276.png) ## Debug log Not available, sorry.

If you can get into the GUI fast enough try setting main menu Settings → “Anonymous usage reports” to “None / Disabled”.

I’m not aware of the command line parameter to disable usage log reporting, but if you can’t get into the GUI to turn it off you could also try deleting any pending submissions from your temp folder. Assuming standard settings, this can be done in the command shell by:

changing to your temp folder by running cd %tmp%
listing pending submissions by running dir dupl-usagereport-*
If there are more than 50 or so of them, delete them by running del dupl-usagereport-*

You can also do it in Windows Explorer by:

Enter %tmp% in the path folder
Sort or filter such that all the dupl-usagereport-* files are grouped together
highlight and delete

Stephen · February 15, 2018, 5:03pm

Thanks @JonMikelV I’ll look into that.

Using @Pectojin s client tool I just noticed this that I thought might shed a little more light on it.

Fetching backup list from API...
- Backup:
    ID: '1'
    Name: SteveW10HP360
  Progress:
    Backend:
      BackendAction: List
      Processed files: 76.42829631531647%
    Counting: true
    State: Backup_ProcessingFiles
    Task ID: 2
  Schedule:
    Last run: 02:20 PM
    Next run: 02:30 PM
    Repeat: 30m

code: 200

You’ll notice it says that the backup state is “Backup_processing files” and “Counting” is “true”. So while I am not expecting the application to be doing anything at the time it is crashing, it appears it is trying to, so I’m not sure if it is during one of those processes that it is failing. In any case, I’ll check out the links you referenced and see if those resolve it.
Thanks!

Stephen · February 16, 2018, 10:20am

@JonMikelV thanks! I deleted the dupl-usagereport- files and it seems stable now. I’m not really thrilled about the idea of disabling the anonymous usage reports since those are presumably useful to the development team to know how the software is being used, therefore if I disable this I’m no longer playing my part as a community member by reporting the usage. That said, if it happens again I probably will disable it. Hopefully it can be fixed for the stable release.

For reference, there were 114 dupl-usagereport- files. I’ve kept a copy of them all in case there is any information in them that would help you find the source of this problem, but I couldn’t see anything obvious in them myself. Let me know if you need them.

JonMikelV · February 16, 2018, 6:56pm

Glad to hear it worked for you!

So far it looks like the cause of the problem is not being able to submit the reports to the reports server. The result is the log files queue up on the temp folder. The crash is too many (50+ ?) report files queued.

Thanks for thinking of keeping the report files (instead of deleting them) but unless @kenkendk feels they might shed some light, they’re probably ok to delete.