Re: [PATCH] SUNRPC: Fix a race in xs_reset_transport

["Suzuki K. Poulose" <Suzuki.Poulose@arm.com>]

On 15/09/15 19:52, Jeff Layton wrote:
> On Tue, 15 Sep 2015 16:49:23 +0100
> "Suzuki K. Poulose" <suzuki.poulose@arm.com> wrote:
>
>> From: "Suzuki K. Poulose" <suzuki.poulose@arm.com>
>>
>> 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 : [<ffffc000001b4920>] lr : [<ffffc000004d1974>] 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:
>> [<ffffc000001b4920>] iput+0x144/0x170
>> [<ffffc000004d1970>] sock_release+0xb8/0xdc
>> [<ffffc00000578df0>] xs_reset_transport+0x8c/0xac
>> [<ffffc00000578e60>] xs_close+0x50/0x6c
>> [<ffffc00000578e9c>] xs_destroy+0x20/0x5c
>> [<ffffc00000575f70>] xprt_destroy+0x68/0x8c
>> [<ffffc0000057777c>] xprt_put+0x24/0x30
>> [<ffffc000005726c4>] rpc_free_client+0x78/0xd8
>> [<ffffc0000057288c>] rpc_release_client+0x94/0xec
>> [<ffffc00000572aac>] rpc_shutdown_client+0x58/0x118
>> [<ffffc00000278588>] nfs_mount+0x100/0x234
>> [<ffffc0000026cc88>] nfs_request_mount+0xa8/0x12c
>> [<ffffc0000026e564>] nfs_try_mount+0x54/0x2b4
>> [<ffffc0000026f140>] nfs_fs_mount+0x5cc/0xac0
>> [<ffffc0000019f1a0>] mount_fs+0x38/0x158
>> [<ffffc000001b81a8>] vfs_kern_mount+0x48/0x11c
>> [<ffffc000001bb390>] do_mount+0x208/0xc04
>> [<ffffc000001bc0b0>] SyS_mount+0x78/0xd0
>> [<ffffc000007f0fa8>] mount_root+0x80/0x148
>> [<ffffc000007f11a8>] prepare_namespace+0x138/0x184
>> [<ffffc000007f0b20>] kernel_init_freeable+0x1cc/0x1f4
>> [<ffffc000005a2914>] 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 <suzuki.poulose@arm.com>
>> ---
>>   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