Prune operation got stuck for 2 days

saspus · 1 May 2020 19:53

Prune got stuck on deleting snapshot 32 two days ago. Process is hanging waiting for something.
I’m not sure how to get spindump on linux. This is SFTP backend. What diagnostic can I provide?

Maybe it makes sense to implement software watchdog to reset connection if no traffic flows for a few minutes? Or at least hours?

ash-4.3# ps -ax  | grep dupl | grep -v grep
 7832 ?        Sl     7:02 /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.1 -log prune -storage cumulonimbus -keep 31:360 -keep 7:90 -keep 1:14 -a
19716 ?        Sl    41:13 /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.1 -log backup -storage cumulonimbus -stats
24164 ?        Ssl    7:32 /var/services/homes/duplicacy-web/duplicacy_web_linux_x64_1.3.0

ash-4.3# tail prune-20200429-045733.log
2020-04-29 04:58:27.210 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 23
2020-04-29 04:58:28.710 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 24
2020-04-29 04:58:30.412 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 25
2020-04-29 04:58:31.876 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 26
2020-04-29 04:58:33.326 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 27
2020-04-29 04:58:34.760 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 28
2020-04-29 04:58:36.179 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 29
2020-04-29 04:58:37.638 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 30
2020-04-29 04:58:39.095 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 31
2020-04-29 04:58:40.555 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 32

gchen · 1 May 2020 22:20

Can you run gdb -p pid to look into the process and then thread apply all bt to get the backtrace of all threads?

The CLI used to have a bug that got stuck on a closed ssh connection but that has been fixed.

saspus · 1 May 2020 22:41

ash-4.3# synogear install
root@Tuchka:/volume1/homes/alex# ps -ax |grep duplicacy
 3757 pts/11   S+     0:00 grep --color=auto duplicacy
 7832 ?        Sl     7:05 /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.1 -log prune -storage cumulonimbus -keep 31:360 -keep 7:90 -keep 1:14 -a
19716 ?        Sl    43:31 /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.1 -log backup -storage cumulonimbus -stats
24164 ?        Ssl    7:38 /var/services/homes/duplicacy-web/duplicacy_web_linux_x64_1.3.0
root@Tuchka:/volume1/homes/alex# sudo gdb -p 7832
GNU gdb (GDB) 7.12.1
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 7832
[New LWP 7833]
[New LWP 7834]
[New LWP 7835]
[New LWP 7836]
[New LWP 7837]
[New LWP 7838]
[New LWP 7839]
[New LWP 7841]
[New LWP 7842]
[New LWP 7843]
[New LWP 7844]
runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
536	/usr/local/go/src/runtime/sys_linux_amd64.s: No such file or directory.
warning: Unsupported auto-load script at offset 0 in section .debug_gdb_scripts
of file /volume1/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.1.
Use `info auto-load python-scripts [REGEXP]' to list them.
(gdb) thread apply all bt

Thread 12 (LWP 7844):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0xc00032e848, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0xc00032e848) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x0000000000433221 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1936
#4  0x000000000043437a in runtime.findrunnable (gp=0xc000040500, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2399
#5  0x0000000000434f9c in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2525
#6  0x00000000004352b1 in runtime.park_m (gp=0xc000080900) at /usr/local/go/src/runtime/proc.go:2605
#7  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
#8  0x000000c0003fc420 in ?? ()
#9  0x0000000000000000 in ?? ()

Thread 11 (LWP 7843):
#0  runtime.epollwait () at /usr/local/go/src/runtime/sys_linux_amd64.s:675
#1  0x000000000042b236 in runtime.netpoll (block=true, ~r1=...) at /usr/local/go/src/runtime/netpoll_epoll.go:71
#2  0x000000000043434f in runtime.findrunnable (gp=0xc00003e000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2380
#3  0x0000000000434f9c in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2525
#4  0x00000000004352b1 in runtime.park_m (gp=0xc000000180) at /usr/local/go/src/runtime/proc.go:2605
#5  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
#6  0x0000000000000000 in ?? ()

Thread 10 (LWP 7842):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0xc000390bc8, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0xc000390bc8) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x0000000000433221 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1936
#4  0x0000000000436738 in runtime.exitsyscall0 (gp=0xc000000180) at /usr/local/go/src/runtime/proc.go:3128
#5  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
---Type <return> to continue, or q <return> to quit---
#6  0x000000c000134a80 in ?? ()
#7  0x0000000000000000 in ?? ()

Thread 9 (LWP 7841):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0xc000444148, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0xc000444148) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x0000000000433221 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1936
#4  0x000000000043437a in runtime.findrunnable (gp=0xc000042a00, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2399
#5  0x0000000000434f9c in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2525
#6  0x00000000004352b1 in runtime.park_m (gp=0xc000080900) at /usr/local/go/src/runtime/proc.go:2605
#7  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
#8  0x0000000000000000 in ?? ()

Thread 8 (LWP 7839):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0xc000390148, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0xc000390148) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x0000000000433221 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1936
#4  0x000000000043437a in runtime.findrunnable (gp=0xc00003e000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2399
#5  0x0000000000434f9c in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2525
#6  0x00000000004352b1 in runtime.park_m (gp=0xc000393080) at /usr/local/go/src/runtime/proc.go:2605
#7  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
#8  0x0000000000000000 in ?? ()

Thread 7 (LWP 7838):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0x1a9fa38 <runtime.newmHandoff+24>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0x1a9fa38 <runtime.newmHandoff+24>) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x0000000000433143 in runtime.templateThread () at /usr/local/go/src/runtime/proc.go:1914
#4  0x0000000000431e14 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1206
#5  0x0000000000431d2f in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1172
#6  0x000000000045e7c3 in runtime.clone () at /usr/local/go/src/runtime/sys_linux_amd64.s:587
#7  0x0000000000000000 in ?? ()

Thread 6 (LWP 7837):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0xc000054bc8, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0xc000054bc8) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x0000000000433221 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1936
#4  0x000000000043437a in runtime.findrunnable (gp=0xc000040500, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2399
#5  0x0000000000434f9c in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2525
#6  0x00000000004352b1 in runtime.park_m (gp=0xc000080900) at /usr/local/go/src/runtime/proc.go:2605
#7  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
#8  0x0000000000000000 in ?? ()

Thread 5 (LWP 7836):
---Type <return> to continue, or q <return> to quit---
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0x1a9fb20 <runtime.sig>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a908 in runtime.notetsleep_internal (n=0x1a9fb20 <runtime.sig>, ns=-1, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:174
#3  0x000000000040ab0c in runtime.notetsleepg (n=0x1a9fb20 <runtime.sig>, ns=-1, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:228
#4  0x0000000000443a7c in os/signal.signal_recv (~r0=<optimized out>) at /usr/local/go/src/runtime/sigqueue.go:139
#5  0x000000000071cdd2 in os/signal.loop () at /usr/local/go/src/os/signal/signal_unix.go:23
#6  0x000000000045c8e1 in runtime.goexit () at /usr/local/go/src/runtime/asm_amd64.s:1337
#7  0x0000000000000000 in ?? ()

Thread 4 (LWP 7835):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0xc000054848, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0xc000054848) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x0000000000433221 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1936
#4  0x000000000043437a in runtime.findrunnable (gp=0xc000044f00, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2399
#5  0x0000000000434f9c in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2525
#6  0x00000000004352b1 in runtime.park_m (gp=0xc000446a80) at /usr/local/go/src/runtime/proc.go:2605
#7  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
#8  0x0000000000000000 in ?? ()

Thread 3 (LWP 7834):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b3f2 in runtime.futexsleep (addr=0x1a86c00 <runtime.timers+160>, val=0, ns=9999922792) at /usr/local/go/src/runtime/os_linux.go:63
#2  0x000000000040a9b2 in runtime.notetsleep_internal (n=0x1a86c00 <runtime.timers+160>, ns=9999922792, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:193
#3  0x000000000040ab0c in runtime.notetsleepg (n=0x1a86c00 <runtime.timers+160>, ns=9999922792, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:228
#4  0x000000000044c03a in runtime.timerproc (tb=0x1a86be0 <runtime.timers+128>) at /usr/local/go/src/runtime/time.go:311
#5  0x000000000045c8e1 in runtime.goexit () at /usr/local/go/src/runtime/asm_amd64.s:1337
#6  0x0000000001a86be0 in runtime.timers ()
#7  0x0000000000000000 in ?? ()

Thread 2 (LWP 7833):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b3f2 in runtime.futexsleep (addr=0x1a82cb0 <runtime.sched+272>, val=0, ns=60000000000) at /usr/local/go/src/runtime/os_linux.go:63
#2  0x000000000040a9b2 in runtime.notetsleep_internal (n=0x1a82cb0 <runtime.sched+272>, ns=60000000000, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:193
#3  0x000000000040aa81 in runtime.notetsleep (n=0x1a82cb0 <runtime.sched+272>, ns=60000000000, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:216
#4  0x0000000000439a94 in runtime.sysmon () at /usr/local/go/src/runtime/proc.go:4305
#5  0x0000000000431e14 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1206
#6  0x0000000000431d2f in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1172
#7  0x000000000045e7c3 in runtime.clone () at /usr/local/go/src/runtime/sys_linux_amd64.s:587
#8  0x0000000000000000 in ?? ()

Thread 1 (LWP 7832):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:536
#1  0x000000000042b37b in runtime.futexsleep (addr=0x1a83768 <runtime.m0+328>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:46
#2  0x000000000040a821 in runtime.notesleep (n=0x1a83768 <runtime.m0+328>) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x00000000004338ac in runtime.stoplockedm () at /usr/local/go/src/runtime/proc.go:2076
#4  0x000000000043513a in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2477
---Type <return> to continue, or q <return> to quit---
#5  0x00000000004352b1 in runtime.park_m (gp=0xc000080d80) at /usr/local/go/src/runtime/proc.go:2605
#6  0x000000000045a97b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299
#7  0x000000000045a899 in runtime.rt0_go () at /usr/local/go/src/runtime/asm_amd64.s:201
#8  0x0000000000000000 in ?? ()
(gdb)

Whoa! I did not realize the duplicacy binary is symbolicated – I did not even bother with gdb expecting to see list of addresses only!

I’ll keep the session open, let me know if you want me to poke around.

gchen · 2 May 2020 00:15

I don’t see any Duplicacy code in the stack trace. Maybe a golang bug?

saspus · 2 May 2020 01:20

Isn’t block on runtime.futexsleep an expected behavior when goroutines are sleeping on an event? The thread 11 looks suspicious – looks like it polled network and waits for response?

On the other hand, my limited google-fu yielded this fairly recent bug report runtime: deadlock in runtime.findrunnable · Issue #35532 · golang/go · GitHub with very similarly looking symptoms.

Does your go have this patch? https://go-review.googlesource.com/c/go/+/207348/

Do you want me to kill and continue to see if this happens again or keep it in the debugger in case you want to look at other possible state?

gchen · 2 May 2020 02:47

The stack trace there looks similar but I don’t know if it is the same issue. This one likely happened when the program was exiting.

My go version is 1.12.9. I don’t see the patch went into the 1.12 branch.

You can kill the process now – the stack trace should be enough.

saspus · 6 May 2020 23:22

I’m hitting this issue every three days, which is pretty much every time I run prune on that SFTP storage.

The last messages are always like this:

2020-05-06 14:58:36.368 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 58
2020-05-06 14:58:37.866 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 59
2020-05-06 15:03:13.906 WARN SFTP_RETRY Encountered an error (EOF); retry after 1 second(s)

(it’s now 16:20, so it was hanging for more than an hour)

Sometimes hang occurs after few retries

alex@Tuchka:/var/services/homes/duplicacy-web/.duplicacy-web/logs$ grep -B 2 -R "WARN SFTP_RETRY Encountered an error (EOF); retry after " .
./prune-20200503-051708.log-2020-05-03 05:18:59.134 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 58
./prune-20200503-051708.log-2020-05-03 05:19:00.821 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 59
./prune-20200503-051708.log:2020-05-03 05:24:10.604 WARN SFTP_RETRY Encountered an error (EOF); retry after 1 second(s)
./prune-20200503-051708.log:2020-05-03 05:24:13.712 WARN SFTP_RETRY Encountered an error (EOF); retry after 2 second(s)
./prune-20200503-051708.log:2020-05-03 05:24:17.352 WARN SFTP_RETRY Encountered an error (EOF); retry after 4 second(s)
./prune-20200503-051708.log:2020-05-03 05:24:22.903 WARN SFTP_RETRY Encountered an error (EOF); retry after 8 second(s)
./prune-20200503-051708.log:2020-05-03 05:24:32.557 WARN SFTP_RETRY Encountered an error (EOF); retry after 16 second(s)
./prune-20200503-051708.log:2020-05-03 05:24:50.495 WARN SFTP_RETRY Encountered an error (EOF); retry after 32 second(s)
./prune-20200503-051708.log:2020-05-03 05:25:24.093 WARN SFTP_RETRY Encountered an error (EOF); retry after 64 second(s)
./prune-20200503-051708.log:2020-05-03 05:26:29.619 WARN SFTP_RETRY Encountered an error (EOF); retry after 128 second(s)
./prune-20200503-051708.log-2020-05-03 05:28:40.007 WARN SFTP_RETRY Encountered an error (failed to send packet: EOF); retry after 1 second(s)
./prune-20200503-051708.log:2020-05-03 05:28:42.634 WARN SFTP_RETRY Encountered an error (EOF); retry after 2 second(s)
./prune-20200503-051708.log:2020-05-06 00:11:24.571 WARN SFTP_RETRY Encountered an error (EOF); retry after 4 second(s)
--
./prune-20200506-043320.log-2020-05-06 04:34:57.002 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 58
./prune-20200506-043320.log-2020-05-06 04:34:58.516 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 59
./prune-20200506-043320.log:2020-05-06 04:39:34.737 WARN SFTP_RETRY Encountered an error (EOF); retry after 1 second(s)
./prune-20200506-043320.log:2020-05-06 04:39:36.602 WARN SFTP_RETRY Encountered an error (EOF); retry after 2 second(s)
./prune-20200506-043320.log:2020-05-06 04:39:39.500 WARN SFTP_RETRY Encountered an error (EOF); retry after 4 second(s)
./prune-20200506-043320.log:2020-05-06 04:39:44.376 WARN SFTP_RETRY Encountered an error (EOF); retry after 8 second(s)
./prune-20200506-043320.log:2020-05-06 04:39:53.236 WARN SFTP_RETRY Encountered an error (EOF); retry after 16 second(s)
./prune-20200506-043320.log:2020-05-06 04:40:11.139 WARN SFTP_RETRY Encountered an error (EOF); retry after 32 second(s)
./prune-20200506-043320.log:2020-05-06 04:40:43.978 WARN SFTP_RETRY Encountered an error (EOF); retry after 64 second(s)
./prune-20200506-043320.log:2020-05-06 04:41:48.858 WARN SFTP_RETRY Encountered an error (EOF); retry after 128 second(s)
--
./prune-20200506-145658.log-2020-05-06 14:58:36.368 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 58
./prune-20200506-145658.log-2020-05-06 14:58:37.866 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 59
./prune-20200506-145658.log:2020-05-06 15:03:13.906 WARN SFTP_RETRY Encountered an error (EOF); retry after 1 second(s)

Would you be able to build me a version with top of tree Go (I don’t have linux toolchain setup) – I then can replace the CLI engine and see if the issue dissapears? Since I have such a reliable repro lets put it to good use…

gchen · 6 May 2020 23:29

This may be a different issue. Can you attach gdb to the stuck process and get a full stack trace again?

saspus · 6 May 2020 23:57

I looked at the stack it was very similar to the previous one. I’ve killed the process already. Will do once it happens again.

gchen · 7 May 2020 00:05

Then there is no need to get another stack trace. I’ll send you a new binary shortly.

gchen · 7 May 2020 01:26

This version is built with go 1.14.2: http://acrosync.com/duplicacy/duplicacy_linux_x64_2.5.2

saspus · 7 May 2020 03:10

Thank you. I could not find how to fix the cli version in the config file, so I just renamed it to 2.5.1 and put there to run. Will report back in a few days or as soon as it hangs

saspus · 7 May 2020 06:12

Ok, this seems to now happen every time I run prune.

Here is the log:

Running prune command from /var/services/homes/duplicacy-web/.duplicacy-web/repositories/localhost/all
Options: [-log prune -storage cumulonimbus -keep 31:360 -keep 7:90 -keep 1:14 -a]
2020-05-06 20:35:10.026 INFO STORAGE_SET Storage set to sftp://tuchka@cumulonimbus/NetBackup/Tuchka-Duplicacy
2020-05-06 20:35:11.059 INFO RETENTION_POLICY Keep 1 snapshot every 31 day(s) if older than 360 day(s)
2020-05-06 20:35:11.059 INFO RETENTION_POLICY Keep 1 snapshot every 7 day(s) if older than 90 day(s)
2020-05-06 20:35:11.059 INFO RETENTION_POLICY Keep 1 snapshot every 1 day(s) if older than 14 day(s)
2020-05-06 20:35:24.031 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 3
2020-05-06 20:35:25.372 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 4
2020-05-06 20:35:26.664 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 5
2020-05-06 20:35:27.907 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 6
2020-05-06 20:35:29.152 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 7
2020-05-06 20:35:30.375 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 8
2020-05-06 20:35:31.614 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 9
2020-05-06 20:35:32.850 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 10
2020-05-06 20:35:34.056 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 11
2020-05-06 20:35:35.259 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 12
2020-05-06 20:35:36.511 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 14
2020-05-06 20:35:37.741 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 15
2020-05-06 20:35:38.959 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 16
2020-05-06 20:35:40.194 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 17
2020-05-06 20:35:41.437 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 18
2020-05-06 20:35:42.659 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 19
2020-05-06 20:35:43.885 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 20
2020-05-06 20:35:45.117 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 21
2020-05-06 20:35:46.379 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 22
2020-05-06 20:35:47.619 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 23
2020-05-06 20:35:48.831 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 24
2020-05-06 20:35:50.073 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 25
2020-05-06 20:35:51.302 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 26
2020-05-06 20:35:52.526 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 27
2020-05-06 20:35:53.754 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 28
2020-05-06 20:35:54.990 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 29
2020-05-06 20:35:56.254 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 30
2020-05-06 20:35:57.469 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 31
2020-05-06 20:35:58.700 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 32
2020-05-06 20:35:59.914 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 34
2020-05-06 20:36:01.225 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 35
2020-05-06 20:36:02.529 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 36
2020-05-06 20:36:03.813 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 37
2020-05-06 20:36:05.108 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 38
2020-05-06 20:36:06.400 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 39
2020-05-06 20:36:07.696 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 40
2020-05-06 20:36:09.005 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 41
2020-05-06 20:36:10.312 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 42
2020-05-06 20:36:11.597 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 43
2020-05-06 20:36:12.879 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 44
2020-05-06 20:36:14.173 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 45
2020-05-06 20:36:15.461 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 46
2020-05-06 20:36:16.755 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 47
2020-05-06 20:36:18.044 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 49
2020-05-06 20:36:19.349 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 50
2020-05-06 20:36:20.649 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 51
2020-05-06 20:36:21.933 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 52
2020-05-06 20:36:23.222 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 53
2020-05-06 20:36:24.509 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 54
2020-05-06 20:36:25.775 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 55
2020-05-06 20:36:27.084 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 56
2020-05-06 20:36:28.404 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 57
2020-05-06 20:36:29.713 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 58
2020-05-06 20:36:31.028 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 59
2020-05-06 20:40:26.552 WARN SFTP_RETRY Encountered an error (EOF); retry after 1 second(s)
2020-05-06 20:40:28.326 WARN SFTP_RETRY Encountered an error (EOF); retry after 2 second(s)
2020-05-06 20:40:31.070 WARN SFTP_RETRY Encountered an error (EOF); retry after 4 second(s)

Current time 23:06

Processes:

ash-4.3# ps -ax | grep duplicacy | grep -v grep
17746 ?        Sl   110:18 /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.1 -log backup -storage cumulonimbus -stats
24164 ?        Ssl   11:43 /var/services/homes/duplicacy-web/duplicacy_web_linux_x64_1.3.0
31577 ?        Sl     5:58 /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.1 -log prune -storage cumulonimbus -keep 31:360 -keep 7:90 -keep 1:14 -a

Never mind the version referring to 2.5.1. it is in fact renamed 2.5.2

ash-4.3# ls -alt /var/services/homes/duplicacy-web/.duplicacy-web/bin/
total 172516
drwx------+ 1 duplicacy-web users      142 May  6 21:02 ..
-rwx------+ 1 duplicacy-web users 29861372 May  6 20:06 duplicacy_linux_x64_2.5.1
-rwx------+ 1 alex          users 31650873 May  6 20:06 duplicacy_linux_x64_2.5.1.old
drwx------+ 1 duplicacy-web users      308 May  6 20:06 .
-rwxrwxrwx  1 alex          users 29861372 May  6 20:00 duplicacy_linux_x64_2.5.2
-rwx------+ 1 duplicacy-web users 31654969 Apr 14 12:45 duplicacy_linux_x64_2.5.0
-rwx------+ 1 duplicacy-web users 26806861 Apr  2 11:26 duplicacy_linux_x64_2.4.1
-rwx------+ 1 duplicacy-web users 26806950 Mar  1 00:24 duplicacy_linux_x64_2.3.0

Stacks of 31577:

(gdb) thread apply all bt

Thread 10 (LWP 31913):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0xc0003e8148, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b06f in runtime.notesleep (n=0xc0003e8148) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x000000000043ab80 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1828
#4  0x000000000043c19d in runtime.findrunnable (gp=0xc000043000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2360
#5  0x000000000043ccdc in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2520
#6  0x000000000043d25d in runtime.park_m (gp=0xc000001800) at /usr/local/go/src/runtime/proc.go:2690
#7  0x000000000046518b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x000000c000470001 in ?? ()
#9  0x0000000000000000 in ?? ()

Thread 9 (LWP 31594):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0xc000520148, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b06f in runtime.notesleep (n=0xc000520148) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x000000000043ab80 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1828
#4  0x000000000043c19d in runtime.findrunnable (gp=0xc000040800, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2360
#5  0x000000000043ccdc in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2520
#6  0x000000000043d25d in runtime.park_m (gp=0xc000130300) at /usr/local/go/src/runtime/proc.go:2690
#7  0x000000000046518b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 8 (LWP 31585):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0xc0000804c8, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b06f in runtime.notesleep (n=0xc0000804c8) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x000000000043ab80 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1828
#4  0x000000000043c19d in runtime.findrunnable (gp=0xc00003e000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2360
#5  0x000000000043ccdc in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2520
#6  0x000000000043d25d in runtime.park_m (gp=0xc000130300) at /usr/local/go/src/runtime/proc.go:2690
#7  0x000000000046518b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 7 (LWP 31584):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0xc000050bc8, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b06f in runtime.notesleep (n=0xc000050bc8) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x000000000043ab80 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1828
#4  0x000000000043c19d in runtime.findrunnable (gp=0xc000043000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2360
#5  0x000000000043ccdc in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2520
#6  0x000000000043d456 in runtime.goschedImpl (gp=0xc000000a80) at /usr/local/go/src/runtime/proc.go:2705
#7  0x000000000043d614 in runtime.gosched_m (gp=0xc000000a80) at /usr/local/go/src/runtime/proc.go:2713
#8  0x000000000046518b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#9  0x0000000000000000 in ?? ()

Thread 6 (LWP 31583):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0x1930f38 <runtime.newmHandoff+24>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b06f in runtime.notesleep (n=0x1930f38 <runtime.newmHandoff+24>) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x000000000043aaa2 in runtime.templateThread () at /usr/local/go/src/runtime/proc.go:1806
#4  0x0000000000439753 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1097
#5  0x000000000043966e in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1062
#6  0x0000000000469323 in runtime.clone () at /usr/local/go/src/runtime/sys_linux_amd64.s:619
#7  0x0000000000000000 in ?? ()

Thread 5 (LWP 31582):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0xc000080148, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b06f in runtime.notesleep (n=0xc000080148) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x000000000043ab80 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1828
#4  0x000000000043b5c4 in runtime.gcstopm () at /usr/local/go/src/runtime/proc.go:2028
#5  0x000000000043bfbb in runtime.findrunnable (gp=0xc000043000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2085
#6  0x000000000043ccdc in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2520
#7  0x000000000043d25d in runtime.park_m (gp=0xc000001800) at /usr/local/go/src/runtime/proc.go:2690
#8  0x000000000046518b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#9  0x0000000000000000 in ?? ()

Thread 4 (LWP 31581):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0x1931040 <runtime.sig>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b146 in runtime.notetsleep_internal (n=0x1931040 <runtime.sig>, ns=-1, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:174
#3  0x000000000040b34c in runtime.notetsleepg (n=0x1931040 <runtime.sig>, ns=-1, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:228
#4  0x000000000044c0bc in os/signal.signal_recv (~r0=<optimized out>) at /usr/local/go/src/runtime/sigqueue.go:147
#5  0x0000000000730f42 in os/signal.loop () at /usr/local/go/src/os/signal/signal_unix.go:23
#6  0x0000000000467131 in runtime.goexit () at /usr/local/go/src/runtime/asm_amd64.s:1373
---Type <return> to continue, or q <return> to quit---
#7  0x0000000000000000 in ?? ()

Thread 3 (LWP 31579):
#0  runtime.epollwait () at /usr/local/go/src/runtime/sys_linux_amd64.s:705
#1  0x0000000000430932 in runtime.netpoll (delay=9999866741, ~r1=...) at /usr/local/go/src/runtime/netpoll_epoll.go:119
#2  0x000000000043bebb in runtime.findrunnable (gp=0xc000040800, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2323
#3  0x000000000043ccdc in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2520
#4  0x000000000043d25d in runtime.park_m (gp=0xc000130300) at /usr/local/go/src/runtime/proc.go:2690
#5  0x000000000046518b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#6  0x0000000000000000 in ?? ()

Thread 2 (LWP 31578):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430cd4 in runtime.futexsleep (addr=0x19061b8 <runtime.sched+280>, val=0, ns=9999853807) at /usr/local/go/src/runtime/os_linux.go:51
#2  0x000000000040b1ee in runtime.notetsleep_internal (n=0x19061b8 <runtime.sched+280>, ns=9999853807, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:193
#3  0x000000000040b2c1 in runtime.notetsleep (n=0x19061b8 <runtime.sched+280>, ns=9999853807, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:216
#4  0x0000000000441dd2 in runtime.sysmon () at /usr/local/go/src/runtime/proc.go:4492
#5  0x0000000000439753 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1097
#6  0x000000000043966e in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1062
#7  0x0000000000469323 in runtime.clone () at /usr/local/go/src/runtime/sys_linux_amd64.s:619
#8  0x0000000000000000 in ?? ()

Thread 1 (LWP 31577):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:568
#1  0x0000000000430c56 in runtime.futexsleep (addr=0x1906c68 <runtime.m0+328>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000040b06f in runtime.notesleep (n=0x1906c68 <runtime.m0+328>) at /usr/local/go/src/runtime/lock_futex.go:151
#3  0x000000000043b218 in runtime.stoplockedm () at /usr/local/go/src/runtime/proc.go:1971
#4  0x000000000043ce86 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2454
#5  0x000000000043d25d in runtime.park_m (gp=0xc000130900) at /usr/local/go/src/runtime/proc.go:2690
#6  0x000000000046518b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#7  0x00000000004650a4 in runtime.rt0_go () at /usr/local/go/src/runtime/asm_amd64.s:220
#8  0x0000000000000000 in ?? ()
(gdb)

gchen · 7 May 2020 19:13

The gdb stack trace isn’t very useful as it doesn’t show any Duplicacy code. I almost forgot that there is a built-in profiler that gives a better stack trace…

Add -profile 127.0.0.1:8080 as a global option to the prune job, then while the prune is running go to http://127.0.0.1:8080/debug/pprof/ in a browser, then click goroutine.

saspus · 7 May 2020 21:23

Log:

alex@Tuchka:/var/services/homes/duplicacy-web/.duplicacy-web/logs$ sudo tail prune-20200507-135025.log
2020-05-07 13:51:50.075 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 57
2020-05-07 13:51:51.384 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 58
2020-05-07 13:51:52.677 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 59
2020-05-07 13:51:53.996 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 62
2020-05-07 13:51:55.614 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 63
2020-05-07 13:51:57.237 INFO SNAPSHOT_DELETE Deleting snapshot tuchka at revision 64
2020-05-07 13:55:51.507 WARN SFTP_RETRY Encountered an error (EOF); retry after 1 second(s)
2020-05-07 13:55:53.454 WARN SFTP_RETRY Encountered an error (EOF); retry after 2 second(s)
2020-05-07 13:55:56.332 WARN SFTP_RETRY Encountered an error (EOF); retry after 4 second(s)
2020-05-07 13:56:01.277 WARN SFTP_RETRY Encountered an error (EOF); retry after 8 second(s)

Corresponding log from sftp server:

Level	Log	Date & Time	User	Event
Information	Connection	2020/05/07 13:56:10	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.
Information	Connection	2020/05/07 13:56:01	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.
Information	Connection	2020/05/07 13:55:56	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.
Information	Connection	2020/05/07 13:55:53	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.
Information	Connection	2020/05/07 13:50:25	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.
Information	Connection	2020/05/07 13:50:19	tuchka	SFTP client [tuchka] from [10.0.17.130] logged out the server with totally [0 Bytes] uploaded and [842 Bytes] downloaded.
Information	Connection	2020/05/07 13:24:41	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.
Information	Connection	2020/05/07 13:24:18	tuchka	SFTP client [tuchka] from [10.0.17.130] logged out the server with totally [0 Bytes] uploaded and [842 Bytes] downloaded.
Information	Connection	2020/05/07 13:23:00	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.
Information	Connection	2020/05/06 21:02:01	tuchka	SFTP client [tuchka] from [10.0.17.130] logged in through SFTP.

Time now: 14:48

profiler:

    goroutine profile: total 41
5 @ 0x437250 0x405f27 0x405c2b 0xc2775d 0x467131
#	0xc2775c	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*Client).handleGlobalRequests+0x6c	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/client.go:138

5 @ 0x437250 0x405f27 0x405c2b 0xc277d2 0x467131
#	0xc277d1	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*Client).handleChannelOpens+0x51	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/client.go:147

5 @ 0x437250 0x405f27 0x405c2b 0xc2cf2e 0xc451c7 0xc45045 0x467131
#	0xc2cf2d	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).readPacket+0x4d	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:187
#	0xc451c6	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*mux).onePacket+0x36			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/mux.go:215
#	0xc45044	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*mux).loop+0x34			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/mux.go:190

5 @ 0x437250 0x42ff4a 0x42f4b5 0x4d88d5 0x4d976b 0x4d974d 0x5caaef 0x5dd48e 0x58449f 0x474b97 0xc23e63 0xc23e10 0xc4c8b8 0xc4c7e7 0xc2da40 0xc2cffd 0x467131
#	0x42f4b4	internal/poll.runtime_pollWait+0x54										/usr/local/go/src/runtime/netpoll.go:203
#	0x4d88d4	internal/poll.(*pollDesc).wait+0x44										/usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#	0x4d976a	internal/poll.(*pollDesc).waitRead+0x19a									/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#	0x4d974c	internal/poll.(*FD).Read+0x17c											/usr/local/go/src/internal/poll/fd_unix.go:169
#	0x5caaee	net.(*netFD).Read+0x4e												/usr/local/go/src/net/fd_unix.go:202
#	0x5dd48d	net.(*conn).Read+0x8d												/usr/local/go/src/net/net.go:184
#	0x58449e	bufio.(*Reader).Read+0x24e											/usr/local/go/src/bufio/bufio.go:226
#	0x474b96	io.ReadAtLeast+0x86												/usr/local/go/src/io/io.go:310
#	0xc23e62	io.ReadFull+0x82												/usr/local/go/src/io/io.go:329
#	0xc23e0f	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*gcmCipher).readCipherPacket+0x2f		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/cipher.go:373
#	0xc4c8b7	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*connectionState).readPacket+0x67		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/transport.go:130
#	0xc4c7e6	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*transport).readPacket+0x36			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/transport.go:114
#	0xc2da3f	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).readOnePacket+0x4f	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:374
#	0xc2cffc	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).readLoop+0x4c		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:197

5 @ 0x437250 0x447413 0xc2d44a 0x467131
#	0xc2d449	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).kexLoop+0xf9	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:268

5 @ 0x437250 0x448e48 0x448e1e 0x470e1d 0xc44664 0xc4e8c3 0x467131
#	0x448e1d	sync.runtime_notifyListWait+0xcd							/usr/local/go/src/runtime/sema.go:513
#	0x470e1c	sync.(*Cond).Wait+0x9c									/usr/local/go/src/sync/cond.go:56
#	0xc44663	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*mux).Wait+0x83	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/mux.go:110
#	0xc4e8c2	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.NewClient.func1+0x32	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/client.go:62

1 @ 0x40b334 0x44c0bc 0x730f42 0x467131
#	0x44c0bb	os/signal.signal_recv+0x9b	/usr/local/go/src/runtime/sigqueue.go:147
#	0x730f41	os/signal.loop+0x21		/usr/local/go/src/os/signal/signal_unix.go:23

1 @ 0x437250 0x40530d 0x4050d5 0xd052cc 0xd05277 0xd05263 0xd052e9 0xd023a4 0xd2d7c0 0x7ac168 0x7a93e2 0xd352b3 0x436e72 0x467131
#	0xd052cb	github.com/gilbertchen/duplicacy/src.(*ChunkOperator).AddTask+0x8eb				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:94
#	0xd05276	github.com/gilbertchen/duplicacy/src.(*ChunkOperator).Fossilize+0x896				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:107
#	0xd05262	github.com/gilbertchen/duplicacy/src.(*SnapshotManager).fossilizeChunk+0x882			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_snapshotmanager.go:1632
#	0xd052e8	github.com/gilbertchen/duplicacy/src.(*SnapshotManager).pruneSnapshotsNonExhaustive+0x908	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_snapshotmanager.go:2220
#	0xd023a3	github.com/gilbertchen/duplicacy/src.(*SnapshotManager).PruneSnapshots+0x2af3			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_snapshotmanager.go:2070
#	0xd2d7bf	main.pruneSnapshots+0x87f									/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:1147
#	0x7ac167	github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.Command.Run+0x7a7		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/command.go:160
#	0x7a93e1	github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.(*App).Run+0x6d1		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/app.go:179
#	0xd352b2	main.main+0x5d92										/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:2099
#	0x436e71	runtime.main+0x211										/usr/local/go/src/runtime/proc.go:203

1 @ 0x437250 0x405f27 0x405beb 0xc601cc 0xc5c617 0xd1d856 0xce8563 0xce948c 0xcbb9b0 0xd1cef6 0x467131
#	0xc601cb	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).sendPacket+0xab	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:109
#	0xc5c616	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*Client).Rename+0xd6		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/client.go:664
#	0xd1d855	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).MoveFile.func2+0x175			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:210
#	0xce8562	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).retry+0x62					/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:125
#	0xce948b	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).MoveFile+0x27b				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:210
#	0xcbb9af	github.com/gilbertchen/duplicacy/src.(*ChunkOperator).Run+0x5ef					/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:171
#	0xd1cef5	github.com/gilbertchen/duplicacy/src.CreateChunkOperator.func1+0xb5				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:60

1 @ 0x437250 0x405f27 0x405c2b 0xc4778a 0xc4f575 0x467131
#	0xc47789	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*Session).wait+0x79	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/session.go:423
#	0xc4f574	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.newSession.func1+0x34	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/session.go:593

1 @ 0x437250 0x405f27 0x405c2b 0xd35f50 0x467131
#	0xd35f4f	main.main.func1+0x5f	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:2093

1 @ 0x437250 0x42ff4a 0x42f4b5 0x4d88d5 0x4d976b 0x4d974d 0x5caaef 0x5dd48e 0x6f2da8 0x467131
#	0x42f4b4	internal/poll.runtime_pollWait+0x54		/usr/local/go/src/runtime/netpoll.go:203
#	0x4d88d4	internal/poll.(*pollDesc).wait+0x44		/usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#	0x4d976a	internal/poll.(*pollDesc).waitRead+0x19a	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#	0x4d974c	internal/poll.(*FD).Read+0x17c			/usr/local/go/src/internal/poll/fd_unix.go:169
#	0x5caaee	net.(*netFD).Read+0x4e				/usr/local/go/src/net/fd_unix.go:202
#	0x5dd48d	net.(*conn).Read+0x8d				/usr/local/go/src/net/net.go:184
#	0x6f2da7	net/http.(*connReader).backgroundRead+0x57	/usr/local/go/src/net/http/server.go:678

1 @ 0x437250 0x42ff4a 0x42f4b5 0x4d88d5 0x4db114 0x4db0f6 0x5cb3a2 0x5e70a2 0x5e5e34 0x6fd4fd 0x6fd247 0xd35d1c 0xd35cde 0x467131
#	0x42f4b4	internal/poll.runtime_pollWait+0x54		/usr/local/go/src/runtime/netpoll.go:203
#	0x4d88d4	internal/poll.(*pollDesc).wait+0x44		/usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#	0x4db113	internal/poll.(*pollDesc).waitRead+0x1d3	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#	0x4db0f5	internal/poll.(*FD).Accept+0x1b5		/usr/local/go/src/internal/poll/fd_unix.go:384
#	0x5cb3a1	net.(*netFD).accept+0x41			/usr/local/go/src/net/fd_unix.go:238
#	0x5e70a1	net.(*TCPListener).accept+0x31			/usr/local/go/src/net/tcpsock_posix.go:139
#	0x5e5e33	net.(*TCPListener).Accept+0x63			/usr/local/go/src/net/tcpsock.go:261
#	0x6fd4fc	net/http.(*Server).Serve+0x25c			/usr/local/go/src/net/http/server.go:2901
#	0x6fd246	net/http.(*Server).ListenAndServe+0xb6		/usr/local/go/src/net/http/server.go:2830
#	0xd35d1b	net/http.ListenAndServe+0x5b			/usr/local/go/src/net/http/server.go:3086
#	0xd35cdd	main.setGlobalOptions.func1+0x1d		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:158

1 @ 0x437250 0x447413 0x91c9f0 0x467131
#	0x91c9ef	github.com/gilbertchen/duplicacy/vendor/go.opencensus.io/stats/view.(*worker).start+0xff	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/go.opencensus.io/stats/view/worker.go:154

1 @ 0x437250 0x447413 0xd1cb6a 0x467131
#	0xd1cb69	github.com/gilbertchen/duplicacy/src.CreateChunkDownloader.func1+0x169	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkdownloader.go:80

1 @ 0x437250 0x448e48 0x448e1e 0x470e1d 0xc1ca2e 0xc20ad5 0xc21d5b 0x474b97 0xc622e3 0xc622ee 0xc5fed8 0xc5feba 0xc5fd88 0x467131
#	0x448e1d	sync.runtime_notifyListWait+0xcd								/usr/local/go/src/runtime/sema.go:513
#	0x470e1c	sync.(*Cond).Wait+0x9c										/usr/local/go/src/sync/cond.go:56
#	0xc1ca2d	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*buffer).Read+0x1dd		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/buffer.go:94
#	0xc20ad4	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*channel).ReadExtended+0x1e4	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/channel.go:351
#	0xc21d5a	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*channel).Read+0x5a		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/channel.go:528
#	0x474b96	io.ReadAtLeast+0x86										/usr/local/go/src/io/io.go:310
#	0xc622e2	io.ReadFull+0x72										/usr/local/go/src/io/io.go:329
#	0xc622ed	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.recvPacket+0x7d			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/packet.go:144
#	0xc5fed7	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*conn).recvPacket+0xf7		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:22
#	0xc5feb9	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).recv+0xd9		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:75
#	0xc5fd87	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).loop+0x57		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:60

1 @ 0x798ff5 0x798e10 0x795baa 0x7a31ba 0x7a3c15 0x6f9dc4 0x6fbc05 0x6fd153 0x6f8bcc 0x467131
#	0x798ff4	runtime/pprof.writeRuntimeProfile+0x94	/usr/local/go/src/runtime/pprof/pprof.go:694
#	0x798e0f	runtime/pprof.writeGoroutine+0x9f	/usr/local/go/src/runtime/pprof/pprof.go:656
#	0x795ba9	runtime/pprof.(*Profile).WriteTo+0x3d9	/usr/local/go/src/runtime/pprof/pprof.go:329
#	0x7a31b9	net/http/pprof.handler.ServeHTTP+0x339	/usr/local/go/src/net/http/pprof/pprof.go:248
#	0x7a3c14	net/http/pprof.Index+0x734		/usr/local/go/src/net/http/pprof/pprof.go:271
#	0x6f9dc3	net/http.HandlerFunc.ServeHTTP+0x43	/usr/local/go/src/net/http/server.go:2012
#	0x6fbc04	net/http.(*ServeMux).ServeHTTP+0x1a4	/usr/local/go/src/net/http/server.go:2387
#	0x6fd152	net/http.serverHandler.ServeHTTP+0xa2	/usr/local/go/src/net/http/server.go:2807
#	0x6f8bcb	net/http.(*conn).serve+0x86b		/usr/local/go/src/net/http/server.go:1895

Edit. It’s now 15:40, stack state substantially not different, no progress in the log

goroutine profile: total 41
5 @ 0x437250 0x405f27 0x405c2b 0xc2775d 0x467131
#	0xc2775c	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*Client).handleGlobalRequests+0x6c	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/client.go:138

5 @ 0x437250 0x405f27 0x405c2b 0xc277d2 0x467131
#	0xc277d1	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*Client).handleChannelOpens+0x51	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/client.go:147

5 @ 0x437250 0x405f27 0x405c2b 0xc2cf2e 0xc451c7 0xc45045 0x467131
#	0xc2cf2d	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).readPacket+0x4d	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:187
#	0xc451c6	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*mux).onePacket+0x36			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/mux.go:215
#	0xc45044	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*mux).loop+0x34			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/mux.go:190

5 @ 0x437250 0x42ff4a 0x42f4b5 0x4d88d5 0x4d976b 0x4d974d 0x5caaef 0x5dd48e 0x58449f 0x474b97 0xc23e63 0xc23e10 0xc4c8b8 0xc4c7e7 0xc2da40 0xc2cffd 0x467131
#	0x42f4b4	internal/poll.runtime_pollWait+0x54										/usr/local/go/src/runtime/netpoll.go:203
#	0x4d88d4	internal/poll.(*pollDesc).wait+0x44										/usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#	0x4d976a	internal/poll.(*pollDesc).waitRead+0x19a									/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#	0x4d974c	internal/poll.(*FD).Read+0x17c											/usr/local/go/src/internal/poll/fd_unix.go:169
#	0x5caaee	net.(*netFD).Read+0x4e												/usr/local/go/src/net/fd_unix.go:202
#	0x5dd48d	net.(*conn).Read+0x8d												/usr/local/go/src/net/net.go:184
#	0x58449e	bufio.(*Reader).Read+0x24e											/usr/local/go/src/bufio/bufio.go:226
#	0x474b96	io.ReadAtLeast+0x86												/usr/local/go/src/io/io.go:310
#	0xc23e62	io.ReadFull+0x82												/usr/local/go/src/io/io.go:329
#	0xc23e0f	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*gcmCipher).readCipherPacket+0x2f		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/cipher.go:373
#	0xc4c8b7	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*connectionState).readPacket+0x67		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/transport.go:130
#	0xc4c7e6	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*transport).readPacket+0x36			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/transport.go:114
#	0xc2da3f	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).readOnePacket+0x4f	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:374
#	0xc2cffc	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).readLoop+0x4c		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:197

5 @ 0x437250 0x447413 0xc2d44a 0x467131
#	0xc2d449	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*handshakeTransport).kexLoop+0xf9	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/handshake.go:268

5 @ 0x437250 0x448e48 0x448e1e 0x470e1d 0xc44664 0xc4e8c3 0x467131
#	0x448e1d	sync.runtime_notifyListWait+0xcd							/usr/local/go/src/runtime/sema.go:513
#	0x470e1c	sync.(*Cond).Wait+0x9c									/usr/local/go/src/sync/cond.go:56
#	0xc44663	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*mux).Wait+0x83	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/mux.go:110
#	0xc4e8c2	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.NewClient.func1+0x32	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/client.go:62

1 @ 0x40b334 0x44c0bc 0x730f42 0x467131
#	0x44c0bb	os/signal.signal_recv+0x9b	/usr/local/go/src/runtime/sigqueue.go:147
#	0x730f41	os/signal.loop+0x21		/usr/local/go/src/os/signal/signal_unix.go:23

1 @ 0x437250 0x40530d 0x4050d5 0xd052cc 0xd05277 0xd05263 0xd052e9 0xd023a4 0xd2d7c0 0x7ac168 0x7a93e2 0xd352b3 0x436e72 0x467131
#	0xd052cb	github.com/gilbertchen/duplicacy/src.(*ChunkOperator).AddTask+0x8eb				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:94
#	0xd05276	github.com/gilbertchen/duplicacy/src.(*ChunkOperator).Fossilize+0x896				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:107
#	0xd05262	github.com/gilbertchen/duplicacy/src.(*SnapshotManager).fossilizeChunk+0x882			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_snapshotmanager.go:1632
#	0xd052e8	github.com/gilbertchen/duplicacy/src.(*SnapshotManager).pruneSnapshotsNonExhaustive+0x908	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_snapshotmanager.go:2220
#	0xd023a3	github.com/gilbertchen/duplicacy/src.(*SnapshotManager).PruneSnapshots+0x2af3			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_snapshotmanager.go:2070
#	0xd2d7bf	main.pruneSnapshots+0x87f									/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:1147
#	0x7ac167	github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.Command.Run+0x7a7		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/command.go:160
#	0x7a93e1	github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.(*App).Run+0x6d1		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/app.go:179
#	0xd352b2	main.main+0x5d92										/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:2099
#	0x436e71	runtime.main+0x211										/usr/local/go/src/runtime/proc.go:203

1 @ 0x437250 0x405f27 0x405beb 0xc601cc 0xc5c617 0xd1d856 0xce8563 0xce948c 0xcbb9b0 0xd1cef6 0x467131
#	0xc601cb	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).sendPacket+0xab	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:109
#	0xc5c616	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*Client).Rename+0xd6		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/client.go:664
#	0xd1d855	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).MoveFile.func2+0x175			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:210
#	0xce8562	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).retry+0x62					/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:125
#	0xce948b	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).MoveFile+0x27b				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:210
#	0xcbb9af	github.com/gilbertchen/duplicacy/src.(*ChunkOperator).Run+0x5ef					/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:171
#	0xd1cef5	github.com/gilbertchen/duplicacy/src.CreateChunkOperator.func1+0xb5				/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkoperator.go:60

1 @ 0x437250 0x405f27 0x405c2b 0xc4778a 0xc4f575 0x467131
#	0xc47789	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*Session).wait+0x79	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/session.go:423
#	0xc4f574	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.newSession.func1+0x34	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/session.go:593

1 @ 0x437250 0x405f27 0x405c2b 0xd35f50 0x467131
#	0xd35f4f	main.main.func1+0x5f	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:2093

1 @ 0x437250 0x42ff4a 0x42f4b5 0x4d88d5 0x4db114 0x4db0f6 0x5cb3a2 0x5e70a2 0x5e5e34 0x6fd4fd 0x6fd247 0xd35d1c 0xd35cde 0x467131
#	0x42f4b4	internal/poll.runtime_pollWait+0x54		/usr/local/go/src/runtime/netpoll.go:203
#	0x4d88d4	internal/poll.(*pollDesc).wait+0x44		/usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#	0x4db113	internal/poll.(*pollDesc).waitRead+0x1d3	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#	0x4db0f5	internal/poll.(*FD).Accept+0x1b5		/usr/local/go/src/internal/poll/fd_unix.go:384
#	0x5cb3a1	net.(*netFD).accept+0x41			/usr/local/go/src/net/fd_unix.go:238
#	0x5e70a1	net.(*TCPListener).accept+0x31			/usr/local/go/src/net/tcpsock_posix.go:139
#	0x5e5e33	net.(*TCPListener).Accept+0x63			/usr/local/go/src/net/tcpsock.go:261
#	0x6fd4fc	net/http.(*Server).Serve+0x25c			/usr/local/go/src/net/http/server.go:2901
#	0x6fd246	net/http.(*Server).ListenAndServe+0xb6		/usr/local/go/src/net/http/server.go:2830
#	0xd35d1b	net/http.ListenAndServe+0x5b			/usr/local/go/src/net/http/server.go:3086
#	0xd35cdd	main.setGlobalOptions.func1+0x1d		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:158

1 @ 0x437250 0x447413 0x91c9f0 0x467131
#	0x91c9ef	github.com/gilbertchen/duplicacy/vendor/go.opencensus.io/stats/view.(*worker).start+0xff	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/go.opencensus.io/stats/view/worker.go:154

1 @ 0x437250 0x447413 0xd1cb6a 0x467131
#	0xd1cb69	github.com/gilbertchen/duplicacy/src.CreateChunkDownloader.func1+0x169	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkdownloader.go:80

1 @ 0x437250 0x448e48 0x448e1e 0x470e1d 0xc1ca2e 0xc20ad5 0xc21d5b 0x474b97 0xc622e3 0xc622ee 0xc5fed8 0xc5feba 0xc5fd88 0x467131
#	0x448e1d	sync.runtime_notifyListWait+0xcd								/usr/local/go/src/runtime/sema.go:513
#	0x470e1c	sync.(*Cond).Wait+0x9c										/usr/local/go/src/sync/cond.go:56
#	0xc1ca2d	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*buffer).Read+0x1dd		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/buffer.go:94
#	0xc20ad4	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*channel).ReadExtended+0x1e4	/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/channel.go:351
#	0xc21d5a	github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh.(*channel).Read+0x5a		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/golang.org/x/crypto/ssh/channel.go:528
#	0x474b96	io.ReadAtLeast+0x86										/usr/local/go/src/io/io.go:310
#	0xc622e2	io.ReadFull+0x72										/usr/local/go/src/io/io.go:329
#	0xc622ed	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.recvPacket+0x7d			/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/packet.go:144
#	0xc5fed7	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*conn).recvPacket+0xf7		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:22
#	0xc5feb9	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).recv+0xd9		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:75
#	0xc5fd87	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).loop+0x57		/Users/gchen/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:60

1 @ 0x6f2d51 0x467131
#	0x6f2d50	net/http.(*connReader).backgroundRead+0x0	/usr/local/go/src/net/http/server.go:677

1 @ 0x798ff5 0x798e10 0x795baa 0x7a31ba 0x7a3c15 0x6f9dc4 0x6fbc05 0x6fd153 0x6f8bcc 0x467131
#	0x798ff4	runtime/pprof.writeRuntimeProfile+0x94	/usr/local/go/src/runtime/pprof/pprof.go:694
#	0x798e0f	runtime/pprof.writeGoroutine+0x9f	/usr/local/go/src/runtime/pprof/pprof.go:656
#	0x795ba9	runtime/pprof.(*Profile).WriteTo+0x3d9	/usr/local/go/src/runtime/pprof/pprof.go:329
#	0x7a31b9	net/http/pprof.handler.ServeHTTP+0x339	/usr/local/go/src/net/http/pprof/pprof.go:248
#	0x7a3c14	net/http/pprof.Index+0x734		/usr/local/go/src/net/http/pprof/pprof.go:271
#	0x6f9dc3	net/http.HandlerFunc.ServeHTTP+0x43	/usr/local/go/src/net/http/server.go:2012
#	0x6fbc04	net/http.(*ServeMux).ServeHTTP+0x1a4	/usr/local/go/src/net/http/server.go:2387
#	0x6fd152	net/http.serverHandler.ServeHTTP+0xa2	/usr/local/go/src/net/http/server.go:2807
#	0x6f8bcb	net/http.(*conn).serve+0x86b		/usr/local/go/src/net/http/server.go:1895

gchen · 8 May 2020 02:14

There are at least 2 issues here. First, is the SFTP storage on a synology box? Only synology is known for forcefully closing the connection when the file path is too long. The MoveFile function renames a chunk by adding a .fsl extension to the file name and that may exceed a limit set by synology. You can verify this by shortening the storage path from /NetBackup/Tuchka-Duplicacy to ``/NetBackup/Tuchka` for example to see if MoveFile still fails.

The other issue is that when the SFTP backend retries on a closed connection it doesn’t close the connection. The connection is already closed by the server so why bother closing it again, but from the log it looks like the server still keeps the connection open (no logged out messages for connections made at 13:50:25 and after). So maybe after a few retries the server decides not to respond any more instead of sending an EOF. You can verify this by manually kill the ssh connection and watch if there is another retry from Duplicacy.

saspus · 8 May 2020 07:19

Oh crap! Yes, it’s Synology, and this mess turned out to be self-inflicted issue, sorry for wasting everybody’s time

When I went to edit the storage in the config file I have noticed that I forgot to add the second / to the path.

Added it now, issue is gone (I did also shorten the path – but I don’t think that mattered – it was not that long)

So the issue is that synology sftp server keep being a source of endless frustration; I’m not sure if it is worth doing anything about it in duplicacy (e.g. a watchdog to recover from stall) since unless you have reports of similar behavior with other well-behaving SFTP servers this issue would be limited to synology and unless the user adds a slash it won’t work priorly anyway. Wondering if there is some way to warn users – I knew about this issue, posted about it, and yet it did not cross my mind to check it this time…

Thank you for great help.

Edit. Killing the connection did not seem to help — the duplicacy would not retry.