Rclone to tardigrade stalls at end of file

What is the problem you are having with rclone?

When copying a (larger) file to tardigrade it stops at 100% and never completes

What is your rclone version (output from rclone version)

rclone v1.53.1

  • os/arch: linux/amd64
  • go version: go1.15.2

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Linux archie 5.9.1-arch1-1 #1 SMP PREEMPT Sat, 17 Oct 2020 13:30:37 +0000 x86_64 GNU/Linux

Which cloud storage system are you using? (eg Google Drive)

tardigrade

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone copy -P /home/user/dirname/ tardigrade:dirname

The rclone config contents with secrets removed.

[tardigrade]
type = tardigrade
satellite_address = XXX
api_key = XXX
access_grant = XXX

A log from the command with the -vv flag

2020/10/25 12:29:44 DEBUG : rclone: Version "v1.53.1" starting with parameters ["rclone" "copy" "-vv" "-P" "/home/hans/bluetooth/test/" "tardigrade:hans/backups/bluetooth/test/"]
2020/10/25 12:29:44 DEBUG : Creating backend with remote "/home/hans/bluetooth/test/"
2020/10/25 12:29:44 DEBUG : Using config file from "/home/hans/.config/rclone/rclone.conf"
2020/10/25 12:29:44 DEBUG : Creating backend with remote "tardigrade:hans/backups/bluetooth/test/"
2020/10/25 12:29:44 DEBUG : FS sj://hans/backups/bluetooth/test: connecting...
2020/10/25 12:29:44 DEBUG : FS sj://hans/backups/bluetooth/test: connected: <nil>
2020/10/25 12:29:45 DEBUG : fs cache: renaming cache item "tardigrade:hans/backups/bluetooth/test/" to be canonical "tardigrade:hans/backups/bluetooth/test"
2020-10-25 12:29:45 DEBUG : FS sj://hans/backups/bluetooth/test: ls ./
2020-10-25 12:29:45 DEBUG : FS sj://hans/backups/bluetooth/test: OBJ ls ./ ("hans", "backups/bluetooth/test")
2020-10-25 12:29:45 DEBUG : FS sj://hans/backups/bluetooth/test: opts &{Prefix:backups/bluetooth/test/ Cursor: Recursive:false System:true Custom:true}
2020-10-25 12:29:45 DEBUG : FS sj://hans/backups/bluetooth/test: Waiting for checks to finish
2020-10-25 12:29:45 DEBUG : FS sj://hans/backups/bluetooth/test: Waiting for transfers to finish
2020-10-25 12:29:49 DEBUG : FS sj://hans/backups/bluetooth/test: cp input ./20100729-henna-hands.mov # [HashesOption([])] 10826454
2020-10-25 12:29:49 DEBUG : FS sj://hans/backups/bluetooth/test: cp input ./20100729-henna-hands2.mov # [HashesOption([])] 44152677
2020-10-25 12:29:49 DEBUG : FS sj://hans/backups/bluetooth/test: cp input ./20100729-making-favor-boxes.mov # [HashesOption([])] 50491135
2020-10-25 12:29:49 DEBUG : FS sj://hans/backups/bluetooth/test: cp input ./20100729-naryan1.mov # [HashesOption([])] 45318629
Transferred:      143.803M / 199.905 MBytes, 72%, 139.850 kBytes/s, ETA 6m50s
Transferred:            0 / 7, 0%
Elapsed time:     17m34.0s
Transferring:
 *                      20100729-henna-hands.mov:100% /10.325M, 0/s, 0s
 *                     20100729-henna-hands2.mov:100% /42.107M, 0/s, 0s
 *               20100729-making-favor-boxes.mov:100% /48.152M, 0/s, 0s
 *                          20100729-naryan1.mov:100% /43.219M, 0/s, 0s

How long did you wait? The backend may be doing a post-copy checksum which might take a while.

Can you try with the latest beta and if you still have the problem then make a new issue on github and we can take a look at it there - thanks

Used the beta vesion.
I let it run for 16 minutes, it still just sits there ....

Can you make the bug report on github. I can't right now.

+ export GODEBUG=asyncpreemptoff=1
+ GODEBUG=asyncpreemptoff=1
+ rclone-beta version
rclone v1.53.2
- os/arch: linux/amd64
- go version: go1.15.3
+ uname -a
Linux archie 5.9.1-arch1-1 #1 SMP PREEMPT Sat, 17 Oct 2020 13:30:37 +0000 x86_64 GNU/Linux
+ rclone-beta copy -P -vv /home/hans/test/rclone/ tardigrade:hans/test/rclone/
2020/10/26 09:32:40 DEBUG : rclone: Version "v1.53.2" starting with parameters ["rclone-beta" "copy" "-P" "-vv" "/home/hans/test/rclone/" "tardigrade:hans/test/rclone/"]
2020/10/26 09:32:40 DEBUG : Creating backend with remote "/home/hans/test/rclone/"
2020/10/26 09:32:40 DEBUG : Using config file from "/home/hans/.config/rclone/rclone.conf"
2020/10/26 09:32:40 DEBUG : Creating backend with remote "tardigrade:hans/test/rclone/"
2020/10/26 09:32:40 DEBUG : FS sj://hans/test/rclone: connecting...
2020/10/26 09:32:40 DEBUG : FS sj://hans/test/rclone: connected: <nil>
2020/10/26 09:32:40 DEBUG : fs cache: renaming cache item "tardigrade:hans/test/rclone/" to be canonical "tardigrade:hans/test/rclone"
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: ls ./
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: OBJ ls ./ ("hans", "test/rclone")
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: opts &{Prefix:test/rclone/ Cursor: Recursive:false System:true Custom:true}
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: Waiting for checks to finish
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: Waiting for transfers to finish
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-naryan1.mov # [HashesOption([])] 45318629
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-henna-hands2.mov # [HashesOption([])] 44152677
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-making-favor-boxes.mov # [HashesOption([])] 50491135
2020-10-26 09:32:40 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-henna-hands.mov # [HashesOption([])] 10826454
Transferred:      143.803M / 199.905 MBytes, 72%, 151.197 kBytes/s, ETA 6m19s
Transferred:            0 / 7, 0%
Elapsed time:     16m14.4s
Transferring:
 *                      20100729-henna-hands.mov:100% /10.325M, 0/s, 0s
 *                     20100729-henna-hands2.mov:100% /42.107M, 0/s, 0s
 *               20100729-making-favor-boxes.mov:100% /48.152M, 0/s, 0s
 *                          20100729-naryan1.mov:100% /43.219M, 0/s, 0s

I need you to do it so you get the notifications :slight_smile:

As doubtless the problem will take some iterating to fix.

Could you try this beta https://beta.rclone.org/v1.54.0-beta.4844.be6a888e5/ - unfortunately the one you chose was the 1.53.2 release which due to oddness in the automation also gets classed as a beta.

Is there an (arch) Linux version in that list?

Sorry the build was broken :frowning:

Here is a new one

v1.54.0-beta.4846.bf2b97535 on branch master (uploaded in 15-30 mins)

I still do not see a linux version

Will investigate, sorry!

OK here we go, 3rd time lucky!

v1.54.0-beta.4847.605f2b819 on branch master (uploaded in 15-30 mins)

Got the beta. But it doesn't seem to solve my problem:

+ export GODEBUG=asyncpreemptoff=1
+ GODEBUG=asyncpreemptoff=1
+ rclone-beta version
rclone v1.54.0-beta.4847.605f2b819
- os/arch: linux/amd64
- go version: go1.15.3
+ uname -a
Linux archie 5.9.1-arch1-1 #1 SMP PREEMPT Sat, 17 Oct 2020 13:30:37 +0000 x86_64 GNU/Linux
+ rclone-beta copy -P -vv /home/hans/test/rclone/ tardigrade:hans/test/rclone/
2020/10/27 09:19:30 DEBUG : rclone: Version "v1.54.0-beta.4847.605f2b819" starting with parameters ["rclone-beta" "copy" "-P" "-vv" "/home/hans/test/rclone/" "tardigrade:hans/test/rclone/"]
2020/10/27 09:19:30 DEBUG : Creating backend with remote "/home/hans/test/rclone/"
2020/10/27 09:19:30 DEBUG : Using config file from "/home/hans/.config/rclone/rclone.conf"
2020/10/27 09:19:30 DEBUG : Creating backend with remote "tardigrade:hans/test/rclone/"
2020/10/27 09:19:30 DEBUG : FS sj://hans/test/rclone: connecting...
2020/10/27 09:19:30 DEBUG : FS sj://hans/test/rclone: connected: <nil>
2020/10/27 09:19:31 DEBUG : fs cache: renaming cache item "tardigrade:hans/test/rclone/" to be canonical "tardigrade:hans/test/rclone"
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: ls ./
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: OBJ ls ./ ("hans", "test/rclone")
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: opts &{Prefix:test/rclone/ Cursor: Recursive:false System:true Custom:true}
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-henna-hands.mov # [HashesOption([])] 10826454
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-making-favor-boxes.mov # [HashesOption([])] 50491135
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: Waiting for checks to finish
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-henna-hands2.mov # [HashesOption([])] 44152677
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: cp input ./20100729-naryan1.mov # [HashesOption([])] 45318629
2020-10-27 09:19:31 DEBUG : FS sj://hans/test/rclone: Waiting for transfers to finish
Transferred:      143.803M / 199.905 MBytes, 72%, 154.854 kBytes/s, ETA 6m10s
Transferred:            0 / 7, 0%
Elapsed time:     15m51.5s
Transferring:
 *                      20100729-henna-hands.mov:100% /10.325M, 0/s, 0s
 *                     20100729-henna-hands2.mov:100% /42.107M, 0/s, 0s
 *               20100729-making-favor-boxes.mov:100% /48.152M, 0/s, 0s
 *                          20100729-naryan1.mov:100% /43.219M, 0/s, 0s

When rclone is stuck at the end, can you kill it with kill -QUIT or press CTRL-/ and post the backtrace - that will tell us what rclone is doing.

Thanks

last few lines of the trace: hope this helps. If you want the full trace let me know how to capture it.

crypto/tls.(*Conn).readFromUntil(0xc0050fea80, 0x7f48ddb069d8, 0xc0060ee200, 0x5, 0xc0060ee200, 0x65c6e7e97253c16c)
	crypto/tls/conn.go:801 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0050fea80, 0x0, 0x0, 0xc00a3a9c38)
	crypto/tls/conn.go:608 +0x115
crypto/tls.(*Conn).readRecord(...)
	crypto/tls/conn.go:576
crypto/tls.(*Conn).Read(0xc0050fea80, 0xc007656000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	crypto/tls/conn.go:1252 +0x15f
bufio.(*Scanner).Scan(0xc00387f480, 0x0)
	bufio/scan.go:214 +0xa9
storj.io/drpc/drpcwire.(*Reader).ReadPacket(0xc0040e01e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	storj.io/drpc@v0.0.14/drpcwire/transport.go:121 +0x105
storj.io/drpc/drpcmanager.(*Manager).manageReader(0xc003bd4800)
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:249 +0x125
created by storj.io/drpc/drpcmanager.NewWithOptions
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:77 +0x41d

goroutine 3877 [semacquire, 14 minutes]:
sync.runtime_Semacquire(0xc007f8acf8)
	runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc007f8acf0)
	sync/waitgroup.go:130 +0x65
storj.io/drpc/drpcmanager.(*Manager).manageStream(0xc003bd4800, 0x1d951a0, 0xc00965cbe0, 0xc00fff1980)
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:280 +0x145
created by storj.io/drpc/drpcmanager.(*Manager).NewClientStream
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:163 +0xf9

goroutine 3878 [chan receive, 14 minutes]:
storj.io/common/rpc/rpcpool.(*Conn).NewStream.func1(0x1d9bc60, 0xc00fff1980, 0xc0039f44b0, 0xc0040e0200)
	storj.io/common@v0.0.0-20200729140050-4c1ddac6fa63/rpc/rpcpool/pool.go:220 +0x5c
created by storj.io/common/rpc/rpcpool.(*Conn).NewStream
	storj.io/common@v0.0.0-20200729140050-4c1ddac6fa63/rpc/rpcpool/pool.go:219 +0x25c

goroutine 3838 [select, 14 minutes]:
storj.io/drpc/drpcmanager.(*Manager).manageStreamPackets(0xc003bd4800, 0xc007f8acf0, 0xc00fff1980)
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:296 +0x1f4
created by storj.io/drpc/drpcmanager.(*Manager).manageStream
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:278 +0xe5

goroutine 3839 [select, 14 minutes]:
storj.io/drpc/drpcmanager.(*Manager).manageStreamContext(0xc003bd4800, 0x1d951a0, 0xc00965cbe0, 0xc007f8acf0, 0xc00fff1980)
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:322 +0x1c5
created by storj.io/drpc/drpcmanager.(*Manager).manageStream
	storj.io/drpc@v0.0.14/drpcmanager/manager.go:279 +0x132

rax    0xca
rbx    0x28051c0
rcx    0x471b63
rdx    0x0
rdi    0x2805308
rsi    0x80
rbp    0x7ffde5dcab40
rsp    0x7ffde5dcaaf8
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x3
r13    0x2804940
r14    0x0
r15    0x0
rip    0x471b61
rflags 0x286
cs     0x33
fs     0x0
gs     0x0

I can see it is busy in the storj library from that.

Can you try this - I updated the storj library to the latest version v1.3.1 from v1.2.0

v1.54.0-beta.4849.de66db3bd.fix-storj on branch fix-storj (uploaded in 15-30 mins)

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.