'Bad file descriptor' when moving files to rclone mount point

dippynark · January 20, 2020, 9:07pm

What is the problem you are having with rclone?

I am very intermittently seeing Bad file descriptor error when moving a file to an rclone mount point. This is happening when importing files using Sonarr (https://github.com/Sonarr/Sonarr) so it's not too easy to recreate or give more information on (maybe there is but I am not aware). Sonarr is trying to move a file from the local filesystem into the rclone mount point.

Sonarr works without using the rclone mount point so I'm assuming it's related to rclone.

The mount point is run using a systemd unit using the following flags:

/opt/bin/rclone mount media: /mnt/google-drive/Media \
    --config=/root/.config/rclone/rclone.conf \
    --drive-acknowledge-abuse \
    --drive-chunk-size=256M \
    --buffer-size=64M \
    --use-mmap \
    --attr-timeout=8760h \
    --dir-cache-time=8760h \
    --gid=1000 \
    --uid=1000 \
    --tpslimit=10 \
    --allow-other \
    --log-level=DEBUG \
    --debug-fuse

What is your rclone version (output from `rclone version`)

rclone v1.50.2
- os/arch: linux/amd64
- go version: go1.13.4

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

Container Linux 2303.3.0, 64 bit

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

Moving file to rclone mount point

A log from the command with the `-vv` flag (eg output from `rclone -vv copy /tmp remote:tmp`)

Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: Write: len=8192, offset=2465792
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: >Write: written=8192, err=<nil>
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : fuse: -> [ID=0xa9a5b5] Write 8192
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : fuse: <- Write [ID=0xa9a5b6 Node=0x1965 Uid=1000 Gid=1000 Pid=5091] 0x3 8192 @2473984 fl=0 lock=0 ffl=OpenWriteOnly
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: Write: len=8192, offset=2473984
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: >Write: written=8192, err=<nil>
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : fuse: -> [ID=0xa9a5b6] Write 8192
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : fuse: <- Flush [ID=0xa9a5b7 Node=0x1965 Uid=1000 Gid=1000 Pid=21023] 0x3 fl=0x0 lk=0x3d329731486bc53f
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: Flush:
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : fuse: <- Write [ID=0xa9a5b8 Node=0x1965 Uid=1000 Gid=1000 Pid=5091] 0x3 8192 @2482176 fl=0 lock=0 ffl=OpenWriteOnly
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : fuse: <- Interrupt [ID=0xa9a5b9 Node=0x0 Uid=0 Gid=0 Pid=0] ID 0xa9a5b8
Jan 20 19:11:30 core1 rclone[3654]: 2020/01/20 19:11:30 DEBUG : fuse: -> [ID=0xa9a5b9] Interrupt
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: <- Statfs [ID=0xa9a5ba Node=0x2 Uid=0 Gid=0 Pid=2032]
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : : Statfs:
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:270179382255 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: -> [ID=0xa9a5ba] Statfs blocks=274877906944/270179382255/274877906944 files=1000000000/1000000000 bsize=4096 frsize=4096 namelen=255
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: Size and modification time the same (differ by -20.778µs, within tolerance 1ms)
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: >Flush: err=<nil>
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: -> [ID=0xa9a5b7] Flush
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: Write: len=8192, offset=2482176
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 ERROR : TV Shows/Show/Season 4/Episode.mkv.partial~: WriteFileHandle.Write: error: Bad file descriptor
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: >Write: written=0, err=bad file descriptor
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: -> [ID=0xa9a5b8] Write error=bad file descriptor
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: <- Flush [ID=0xa9a5bb Node=0x1965 Uid=1000 Gid=1000 Pid=5091] 0x3 fl=0x0 lk=0x4facf5a68b7a074e
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: Flush:
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: WriteFileHandle.Flush nothing to do
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: >Flush: err=<nil>
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: -> [ID=0xa9a5bb] Flush
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: <- Release [ID=0xa9a5bc Node=0x1965 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenWriteOnly rfl=0 owner=0x0
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: Release:
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: WriteFileHandle.Release nothing to do
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : &{TV Shows/Show/Season 4/Episode.mkv.partial~ (w)}: >Release: err=<nil>
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: -> [ID=0xa9a5bc] Release
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : fuse: <- Setattr [ID=0xa9a5bd Node=0x1965 Uid=1000 Gid=1000 Pid=5091] atime=2020-01-20 18:55:54 +0000 UTC mtime=2020-01-20 18:58:28 +0000 UTC handle=INVALID-0x0
Jan 20 19:11:32 core1 rclone[3654]: 2020/01/20 19:11:32 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: Setattr: a=Setattr [ID=0xa9a5bd Node=0x1965 Uid=1000 Gid=1000 Pid=5091] atime=2020-01-20 18:55:54 +0000 UTC mtime=2020-01-20 18:58:28 +0000 UTC handle=INVALID-0x0
Jan 20 19:11:33 core1 rclone[3654]: 2020/01/20 19:11:33 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: File.applyPendingModTime OK
Jan 20 19:11:33 core1 rclone[3654]: 2020/01/20 19:11:33 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: >Setattr: err=<nil>
Jan 20 19:11:33 core1 rclone[3654]: 2020/01/20 19:11:33 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: Attr:
Jan 20 19:11:33 core1 rclone[3654]: 2020/01/20 19:11:33 DEBUG : TV Shows/Show/Season 4/Episode.mkv.partial~: >Attr: a=valid=8760h0m0s ino=0 size=2482176 mode=-rw-r--r--, err=<nil>
Jan 20 19:11:33 core1 rclone[3654]: 2020/01/20 19:11:33 DEBUG : fuse: -> [ID=0xa9a5bd] Setattr valid=8760h0m0s ino=3940880588782057757 size=2482176 mode=-rw-r--r--
Jan 20 19:11:36 core1 rclone[3654]: 2020/01/20 19:11:36 DEBUG : fuse: <- Getattr [ID=0xa9a5be Node=0x1962 Uid=1000 Gid=1000 Pid=5091] 0x0 fl=0
Jan 20 19:11:36 core1 rclone[3654]: 2020/01/20 19:11:36 DEBUG : TV Shows/Show/Season 4/: Attr:
Jan 20 19:11:36 core1 rclone[3654]: 2020/01/20 19:11:36 DEBUG : TV Shows/Show/Season 4/: >Attr: attr=valid=8760h0m0s ino=0 size=0 mode=drwxr-xr-x, err=<nil>

ncw · January 21, 2020, 8:12am

Hmm, "bad file descriptor" is EBADF which is caused by the use of an unknown file descriptor, or possibly by the use of a closed file descriptor.

Try adding --vfs-cache-mode writes to your mount?

Can you also try the latest beta which has fixes to do with renaming files.

dippynark · January 21, 2020, 12:29pm

That seems to work but the whole application hangs whilst moving a file - potentially this is not a responsibility of rclone?

$ rclone --version
rclone v1.50.2-178-g7125cb10-beta
- os/arch: linux/amd64
- go version: go1.13.6

ncw · January 21, 2020, 1:36pm

Glad it works.

Rclone won't return to the app until the operation is finished so you know that what you asked for has been done.

Are you moving a big file into the mount?

I plan to make rclone work in a more asynchronous way in the future.

dippynark · January 21, 2020, 6:40pm

Yeah, moving large media files - it's strange because Sonarr doesn't stall when not using --vfs-cache-mode - the asynchronous functionality sounds really useful

ncw · January 22, 2020, 1:29pm

I think so too... It needs a lot of careful thought though so I'm doing that bit first

system · April 21, 2020, 1:29pm

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