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/>
next in thread | raw e-mail | index | archive | help
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D244431 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 upgra= ded, 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=3D18446744073390849796, ino=3D152281, mode=3D0100644, nlink=3D1, uid=3D0, gid=3D0, rdev=3D0, atime=3D1582713427, mtime=3D1582713243, ctime=3D1582713243, birthtime=3D-1.-00000001, size=3D10= 0, blksize=3D65536, blocks=3D1, flags=3D0x0 } 77244 vi RET fstatat 0 77244 vi CALL=20 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=3D18446744073390849796, ino=3D152281, mode=3D0100644, nlink=3D1, uid=3D0, gid=3D0, rdev=3D0, atime=3D1582713427, mtime=3D1582713433, ctime=3D1582713433, birthtime=3D-1.-00000001, size=3D0, blksize=3D65536, blocks=3D0, flags=3D0x0 } 77244 vi RET fstat 0 77244 vi CALL=20 mmap(0,0x11000,0x3<PROT_READ|PROT_WRITE>,0x1002<MAP_PRIVATE|MAP_ANON>,0xfff= fffff,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=3D18446744073390849796, ino=3D152281, mode=3D0100644, nlink=3D1, uid=3D0, gid=3D0, rdev=3D0, atime=3D1582713427, mtime=3D1582713433, ctime=3D1582713433, birthtime=3D-1.-00000001, size=3D91, blksize=3D65536, blocks=3D0, flags=3D0x0 } 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= =3D0]): 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 (8= 9) 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 return= s an error: 77244 vi RET write 91/0x5b 77244 vi CALL fstat(0xa,0x7fffffffbfa0) 77244 vi STRU struct stat {dev=3D18446744073390849796, ino=3D152281, mode=3D0100644, nlink=3D1, uid=3D0, gid=3D0, rdev=3D0, atime=3D1582713427, mtime=3D1582713433, ctime=3D1582713433, birthtime=3D-1.-00000001, size=3D91, blksize=3D65536, blocks=3D0, flags=3D0x0 } 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 (8= 9) 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 "000000= 01" and once or twice "00000004", but all the other tries (10+) yielded "000000= 08". 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. --=20 You are receiving this mail because: You are the assignee for the bug.=
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?bug-244431-227>