Duplicacy restore command says it's finished, but never terminates

Support
#1

Recently when restoring, duplicacy restore hangs forever after printing the total running time. Probably this is new behaviour in 3.1.0. The version I used previously that didn’t do this was 2.7.6. If there were other versions between those I didn’t use them.

Restored /home/user/.common to revision 135
Files: 35357 total, 6108.40M bytes
Downloaded 17276 file, 806.16M bytes, 219 chunks
Skipped 18051 file, 5302.24M bytes
Total running time: 00:04:07

In another terminal:

ps aux | grep duplicacy
user        1460  1.4  0.8 1138628 216728 pts/3  Sl+  07:16   1:48 duplicacy restore -hash -overwrite -delete -threads 8 -stats -r 135

In this instance I’ve been waiting around 2 hours. I don’t think it’s ever going to finish. What is it doing?

It probably doesn’t matter, since duplicacy seems to think it has no further work to do, but the remote is on Wasabi.

This is on Fedora 36.

Thanks.

#2

I finally hit ctrl-c and ran:

duplicacy diff -hash

just to make sure the snapshot really was completely uploaded. It returned no results so my directory matches the snapshot. duplicacy is doing everything it should, except exiting.

#3

Do you see any errors in the log file ~/.duplicacy-web/logs/duplicacy_web.log?

#4

I don’t use the web, only the CLI.

I checked for the presence of that file anyway just in case, but there’s no ~/.duplicacy-web directory.

#5

I’ve been toggling back and forth between restoring the last two snapshots in my repo, r134 and r135, to try to identify the problem.

For some reason it’s more likely to hang on r 135 (the latest snapshot) than r 134 (the second to last snapshot). That could be a red herring but it seldom happens on r 134 and [almost?] always happens on r 135.

I tried with a single thread in case it’s a threading issue. I couldn’t reproduce it with a single thread in 5 consecutive tests.

Then I tried two threads and it immediately failed:

> duplicacy restore -hash -overwrite -delete -threads 2 -stats -r 134
... lots of output omitted
Restored /home/user/.common to revision 134
Files: 35633 total, 6304.83M bytes
Downloaded 17554 file, 1002.59M bytes, 232 chunks
Skipped 18051 file, 5302.24M bytes
Total running time: 00:08:09
Downloaded chunk 1115 size 6281305, 2.49MB/s 00:34:02 19.3%

This is pretty interesting because it’s telling me it downloaded a chunk AFTER it is finished. It doesn’t always do this when it hangs, but it did do this on one of my previous tests so the above is the second time it happened that I’ve observed.

At this point it looks like a threading issue to me. I ran it with strace but I couldn’t interpret the output.

#6

You can add a global option -profile to enable the built-in profiling tool:

duplicacy -profile 127.0.0.1:8080 restore -hash -overwrite -delete -threads 2 -stats -r 135

When it gets stuck, open http://127.0.0.1:8080/debug/pprof/ in browser then select goroutine. You will see a full stack trace. Post the trace here and we can figure out where it gets stuck.

#7

OK interesting, I didn’t know that was in there. Thanks.

I tried it, here’s where it’s parked right now. I uploaded the output of that debug page.

Restored /home/user/.common to revision 135
Files: 35357 total, 6108.40M bytes
Downloaded 17276 file, 806.16M bytes, 202 chunks
Skipped 18051 file, 5302.24M bytes
Total running time: 00:10:13
Downloaded chunk 1086 size 14563511, 1.67MB/s 00:50:46 16.9%

goroutine.txt (6.8 KB)