RE: Kernel panic over qedr with

From: Chuck Lever [mailto:chuck.lever@oracle.com]
Sent: Tuesday, January 30, 2018 12:01 AM

quoted

On Jan 29, 2018, at 9:35 AM, Kalderon, Michal

[off-list ref] wrote:

quoted

quoted

From: linux-rdma-owner@vger.kernel.org [mailto:linux-rdma-
owner@vger.kernel.org] On Behalf Of Kalderon, Michal
Sent: Wednesday, January 24, 2018 3:10 PM
To: Chuck Lever <redacted>
Cc: linux-rdma@vger.kernel.org
Subject: RE: Kernel panic over qedr with

[This sender failed our fraud detection checks and may not be who
they appear to be. Learn about spoofing at
http://aka.ms/LearnAboutSpoofing]

quoted

From: Chuck Lever [mailto:chuck.lever@oracle.com]
Sent: Tuesday, January 23, 2018 7:14 PM

quoted

On Jan 23, 2018, at 9:05 AM, Kalderon, Michal

[off-list ref] wrote:

quoted

Hi Chuck,

I’m hitting issues with NFS over qedr (either iWARP / RoCE)

I get a kernel panic during mount.
Looks like it started with 4.15-rcx Looking at qedr code it looks
like the wr we get may be corrupted/ Below the stack trace and
following logs with RCP debug enabled…

Can you please advise on how to proceed with debugging ?

I don't see anything distinctive in the log output.
I would start with a git bisect if your reproducer hits the oops every time.

On it, thanks.

Hi Chuck,

Git bisect helped in finding this commit as the one introducing the oops:

01bb35c89d90abe6fd1c0be001f84bbdfa7fa7d1 is the first bad commit
commit 01bb35c89d90abe6fd1c0be001f84bbdfa7fa7d1
Author: Chuck Lever [off-list ref]
Date:   Fri Oct 20 10:48:36 2017 -0400

   xprtrdma: RPC completion should wait for Send completion


I can't see the issue in the patch, but am lacking some more knowledge in

implementation.

quoted

Not sure why or whether it helps, but we see the oops consistently with

iWARP. And intermittently with RoCE.

quoted

Can you please take a look ?

I'm guessing, as object generated from my kernel source does not seem to
align with your RIP (__qedr_post_send+0x85 lands in the middle of
instruction). But you are failing somewhere in qedr_can_post_send,
probably qed_chain_get_elem_left_u32.

Can you tell me what the bad WR looks like? Each sendctx is initialized in
rpcrdma_sendctx_create, including the Send WR, which is re-used. During
operation, xprtrdma in this release overwrites only the send_flags and
num_sge fields.
Only thing I can think of is that something is overwriting the sendctx. Could
be that the SMP acquire/release logic is not stopping
rpcrdma_sendctx_get_locked from returning a sendctx that is still in use. Or,
the rl_flags field is getting corrupted because I over-optimized the set and
clear_bit calls.

Hi Chuck, 

I found the issue in rpcrdma, but not sure what the proper fix is.
The problem was there before this patch, but adding an additional field to rpcrdma_sendctx exposed the bug.
In rpcrdma_sendctx_create you allocate sizeof(*sc) + ri_max_send_sges *sizeof(ib_sge) 
ri_max_send_sges is equal to 1 ( max_sge -  RPCRDMA_MIN_SEND_SGE ) our device supports 4 max_sge
in rpcrdma_prepare_msg_sges you access sge[1] -> this corrupted the memory of the following sendctx

(specifically wrote the length value to the next ptr of the send_wr, in our code we check if wr->next != NULL and if so, we process it
As a wr, leading to the NULL ptr dereference __qedr_post_send was in qedr_can_post_send in the line that access wr->

The reason this patch exposed the bug is because before the size of the struct before the patch was 64 bytes
sizeof ib_sge is 16 and OS padded to overall 96 bytes, so accessing sge[1] was in the padding area
once the req ptr was added, sizeof struct was increased to 72 bytes, and the padding was no longer sufficient for sge[1]

I guess a device that supports more SGEs than 4 is not exposed 
By just increasing the sge array size I was able to work around the problem. But not sure what the proper fix should be
With regards to calculating how many sges should be allocated, and why ri_max_send_sges is set to max_sge - MIN_SEND_SGE)

Thanks,
Michal

quoted

Thanks,
Michal

quoted

quoted

quoted

Thanks,
Michal

[  782.951762] BUG: unable to handle kernel NULL pointer
dereference at 0000000000000040 [  782.952286] IP:
__qedr_post_send+0x85/0x127c [qedr] [  782.952797] PGD 0 P4D 0 [
782.953293] Oops: 0000 [#1] SMP PTI [  782.953781] Modules linked
in: qedr(E) qede qed
rpcsec_gss_krb5
nfsv4 dns_resolver nfs fscache xt_CHECKSUM iptable_mangle
ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4

nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack
libcrc32c ipt_REJECT nf_reject_ipv4 tun bridge stp llc
ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter
bonding rpcrdma ib_isert iscsi_target_mod ib_iser ib_srpt
target_core_mod ib_srp scsi_transport_srp ib_ipoib rdma_ucm ib_ucm
ib_uverbs ib_umad

rdma_cm

quoted

ib_cm iw_cm ib_core intel_powerclamp coretemp kvm irqbypass
crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel
crypto_simd glue_helper cryptd iTCO_wdt gpio_ich

iTCO_vendor_support

quoted

quoted

quoted

ipmi_si pcspkr sg lpc_ich
i2c_i801 ipmi_devintf ipmi_msghandler ioatdma i7core_edac shpchp [
782.957637]  acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd grace
sunrpc ip_tables ext4 mbcache jbd2 sr_mod sd_mod cdrom ata_generic
pata_acpi
mgag200 drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops
ttm drm igb ata_piix ptp libata pps_core e1000 crc32c_intel dca
i2c_algo_bit i2c_core

quoted

[  782.959572] CPU: 7 PID: 3422 Comm: mount.nfs Tainted: G            E

4.15.0-rc9+ #2

quoted

[  782.960232] Hardware name: Intel Corporation S5520HC/S5520HC,
BIOS
S5500.86B.01.00.0059.082320111421 08/23/2011 [  782.960901] RIP:
0010:__qedr_post_send+0x85/0x127c [qedr] [  782.961575] RSP:
0018:ffffab3d8259b6f8 EFLAGS: 00010082 [  782.962244] RAX:
0000000000000025 RBX: 0000000000000028 RCX: 0000000000000006 [
782.962907] RDX: 0000000000000000 RSI: 0000000000000092 RDI:
ffff9b275fd968f0 [  782.963573] RBP: ffffab3d8259b780 R08:
00000000000004cc R09: 0000000000000000 [  782.964242] R10:
ffff9b2753218540 R11: ffff9b25d9d67400 R12: ffff9b25d60aa000 [
782.964894] R13: 0000000000000028 R14: 0000000000000000 R15:
ffff9b259400e400 [  782.965557] FS:  00007f91dad3a880(0000)
GS:ffff9b275fd80000(0000) knlGS:0000000000000000 [  782.966235] CS:
0010

DS: 0000 ES: 0000 CR0: 0000000080050033 [  782.966906] CR2:
0000000000000040 CR3: 0000000393dbc003 CR4: 00000000000206e0 [
782.967593] Call Trace:

quoted

[  782.968271]  qedr_post_send+0x12e/0x180 [qedr] [  782.968950]
rpcrdma_ep_post+0x83/0xf0 [rpcrdma] [  782.969637]
xprt_rdma_send_request+0x84/0xe0 [rpcrdma] [  782.970349]
xprt_transmit+0x6c/0x370 [sunrpc] [  782.971057]  ?
call_decode+0x820/0x820 [sunrpc] [  782.971759]  ?
call_decode+0x820/0x820 [sunrpc] [  782.972464]
call_transmit+0x194/0x280 [sunrpc] [  782.973174]
__rpc_execute+0x7e/0x3f0 [sunrpc] [  782.973867]
rpc_run_task+0x106/0x150 [sunrpc] [  782.974577]
nfs4_proc_setclientid+0x213/0x380 [nfsv4] [  782.975279]
nfs40_discover_server_trunking+0x80/0xe0 [nfsv4] [  782.975982]
nfs4_discover_server_trunking+0x78/0x2b0 [nfsv4] [  782.976688]
nfs4_init_client+0x11b/0x260 [nfsv4] [  782.977402]  ?
__rpc_init_priority_wait_queue+0x83/0xb0 [sunrpc] [  782.978129]  ?
nfs4_alloc_client+0x15f/0x200 [nfsv4] [  782.978853]  ?
nfs_get_client+0x2c1/0x360 [nfs] [  782.979583]  ?
pcpu_alloc_area+0xc0/0x130 [  782.980317]
nfs4_set_client+0x9d/0xe0 [nfsv4]


RCP Logs
[  782.948548] RPC:   209 xmit complete
[  782.948549] RPC:   209 sleep_on(queue "xprt_pending" time

4295450237)

quoted

quoted

[  782.948550] RPC:   209 added to queue 000000006f382a4e

"xprt_pending"

quoted

quoted

[  782.948550] RPC:   209 setting alarm for 60000 ms
[  782.948552] RPC:   209 sync task going to sleep
[  782.948808] RPC:       rpcrdma_wc_receive: rep 0000000067b47231

opcode

quoted

'recv', length 52: success

quoted

[  782.948811] RPC:       rpcrdma_reply_handler: incoming rep

0000000067b47231

quoted

[  782.948814] RPC:       rpcrdma_reply_handler: reply 0000000067b47231

completes request 0000000096e058c2 (xid 0x4e366e3c)

quoted

[  782.948869] RPC:       rpcrdma_inline_fixup: srcp 0x00000000a5e2c17f

len

quoted

quoted

quoted

24 hdrlen 24

quoted

[  782.948871] RPC:       wake_up_first(0000000004dd7309

"xprt_sending")

quoted

quoted

quoted

quoted

[  782.948874] RPC:   209 xid 4e366e3c complete (24 bytes received)
[  782.948875] RPC:   209 __rpc_wake_up_task (now 4295450237)
[  782.948876] RPC:   209 disabling timer
[  782.948877] RPC:   209 removed from queue 000000006f382a4e

"xprt_pending"

quoted

[  782.948881] RPC:       __rpc_wake_up_task done
[  782.948916] RPC:   209 sync task resuming
[  782.948918] RPC:   209 call_status (status 24)
[  782.948919] RPC:   209 call_decode (status 24)
[  782.948921] RPC:   209 validating NULL cred 000000000941bc29
[  782.948923] RPC:   209 using AUTH_NULL cred 000000000941bc29 to

unwrap rpc data

quoted

[  782.948925] RPC:   209 call_decode result 0
[  782.948926] RPC:   209 return 0, status 0
[  782.948927] RPC:   209 release task
[  782.948929] RPC:       xprt_rdma_free: called on 0x0000000067b47231
[  782.948963] RPC:   209 release request 00000000088290f9
[  782.948964] RPC:       wake_up_first(0000000066fcc180

"xprt_backlog")

quoted

quoted

quoted

quoted

[  782.948966] RPC:       rpc_release_client(00000000d13a4ef8)
[  782.948968] RPC:   209 freeing task
[  782.949065] svc: svc_destroy(NFSv4 callback, 2)
[  782.949069] RPC:       new task initialized, procpid 3422
[  782.949070] RPC:       allocated task 00000000407c4b9f
[  782.949071] RPC:   210 __rpc_execute flags=0x5280
[  782.949072] RPC:   210 call_start nfs4 proc SETCLIENTID (sync)
[  782.949073] RPC:   210 call_reserve (status 0)
[  782.949074] RPC:   210 reserved req 00000000088290f9 xid 4f366e3c
[  782.949076] RPC:   210 call_reserveresult (status 0)
[  782.949077] RPC:   210 call_refresh (status 0)
[  782.949078] RPC:   210 refreshing UNIX cred 000000005a6be29a
[  782.949079] RPC:   210 call_refreshresult (status 0)
[  782.949080] RPC:   210 call_allocate (status 0)
[  782.949081] RPC:   210 xprt_rdma_allocate: send size = 1456, recv size

=

quoted

quoted

quoted

276, req = 00000000f056c1ce

quoted

[  782.949082] RPC:   210 call_bind (status 0)
[  782.949083] RPC:   210 call_connect xprt 00000000e40824fb is

connected

quoted

quoted

quoted

quoted

[  782.949083] RPC:   210 call_transmit (status 0)
[  782.949084] RPC:   210 xprt_prepare_transmit
[  782.949085] RPC:   210 xprt_cwnd_limited cong = 0 cwnd = 8192
[  782.949085] RPC:   210 rpc_xdr_encode (status 0)
[  782.949086] RPC:   210 marshaling UNIX cred 000000005a6be29a
[  782.949088] RPC:   210 using AUTH_UNIX cred 000000005a6be29a to

wrap

quoted

rpc data

quoted

[  782.949090] RPC:   210 xprt_transmit(192)
[  782.949091] RPC:   210 rpcrdma_marshal_req: inline/inline: hdrlen 28

rpclen

quoted

[  782.949093] RPC:       rpcrdma_ep_post: posting 2 s/g entries

--
Chuck Lever

  칻

 & ~ &   +-  ݶ  w  ˛   m b  kvf   ^n r   z   h    &  
 G   h ( 階 ݢj"   m

z ޖ

quoted

quoted

f   h   ~ m

--
Chuck Lever

N�����r��y���b�X��ǧv�^�)޺{.n�+����{��ٚ�{ay�
ʇڙ�,j��f���h�����/oSc��ڳ9�u�����&jw��(�階�ݢj"���m�����z�ޖ���f���h���~�m�