ocfs2: fix DLM_BADARGS error in concurrent file locking

When calling flock(2) by multiple processes concurrently, it is reported to be very easy resulting DLM_BADARGS error. In dmesg the similar lines can be found:

Sep  2 11:17:32 acct20 kernel: (6935,1):ocfs2_lock_create:901 ERROR: Dlm error "DLM_BADARGS" while
calling dlmlock on resource
F00000000000000005d1cfe83ab8dad: bad api args
Sep  2 11:17:32 acct20 kernel: (6935,1):ocfs2_file_lock:1486 ERROR: status = -22

Here is the analysis how this error comes, in condition that 2 process concurrently call flock(2) on same file:

1) call sequence of process 1 is (first listed first called):
[ocfs2_do_flock] [ocfs2_file_lock] [ocfs2_lock_create] [dlmlock] [dlm_get_lock_resource]
[dlm_do_master_request] [o2net_send_message_vec]
In o2net_send_message_vec(), at line 1049:

        wait_event(nsw.ns_wq, o2net_nsw_completed(nn, &nsw));

Here process 1 is scheduled out, and process 2 is scheduled in to ran. At this moment, res->owner (ownership of the locking file resource) is set to
DLM_LOCK_RES_OWNER_UNKNOWN.

2) call sequence of process 2 is (first listed first called):
[ocfs2_do_flock] [ocfs2_file_lock] [ocfs2_lock_create] [dlmlock] [dlmlock_remote]
[o2net_send_message_vec]
in dlmlock(), at line 725:

                if (res->owner == dlm->node_num)
                        status = dlmlock_master(dlm, res, lock, flags);
                else
                        status = dlmlock_remote(dlm, res, lock, flags);
    Since res->owner is still set to DLM_LOCK_RES_OWNER_UNKNOWN and not decided in process 1 yet,
process 2 calls dlmlock_remote() here. But inside dlmlock_remote(), at line 247:
        __dlm_wait_on_lockres(res);
    After this function returned, res->owner is set correctly to 0 (node 0). Then at line 257:
        status = dlm_send_remote_lock_request(dlm, res, lock, flags);
    dlm_send_remote_lock_request() calls o2net_send_message() at line 330, as bellowed:
        tmpret = o2net_send_message(DLM_CREATE_LOCK_MSG, dlm->key, &create,
                                    sizeof(create), res->owner, &status);
    o2net_send_message() calls o2net_send_message_vec() and at line 987, the code is:
        if (target_node == o2nm_this_node()) {
                ret = -ELOOP;
                goto out;
        }

Here target_node is res->owner which is already set to 0. But before calling dlmlock_remote(),
res->owner is not set properly (still is DLM_LOCK_RES_OWNER_UNKNOWN). After entering dlmlock_remote(), and returning from __dlm_wait_on_lockres(), though res->owner is correct, the execution flow is in mistaken location.

3) The result is, process 1 can make the flock, and process 2 generates BADARGS error. 20 processes condition also got tested, only first process can success the flock, and other processes all got BADARGS.

With Sunil and Mark's suggestion, the solution is,
1) If a tmpres returned from hashed resources, check its owner.
2) if tmpres->owner is DLM_LOCK_RES_OWNER_UNKNOWN, it means another process owns the resource but dose not finish its initiation. We should wait on DLM_LOCK_RES_IN_PROGRESS until the initiation accomplished.
3) Once the initiation done, re-lookup the resource.

After basic testing on 2 nodes (each node forks 200,000 processes calling flock(2)) and 8 nodes (each node forks 1000 processes calling flock(2)), it works fine so far.

---
 fs/ocfs2/dlm/dlmmaster.c |   13 +++++++++++++
 1 files changed, 13 insertions(+), 0 deletions(-)

index 44f87ca..c777844 100644
@@ -742,6 +742,19 @@ lookup:
 			goto lookup;
 		}
 
+		/* tmpres might be initiating by another process, in this case
+		 * we should wait until the initiation done  */
+		spin_lock(&tmpres->spinlock);
+		if (tmpres->owner == DLM_LOCK_RES_OWNER_UNKNOWN ||
+		    (tmpres->state & DLM_LOCK_RES_IN_PROGRESS)) {
+			__dlm_wait_on_lockres_flags(tmpres, DLM_LOCK_RES_IN_PROGRESS);
+			spin_unlock(&tmpres->spinlock);
+			dlm_lockres_put(tmpres);
+			tmpres = NULL;
+			goto lookup;
+		}
+		spin_unlock(&tmpres->spinlock);
+
 		mlog(0, "found in hash!\n");
 		if (res)
 			dlm_lockres_put(res);

Coly Li
SuSE PRC Labs

Sunil Mushran Wrote:

Cool. Since I was not sure this was a race error, you can see, I did not mention race anywhere. I like this title more ;-)

The comment is perfect IMHO.

Sure, thanks for the suggestion. I will test the patch will all multinode tests, and submit a patch to ocfs2 test-suite for this fix.

Coly Li
SuSE PRC Labs

So I have a new patch. It has debug code too. I am still testing this. Don't upload it to bz.

@@ -672,6 +672,12 @@ void __dlm_lockres_drop_inflight_ref(struct 

dlm_ctxt *dlm,

 {
        assert_spin_locked(&res->spinlock);

+ if (res->inflight_locks == 0) {
+ mlog(ML_ERROR, "%s:%.*s: inflight=0\n",
+ dlm->name, res->lockname.len, res->lockname.name);
+ __dlm_print_one_lock_resource(res);
+ dump_stack();
+ }

        BUG_ON(res->inflight_locks == 0);
        res->inflight_locks--;
        mlog(0, "%s:%.*s: inflight--: now %u\n",
@@ -726,14 +732,22 @@ lookup:
        if (tmpres) {
                int dropping_ref = 0;

+ spin_unlock(&dlm->spinlock);
+

                spin_lock(&tmpres->spinlock);

+ if (tmpres->owner == DLM_LOCK_RES_OWNER_UNKNOWN) {
+ mlog(ML_NOTICE, "%s:%.*s Another thread is
mastering "
+ "this resource\n", dlm->name, namelen, lockid);
+ __dlm_wait_on_lockres(tmpres);
+ BUG_ON(tmpres->owner == DLM_LOCK_RES_OWNER_UNKNOWN);
+ }
+

                if (tmpres->owner == dlm->node_num) {
                        BUG_ON(tmpres->state & DLM_LOCK_RES_DROPPING_REF);
                        dlm_lockres_grab_inflight_ref(dlm, tmpres);
                } else if (tmpres->state & DLM_LOCK_RES_DROPPING_REF)
                        dropping_ref = 1;
                spin_unlock(&tmpres->spinlock);

- spin_unlock(&dlm->spinlock);

                /* wait until done messaging the master, drop our ref to 

allow
* the lockres to be purged, start over. */

Well, if you get an oops, get the stack. If you had, it would have looked like this.

(19990,0):__dlm_lockres_drop_inflight_ref:677
ERROR:
1B57953A48324D258163FE31C04C4B11:F00000000000000000801f61f38b60c: inflight=0

Call Trace:
.show_stack+0x68/0x1b0 (unreliable)
 .__dlm_lockres_drop_inflight_ref+0x98/0x184 [ocfs2_dlm]
 .dlmlock_master+0x41c/0x4f8 [ocfs2_dlm]
 .dlmlock+0x8b0/0x11a0 [ocfs2_dlm]
 .ocfs2_lock_create+0x174/0x3a8 [ocfs2]
 .ocfs2_file_lock+0x158/0x6d8 [ocfs2]
 .ocfs2_flock+0x18c/0x278 [ocfs2]
 .sys_flock+0x170/0x1d4
 syscall_exit+0x0/0x40

kernel BUG in __dlm_lockres_drop_inflight_ref at /rpmbuild/smushran/BUILD/ocfs2-1.4.1/fs/ocfs2/dlm/dlmmaster.c:680!

This tells you what the issue is. We are forgetting to take an inflight ref. The new patch moves the code up so that we take the reference.

Secondly, dlm->spinlock does not protect res->owner. Furthermore, that BUG_ON is important because that is the case. If mastery is underway, the state will remain IN_PROGRESS. I am curious as to why you feel otherwise.

Lastly, the perl script can be improved by enclosing the 20 fork loop into another loop that changes the filename. To startwith, touch 5000 files (test.flock%d). umount and mount again. This will drop the caches. Now before running any ls, run flock.pl. It will spawn 20 processes to flock() each file and wait till the 20 forks have exited before letting loose another
20 for the next file. (Makesure you have another node or two or more that have
just mounted that volume.)

I ran this with 5000 files successfully. I did encounter a problem in the last
run, not where I expected it. Still a work in progress. I can't email you the
perl script as my box will remain in the debugger for the night. ;)

My problem with your patch is not that it is wrong, but it is punting the issue. Say we do have a case in which the res->owner remains unknown eventhough
the state in not in_prog. In that case, the process will keep looping. By oopsing, we catch the problem upfront.

Sunil

Sunil Mushran Wrote:
[snip]

On a 8 nodes cluster setup by xen, I tested these test cases,
- run_buildkernel.py
- cross_delete.py
- dlmstress1.sh
- run_extend_and_write.py
- run_lvb_torture.py
- mmap_test
- test_netfail.py

Not tested cases are run_create_racer.py and open_delete.py, cause I encountered some error when setup them.

When I ran dlmsress1.sh and test_netfail.py,
- Kernel BUG at fs/ocfs2/dlm/dlmast.c:334 was triggered 3 times.
- Kernel BUG at fs/ocfs2/dlm/dlmmaster.c:1694 was triggered once.
Right now, there is not obvious clue they are directly related to this patch. They might stay there already, I will do more testing to confirm.

Thanks.

Coly Li
SuSE PRC Labs

Hi Coly,

How did you setup the env for testing? are you using the latest testsuite from ocfs2-test.git? As for the cluster testing, we need to install openmpi first, and setup passwordless ssh&rsh connection among all nodes.

Besides, all testing binaries need to be run from a installed BINDIR after a successful building&installation.

Regards,
Tristan

Actually we've moved to git repository for ocfs2-test src management, so you'd better turn to our git repo for pulling latest test sources. Such as,

1. git clone git://oss.oracle.com/git/ocfs2-test ocfs2-test

2. ./autogen.sh

3. make && make install DESTDIR=/your/dest/path

All testing binaries should be fairly ready for test if you've already configed your openmpi and ssh&rsh connection well.

Just feel free to let Marcos and me know if you're being hindered by any problem during the testing:)

Regards,
Tristan