Date:   Mon, 18 Dec 2017 13:22:13 +0100
From:   Steffen Klassert <steffen.klassert@...unet.com>
To:     Darius Ski <darius.ski@...il.com>
CC:     <netdev@...r.kernel.org>
Subject: Re: BUG: 4.14.6 unable to handle kernel NULL pointer dereference at
 xfrm_output_resume

On Mon, Dec 18, 2017 at 01:50:10PM +0200, Darius Ski wrote:
> Hi,
> 
> running 4.14.6 with 3 IPSec tunnels via Racoon/setkey and today woke up to this:
> 
> [Mon Dec 18 07:26:15 2017] ------------[ cut here ]------------
> [Mon Dec 18 07:26:15 2017] WARNING: CPU: 0 PID: 10555 at
> ./include/net/dst.h:256 xfrm_resolve_and_create_bundle+0x97e/0x9b0
> [Mon Dec 18 07:26:15 2017] Modules linked in: smartpqi
> [Mon Dec 18 07:26:15 2017] CPU: 0 PID: 10555 Comm: java Not tainted 4.14.6 #1
> [Mon Dec 18 07:26:15 2017] Hardware name: HPE ProLiant DL380
> Gen10/ProLiant DL380 Gen10, BIOS U30 11/14/2017
> [Mon Dec 18 07:26:15 2017] task: ffff8852b33aca40 task.stack: ffffc9000fe88000
> [Mon Dec 18 07:26:15 2017] RIP: 0010:xfrm_resolve_and_create_bundle+0x97e/0x9b0
> [Mon Dec 18 07:26:15 2017] RSP: 0018:ffffc9000fe8ba40 EFLAGS: 00010246
> [Mon Dec 18 07:26:15 2017] RAX: 0000000000000000 RBX: ffff882a136b9540
> RCX: 00000000000005dc
> [Mon Dec 18 07:26:15 2017] RDX: ffffffff818bece0 RSI: 0000000000000000
> RDI: ffff882f73c3cd00
> [Mon Dec 18 07:26:15 2017] RBP: ffffc9000fe8bb40 R08: 00000000000000ff
> R09: 0000000000000002
> [Mon Dec 18 07:26:15 2017] R10: ffff885f741a0990 R11: ffff885f741a09a8
> R12: 0000000000000001
> [Mon Dec 18 07:26:15 2017] R13: 0000000000000006 R14: ffff882a136b9540
> R15: ffff882f73c3cd00
> [Mon Dec 18 07:26:15 2017] FS:  00007f86c239b700(0000)
> GS:ffff882f7f800000(0000) knlGS:0000000000000000
> [Mon Dec 18 07:26:15 2017] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [Mon Dec 18 07:26:15 2017] CR2: 00007f6b241d2000 CR3: 00000052c6274002
> CR4: 00000000001606f0
> [Mon Dec 18 07:26:15 2017] DR0: 0000000000000000 DR1: 0000000000000000
> DR2: 0000000000000000
> [Mon Dec 18 07:26:15 2017] DR3: 0000000000000000 DR6: 00000000fffe0ff0
> DR7: 0000000000000400
> [Mon Dec 18 07:26:15 2017] Call Trace:
> [Mon Dec 18 07:26:15 2017]  ? __dev_queue_xmit+0x229/0x560
> [Mon Dec 18 07:26:15 2017]  ? esp_output_tail+0x24f/0x570
> [Mon Dec 18 07:26:15 2017]  ? xfrm_policy_lookup_bytype.constprop.50+0x539/0x710
> [Mon Dec 18 07:26:15 2017]  ? xfrm_lookup+0x289/0x760
> [Mon Dec 18 07:26:15 2017]  xfrm_lookup+0x289/0x760
> [Mon Dec 18 07:26:15 2017]  ? ip_route_output_key_hash+0x5c/0x80
> [Mon Dec 18 07:26:15 2017]  xfrm_lookup_route+0x16/0x60
> [Mon Dec 18 07:26:15 2017]  ip_queue_xmit+0x335/0x3a0
> [Mon Dec 18 07:26:15 2017]  ? kmem_cache_alloc_node_trace+0x137/0x580
> [Mon Dec 18 07:26:15 2017]  ? __kmalloc_reserve.isra.41+0x2e/0x80
> [Mon Dec 18 07:26:15 2017]  tcp_transmit_skb+0x4c1/0x900
> [Mon Dec 18 07:26:15 2017]  tcp_write_xmit+0x1c3/0xfa0
> [Mon Dec 18 07:26:15 2017]  ? _copy_from_iter_full+0x93/0x230
> [Mon Dec 18 07:26:15 2017]  __tcp_push_pending_frames+0x2d/0xd0
> [Mon Dec 18 07:26:15 2017]  tcp_sendmsg_locked+0x663/0xe30
> [Mon Dec 18 07:26:15 2017]  ? tcp_poll+0x27c/0x290
> [Mon Dec 18 07:26:15 2017]  tcp_sendmsg+0x27/0x40
> [Mon Dec 18 07:26:15 2017]  sock_write_iter+0x95/0x110
> [Mon Dec 18 07:26:15 2017]  __vfs_write+0xf8/0x160
> [Mon Dec 18 07:26:15 2017]  vfs_write+0xb0/0x190
> [Mon Dec 18 07:26:15 2017]  SyS_write+0x52/0xc0
> [Mon Dec 18 07:26:15 2017]  ? SyS_epoll_wait+0x9c/0xe0
> [Mon Dec 18 07:26:15 2017]  entry_SYSCALL_64_fastpath+0x13/0x94
> [Mon Dec 18 07:26:15 2017] RIP: 0033:0x7f877661f1ad
> [Mon Dec 18 07:26:15 2017] RSP: 002b:00007f86c239a730 EFLAGS: 00000293
> ORIG_RAX: 0000000000000001
> [Mon Dec 18 07:26:15 2017] RAX: ffffffffffffffda RBX: 00000000e8e42860
> RCX: 00007f877661f1ad
> [Mon Dec 18 07:26:15 2017] RDX: 0000000000000007 RSI: 00007f86bc440f50
> RDI: 0000000000000ea9
> [Mon Dec 18 07:26:15 2017] RBP: 000000002000b3ad R08: 0000000000000007
> R09: 00000000e982ff48
> [Mon Dec 18 07:26:15 2017] R10: 0000000000004f34 R11: 0000000000000293
> R12: 0000000000000000
> [Mon Dec 18 07:26:15 2017] R13: 00000000fb287ba8 R14: 00000000c8ccca00
> R15: 00007f86bc43f800
> [Mon Dec 18 07:26:15 2017] Code: c7 c5 ed ff ff ff 4c 89 eb e9 d2 fb
> ff ff e8 4e 26 00 00 e8 95 2b a3 ff 85 c0 74 0f 8d 48 01 f0 0f b1 0a
> 0f 84 ba fe ff ff eb ed <0f> ff 44 8b a5 70 ff ff ff e9 b1 fe ff ff 48
> 63 db 49 89 dd e9
> [Mon Dec 18 07:26:15 2017] ---[ end trace 55978b2661bba1e7 ]---
> [Mon Dec 18 07:26:15 2017] BUG: unable to handle kernel NULL pointer
> dereference at 0000000000000018
> [Mon Dec 18 07:26:15 2017] IP: xfrm_output_resume+0x1bd/0x350
> [Mon Dec 18 07:26:15 2017] PGD 52c6372067 P4D 52c6372067 PUD 52f3453067 PMD 0
> [Mon Dec 18 07:26:15 2017] Oops: 0000 [#1] SMP
> [Mon Dec 18 07:26:15 2017] Modules linked in: smartpqi
> [Mon Dec 18 07:26:15 2017] CPU: 0 PID: 10555 Comm: java Tainted: G
>    W       4.14.6 #1
> [Mon Dec 18 07:26:15 2017] Hardware name: HPE ProLiant DL380
> Gen10/ProLiant DL380 Gen10, BIOS U30 11/14/2017
> [Mon Dec 18 07:26:15 2017] task: ffff8852b33aca40 task.stack: ffffc9000fe88000
> [Mon Dec 18 07:26:15 2017] RIP: 0010:xfrm_output_resume+0x1bd/0x350
> [Mon Dec 18 07:26:15 2017] RSP: 0018:ffffc9000fe8bc10 EFLAGS: 00010246
> [Mon Dec 18 07:26:15 2017] RAX: 0000000000000000 RBX: 0000000000000000
> RCX: 0000000000000000
> [Mon Dec 18 07:26:15 2017] RDX: 000000000000002f RSI: 0000000000000000
> RDI: 0000000000000000
> [Mon Dec 18 07:26:15 2017] RBP: ffff882f7729c990 R08: 000000000000000c
> R09: ffffc9000fe8ba18
> [Mon Dec 18 07:26:15 2017] R10: 000000000000000c R11: 00000000000008b8
> R12: ffffffff81cd6600
> [Mon Dec 18 07:26:15 2017] R13: ffff882c6d90e000 R14: ffff882c6d90e03c
> R15: 0000000000007180
> [Mon Dec 18 07:26:15 2017] FS:  00007f86c239b700(0000)
> GS:ffff882f7f800000(0000) knlGS:0000000000000000
> [Mon Dec 18 07:26:15 2017] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [Mon Dec 18 07:26:15 2017] CR2: 0000000000000018 CR3: 00000052c6274002
> CR4: 00000000001606f0
> [Mon Dec 18 07:26:15 2017] DR0: 0000000000000000 DR1: 0000000000000000
> DR2: 0000000000000000
> [Mon Dec 18 07:26:15 2017] DR3: 0000000000000000 DR6: 00000000fffe0ff0
> DR7: 0000000000000400
> [Mon Dec 18 07:26:15 2017] Call Trace:
> [Mon Dec 18 07:26:15 2017]  tcp_transmit_skb+0x4c1/0x900
> [Mon Dec 18 07:26:15 2017]  tcp_write_xmit+0x1c3/0xfa0
> [Mon Dec 18 07:26:15 2017]  ? _copy_from_iter_full+0x93/0x230
> [Mon Dec 18 07:26:15 2017]  __tcp_push_pending_frames+0x2d/0xd0
> [Mon Dec 18 07:26:15 2017]  tcp_sendmsg_locked+0x663/0xe30
> [Mon Dec 18 07:26:15 2017]  ? tcp_poll+0x27c/0x290
> [Mon Dec 18 07:26:15 2017]  tcp_sendmsg+0x27/0x40
> [Mon Dec 18 07:26:15 2017]  sock_write_iter+0x95/0x110
> [Mon Dec 18 07:26:15 2017]  __vfs_write+0xf8/0x160
> [Mon Dec 18 07:26:15 2017]  vfs_write+0xb0/0x190
> [Mon Dec 18 07:26:15 2017]  SyS_write+0x52/0xc0
> [Mon Dec 18 07:26:15 2017]  ? SyS_epoll_wait+0x9c/0xe0
> [Mon Dec 18 07:26:15 2017]  entry_SYSCALL_64_fastpath+0x13/0x94
> [Mon Dec 18 07:26:15 2017] RIP: 0033:0x7f877661f1ad
> [Mon Dec 18 07:26:15 2017] RSP: 002b:00007f86c239a730 EFLAGS: 00000293
> ORIG_RAX: 0000000000000001
> [Mon Dec 18 07:26:15 2017] RAX: ffffffffffffffda RBX: 00000000e8e42860
> RCX: 00007f877661f1ad
> [Mon Dec 18 07:26:15 2017] RDX: 0000000000000007 RSI: 00007f86bc440f50
> RDI: 0000000000000ea9
> [Mon Dec 18 07:26:15 2017] RBP: 000000002000b3ad R08: 0000000000000007
> R09: 00000000e982ff48
> [Mon Dec 18 07:26:15 2017] R10: 0000000000004f34 R11: 0000000000000293
> R12: 0000000000000000
> [Mon Dec 18 07:26:15 2017] R13: 00000000fb287ba8 R14: 00000000c8ccca00
> R15: 00007f86bc43f800
> [Mon Dec 18 07:26:15 2017] Code: f6 0f 8f ed fe ff ff 31 f6 85 d2 0f
> 8f e3 fe ff ff e9 f1 fe ff ff 85 f6 89 f3 0f 85 12 ff ff ff 48 8b 7d
> 58 48 89 f8 48 83 e0 fe <48> 8b 58 18 48 85 db 0f 84 e4 00 00 00 8b 83
> 80 00 00 00 85 c0
> [Mon Dec 18 07:26:15 2017] RIP: xfrm_output_resume+0x1bd/0x350 RSP:
> ffffc9000fe8bc10
> [Mon Dec 18 07:26:15 2017] CR2: 0000000000000018
> [Mon Dec 18 07:26:15 2017] ---[ end trace 55978b2661bba1e8 ]---
> 
> 
> Anyone got ideas what is going on? Java process 10555 is communicating
> via those IPSec tunnels and it used to run for year+ on 3.14 kernel
> and crashed within 2 days of moving to new server with 4.14.6.

Looks like a race in the new xfrm percpu dst cache. The old flow cache
ran the reslover routines with bottom halves disabled, the new percpu
cache does not and I think this is missing.

Can you please try this patch:

diff --git a/net/xfrm/xfrm_policy.c b/net/xfrm/xfrm_policy.c
index 6eb228a70131..b08c6c7991b5 100644
--- a/net/xfrm/xfrm_policy.c
+++ b/net/xfrm/xfrm_policy.c
@@ -2048,8 +2048,11 @@ xfrm_bundle_lookup(struct net *net, const struct flowi *fl, u16 family, u8 dir,
 	if (num_xfrms <= 0)
 		goto make_dummy_bundle;
 
+	local_bh_disable();
 	xdst = xfrm_resolve_and_create_bundle(pols, num_pols, fl, family,
 						  xflo->dst_orig);
+	local_bh_enable();
+
 	if (IS_ERR(xdst)) {
 		err = PTR_ERR(xdst);
 		if (err != -EAGAIN)
@@ -2136,9 +2139,12 @@ struct dst_entry *xfrm_lookup(struct net *net, struct dst_entry *dst_orig,
 				goto no_transform;
 			}
 
+			local_bh_disable();
 			xdst = xfrm_resolve_and_create_bundle(
 					pols, num_pols, fl,
 					family, dst_orig);
+			local_bh_enable();
+
 			if (IS_ERR(xdst)) {
 				xfrm_pols_put(pols, num_pols);
 				err = PTR_ERR(xdst);

Powered by blists - more mailing lists