Details
-
Bug
-
Resolution: Duplicate
-
Critical
-
None
-
Lustre 2.10.7
-
None
-
CentOS 7.6
-
3
-
9223372036854775807
Description
New LBUG tonight with 2.10.7, likely a duplicate of LU-12120.
[219417.266382] LustreError: 281433:0:(tgt_grant.c:559:tgt_grant_incoming()) oak-OST0053: cli 0eb5afeb-9924-327f-d61d-428dac6cb441/ffff883c7ef04800 dirty 0 pend 0 grant -29360128 [219417.283969] LustreError: 281433:0:(tgt_grant.c:561:tgt_grant_incoming()) LBUG [219417.292035] Pid: 281433, comm: ll_ost00_045 3.10.0-693.2.2.el7_lustre.pl3.x86_64 #1 SMP Thu Mar 15 13:06:45 PDT 2018 [219417.303881] Call Trace: [219417.306716] [<ffffffff8103a212>] save_stack_trace_tsk+0x22/0x40 [219417.313560] [<ffffffffc08087cc>] libcfs_call_trace+0x8c/0xc0 [libcfs] [219417.320982] [<ffffffffc080887c>] lbug_with_loc+0x4c/0xa0 [libcfs] [219417.328013] [<ffffffffc0bf81b0>] tgt_grant_prepare_read+0x0/0x3b0 [ptlrpc] [219417.335979] [<ffffffffc0bf82bb>] tgt_grant_prepare_read+0x10b/0x3b0 [ptlrpc] [219417.344121] [<ffffffffc119df6d>] ofd_set_info_hdl+0x23d/0x4a0 [ofd] [219417.351343] [<ffffffffc0bda115>] tgt_request_handle+0x925/0x1370 [ptlrpc] [219417.359202] [<ffffffffc0b82dd6>] ptlrpc_server_handle_request+0x236/0xa90 [ptlrpc] [219417.367930] [<ffffffffc0b86512>] ptlrpc_main+0xa92/0x1e40 [ptlrpc] [219417.375101] [<ffffffff810b098f>] kthread+0xcf/0xe0 [219417.380671] [<ffffffff816b4f58>] ret_from_fork+0x58/0x90 [219417.386823] [<ffffffffffffffff>] 0xffffffffffffffff [219417.392529] Kernel panic - not syncing: LBUG
prior to this, a lot of evictions and network errors
[218920.410034] LustreError: 257942:0:(events.c:449:server_bulk_callback()) event type 5, status -125, desc ffff881d0b310a00 [218923.029069] LustreError: 257941:0:(events.c:449:server_bulk_callback()) event type 5, status -125, desc ffff882566547000 [218928.063611] LustreError: 257941:0:(events.c:449:server_bulk_callback()) event type 5, status -125, desc ffff880050289600 [218957.709743] Lustre: oak-OST004d: haven't heard from client ed27e8aa-82e0-d7bd-37eb-95d83ba476b8 (at 10.8.7.32@o2ib6) in 227 seconds. I think it's dead, and I am evicting it. exp ffff883c83a64000, cur 1558412848 expire 1558412698 last 1558412621
Attaching vmcore-dmesg, output of basic crash commands and foreach bt.
Please note that (just in case) I didn't have the patch for LU-12018 on this OSS. It was a stock 2.10.7. Now the OSS has been updated.
Attachments
Issue Links
- duplicates
-
LU-12120 LustreError: 15069:0:(tgt_grant.c:561:tgt_grant_incoming()) LBUG
-
- Resolved
-
Hello,
I've looked at the code a little, and here is what I found (I hope it helps):
I suppose this is now obvious to anyone who read Stephane's description: the LBUG is triggered by a negative value of ted_grant.
I first thought it happened in tgt_grant_incoming() itself, because of this line:
But this assignment is actually protected:
dropped = oa->oa_dropped; ... if (ted->ted_grant < dropped) { CDEBUG(D_CACHE, ...); dropped = 0; } ... ted->ted_grant -= dropped;
Guided by LU-6877, I looked for a potential error during an arithmetic conversion:
I could not find any (though that looked promising at first with long being at least an int32_t and long long an int64_t).
From there I concluded that ted->ted_grant must be set to a negative value elsewhere/earlier. Repeating a similar analysis, I could only find one place where this can happen [*]:
All the other places where ted_grant is set seem to be protected with appropriate checks.
Now tgt_grant_shrink() is only called in two places: tgt_grant_prepare_read() and tgt_grant_prepare_write(). The odd part is that in tgt_grant_prepare_read() it is called after tgt_grant_incoming() (the function that raises the LBUG).
My understanding is that there is a workqueue on the client side that periodically updates a client's grant size (cf. ost_grant_work_handler()). The update RPC is sent asynchronously and a callback is set to process the server's response:
So at some point the client probably receives a bogus value from the server, and the next RPC triggers the LBUG.
Where to go from there?
I could not figure out where exp->exp_target_data comes from in tgt_grant_shrink(). If someone can, we should be able to find the root cause of all this.
—
[*] I only looked at places in the code where ted_grant is explicitly set (grep -R 'ted->ted_grant\s+[-+]?=' lustre). However, it is possible that somewhere, the whole ted structure is set at once and I missed it (for example during RPC packing / unpacking).