Return-Path: Received: from eu-smtp-delivery-143.mimecast.com ([207.82.80.143]:60661 "EHLO eu-smtp-delivery-143.mimecast.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752007AbbIPIIM convert rfc822-to-8bit (ORCPT ); Wed, 16 Sep 2015 04:08:12 -0400 Message-ID: <55F92368.2010004@arm.com> Date: Wed, 16 Sep 2015 09:08:08 +0100 From: "Suzuki K. Poulose" MIME-Version: 1.0 To: Jeff Layton CC: Trond Myklebust , Anna Schumaker , "J. Bruce Fields" , "David S. Miller" , "linux-nfs@vger.kernel.org" , "linux-kernel@vger.kernel.org" Subject: Re: [PATCH] SUNRPC: Fix a race in xs_reset_transport References: <1442332163-9230-1-git-send-email-suzuki.poulose@arm.com> <20150915145229.4e69d5f7@synchrony.poochiereds.net> In-Reply-To: <20150915145229.4e69d5f7@synchrony.poochiereds.net> Content-Type: text/plain; charset=WINDOWS-1252; format=flowed Sender: linux-nfs-owner@vger.kernel.org List-ID: On 15/09/15 19:52, Jeff Layton wrote: > On Tue, 15 Sep 2015 16:49:23 +0100 > "Suzuki K. Poulose" wrote: > >> From: "Suzuki K. Poulose" >> >> Encountered the following BUG() with 4.3-rc1 on a fast model >> for arm64 with NFS root filesystem. >> >> ------------[ cut here ]------------ >> kernel BUG at fs/inode.c:1493! >> >> Internal error: Oops - BUG: 0 [#1] PREEMPT SMP >> Modules linked in: >> CPU: 2 PID: 1 Comm: swapper/0 Not tainted 4.3.0-rc1+ #855 >> Hardware name: FVP Base (DT) >> task: ffffc000760b0000 ti: ffffc00076070000 task.ti: ffffc00076070000 >> PC is at iput+0x144/0x170 >> LR is at sock_release+0xbc/0xdc >> pc : [] lr : [] pstate: 40000045 >> sp : ffffc00076073790 >> x29: ffffc00076073790 x28: ffffc00076073b40 >> x27: 00000000000003e8 x26: ffffc00076955000 >> x25: 000000000000000c x24: ffffc00076637200 >> x23: ffffc00076073930 x22: ffffc000769b8180 >> x21: ffffc000740500a8 x20: ffffc00074050158 >> x19: ffffc00074050030 x18: 000000009fcef6bf >> x17: 00000000593e3df5 x16: 00000000b597f71d >> x15: 00000000e2f9d3f6 x14: 0ffffffffffffffe >> x13: 0000000000000020 x12: 0101010101010101 >> x11: 00000000000001c9 x10: 0000000000000750 >> x9 : ffffc00076073670 x8 : ffffc000760b07b0 >> x7 : 0000000000000001 x6 : 0000000000000001 >> x5 : 0000000000000000 x4 : 00000000ffffffff >> x3 : 0000000000000000 x2 : ffffffffffffffff >> x1 : ffffc00076070000 x0 : 0000000000000060 >> >> Process swapper/0 (pid: 1, stack limit = 0xffffc00076070020) >> Stack: (0xffffc00076073790 to 0xffffc00076074000) >> >> [ stack contents stripped ] >> >> Call trace: >> [] iput+0x144/0x170 >> [] sock_release+0xb8/0xdc >> [] xs_reset_transport+0x8c/0xac >> [] xs_close+0x50/0x6c >> [] xs_destroy+0x20/0x5c >> [] xprt_destroy+0x68/0x8c >> [] xprt_put+0x24/0x30 >> [] rpc_free_client+0x78/0xd8 >> [] rpc_release_client+0x94/0xec >> [] rpc_shutdown_client+0x58/0x118 >> [] nfs_mount+0x100/0x234 >> [] nfs_request_mount+0xa8/0x12c >> [] nfs_try_mount+0x54/0x2b4 >> [] nfs_fs_mount+0x5cc/0xac0 >> [] mount_fs+0x38/0x158 >> [] vfs_kern_mount+0x48/0x11c >> [] do_mount+0x208/0xc04 >> [] SyS_mount+0x78/0xd0 >> [] mount_root+0x80/0x148 >> [] prepare_namespace+0x138/0x184 >> [] kernel_init_freeable+0x1cc/0x1f4 >> [] kernel_init+0xc/0xd8 >> Code: b5fffc00 17ffffed d4210000 17ffffd7 (d4210000) >> ---[ end trace 02951451f1831f54 ]--- >> >> With rpc_debug enabled here is the log : >> >> RPC: shutting down mount client for your.nfs.server >> RPC: rpc_release_client(ffffc00076637800) >> RPC: destroying UNIX authenticator ffffc000008f48c8 >> RPC: destroying mount client for your.nfs.server >> RPC: destroying transport ffffc00076226000 >> RPC: xs_destroy xprt ffffc00076226000 >> RPC: xs_close xprt ffffc00076226000 >> RPC: xs_tcp_state_change client ffffc00076226000... >> RPC: state 4 conn 1 dead 0 zapped 1 sk_shutdown 3 >> RPC: xs_tcp_state_change client ffffc00076226000... >> RPC: state 5 conn 0 dead 0 zapped 1 sk_shutdown 3 >> RPC: xs_tcp_state_change client ffffc00076226000... >> RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3 >> RPC: disconnected transport ffffc00076226000 >> RPC: xs_tcp_state_change client ffffc00076226000... >> RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3 >> RPC: disconnected transport ffffc00076226000 >> RPC: xs_tcp_data_ready... >> RPC: xs_tcp_state_change client ffffc00076226000... >> RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3 >> RPC: disconnected transport ffffc00076226000 >> RPC: wake_up_first(ffffc00076226170 "xprt_sending") >> >> So it looks like just before we lock the callbacks in xs_reset_transport, >> a few of the callbacks got through and issued the reset before we could >> lock it. And we end up repeating the cleanups, ending up in the above >> BUG() due to multiple sock_release(). >> >> This patch fixes the race by confirming that somebody else hasn't performed >> the reset while we were waiting for the lock. Also, the kernel_shutdown() >> is performed only if the sock is non-NULL to avoid a possible race. >> >> Signed-off-by: Suzuki K. Poulose >> --- >> net/sunrpc/xprtsock.c | 9 ++++++++- >> 1 file changed, 8 insertions(+), 1 deletion(-) >> >> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c >> index 7be90bc..6f4789d 100644 >> --- a/net/sunrpc/xprtsock.c >> +++ b/net/sunrpc/xprtsock.c >> @@ -822,9 +822,16 @@ static void xs_reset_transport(struct sock_xprt *transport) >> if (atomic_read(&transport->xprt.swapper)) >> sk_clear_memalloc(sk); >> >> - kernel_sock_shutdown(sock, SHUT_RDWR); >> + if (sock) >> + kernel_sock_shutdown(sock, SHUT_RDWR); >> > > Good catch, but...isn't this still racy? What prevents transport->sock > being set to NULL after you assign it to "sock" but before calling > kernel_sock_shutdown? You might end up calling that on a socket that > has already had sock_release called on it. I believe that would be a bad > thing. You are right. I had a try with moving the kernel_sock_shutdown() under the lock, but then it would cause lockups, hence left it there. I should have paid more attention to the kernel_sock_shutdown() which I assumed would be safe :). Thanks for spotting. I will send an updated version. Thanks Suzuki