Rclone mount VFS cache doesn't appear to handle dup() calls gracefully

SmashedSqwurl · July 28, 2019, 12:08am

What is the problem you are having with rclone?

I'm trying to use bup to backup to a mounted rclone crypt backend.

When it tries to write midx or bloom files, I get the following error:

Traceback (most recent call last):    
  File "/usr/lib/bup/cmd/bup-midx", line 272, in <module>
    do_midx_dir(path, opt.output)
  File "/usr/lib/bup/cmd/bup-midx", line 213, in do_midx_dir
    all = list(do_midx_group(path, outfilename, part1)) + part2
  File "/usr/lib/bup/cmd/bup-midx", line 230, in do_midx_group
    rv = _do_midx(outdir, outfilename, sublist, gprefix)
  File "/usr/lib/bup/cmd/bup-midx", line 135, in _do_midx
    f.write('\0'.join(allfilenames))
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/usr/lib/bup/bup/helpers.py", line 723, in atomically_replaced_file
    f.close()
IOError: [Errno 9] Bad file descriptor

I think the source of this error is that bup opens up the midx file for writing, getting file handle 3 (see strace log below). It then mmap's that file, which ends up doing a dup() syscall under the hood, giving us a second file handle 17. When it's finished with the mmap'ed file handle, it calls close() on it. Rclone sees the close() call for 17, but doesn't account for the fact that file handle 3 is still open. It uploads the file and deletes the local copy, invalidating the file handle 3 without bup knowing what has happened.

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

1.48.0

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

Arch Linux 64 bit

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

Box

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

rclone mount box_crypt: /mnt/box_enc --config /etc/box-webdav/rclone.conf \
--use-mmap --transfers 256 --checkers 512 --checksum --fast-list --rc \
--vfs-cache-mode full --cache-dir /var/cache/rclone --vfs-cache-max-size 64G \
--log-file /var/log/rclone.log --log-level DEBUG

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

2019/07/27 18:36:20 DEBUG : objects/pack/: Lookup: name="tmpagv5oD"
2019/07/27 18:36:20 DEBUG : objects/pack/: Create: name="tmpagv5oD"
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: Open: flags=O_RDWR|O_CREATE|O_EXCL|0x20000
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD(0xc0039e11a0): Opening cached copy with flags=O_RDWR|O_CREATE|O_EXCL|0x20000
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: >Open: fd=objects/pack/tmpagv5oD (rw), err=<nil>
2019/07/27 18:36:20 DEBUG : objects/pack/: >Create: node=objects/pack/tmpagv5oD, handle=&{objects/pack/tmpagv5oD (rw)}, err=<nil>
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: Attr:
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2019/07/27 18:36:20 DEBUG : &{objects/pack/tmpagv5oD (rw)}: Write: len=12, offset=0
2019/07/27 18:36:20 DEBUG : &{objects/pack/tmpagv5oD (rw)}: >Write: written=12, err=<nil>
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: Setattr: a=Setattr [ID=0x607c2 Node=0xa5 Uid=0 Gid=0 Pid=15572] size=39516740 handle=0x5 lockowner
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: >Setattr: err=<nil>
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: Attr:
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: >Attr: a=valid=1s ino=0 size=39516740 mode=-rw-r--r--, err=<nil>
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: Fsync:
2019/07/27 18:36:20 DEBUG : objects/pack/tmpagv5oD: >Fsync: err=<nil>
2019/07/27 18:36:20 DEBUG : &{objects/pack/tmpagv5oD (rw)}: Read: len=131072, offset=0
2019/07/27 18:36:20 DEBUG : &{objects/pack/tmpagv5oD (rw)}: >Read: read=131072, err=<nil>
...snip...
2019/07/27 18:36:21 DEBUG : &{objects/pack/tmpagv5oD (rw)}: Write: len=131072, offset=0
2019/07/27 18:36:21 DEBUG : &{objects/pack/tmpagv5oD (rw)}: >Write: written=131072, err=<nil>
...snip...
2019/07/27 18:36:21 DEBUG : &{objects/pack/tmpagv5oD (rw)}: Flush:
2019/07/27 18:36:21 DEBUG : objects/pack/tmpagv5oD(0xc0039e11a0): close:
2019/07/27 18:36:21 DEBUG : objects/pack/tmpagv5oD: Couldn't find file - need to transfer
2019/07/27 18:36:23 DEBUG : objects/pack/tmpagv5oD: updateTime: setting atime to 2019-07-27 18:36:22.991529142 -0500 CDT
2019/07/27 18:36:25 INFO  : objects/pack/tmpagv5oD: Copied (new)
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD: transferred to remote
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD(0xc0039e11a0): >close: err=<nil>
2019/07/27 18:36:25 DEBUG : &{objects/pack/tmpagv5oD (rw)}: >Flush: err=<nil>
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD: Fsync:
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD: >Fsync: err=<nil>
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD: Attr:
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD: >Attr: a=valid=1s ino=0 size=39516740 mode=-rw-r--r--, err=<nil>
2019/07/27 18:36:25 DEBUG : &{objects/pack/tmpagv5oD (rw)}: Write: len=549, offset=39516740
2019/07/27 18:36:25 DEBUG : &{objects/pack/tmpagv5oD (rw)}: >Write: written=0, err=bad file descriptor
2019/07/27 18:36:25 DEBUG : &{objects/pack/tmpagv5oD (rw)}: Flush:
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD(0xc0039e11a0): RWFileHandle.Flush nothing to do
2019/07/27 18:36:25 DEBUG : &{objects/pack/tmpagv5oD (rw)}: >Flush: err=<nil>
2019/07/27 18:36:25 DEBUG : &{objects/pack/tmpagv5oD (rw)}: Release:
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD(0xc0039e11a0): RWFileHandle.Release nothing to do
2019/07/27 18:36:25 DEBUG : &{objects/pack/tmpagv5oD (rw)}: >Release: err=<nil>
2019/07/27 18:36:25 DEBUG : objects/pack/: Lookup: name="tmpagv5oD"
2019/07/27 18:36:25 DEBUG : objects/pack/: >Lookup: node=objects/pack/tmpagv5oD, err=<nil>
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD: Attr:
2019/07/27 18:36:25 DEBUG : objects/pack/tmpagv5oD: >Attr: a=valid=1s ino=0 size=39516740 mode=-rw-r--r--, err=<nil>
2019/07/27 18:36:25 DEBUG : objects/pack/: Remove: name="tmpagv5oD"
2019/07/27 18:36:26 INFO  : objects/pack/tmpagv5oD: Removed from cache

strace log

openat(AT_FDCWD, "/mnt/box_enc/objects/pack/tmpagv5oD", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW, 0600) = 3
fcntl(3, F_GETFD)                       = 0
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
fcntl(3, F_GETFL)                       = 0x28002 (flags O_RDWR|O_LARGEFILE|O_NOFOLLOW)
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
lseek(3, 0, SEEK_CUR)                   = 0
lseek(3, 0, SEEK_CUR)                   = 0
write(3, "MIDX\0\0\0\4\0\0\0\r", 12)    = 12
ftruncate(3, 39516740)                  = 0
lseek(3, 12, SEEK_SET)                  = 12
fdatasync(3)                            = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=39516740, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=39516740, ...}) = 0
dup(3)                                  = 17
mmap(NULL, 39516740, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7fc0dda36000
write(2, "midx: writing 0.00% (0/1645165)\r", 32) = 32
...snip...
write(2, "midx: writing 99.61% (1638784/16"..., 39) = 39
close(17)                               = 0
msync(0x7fc0dda36000, 39516740, MS_SYNC) = 0
munmap(0x7fc0dda36000, 39516740)        = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=39516740, ...}) = 0
lseek(3, 39516740, SEEK_SET)            = 39516740
write(3, "pack-54b98568f664f25c55f780c7daa"..., 549) = -1 EBADF (Bad file descriptor)
close(3)                                = 0
unlink("/mnt/box_enc/objects/pack/tmpagv5oD") = 0

SmashedSqwurl · July 28, 2019, 12:43am

Here's a Python 2 script that will reproduce the error:

import os
import mmap

RCLONE_DIR = '/mnt/box_enc/'
TESTFILE = 'test'
RCLONE_TESTFILE = os.path.join(RCLONE_DIR, TESTFILE)

def run_test(filename):
    print 'Writing to ' + filename
    test_data = '0123456789'
    with open(filename, 'wb+') as f:
        f.truncate(len(test_data) + 2)
        f.flush()
        os.fdatasync(f.fileno())
        st = os.fstat(f.fileno())
        sz = st.st_size
        mm = mmap.mmap(f.fileno(), sz, mmap.MAP_SHARED, mmap.PROT_READ | mmap.PROT_WRITE)
        mm.write(test_data)
        del mm
        f.seek(len(test_data))
        f.write('10')

print 'Testing local directory...'
run_test(TESTFILE) # Succeeds

print 'Testing rclone directory...'
run_test(RCLONE_TESTFILE) # Fails

ncw · July 28, 2019, 9:11am

This seems likely... It is quite difficult to tell from the FUSE interface whether a file handle is still in use. The dup() doesn't get passed to rclone...

If you take a look at the FUSE FAQ you'll see what I mean: https://github.com/libfuse/libfuse/wiki/FAQ#user-content-which-method-is-called-on-the-close-system-call

rclone tries to close the file in flush if at all possible then it can return errors to the user. If the file handle hasn't been written to then it does nothing in flush. This covers 90% of the uses of dup() which generally only write things from one process.

The strace above shows that the first process with FH 3 writes to the file and presumably the one with FH17 does too (though that isn't in the strace since the file is mmaped). This means that when FH 17 is flushed, rclone will say - has this been written - yes, lets write it properly.

So when the process closes FH 3 it has already been closed and hence the error.

However the correct thing to do would be only to close the file in release - there is no possibility of returning errors at that point though, and I'm of the view that if your file didn't get uploaded to cloud storage that is kind of important and you'd like to know about it!

One way around this would be to use an upload queue to retry the uploads if they fail. I've added a note to the upload queue issue to that effect.

Perhaps the right solution is

In flush
- if fh for cache file not open, return
- close cache fh
- if no writes since last flush, return
- sync file to cloud storage
- return but do not close the FUSE fh
In release
- run the flush code just in case (it should do nothing)
- close the FUSE fh - the file has already been synced here so no significant errors to return

That should minimise the file being written twice in flush.

Here is the flush code - the release code is just below if you want to see for yourself what is happening.

Thank you for the repro script - very useful. It looks like from that the mmap is doing a dup() internally. Can you repro the problem using dup() instead of mmap?

Either way, if you can transfer your excellent bug report into a new issue on github that would be much appreciated. (If you click edit on the forum post you can cut and paste the markdown straight into github).

SmashedSqwurl · July 28, 2019, 5:28pm

I opened an issue and included a second version of the script that just does a dup() call without mmap.

Animosity022 · July 28, 2019, 5:53pm

That's possibly the best bug report I've ever seen

SmashedSqwurl · July 28, 2019, 6:35pm

Ha, thanks. I write code for a living so I try to be as thorough as possible.

system · October 26, 2019, 6:39pm

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