From: Chuck Lever <chuck.lever@oracle.com>
Subject: Re: [PATCH] sunrpc: xprt is not connected until after sock is set
Date: Mon, 2 Mar 2009 11:39:03 -0500
Message-ID: <8DF8CA77-399E-4BA3-A340-9FFF0A37A047@oracle.com>
References: <20090223201108.GB3308@merfinllc.com> <20090225023900.GD15475@sgi.com> <20090226001744.GB7613@merfinllc.com> <20090227235434.GH15475@sgi.com> <1235781463.20549.33.camel@heimdal.trondhjem.org> <20090228013457.GF7706@merfinllc.com> <1235785237.20549.51.camel@heimdal.trondhjem.org> <20090228050707.GB22330@merfinllc.com> <1235844568.7677.9.camel@heimdal.trondhjem.org> <20090302163600.GI15475@sgi.com>
Mime-Version: 1.0 (Apple Message framework v930.3)
Content-Type: text/plain; charset=US-ASCII; format=flowed; delsp=yes
Cc: Aaron Straus <aaron-bYFJunmd+ZV8UrSeD/g0lQ@public.gmane.org>, Ben Myers <bpm@sgi.com>,
	"J. Bruce Fields" <bfields@fieldses.org>,
	Linux NFS Mailing List <linux-nfs@vger.kernel.org>,
	Neil Brown <neilb@suse.de>
To: Trond Myklebust <Trond.Myklebust@netapp.com>
Return-path: <linux-nfs-owner@vger.kernel.org>
Received: from rcsinet12.oracle.com ([148.87.113.124]:32491 "EHLO
	rgminet12.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1753929AbZCBQjd (ORCPT
	<rfc822;linux-nfs@vger.kernel.org>); Mon, 2 Mar 2009 11:39:33 -0500
In-Reply-To: <20090302163600.GI15475@sgi.com>
Sender: linux-nfs-owner@vger.kernel.org
List-ID: <linux-nfs.vger.kernel.org>

On Mar 2, 2009, at Mar 2, 2009, 11:36 AM, Ben Myers wrote:
> Hi Trond,
>
> On Sat, Feb 28, 2009 at 01:09:28PM -0500, Trond Myklebust wrote:
>> On Fri, 2009-02-27 at 21:07 -0800, Aaron Straus wrote:
>>> It seems like xs_sendpages does check if sock is NULL and returns
>>> -ENOTCONN in that case.
>
> Here's a trace that shows the above:
>
> Starting kernel based NFS server: idmapd mountd statd  
> nfsdrpc.nfsd[4502]: NaT co
> nsumption 17179869216 [1]
> Modules linked in: nfsd lockd nfs_acl auth_rpcgss sunrpc exportfs  
> ib_ipoib ib_cm
> ib_sa ipv6 ib_uverbs ib_umad iw_cxgb3 cxgb3 mlx4_en mlx4_ib  
> mlx4_core binfmt_mi
> sc fuse dm_crypt crypto_blkcipher nls_iso8859_1 loop dm_mod sr_mod  
> cdrom ib_mthc
> a tg3 ib_mad shpchp sg ib_core button libphy pci_hotplug qla2xxx  
> mptctl usbhid h
> id ff_memless ohci_hcd ehci_hcd usbcore sd_mod crc_t10dif  
> ide_generic mptfc scsi
> _transport_fc scsi_tgt mptspi scsi_transport_spi qla1280 sata_vsc  
> sgiioc4 ioc4 x
> fs fan ide_pci_generic siimage ide_core mptsas mptscsih mptbase  
> scsi_transport_s
> as thermal processor thermal_sys hwmon pata_sil680 libata scsi_mod  
> dock
> Supported: Yes
>
> Pid: 4502, CPU 2, comm:             rpc.nfsd
> psr : 0000101008526030 ifs : 800000000000040d ip  :  
> [<a0000002044acf30>]    Not
> tainted (2.6.27.15-2-default)
> ip is at xs_udp_send_request+0x270/0x340 [sunrpc]
> unat: 0000000000000000 pfs : 000000000000040d rsc : 0000000000000003
> rnat: 0000000000000000 bsps: 0000000000000000 pr  : aa99aaa6aa5aa999
> ldrs: 0000000000000000 ccv : 0000000000000000 fpsr: 0009804c8a70033f
> csd : 0000000000000000 ssd : 0000000000000000
> b0  : a0000002044acd30 b6  : a0000002044accc0 b7  : a0000002044c8fe0
> f6  : 1003e000000000000222e f7  : 1003e00000000000004e2
> f8  : 1003e00000000000009c4 f9  : 1003e0000001f3eb1b6ce
> f10 : 1003e93b691609417c0ec f11 : 1003e0000000000000013
> r1  : a0000002044d9760 r2  : a000000204511ba0 r3  : a000000204511ba0
> r8  : ffffffffffffff95 r9  : e0000060431825a8 r10 : a000000204511ce0
> r11 : 0000000000000000 r12 : e0000060434cfc30 r13 : e0000060434c0000
> r14 : 0000000000000000 r15 : e00000607bd79198 r16 : a0000002044e9fa8
> r17 : e000006078fc6040 r18 : 0000000000000054 r19 : e000006043182668
> r20 : ffffffffffffff95 r21 : 00000001000023ca r22 : e000006078fc6148
> r23 : a000000100efa780 r24 : a000000204511ce0 r25 : 0000000000000000
> r26 : e000006078fc613c r27 : e00000607bd795a8 r28 : 0000000000000000
> r29 : e00000607bd796e0 r30 : 0000000000000000 r31 : e00000607b3dc000
>
> Call Trace:
> [<a000000100016a30>] show_stack+0x50/0xa0
>                                sp=e0000060434cf790  
> bsp=e0000060434c1720
> [<a0000001000172a0>] show_regs+0x820/0x860
>                                sp=e0000060434cf960  
> bsp=e0000060434c16c8
> [<a0000001000266a0>] die+0x1a0/0x2e0
>                                sp=e0000060434cf960  
> bsp=e0000060434c1688
> [<a000000100026830>] die_if_kernel+0x50/0x80
>                                sp=e0000060434cf960  
> bsp=e0000060434c1658
> [<a0000001006e79a0>] ia64_fault+0xac0/0xb60
>                                sp=e0000060434cf960  
> bsp=e0000060434c1610
> [<a00000010000c7a0>] ia64_native_leave_kernel+0x0/0x270
>                                sp=e0000060434cfa60  
> bsp=e0000060434c1610
> [<a0000002044acf30>] xs_udp_send_request+0x270/0x340 [sunrpc]
>                                sp=e0000060434cfc30  
> bsp=e0000060434c15a0
> [<a0000002044a9a20>] xprt_transmit+0x3a0/0x620 [sunrpc]
>                                sp=e0000060434cfc30  
> bsp=e0000060434c1560
> [<a0000002044a28a0>] call_transmit+0x600/0x720 [sunrpc]
>                                sp=e0000060434cfc30  
> bsp=e0000060434c1520
> [<a0000002044b5690>] __rpc_execute+0x1d0/0x7a0 [sunrpc]
>                                sp=e0000060434cfc30  
> bsp=e0000060434c14a0
> [<a0000002044b5ce0>] rpc_execute+0x80/0xa0 [sunrpc]
>                                sp=e0000060434cfc30  
> bsp=e0000060434c1480
> [<a0000002044a43d0>] rpc_run_task+0xf0/0x120 [sunrpc]
>                                sp=e0000060434cfc30  
> bsp=e0000060434c1460
> [<a0000002044a46e0>] rpc_call_sync+0xe0/0x160 [sunrpc]
>                                sp=e0000060434cfc30  
> bsp=e0000060434c1430
> [<a0000002044ca500>] rpcb_register_call+0x120/0x220 [sunrpc]
>                                sp=e0000060434cfc70  
> bsp=e0000060434c13e8
> [<a0000002044ca7b0>] rpcb_register+0x1b0/0x1e0 [sunrpc]
>                                sp=e0000060434cfcc0  
> bsp=e0000060434c1398
> [<a0000002044bd200>] svc_register+0x1e0/0x360 [sunrpc]
>                                sp=e0000060434cfd20  
> bsp=e0000060434c1310
> [<a0000002044c0c50>] svc_setup_socket+0x150/0x9a0 [sunrpc]
>                                sp=e0000060434cfd30  
> bsp=e0000060434c12c0
> [<a0000002044c3e10>] svc_addsock+0x1d0/0x480 [sunrpc]
>                                sp=e0000060434cfd40  
> bsp=e0000060434c1270
> [<a000000204b52550>] write_ports+0x1f0/0x6c0 [nfsd]
>                                sp=e0000060434cfdd0  
> bsp=e0000060434c1228
> [<a000000204b54270>] nfsctl_transaction_write+0xf0/0x1c0 [nfsd]
>                                sp=e0000060434cfe20  
> bsp=e0000060434c11e8
> [<a0000001001b6a90>] vfs_write+0x1b0/0x360
>                                sp=e0000060434cfe20  
> bsp=e0000060434c1198
> [<a0000001001b6de0>] sys_write+0x80/0x100
>                                sp=e0000060434cfe20  
> bsp=e0000060434c1120
> [<a00000010000c600>] ia64_ret_from_syscall+0x0/0x20
>                                sp=e0000060434cfe30  
> bsp=e0000060434c1120
> [<a000000000010720>] __kernel_syscall_via_break+0x0/0x20
>                                sp=e0000060434d0000  
> bsp=e0000060434c1120
>
> If I read it correctly the xs_sendpages return value is in r8, - 
> ENOTCONN.  We
> had xs_udp_finish_connecting in rpciod racing with the above write.

I had a patch that addressed a similar race in the UDP connect logic.   
Trond, did you get that one when I sent it before Connectathon?

--
Chuck Lever
chuck[dot]lever[at]oracle[dot]com