Return-Path: Received: from userp1040.oracle.com ([156.151.31.81]:39669 "EHLO userp1040.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756963AbcJXVjB (ORCPT ); Mon, 24 Oct 2016 17:39:01 -0400 Content-Type: text/plain; charset=us-ascii Mime-Version: 1.0 (Mac OS X Mail 9.3 \(3124\)) Subject: Re: upstream server crash From: Chuck Lever In-Reply-To: <20161024204022.GB27359@fieldses.org> Date: Mon, 24 Oct 2016 17:38:11 -0400 Cc: Jeff Layton , Eryu Guan , Linux NFS Mailing List Message-Id: <58FE664A-94BE-4589-A3D1-D734284272A0@oracle.com> References: <20161023182115.GA14481@fieldses.org> <20161024031519.GN2462@eguan.usersys.redhat.com> <1477315868.2625.37.camel@redhat.com> <7B3F94BF-CAA1-4001-BEBC-C93965A81DE4@oracle.com> <1477322377.14828.4.camel@redhat.com> <1477322680.14828.6.camel@redhat.com> <20161024180858.GA27359@fieldses.org> <1477336654.21854.9.camel@redhat.com> <20161024204022.GB27359@fieldses.org> To: "J. Bruce Fields" Sender: linux-nfs-owner@vger.kernel.org List-ID: > On Oct 24, 2016, at 4:40 PM, J. Bruce Fields wrote: > > On Mon, Oct 24, 2016 at 03:17:34PM -0400, Jeff Layton wrote: >> On Mon, 2016-10-24 at 14:08 -0400, J. Bruce Fields wrote: >>> On Mon, Oct 24, 2016 at 11:24:40AM -0400, Jeff Layton wrote: >>>> >>>> On Mon, 2016-10-24 at 11:19 -0400, Jeff Layton wrote: >>>>> >>>>> On Mon, 2016-10-24 at 09:51 -0400, Chuck Lever wrote: >>>>>> >>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> On Oct 24, 2016, at 9:31 AM, Jeff Layton wrote: >>>>>>> >>>>>>> On Mon, 2016-10-24 at 11:15 +0800, Eryu Guan wrote: >>>>>>>> >>>>>>>> >>>>>>>> >>>>>>>> On Sun, Oct 23, 2016 at 02:21:15PM -0400, J. Bruce Fields wrote: >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> I'm getting an intermittent crash in the nfs server as of >>>>>>>>> 68778945e46f143ed7974b427a8065f69a4ce944 "SUNRPC: Separate buffer >>>>>>>>> pointers for RPC Call and Reply messages". >>>>>>>>> >>>>>>>>> I haven't tried to understand that commit or why it would be a problem yet, I >>>>>>>>> don't see an obvious connection--I can take a closer look Monday. >>>>>>>>> >>>>>>>>> Could even be that I just landed on this commit by chance, the problem is a >>>>>>>>> little hard to reproduce so I don't completely trust my testing. >>>>>>>> >>>>>>>> I've hit the same crash on 4.9-rc1 kernel, and it's reproduced for me >>>>>>>> reliably by running xfstests generic/013 case, on a loopback mounted >>>>>>>> NFSv4.1 (or NFSv4.2), XFS is the underlying exported fs. More details >>>>>>>> please see >>>>>>>> >>>>>>>> http://marc.info/?l=linux-nfs&m=147714320129362&w=2 >>>>>>>> >>>>>>> >>>>>>> Looks like you landed at the same commit as Bruce, so that's probably >>>>>>> legit. That commit is very small though. The only real change that >>>>>>> doesn't affect the new field is this: >>>>>>> >>>>>>> >>>>>>> @@ -1766,7 +1766,7 @@ rpc_xdr_encode(struct rpc_task *task) >>>>>>> req->rq_buffer, >>>>>>> req->rq_callsize); >>>>>>> xdr_buf_init(&req->rq_rcv_buf, >>>>>>> - (char *)req->rq_buffer + req->rq_callsize, >>>>>>> + req->rq_rbuffer, >>>>>>> req->rq_rcvsize); >>>>>>> >>>>>>> >>>>>>> So I'm guessing this is breaking the callback channel somehow? >>>>>> >>>>>> Could be the TCP backchannel code is using rq_buffer in a different >>>>>> way than RDMA backchannel or the forward channel code. >>>>>> >>>>> >>>>> Well, it basically allocates a page per rpc_rqst and then maps that. >>>>> >>>>> One thing I notice is that this patch ensures that rq_rbuffer gets set >>>>> up in rpc_malloc and xprt_rdma_allocate, but it looks like >>>>> xprt_alloc_bc_req didn't get the same treatment. >>>>> >>>>> I suspect that that may be the problem... >>>>> >>>> In fact, maybe we just need this here? (untested and probably >>>> whitespace damaged): >>> >>> No change in results for me. >>> >>> --b. >>>> >>>> >>>> diff --git a/net/sunrpc/backchannel_rqst.c b/net/sunrpc/backchannel_rqst.c >>>> index ac701c28f44f..c561aa8ce05b 100644 >>>> --- a/net/sunrpc/backchannel_rqst.c >>>> +++ b/net/sunrpc/backchannel_rqst.c >>>> @@ -100,6 +100,7 @@ struct rpc_rqst *xprt_alloc_bc_req(struct rpc_xprt *xprt, gfp_t gfp_flags) >>>> goto out_free; >>>> } >>>> req->rq_rcv_buf.len = PAGE_SIZE; >>>> + req->rq_rbuffer = req->rq_rcv_buf.head[0].iov_base; >>>> >>>> /* Preallocate one XDR send buffer */ >>>> if (xprt_alloc_xdr_buf(&req->rq_snd_buf, gfp_flags) < 0) { >> >> Ahh ok, I think I see. >> >> We probably also need to set rq_rbuffer in bc_malloc and and >> xprt_rdma_bc_allocate. >> >> My guess is that we're ending up in rpc_xdr_encode with a NULL >> rq_rbuffer pointer, so the right fix would seem to be to ensure that it >> is properly set whenever rq_buffer is set. >> >> So I think this may be what we want, actually. I'll plan to test it out >> but may not get to it before tomorrow. > > It passes here. Without Jeff's patch, my server locks up during generic/013 with NFS/RDMA and NFSv4.1. With it, I get all the way to generic/089, and then encounter this: Oct 24 17:31:11 klimt kernel: general protection fault: 0000 [#1] SMP Oct 24 17:31:11 klimt kernel: Modules linked in: cts rpcsec_gss_krb5 sb_edac edac_core x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm btrfs irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel iTCO_wdt iTCO_vendor_support aesni_intel lrw gf128mul glue_helper ablk_helper cryptd xor raid6_pq rpcrdma pcspkr i2c_i801 lpc_ich ib_ipoib i2c_smbus mfd_core mei_me sg mei rdma_ucm shpchp ioatdma wmi ib_ucm ipmi_si ipmi_msghandler ib_uverbs ib_umad rdma_cm ib_cm iw_cm acpi_pad acpi_power_meter nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c mlx4_ib ib_core mlx4_en sd_mod sr_mod cdrom ast drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm mlx4_core ahci libahci igb crc32c_intel ptp libata pps_core dca i2c_algo_bit i2c_core dm_mirror dm_region_hash dm_log dm_mod Oct 24 17:31:11 klimt kernel: CPU: 3 PID: 1681 Comm: nfsd Not tainted 4.9.0-rc2-00006-g0e8f985 #2 Oct 24 17:31:11 klimt kernel: Hardware name: Supermicro Super Server/X10SRL-F, BIOS 1.0c 09/09/2015 Oct 24 17:31:11 klimt kernel: task: ffff88083feb15c0 task.stack: ffffc900058a0000 Oct 24 17:31:11 klimt kernel: RIP: 0010:[] [] __kmalloc_track_caller+0x1b0/0x220 Oct 24 17:31:11 klimt kernel: RSP: 0018:ffffc900058a3b88 EFLAGS: 00010286 Oct 24 17:31:11 klimt kernel: RAX: 0000000000000000 RBX: 00000000024000c0 RCX: 0000000000293b6b Oct 24 17:31:11 klimt kernel: RDX: 0000000000293b6a RSI: 0000000000000000 RDI: 0000000000000002 Oct 24 17:31:11 klimt kernel: RBP: ffffc900058a3bc8 R08: 000000000001c560 R09: ffff88085f003a40 Oct 24 17:31:11 klimt kernel: R10: ffff88085f003a40 R11: ffff88083fc9b3c0 R12: 00000000024000c0 Oct 24 17:31:11 klimt kernel: R13: 0000000000000018 R14: ffff88081993d600 R15: c0d435750e5f8620 Oct 24 17:31:11 klimt kernel: FS: 0000000000000000(0000) GS:ffff88087fcc0000(0000) knlGS:0000000000000000 Oct 24 17:31:11 klimt kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Oct 24 17:31:11 klimt kernel: CR2: 00007fca9725a298 CR3: 0000000001c06000 CR4: 00000000001406e0 Oct 24 17:31:11 klimt kernel: Stack: Oct 24 17:31:11 klimt kernel: ffff88085f003a40 ffff88085f003a40 ffffffff812c227b 0000000000000018 Oct 24 17:31:11 klimt kernel: ffff880852ee6b00 ffff88085583a000 ffff88081993d600 ffff880839a95840 Oct 24 17:31:11 klimt kernel: ffffc900058a3be8 ffffffff811a65d0 ffff88081993d600 00000000024000c0 Oct 24 17:31:11 klimt kernel: Call Trace: Oct 24 17:31:11 klimt kernel: [] ? selinux_cred_prepare+0x1b/0x30 Oct 24 17:31:11 klimt kernel: [] kmemdup+0x20/0x50 Oct 24 17:31:11 klimt kernel: [] selinux_cred_prepare+0x1b/0x30 Oct 24 17:31:11 klimt kernel: [] security_prepare_creds+0x39/0x60 Oct 24 17:31:11 klimt kernel: [] prepare_creds+0x12f/0x150 Oct 24 17:31:11 klimt kernel: [] nfsd_setuser+0x8c/0x250 [nfsd] Oct 24 17:31:11 klimt kernel: [] nfsd_setuser_and_check_port+0x77/0xa0 [nfsd] Oct 24 17:31:11 klimt kernel: [] ? security_prepare_creds+0x39/0x60 Oct 24 17:31:11 klimt kernel: [] ? write_bytes_to_xdr_buf+0xa6/0xd0 [sunrpc] Oct 24 17:31:11 klimt kernel: [] fh_verify+0x5cc/0x610 [nfsd] Oct 24 17:31:11 klimt kernel: [] nfsd4_getattr+0x1b/0x80 [nfsd] Oct 24 17:31:11 klimt kernel: [] nfsd4_proc_compound+0x40d/0x690 [nfsd] Oct 24 17:31:11 klimt kernel: [] nfsd_dispatch+0xd4/0x1d0 [nfsd] Oct 24 17:31:11 klimt kernel: [] svc_process_common+0x3d9/0x700 [sunrpc] Oct 24 17:31:11 klimt kernel: [] svc_process+0xf1/0x1d0 [sunrpc] Oct 24 17:31:11 klimt kernel: [] nfsd+0xff/0x160 [nfsd] Oct 24 17:31:11 klimt kernel: [] ? nfsd_destroy+0x60/0x60 [nfsd] Oct 24 17:31:11 klimt kernel: [] kthread+0xe5/0xf0 Oct 24 17:31:11 klimt kernel: [] ? kthread_stop+0x120/0x120 Oct 24 17:31:11 klimt kernel: [] ret_from_fork+0x25/0x30 Oct 24 17:31:11 klimt kernel: Code: 85 d2 75 dd eb d3 48 89 c3 66 90 eb 6e 81 e3 00 00 10 00 0f 84 e4 fe ff ff 66 90 e9 e7 fe ff ff 49 63 42 20 48 8d 4a 01 4d 8b 02 <49> 8b 1c 07 4c 89 f8 65 49 0f c7 08 0f 94 c0 84 c0 0f 85 3b ff Oct 24 17:31:11 klimt kernel: RIP [] __kmalloc_track_caller+0x1b0/0x220 Oct 24 17:31:11 klimt kernel: RSP Oct 24 17:31:11 klimt kernel: ---[ end trace af2b44f9db7f5a36 ]--- This appears to be unrelated. Maybe. Bruce, do you have CONFIG_VMAP_STACK set? I took the default, just wondering if that was an especially safe thing to try. > --b. > >> >> -- >> Jeff Layton > >> From ef2a391bc4d8f6b729aacee7cde8d9baf86767c3 Mon Sep 17 00:00:00 2001 >> From: Jeff Layton >> Date: Mon, 24 Oct 2016 15:13:40 -0400 >> Subject: [PATCH] sunrpc: fix some missing rq_rbuffer assignments >> >> I think we basically need to set rq_rbuffer whenever rq_buffer is set. >> >> Signed-off-by: Jeff Layton >> --- >> net/sunrpc/xprtrdma/svc_rdma_backchannel.c | 1 + >> net/sunrpc/xprtsock.c | 1 + >> 2 files changed, 2 insertions(+) >> >> diff --git a/net/sunrpc/xprtrdma/svc_rdma_backchannel.c b/net/sunrpc/xprtrdma/svc_rdma_backchannel.c >> index 2d8545c34095..fc4535ead7c2 100644 >> --- a/net/sunrpc/xprtrdma/svc_rdma_backchannel.c >> +++ b/net/sunrpc/xprtrdma/svc_rdma_backchannel.c >> @@ -182,6 +182,7 @@ xprt_rdma_bc_allocate(struct rpc_task *task) >> return -ENOMEM; >> >> rqst->rq_buffer = page_address(page); >> + rqst->rq_rbuffer = (char *)rqst->rq_buffer + rqst->rq_callsize; >> return 0; >> } >> >> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c >> index 0137af1c0916..e01c825bc683 100644 >> --- a/net/sunrpc/xprtsock.c >> +++ b/net/sunrpc/xprtsock.c >> @@ -2563,6 +2563,7 @@ static int bc_malloc(struct rpc_task *task) >> buf->len = PAGE_SIZE; >> >> rqst->rq_buffer = buf->data; >> + rqst->rq_rbuffer = (char *)rqst->rq_buffer + rqst->rq_callsize; >> return 0; >> } >> >> -- >> 2.7.4 -- Chuck Lever