Duplicati Hangs after Internet Disconnect

[daniel7]

Hi there,
I have Duplicati 2.0.3.3_beta_2018-04-02 installed (with the openmediavault plugin) on my NAS.

After setting everything up I can successfully start the backup process and files are written to AWS S3. Each night at around 3 am my ISP disconnects my internet connection and Duplicati does not recover from this.

At the top is says that my Backup is “Running …” but nothing happens.

In my log file for the backup there is nothing in the “General” section, but in the “Remote”-Tab :

27. Apr.2018 03:38: put duplicati-b6[…]a.dblock.zip.aes

That is the last line in the log and at 3:38 my ISP disconnected me for a few seconds.

What can I do that Duplicati resumes the last upload when this happens? The storage target is AWS S3.

Best regards,
Daniel

[daniel7]

Hi,
This problem is reproducible on my machine, so we can try different things and I can post the logs every day.

I got this log message from the “Reporting”-Tab --> Show log.
There are no log messages in the General Section and the Remote section is full of put messages

Apr 27, 2018 3:38 AM: put duplicati-b617d87f9273c4575966df12e02f7c27a.dblock.zip.aes
Apr 27, 2018 3:38 AM: put duplicati-ic1e72e85e2654b9b9a4ed11a92492205.dindex.zip.aes
Apr 27, 2018 3:36 AM: put duplicati-b06ab335ab47f4719b8dc368f73257065.dblock.zip.aes
Apr 27, 2018 3:36 AM: put duplicati-ieb7a59d70a9f47b5a032ce2654c97c5a.dindex.zip.aes     
Apr 27, 2018 3:34 AM: put duplicati-bcb031309288c481487ac88819fa3b205.dblock.zip.aes
Apr 27, 2018 3:34 AM: put duplicati-i37f373394ec145ce98b88eed3a5bdfc0.dindex.zip.aes 
Apr 27, 2018 3:31 AM: put duplicati-be4037b3adfb14574b73a953097ff15c9.dblock.zip.aes
Apr 27, 2018 3:31 AM: put duplicati-i95c1f2eb307946eea5511a1758500992.dindex.zip.aes
Apr 27, 2018 3:29 AM: put duplicati-bdf32c9b6294f45dbbfdd7ba4dd194c24.dblock.zip.aes 
Apr 27, 2018 3:29 AM: put duplicati-i2425dc1c9ddc44faa0fee282692e84ef.dindex.zip.aes
Apr 27, 2018 3:26 AM: put duplicati-b4e05a1ad51684544aa1059db6257e5b3.dblock.zip.aes
Apr 27, 2018 3:26 AM: put duplicati-id3f1e20758664e73a8c15e4b191ad58a.dindex.zip.aes
Apr 27, 2018 3:24 AM: put duplicati-b442a2a841ca74d5d999e8aaf7f934e86.dblock.zip.aes 
Apr 27, 2018 3:24 AM: put duplicati-i7c953794b8d64442af96a3f85acac4bf.dindex.zip.aes
Apr 27, 2018 3:22 AM: put duplicati-b55a8e72af6004d1cb55d4a3fd3582da3.dblock.zip.aes
Apr 27, 2018 3:22 AM: put duplicati-i2629d0a16eee4c17bfd0646f22294e74.dindex.zip.aes
Apr 27, 2018 3:20 AM: put duplicati-b972a3083e62043e3bd8bcce49bfedd27.dblock.zip.aes
Apr 27, 2018 3:20 AM: put duplicati-i5390a41243f54a6bb30f66ef92ac66f6.dindex.zip.aes
[... it goes on and on with these put messages, nothing else is in the log ...]
Apr 26, 2018 9:03 PM: put duplicati-if9492d4c73884486b31959fd4ad6e809.dindex.zip.aes
Apr 26, 2018 9:01 PM: put duplicati-bd65a9c722eaa41bf9dde0173e93ae668.dblock.zip.aes
Apr 26, 2018 9:00 PM: list  

When I go to About->Show log:
Stored Section contains:
Apr 25, 2018 3:07 PM: Failed while executing “Backup” with id: 1
Apr 25, 2018 3:07 PM: Error in worker

Live Section contains nothing except with the Information log level it tells me when I started the server.

I will try again and then post the contents of the live section. (Should I try to set the --retry-delay --number-of-retries for the next run to higher values?)

Daniel

[JonMikelV]

@daniel7

Should I try to set the --retry-delay --number-of-retries for the next run to higher values?

It’s worth a try, but I doubt it will help as normally the logs would show retries if they were already happening.

[daniel7]

So I now have the Informational Live Logs:
It just stopps without any error message when the internet connection is disrupted:

May 1, 2018 3:33 AM: Backend event: Put - Started: duplicati-bdd20eecfe6714e3990d74fc61233690e.dblock.zip.aes (249,92 MB)
May 1, 2018 3:33 AM: Backend event: Put - Completed: duplicati-i93fb8e622400424c863d97ce0a986c8d.dindex.zip.aes (151,14 KB)
May 1, 2018 3:33 AM: Backend event: Put - Started: duplicati-i93fb8e622400424c863d97ce0a986c8d.dindex.zip.aes (151,14 KB)
May 1, 2018 3:33 AM: Backend event: Put - Completed: duplicati-bc4870b60763646c1a740f18c55b38c68.dblock.zip.aes (249,92 MB) 
May 1, 2018 3:31 AM: Backend event: Put - Started: duplicati-bc4870b60763646c1a740f18c55b38c68.dblock.zip.aes (249,92 MB)
May 1, 2018 3:31 AM: Backend event: Put - Completed: duplicati-i9e8ea01a30df469cb08547dccd1f16d8.dindex.zip.aes (137,64 KB)
May 1, 2018 3:31 AM: Backend event: Put - Started: duplicati-i9e8ea01a30df469cb08547dccd1f16d8.dindex.zip.aes (137,64 KB) 
May 1, 2018 3:31 AM: Backend event: Put - Completed: duplicati-b1b5728b74935490ea88173e19b04444d.dblock.zip.aes (249,91 MB)
May 1, 2018 3:28 AM: Backend event: Put - Started: duplicati-b1b5728b74935490ea88173e19b04444d.dblock.zip.aes (249,91 MB)
May 1, 2018 3:28 AM: Backend event: Put - Completed: duplicati-ia5abf15f729a4a5b84bd7b22004e0671.dindex.zip.aes (170,33 KB)
May 1, 2018 3:28 AM: Backend event: Put - Started: duplicati-ia5abf15f729a4a5b84bd7b22004e0671.dindex.zip.aes (170,33 KB)
May 1, 2018 3:28 AM: Backend event: Put - Completed: duplicati-b916b1d1139344c75a858c755646c8783.dblock.zip.aes (249,96 MB)
May 1, 2018 3:26 AM: Backend event: Put - Started: duplicati-b916b1d1139344c75a858c755646c8783.dblock.zip.aes (249,96 MB)
May 1, 2018 3:26 AM: Backend event: Put - Completed: duplicati-i4ca42c4e6c264e588370cfc13badb452.dindex.zip.aes (171,50 KB)
May 1, 2018 3:26 AM: Backend event: Put - Started: duplicati-i4ca42c4e6c264e588370cfc13badb452.dindex.zip.aes (171,50 KB)
May 1, 2018 3:26 AM: Backend event: Put - Completed: duplicati-b32c7ae2ef7204c92877d2e913f7543cf.dblock.zip.aes (249,96 MB) 
May 1, 2018 3:24 AM: Backend event: Put - Started: duplicati-b32c7ae2ef7204c92877d2e913f7543cf.dblock.zip.aes (249,96 MB)
May 1, 2018 3:24 AM: Backend event: Put - Completed: duplicati-if2721f9f23374f5c9dc4d3e1dc3f7a9e.dindex.zip.aes (184,84 KB)
May 1, 2018 3:24 AM: Backend event: Put - Started: duplicati-if2721f9f23374f5c9dc4d3e1dc3f7a9e.dindex.zip.aes (184,84 KB)
May 1, 2018 3:24 AM: Backend event: Put - Completed: duplicati-bc3ae454c837242a2bd31741c70fcd183.dblock.zip.aes (249,95 MB)
May 1, 2018 3:21 AM: Backend event: Put - Started: duplicati-bc3ae454c837242a2bd31741c70fcd183.dblock.zip.aes (249,95 MB)
May 1, 2018 3:21 AM: Backend event: Put - Completed: duplicati-i271ec3189f484e999829b88f8ab70c16.dindex.zip.aes (148,39 KB)
May 1, 2018 3:21 AM: Backend event: Put - Started: duplicati-i271ec3189f484e999829b88f8ab70c16.dindex.zip.aes (148,39 KB)
May 1, 2018 3:21 AM: Backend event: Put - Completed: duplicati-ba1d64499f7004d0f8620a8cf4b85c50b.dblock.zip.aes (249,91 MB)
May 1, 2018 3:19 AM: Backend event: Put - Started: duplicati-ba1d64499f7004d0f8620a8cf4b85c50b.dblock.zip.aes (249,91 MB)
May 1, 2018 3:19 AM: Backend event: Put - Completed: duplicati-i3d9d3e67d98b43c2b2e2833615e4e237.dindex.zip.aes (174,04 KB)
May 1, 2018 3:19 AM: Backend event: Put - Started: duplicati-i3d9d3e67d98b43c2b2e2833615e4e237.dindex.zip.aes (174,04 KB)
May 1, 2018 3:19 AM: Backend event: Put - Completed: duplicati-b066e5610e7ea4637a015dad7fedc7c09.dblock.zip.aes (249,95 MB)
May 1, 2018 3:17 AM: Backend event: Put - Started: duplicati-b066e5610e7ea4637a015dad7fedc7c09.dblock.zip.aes (249,95 MB)
May 1, 2018 3:17 AM: Backend event: Put - Completed: duplicati-i76b0436d61314179ab11120bb9b984b8.dindex.zip.aes (161,51 KB)
...

[JonMikelV]

Thanks again for the detail!

@kenkendk or @Pectojin, do either of you have any insight into the http module and what might have changed recently?

[Pectojin]

Hmm, I have been noticing similarly that my macbook stalls occasionally during backups as well if it goes to sleep (like for the past month).

I’m not sure it’s a http module thing though.

[kenkendk]

There has not been any changes to the http module. The S3 backend uses the standard Mono http(s) connections. I am guessing that there is a problem with a timeout somewhere that does not kick in.

It should work such that the timeout happens, causing the upload to fail, and then Duplicati simply re-tries the upload and all is good.

Unfortunately, due to the way web connections are implementend in .Net (and the AWS library), we cannot replace the connection instance, so we need to figure out how to fix this through the AWS library.

[mplorentz]

@kenkendk is there a Github ticket for this already? If not I can create one. I am having this problem as well and there are several other threads that sound like this issue (linked below).

Duplicati job hangs on MacOS

Note: Starting new topic that better articulates my issue than topic “Slow Duplicati Bakcup on Mac OS” When running an initial backup, sometimes the backup hangs. Here is a current example from a 250GB backup I have been trying to run over the last two days. Notice that the is a put operation happening every minute or so and then at 12:24pm everything suddenly stops until I find the job stalled 9 hrs later and I restart it. Then again at 2:33am everything suddenly stops until I find the job…

Slow Duplicati Bakcup on Mac OS

Hi, I’m having some issues with Duplicati in my Mac OS computer. Is is very slow to backup. It takes a lot of time to execute this process in a folder with no more than 3 images. In windows, I tried I do not have this problem. Thanks.

SSH / SFTP hangs forever

In some cases the verify step with SSH seems to hang forever. I’ve got no idea why this is happening, because everything is working, except verification. Logs just show that file is being downloaded and that’s it. Duplicati never continues from this step. Yet it’s hard to say if the issue is with the ssh client library which duplicati is usingor duplicati itself. I’ve scheduled task killing to get rid of this, but it naturally reduces the reliability of backup.

[Sami_Lehtinen]

I can just say that I haven’t had that problem with SFTP anymore. I don’t have a clue what was the real reason for the Duplicati hanging. Yet I know it was SFTP and data transfer related. Probably something hang forever or had extremely long timeout or some return value was misinterpreted and lead to never ending wait or so.

But I haven’t seen that problem for quite a while. If someone else suffers from it, providing debug logs could be very helpful.

I’ve updated Duplicati and my distribution and so many things have changed that I’m unable to pinpoint the problem.

[Mark_Daubenmier]

Hi @Sami_Lehtinen - The link that @mplorentz provided above to “Duplicati job hangs on MacOS” shows the log file from when my job was hanging.

[Sami_Lehtinen]

Sure the logs shows when and where the job hangs, but it doesn’t show you why. That’s the problem. It would require more debugging, more detailed logs and probably even more debug stuff. -> Not worth of it.

The log is exactly similar as my logs which I provided earlier showing sftp hang, and it’s no good for fixing the issue. Because it doesn’t show what the issue is.

[Mark_Daubenmier]

OK. Got it. I see now that it was not helpful. I am out of my league here.

[kenkendk]

@mplorentz

@kenkendk is there a Github ticket for this already?

I do not recall there being one.

Unfortunately, the .Net http stuff is pretty locked down and used everywhere so there is often very few ways to fix issues such as this. For instance, the S3 library starts its own https connections and sets whatever timeout and error handling it needs, without any way to change it from the calling code.

We would need to build and distribute a custom runtime to fix such issues.

One sledgehammer approach would be to always run each backup in an isolated process, such that we can kill it when no progress has been reported for a while. For this particular issue, we could perhaps just run the upload/download process in another process.

[ts678]

AWS SDK for .NET Retries and Timeouts documentation has some, though I have no idea if they’re enough.
For AWS S3, there might also be a chance that a libraries update would help. It looks like last one was 9/17. Maybe using more settings below could avoid the major runtime or process work, at least where they apply?

AmazonS3Config
HttpWebRequest Class (.NET Framework)
System.Net.HttpWebRequest: Property Members (Mono)

[mplorentz]

Unfortunately (and fortunately) I can no longer reproduce this. I upgraded my bandwidth and now my backup completes before it hangs. I worry that there is still a bug lurking here, but I’m not sure how to further debug it.