I/O error trashing file on sftp mount

chtk · November 22, 2022, 9:31pm

What is the problem you are having with rclone?

Because it doesn't have an active maintainer anymore, I'm trying to move away from sshfs to mount a USB-drive attached to my main machine on my laptop. Both are running Linux, OpenSSH 9.1_p1, RClone 1.60.1

Seems to work fine for the most part except for one thing. Trashing a file on the sftp mount from the filemanager (Nemo), or by running gio trash [file] results in an error:

$ gio trash tmp/foo
gio: file:///home/stefan/mnt/tmp/foo: Unable to create trashing info file for /home/stefan/mnt/tmp/foo: Input/output error

This works fine with the same remote locations mounted using sshfs, but sadly somehow fails on rclone.

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

rclone v1.60.1-DEV
- os/version: gentoo 2.9 (64 bit)
- os/kernel: 6.0.7-gentoo-x86_64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.19.3
- go/linking: dynamic
- go/tags: none

It seems the -DEV is added by the Gentoo package. I tried the version installed using rclone selfupdate as well, with the same results.

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

sftp

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

rclone mount beesje-iii: tmp/ -vv --debug-fuse

The rclone config contents with secrets removed.

[beesje-iii]
type = sftp
host = beesje-iii
key_use_agent = true
shell_type = unix
md5sum_command = md5sum
sha1sum_command = sha1sum

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

2022/11/22 21:51:25 DEBUG : fuse: <- Lookup [ID=0x3f8 Node=0x1 Uid=1000 Gid=1000 Pid=1655988] "foo"
2022/11/22 21:51:25 DEBUG : /: Lookup: name="foo"
2022/11/22 21:51:25 DEBUG : /: >Lookup: node=foo, err=<nil>
2022/11/22 21:51:25 DEBUG : foo: Attr:
2022/11/22 21:51:25 DEBUG : foo: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x3f8] Lookup 0x5 gen=0 valid=1s attr={valid=1s ino=11250026935264495724 size=0 mode=-rw-r--r--}
2022/11/22 21:51:25 DEBUG : fuse: <- Getattr [ID=0x3fa Node=0x1 Uid=1000 Gid=1000 Pid=1655988] 0x0 fl=0
2022/11/22 21:51:25 DEBUG : /: Attr:
2022/11/22 21:51:25 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x3fa] Getattr valid=1s ino=1 size=0 mode=drwxr-xr-x
2022/11/22 21:51:25 DEBUG : fuse: <- Lookup [ID=0x3fc Node=0x1 Uid=1000 Gid=1000 Pid=1655988] ".Trash"
2022/11/22 21:51:25 DEBUG : /: Lookup: name=".Trash"
2022/11/22 21:51:25 DEBUG : /: >Lookup: node=.Trash/, err=<nil>
2022/11/22 21:51:25 DEBUG : .Trash/: Attr:
2022/11/22 21:51:25 DEBUG : .Trash/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x3fc] Lookup 0x2 gen=0 valid=1s attr={valid=1s ino=12659673830537892932 size=0 mode=drwxr-xr-x}
2022/11/22 21:51:25 DEBUG : fuse: <- Lookup [ID=0x3fe Node=0x1 Uid=1000 Gid=1000 Pid=1655988] ".Trash-1000"
2022/11/22 21:51:25 DEBUG : /: Lookup: name=".Trash-1000"
2022/11/22 21:51:25 DEBUG : /: >Lookup: node=.Trash-1000/, err=<nil>
2022/11/22 21:51:25 DEBUG : .Trash-1000/: Attr:
2022/11/22 21:51:25 DEBUG : .Trash-1000/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x3fe] Lookup 0x3 gen=0 valid=1s attr={valid=1s ino=13592193118483318026 size=0 mode=drwxr-xr-x}
2022/11/22 21:51:25 DEBUG : fuse: <- Lookup [ID=0x400 Node=0x3 Uid=1000 Gid=1000 Pid=1655988] "info"
2022/11/22 21:51:25 DEBUG : .Trash-1000/: Lookup: name="info"
2022/11/22 21:51:25 DEBUG : .Trash-1000/: >Lookup: node=.Trash-1000/info/, err=<nil>
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/: Attr:
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x400] Lookup 0x6 gen=0 valid=1s attr={valid=1s ino=14021841314644340930 size=0 mode=drwxr-xr-x}
2022/11/22 21:51:25 DEBUG : fuse: <- Lookup [ID=0x402 Node=0x3 Uid=1000 Gid=1000 Pid=1655988] "files"
2022/11/22 21:51:25 DEBUG : .Trash-1000/: Lookup: name="files"
2022/11/22 21:51:25 DEBUG : .Trash-1000/: >Lookup: node=.Trash-1000/files/, err=<nil>
2022/11/22 21:51:25 DEBUG : .Trash-1000/files/: Attr:
2022/11/22 21:51:25 DEBUG : .Trash-1000/files/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x402] Lookup 0x4 gen=0 valid=1s attr={valid=1s ino=5565465136058772125 size=0 mode=drwxr-xr-x}
2022/11/22 21:51:25 DEBUG : fuse: <- Lookup [ID=0x404 Node=0x6 Uid=1000 Gid=1000 Pid=1655988] "foo.trashinfo"
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/: Lookup: name="foo.trashinfo"
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/: >Lookup: node=<nil>, err=no such file or directory
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x404] Lookup error=ENOENT
2022/11/22 21:51:25 DEBUG : fuse: <- Create [ID=0x406 Node=0x6 Uid=1000 Gid=1000 Pid=1655988] "foo.trashinfo" fl=OpenReadOnly+OpenCreate+OpenExclusive mode=-rw-r--r-- umask=-----w--w-
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/: Create: name="foo.trashinfo"
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/foo.trashinfo: Open: flags=O_RDONLY|O_CREATE|O_EXCL
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/foo.trashinfo: >Open: fd=<nil *ReadFileHandle>, err=can't open file - writer failed
2022/11/22 21:51:25 ERROR : IO error: can't open file - writer failed
2022/11/22 21:51:25 DEBUG : .Trash-1000/info/: >Create: node=<nil>, handle=<nil>, err=can't open file - writer failed
2022/11/22 21:51:25 DEBUG : fuse: -> [ID=0x406] Create error=EIO: can't open file - writer failed

ncw · November 22, 2022, 10:10pm

That's an odd set of flags for an open call. Read only + create?

I wonder if rclone has misinterpreted the flags.

Or if rclone is implementing them wrong.

Ideally I'd ask you to strace the app that did that open to check. Is that possible?

chtk · November 22, 2022, 10:42pm

I think I've seen that response in some other places to people with similar questions/issues. I'll see if I can find those links tomorrow.

That's absolutely possible. I can do that. Tomorrow though, it's getting a bit late here.

chtk · November 23, 2022, 7:35am

This is the strace log for gio trash tmp/foo/: dpaste: stdin

This is a possibly related topic on this forum. Rclone mount and rtorrent issue

Another topic with a comment showing the same open flags: Chrome os crostini mount help - #14 by beesho85

ncw · November 23, 2022, 6:40pm

Thanks for the strace.

Here is the relevant part

openat(AT_FDCWD, "/home/stefan/mnt/tmp/.Trash-1000/info/foo.trashinfo", O_RDONLY|O_CREAT|O_EXCL, 0666) = -1 EIO (Input/output error)

Which shows that the app is indeed using O_RDONLY|O_CREAT|O_EXCL

Now rclone has a very comprehensive test suite for these, and this is what rclone does from the test suite. These tests were validated against an ext4 file system.

		flags:               os.O_RDONLY | os.O_CREATE | os.O_EXCL,
		what:                "os.O_RDONLY|os.O_CREATE|os.O_EXCL",
		openNonExistentErr:  nil,
		readNonExistentErr:  io.EOF,
		writeNonExistentErr: EBADF,
		openExistingErr:     EEXIST,
		readExistingErr:     nil,
		writeExistingErr:    nil,
		contents:            "hello",

The EIO is coming from this code

github.com

rclone/rclone/blob/430bf0d5eb65d948142f3bee41e20e2776372fcb/vfs/file.go#L501


      
          func (f *File) waitForValidObject() (o fs.Object, err error) {
          	for i := 0; i < 50; i++ {
          		f.mu.RLock()
          		o = f.o
          		nwriters := len(f.writers)
          		f.mu.RUnlock()
          		if o != nil {
          			return o, nil
          		}
          		if nwriters == 0 {
          			return nil, errors.New("can't open file - writer failed")
          		}
          		time.Sleep(100 * time.Millisecond)
          	}
          	return nil, ENOENT
          }
          
          
// openRead open the file for read
          func (f *File) openRead() (fh *ReadFileHandle, err error) {
          	// if o is nil it isn't valid yet
          	_, err = f.waitForValidObject()

Which means that rclone failed to find an object to open for reading, but the object might well not have existed as it would have been created with those flags as the openNonExistentErr: nil says. So it looks like there is a logic error in rclone somewhere.

Will investigate further...

ncw · November 24, 2022, 10:45am

I managed replicate this easily enough.

It replicates with

--vfs-cache-mode off
--vfs-cache mode writes

but not with

--vfs-cache-mode full

I would expect it to work with --vfs-cache-mode writes too, so that's a bug.

Whether it works with --vfs-cache-mode off is a different matter. In that mode we can't read and write files and opening O_RDONLY|O_CREAT|O_EXCL is kind of ambigous as if the file doesn't exist we will create it, but we have got read only on it.

Luckily there is a simple fix which seems to work for all 3 --vfs-cache-modes

Can you give this a go?

v1.61.0-beta.6576.cbb063fdb.fix-vfs-rdonly-create on branch fix-vfs-rdonly-create (uploaded in 15-30 mins)

I conjecture it might still fail for you in --vfs-cache-mode off mode, but in a different way as gio can't delete its lock file. It should work with --vfs-cache-mode writes though.

chtk · November 24, 2022, 5:01pm

Yeah, this seems to have fixed the issue.

Thanks for the fast response!

ncw · November 24, 2022, 5:05pm

Great. That bug has been lurking for a long time - great to fix it!

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.61. If I make a v1.60.2 I'll put it in that too.

system · November 27, 2022, 5:05pm

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