* Re: syzbot rcu/debugobjects warning [not found] ` <CAJWu+ooHzLpJZxsFq7hifmaEh7fOdYsExKz6pGLgSPQUxAB4Nw@mail.gmail.com> @ 2018-03-23 20:41 ` Thomas Gleixner 2018-03-25 6:29 ` Joel Fernandes 0 siblings, 1 reply; 3+ messages in thread From: Thomas Gleixner @ 2018-03-23 20:41 UTC (permalink / raw) To: Joel Fernandes; +Cc: Paul McKenney, LKML, Todd Poynor, netdev On Fri, 23 Mar 2018, Joel Fernandes wrote: > On Fri, Mar 23, 2018 at 2:11 AM, Thomas Gleixner <tglx@linutronix.de> wrote: > > On Thu, 22 Mar 2018, Joel Fernandes wrote: > Sorry. Here is the raw crash log: https://pastebin.com/raw/puvh0cXE > (The kernel logs are toward the end with the above). And that is interesting: [ 150.629667] <IRQ> [ 150.631700] [<ffffffff81d96069>] dump_stack+0xc1/0x128 [ 150.637051] [<ffffffff81dfefb6>] ? __debug_object_init+0x526/0xc40 [ 150.643431] [<ffffffff8142fbd1>] panic+0x1bc/0x3a8 [ 150.648416] [<ffffffff8142fa15>] ? percpu_up_read_preempt_enable.constprop.53+0xd7/0xd7 [ 150.656611] [<ffffffff81430835>] ? load_image_and_restore+0xf9/0xf9 [ 150.663070] [<ffffffff81269efd>] ? vprintk_default+0x1d/0x30 [ 150.668925] [<ffffffff81131879>] ? __warn+0x1a9/0x1e0 [ 150.674170] [<ffffffff81dfefb6>] ? __debug_object_init+0x526/0xc40 [ 150.680543] [<ffffffff81131894>] __warn+0x1c4/0x1e0 [ 150.685614] [<ffffffff81131afc>] warn_slowpath_null+0x2c/0x40 [ 150.691972] [<ffffffff81dfefb6>] __debug_object_init+0x526/0xc40 [ 150.698174] [<ffffffff81dfea90>] ? debug_object_fixup+0x30/0x30 [ 150.704283] [<ffffffff81dff709>] debug_object_init_on_stack+0x19/0x20 [ 150.710917] [<ffffffff81287a93>] __wait_rcu_gp+0x93/0x1b0 [ 150.716508] [<ffffffff81290251>] synchronize_rcu.part.65+0x101/0x110 [ 150.723054] [<ffffffff81290150>] ? rcu_pm_notify+0xc0/0xc0 [ 150.728735] [<ffffffff81292bc0>] ? __call_rcu.constprop.72+0x910/0x910 [ 150.735459] [<ffffffff81235221>] ? __lock_is_held+0xa1/0xf0 [ 150.741223] [<ffffffff81290287>] synchronize_rcu+0x27/0x90 So this calls synchronize_rcu from a rcu callback. That's a nono. This is on the back of an interrupt in softirq context and __wait_rcu_gp() can sleep, which is obviously a bad idea in softirq context.... Cc'ed netdev .... And that also explains the debug object splat because this is not running on the task stack. It's running on the softirq stack .... [ 150.746908] [<ffffffff83588b35>] __l2tp_session_unhash+0x3d5/0x550 [ 150.753281] [<ffffffff8358891f>] ? __l2tp_session_unhash+0x1bf/0x550 [ 150.759828] [<ffffffff8114596a>] ? __local_bh_enable_ip+0x6a/0xd0 [ 150.766123] [<ffffffff8358ddb0>] ? l2tp_udp_encap_recv+0xd90/0xd90 [ 150.772497] [<ffffffff83588e97>] l2tp_tunnel_closeall+0x1e7/0x3a0 [ 150.778782] [<ffffffff835897be>] l2tp_tunnel_destruct+0x30e/0x5a0 [ 150.785067] [<ffffffff8358965a>] ? l2tp_tunnel_destruct+0x1aa/0x5a0 [ 150.791537] [<ffffffff835894b0>] ? l2tp_tunnel_del_work+0x460/0x460 [ 150.797997] [<ffffffff82ee8053>] __sk_destruct+0x53/0x570 [ 150.803588] [<ffffffff81293918>] rcu_process_callbacks+0x898/0x1300 [ 150.810048] [<ffffffff812939f7>] ? rcu_process_callbacks+0x977/0x1300 [ 150.816684] [<ffffffff82ee8000>] ? __sk_dst_check+0x240/0x240 [ 150.822625] [<ffffffff838be5d6>] __do_softirq+0x206/0x951 [ 150.828223] [<ffffffff81147315>] irq_exit+0x165/0x190 [ 150.833557] [<ffffffff838bd1eb>] smp_apic_timer_interrupt+0x7b/0xa0 [ 150.840018] [<ffffffff838b9470>] apic_timer_interrupt+0xa0/0xb0 [ 150.846132] <EOI> [ 150.848166] [<ffffffff838b6756>] ? native_safe_halt+0x6/0x10 [ 150.854036] [<ffffffff8123bf2d>] ? trace_hardirqs_on+0xd/0x10 [ 150.859973] [<ffffffff838b5d85>] default_idle+0x55/0x360 [ 150.865478] [<ffffffff8106be0a>] arch_cpu_idle+0xa/0x10 [ 150.870896] [<ffffffff838b6b96>] default_idle_call+0x36/0x60 [ 150.876751] [<ffffffff81226cb0>] cpu_startup_entry+0x2b0/0x380 [ 150.882787] [<ffffffff81226a00>] ? cpu_in_idle+0x20/0x20 [ 150.888291] [<ffffffff812d2343>] ? clockevents_register_device+0x123/0x200 [ 150.895358] [<ffffffff810b0693>] start_secondary+0x303/0x3e0 [ 150.901209] [<ffffffff810b0390>] ? set_cpu_sibling_map+0x11f0/0x11f0 Thanks, tglx ^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: syzbot rcu/debugobjects warning 2018-03-23 20:41 ` syzbot rcu/debugobjects warning Thomas Gleixner @ 2018-03-25 6:29 ` Joel Fernandes 2018-03-26 17:38 ` Guillaume Nault 0 siblings, 1 reply; 3+ messages in thread From: Joel Fernandes @ 2018-03-25 6:29 UTC (permalink / raw) To: Thomas Gleixner Cc: Paul McKenney, LKML, Todd Poynor, open list:BPF (Safe dynamic programs and tools), Ben Hutchings, Greg Kroah-Hartman, Guillaume Nault On Fri, Mar 23, 2018 at 1:41 PM, Thomas Gleixner <tglx@linutronix.de> wrote: > On Fri, 23 Mar 2018, Joel Fernandes wrote: >> On Fri, Mar 23, 2018 at 2:11 AM, Thomas Gleixner <tglx@linutronix.de> wrote: >> > On Thu, 22 Mar 2018, Joel Fernandes wrote: >> Sorry. Here is the raw crash log: https://pastebin.com/raw/puvh0cXE >> (The kernel logs are toward the end with the above). > > And that is interesting: > > [ 150.629667] <IRQ> [ 150.631700] [<ffffffff81d96069>] dump_stack+0xc1/0x128 > [ 150.637051] [<ffffffff81dfefb6>] ? __debug_object_init+0x526/0xc40 > [ 150.643431] [<ffffffff8142fbd1>] panic+0x1bc/0x3a8 > [ 150.648416] [<ffffffff8142fa15>] ? percpu_up_read_preempt_enable.constprop.53+0xd7/0xd7 > [ 150.656611] [<ffffffff81430835>] ? load_image_and_restore+0xf9/0xf9 > [ 150.663070] [<ffffffff81269efd>] ? vprintk_default+0x1d/0x30 > [ 150.668925] [<ffffffff81131879>] ? __warn+0x1a9/0x1e0 > [ 150.674170] [<ffffffff81dfefb6>] ? __debug_object_init+0x526/0xc40 > [ 150.680543] [<ffffffff81131894>] __warn+0x1c4/0x1e0 > [ 150.685614] [<ffffffff81131afc>] warn_slowpath_null+0x2c/0x40 > [ 150.691972] [<ffffffff81dfefb6>] __debug_object_init+0x526/0xc40 > [ 150.698174] [<ffffffff81dfea90>] ? debug_object_fixup+0x30/0x30 > [ 150.704283] [<ffffffff81dff709>] debug_object_init_on_stack+0x19/0x20 > [ 150.710917] [<ffffffff81287a93>] __wait_rcu_gp+0x93/0x1b0 > [ 150.716508] [<ffffffff81290251>] synchronize_rcu.part.65+0x101/0x110 > [ 150.723054] [<ffffffff81290150>] ? rcu_pm_notify+0xc0/0xc0 > [ 150.728735] [<ffffffff81292bc0>] ? __call_rcu.constprop.72+0x910/0x910 > [ 150.735459] [<ffffffff81235221>] ? __lock_is_held+0xa1/0xf0 > [ 150.741223] [<ffffffff81290287>] synchronize_rcu+0x27/0x90 > > So this calls synchronize_rcu from a rcu callback. That's a nono. This is > on the back of an interrupt in softirq context and __wait_rcu_gp() can > sleep, which is obviously a bad idea in softirq context.... > > Cc'ed netdev .... > > And that also explains the debug object splat because this is not running > on the task stack. It's running on the softirq stack .... > > [ 150.746908] [<ffffffff83588b35>] __l2tp_session_unhash+0x3d5/0x550 > [ 150.753281] [<ffffffff8358891f>] ? __l2tp_session_unhash+0x1bf/0x550 > [ 150.759828] [<ffffffff8114596a>] ? __local_bh_enable_ip+0x6a/0xd0 > [ 150.766123] [<ffffffff8358ddb0>] ? l2tp_udp_encap_recv+0xd90/0xd90 > [ 150.772497] [<ffffffff83588e97>] l2tp_tunnel_closeall+0x1e7/0x3a0 > [ 150.778782] [<ffffffff835897be>] l2tp_tunnel_destruct+0x30e/0x5a0 > [ 150.785067] [<ffffffff8358965a>] ? l2tp_tunnel_destruct+0x1aa/0x5a0 > [ 150.791537] [<ffffffff835894b0>] ? l2tp_tunnel_del_work+0x460/0x460 > [ 150.797997] [<ffffffff82ee8053>] __sk_destruct+0x53/0x570 > [ 150.803588] [<ffffffff81293918>] rcu_process_callbacks+0x898/0x1300 > [ 150.810048] [<ffffffff812939f7>] ? rcu_process_callbacks+0x977/0x1300 > [ 150.816684] [<ffffffff82ee8000>] ? __sk_dst_check+0x240/0x240 > [ 150.822625] [<ffffffff838be5d6>] __do_softirq+0x206/0x951 > [ 150.828223] [<ffffffff81147315>] irq_exit+0x165/0x190 > [ 150.833557] [<ffffffff838bd1eb>] smp_apic_timer_interrupt+0x7b/0xa0 > [ 150.840018] [<ffffffff838b9470>] apic_timer_interrupt+0xa0/0xb0 > [ 150.846132] <EOI> [ 150.848166] [<ffffffff838b6756>] ? native_safe_halt+0x6/0x10 > [ 150.854036] [<ffffffff8123bf2d>] ? trace_hardirqs_on+0xd/0x10 > [ 150.859973] [<ffffffff838b5d85>] default_idle+0x55/0x360 > [ 150.865478] [<ffffffff8106be0a>] arch_cpu_idle+0xa/0x10 > [ 150.870896] [<ffffffff838b6b96>] default_idle_call+0x36/0x60 > [ 150.876751] [<ffffffff81226cb0>] cpu_startup_entry+0x2b0/0x380 > [ 150.882787] [<ffffffff81226a00>] ? cpu_in_idle+0x20/0x20 > [ 150.888291] [<ffffffff812d2343>] ? clockevents_register_device+0x123/0x200 > [ 150.895358] [<ffffffff810b0693>] start_secondary+0x303/0x3e0 > [ 150.901209] [<ffffffff810b0390>] ? set_cpu_sibling_map+0x11f0/0x11f0 Thomas, thanks a lot. It appears this issue will not happen on mainline since from commit 765924e362d1 (subject "l2tp: don't close sessions in l2tp_tunnel_destruct()"), l2tp_tunnel_closeall is no longer called from l2tp_tunnel_destruct. From that commit message it seems one of the motivations is to solve scheduling from atomic issue. However for this change to be applied to android-4.9 and/or 4.9 stable, it depends on several other l2p patches and they aren't straight forward cherry-picks from mainline (and I don't have much background with this driver). v3.16.56 stable seems to be further along with l2tp than v4.9.89, in that it atleast has more of the upstream patches adapted for it, that the above patch depends on. Since this also related to stable, I am CC'ing Greg kh and Ben. Here are some of the commits in 3.16 stable that I couldn't find applied to v4.9 stable. The above fix quotes the below patches as dependencies so they would need to be stable backported. Also CC'ing Guillaume since he authored the above mentioned fix. 0c15ddabbcf l2tp: don't register sessions in l2tp_session_create() a3c5d5b70f4e l2tp: fix race condition in l2tp_tunnel_delete 5b216e8dcda2 l2tp: prevent creation of sessions on terminated tunnels 76ff5e22f1e0 l2tp: hold tunnel while looking up sessions in l2tp_netlink ceb8f6b23a38 l2tp: define parameters of l2tp_session_get*() as "const" 0295d020b63f l2tp: initialise session's refcount before making it reachable 29a77518927e l2tp: take reference on sessions being dumped b301c9b7782f l2tp: take a reference on sessions used in genetlink handlers By the way I think the reason why scheduling while atomic checks didn't show up is because the debugobjects warning caused a panic first, before that could happen. - Joel PS: There's also 12d656af4e3d2 ("l2tp: Avoid schedule while atomic in exit_net") which was fixing a call to synchronize_rcu in the same path/function, but the caller originated from l2tp_exit_net. But this patch is already in the stable trees. I am just mentioning it here for completeness. ^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: syzbot rcu/debugobjects warning 2018-03-25 6:29 ` Joel Fernandes @ 2018-03-26 17:38 ` Guillaume Nault 0 siblings, 0 replies; 3+ messages in thread From: Guillaume Nault @ 2018-03-26 17:38 UTC (permalink / raw) To: Joel Fernandes Cc: Thomas Gleixner, Paul McKenney, LKML, Todd Poynor, open list:BPF (Safe dynamic programs and tools), Ben Hutchings, Greg Kroah-Hartman On Sat, Mar 24, 2018 at 11:29:42PM -0700, Joel Fernandes wrote: > On Fri, Mar 23, 2018 at 1:41 PM, Thomas Gleixner <tglx@linutronix.de> wrote: > > On Fri, 23 Mar 2018, Joel Fernandes wrote: > >> On Fri, Mar 23, 2018 at 2:11 AM, Thomas Gleixner <tglx@linutronix.de> wrote: > >> > On Thu, 22 Mar 2018, Joel Fernandes wrote: > >> Sorry. Here is the raw crash log: https://pastebin.com/raw/puvh0cXE > >> (The kernel logs are toward the end with the above). > > > > And that is interesting: > > > > [ 150.629667] <IRQ> [ 150.631700] [<ffffffff81d96069>] dump_stack+0xc1/0x128 > > [ 150.637051] [<ffffffff81dfefb6>] ? __debug_object_init+0x526/0xc40 > > [ 150.643431] [<ffffffff8142fbd1>] panic+0x1bc/0x3a8 > > [ 150.648416] [<ffffffff8142fa15>] ? percpu_up_read_preempt_enable.constprop.53+0xd7/0xd7 > > [ 150.656611] [<ffffffff81430835>] ? load_image_and_restore+0xf9/0xf9 > > [ 150.663070] [<ffffffff81269efd>] ? vprintk_default+0x1d/0x30 > > [ 150.668925] [<ffffffff81131879>] ? __warn+0x1a9/0x1e0 > > [ 150.674170] [<ffffffff81dfefb6>] ? __debug_object_init+0x526/0xc40 > > [ 150.680543] [<ffffffff81131894>] __warn+0x1c4/0x1e0 > > [ 150.685614] [<ffffffff81131afc>] warn_slowpath_null+0x2c/0x40 > > [ 150.691972] [<ffffffff81dfefb6>] __debug_object_init+0x526/0xc40 > > [ 150.698174] [<ffffffff81dfea90>] ? debug_object_fixup+0x30/0x30 > > [ 150.704283] [<ffffffff81dff709>] debug_object_init_on_stack+0x19/0x20 > > [ 150.710917] [<ffffffff81287a93>] __wait_rcu_gp+0x93/0x1b0 > > [ 150.716508] [<ffffffff81290251>] synchronize_rcu.part.65+0x101/0x110 > > [ 150.723054] [<ffffffff81290150>] ? rcu_pm_notify+0xc0/0xc0 > > [ 150.728735] [<ffffffff81292bc0>] ? __call_rcu.constprop.72+0x910/0x910 > > [ 150.735459] [<ffffffff81235221>] ? __lock_is_held+0xa1/0xf0 > > [ 150.741223] [<ffffffff81290287>] synchronize_rcu+0x27/0x90 > > > > So this calls synchronize_rcu from a rcu callback. That's a nono. This is > > on the back of an interrupt in softirq context and __wait_rcu_gp() can > > sleep, which is obviously a bad idea in softirq context.... > > > > Cc'ed netdev .... > > > > And that also explains the debug object splat because this is not running > > on the task stack. It's running on the softirq stack .... > > > > [ 150.746908] [<ffffffff83588b35>] __l2tp_session_unhash+0x3d5/0x550 > > [ 150.753281] [<ffffffff8358891f>] ? __l2tp_session_unhash+0x1bf/0x550 > > [ 150.759828] [<ffffffff8114596a>] ? __local_bh_enable_ip+0x6a/0xd0 > > [ 150.766123] [<ffffffff8358ddb0>] ? l2tp_udp_encap_recv+0xd90/0xd90 > > [ 150.772497] [<ffffffff83588e97>] l2tp_tunnel_closeall+0x1e7/0x3a0 > > [ 150.778782] [<ffffffff835897be>] l2tp_tunnel_destruct+0x30e/0x5a0 > > [ 150.785067] [<ffffffff8358965a>] ? l2tp_tunnel_destruct+0x1aa/0x5a0 > > [ 150.791537] [<ffffffff835894b0>] ? l2tp_tunnel_del_work+0x460/0x460 > > [ 150.797997] [<ffffffff82ee8053>] __sk_destruct+0x53/0x570 > > [ 150.803588] [<ffffffff81293918>] rcu_process_callbacks+0x898/0x1300 > > [ 150.810048] [<ffffffff812939f7>] ? rcu_process_callbacks+0x977/0x1300 > > [ 150.816684] [<ffffffff82ee8000>] ? __sk_dst_check+0x240/0x240 > > [ 150.822625] [<ffffffff838be5d6>] __do_softirq+0x206/0x951 > > [ 150.828223] [<ffffffff81147315>] irq_exit+0x165/0x190 > > [ 150.833557] [<ffffffff838bd1eb>] smp_apic_timer_interrupt+0x7b/0xa0 > > [ 150.840018] [<ffffffff838b9470>] apic_timer_interrupt+0xa0/0xb0 > > [ 150.846132] <EOI> [ 150.848166] [<ffffffff838b6756>] ? native_safe_halt+0x6/0x10 > > [ 150.854036] [<ffffffff8123bf2d>] ? trace_hardirqs_on+0xd/0x10 > > [ 150.859973] [<ffffffff838b5d85>] default_idle+0x55/0x360 > > [ 150.865478] [<ffffffff8106be0a>] arch_cpu_idle+0xa/0x10 > > [ 150.870896] [<ffffffff838b6b96>] default_idle_call+0x36/0x60 > > [ 150.876751] [<ffffffff81226cb0>] cpu_startup_entry+0x2b0/0x380 > > [ 150.882787] [<ffffffff81226a00>] ? cpu_in_idle+0x20/0x20 > > [ 150.888291] [<ffffffff812d2343>] ? clockevents_register_device+0x123/0x200 > > [ 150.895358] [<ffffffff810b0693>] start_secondary+0x303/0x3e0 > > [ 150.901209] [<ffffffff810b0390>] ? set_cpu_sibling_map+0x11f0/0x11f0 > > Thomas, thanks a lot. It appears this issue will not happen on > mainline since from commit 765924e362d1 (subject "l2tp: don't close > sessions in l2tp_tunnel_destruct()"), l2tp_tunnel_closeall is no > longer called from l2tp_tunnel_destruct. From that commit message it > seems one of the motivations is to solve scheduling from atomic issue. > I agree that this patch should fix the above splat. > However for this change to be applied to android-4.9 and/or 4.9 > stable, it depends on several other l2p patches and they aren't > straight forward cherry-picks from mainline (and I don't have much > background with this driver). > > v3.16.56 stable seems to be further along with l2tp than v4.9.89, in > that it atleast has more of the upstream patches adapted for it, that > the above patch depends on. Since this also related to stable, I am > CC'ing Greg kh and Ben. > I generally review l2tp patches proposed for -stable trees (although not in time). If a patch has been ported to 3.16.y and is missing in another tree, then it should be safe to port it there too. > Here are some of the commits in 3.16 stable that I couldn't find > applied to v4.9 stable. The above fix quotes the below patches as > dependencies so they would need to be stable backported. Also CC'ing > Guillaume since he authored the above mentioned fix. > > 0c15ddabbcf l2tp: don't register sessions in l2tp_session_create() > a3c5d5b70f4e l2tp: fix race condition in l2tp_tunnel_delete > 5b216e8dcda2 l2tp: prevent creation of sessions on terminated tunnels > 76ff5e22f1e0 l2tp: hold tunnel while looking up sessions in l2tp_netlink > ceb8f6b23a38 l2tp: define parameters of l2tp_session_get*() as "const" > 0295d020b63f l2tp: initialise session's refcount before making it reachable > 29a77518927e l2tp: take reference on sessions being dumped > b301c9b7782f l2tp: take a reference on sessions used in genetlink handlers > Yes, I think it'd make sense to port these patches. ^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2018-03-26 17:38 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <CAJWu+oo1mnS=2v_SbnDCDih6AyystU2aXVCUEa5k0W0q0Ovk6w@mail.gmail.com>
[not found] ` <alpine.DEB.2.21.1803231004130.4625@nanos.tec.linutronix.de>
[not found] ` <CAJWu+ooHzLpJZxsFq7hifmaEh7fOdYsExKz6pGLgSPQUxAB4Nw@mail.gmail.com>
2018-03-23 20:41 ` syzbot rcu/debugobjects warning Thomas Gleixner
2018-03-25 6:29 ` Joel Fernandes
2018-03-26 17:38 ` Guillaume Nault
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).