Bad file descriptor on rclone mount when duping stdout/stderr

emboehm · June 11, 2020, 1:24pm

What is the problem you are having with rclone?

I am getting bad file descriptor when duping stdout/stderr to files on rclone mount and sending output to the file descriptors.

I originally tried a cached remote. I saw that cached remotes were deprecated so I tried again with rclone mount.

I am not sure if this should work or if this type of operation is not supported.

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

rclone v1.52.0

os/arch: linux/386
go version: go1.14.3

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

CentOS Linux release 7.3.1611 (Core) 64-bit
Linux 3.10.0-514.el7.x86_64

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

Box

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

cat test_io.sh
#!/bin/bash

[[ $SH_DEBUG == true ]] && set -x

function get_string() {

   local str=$(tr -dc A-z-a-z0-9 < /dev/urandom | head -c 80)

   echo $str
}

if [[ $# -ne 2 ]]
then
    echo "Test requires two arguments: log_file and log_errfile"
    exit 1
fi

log_file=${1}
log_errfile=${2}

touch "$log_file"
exec 6>&1                               # Link file descriptor #6 with stdout. Saves stdout.
exec > "$log_file"              # stdout replaced with file $log_file.

touch "$log_errfile"
exec 7>&2                               # Link file descriptor #7 with stderr. Saves stderr.
exec 2> "$log_errfile"  # stderr replaced with file $log_errfile.

for i in {1..10}
do 
    printf "%s\n" $(get_string)
    printf "%s\n" $(get_string) 1>&2
done


# cd /opt/mysql-test/backup/rclone/box_hnd_mount_cache/mount/test_io
# test_io.sh log_file log_errfile
# ls -l
total 0
-rw-r--r-- 1 root root 0 Jun  9 07:45 log_errfile
-rw-r--r-- 1 root root 0 Jun  9 07:45 log_file

The rclone config contents with secrets removed.

[box_hnd]
type = box
allow-other = 1
buffer-size = 1G
dir-cache-time = 5m0s
log-file = /opt/mysql-test/backup/rclone/box_hnd_mount_cache/box_hnd_mount_cache.log
max-read-ahead = 128k
vfs-cache-mode = full
vfs-read-chunk-size = 64M
vfs-read-chunk-size-limit = 2G
write-back-cache = 1
uid = 54363
gid = 20
rc = 1
rc-addr = 127.0.0.1:5572

2020/06/09 07:40:38 DEBUG : rclone: Version "v1.52.0" starting with parameters ["rclone" "-vv" "--config" "/opt/mysql_backup/scripts/rclone.conf" "mount" "box_hnd:RB_DASHBOARD_BACKUP/automysqlbackup" "/opt/mysql-test/backup/rclone/box_hnd_mount_cache/mount" "--log-file=/opt/mysql-test/backup/rclone/box_hnd_mount_cache/box_hnd_mount_cache.log" "--daemon"]

A log from the command with the `-vv` flag

2020/06/09 07:45:11 DEBUG : test_io/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/log_file: Open: flags=OpenWriteOnly
2020/06/09 07:45:11 DEBUG : test_io/log_file: Open: flags=O_WRONLY
2020/06/09 07:45:11 DEBUG : test_io/log_file: >Open: fd=test_io/log_file (w), err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/log_file: >Open: fh=&{test_io/log_file (w)}, err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/log_file: Setattr: a=Setattr [ID=0x56 Node=0xb Uid=0 Gid=0 Pid=175761] size=0 handle=INVALID-0x0 lockowner
2020/06/09 07:45:11 DEBUG : test_io/log_file: Truncating 1 file handles
2020/06/09 07:45:11 DEBUG : test_io/log_file: >Setattr: err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/log_file: Attr:
2020/06/09 07:45:11 DEBUG : test_io/log_file: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/09 07:45:11 DEBUG : &{test_io/log_file (w)}: Flush:
2020/06/09 07:45:11 DEBUG : test_io/log_file: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2020/06/09 07:45:11 DEBUG : &{test_io/log_file (w)}: >Flush: err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/: Lookup: name="log_errfile"
2020/06/09 07:45:11 DEBUG : test_io/: >Lookup: node=<nil>, err=no such file or directory
2020/06/09 07:45:11 DEBUG : test_io/: Create: name="log_errfile"
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: Open: flags=O_WRONLY|O_CREATE|0x800
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: >Open: fd=test_io/log_errfile (w), err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/: >Create: node=test_io/log_errfile, handle=&{test_io/log_errfile (w)}, err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: Attr:
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/09 07:45:11 DEBUG : &{test_io/log_errfile (w)}: Flush:
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2020/06/09 07:45:11 DEBUG : &{test_io/log_errfile (w)}: >Flush: err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: Setattr: a=Setattr [ID=0x5b Node=0xc Uid=0 Gid=0 Pid=175764] atime=2020-06-09 07:45:11.341778273 -0700 PDT atime=now mtime=2020-06-09 07:45:11.341778273 -0700 PDT mtime=now handle=INVALID-0x0
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: >Setattr: err=<nil>
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: Attr:
2020/06/09 07:45:11 DEBUG : test_io/log_errfile: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/09 07:45:11 DEBUG : &{test_io/log_errfile (w)}: Flush:
2020/06/09 07:45:11 DEBUG : box root 'RB_DASHBOARD_BACKUP/automysqlbackup': File to upload is small (0 bytes), uploading instead of streaming
2020/06/09 07:45:12 DEBUG : test_io/log_errfile: SHA-1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK
2020/06/09 07:45:12 INFO  : test_io/log_errfile: Copied (new)
2020/06/09 07:45:12 DEBUG : test_io/log_errfile: File._applyPendingModTime OK
2020/06/09 07:45:12 DEBUG : &{test_io/log_errfile (w)}: >Flush: err=<nil>
2020/06/09 07:45:12 DEBUG : &{test_io/log_errfile (w)}: Release:
2020/06/09 07:45:12 DEBUG : test_io/log_errfile: WriteFileHandle.Release nothing to do
2020/06/09 07:45:12 DEBUG : &{test_io/log_errfile (w)}: >Release: err=<nil>
[...]
2020/06/09 07:45:15 DEBUG : test_io/log_file: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/09 07:45:15 DEBUG : &{test_io/log_file (w)}: Write: len=81, offset=0
2020/06/09 07:45:15 ERROR : test_io/log_file: WriteFileHandle.Write: error: Bad file descriptor
2020/06/09 07:45:15 DEBUG : &{test_io/log_file (w)}: >Write: written=0, err=bad file descriptor
2020/06/09 07:45:15 DEBUG : test_io/log_errfile: Attr:
2020/06/09 07:45:15 DEBUG : test_io/log_errfile: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/09 07:45:15 DEBUG : &{test_io/log_errfile (w)}: Write: len=88, offset=0
2020/06/09 07:45:15 ERROR : test_io/log_errfile: WriteFileHandle.Write: error: Bad file descriptor
2020/06/09 07:45:15 DEBUG : &{test_io/log_errfile (w)}: >Write: written=0, err=bad file descriptor
2020/06/09 07:45:15 DEBUG : &{test_io/log_file (w)}: Flush:
2020/06/09 07:45:15 DEBUG : test_io/log_file: WriteFileHandle.Flush nothing to do

ncw · June 11, 2020, 8:14pm

What is your rclone command?

You appear to have mount flags in the backend config so I'm a bit confused about that!

I think if you use VFS cache mode writes or full it should work, but according to your log I don't think you are.

emboehm · June 11, 2020, 8:37pm

I thought I could use switches in the config files instead of on the command-line. I was trying to make the command-line simpler.

Are you saying that I can't use these options in the config file?

allow-other = 1
buffer-size = 1G
dir-cache-time = 5m0s
log-file = /opt/mysql-test/backup/rclone/box_hnd_mount_cache/box_hnd_mount_cache.log
max-read-ahead = 128k
vfs-cache-mode = full
vfs-read-chunk-size = 64M
vfs-read-chunk-size-limit = 2G
write-back-cache = 1
uid = 54363
gid = 20
rc = 1
rc-addr = 127.0.0.1:5572

calisro · June 11, 2020, 8:46pm

backend specific ones you can. global ones you cant yet. If you run through 'rclone config' in the advanced more you can see which ones you can add to the config.

https://rclone.org/docs/#config-file

emboehm · June 11, 2020, 9:01pm

My test passed when I changed rclone.conf and the startup command

cat rclone.conf
[box_hnd]
type = box

# command-line
rclone -vv \
--config /opt/mysql_backup/scripts/rclone.conf \
mount \
box_hnd:RB_DASHBOARD_BACKUP/automysqlbackup \
/opt/mysql-test/backup/rclone/box_hnd/mount \
--allow-other \
--buffer-size 10M \
--dir-cache-time 5m0s \
--fast-list \
--log-file /opt/mysql-test/backup/rclone/box_hnd/box_hnd.log \
--max-read-ahead 128k \
--vfs-cache-mode full \
--vfs-read-chunk-size 64M \
--vfs-read-chunk-size-limit 2G \
--uid 54363 \
--gid 20 \
--rc \
--rc-addr 127.0.0.1:5572 \
--daemon

I will have to experiment with what can be moved to the config.

Are these log entries anything to be concerned about (i.e, 'File.delWriter couldn't find handle')?

2020/06/11 13:53:33 DEBUG : test_io/log_errfile: File.delWriter couldn't find handle
2020/06/11 13:53:33 DEBUG : test_io/log_errfile: Size and modification time the same (differ by -553.569731ms, within tolerance 1s)
2020/06/11 13:53:33 DEBUG : test_io/log_errfile: Unchanged skipping
2020/06/11 13:53:33 DEBUG : test_io/log_errfile: transferred to remote
2020/06/11 13:53:33 DEBUG : &{test_io/log_errfile (rw)}: >Flush: err=<nil>
2020/06/11 13:53:33 DEBUG : test_io/: ReadDirAll: 
2020/06/11 13:53:33 DEBUG : test_io/: >ReadDirAll: item=2, err=<nil>
2020/06/11 13:53:33 DEBUG : &{test_io/log_file (rw)}: Flush: 
2020/06/11 13:53:33 DEBUG : test_io/log_file: File.delWriter couldn't find handle

ncw · June 12, 2020, 2:13pm

That is correct, alas.

I'd like to do that, but I haven't done it yet.

system · August 12, 2020, 10:13am

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