Message-ID: <CANpmjNNx6QM67jSaAtkYdxA+A5_FGPLBkBxdVXQ_XOLB8pgzNw@mail.gmail.com>
Date: Wed, 23 Oct 2024 11:03:11 +0200
From: Marco Elver <elver@...gle.com>
To: Peter Zijlstra <peterz@...radead.org>
Cc: paulmck@...nel.org, Alexander Potapenko <glider@...gle.com>, 
	syzbot <syzbot+0ec1e96c2cdf5c0e512a@...kaller.appspotmail.com>, 
	audit@...r.kernel.org, eparis@...hat.com, linux-kernel@...r.kernel.org, 
	paul@...l-moore.com, syzkaller-bugs@...glegroups.com
Subject: Re: [syzbot] [kernel?] KCSAN: assert: race in dequeue_entities

On Wed, 23 Oct 2024 at 10:54, Marco Elver <elver@...gle.com> wrote:
>
> On Tue, Oct 22, 2024 at 09:57PM +0200, Marco Elver wrote:
> > On Tue, 22 Oct 2024 at 21:12, Peter Zijlstra <peterz@...radead.org> wrote:
> [...]
> > > So KCSAn is trying to tell me these two paths run concurrently on the
> > > same 'p' ?!? That would be a horrible bug -- both these call chains
> > > should be holding rq->__lock (for task_rq(p)).
> >
> > Yes correct.
> >
> > And just to confirm this is no false positive, the way KCSAN works
> > _requires_ the race to actually happen before it reports anything;
> > this can also be seen in Alexander's report with just 1 stack trace
> > where it saw the value transition from 0 to 1 (TASK_ON_RQ_QUEUED) but
> > didn't know who did the write because kernel/sched was uninstrumented.
>
> Got another version of the splat with CONFIG_KCSAN_VERBOSE=y. Lockdep seems to
> think that both threads here are holding rq->__lock.

Gotta read more carefully, one instance is ffffa2e57dc2f398 another is
ffffa2e57dd2f398. If I read it right, then they're not actually the
same lock.

> | ==================================================================
> | BUG: KCSAN: assert: race in activate_task / dequeue_entities
> |
> | write (marked) to 0xffffa2e506240068 of 4 bytes by interrupt on cpu 0:
> |  activate_task+0xfb/0x130 kernel/sched/core.c:2064
> |  ttwu_do_activate+0xee/0x2b0 kernel/sched/core.c:3671
> |  ttwu_queue kernel/sched/core.c:3944 [inline]
> |  try_to_wake_up+0x509/0x930 kernel/sched/core.c:4270
> |  default_wake_function+0x25/0x30 kernel/sched/core.c:7009
> |  __pollwake fs/select.c:205 [inline]
> |  pollwake+0xc0/0x100 fs/select.c:215
> |  __wake_up_common kernel/sched/wait.c:89 [inline]
> |  __wake_up_common_lock+0xc0/0x110 kernel/sched/wait.c:106
> |  __wake_up_sync_key+0x1b/0x30 kernel/sched/wait.c:173
> |  sock_def_readable+0x19a/0x460 net/core/sock.c:3442
> |  tcp_data_ready+0x194/0x230 net/ipv4/tcp_input.c:5193
> |  tcp_data_queue+0xfd8/0x26b0 net/ipv4/tcp_input.c:5283
> |  tcp_rcv_established+0x8e5/0xeb0 net/ipv4/tcp_input.c:6237
> |  tcp_v4_do_rcv+0x606/0x620 net/ipv4/tcp_ipv4.c:1915
> |  tcp_v4_rcv+0x16e9/0x1890 net/ipv4/tcp_ipv4.c:2350
> |  ip_protocol_deliver_rcu+0x382/0x6a0 net/ipv4/ip_input.c:205
> |  ip_local_deliver_finish+0x1bf/0x290 net/ipv4/ip_input.c:233
> |  NF_HOOK+0x274/0x2f0 include/linux/netfilter.h:314
> |  ip_local_deliver net/ipv4/ip_input.c:254 [inline]
> |  dst_input include/net/dst.h:460 [inline]
> |  ip_sublist_rcv_finish+0x22a/0x2c0 net/ipv4/ip_input.c:580
> |  ip_list_rcv_finish net/ipv4/ip_input.c:630 [inline]
> |  ip_sublist_rcv+0x2e3/0x560 net/ipv4/ip_input.c:638
> |  ip_list_rcv+0x275/0x2b0 net/ipv4/ip_input.c:672
> |  __netif_receive_skb_list_ptype net/core/dev.c:5709 [inline]
> |  __netif_receive_skb_list_core+0x4fc/0x520 net/core/dev.c:5756
> |  __netif_receive_skb_list net/core/dev.c:5808 [inline]
> |  netif_receive_skb_list_internal+0x516/0x720 net/core/dev.c:5899
> |  gro_normal_list include/net/gro.h:515 [inline]
> |  napi_complete_done+0x161/0x3c0 net/core/dev.c:6250
> |  e1000_clean+0x7c7/0x1a70 drivers/net/ethernet/intel/e1000/e1000_main.c:3808
> |  __napi_poll+0x6c/0x2c0 net/core/dev.c:6775
> |  napi_poll net/core/dev.c:6844 [inline]
> |  net_rx_action+0x433/0x8e0 net/core/dev.c:6966
> |  handle_softirqs+0x15c/0x450 kernel/softirq.c:554
> |  __do_softirq kernel/softirq.c:588 [inline]
> |  invoke_softirq kernel/softirq.c:428 [inline]
> |  __irq_exit_rcu+0x72/0x110 kernel/softirq.c:637
> |  irq_exit_rcu+0x9/0x30 kernel/softirq.c:649
> |  common_interrupt+0xa7/0xc0 arch/x86/kernel/irq.c:278
> |  asm_common_interrupt+0x26/0x40 arch/x86/include/asm/idtentry.h:693
> |  finish_task_switch+0x11c/0x3e0 kernel/sched/core.c:5189
> |  context_switch kernel/sched/core.c:5318 [inline]
> |  __schedule+0xf23/0x14a0 kernel/sched/core.c:6675
> |  preempt_schedule_irq+0x9a/0xf0 kernel/sched/core.c:6997
> |  raw_irqentry_exit_cond_resched+0x52/0x60 kernel/entry/common.c:311
> |  irqentry_exit+0x6a/0xa0 kernel/entry/common.c:354
> |  sysvec_apic_timer_interrupt+0x50/0xb0 arch/x86/kernel/apic/apic.c:1037
> |  asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
> |  __seqprop_sequence include/linux/seqlock.h:211 [inline]
> |  get_counters net/ipv6/netfilter/ip6_tables.c:774 [inline]
> |  alloc_counters net/ipv6/netfilter/ip6_tables.c:820 [inline]
> |  copy_entries_to_user net/ipv6/netfilter/ip6_tables.c:837 [inline]
> |  get_entries net/ipv6/netfilter/ip6_tables.c:1039 [inline]
> |  do_ip6t_get_ctl+0x665/0x9d0 net/ipv6/netfilter/ip6_tables.c:1677
> |  nf_getsockopt+0x14e/0x170 net/netfilter/nf_sockopt.c:116
> |  ipv6_getsockopt+0x13c/0x1b0 net/ipv6/ipv6_sockglue.c:1493
> |  tcp_getsockopt+0x9e/0xd0 net/ipv4/tcp.c:4670
> |  sock_common_getsockopt+0x5d/0x70 net/core/sock.c:3776
> |  do_sock_getsockopt+0x18f/0x220 net/socket.c:2391
> |  __sys_getsockopt+0xf1/0x170 net/socket.c:2420
> |  __do_sys_getsockopt net/socket.c:2430 [inline]
> |  __se_sys_getsockopt net/socket.c:2427 [inline]
> |  __x64_sys_getsockopt+0x64/0x80 net/socket.c:2427
> |  x64_sys_call+0x120e/0x2f00 arch/x86/include/generated/asm/syscalls_64.h:56
> |  do_syscall_x64 arch/x86/entry/common.c:52 [inline]
> |  do_syscall_64+0xec/0x1d0 arch/x86/entry/common.c:83
> |  entry_SYSCALL_64_after_hwframe+0x77/0x7f
> |
> | 8 locks held by syz-executor/24825:
> |  #0: ffffa2e5031a2f48 (&xt[i].mutex){+.+.}-{3:3}, at: xt_find_table_lock+0x5e/0x230 net/netfilter/x_tables.c:1243
> |  #1: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
> |  #1: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
> |  #1: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: netif_receive_skb_list_internal+0x24e/0x720 net/core/dev.c:5884
> |  #2: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
> |  #2: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
> |  #2: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: ip_local_deliver_finish+0xe1/0x290 net/ipv4/ip_input.c:232
> |  #3: ffffa2e5072201d8 (slock-AF_INET/1){+.-.}-{2:2}, at: tcp_v4_rcv+0x1677/0x1890 net/ipv4/tcp_ipv4.c:2346
> |  #4: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
> |  #4: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
> |  #4: ffffffff9a357d18 (rcu_read_lock){....}-{1:2}, at: sock_def_readable+0x91/0x460 net/core/sock.c:3439
> |  #5: ffffa2e503a65858 (&ei->socket.wq.wait){..-.}-{2:2}, at: __wake_up_common_lock+0x26/0x110 kernel/sched/wait.c:105
> |  #6: ffffa2e506240930 (&p->pi_lock){-.-.}-{2:2}, at: class_raw_spinlock_irqsave_constructor include/linux/spinlock.h:551 [inline]
> |  #6: ffffa2e506240930 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x50/0x930 kernel/sched/core.c:4154
> |  #7: ffffa2e57dc2f398 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested kernel/sched/core.c:593 [inline]
> |  #7: ffffa2e57dc2f398 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock kernel/sched/sched.h:1505 [inline]
> |  #7: ffffa2e57dc2f398 (&rq->__lock){-.-.}-{2:2}, at: rq_lock kernel/sched/sched.h:1804 [inline]
> |  #7: ffffa2e57dc2f398 (&rq->__lock){-.-.}-{2:2}, at: ttwu_queue kernel/sched/core.c:3942 [inline]
> |  #7: ffffa2e57dc2f398 (&rq->__lock){-.-.}-{2:2}, at: try_to_wake_up+0x4ce/0x930 kernel/sched/core.c:4270
> | irq event stamp: 89470
> | hardirqs last  enabled at (89469): [<ffffffff978623b3>] seqcount_lockdep_reader_access include/linux/seqlock.h:74 [inline]
> | hardirqs last  enabled at (89469): [<ffffffff978623b3>] ktime_get+0xf3/0x2c0 kernel/time/timekeeping.c:848
> | hardirqs last disabled at (89470): [<ffffffff9971605e>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
> | hardirqs last disabled at (89470): [<ffffffff9971605e>] _raw_spin_lock_irqsave+0x4e/0xb0 kernel/locking/spinlock.c:162
> | softirqs last  enabled at (89413): [<ffffffff98f80605>] spin_unlock_bh include/linux/spinlock.h:396 [inline]
> | softirqs last  enabled at (89413): [<ffffffff98f80605>] release_sock+0x105/0x130 net/core/sock.c:3635
> | softirqs last disabled at (89462): [<ffffffff976fb3f2>] __do_softirq kernel/softirq.c:588 [inline]
> | softirqs last disabled at (89462): [<ffffffff976fb3f2>] invoke_softirq kernel/softirq.c:428 [inline]
> | softirqs last disabled at (89462): [<ffffffff976fb3f2>] __irq_exit_rcu+0x72/0x110 kernel/softirq.c:637
> |
> | assert no writes to 0xffffa2e506240068 of 4 bytes by task 16 on cpu 2:
> |  __block_task kernel/sched/sched.h:2770 [inline]
> |  dequeue_entities+0xde4/0xed0 kernel/sched/fair.c:7177
> |  pick_next_entity kernel/sched/fair.c:5627 [inline]
> |  pick_task_fair kernel/sched/fair.c:8856 [inline]
> |  pick_next_task_fair+0xaf/0x820 kernel/sched/fair.c:8876
> |  __pick_next_task kernel/sched/core.c:5955 [inline]
> |  pick_next_task kernel/sched/core.c:6477 [inline]
> |  __schedule+0x5e0/0x14a0 kernel/sched/core.c:6629
> |  __schedule_loop kernel/sched/core.c:6752 [inline]
> |  schedule+0xe7/0x1a0 kernel/sched/core.c:6767
> |  schedule_timeout+0xaf/0x160 kernel/time/timer.c:2615
> |  rcu_gp_fqs_loop+0x2d8/0xd40 kernel/rcu/tree.c:2045
> |  rcu_gp_kthread+0x28/0x2f0 kernel/rcu/tree.c:2247
> |  kthread+0x1dd/0x220 kernel/kthread.c:389
> |  ret_from_fork+0x4b/0x60 arch/x86/kernel/process.c:147
> |  ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
> |
> | 1 lock held by rcu_preempt/16:
> |  #0: ffffa2e57dd2f398 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested kernel/sched/core.c:593 [inline]
> |  #0: ffffa2e57dd2f398 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock kernel/sched/sched.h:1505 [inline]
> |  #0: ffffa2e57dd2f398 (&rq->__lock){-.-.}-{2:2}, at: rq_lock kernel/sched/sched.h:1804 [inline]
> |  #0: ffffa2e57dd2f398 (&rq->__lock){-.-.}-{2:2}, at: __schedule+0x1f9/0x14a0 kernel/sched/core.c:6575
> | irq event stamp: 791056
> | hardirqs last  enabled at (791055): [<ffffffff99716270>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:151 [inline]
> | hardirqs last  enabled at (791055): [<ffffffff99716270>] _raw_spin_unlock_irqrestore+0x30/0x60 kernel/locking/spinlock.c:194
> | hardirqs last disabled at (791056): [<ffffffff99706ad7>] __schedule+0x1d7/0x14a0 kernel/sched/core.c:6555
> | softirqs last  enabled at (788540): [<ffffffff976fb3f2>] __do_softirq kernel/softirq.c:588 [inline]
> | softirqs last  enabled at (788540): [<ffffffff976fb3f2>] invoke_softirq kernel/softirq.c:428 [inline]
> | softirqs last  enabled at (788540): [<ffffffff976fb3f2>] __irq_exit_rcu+0x72/0x110 kernel/softirq.c:637
> | softirqs last disabled at (788529): [<ffffffff976fb3f2>] __do_softirq kernel/softirq.c:588 [inline]
> | softirqs last disabled at (788529): [<ffffffff976fb3f2>] invoke_softirq kernel/softirq.c:428 [inline]
> | softirqs last disabled at (788529): [<ffffffff976fb3f2>] __irq_exit_rcu+0x72/0x110 kernel/softirq.c:637
> |
> | Reported by Kernel Concurrency Sanitizer on:
> | CPU: 2 UID: 0 PID: 16 Comm: rcu_preempt Not tainted 6.12.0-rc2-00003-g44423ac48780-dirty #8
> | Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
> | ==================================================================

Powered by blists - more mailing lists