Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fslock test failed. #4890

Closed
zhoucheng361 opened this issue May 23, 2024 · 5 comments · Fixed by #4910
Closed

fslock test failed. #4890

zhoucheng361 opened this issue May 23, 2024 · 5 comments · Fixed by #4910
Labels
kind/bug Something isn't working

Comments

@zhoucheng361
Copy link
Contributor

What happened:

https://github.com/juicedata/juicefs/actions/runs/9196955688/job/25296286772

Cloning into 'gofslock'...
Note: switching to 'cc7f001fe0e7df1710adc8f0cd[9](https://github.com/juicedata/juicefs/actions/runs/9196955688/job/25296286772#step:8:10)e9d6d21fdb3a9'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by switching back to a branch.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -c with the switch command. Example:

  git switch -c <new-branch-name>

Or undo this operation with:

  git switch -

Turn off this advice by setting config variable advice.detachedHead to false

HEAD is now at cc7f001 Merge pull request #[10](https://github.com/juicedata/juicefs/actions/runs/9196955688/job/25296286772#step:8:11) from fancl20/master
go: downloading golang.org/x/sys v0.0.0-202[11](https://github.com/juicedata/juicefs/actions/runs/9196955688/job/25296286772#step:8:12)216021012-1d35b9e2eb4e
=== RUN   TestConcurrent
=== PAUSE TestConcurrent
=== RUN   TestMultiProcessing
    lock_test.go:186: wrote initial output file to [/jfs/gofslock/fslock/multiprocessing1868176549/out]
    lock_test.go:275: output file doesn't match expected (99 != 100)
--- FAIL: TestMultiProcessing (5.04s)
=== RUN   TestBlockingAndContent
=== PAUSE TestBlockingAndContent
=== RUN   TestUnlock
=== PAUSE TestUnlock
=== RUN   TestSharedConcurrent
=== PAUSE TestSharedConcurrent
=== RUN   TestSharedMultiProcessing
    lock_test.go:587: monitor: acquired exclusive lock
    lock_test.go:596: monitor: observed 'failed_shared' files
    lock_test.go:609: monitor: observed 'has_shared_lock' files
    lock_test.go:6[15](https://github.com/juicedata/juicefs/actions/runs/9196955688/job/25296286772#step:8:16): monitor: failed to re-acquire exclusive lock (0)
    lock_test.go:615: monitor: failed to re-acquire exclusive lock (1)
    lock_test.go:615: monitor: failed to re-acquire exclusive lock (2)
    lock_test.go:615: monitor: failed to re-acquire exclusive lock (3)
    lock_test.go:626: monitor: acquired exclusive lock
--- PASS: TestSharedMultiProcessing (6.09s)
=== RUN   TestExec
=== PAUSE TestExec
=== CONT  TestConcurrent
=== CONT  TestSharedConcurrent
=== CONT  TestExec
=== CONT  TestUnlock
    lock_test.go:431: panicked with: lock is not held
--- PASS: TestUnlock (0.15s)
=== CONT  TestBlockingAndContent
--- PASS: TestSharedConcurrent (0.25s)
--- PASS: TestBlockingAndContent (0.15s)
--- PASS: TestConcurrent (1.02s)
--- PASS: TestExec (11.80s)
FAIL
FAIL	github.com/danjacques/gofslock/fslock	[22](https://github.com/juicedata/juicefs/actions/runs/9196955688/job/25296286772#step:8:23).926s
FAIL

What you expected to happen:

How to reproduce it (as minimally and precisely as possible):

Anything else we need to know?

Environment:

  • JuiceFS version (use juicefs --version) or Hadoop Java SDK version:
  • Cloud provider or hardware configuration running JuiceFS:
  • OS (e.g cat /etc/os-release):
  • Kernel (e.g. uname -a):
  • Object storage (cloud provider and region, or self maintained):
  • Metadata engine info (version, cloud provider managed or self maintained):
  • Network connectivity (JuiceFS to metadata engine, JuiceFS to object storage):
  • Others:
@zhoucheng361 zhoucheng361 added the kind/bug Something isn't working label May 23, 2024
@SandyXSD
Copy link
Contributor

SandyXSD commented May 23, 2024 •
edited
Loading

It looks that kernel uses the same owner for different processes:

2024.05.23 16:11:18.547333 [uid:0,gid:0,pid:1197494] open (16388,0x8002) [fh:14400] - OK <0.000307>
2024.05.23 16:11:18.587396 [uid:0,gid:0,pid:1197494] flock (16388,14400,DBD50627F3B07582,LOCKEX,false) - OK <0.039593>
2024.05.23 16:11:18.705936 [uid:0,gid:0,pid:1197494] flush (16388,14400,78C773008E163E24) - OK <0.000028>
2024.05.23 16:11:18.725796 [uid:0,gid:0,pid:1197343] open (16388,0x8002) [fh:15040] - OK <0.001196>
2024.05.23 16:11:18.726301 [uid:0,gid:0,pid:1197343] flock (16388,15040,DBD50627F3B07582,LOCKEX,false) - OK <0.000388>
2024.05.23 16:11:18.740483 [uid:0,gid:0,pid:0] release (16388,14400) - OK <0.034301>
2024.05.23 16:11:18.825006 [uid:0,gid:0,pid:1197343] flush (16388,15040,B33FDE7A78327F3D) - OK <0.000003>
2024.05.23 16:11:18.852910 [uid:0,gid:0,pid:0] release (16388,15040) - OK <0.027586>

@SandyXSD
Copy link
Contributor

In kernel VFS the owner is set as the pointer of file struct:

flock_make_lock(struct file *filp, unsigned int cmd, struct file_lock *fl)
{
	...
	fl->fl_file = filp;
	fl->fl_owner = filp;
	fl->fl_pid = current->tgid;
	fl->fl_flags = FL_FLOCK;
	fl->fl_type = type;
	fl->fl_end = OFFSET_MAX;

	return fl;
}

This pointer is allocated by open, and freed after release:

static void __fput(struct file *file)
{
	...
	if (file->f_op->release)
		file->f_op->release(inode, file);
	...
out:
	file_free(file);
}

In FUSE the owner in the arguments is converted from the VFS owner, as:

inarg->owner = fuse_lock_owner_id(fc, fl->fl_owner);

and

u64 fuse_lock_owner_id(struct fuse_conn *fc, fl_owner_t id)
{
	u32 *k = fc->scramble_key;
	u64 v = (unsigned long) id;
	u32 v0 = v;
	u32 v1 = v >> 32;
	u32 sum = 0;
	int i;

	for (i = 0; i < 32; i++) {
		v0 += ((v1 << 4 ^ v1 >> 5) + v1) ^ (sum + k[sum & 3]);
		sum += 0x9E3779B9;
		v1 += ((v0 << 4 ^ v0 >> 5) + v0) ^ (sum + k[sum>>11 & 3]);
	}

	return (u64) v0 + ((u64) v1 << 32);
}

Here the scramble_key is randomly generated when the FUSE connection is initiated:

get_random_bytes(&fc->scramble_key, sizeof(fc->scramble_key));

@SandyXSD SandyXSD added the pending Solution to this issue is not decided label May 29, 2024
@SandyXSD
Copy link
Contributor

FUSE release is async for most files:

static void fuse_file_put(struct fuse_file *ff, bool sync, bool isdir)
{
	if (refcount_dec_and_test(&ff->count)) {
		struct fuse_args *args = &ff->release_args->args;

		if (isdir ? ff->fm->fc->no_opendir : ff->fm->fc->no_open) {
			/* Do nothing when client does not implement 'open' */
			fuse_release_end(ff->fm, args, 0);
		} else if (sync) {
			fuse_simple_request(ff->fm, args);
			fuse_release_end(ff->fm, args, 0);
		} else {
			args->end = fuse_release_end;
			if (fuse_simple_background(ff->fm, args,
						   GFP_KERNEL | __GFP_NOFAIL))
				fuse_release_end(ff->fm, args, -ENOTCONN);
		}
		kfree(ff);
	}
}

@SandyXSD
Copy link
Contributor

Timeline:

  1. p1: got lock(open & flock), reads value(1), writes value(2), unlock(flush & release)
  2. p1: kernel frees the file pointer, FUSE schedules the release request
  3. p2: got lock, and reuses the same file pointer as p1; JuiceFS treats them as the same owner
  4. p2: reads value(2)
  5. p1: release request arrived, the plock is unlocked (!!!)
  6. p3: got lock as well, reads value(2)
  7. p2 and p3 both write value(3), then the test fails

@SandyXSD
Copy link
Contributor

SandyXSD commented May 30, 2024 •
edited
Loading

Related access log:

2024.05.23 16:11:18.547333 [uid:0,gid:0,pid:1197494] open (16388,0x8002) [fh:14400] - OK <0.000307>
2024.05.23 16:11:18.548213 [uid:0,gid:0,pid:1197343] lookup (11405,fslock): (11408,[drwxr-xr-x:0040755,3,0,0,1716435733,1716451874,1716451874,4096]) - OK <0.000328>
2024.05.23 16:11:18.549223 [uid:0,gid:0,pid:1197343] open (16388,0x8002) [fh:14404] - OK <0.000369>
2024.05.23 16:11:18.572322 [uid:0,gid:0,pid:1197593] flock (16388,14314,024173F8BDF396D3,LOCKEX,false) - resource temporarily unavailable <0.054246>
2024.05.23 16:11:18.574259 [uid:0,gid:0,pid:1197593] flush (16388,14314,577EADE48FFB40D0) - OK <0.000009>
2024.05.23 16:11:18.587396 [uid:0,gid:0,pid:1197494] flock (16388,14400,DBD50627F3B07582,LOCKEX,false) - OK <0.039593>
2024.05.23 16:11:18.587874 [uid:0,gid:0,pid:1197494] getattr (16387): (16387,[-rw-r--r--:0100644,1,0,0,1716451874,1716451878,1716451878,2]) - OK <0.000201>
2024.05.23 16:11:18.588111 [uid:0,gid:0,pid:1197494] open (16387,0x8000) [fh:14453] - OK <0.000177>
2024.05.23 16:11:18.588472 [uid:0,gid:0,pid:1197494] read (16387,4096,0): (2{20}) - OK <0.000280>
2024.05.23 16:11:18.590394 [uid:0,gid:0,pid:1197494] flush (16387,14453,78C773008E163E24) - OK <0.000001>
2024.05.23 16:11:18.590912 [uid:0,gid:0,pid:1197593] open (16388,0x8002) [fh:14458] - OK <0.008177>
2024.05.23 16:11:18.593875 [uid:0,gid:0,pid:1197494] open (16387,0x8001) [fh:14486] - OK <0.003140>
2024.05.23 16:11:18.598135 [uid:0,gid:0,pid:1197343] flock (16388,14404,10111F04809616E2,LOCKEX,false) - resource temporarily unavailable <0.048503>
2024.05.23 16:11:18.598317 [uid:0,gid:0,pid:1197343] flush (16388,14404,B33FDE7A78327F3D) - OK <0.000003>
2024.05.23 16:11:18.598398 [uid:0,gid:0,pid:0] release (16388,14404) - OK <0.000005>
2024.05.23 16:11:18.600114 [uid:0,gid:0,pid:1197343] open (16388,0x8002) [fh:14562] - OK <0.000617>
2024.05.23 16:11:18.608237 [uid:0,gid:0,pid:1197593] flock (16388,14458,E4E56C8D914CF53B,LOCKEX,false) - resource temporarily unavailable <0.017167>
2024.05.23 16:11:18.608563 [uid:0,gid:0,pid:1197593] flush (16388,14458,577EADE48FFB40D0) - OK <0.000003>
2024.05.23 16:11:18.608634 [uid:0,gid:0,pid:0] release (16388,14458) - OK <0.000003>
2024.05.23 16:11:18.628584 [uid:0,gid:0,pid:1197593] open (16388,0x8002) [fh:14628] - OK <0.018672>
2024.05.23 16:11:18.634345 [uid:0,gid:0,pid:0] release (16387,14453) - OK <0.038916>
2024.05.23 16:11:18.646764 [uid:0,gid:0,pid:1197343] flock (16388,14562,11A45B134117B2D8,LOCKEX,false) - resource temporarily unavailable <0.046522>
2024.05.23 16:11:18.646836 [uid:0,gid:0,pid:1197343] flush (16388,14562,B33FDE7A78327F3D) - OK <0.000002>
2024.05.23 16:11:18.646881 [uid:0,gid:0,pid:0] release (16388,14562) - OK <0.000003>
2024.05.23 16:11:18.648865 [uid:0,gid:0,pid:1197343] open (16388,0x8002) [fh:14714] - OK <0.000336>
2024.05.23 16:11:18.679472 [uid:0,gid:0,pid:1197593] flock (16388,14628,FA09043A9C7D90B0,LOCKEX,false) - resource temporarily unavailable <0.050358>
2024.05.23 16:11:18.679539 [uid:0,gid:0,pid:1197593] flush (16388,14628,577EADE48FFB40D0) - OK <0.000003>
2024.05.23 16:11:18.679565 [uid:0,gid:0,pid:0] release (16388,14628) - OK <0.000003>
2024.05.23 16:11:18.679726 [uid:0,gid:0,pid:1197494] setattr (16387[0],0x208,[size=0]): (16387,[-rw-r--r--:0100644,1,0,0,1716451874,1716451878,1716451878,0]) - OK <0.085665>
2024.05.23 16:11:18.680157 [uid:0,gid:0,pid:1197494] write (16387,2,0,14486): (21) - OK <0.000052>
2024.05.23 16:11:18.680861 [uid:0,gid:0,pid:1197593] open (16388,0x8002) [fh:14774] - OK <0.000188>
2024.05.23 16:11:18.690767 [uid:0,gid:0,pid:1197343] flock (16388,14714,777EADD6F88FBF31,LOCKEX,false) - resource temporarily unavailable <0.041720>
2024.05.23 16:11:18.691088 [uid:0,gid:0,pid:1197343] flush (16388,14714,B33FDE7A78327F3D) - OK <0.000003>
2024.05.23 16:11:18.691219 [uid:0,gid:0,pid:0] release (16388,14714) - OK <0.000003>
2024.05.23 16:11:18.692673 [uid:0,gid:0,pid:1197343] open (16388,0x8002) [fh:14874] - OK <0.000346>
2024.05.23 16:11:18.705671 [uid:0,gid:0,pid:1197494] flush (16387,14486,78C773008E163E24) - OK <0.025449>
2024.05.23 16:11:18.705724 [uid:0,gid:0,pid:0] release (16387,14486) - OK <0.000004>
2024.05.23 16:11:18.705936 [uid:0,gid:0,pid:1197494] flush (16388,14400,78C773008E163E24) - OK <0.000028>
2024.05.23 16:11:18.706137 [uid:0,gid:0,pid:1197593] flock (16388,14774,B8CE63008B2D04B4,LOCKEX,false) - resource temporarily unavailable <0.025217>
2024.05.23 16:11:18.706213 [uid:0,gid:0,pid:1197593] flush (16388,14774,577EADE48FFB40D0) - OK <0.000003>
2024.05.23 16:11:18.706293 [uid:0,gid:0,pid:0] release (16388,14774) - OK <0.000006>
2024.05.23 16:11:18.707826 [uid:0,gid:0,pid:1197593] open (16388,0x8002) [fh:14930] - OK <0.000478>
2024.05.23 16:11:18.723414 [uid:0,gid:0,pid:1197343] flock (16388,14874,4C152029E8896BE1,LOCKEX,false) - resource temporarily unavailable <0.030611>
2024.05.23 16:11:18.723471 [uid:0,gid:0,pid:1197343] flush (16388,14874,B33FDE7A78327F3D) - OK <0.000002>
2024.05.23 16:11:18.723587 [uid:0,gid:0,pid:0] release (16388,14874) - OK <0.000002>
2024.05.23 16:11:18.725796 [uid:0,gid:0,pid:1197343] open (16388,0x8002) [fh:15040] - OK <0.001196>
2024.05.23 16:11:18.726301 [uid:0,gid:0,pid:1197343] flock (16388,15040,DBD50627F3B07582,LOCKEX,false) - OK <0.000388>
2024.05.23 16:11:18.726834 [uid:0,gid:0,pid:1197343] getattr (16387): (16387,[-rw-r--r--:0100644,1,0,0,1716451874,1716451878,1716451878,2]) - OK <0.000392>
2024.05.23 16:11:18.727187 [uid:0,gid:0,pid:1197343] open (16387,0x8000) [fh:15051] - OK <0.000284>
2024.05.23 16:11:18.727687 [uid:0,gid:0,pid:1197343] read (16387,4096,0): (2{21}) - OK <0.000415>
2024.05.23 16:11:18.727746 [uid:0,gid:0,pid:1197343] flush (16387,15051,B33FDE7A78327F3D) - OK <0.000001>
2024.05.23 16:11:18.727831 [uid:0,gid:0,pid:0] release (16387,15051) - OK <0.000002>
2024.05.23 16:11:18.727981 [uid:0,gid:0,pid:1197343] open (16387,0x8001) [fh:15054] - OK <0.000190>
2024.05.23 16:11:18.740483 [uid:0,gid:0,pid:0] release (16388,14400) - OK <0.034301>
2024.05.23 16:11:18.744490 [uid:0,gid:0,pid:1197593] flock (16388,14930,4F7B3C34F8D8CA68,LOCKEX,false) - OK <0.036565>
2024.05.23 16:11:18.744835 [uid:0,gid:0,pid:1197593] open (16387,0x8000) [fh:15095] - OK <0.000209>
2024.05.23 16:11:18.745097 [uid:0,gid:0,pid:1197593] getattr (16387): (16387,[-rw-r--r--:0100644,1,0,0,1716451874,1716451878,1716451878,2]) - OK <0.000174>
2024.05.23 16:11:18.788183 [uid:0,gid:0,pid:1197343] setattr (16387[0],0x208,[size=0]): (16387,[-rw-r--r--:0100644,1,0,0,1716451874,1716451878,1716451878,0]) - OK <0.060124>
2024.05.23 16:11:18.788697 [uid:0,gid:0,pid:1197343] write (16387,2,0,15054): (22) - OK <0.000031>
2024.05.23 16:11:18.790401 [uid:0,gid:0,pid:1197593] flush (16387,15095,577EADE48FFB40D0) - OK <0.000001>
2024.05.23 16:11:18.790894 [uid:0,gid:0,pid:0] release (16387,15095) - OK <0.000003>
2024.05.23 16:11:18.791174 [uid:0,gid:0,pid:1197593] getattr (16387): (16387,[-rw-r--r--:0100644,1,0,0,1716451874,1716451878,1716451878,0]) - OK <0.000259>
2024.05.23 16:11:18.791942 [uid:0,gid:0,pid:1197593] open (16387,0x8001) [fh:15370] - OK <0.000437>
2024.05.23 16:11:18.824645 [uid:0,gid:0,pid:1197343] flush (16387,15054,B33FDE7A78327F3D) - OK <0.033176>
2024.05.23 16:11:18.825006 [uid:0,gid:0,pid:1197343] flush (16388,15040,B33FDE7A78327F3D) - OK <0.000003>
2024.05.23 16:11:18.852801 [uid:0,gid:0,pid:0] release (16387,15054) - OK <0.027975>
2024.05.23 16:11:18.852910 [uid:0,gid:0,pid:0] release (16388,15040) - OK <0.027586>
2024.05.23 16:11:18.878904 [uid:0,gid:0,pid:1197593] setattr (16387[0],0x208,[size=0]): (16387,[-rw-r--r--:0100644,1,0,0,1716451874,1716451878,1716451878,0]) - OK <0.086905>
2024.05.23 16:11:18.879271 [uid:0,gid:0,pid:1197593] write (16387,2,0,15370): (22) - OK <0.000064>
2024.05.23 16:11:18.908230 [uid:0,gid:0,pid:1197593] flush (16387,15370,577EADE48FFB40D0) - OK <0.028909>
2024.05.23 16:11:18.908385 [uid:0,gid:0,pid:0] release (16387,15370) - OK <0.000004>
2024.05.23 16:11:18.908399 [uid:0,gid:0,pid:1197593] flush (16388,14930,577EADE48FFB40D0) - OK <0.000004>
2024.05.23 16:11:18.936636 [uid:0,gid:0,pid:0] release (16388,14930) - OK <0.028074>

@SandyXSD SandyXSD mentioned this issue May 30, 2024
Merged
@SandyXSD SandyXSD removed the pending Solution to this issue is not decided label May 30, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

vfs: fix the issue that plock may be unlocked by mistake juicedata/juicefs
2 participants
@SandyXSD @zhoucheng361