Re: [PATCH] bridge: Fix a deadlock when enabling multicast snooping

[Nikolay Aleksandrov]

On 04/12/2020 00:42, Huang, Joseph wrote:
>> From: Huang, Joseph
>> Sent: Thursday, December 3, 2020 4:53 PM
>> To: Nikolay Aleksandrov <nikolay@xxxxxxxxxx>; Jakub Kicinski
>> <kuba@xxxxxxxxxx>
>> Cc: Roopa Prabhu <roopa@xxxxxxxxxx>; David S. Miller
>> <davem@xxxxxxxxxxxxx>; bridge@xxxxxxxxxxxxxxxxxxxxxxxxxx;
>> netdev@xxxxxxxxxxxxxxx; linux-kernel@xxxxxxxxxxxxxxx; Linus Lüssing
>> <linus.luessing@xxxxxxxxx>
>> Subject: RE: [PATCH] bridge: Fix a deadlock when enabling multicast snooping
>>
>>> From: Nikolay Aleksandrov <nikolay@xxxxxxxxxx>
>>> Sent: Thursday, December 3, 2020 3:47 PM
>>> To: Jakub Kicinski <kuba@xxxxxxxxxx>; Huang, Joseph
>>> <Joseph.Huang@xxxxxxxxxx>
>>> Cc: Roopa Prabhu <roopa@xxxxxxxxxx>; David S. Miller
>>> <davem@xxxxxxxxxxxxx>; bridge@xxxxxxxxxxxxxxxxxxxxxxxxxx;
>>> netdev@xxxxxxxxxxxxxxx; linux-kernel@xxxxxxxxxxxxxxx; Linus Lüssing
>>> <linus.luessing@xxxxxxxxx>
>>> Subject: Re: [PATCH] bridge: Fix a deadlock when enabling multicast
>>> snooping
>>>
>>> On 03/12/2020 20:28, Jakub Kicinski wrote:
>>>> On Tue, 1 Dec 2020 16:40:47 -0500 Joseph Huang wrote:
>>>>> When enabling multicast snooping, bridge module deadlocks on
>>>>> multicast_lock if 1) IPv6 is enabled, and 2) there is an existing
>>>>> querier on the same L2 network.
>>>>>
>>>>> The deadlock was caused by the following sequence: While holding the
>>>>> lock, br_multicast_open calls br_multicast_join_snoopers, which
>>>>> eventually causes IP stack to (attempt to) send out a Listener Report (in
>>> igmp6_join_group).
>>>>> Since the destination Ethernet address is a multicast address,
>>>>> br_dev_xmit feeds the packet back to the bridge via br_multicast_rcv,
>>>>> which in turn calls br_multicast_add_group, which then deadlocks on
>>> multicast_lock.
>>>>>
>>>>> The fix is to move the call br_multicast_join_snoopers outside of the
>>>>> critical section. This works since br_multicast_join_snoopers only
>>>>> deals with IP and does not modify any multicast data structures of
>>>>> the bridge, so there's no need to hold the lock.
>>>>>
>>>>> Fixes: 4effd28c1245 ("bridge: join all-snoopers multicast address")
>>>>>
>>>>> Signed-off-by: Joseph Huang <Joseph.Huang@xxxxxxxxxx>
>>>>
>>>> Nik, Linus - how does this one look?
>>>>
>>>
>>> Hi,
>>> Thanks, somehow I missed this one too. Need to check my email config. :) I
>>> believe I see how it can happen, although it's not straight-forward to follow.
>>> A selftest for this case would be great, and any traces (e.g. hung task)
>> would
>>> help a lot as well.
>>> Correct me if I'm wrong but the sequence is something like:
>>> br_multicast_join_snoopers -> ipv6_dev_mc_inc -> __ipv6_dev_mc_inc ->
>>> igmp6_group_added
>>> -> MLDv1 (mode) igmp6_join_group() -> Again MLDv1 mode
>>> -> igmp6_join_group() -> igmp6_join_group
>>> -> igmp6_send() on the bridge device -> br_dev_xmit and onto the bridge
>>> -> mcast processing code
>>> which uses the multicast_lock spinlock. Right?
>>
>> That is correct.
>>
>> Here's a stack trace from a typical run:
>>
>> echo -n 1 > /sys/devices/virtual/net/gmn0/bridge/multicast_snooping
>> [  936.146754] rcu: INFO: rcu_preempt self-detected stall on CPU
>> [  936.152534] rcu:   0-....: (5594 ticks this GP)
>> idle=75a/1/0x4000000000000002 softirq=2787/2789 fqs=2625
>> [  936.162026]        (t=5253 jiffies g=4205 q=12)
>> [  936.166041] Task dump for CPU 0:
>> [  936.169272] sh              R  running task        0  1315   1295 0x00000002
>> [  936.176332] Call trace:
>> [  936.178797]  dump_backtrace+0x0/0x140
>> [  936.182469]  show_stack+0x14/0x20
>> [  936.185793]  sched_show_task+0x108/0x138
>> [  936.189727]  dump_cpu_task+0x40/0x50
>> [  936.193313]  rcu_dump_cpu_stacks+0x94/0xd0
>> [  936.197420]  rcu_sched_clock_irq+0x75c/0x9c0
>> [  936.201698]  update_process_times+0x2c/0x68
>> [  936.205893]  tick_sched_handle.isra.0+0x30/0x50
>> [  936.210432]  tick_sched_timer+0x48/0x98
>> [  936.214272]  __hrtimer_run_queues+0x110/0x1b0
>> [  936.218635]  hrtimer_interrupt+0xe4/0x240
>> [  936.222656]  arch_timer_handler_phys+0x30/0x40
>> [  936.227106]  handle_percpu_devid_irq+0x80/0x140
>> [  936.231654]  generic_handle_irq+0x24/0x38
>> [  936.235669]  __handle_domain_irq+0x60/0xb8
>> [  936.239774]  gic_handle_irq+0x5c/0x148
>> [  936.243535]  el1_irq+0xb8/0x180
>> [  936.246689]  queued_spin_lock_slowpath+0x118/0x3b0
>> [  936.251495]  _raw_spin_lock+0x5c/0x68
>> [  936.255221]  br_multicast_add_group+0x40/0x170 [bridge]
>> [  936.260491]  br_multicast_rcv+0x7ac/0xe30 [bridge]
>> [  936.265322]  br_dev_xmit+0x140/0x368 [bridge]
>> [  936.269689]  dev_hard_start_xmit+0x94/0x158
>> [  936.273876]  __dev_queue_xmit+0x5ac/0x7f8
>> [  936.277890]  dev_queue_xmit+0x10/0x18
>> [  936.281563]  neigh_resolve_output+0xec/0x198
>> [  936.285845]  ip6_finish_output2+0x240/0x710
>> [  936.290039]  __ip6_finish_output+0x130/0x170
>> [  936.294318]  ip6_output+0x6c/0x1c8
>> [  936.297731]  NF_HOOK.constprop.0+0xd8/0xe8
>> [  936.301834]  igmp6_send+0x358/0x558
>> [  936.305326]  igmp6_join_group.part.0+0x30/0xf0
>> [  936.309774]  igmp6_group_added+0xfc/0x110
>> [  936.313787]  __ipv6_dev_mc_inc+0x1a4/0x290
>> [  936.317885]  ipv6_dev_mc_inc+0x10/0x18
>> [  936.321677]  br_multicast_open+0xbc/0x110 [bridge]
>> [  936.326506]  br_multicast_toggle+0xec/0x140 [bridge]
>>
>>
>>>
>>> One question - shouldn't leaving have the same problem? I.e.
>>> br_multicast_toggle -> br_multicast_leave_snoopers
>>> -> br_ip6_multicast_leave_snoopers -> ipv6_dev_mc_dec ->
>>> -> igmp6_group_dropped -> igmp6_leave_group ->
>>> MLDv1 mode && last reporter -> igmp6_send() ?
>>>
>>> I think it was saved by the fact that !br_opt_get(br,
>>> BROPT_MULTICAST_ENABLED) would be true and the multicast lock won't
>> be
>>> acquired in the br_dev_xmit path? If so, I'd appreciate a comment about
>> that
>>> because it's not really trivial to find out. :)
>>
>> That's a really good point. Leave should have deadlocked as well, but when I
>> tested the patch, I was able to turn on/off multicast snooping multiple times
>> without any problem.
>>
>> Is it because this line in igmp6_leave_group?
>>
>>               if (ma->mca_flags & MAF_LAST_REPORTER)
>>                       igmp6_send(&ma->mca_addr, ma->idev->dev,
>>                               ICMPV6_MGM_REDUCTION);
>>
>> Perhaps MAF_LAST_REPORTER was not set, so igmp6_send was not called?
>>
>>>
>>> Anyhow, the patch is fine as-is too:
>>> Acked-by: Nikolay Aleksandrov <nikolay@xxxxxxxxxx>
>>>
>>> Thanks,
>>>  Nik
>>
>> Thanks,
>> Joseph
> 
> Would it be advisable if we move br_multicast_leave_snoopers out of the critical
> section as well? Even though I can't really verify that if this is helpful since I haven't
> seen it deadlock when disabling multicast snooping.
> 
> Thanks,
> Joseph
> 
 The reason we're not seeing a deadlock is because the multicast snooping bit
is not set and the lock is never acquired when sending the packet through br_multicast_rcv().
Anyway I'd move it out for symmetry and it would be less confusing as you'd just have a standard
if/else in the end. By the way now that I looked again the patch is not entirely correct as you'll
do multiple joins/leaves on every br_multicast_toggle(), i.e. with the patch you bypass the check
for the same value and actually try to change state each time (the
if (!!br_opt_get(br, BROPT_MULTICAST_ENABLED) == !!val) check).

We also lose the symmetry between br_dev_open and stop, and expose otherwise
private multicast code, so I'd pull out the snoopers leave for br_dev_stop() as well.

Please add a comment why it's needed, so we won't wonder about it later. And also include the
trace in the commit message so we'd have it.

Edit: I just tried it and it's very easy to reproduce, steps:
1. sysctl net.ipv6.conf.all.force_mld_version=1
2. have another querier
3. ip link set dev bridge type bridge mcast_snooping 0 && ip link set dev bridge type bridge mcast_snooping 1
< deadlock >

Thanks,
 Nik