CPU soft lockup in a spin lock using tproxy and nfqueue

CPU soft lockup in a spin lock using tproxy and nfqueue

[Major Dávid]

Hi all, Hi Pablo,

Following comments on bug: https://bugzilla.netfilter.org/show_bug.cgi?id=1662

I researched a little bit further. I started to use older kernels from
Ubuntu mainline PPA to get a rough estimate about affected kernel versions.
At kernel version v3.18.140 still getting a soft lockup, I spun up a good
oldie' Ubuntu Precise VM environment to test older kernels. No nftables
support in Precise so I ported my test ruleset to iptables:

iptables -t mangle -F
iptables -t mangle -X

iptables -t mangle -A PREROUTING --match state --state NEW \
--protocol tcp --dport 80 --match mark ! --mark 0x80000000/0x80000000 \
--jump NFQUEUE --queue-num 0

iptables -t mangle -A PREROUTING --match state --state NEW \
--protocol tcp --dport 80 --match mark --mark 0x80000000/0x80000000 \
--jump CONNMARK --save-mark

iptables -t mangle -A PREROUTING --match connmark \
--mark 0x80000000/0x80000000 --protocol tcp --jump TPROXY \
--on-ip 127.0.0.1 --on-port 44444 --tproxy-mark 0x80000000/0x80000000

iptables -t mangle -A PREROUTING --match socket \
--transparent --jump MARK --set-mark 0x80000000/0x80000000

And for my surprise, I did not get any soft lockup on Precise with the
same v3.18.140 kernel as Jammy env had.

Using the above rules in Jammy, there is a soft lockup.

After comparing the lsmod output of the two systems I realized that
the iptables command on Jammy uses the nf_tables backend. Re-running
the test with the above ruleset, but changed to "iptables-legacy", on
Ubuntu Jammy I did not get any soft lockup.

I think the iptables code-path does not trigger the issue but nftables does.

I checked out the first commit were tproxy support was added to nftables:

4ed8eb6570a4 ("netfilter: nf_tables: Add native tproxy support", 2018-07-30)

And after a small adjustment in the nftables example rules (counter keyword not supported),
I got the soft lockup again in the Jammy env:

[ 1268.393958] watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [sample-queue-ha:957]
[ 1268.395321] Kernel panic - not syncing: softlockup: hung tasks
[ 1268.396132] CPU: 1 PID: 957 Comm: sample-queue-ha Tainted: G             L    4.18.0-rc6custom+ #1
[ 1268.397385] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.15.0-1 04/01/2014
[ 1268.398576] Call Trace:
[ 1268.399015]  <IRQ>
[ 1268.399406]  dump_stack+0x76/0xb5
[ 1268.399887]  panic+0xfd/0x322
[ 1268.400329]  watchdog_timer_fn+0x26c/0x2b0
[ 1268.400977]  ? watchdog+0x30/0x30
[ 1268.401470]  __hrtimer_run_queues+0x113/0x3c0
[ 1268.402084]  hrtimer_interrupt+0x110/0x370
[ 1268.402707]  smp_apic_timer_interrupt+0x7b/0x210
[ 1268.403367]  apic_timer_interrupt+0xf/0x20
[ 1268.403979] RIP: 0010:native_queued_spin_lock_slowpath+0x72/0x490
[ 1268.404763] Code: b1 23 85 c0 75 e8 48 8b 45 d0 65 48 33 04 25 28 00 00 00 0f 85 ef
03 00 00 48 83 c4 28 5b 41 5c 41 5d 41 5e 41 5f 5d c3 f3 90 <eb> c2 8b 45 bc 3d 00 01
00 00 0f 84 a5 01 00 00 30 c0 85 c0 0f 84
[ 1268.408080] RSP: 0018:ffff9a60ffc837f8 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff13
[ 1268.409374] RAX: 0000000000000001 RBX: ffffa6af0054fbc0 RCX: 0000000000000050
[ 1268.410499] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffa6af0054fbc0
[ 1268.411764] RBP: ffff9a60ffc83848 R08: 0000000000000000 R09: ffff9a60fb802330
[ 1268.413033] R10: ffffffff87466780 R11: ffff9a60f85c82dc R12: 0000000000000001
[ 1268.441802] R13: 0000000000000050 R14: ffff9a60f8710000 R15: ffffffff883df540
[ 1268.474297]  ? apic_timer_interrupt+0xa/0x20
[ 1268.506655]  ? sk_clone_lock+0x5b2/0x820
[ 1268.535705]  ? tcp_compressed_ack_kick+0xa0/0xa0
[ 1268.566980]  ? tcp_delack_timer_handler+0x2b0/0x2b0
[ 1268.598468]  _raw_spin_lock+0x21/0x30
[ 1268.625308]  __inet_inherit_port+0x97/0x300
[ 1268.650538]  ? tcp_assign_congestion_control+0x4c/0x280
[ 1268.676091]  ? tcp_create_openreq_child+0x395/0x5e0
[ 1268.699038]  tcp_v4_syn_recv_sock+0x2e4/0x690
[ 1268.724238]  tcp_get_cookie_sock+0x64/0x250
[ 1268.747900]  cookie_v4_check+0x6dd/0xf00
[ 1268.774811]  tcp_v4_do_rcv+0x222/0x320
[ 1268.799555]  tcp_v4_rcv+0x136a/0x1390
[ 1268.826036]  ip_local_deliver_finish+0x8b/0x3d0
[ 1268.850129]  ip_local_deliver+0x7c/0x170
[ 1268.875474]  ? inet_del_offload+0x40/0x40
[ 1268.896954]  ip_rcv_finish+0x72/0x110
[ 1268.919959]  ip_rcv+0x66/0x100
[ 1268.942994]  ? ip_rcv_finish_core.isra.0+0x710/0x710
[ 1268.964075]  __netif_receive_skb_one_core+0x64/0xa0
[ 1268.986015]  __netif_receive_skb+0x24/0x120
[ 1269.009437]  netif_receive_skb_internal+0x47/0x160
[ 1269.027549]  napi_gro_receive+0x11b/0x1b0
[ 1269.048952]  e1000_receive_skb+0xad/0x170 [e1000e]
[ 1269.069667]  ? __napi_alloc_skb+0xad/0x1d0
[ 1269.087054]  e1000_clean_rx_irq+0x356/0x630 [e1000e]
[ 1269.107997]  e1000e_poll+0xf3/0x400 [e1000e]
[ 1269.127928]  napi_poll+0xd9/0x360
[ 1269.145398]  net_rx_action+0xe0/0x3c0
[ 1269.164703]  __do_softirq+0x12f/0x52d
[ 1269.180301]  irq_exit+0x92/0xe0
[ 1269.198312]  do_IRQ+0xa3/0x140
[ 1269.215611]  common_interrupt+0xf/0xf
[ 1269.235155]  </IRQ>
[ 1269.253222] RIP: 0010:inet_bind_bucket_destroy+0x33/0xc0
[ 1269.269167] Code: 41 56 41 55 41 54 53 49 89 fe 48 89 f3 48 83 ec 10 65 48 8b 04 25
28 00 00 00 48 89 45 d8 31 c0 48 83 fe c8 74 5a 48 8b 43 38 <48> 85 c0 75 30 48 83 fb
d8 74 6b 4c 8b 6b 30 4c 8b 63 28 4d 85 ed
[ 1269.324560] RSP: 0018:ffffa6af008f73f0 EFLAGS: 00000293 ORIG_RAX: ffffffffffffffd5
[ 1269.363328] RAX: ffff9a60f8245a68 RBX: ffff9a60f93aea00 RCX: 0000000000000000
[ 1269.387817] RDX: 0000000000000001 RSI: ffff9a60f93aea00 RDI: ffff9a60fc99b680
[ 1269.410607] RBP: ffffa6af008f7420 R08: 0000000006422a0a R09: 0000000000000000
[ 1269.433872] R10: 0000000000000010 R11: ffffffff86f7a768 R12: ffff9a60f82455b8
[ 1269.459357] R13: ffff9a60f93aea00 R14: ffff9a60fc99b680 R15: ffffffff883df540
[ 1269.482675]  inet_twsk_bind_unhash+0x84/0x100
[ 1269.506983]  inet_twsk_kill+0x10d/0x1e0
[ 1269.531047]  inet_twsk_deschedule_put+0x25/0x30
[ 1269.554010]  nf_tproxy_handle_time_wait4+0x16b/0x200 [nf_tproxy_ipv4]
[ 1269.577850]  nft_tproxy_eval+0x5b1/0x9c6 [nft_tproxy]
[ 1269.602276]  nft_do_chain+0x172/0xb30 [nf_tables]
[ 1269.628693]  ? nft_tproxy_init+0x240/0x240 [nft_tproxy]
[ 1269.656098]  ? nft_do_chain+0x172/0xb30 [nf_tables]
[ 1269.679579]  ? consume_skb+0x47/0x100
[ 1269.703950]  ? security_sock_rcv_skb+0x2f/0x50
[ 1269.728455]  ? sk_filter_trim_cap+0x54/0x290
[ 1269.754011]  ? tcp_v4_do_rcv+0x111/0x320
[ 1269.777794]  ? tcp_v4_do_rcv+0x111/0x320
[ 1269.802569]  ? tcp_v4_rcv+0x136a/0x1390
[ 1269.827199]  ? ip_local_deliver_finish+0x8b/0x3d0
[ 1269.850628]  nft_do_chain_inet+0x8d/0x150 [nf_tables]
[ 1269.875429]  ? nft_do_chain_inet+0x8d/0x150 [nf_tables]
[ 1269.899376]  ? inet_del_offload+0x40/0x40
[ 1269.923031]  nf_reinject+0x11e/0x370
[ 1269.947908]  nfqnl_reinject+0x60/0x90 [nfnetlink_queue]
[ 1269.972695]  nfqnl_recv_verdict+0x46d/0xa80 [nfnetlink_queue]
[ 1269.994270]  ? nla_parse+0xe0/0x1f0
[ 1270.015330]  nfnetlink_rcv_msg+0x19d/0x520 [nfnetlink]
[ 1270.038142]  ? __accumulate_pelt_segments+0x2e/0x50
[ 1270.057147]  ? security_capable+0x3c/0x60
[ 1270.076403]  ? nfnetlink_net_exit_batch+0x110/0x110 [nfnetlink]
[ 1270.098143]  netlink_rcv_skb+0x4d/0x150
[ 1270.114926]  nfnetlink_rcv+0xa6/0x1c0 [nfnetlink]
[ 1270.135217]  netlink_unicast+0x1e1/0x320
[ 1270.151675]  netlink_sendmsg+0x426/0x610
[ 1270.170631]  sock_sendmsg+0x51/0xa0
[ 1270.187027]  ___sys_sendmsg+0x322/0x480
[ 1270.204820]  ? netlink_recvmsg+0x2a4/0x750
[ 1270.221160]  ? sock_recvmsg+0x5c/0xa0
[ 1270.239267]  ? __sys_recvfrom+0xf3/0x180
[ 1270.257812]  __sys_sendmsg+0x63/0xa0
[ 1270.274550]  ? __sys_sendmsg+0x63/0xa0
[ 1270.294016]  __x64_sys_sendmsg+0x28/0x40
[ 1270.310840]  do_syscall_64+0x66/0x210
[ 1270.328774]  ? prepare_exit_to_usermode+0x9c/0x110
[ 1270.345359]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1270.364286] RIP: 0033:0x7ff17d7cbb17
[ 1270.382162] Code: 0f 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b9 0f 1f 00 f3 0f 1e
fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 2e 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51
c3 48 83 ec 28 89 54 24 1c 48 89 74 24 10
[ 1270.442986] RSP: 002b:00007ffd06666018 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
[ 1270.484914] RAX: ffffffffffffffda RBX: 00005591b5934510 RCX: 00007ff17d7cbb17
[ 1270.510398] RDX: 0000000000000000 RSI: 00007ffd06666030 RDI: 0000000000000003
[ 1270.534988] RBP: 00007ffd06666090 R08: 0000000000000028 R09: 0000000000000301
[ 1270.558997] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
[ 1270.584564] R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000080
[ 1270.610953] Kernel Offset: 0x4600000 from 0xffffffff81000000 (relocation range:
0xffffffff80000000-0xffffffffbfffffff)
[ 1270.659917] ---[ end Kernel panic - not syncing: softlockup: hung tasks ]---

Re: CPU soft lockup in a spin lock using tproxy and nfqueue

[Florian Westphal]

Major Dávid <major.david@balasys.hu> wrote:
> Hi all, Hi Pablo,
> 
> Following comments on bug: https://bugzilla.netfilter.org/show_bug.cgi?id=1662
>
> I researched a little bit further. I started to use older kernels from
> Ubuntu mainline PPA to get a rough estimate about affected kernel versions.
> At kernel version v3.18.140 still getting a soft lockup, I spun up a good
> oldie' Ubuntu Precise VM environment to test older kernels. No nftables
> support in Precise so I ported my test ruleset to iptables:
> 
> iptables -t mangle -F
> iptables -t mangle -X

Thanks, this is a bug in nft_tproxy.c.

Can you test following fix?

Thanks!

Subject: netfilter: tproxy: fix deadlock due to missing BH disable

The xtables packet traverser performs an unconditional
local_bh_disable(), but the nf_tables evaluation loop does not.

Functions that are called from either xtables or nftables must assume
that they can be called in process context.

inet_twsk_deschedule_put() assumes that no softirq interrupt can occur.
If tproxy is used from nf_tables its possible that we'll deadlock
trying to aquire a lock already held in process context.

diff --git a/include/net/netfilter/nf_tproxy.h b/include/net/netfilter/nf_tproxy.h
--- a/include/net/netfilter/nf_tproxy.h
+++ b/include/net/netfilter/nf_tproxy.h
@@ -17,6 +17,13 @@ static inline bool nf_tproxy_sk_is_transparent(struct sock *sk)
 	return false;
 }
 
+static inline void nf_tproxy_twsk_deschedule_put(struct inet_timewait_sock *tw)
+{
+	local_bh_disable();
+	inet_twsk_deschedule_put(tw);
+	local_bh_enable();
+}
+
 /* assign a socket to the skb -- consumes sk */
 static inline void nf_tproxy_assign_sock(struct sk_buff *skb, struct sock *sk)
 {
diff --git a/net/ipv4/netfilter/nf_tproxy_ipv4.c b/net/ipv4/netfilter/nf_tproxy_ipv4.c
--- a/net/ipv4/netfilter/nf_tproxy_ipv4.c
+++ b/net/ipv4/netfilter/nf_tproxy_ipv4.c
@@ -38,7 +38,7 @@ nf_tproxy_handle_time_wait4(struct net *net, struct sk_buff *skb,
 					    hp->source, lport ? lport : hp->dest,
 					    skb->dev, NF_TPROXY_LOOKUP_LISTENER);
 		if (sk2) {
-			inet_twsk_deschedule_put(inet_twsk(sk));
+			nf_tproxy_twsk_deschedule_put(inet_twsk(sk));
 			sk = sk2;
 		}
 	}
diff --git a/net/ipv6/netfilter/nf_tproxy_ipv6.c b/net/ipv6/netfilter/nf_tproxy_ipv6.c
--- a/net/ipv6/netfilter/nf_tproxy_ipv6.c
+++ b/net/ipv6/netfilter/nf_tproxy_ipv6.c
@@ -63,7 +63,7 @@ nf_tproxy_handle_time_wait6(struct sk_buff *skb, int tproto, int thoff,
 					    lport ? lport : hp->dest,
 					    skb->dev, NF_TPROXY_LOOKUP_LISTENER);
 		if (sk2) {
-			inet_twsk_deschedule_put(inet_twsk(sk));
+			nf_tproxy_twsk_deschedule_put(inet_twsk(sk));
 			sk = sk2;
 		}
 	}

Re: CPU soft lockup in a spin lock using tproxy and nfqueue

[Major Dávid]

On 3/2/23 15:29, Florian Westphal wrote:
> Thanks, this is a bug in nft_tproxy.c.
> 
> Can you test following fix?
> 
> Thanks!

Thanks,

I builded and tested in my Jammy environment, and I could not reproduce
any soft lockups with this patch anymore.

But I am also wondering that the inet_twsk_deschedule_put is really
needed in this particular case in tproxy? As I understand it, there
is an other independent mechanism which destroys tw sockets, so no
need do it here?

Re: CPU soft lockup in a spin lock using tproxy and nfqueue

[Florian Westphal]

Major Dávid <major.david@balasys.hu> wrote:
> Thanks,
> 
> I builded and tested in my Jammy environment, and I could not reproduce
> any soft lockups with this patch anymore.

Thanks.

> But I am also wondering that the inet_twsk_deschedule_put is really
> needed in this particular case in tproxy? As I understand it, there
> is an other independent mechanism which destroys tw sockets, so no
> need do it here?

Which one?  As far as I can see TCP stack would end up adding a
duplicate quadruple to the hash if we only drop the reference and
keep the listen sk around.

And if we assign the tw socket to the skb TCP stack might not be able
to find the correct listener if the service is on a different port
than what is in the TCP header.

Did I miss anything?

Re: CPU soft lockup in a spin lock using tproxy and nfqueue

[Major Dávid]

On 3/3/23 01:09, Florian Westphal wrote:
> 
> Which one?  As far as I can see TCP stack would end up adding a
> duplicate quadruple to the hash if we only drop the reference and
> keep the listen sk around.

I just thought that tcp_timewait_state_process is called by TCP stack to
handle TW state, which actually call inet_twsk_deschedule_put parallel to tproxy and
that would be the root cause of the deadlock.

So I guess now, basically we would leak away the tw socket if we do not call put in tproxy?

Re: CPU soft lockup in a spin lock using tproxy and nfqueue

[Florian Westphal]

Major Dávid <major.david@balasys.hu> wrote:
> On 3/3/23 01:09, Florian Westphal wrote:
> > 
> > Which one?  As far as I can see TCP stack would end up adding a
> > duplicate quadruple to the hash if we only drop the reference and
> > keep the listen sk around.
> 
> I just thought that tcp_timewait_state_process is called by TCP stack to
> handle TW state, which actually call inet_twsk_deschedule_put parallel to tproxy and
> that would be the root cause of the deadlock.

No, it won't be called.

We can do two things:
1. Assign the tw sk to skb->sk, then its handled by
   tcp_timewait_state_process() in tcp stack.

Problem is that after the tw sk was handled, tcp stack won't find
a listener socket if the tproxy service is running on a different port.

2. Assign the listener socket to skb->sk (this is whats done now).

> So I guess now, basically we would leak away the tw socket if we do not call put in tproxy?

We could just drop the reference, but then, as far as i can see, we end
up with two identical connection entries in the ehash table.

Re: CPU soft lockup in a spin lock using tproxy and nfqueue

[Major Dávid]

On 3/3/23 10:33, Florian Westphal wrote:
>>
>> I just thought that tcp_timewait_state_process is called by TCP stack to
>> handle TW state, which actually call inet_twsk_deschedule_put parallel to tproxy and
>> that would be the root cause of the deadlock.
> 
> No, it won't be called.
> 
> We can do two things:
> 1. Assign the tw sk to skb->sk, then its handled by
>     tcp_timewait_state_process() in tcp stack.
> 
> Problem is that after the tw sk was handled, tcp stack won't find
> a listener socket if the tproxy service is running on a different port.
> 
> 2. Assign the listener socket to skb->sk (this is whats done now).
> 
>> So I guess now, basically we would leak away the tw socket if we do not call put in tproxy?
> 
> We could just drop the reference, but then, as far as i can see, we end
> up with two identical connection entries in the ehash table.

Okay, I agree with this, and thanks again the quick fix here.

When we could expect this in the mainline or 5.15 LTS?

Should I do someting further with the bugzilla ticket 1662?

Re: CPU soft lockup in a spin lock using tproxy and nfqueue

[Florian Westphal]

Major Dávid <major.david@balasys.hu> wrote:
> Okay, I agree with this, and thanks again the quick fix here.
> 
> When we could expect this in the mainline or 5.15 LTS?

I'll post the patch for merging in a few minutes, I just need
to add a proper fixes-tag so -stable team will know to which
kernel releases the patch needs to be applied to.