Deadlock during backup

MUIQ · 12 November 2019 08:40

I’m trying to backup ~1.3 TB data to sftp location using duplicacy cli 2.2.3. Upload speed is 10-20 Mbit/s. duplicacy cannot upload more than x0 GB data, the process just freezes after several hours.
This is the log, the full log contains 111650 lines.

Repository set to /data
Storage set to sftp://root@192.168.2.1//mnt/sda1/backup/nas
No previous backup found
Indexing /data
Parsing filter file /config/filters
Loaded 2 include/exclude pattern(s)
Listing all chunks
Skipped chunk 1 size 3614099, 3.45MB/s 3 days 23:39:28 0.0%
Skipped chunk 2 size 3886605, 7.15MB/s 1 day 22:05:28 0.0%
Skipped chunk 3 size 2481022, 9.52MB/s 1 day 10:38:06 0.0%
Skipped chunk 4 size 4101049, 13.43MB/s 1 day 00:32:56 0.0%
Skipped chunk 5 size 1265573, 14.64MB/s 22:31:28 0.0%
Skipped chunk 6 size 7266189, 21.57MB/s 15:17:14 0.0%
Skipped chunk 7 size 9394285, 30.53MB/s 10:48:02 0.0%
Skipped chunk 8 size 5736289, 36.00MB/s 09:09:33 0.0%
Skipped chunk 9 size 2009195, 37.91MB/s 08:41:46 0.0%
Skipped chunk 10 size 6963927, 44.55MB/s 07:24:00 0.0%
...
Skipped chunk 109482 size 3535629, 102.55MB/s 01:45:51 45.1%
Skipped chunk 109483 size 1327335, 102.55MB/s 01:45:51 45.1%
Skipped chunk 109484 size 4330129, 102.55MB/s 01:45:51 45.1%
Skipped chunk 109485 size 7635842, 102.55MB/s 01:45:51 45.1%
Skipped chunk 109486 size 9161778, 102.56MB/s 01:45:51 45.1%
Skipped chunk 109487 size 4992778, 102.56MB/s 01:45:51 45.1%
Skipped chunk 109488 size 1842590, 102.56MB/s 01:45:51 45.1%
Skipped chunk 109489 size 2059817, 102.56MB/s 01:45:51 45.1%
Skipped chunk 109490 size 10763862, 102.56MB/s 01:45:51 45.1%
Skipped chunk 109491 size 9661913, 102.54MB/s 01:45:52 45.1%
Skipped chunk 109492 size 7961895, 102.54MB/s 01:45:51 45.1%
Skipped chunk 109493 size 4071812, 102.54MB/s 01:45:51 45.1%
Skipped chunk 109494 size 4024512, 102.54MB/s 01:45:51 45.1%
Uploaded chunk 109495 size 8337177, 102.39MB/s 01:46:01 45.1%
Uploaded chunk 109496 size 9614370, 102.19MB/s 01:46:13 45.1%
Uploaded chunk 109497 size 5363100, 102.10MB/s 01:46:19 45.1%
Uploaded chunk 109498 size 1134803, 102.06MB/s 01:46:21 45.1%
Uploaded chunk 109499 size 1363325, 102.02MB/s 01:46:24 45.1%
Uploaded chunk 109500 size 7340202, 101.89MB/s 01:46:32 45.1%
Uploaded chunk 109501 size 8590495, 101.71MB/s 01:46:43 45.1%
Uploaded chunk 109502 size 13322783, 101.49MB/s 01:46:57 45.1%
Uploaded chunk 109503 size 2602085, 101.43MB/s 01:47:01 45.1%
Uploaded chunk 109504 size 1061866, 101.41MB/s 01:47:02 45.1%
Uploaded chunk 109505 size 12366762, 101.18MB/s 01:47:16 45.1%
Uploaded chunk 109506 size 1217825, 101.14MB/s 01:47:19 45.1%
Uploaded chunk 109507 size 9100677, 100.95MB/s 01:47:31 45.1%
Uploaded chunk 109508 size 8915318, 100.79MB/s 01:47:41 45.1%
...
Uploaded chunk 111628 size 1354045, 35.32MB/s 05:02:30 45.9%
Uploaded chunk 111629 size 11149440, 35.29MB/s 05:02:41 45.9%
Uploaded chunk 111630 size 1506111, 35.29MB/s 05:02:43 45.9%
Uploaded chunk 111631 size 1507132, 35.29MB/s 05:02:45 45.9%
Uploaded chunk 111632 size 2718774, 35.28MB/s 05:02:49 45.9%
Uploaded chunk 111633 size 4149759, 35.27MB/s 05:02:53 45.9%
Uploaded chunk 111634 size 1677151, 35.27MB/s 05:02:54 45.9%
Uploaded chunk 111635 size 4189126, 35.26MB/s 05:02:59 45.9%
Uploaded chunk 111636 size 6237187, 35.25MB/s 05:03:05 46.0%
Uploaded chunk 111637 size 5744554, 35.23MB/s 05:03:11 46.0%

Nothing happens after the last line, the duplicacy process is in memory with CPU load around zero.

towerbr · 12 November 2019 10:50

Welcome to the forum @MUIQ!

Maybe running with -verbose (or even -debug) option can give you/us more information:

gchen · 12 November 2019 14:45

The best way to figure out what caused the deadlock is to run the backup with the -profile option:

duplicacy -profile 127.0.0.1:8080 backup -stats

When the output freezes, open the browser at http://127.0.0.1:8080/debug/pprof/, and click full goroutine stack dump. The stack dump should tell you where the process gets stuck. If you’re unsure, post the full stack dump here.

MUIQ · 12 November 2019 16:23

Does it work in docker container? I mapped 8080 port to host’s ip, but it doesn’t response.

MUIQ · 13 November 2019 04:38

Stack dump

goroutine profile: total 8
1 @ 0x40f312 0x441356 0x6be502 0x459cb1
#       0x441355        os/signal.signal_recv+0xa5      /usr/local/go/src/runtime/sigqueue.go:139
#       0x6be501        os/signal.loop+0x21             /usr/local/go/src/os/signal/signal_unix.go:22

1 @ 0x42c90a 0x427a4a 0x4270c7 0x4c4fcb 0x4c504d 0x4c5ead 0x59019f 0x5a144a 0x68943a 0x459cb1
#       0x4270c6        internal/poll.runtime_pollWait+0x56             /usr/local/go/src/runtime/netpoll.go:173
#       0x4c4fca        internal/poll.(*pollDesc).wait+0x9a             /usr/local/go/src/internal/poll/fd_poll_runtime.go:85
#       0x4c504c        internal/poll.(*pollDesc).waitRead+0x3c         /usr/local/go/src/internal/poll/fd_poll_runtime.go:90
#       0x4c5eac        internal/poll.(*FD).Read+0x17c                  /usr/local/go/src/internal/poll/fd_unix.go:157
#       0x59019e        net.(*netFD).Read+0x4e                          /usr/local/go/src/net/fd_unix.go:202
#       0x5a1449        net.(*conn).Read+0x69                           /usr/local/go/src/net/net.go:176
#       0x689439        net/http.(*connReader).backgroundRead+0x59      /usr/local/go/src/net/http/server.go:668

1 @ 0x42c90a 0x427a4a 0x4270c7 0x4c4fcb 0x4c504d 0x4c7448 0x590ab2 0x5ab03e 0x5a9619 0x693d3f 0x692ad5 0x692829 0x69386a 0xb6940d 0x459cb1
#       0x4270c6        internal/poll.runtime_pollWait+0x56             /usr/local/go/src/runtime/netpoll.go:173
#       0x4c4fca        internal/poll.(*pollDesc).wait+0x9a             /usr/local/go/src/internal/poll/fd_poll_runtime.go:85
#       0x4c504c        internal/poll.(*pollDesc).waitRead+0x3c         /usr/local/go/src/internal/poll/fd_poll_runtime.go:90
#       0x4c7447        internal/poll.(*FD).Accept+0x1a7                /usr/local/go/src/internal/poll/fd_unix.go:372
#       0x590ab1        net.(*netFD).accept+0x41                        /usr/local/go/src/net/fd_unix.go:238
#       0x5ab03d        net.(*TCPListener).accept+0x2d                  /usr/local/go/src/net/tcpsock_posix.go:136
#       0x5a9618        net.(*TCPListener).AcceptTCP+0x48               /usr/local/go/src/net/tcpsock.go:246
#       0x693d3e        net/http.tcpKeepAliveListener.Accept+0x2e       /usr/local/go/src/net/http/server.go:3219
#       0x692ad4        net/http.(*Server).Serve+0x1a4                  /usr/local/go/src/net/http/server.go:2773
#       0x692828        net/http.(*Server).ListenAndServe+0xa8          /usr/local/go/src/net/http/server.go:2714
#       0x693869        net/http.ListenAndServe+0x79                    /usr/local/go/src/net/http/server.go:2972
#       0xb6940c        main.setGlobalOptions.func1+0x3c                /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:158

1 @ 0x42c90a 0x42c9be 0x4035bb 0x403355 0xa9d0a0 0xa9bf2e 0x463cfa 0x4638aa 0xb52a22 0xb1db30 0xb1f109 0xaf7767 0xb51873 0x459cb1
#       0xa9d09f        github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).dispatchRequest+0x1bf /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:110
#       0xa9bf2d        github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*File).ReadFrom+0x19d              /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/client.go:988
#       0x463cf9        io.copyBuffer+0x319                                                                             /usr/local/go/src/io/io.go:386
#       0x4638a9        io.Copy+0x59                                                                                    /usr/local/go/src/io/io.go:362
#       0xb52a21        github.com/gilbertchen/duplicacy/src.(*SFTPStorage).UploadFile.func3+0x281                      /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:323
#       0xb1db2f        github.com/gilbertchen/duplicacy/src.(*SFTPStorage).retry+0x6f                                  /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:125
#       0xb1f108        github.com/gilbertchen/duplicacy/src.(*SFTPStorage).UploadFile+0x3a8                            /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:307
#       0xaf7766        github.com/gilbertchen/duplicacy/src.(*ChunkUploader).Upload+0x416                              /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkuploader.go:138
#       0xb51872        github.com/gilbertchen/duplicacy/src.(*ChunkUploader).Start.func1+0x82                          /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkuploader.go:60

1 @ 0x42c90a 0x42c9be 0x4035bb 0x403355 0xb4f3db 0xaf4e70 0xae1955 0xb5e0a1 0x72d00a 0x72aa04 0xb68cfc 0x42c4b2 0x459cb1
#       0xb4f3da        github.com/gilbertchen/duplicacy/src.(*ChunkUploader).StartChunk+0x4fa                  /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkuploader.go:72
#       0xb4f3da        github.com/gilbertchen/duplicacy/src.(*BackupManager).Backup.func3+0x4fa                /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_backupmanager.go:521
#       0xaf4e6f        github.com/gilbertchen/duplicacy/src.(*ChunkMaker).ForEachChunk+0x80f                   /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkmaker.go:286
#       0xae1954        github.com/gilbertchen/duplicacy/src.(*BackupManager).Backup+0x3b64                     /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_backupmanager.go:497
#       0xb5e0a0        main.backupRepository+0x5b0                                                             /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:723
#       0x72d009        github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.Command.Run+0x7e9    /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/command.go:160
#       0x72aa03        github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.(*App).Run+0x863     /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/app.go:179
#       0xb68cfb        main.main+0x584b                                                                        /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:1996
#       0x42c4b1        runtime.main+0x211                                                                      /usr/local/go/src/runtime/proc.go:198

1 @ 0x42c90a 0x42c9be 0x404212 0x403f0b 0xb69640 0x459cb1
#       0xb6963f        main.main.func1+0x5f    /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:1990

1 @ 0x42c90a 0x43c5c0 0x4569c4 0x459cb1
#       0x42c909        runtime.gopark+0x119            /usr/local/go/src/runtime/proc.go:291
#       0x43c5bf        runtime.selectgo+0xe4f          /usr/local/go/src/runtime/select.go:392
#       0x4569c3        runtime.ensureSigM.func1+0x1f3  /usr/local/go/src/runtime/signal_unix.go:549

1 @ 0x71cf18 0x71cd20 0x719864 0x72502d 0x7253b1 0x68f9e4 0x6916d0 0x69270c 0x68ea01 0x459cb1
#       0x71cf17        runtime/pprof.writeRuntimeProfile+0x97  /usr/local/go/src/runtime/pprof/pprof.go:679
#       0x71cd1f        runtime/pprof.writeGoroutine+0x9f       /usr/local/go/src/runtime/pprof/pprof.go:641
#       0x719863        runtime/pprof.(*Profile).WriteTo+0x3e3  /usr/local/go/src/runtime/pprof/pprof.go:310
#       0x72502c        net/http/pprof.handler.ServeHTTP+0x20c  /usr/local/go/src/net/http/pprof/pprof.go:243
#       0x7253b0        net/http/pprof.Index+0x1d0              /usr/local/go/src/net/http/pprof/pprof.go:254
#       0x68f9e3        net/http.HandlerFunc.ServeHTTP+0x43     /usr/local/go/src/net/http/server.go:1947
#       0x6916cf        net/http.(*ServeMux).ServeHTTP+0x12f    /usr/local/go/src/net/http/server.go:2340
#       0x69270b        net/http.serverHandler.ServeHTTP+0xbb   /usr/local/go/src/net/http/server.go:2697
#       0x68ea00        net/http.(*conn).serve+0x650            /usr/local/go/src/net/http/server.go:1830

-v and -d doesn’t contain useful information for developers.

MUIQ · 13 November 2019 08:03

Sounds like, sftp package in duplicacy is outdated. duplicacy uses version 1.0.0 (30 Aug 2017), the latest one is 1.10.1 (26 Aug)

MUIQ · 13 November 2019 17:17

Next test iteration. Backup process had started at 7:42 and have frozen at 16:14. I don’t know amount of sent data during test iteration, probably 20-30 GB. Right now is 20:15, the duplicacy process freezes.

  PID  PPID USER     STAT   VSZ %VSZ CPU %CPU COMMAND
  219   210 root     S     822m   2%   0   0% duplicacy -profile 127.0.0.1:12345 backup

Stack dump looks the same (?)

goroutine profile: total 8
1 @ 0x40f312 0x441356 0x6be502 0x459cb1
#	0x441355	os/signal.signal_recv+0xa5	/usr/local/go/src/runtime/sigqueue.go:139
#	0x6be501	os/signal.loop+0x21		/usr/local/go/src/os/signal/signal_unix.go:22

1 @ 0x42c90a 0x427a4a 0x4270c7 0x4c4fcb 0x4c504d 0x4c5ead 0x59019f 0x5a144a 0x68943a 0x459cb1
#	0x4270c6	internal/poll.runtime_pollWait+0x56		/usr/local/go/src/runtime/netpoll.go:173
#	0x4c4fca	internal/poll.(*pollDesc).wait+0x9a		/usr/local/go/src/internal/poll/fd_poll_runtime.go:85
#	0x4c504c	internal/poll.(*pollDesc).waitRead+0x3c		/usr/local/go/src/internal/poll/fd_poll_runtime.go:90
#	0x4c5eac	internal/poll.(*FD).Read+0x17c			/usr/local/go/src/internal/poll/fd_unix.go:157
#	0x59019e	net.(*netFD).Read+0x4e				/usr/local/go/src/net/fd_unix.go:202
#	0x5a1449	net.(*conn).Read+0x69				/usr/local/go/src/net/net.go:176
#	0x689439	net/http.(*connReader).backgroundRead+0x59	/usr/local/go/src/net/http/server.go:668

1 @ 0x42c90a 0x427a4a 0x4270c7 0x4c4fcb 0x4c504d 0x4c7448 0x590ab2 0x5ab03e 0x5a9619 0x693d3f 0x692ad5 0x692829 0x69386a 0xb6940d 0x459cb1
#	0x4270c6	internal/poll.runtime_pollWait+0x56		/usr/local/go/src/runtime/netpoll.go:173
#	0x4c4fca	internal/poll.(*pollDesc).wait+0x9a		/usr/local/go/src/internal/poll/fd_poll_runtime.go:85
#	0x4c504c	internal/poll.(*pollDesc).waitRead+0x3c		/usr/local/go/src/internal/poll/fd_poll_runtime.go:90
#	0x4c7447	internal/poll.(*FD).Accept+0x1a7		/usr/local/go/src/internal/poll/fd_unix.go:372
#	0x590ab1	net.(*netFD).accept+0x41			/usr/local/go/src/net/fd_unix.go:238
#	0x5ab03d	net.(*TCPListener).accept+0x2d			/usr/local/go/src/net/tcpsock_posix.go:136
#	0x5a9618	net.(*TCPListener).AcceptTCP+0x48		/usr/local/go/src/net/tcpsock.go:246
#	0x693d3e	net/http.tcpKeepAliveListener.Accept+0x2e	/usr/local/go/src/net/http/server.go:3219
#	0x692ad4	net/http.(*Server).Serve+0x1a4			/usr/local/go/src/net/http/server.go:2773
#	0x692828	net/http.(*Server).ListenAndServe+0xa8		/usr/local/go/src/net/http/server.go:2714
#	0x693869	net/http.ListenAndServe+0x79			/usr/local/go/src/net/http/server.go:2972
#	0xb6940c	main.setGlobalOptions.func1+0x3c		/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:158

1 @ 0x42c90a 0x42c9be 0x4035bb 0x403355 0xa9d0a0 0xa9bf2e 0x463cfa 0x4638aa 0xb52a22 0xb1db30 0xb1f109 0xaf7767 0xb51873 0x459cb1
#	0xa9d09f	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*clientConn).dispatchRequest+0x1bf	/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/conn.go:110
#	0xa9bf2d	github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp.(*File).ReadFrom+0x19d		/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/pkg/sftp/client.go:988
#	0x463cf9	io.copyBuffer+0x319										/usr/local/go/src/io/io.go:386
#	0x4638a9	io.Copy+0x59											/usr/local/go/src/io/io.go:362
#	0xb52a21	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).UploadFile.func3+0x281			/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:323
#	0xb1db2f	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).retry+0x6f					/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:125
#	0xb1f108	github.com/gilbertchen/duplicacy/src.(*SFTPStorage).UploadFile+0x3a8				/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_sftpstorage.go:307
#	0xaf7766	github.com/gilbertchen/duplicacy/src.(*ChunkUploader).Upload+0x416				/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkuploader.go:138
#	0xb51872	github.com/gilbertchen/duplicacy/src.(*ChunkUploader).Start.func1+0x82				/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkuploader.go:60

1 @ 0x42c90a 0x42c9be 0x4035bb 0x403355 0xb4f3db 0xaf4e70 0xae1955 0xb5e0a1 0x72d00a 0x72aa04 0xb68cfc 0x42c4b2 0x459cb1
#	0xb4f3da	github.com/gilbertchen/duplicacy/src.(*ChunkUploader).StartChunk+0x4fa			/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkuploader.go:72
#	0xb4f3da	github.com/gilbertchen/duplicacy/src.(*BackupManager).Backup.func3+0x4fa		/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_backupmanager.go:521
#	0xaf4e6f	github.com/gilbertchen/duplicacy/src.(*ChunkMaker).ForEachChunk+0x80f			/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_chunkmaker.go:286
#	0xae1954	github.com/gilbertchen/duplicacy/src.(*BackupManager).Backup+0x3b64			/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/src/duplicacy_backupmanager.go:497
#	0xb5e0a0	main.backupRepository+0x5b0								/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:723
#	0x72d009	github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.Command.Run+0x7e9	/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/command.go:160
#	0x72aa03	github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli.(*App).Run+0x863	/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/vendor/github.com/gilbertchen/cli/app.go:179
#	0xb68cfb	main.main+0x584b									/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:1996
#	0x42c4b1	runtime.main+0x211									/usr/local/go/src/runtime/proc.go:198

1 @ 0x42c90a 0x42c9be 0x404212 0x403f0b 0xb69640 0x459cb1
#	0xb6963f	main.main.func1+0x5f	/Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy/duplicacy/duplicacy_main.go:1990

1 @ 0x42c90a 0x43c5c0 0x4569c4 0x459cb1
#	0x42c909	runtime.gopark+0x119		/usr/local/go/src/runtime/proc.go:291
#	0x43c5bf	runtime.selectgo+0xe4f		/usr/local/go/src/runtime/select.go:392
#	0x4569c3	runtime.ensureSigM.func1+0x1f3	/usr/local/go/src/runtime/signal_unix.go:549

1 @ 0x71cf18 0x71cd20 0x719864 0x72502d 0x7253b1 0x68f9e4 0x6916d0 0x69270c 0x68ea01 0x459cb1
#	0x71cf17	runtime/pprof.writeRuntimeProfile+0x97	/usr/local/go/src/runtime/pprof/pprof.go:679
#	0x71cd1f	runtime/pprof.writeGoroutine+0x9f	/usr/local/go/src/runtime/pprof/pprof.go:641
#	0x719863	runtime/pprof.(*Profile).WriteTo+0x3e3	/usr/local/go/src/runtime/pprof/pprof.go:310
#	0x72502c	net/http/pprof.handler.ServeHTTP+0x20c	/usr/local/go/src/net/http/pprof/pprof.go:243
#	0x7253b0	net/http/pprof.Index+0x1d0		/usr/local/go/src/net/http/pprof/pprof.go:254
#	0x68f9e3	net/http.HandlerFunc.ServeHTTP+0x43	/usr/local/go/src/net/http/server.go:1947
#	0x6916cf	net/http.(*ServeMux).ServeHTTP+0x12f	/usr/local/go/src/net/http/server.go:2340
#	0x69270b	net/http.serverHandler.ServeHTTP+0xbb	/usr/local/go/src/net/http/server.go:2697
#	0x68ea00	net/http.(*conn).serve+0x650		/usr/local/go/src/net/http/server.go:1830

gchen · 13 November 2019 17:19

This can be a bug in the sftp package. I guess what likely happened was that since so many chunks were skipped there had been no activity for a while on the ssh connection and the server closed the connection. You can try setting the environment variable DUPLICACY_UPLOAD_KEEPALIVE to 300, which means every 300 seconds, Duplicacy will force a lookup on a chunk even if the chunk is known to exist. The default value for this parameter is 1800.

MUIQ · 13 November 2019 17:22

I experienced this issue since the beginning of backup, to empty repository.

Ok, I’ll try.

Christoph · 13 November 2019 21:41

If the problem goes away with a lower value, would there be any reason not to reduce the default value?

MUIQ · 15 November 2019 07:12

Ok, did not help. Backup freezed after 10 hours of work. There are no CPU load nor network traffic during last 3 hours.

gchen · 15 November 2019 17:48

Check the sshd log on your server to see if and when the ssh connection was closed.

MUIQ · 15 November 2019 18:46

Some explanation. I have 2 apartments. The networks in apartments are connected via VPN tunnel. This is why the speed is so low.
sftp server runs on the OpenWrt router (openssh-sftp-server package), and USB HDD is connected directly to the router.

Expected log (from other backup tasks, no more than several GB of data each):

Fri Nov 15 01:12:33 2019 authpriv.info dropbear[6383]: Child connection from 172.16.1.1:55862
Fri Nov 15 01:12:35 2019 authpriv.notice dropbear[6383]: Password auth succeeded for 'root' from 172.16.1.1:55862
Fri Nov 15 01:13:00 2019 authpriv.info dropbear[6383]: Exit (root): Exited normally
Fri Nov 15 01:18:44 2019 authpriv.info dropbear[6469]: Child connection from 172.16.1.1:35304
Fri Nov 15 01:18:46 2019 authpriv.notice dropbear[6469]: Password auth succeeded for 'root' from 172.16.1.1:35304
Fri Nov 15 01:26:27 2019 authpriv.info dropbear[6481]: Child connection from 172.16.1.1:50278
Fri Nov 15 01:26:28 2019 authpriv.notice dropbear[6481]: Password auth succeeded for 'root' from 172.16.1.1:50278
Fri Nov 15 01:26:43 2019 authpriv.info dropbear[6481]: Exit (root): Exited normally
Fri Nov 15 01:30:40 2019 authpriv.info dropbear[6469]: Exit (root): Exited normally
Fri Nov 15 01:32:17 2019 authpriv.info dropbear[6566]: Child connection from 172.16.1.1:48618
Fri Nov 15 01:32:19 2019 authpriv.notice dropbear[6566]: Password auth succeeded for 'root' from 172.16.1.1:48618
Fri Nov 15 01:32:25 2019 authpriv.info dropbear[6566]: Exit (root): Exited normally
Fri Nov 15 01:42:12 2019 authpriv.info dropbear[6652]: Child connection from 172.16.1.1:57324
Fri Nov 15 01:42:14 2019 authpriv.notice dropbear[6652]: Password auth succeeded for 'root' from 172.16.1.1:57324
Fri Nov 15 01:43:18 2019 authpriv.info dropbear[6652]: Exit (root): Exited normally
Fri Nov 15 01:51:07 2019 authpriv.info dropbear[6738]: Child connection from 172.16.1.1:39982
Fri Nov 15 01:51:09 2019 authpriv.notice dropbear[6738]: Password auth succeeded for 'root' from 172.16.1.1:39982
Fri Nov 15 01:51:23 2019 authpriv.info dropbear[6738]: Exit (root): Exited normally
Fri Nov 15 01:54:41 2019 authpriv.info dropbear[6741]: Child connection from 172.16.1.1:33780
Fri Nov 15 01:54:43 2019 authpriv.notice dropbear[6741]: Password auth succeeded for 'root' from 172.16.1.1:33780
Fri Nov 15 01:55:11 2019 authpriv.info dropbear[6741]: Exit (root): Exited normally
Fri Nov 15 01:56:20 2019 authpriv.info dropbear[6743]: Child connection from 172.16.1.1:44774
Fri Nov 15 01:56:22 2019 authpriv.notice dropbear[6743]: Password auth succeeded for 'root' from 172.16.1.1:44774
Fri Nov 15 01:56:23 2019 authpriv.info dropbear[6743]: Exit (root): Exited normally

Log from bad task:

Thu Nov 14 20:50:55 2019 authpriv.info dropbear[3995]: Child connection from 172.16.1.1:36658
Thu Nov 14 20:50:57 2019 authpriv.notice dropbear[3995]: Password auth succeeded for 'root' from 172.16.1.1:36658
...
Fri Nov 15 00:11:54 2019 authpriv.info dropbear[3995]: Exit (root): Error reading: Connection reset by peer
Fri Nov 15 00:11:56 2019 authpriv.info dropbear[5695]: Child connection from 172.16.1.1:44130
Fri Nov 15 00:11:56 2019 authpriv.notice dropbear[5695]: Password auth succeeded for 'root' from 172.16.1.1:44130
...
Fri Nov 15 07:11:51 2019 authpriv.info dropbear[5695]: Exit (root): Error reading: Connection reset by peer

I don’t know why it resets ones during the night.

gchen · 16 November 2019 01:38

It must be this bug: Deadlock if server kills the transfer · Issue #181 · pkg/sftp · GitHub

I’ll update the sftp package, and make a release in a few days.

MUIQ · 25 November 2019 07:08

Could you create release or RC ASAP? duplicacy is useless in my environment right now.

gchen · 25 November 2019 16:50

The new release should be ready later today.

gchen · 26 November 2019 02:47

CLI version 2.3.0 has been released. You’ll just need to restart the web GUI and it will update the CLI automatically (unless you set the 'cli_version key in ~/.duplicacy-web/duplicacy.json).

MUIQ · 7 December 2019 07:41

Tested during 10 days - it works now!

TheBestPessimist · 1 February 2020 16:00

This topic was automatically closed after 56 days. New replies are no longer allowed.