[LU-1044] ASSERTION((req->rq_req_swab_mask & (1 << index)) == 0) failed Created: 26/Jan/12  Updated: 05/Mar/12  Resolved: 05/Mar/12

Status: Resolved
Project: Lustre
Component/s: None
Affects Version/s: Lustre 2.1.0, Lustre 1.8.x (1.8.0 - 1.8.5)
Fix Version/s: None

Type: Bug Priority: Blocker
Reporter: Prakash Surya (Inactive) Assignee: Jinshan Xiong (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

toss 2.0-beta12.ch5
lustre-2.1.0-17chaos_2.6.32_220.2.1.3chaos.ch5.x86_64.x86_64


Attachments: Text File 0003-LU-1044-ptlrpc-Fixed-a-swab-race-for-ptlrpc.patch    
Severity: 3
Rank (Obsolete): 6476

 Description   

2012-01-26 10:35:09 LustreError: 15531:0:(lustre_net.h:761:lustre_set_req_swabbed()) ASSERTION((req->rq_req_swab_mask & (1 << index)) == 0) failed
2012-01-26 10:35:09 LustreError: 15531:0:(lustre_net.h:761:lustre_set_req_swabbed()) LBUG
2012-01-26 10:35:09 Jan 26 10:35:09 Pid: 15531, comm: ldlm_cn_09
2012-01-26 10:35:09 momus31 kernel:
2012-01-26 10:35:09 LustreError: 15531:0:(lustre_netCall Trace:
2012-01-26 10:35:09 .h:761:lustre_se [<ffffffffa054e895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
2012-01-26 10:35:09 t_req_swabbed()) [<ffffffffa054edc7>] lbug_with_loc+0x47/0xb0 [libcfs]
2012-01-26 10:35:09 LBUG
2012-01-26 10:35:09 [<ffffffffa055842d>] libcfs_assertion_failed+0x2d/0x30 [libcfs]
2012-01-26 10:35:09 [<ffffffffa07f8189>] ptlrpc_buf_set_swabbed+0xc9/0x130 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa08182a1>] __req_capsule_get+0x3f1/0x5a0 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa07f8590>] ? lustre_swab_ldlm_request+0x0/0x30 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa0818585>] req_capsule_client_get+0x15/0x20 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa07d7b7a>] ldlm_cancel_hpreq_check+0xba/0x1e0 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa07fea53>] ptlrpc_server_handle_req_in+0x7a3/0x8e0 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa0802b96>] ptlrpc_main+0x6e6/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa08024b0>] ? ptlrpc_main+0x0/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffff8100c14a>] child_rip+0xa/0x20
2012-01-26 10:35:09 [<ffffffffa08024b0>] ? ptlrpc_main+0x0/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa08024b0>] ? ptlrpc_main+0x0/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffff8100c140>] ? child_rip+0x0/0x20
2012-01-26 10:35:09
2012-01-26 10:35:09 Kernel panic - not syncing: LBUG
2012-01-26 10:35:09 Pid: 15531, comm: ldlm_cn_09 Not tainted 2.6.32-220.2.1.3chaos.ch5.x86_64 #1
2012-01-26 10:35:09 Jan 26 10:35:09 Call Trace:
2012-01-26 10:35:09 momus31 kernel: [<ffffffff814edddb>] ? panic+0x78/0x143
2012-01-26 10:35:09 Kernel panic - n [<ffffffffa054ee1b>] ? lbug_with_loc+0x9b/0xb0 [libcfs]
2012-01-26 10:35:09 ot syncing: LBUG [<ffffffffa055842d>] ? libcfs_assertion_failed+0x2d/0x30 [libcfs]
2012-01-26 10:35:09
2012-01-26 10:35:09 [<ffffffffa07f8189>] ? ptlrpc_buf_set_swabbed+0xc9/0x130 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa08182a1>] ? __req_capsule_get+0x3f1/0x5a0 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa07f8590>] ? lustre_swab_ldlm_request+0x0/0x30 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa0818585>] ? req_capsule_client_get+0x15/0x20 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa07d7b7a>] ? ldlm_cancel_hpreq_check+0xba/0x1e0 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa07fea53>] ? ptlrpc_server_handle_req_in+0x7a3/0x8e0 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa0802b96>] ? ptlrpc_main+0x6e6/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa08024b0>] ? ptlrpc_main+0x0/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffff8100c14a>] ? child_rip+0xa/0x20
2012-01-26 10:35:09 [<ffffffffa08024b0>] ? ptlrpc_main+0x0/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffffa08024b0>] ? ptlrpc_main+0x0/0x1690 [ptlrpc]
2012-01-26 10:35:09 [<ffffffff8100c140>] ? child_rip+0x0/0x20



 Comments   
Comment by Prakash Surya (Inactive) [ 26/Jan/12 ]

Initially, it appears as though the swap bit in question is being modified in between access in this code path:

        if (ptlrpc_buf_need_swab(req, inout, offset)) {
                lustre_swab_ptlrpc_body(pb);
                ptlrpc_buf_set_swabbed(req, inout, offset);
        }

`ptlrpc_buf_need_swab` will only return true if `req->rq_req_swab_mask & (1 << index)` is false. Thus, if it's calling `ptlrpc_buf_set_swabbed`, that must mean that `req->rq_req_swab_mask & (1 << index)` is false when it's executed within `ptlrpc_buf_need_swab`. But then when that same check it executed in `ptlrpc_buf_set_swabbed` its true (hence the LBUG).

Where is the lock taken on `req` in this code path? The only way I can see this happening is if another thread swabs `req` in between the two above accesses. And that would imply improper lock handling on `req`.

Comment by Prakash Surya (Inactive) [ 26/Jan/12 ]

I was going down the wrong path earlier, the real call to `ptlrpc_buf_set_swabbed` I believe happened here:

        if (ptlrpc_buf_need_swab(pill->rc_req, inout, offset) &&
            swabber != NULL && value != NULL)
                do_swab = 1; 
        else 
                do_swab = 0; 

        if (!(field->rmf_flags & RMF_F_STRUCT_ARRAY)) {
                if (dump && field->rmf_dumper) {
                        CDEBUG(D_RPCTRACE, "Dump of %sfield %s follows\n",
                               do_swab ? "unswabbed " : "", field->rmf_name);
                        field->rmf_dumper(value);
                }    
                if (!do_swab)
                        return;
                swabber(value);
                ptlrpc_buf_set_swabbed(pill->rc_req, inout, offset);
                if (dump) {
                        CDEBUG(D_RPCTRACE, "Dump of swabbed field %s "
                               "follows\n", field->rmf_name);
                        field->rmf_dumper(value);
                }    

                return;
        } 

Although, I think the same logic regarding `req->rq_req_swab_mask` changing in between calls to `ptlrpc_buf_need_swab` and `ptlrpc_buf_set_swabbed` still stands.

Comment by Oleg Drokin [ 26/Jan/12 ]

I did a quick search for ldlm_cancel_hpreq_check and I don't see it anywhere in our code neither 2.x nor 1.8.x.
Is this some sort of a patch you carry? The only patch I am able to find that has a function with this name is some sort of super old version in bug 22107, and even then it's for 1.x only

Also did this crash happen on a client? What version was the client running?

Comment by Andreas Dilger [ 26/Jan/12 ]

Also, is the client a PPC BlueGene system?

Comment by Prakash Surya (Inactive) [ 27/Jan/12 ]

Oleg: The ldlm_cancel_hpreq_check was introduced by one of the LU-874 patches we are carrying locally (since they haven't landed yet AFAIK). As such, it might be a good idea to point Jinshan to this thread since he was a big contributor to those patches. In particular, that function was introduced by change-id: I1a300916b4b3b592ca565ffc06cb3658d699d7a0.

Andreas: I can't say for sure, but after talking with Chris and Ned, I think the consensus is that we do still indeed have a PPC BG machine out in our environment mounting this filesystem. I don't know of any other reason why scrubbing would be necessary. Although, I'll check with one of the admins to make sure of this.

Comment by Peter Jones [ 27/Jan/12 ]

jinshan

Could you please look into this possible problem with one of the LU874 patches?

Thanks

Peter

Comment by Prakash Surya (Inactive) [ 27/Jan/12 ]

And just for completeness, here's the LU-874 patch stack we are carrying locally:

Change-id: If14eff6361f55d2b2eeb2db7146789dda4c32060
Change-id: I2fa99a0f09a42e1333589fc7bc2a6eebef4924b6
Change-id: I33e2d113d7929a56389741c06dffb5efb6bf28a3
Change-id: I1a300916b4b3b592ca565ffc06cb3658d699d7a0

Comment by D. Marc Stearman (Inactive) [ 27/Jan/12 ]

I can confirm, we do have PPC bluegene clients mounting this file system. Both IO nodes, and login nodes.

Comment by Oleg Drokin [ 27/Jan/12 ]

So, is the crash happening on OST?

Comment by Prakash Surya (Inactive) [ 27/Jan/12 ]

Oleg: Yeah, the OSS.

Comment by Christopher Morrone [ 27/Jan/12 ]

Oleg: Our branch is available at github.com/chaos/lustre.

Comment by Jinshan Xiong (Inactive) [ 27/Jan/12 ]

Can you please use this patch(in attachment) as a workaround fix? Because LU-874 http://review.whamcloud.com/#change,1918 is still in inspection, so I'd like to merge it into that patch instead of having a standalone one.

Comment by Jinshan Xiong (Inactive) [ 27/Jan/12 ]

Thanks oleg for helping me find this out issue. There is a similar issue(LU-898 review.whamcloud.com/1799) which was merged, but we may not need that patch to make it work.

Comment by Prakash Surya (Inactive) [ 27/Jan/12 ]

Jinshan, since this will be running in a production environment, we are reluctant to apply the patch with it not submitted through Gerrit. Would you be able to merge it into that patch and push a new revision?

Comment by Jinshan Xiong (Inactive) [ 27/Jan/12 ]

Hi Prakash, please take a look at patch set 10 of http://review.whamcloud.com/#change,1918. I'll urge guys to inspect it.

Comment by Prakash Surya (Inactive) [ 27/Jan/12 ]

Thanks, Jinshan.

Comment by Christopher Morrone [ 02/Mar/12 ]

No additional instances of this bug. I am ready to believe it introduced by the earlier revision LU-874. This can be closed or at least the priority reduced to "minor".

Comment by Peter Jones [ 05/Mar/12 ]

ok then let's close for now and reopen if it reappears

Generated at Sat Feb 10 01:12:57 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.