Date: Wed, 26 Feb 2020 12:02:43 +0000 From: bugzilla-noreply@freebsd.org To: bugs@FreeBSD.org Subject: [Bug 244431] Incorrect file handle in fsync on FUSE-based filesystem. Message-ID: <bug-244431-227@https.bugs.freebsd.org/bugzilla/>
index | next in thread | raw e-mail
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@FreeBSD.org Reporter: chogata@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.help
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?bug-244431-227>