Locked Mount due to downloaders

Suspected Bug
1

What is the problem you are having with rclone?

Locked rclone mount

Run the command 'rclone version' and share the full output of the command.

rclone v1.58.0-beta

  • os/version: ubuntu 18.04 (64 bit)
  • os/kernel: 5.17.7-xanmod1 (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.17.8
  • go/linking: dynamic
  • go/tags: cmount

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

Google Drive

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

rclone cmount PersonalGD:Metadata/Media /mnt/GDMedia --use-mmap --umask=002 --allow-other --attr-timeout=0 --buffer-size=0M --async-read=false --poll-interval=0 --config=/home/darthshadow/rclone/rclone.conf --cache-dir=/home/darthshadow/rclone/vfs/GD/ --dir-cache-time=96000h --drive-chunk-size=16M --drive-pacer-min-sleep=1ms --vfs-read-ahead=0M --vfs-read-chunk-size=512k --vfs-read-chunk-size-limit=8M --vfs-cache-mode=full --vfs-write-back=1m --vfs-cache-max-age=168h --vfs-cache-max-size=25G --vfs-cache-poll-interval=5m --log-level=INFO --log-file=/home/darthshadow/rclone/logs/rclone-gd.log --stats=30s --stats-log-level=NOTICE --rc --rc-no-auth --rc-addr=127.0.0.1:5572 --rc-job-expire-duration=30m --rc-job-expire-interval=60s --tpslimit-burst=100 --drive-disable-http2=true

The rclone config contents with secrets removed.

[PersonalGD]
type = drive
scope = drive
use_trash = true
skip_gdocs = true
trashed_only = false
acknowledge_abuse = true

A log from the command with the -vv flag

Relevant log from SIGQUIT

goroutine 3339996 [chan receive, 278 minutes, locked to thread]:
github.com/rclone/rclone/vfs/vfscache/downloaders.(*Downloaders).Download(0xc0060c02c0, {0x0, 0x24ee710})
        /tmp/golang/src/github.com/rclone/rclone/vfs/vfscache/downloaders/downloaders.go:269 +0x1ba
github.com/rclone/rclone/vfs/vfscache.(*Item)._ensure(0xc004935960, 0x1000, 0xc02056b9c8)
        /tmp/golang/src/github.com/rclone/rclone/vfs/vfscache/item.go:1136 +0x2de
github.com/rclone/rclone/vfs/vfscache.(*Item).readAt(0xc004935960, {0x7efc8c58f080, 0x8000, 0x40000000}, 0x1000)
        /tmp/golang/src/github.com/rclone/rclone/vfs/vfscache/item.go:1247 +0x137
github.com/rclone/rclone/vfs/vfscache.(*Item).ReadAt(0xc004935960, {0x7efc8c58f080, 0x8000, 0x40000000}, 0xc02056bb48)
        /tmp/golang/src/github.com/rclone/rclone/vfs/vfscache/item.go:1212 +0x105
github.com/rclone/rclone/vfs.(*RWFileHandle)._readAt(0xc0b82ad3c0, {0x7efc8c58f080, 0xc000056070, 0x40000000}, 0x1000, 0x1)
        /tmp/golang/src/github.com/rclone/rclone/vfs/read_write.go:266 +0x415
github.com/rclone/rclone/vfs.(*RWFileHandle).ReadAt(0xc00069e000, {0x7efc8c58f080, 0x2488662, 0x10}, 0xc02056bd08)
        /tmp/golang/src/github.com/rclone/rclone/vfs/read_write.go:278 +0xf3
github.com/rclone/rclone/cmd/cmount.(*FS).Read(0x7efc8c024980, {0xc05f293080, 0x3e}, {0x7efc8c58f080, 0x8000, 0x40000000}, 0x56be00, 0x3e)
        /tmp/golang/src/github.com/rclone/rclone/cmd/cmount/fs.go:383 +0x20f
github.com/billziss-gh/cgofuse/fuse.hostRead(0xc02056be20, 0x7efc8c58f080, 0x8000, 0x0, 0x7efcffffece0)
        /tmp/golang/pkg/mod/github.com/darthshadow/cgofuse@v1.5.1-0.20211026130714-f0ad03169e0f/fuse/host.go:245 +0x11c
github.com/billziss-gh/cgofuse/fuse.go_hostRead(...)
        /tmp/golang/pkg/mod/github.com/darthshadow/cgofuse@v1.5.1-0.20211026130714-f0ad03169e0f/fuse/host_cgo.go:909

rclone.log (7.9 KB)

2

This trace

1: chan receive [278 minutes] [locked]
    downloaders downloaders.go:269    (*Downloaders).Download(*Downloaders(#29), Range{0x0, #6})
    vfscache    item.go:1136          (*Item)._ensure(*Item(#27), 4096, 825176275400)
    vfscache    item.go:1247          (*Item).readAt(*Item(#27), []byte(#38 len=32768 cap=1073741824), 4096)
    vfscache    item.go:1212          (*Item).ReadAt(*Item(#27), []byte(#38 len=32768 cap=1073741824), 825176275784)
    vfs         read_write.go:266     (*RWFileHandle)._readAt(*RWFileHandle(#36), []byte(#38 len=824634073200 cap=1073741824), 4096, true)
    vfs         read_write.go:278     (*RWFileHandle).ReadAt(*RWFileHandle(#20), []byte(#38 len=38307426 cap=16), 825176276232)
    cmount      fs.go:383             (*FS).Read(*FS(#37), string(#35, len=62), []byte(#38 len=32768 cap=1073741824), 5684736, 62)
    fuse        host.go:245           hostRead(#34, #38, 0x8000, 0, #39)
    fuse        host_cgo.go:909       go_hostRead(...)

The downloader is waiting for the download of data to finish, however looking at the other things in the log, it doesn't appear to be running.

Why that is, I'm not sure - I suspect the answer would be in a DEBUG log somewhere!

Can you reproduce the problem?

What problems does this cause in practice? Is the whole mount locked, or one directory or one file?

3

It's been happening on different machines but only happens after several (~3-4) days so any DEBUG log is going to be very large. I will still add it to the mount command the next time it happens, if you can't think of anything better by then.

This is behind a mergerfs mount which gets locked. Even something like df -h on the system gets stuck. The actual rclone mount seems responsive but I didn't try running a find to see if that completed or not.

4

Probably all the info I need will be in a grep -C10 bad-file-name rclone.log

Hmm...

It looks like that file leaked its downloaders somehow. That should be in the log hopefull!

5

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