From nobody Wed May 19 17:30:48 2021 X-Original-To: bugs@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id DC16B8B400A for ; Wed, 19 May 2021 17:30:48 +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) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "R3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4FlfzD3VB0z4YRp for ; Wed, 19 May 2021 17:30:48 +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) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id 60FF316E04 for ; Wed, 19 May 2021 17:30:48 +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 14JHUmlt060010 for ; Wed, 19 May 2021 17:30:48 GMT (envelope-from bugzilla-noreply@freebsd.org) Received: (from www@localhost) by kenobi.freebsd.org (8.15.2/8.15.2/Submit) id 14JHUmqH060009 for bugs@FreeBSD.org; Wed, 19 May 2021 17:30:48 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 256005] [FUSEFS] Subsequent posix lock operation fails when it should not. Date: Wed, 19 May 2021 17:30:48 +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: CURRENT X-Bugzilla-Keywords: X-Bugzilla-Severity: Affects Some People X-Bugzilla-Who: chogata@moosefs.pro 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 List-Id: Bug reports List-Archive: http://lists.freebsd.org/bugs List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-bugs@freebsd.org MIME-Version: 1.0 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D256005 Bug ID: 256005 Summary: [FUSEFS] Subsequent posix lock operation fails when it should not. Product: Base System Version: CURRENT Hardware: Any OS: Any Status: New Severity: Affects Some People Priority: --- Component: kern Assignee: bugs@FreeBSD.org Reporter: chogata@moosefs.pro Hi, At MooseFS test lab we run some tests to see if issues mentioned in bug #25= 5945 and bug #253500 were solved in 14-CURRENT and we encountered another issue = with posix locks handled via FUSEFS. I executed this simple script: --------- #!/usr/bin/env python import posix import time fd =3D posix.open("lock.file",posix.O_WRONLY|posix.O_CREAT,0o666) print(fd) print(posix.lockf(fd,posix.F_LOCK,0)) time.sleep(2) print(posix.lockf(fd,posix.F_TLOCK,0)) time.sleep(2) print(posix.lockf(fd,posix.F_ULOCK,0)) --------- When this is run on a local filesystem, the output is as expected, that is: --------- 3 None None None --------- However, when I run it on MooseFS, I get: --------- 3 None Traceback (most recent call last): File "/mnt/mfs/f13/test.py", line 14, in print(posix.lockf(fd,posix.F_TLOCK,0)) BlockingIOError: [Errno 35] Resource temporarily unavailable --------- and that is not correct, because a process, that owns a posix lock on a fil= e, is supposed to be able to lock this file again. So I checked the operation history and this is what I got (I cut out everyt= hing that happened before the open/create operation of file "lock.file" as it is= not relevant): --------- 05.19 16:38:13.441623: uid:0 gid:0 pid:766 cmd:lookup (1,lock.file): ENOENT= (No such file or directory) 05.19 16:38:13.442336: uid:0 gid:0 pid:766 cmd:create (1,lock.file,O_RDWR|O_CREAT,-rw-r--r--:0100644): OK (0.0,233781,1.0,[-rw-r--r--:0100644,1,0,0,1621442293,1621442293,1621442293,= 0]) (direct_io:0,keep_cache:0,append_mode:0) [handle:01000004] 05.19 16:38:13.443110: uid:0 gid:0 pid:766 cmd:setlkw (inode:233781 owner:0000000000018723 start:0 end:18446744073709551615 type:W) [handle:01000004]: OK 05.19 16:38:15.449501: uid:0 gid:0 pid:766 cmd:setlk (inode:233781 owner:0000000000E3D000 start:0 end:18446744073709551615 type:W) [handle:01000004]: EAGAIN (Resource temporarily unavailable) 05.19 16:38:15.450339: uid:0 gid:0 pid:766 cmd:access (1,0x1): OK 05.19 16:38:15.451038: uid:0 gid:0 pid:766 cmd:lookup (1,f13): OK (1.0,8243,1.0,[drwxr-xr-x:0040755,2,0,0,1621442079,1621442071,1621442071,10= 01824]) 05.19 16:38:15.451110: uid:0 gid:0 pid:766 cmd:access (8243,0x1): OK 05.19 16:38:15.451743: uid:0 gid:0 pid:766 cmd:lookup (8243,test.py): OK (0.0,233775,1.0,[-rwxr-xr-x:0100755,1,0,0,1621442269,1621442071,1621442071,= 559]) 05.19 16:38:15.451801: uid:0 gid:0 pid:766 cmd:access (233775,0x4): OK (for= ced - kernel bug workaround) 05.19 16:38:15.451868: uid:0 gid:0 pid:766 cmd:open (233775,O_RDONLY) (using cached data from lookup): OK (direct_io:0,keep_cache:1,append_mode:0) [handle:01000005] 05.19 16:38:15.452915: uid:0 gid:0 pid:766 cmd:setlk (inode:233775 owner:FFFFFFFF8EB01020 start:0 end:18446744073709551615 type:U) [handle:01000005]: OK 05.19 16:38:15.453583: uid:0 gid:0 pid:766 cmd:setlk (inode:233775 owner:FFFFFFFF8EB01020 start:0 end:18446744073709551615 type:U) [handle:01000005]: OK 05.19 16:38:15.454143: uid:0 gid:0 pid:766 cmd:flush (233775) - releasing a= ll POSIX-type locks for 00000000000002FE (received from kernel): OK 05.19 16:38:15.454151: uid:0 gid:0 pid:766 cmd:flush (233775) [handle:01000005,uselocks:2,lock_owner:00000000000002FE]: OK 05.19 16:38:15.454204: uid:0 gid:0 pid:766 cmd:release (233775) [handle:01000005,uselocks:2,lock_owner:00000000000002FE]: OK 05.19 16:38:15.456512: uid:0 gid:0 pid:766 cmd:setlk (inode:233781 owner:FFFFFFFFCDEFB9F0 start:0 end:18446744073709551615 type:U) [handle:01000004]: OK 05.19 16:38:15.457012: uid:0 gid:0 pid:766 cmd:flush (233781) - releasing a= ll POSIX-type locks for 00000000000002FE (received from kernel): OK 05.19 16:38:15.457022: uid:0 gid:0 pid:766 cmd:flush (233781) [handle:01000004,uselocks:2,lock_owner:00000000000002FE]: OK 05.19 16:38:15.457478: uid:0 gid:0 pid:766 cmd:release (233781) - releasing= all POSIX-type locks for 0000000000E3D000 (left by kernel): OK 05.19 16:38:15.457850: uid:0 gid:0 pid:766 cmd:release (233781) - releasing= all POSIX-type locks for 0000000000018723 (left by kernel): OK 05.19 16:38:15.457861: uid:0 gid:0 pid:766 cmd:release (233781) [handle:01000004,uselocks:2,lock_owner:00000000000002FE]: OK --------- Just to be sure, I ran it on Linux on MooseFS, it behaved like FreeBSD on l= ocal filesystem: displayed the file descriptor number and 3 "None"s. Operation l= og (from the same moment as the one above, so opening/creating the lockfile) l= ooks like that: --------- 05.19 19:04:33.608503: uid:0 gid:0 pid:1703 cmd:lookup (233782,lock.file): ENOENT (No such file or directory) 05.19 19:04:33.609052: uid:0 gid:0 pid:1703 cmd:create (233782,lock.file,O_WRONLY|O_CREAT,-rw-rw-rw-:0100666): OK (0.0,233784,1.0,[-rw-r--r--:0100644,1,0,0,1621443873,1621443873,1621443873,= 0]) (direct_io:0,keep_cache:0,append_mode:0) [handle:0A000001] 05.19 19:04:33.609475: uid:0 gid:0 pid:1703 cmd:setlkw (inode:233784 owner:53C3FEC6E42D7114 start:0 end:18446744073709551615 type:W) [handle:0A000001]: OK 05.19 19:04:35.124774: uid:0 gid:0 pid:1667 cmd:getattr (233782) [no handle= ]: OK (1.0,[drwxr-xr-x:0040755,2,0,0,1621443864,1621443873,1621443873,1]) 05.19 19:04:35.610893: uid:0 gid:0 pid:1703 cmd:setlk (inode:233784 owner:53C3FEC6E42D7114 start:0 end:18446744073709551615 type:W) [handle:0A000001]: OK 05.19 19:04:37.613568: uid:0 gid:0 pid:1703 cmd:setlk (inode:233784 owner:53C3FEC6E42D7114 start:0 end:18446744073709551615 type:U) [handle:0A000001]: OK 05.19 19:04:37.616895: uid:0 gid:0 pid:1703 cmd:flush (233784) - releasing = all POSIX-type locks for 53C3FEC6E42D7114 (received from kernel): OK 05.19 19:04:37.616898: uid:0 gid:0 pid:1703 cmd:flush (233784) [handle:0A000001,uselocks:2,lock_owner:53C3FEC6E42D7114]: OK --------- So, clearly, on FreeBSD MooseFS gets some weird owner lock values from FUSE, while on Linux it all looks consistent. As a result, the second lock fails, because MooseFS thinks some other process is trying to obtain the lock. --=20 You are receiving this mail because: You are the assignee for the bug.=