From owner-freebsd-bugs@freebsd.org Wed Feb 26 12:02:44 2020 Return-Path: Delivered-To: freebsd-bugs@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 2E7AD25661D for ; Wed, 26 Feb 2020 12:02:44 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from mailman.nyi.freebsd.org (mailman.nyi.freebsd.org [IPv6:2610:1c1:1:606c::50:13]) by mx1.freebsd.org (Postfix) with ESMTP id 48SDvS0L6nz4P80 for ; Wed, 26 Feb 2020 12:02:44 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: by mailman.nyi.freebsd.org (Postfix) id 0B46525661C; Wed, 26 Feb 2020 12:02:44 +0000 (UTC) Delivered-To: bugs@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 0AD6F25661B for ; Wed, 26 Feb 2020 12:02:44 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from mxrelay.nyi.freebsd.org (mxrelay.nyi.freebsd.org [IPv6:2610:1c1:1:606c::19:3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) server-signature RSA-PSS (4096 bits) client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "Let's Encrypt Authority X3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 48SDvR6XNCz4P7v for ; Wed, 26 Feb 2020 12:02:43 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from kenobi.freebsd.org (kenobi.freebsd.org [IPv6:2610:1c1:1:606c::50:1d]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) server-signature RSA-PSS (4096 bits)) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id DA3662710D for ; Wed, 26 Feb 2020 12:02:43 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from kenobi.freebsd.org ([127.0.1.5]) by kenobi.freebsd.org (8.15.2/8.15.2) with ESMTP id 01QC2hT9059290 for ; Wed, 26 Feb 2020 12:02:43 GMT (envelope-from bugzilla-noreply@freebsd.org) Received: (from www@localhost) by kenobi.freebsd.org (8.15.2/8.15.2/Submit) id 01QC2hHV059289 for bugs@FreeBSD.org; Wed, 26 Feb 2020 12:02:43 GMT (envelope-from bugzilla-noreply@freebsd.org) X-Authentication-Warning: kenobi.freebsd.org: www set sender to bugzilla-noreply@freebsd.org using -f From: bugzilla-noreply@freebsd.org To: bugs@FreeBSD.org Subject: [Bug 244431] Incorrect file handle in fsync on FUSE-based filesystem. Date: Wed, 26 Feb 2020 12:02:43 +0000 X-Bugzilla-Reason: AssignedTo X-Bugzilla-Type: new X-Bugzilla-Watch-Reason: None X-Bugzilla-Product: Base System X-Bugzilla-Component: kern X-Bugzilla-Version: 12.1-STABLE X-Bugzilla-Keywords: X-Bugzilla-Severity: Affects Some People X-Bugzilla-Who: chogata@gmail.com X-Bugzilla-Status: New X-Bugzilla-Resolution: X-Bugzilla-Priority: --- X-Bugzilla-Assigned-To: bugs@FreeBSD.org X-Bugzilla-Flags: X-Bugzilla-Changed-Fields: bug_id short_desc product version rep_platform op_sys bug_status bug_severity priority component assigned_to reporter Message-ID: Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: https://bugs.freebsd.org/bugzilla/ Auto-Submitted: auto-generated MIME-Version: 1.0 X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 26 Feb 2020 12:02:44 -0000 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,0666) 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,0x1002,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.=