Deadlock during backup

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.

Welcome to the forum @MUIQ!

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

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.

3 Likes

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

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.

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)

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

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.

1 Like

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

Ok, I’ll try.

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

2 Likes

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

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

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.

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.

3 Likes

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

The new release should be ready later today.

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).

3 Likes

Tested during 10 days - it works now!

2 Likes