[Bug 244431] Incorrect file handle in fsync on FUSE-based filesystem.
bugzilla-noreply at freebsd.org
bugzilla-noreply at freebsd.org
Wed Feb 26 12:02:44 UTC 2020
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=244431
Bug ID: 244431
Summary: Incorrect file handle in fsync on FUSE-based
filesystem.
Product: Base System
Version: 12.1-STABLE
Hardware: amd64
OS: Any
Status: New
Severity: Affects Some People
Priority: ---
Component: kern
Assignee: bugs at FreeBSD.org
Reporter: chogata at gmail.com
OS version: FreeBSD 12.1-p2
Installed: /usr/ports/sysutils/fusefs-libs3/,
/usr/ports/sysutils/moosefs3-client/ (and dependencies). Port tree is upgraded,
so newest versions are installed (MooseFS is in version 3.0.111).
On mounted MooseFS share I opened a file with vi (shipped with system, NOT
vim!), added something to it (anything, even 1 character), then I closed it
with :wq and I got this error:
Error: /mnt/mfs/jakisplik: Bad file descriptor; /mnt/mfs/jakisplik: WARNING:
FILE TRUNCATED.
I then closed it with :q!, opened it again and the characters I added were
there, nothing got truncated, changes got written. But the message was
annoying, so I debugged:
This is trace from vi:
77244 vi CALL fstatat(AT_FDCWD,0x8007991c0,0x7fffffffc180,0)
77244 vi NAMI "/mnt/mfs_f3/jakisplik"
77244 vi STRU struct stat {dev=18446744073390849796, ino=152281,
mode=0100644, nlink=1, uid=0, gid=0, rdev=0, atime=1582713427,
mtime=1582713243, ctime=1582713243, birthtime=-1.-00000001, size=100,
blksize=65536, blocks=1, flags=0x0 }
77244 vi RET fstatat 0
77244 vi CALL
openat(AT_FDCWD,0x8007991c0,0x601<O_WRONLY|O_CREAT|O_TRUNC>,0666<S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH>)
77244 vi NAMI "/mnt/mfs_f3/jakisplik"
77244 vi RET openat 10/0xa
77244 vi CALL fcntl(0xa,F_GETFL)
77244 vi RET fcntl 1
77244 vi CALL fstat(0xa,0x7fffffffbd20)
77244 vi STRU struct stat {dev=18446744073390849796, ino=152281,
mode=0100644, nlink=1, uid=0, gid=0, rdev=0, atime=1582713427,
mtime=1582713433, ctime=1582713433, birthtime=-1.-00000001, size=0,
blksize=65536, blocks=0, flags=0x0 }
77244 vi RET fstat 0
77244 vi CALL
mmap(0,0x11000,0x3<PROT_READ|PROT_WRITE>,0x1002<MAP_PRIVATE|MAP_ANON>,0xffffffff,0)
77244 vi RET mmap 34377715712/0x801125000
77244 vi CALL write(0xa,0x801125680,0x5b)
77244 vi GIO fd 10 wrote 91 bytes
"sdlkjgldfskjglksdfjg
dsf;gjsdf;gjsdlkfg
dsgsdkjglsdfkjgsdflkg
dfklgjsdlgjsdf
34535345
1
"
77244 vi RET write 91/0x5b
77244 vi CALL fstat(0xa,0x7fffffffbfa0)
77244 vi STRU struct stat {dev=18446744073390849796, ino=152281,
mode=0100644, nlink=1, uid=0, gid=0, rdev=0, atime=1582713427,
mtime=1582713433, ctime=1582713433, birthtime=-1.-00000001, size=91,
blksize=65536, blocks=0, flags=0x0 }
77244 vi RET fstat 0
77244 vi CALL fsync(0xa)
77244 vi RET fsync -1 errno 9 Bad file descriptor
77244 vi CALL fstatat(AT_FDCWD,0x7fffffffb800,0x7fffffffbc00,0)
77244 vi NAMI "/usr/share/nls/C/libc.cat"
77244 vi RET fstatat -1 errno 2 No such file or directory
77244 vi CALL fstatat(AT_FDCWD,0x7fffffffb800,0x7fffffffbc00,0)
77244 vi NAMI "/usr/share/nls/libc/C"
77244 vi RET fstatat -1 errno 2 No such file or directory
77244 vi CALL fstatat(AT_FDCWD,0x7fffffffb800,0x7fffffffbc00,0)
77244 vi NAMI "/usr/local/share/nls/C/libc.cat"
77244 vi RET fstatat -1 errno 2 No such file or directory
77244 vi CALL fstatat(AT_FDCWD,0x7fffffffb800,0x7fffffffbc00,0)
77244 vi NAMI "/usr/local/share/nls/libc/C"
77244 vi RET fstatat -1 errno 2 No such file or directory
77244 vi CALL sigaction(SIGTSTP,0x80032c618,0x80032c638)
77244 vi RET sigaction 0
And this is operation log from MooseFS:
02.26 11:21:49.525090: uid:0 gid:0 pid:77159 cmd:getattr (1): OK
(1.0,[drwxrwxrwx:0040777,22,0,0,1582712303,1582712269,1582712269,3085103])
02.26 11:22:01.594382: uid:0 gid:0 pid:70840 cmd:getattr (1): OK
(1.0,[drwxrwxrwx:0040777,22,0,0,1582712303,1582712269,1582712269,3085103])
02.26 11:22:02.634610: uid:0 gid:0 pid:70840 cmd:access (1,0x4): OK
02.26 11:22:02.635052: uid:0 gid:0 pid:70840 cmd:opendir (1): OK
[handle:00000001]
02.26 11:22:02.635365: uid:0 gid:0 pid:70840 cmd:statfs (1): OK
(17739638960128,16586417303552,16586417303552,4175528346,0,20406533)
02.26 11:22:02.635857: uid:0 gid:0 pid:70840 cmd:readdir (1,4096,1373): OK
(1008)
02.26 11:22:02.635947: uid:0 gid:0 pid:70840 cmd:readdir (1,4096,1373): OK (no
data)
02.26 11:22:02.636295: uid:0 gid:0 pid:70840 cmd:access (1,0x1): OK
02.26 11:22:02.636394: uid:0 gid:0 pid:70840 cmd:lookup (1,jakisplik) (using
open dir cache): OK
(0.0,152281,1.0,[-rw-r--r--:0100644,1,0,0,1582712269,1582712290,1582712290,96])
02.26 11:22:05.875419: uid:0 gid:0 pid:77175 cmd:access (1,0x1): OK
02.26 11:22:05.875878: uid:0 gid:0 pid:77175 cmd:lookup (1,jakisplik): OK
(0.0,152281,1.0,[-rw-r--r--:0100644,1,0,0,1582712269,1582712290,1582712290,96])
02.26 11:22:05.876326: uid:0 gid:0 pid:77175 cmd:access (1,0x1): OK
02.26 11:22:05.876734: uid:0 gid:0 pid:77175 cmd:lookup (1,jakisplik): OK
(0.0,152281,1.0,[-rw-r--r--:0100644,1,0,0,1582712269,1582712290,1582712290,96])
02.26 11:22:05.876811: uid:0 gid:0 pid:77175 cmd:access (152281,0x4): OK
02.26 11:22:05.876975: uid:0 gid:0 pid:77175 cmd:open (152281) (using cached
data from lookup): OK (direct_io:0,keep_cache:0) [handle:01000001]
02.26 11:22:05.879620: uid:0 gid:0 pid:77175 cmd:read (152281,96,0): OK (96)
02.26 11:22:05.880246: uid:0 gid:0 pid:77175 cmd:access (1,0x1): OK
02.26 11:22:05.880646: uid:0 gid:0 pid:77175 cmd:lookup (1,jakisplik): OK
(0.0,152281,1.0,[-rw-r--r--:0100644,1,0,0,1582712526,1582712290,1582712290,96])
02.26 11:22:05.880731: uid:0 gid:0 pid:77175 cmd:access (152281,0x2): OK
02.26 11:22:09.611350: uid:0 gid:0 pid:77175 cmd:access (1,0x1): OK
02.26 11:22:09.611732: uid:0 gid:0 pid:77175 cmd:lookup (1,jakisplik): OK
(0.0,152281,1.0,[-rw-r--r--:0100644,1,0,0,1582712526,1582712290,1582712290,96])
02.26 11:22:09.612169: uid:0 gid:0 pid:77175 cmd:access (1,0x1): OK
02.26 11:22:09.612504: uid:0 gid:0 pid:77175 cmd:lookup (1,jakisplik): OK
(0.0,152281,1.0,[-rw-r--r--:0100644,1,0,0,1582712526,1582712290,1582712290,96])
02.26 11:22:09.612581: uid:0 gid:0 pid:77175 cmd:access (152281,0x2): OK
02.26 11:22:09.612686: uid:0 gid:0 pid:77175 cmd:open (152281) (using cached
data from lookup): OK (direct_io:0,keep_cache:0) [handle:01000002]
02.26 11:22:09.613255: uid:0 gid:0 pid:77175 cmd:setattr (152281,0x8,[size=0]):
OK (1.0,[-rw-r--r--:0100644,1,0,0,1582712526,1582712529,1582712529,0])
02.26 11:22:09.613444: uid:0 gid:0 pid:77175 cmd:write (152281,89,0): OK (89)
02.26 11:22:09.615475: uid:0 gid:0 pid:77175 cmd:fsync (152281,0)
[handle:01000002]: OK
02.26 11:22:09.615538: uid:0 gid:0 pid:77175 cmd:fsync (152281,0)
[handle:00000008]: EBADF (Bad file descriptor)
02.26 11:22:09.615686: uid:0 gid:0 pid:77175 cmd:flush (152281)
[handle:01000002,uselocks:0,lock_owner:0000000000012D77]: OK
02.26 11:22:09.616051: uid:0 gid:0 pid:77175 cmd:access (1,0x1): OK
02.26 11:22:09.616482: uid:0 gid:0 pid:77175 cmd:lookup (1,jakisplik): OK
(0.0,152281,1.0,[-rw-r--r--:0100644,1,0,0,1582712526,1582712529,1582712529,89])
02.26 11:22:12.002663: uid:0 gid:0 pid:77175 cmd:release (152281)
[handle:01000002,uselocks:0,lock_owner:0000000000012D77]: OK
02.26 11:22:12.002758: uid:0 gid:0 pid:77175 cmd:release (152281)
[handle:01000001,uselocks:0,lock_owner:0000000000012D77]: OK
02.26 11:22:15.050756: uid:0 gid:0 pid:70840 cmd:getattr (1) (using open dir
cache): OK
(1.0,[drwxrwxrwx:0040777,22,0,0,1582712522,1582712269,1582712269,3085103])
So, you can see that after a succesful write, there is an fsync that returns an
error:
77244 vi RET write 91/0x5b
77244 vi CALL fstat(0xa,0x7fffffffbfa0)
77244 vi STRU struct stat {dev=18446744073390849796, ino=152281,
mode=0100644, nlink=1, uid=0, gid=0, rdev=0, atime=1582713427,
mtime=1582713433, ctime=1582713433, birthtime=-1.-00000001, size=91,
blksize=65536, blocks=0, flags=0x0 }
77244 vi RET fstat 0
77244 vi CALL fsync(0xa)
77244 vi RET fsync -1 errno 9 Bad file descriptor
But, *one* fsync from vi generates *two* fsyncs sent to the filesystem, and the
second one is with a completely wrong handle, because "00000008" was never
returned from any open operation.
02.26 11:22:09.613444: uid:0 gid:0 pid:77175 cmd:write (152281,89,0): OK (89)
02.26 11:22:09.615475: uid:0 gid:0 pid:77175 cmd:fsync (152281,0)
[handle:01000002]: OK
02.26 11:22:09.615538: uid:0 gid:0 pid:77175 cmd:fsync (152281,0)
[handle:00000008]: EBADF (Bad file descriptor)
I repeated the whole vi operation several times, and a curious thing: it's not
always "00000008", but it's that value most of the time. I once got "00000001"
and once or twice "00000004", but all the other tries (10+) yielded "00000008".
Vi used on a local filesystem (ufs) doesn't write any weird messages when
saving an edited file with ":wq", so it's clearly a FUSE-related problem.
--
You are receiving this mail because:
You are the assignee for the bug.
More information about the freebsd-bugs
mailing list