Alexei Starovoitov wrote:
> On Fri, Apr 7, 2023 at 10:17 AM John Fastabend <john.fastabend@xxxxxxxxx> wrote:
> >
> > We noticed some rare sk_buffs were stepping past the queue when system was
> > under memory pressure. The general theory is to skip enqueueing
> > sk_buffs when its not necessary which is the normal case with a system
> > that is properly provisioned for the task, no memory pressure and enough
> > cpu assigned.
> >
> > But, if we can't allocate memory due to an ENOMEM error when enqueueing
> > the sk_buff into the sockmap receive queue we push it onto a delayed
> > workqueue to retry later. When a new sk_buff is received we then check
> > if that queue is empty. However, there is a problem with simply checking
> > the queue length. When a sk_buff is being processed from the ingress queue
> > but not yet on the sockmap msg receive queue its possible to also recv
> > a sk_buff through normal path. It will check the ingress queue which is
> > zero and then skip ahead of the pkt being processed.
> >
> > Previously we used sock lock from both contexts which made the problem
> > harder to hit, but not impossible.
> >
> > To fix also check the 'state' variable where we would cache partially
> > processed sk_buff. This catches the majority of cases. But, we also
> > need to use the mutex lock around this check because we can't have both
> > codes running and check sensibly. We could perhaps do this with atomic
> > bit checks, but we are already here due to memory pressure so slowing
> > things down a bit seems OK and simpler to just grab a lock.
> >
> > To reproduce issue we run NGINX compliance test with sockmap running and
> > observe some flakes in our testing that we attributed to this issue.
> >
> > Fixes: 04919bed948dc ("tcp: Introduce tcp_read_skb()")
> > Tested-by: William Findlay <will@xxxxxxxxxxxxx>
> > Signed-off-by: John Fastabend <john.fastabend@xxxxxxxxx>
> > ---
> > net/core/skmsg.c | 20 +++++++++++++++++++-
> > 1 file changed, 19 insertions(+), 1 deletion(-)
> >
> > diff --git a/net/core/skmsg.c b/net/core/skmsg.c
> > index 198bed303c51..f8731818b5c3 100644
> > --- a/net/core/skmsg.c
> > +++ b/net/core/skmsg.c
> > @@ -987,6 +987,7 @@ EXPORT_SYMBOL_GPL(sk_psock_tls_strp_read);
> > static int sk_psock_verdict_apply(struct sk_psock *psock, struct sk_buff *skb,
> > int verdict)
> > {
> > + struct sk_psock_work_state *state;
> > struct sock *sk_other;
> > int err = 0;
> > u32 len, off;
> > @@ -1003,13 +1004,28 @@ static int sk_psock_verdict_apply(struct sk_psock *psock, struct sk_buff *skb,
> >
> > skb_bpf_set_ingress(skb);
> >
> > + /* We need to grab mutex here because in-flight skb is in one of
> > + * the following states: either on ingress_skb, in psock->state
> > + * or being processed by backlog and neither in state->skb and
> > + * ingress_skb may be also empty. The troublesome case is when
> > + * the skb has been dequeued from ingress_skb list or taken from
> > + * state->skb because we can not easily test this case. Maybe we
> > + * could be clever with flags and resolve this but being clever
> > + * got us here in the first place and we note this is done under
> > + * sock lock and backlog conditions mean we are already running
> > + * into ENOMEM or other performance hindering cases so lets do
> > + * the obvious thing and grab the mutex.
> > + */
> > + mutex_lock(&psock->work_mutex);
> > + state = &psock->work_state;
>
> This splat says that above is wrong:
>
> [ 98.732763] BUG: sleeping function called from invalid context at
> kernel/locking/mutex.c:580
> [ 98.733483] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid:
> 370, name: test_progs
> [ 98.734103] preempt_count: 102, expected: 0
> [ 98.734416] RCU nest depth: 4, expected: 0
> [ 98.734739] 6 locks held by test_progs/370:
> [ 98.735046] #0: ffff888106475530 (sk_lock-AF_INET){+.+.}-{0:0},
> at: inet_shutdown+0x43/0x150
> [ 98.735695] #1: ffffffff84250ba0 (rcu_read_lock){....}-{1:2}, at:
> __ip_queue_xmit+0x5/0xa00
> [ 98.736325] #2: ffffffff84250ba0 (rcu_read_lock){....}-{1:2}, at:
> process_backlog+0xc0/0x360
> [ 98.736971] #3: ffffffff84250ba0 (rcu_read_lock){....}-{1:2}, at:
> ip_local_deliver_finish+0xbb/0x220
> [ 98.737668] #4: ffff8881064748b0 (slock-AF_INET/1){+.-.}-{2:2},
> at: tcp_v4_rcv+0x1b72/0x1d80
> [ 98.738297] #5: ffffffff84250ba0 (rcu_read_lock){....}-{1:2}, at:
> sk_psock_verdict_recv+0x5/0x3a0
> [ 98.738973] Preemption disabled at:
> [ 98.738976] [<ffffffff8238bb41>] ip_finish_output2+0x171/0xfa0
> [ 98.739687] CPU: 1 PID: 370 Comm: test_progs Tainted: G O
> 6.3.0-rc5-00193-g9149a3b041d2 #942
> [ 98.740379] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
> BIOS rel-1.12.0-59-gc9ba5276e321-prebuilt.qemu.org 04/01/2014
> [ 98.741164] Call Trace:
> [ 98.741338] <IRQ>
> [ 98.741483] dump_stack_lvl+0x60/0x70
> [ 98.741735] __might_resched+0x21c/0x340
> [ 98.742005] __mutex_lock+0xb4/0x12a0
> [ 98.743721] ? mutex_lock_io_nested+0x1070/0x1070
> [ 98.744053] ? lock_is_held_type+0xda/0x130
> [ 98.744337] ? preempt_count_sub+0x14/0xc0
> [ 98.744624] ? sk_psock_verdict_apply+0x1a3/0x2f0
> [ 98.744936] sk_psock_verdict_apply+0x1a3/0x2f0
> [ 98.745242] ? preempt_count_sub+0x14/0xc0
> [ 98.745530] sk_psock_verdict_recv+0x1e7/0x3a0
> [ 98.745858] ? preempt_count_sub+0x14/0xc0
> [ 98.746168] tcp_read_skb+0x19c/0x2d0
> [ 98.746447] ? sk_psock_strp_read+0x390/0x390
> [ 98.746774] ? tcp_alloc_md5sig_pool+0x230/0x230
> [ 98.747116] ? rcu_read_lock_held+0x91/0xa0
> [ 98.747427] ? rcu_read_lock_sched_held+0xc0/0xc0
> [ 98.747772] ? __rcu_read_unlock+0x6b/0x2a0
> [ 98.748087] sk_psock_verdict_data_ready+0x99/0x2d0
> [ 98.748446] tcp_data_queue+0xd39/0x19b0
> [ 98.748749] ? tcp_send_rcvq+0x280/0x280
> [ 98.749038] ? tcp_urg+0x7f/0x4c0
> [ 98.749298] ? tcp_ack_update_rtt.isra.55+0x910/0x910
> [ 98.749644] ? lockdep_hardirqs_on+0x79/0x100
> [ 98.749940] ? ktime_get+0x112/0x120
> [ 98.750225] ? ktime_get+0x86/0x120
> [ 98.750498] tcp_rcv_established+0x3fb/0xcc0
> [ 98.752087] tcp_v4_do_rcv+0x34a/0x4c0
> [ 98.752400] tcp_v4_rcv+0x1c9a/0x1d80
> [ 98.754137] ip_protocol_deliver_rcu+0x4f/0x4d0
> [ 98.754562] ip_local_deliver_finish+0x146/0x220
> [ 98.754928] ip_local_deliver+0x100/0x2e0
> [ 98.756055] ip_rcv+0xb6/0x2b0
> [ 98.757689] __netif_receive_skb_one_core+0xd2/0x110
> [ 98.759121] process_backlog+0x160/0x360
> [ 98.759446] __napi_poll+0x57/0x300
> [ 98.759725] net_rx_action+0x555/0x600
> [ 98.760029] ? napi_threaded_poll+0x2b0/0x2b0
> [ 98.760444] __do_softirq+0xeb/0x4e7
> [ 98.760728] ? ip_finish_output2+0x391/0xfa0
> [ 98.761059] do_softirq+0xa1/0xd0
>
> I'm afraid I have to revert this set from bpf tree.
OK thanks. We also got a syzkaller complaint so will fix these two things.
