Hi Paul, Thomas,
I received a crash report from syzbot on the android 4.9 kernel and I
am looking into it, it seems the debugobjects subsystem is warning
that a certain RCU structure is not allocated on the stack, but is
annotated to be.
------------[ cut here ]------------
WARNING: CPU: 1 PID: 0 at lib/debugobjects.c:300
debug_object_is_on_stack lib/debugobjects.c:300 [inline]
WARNING: CPU: 1 PID: 0 at lib/debugobjects.c:300
__debug_object_init+0x526/0xc40 lib/debugobjects.c:326
[...]
<IRQ> [ 150.631700] [<ffffffff81d96069>] dump_stack+0xc1/0x128
lib/dump_stack.c:51
[<ffffffff8142fbd1>] panic+0x1bc/0x3a8 kernel/panic.c:179
[<ffffffff81131894>] __warn+0x1c4/0x1e0 kernel/panic.c:542
[<ffffffff81131afc>] warn_slowpath_null+0x2c/0x40 kernel/panic.c:585
[<ffffffff81dfefb6>] debug_object_is_on_stack lib/debugobjects.c:300 [inline]
[<ffffffff81dfefb6>] __debug_object_init+0x526/0xc40 lib/debugobjects.c:326
[<ffffffff81dff709>] debug_object_init_on_stack+0x19/0x20
lib/debugobjects.c:378
[<ffffffff81287a93>] init_rcu_head_on_stack kernel/rcu/update.c:403 [inline]
[<ffffffff81287a93>] __wait_rcu_gp+0x93/0x1b0 kernel/rcu/update.c:358
[<ffffffff81290251>] synchronize_rcu.part.65+0x101/0x110
kernel/rcu/tree_plugin.h:678
[<ffffffff81290287>] synchronize_rcu+0x27/0x90 kernel/rcu/tree_plugin.h:679
[<ffffffff83588b35>] __l2tp_session_unhash+0x3d5/0x550
net/l2tp/l2tp_core.c:1792
The full report is here:
https://syzkaller.appspot.com/bug?extid=e6a19b585ab2dba3eee8
It seems as per the code that the structure is on the stack so its
weird why debugobjects thinks its not.
The object in question is allocated on the stack by the __wait_rcu_gp
macro when its called from synchronize_rcu:
#define _wait_rcu_gp(checktiny, ...) \
do { \
call_rcu_func_t __crcu_array[] = { __VA_ARGS__ }; \
struct rcu_synchronize __rs_array[ARRAY_SIZE(__crcu_array)]; \
__wait_rcu_gp(checktiny, ARRAY_SIZE(__crcu_array), \
__crcu_array, __rs_array); \
} while (0)
Any debug ideas or thoughts about it?
thanks for any help,
- Joel
On Thu, 22 Mar 2018, Joel Fernandes wrote:
> Hi Paul, Thomas,
>
> I received a crash report from syzbot on the android 4.9 kernel and I
> am looking into it, it seems the debugobjects subsystem is warning
> that a certain RCU structure is not allocated on the stack, but is
> annotated to be.
>
> ------------[ cut here ]------------
> WARNING: CPU: 1 PID: 0 at lib/debugobjects.c:300
> debug_object_is_on_stack lib/debugobjects.c:300 [inline]
> WARNING: CPU: 1 PID: 0 at lib/debugobjects.c:300
> __debug_object_init+0x526/0xc40 lib/debugobjects.c:326
> [...]
> <IRQ> [ 150.631700] [<ffffffff81d96069>] dump_stack+0xc1/0x128
> lib/dump_stack.c:51
> [<ffffffff8142fbd1>] panic+0x1bc/0x3a8 kernel/panic.c:179
> [<ffffffff81131894>] __warn+0x1c4/0x1e0 kernel/panic.c:542
> [<ffffffff81131afc>] warn_slowpath_null+0x2c/0x40 kernel/panic.c:585
> [<ffffffff81dfefb6>] debug_object_is_on_stack lib/debugobjects.c:300 [inline]
> [<ffffffff81dfefb6>] __debug_object_init+0x526/0xc40 lib/debugobjects.c:326
> [<ffffffff81dff709>] debug_object_init_on_stack+0x19/0x20
> lib/debugobjects.c:378
> [<ffffffff81287a93>] init_rcu_head_on_stack kernel/rcu/update.c:403 [inline]
> [<ffffffff81287a93>] __wait_rcu_gp+0x93/0x1b0 kernel/rcu/update.c:358
> [<ffffffff81290251>] synchronize_rcu.part.65+0x101/0x110
> kernel/rcu/tree_plugin.h:678
> [<ffffffff81290287>] synchronize_rcu+0x27/0x90 kernel/rcu/tree_plugin.h:679
> [<ffffffff83588b35>] __l2tp_session_unhash+0x3d5/0x550
> net/l2tp/l2tp_core.c:1792
>
> The full report is here:
> https://syzkaller.appspot.com/bug?extid=e6a19b585ab2dba3eee8
This is beyond useless. That brings me to a google 'Sign in' page. Please
use accessible storage. That information is hardly secrit.
> It seems as per the code that the structure is on the stack so its
> weird why debugobjects thinks its not.
> The object in question is allocated on the stack by the __wait_rcu_gp
> macro when its called from synchronize_rcu:
>
> #define _wait_rcu_gp(checktiny, ...) \
> do { \
> call_rcu_func_t __crcu_array[] = { __VA_ARGS__ }; \
> struct rcu_synchronize __rs_array[ARRAY_SIZE(__crcu_array)]; \
> __wait_rcu_gp(checktiny, ARRAY_SIZE(__crcu_array), \
> __crcu_array, __rs_array); \
> } while (0)
>
>
> Any debug ideas or thoughts about it?
I assume it emitted:
pr_warn("object is not on stack, but annotated\n");
before dumping the WARN_ON(). Right? If so, then you might have run into a
stack corruption. But hard to tell. Please add something like this:
pr_warn("object %p is not on stack %p, but annotated\n", obj,
task_stack_page(current));
Thanks,
tglx
On Fri, Mar 23, 2018 at 2:11 AM, Thomas Gleixner <[email protected]> wrote:
> On Thu, 22 Mar 2018, Joel Fernandes wrote:
>
>> Hi Paul, Thomas,
>>
>> I received a crash report from syzbot on the android 4.9 kernel and I
>> am looking into it, it seems the debugobjects subsystem is warning
>> that a certain RCU structure is not allocated on the stack, but is
>> annotated to be.
>>
>> ------------[ cut here ]------------
>> WARNING: CPU: 1 PID: 0 at lib/debugobjects.c:300
>> debug_object_is_on_stack lib/debugobjects.c:300 [inline]
>> WARNING: CPU: 1 PID: 0 at lib/debugobjects.c:300
>> __debug_object_init+0x526/0xc40 lib/debugobjects.c:326
>> [...]
>> <IRQ> [ 150.631700] [<ffffffff81d96069>] dump_stack+0xc1/0x128
>> lib/dump_stack.c:51
>> [<ffffffff8142fbd1>] panic+0x1bc/0x3a8 kernel/panic.c:179
>> [<ffffffff81131894>] __warn+0x1c4/0x1e0 kernel/panic.c:542
>> [<ffffffff81131afc>] warn_slowpath_null+0x2c/0x40 kernel/panic.c:585
>> [<ffffffff81dfefb6>] debug_object_is_on_stack lib/debugobjects.c:300 [inline]
>> [<ffffffff81dfefb6>] __debug_object_init+0x526/0xc40 lib/debugobjects.c:326
>> [<ffffffff81dff709>] debug_object_init_on_stack+0x19/0x20
>> lib/debugobjects.c:378
>> [<ffffffff81287a93>] init_rcu_head_on_stack kernel/rcu/update.c:403 [inline]
>> [<ffffffff81287a93>] __wait_rcu_gp+0x93/0x1b0 kernel/rcu/update.c:358
>> [<ffffffff81290251>] synchronize_rcu.part.65+0x101/0x110
>> kernel/rcu/tree_plugin.h:678
>> [<ffffffff81290287>] synchronize_rcu+0x27/0x90 kernel/rcu/tree_plugin.h:679
>> [<ffffffff83588b35>] __l2tp_session_unhash+0x3d5/0x550
>> net/l2tp/l2tp_core.c:1792
>>
>> The full report is here:
>> https://syzkaller.appspot.com/bug?extid=e6a19b585ab2dba3eee8
>
> This is beyond useless. That brings me to a google 'Sign in' page. Please
> use accessible storage. That information is hardly secrit.
Sorry. Here is the raw crash log: https://pastebin.com/raw/puvh0cXE
(The kernel logs are toward the end with the above).
>
>> It seems as per the code that the structure is on the stack so its
>> weird why debugobjects thinks its not.
>> The object in question is allocated on the stack by the __wait_rcu_gp
>> macro when its called from synchronize_rcu:
>>
>> #define _wait_rcu_gp(checktiny, ...) \
>> do { \
>> call_rcu_func_t __crcu_array[] = { __VA_ARGS__ }; \
>> struct rcu_synchronize __rs_array[ARRAY_SIZE(__crcu_array)]; \
>> __wait_rcu_gp(checktiny, ARRAY_SIZE(__crcu_array), \
>> __crcu_array, __rs_array); \
>> } while (0)
>>
>>
>> Any debug ideas or thoughts about it?
>
> I assume it emitted:
> pr_warn("object is not on stack, but annotated\n");
>
Yes that is the warning.
> before dumping the WARN_ON(). Right? If so, then you might have run into a
> stack corruption. But hard to tell. Please add something like this:
>
> pr_warn("object %p is not on stack %p, but annotated\n", obj,
> task_stack_page(current));
Sounds good, I will make this change into android-4.9 kernel for debug
purpose and hopefully the bot hits it soon (that's likely since its
been reported many times). Will let you know once we hit it.
Thanks a lot for the ideas,
- Joel
On Fri, 23 Mar 2018, Joel Fernandes wrote:
> On Fri, Mar 23, 2018 at 2:11 AM, Thomas Gleixner <[email protected]> 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
On Fri, Mar 23, 2018 at 1:41 PM, Thomas Gleixner <[email protected]> wrote:
> On Fri, 23 Mar 2018, Joel Fernandes wrote:
>> On Fri, Mar 23, 2018 at 2:11 AM, Thomas Gleixner <[email protected]> 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.
On Sat, Mar 24, 2018 at 11:29:42PM -0700, Joel Fernandes wrote:
> On Fri, Mar 23, 2018 at 1:41 PM, Thomas Gleixner <[email protected]> wrote:
> > On Fri, 23 Mar 2018, Joel Fernandes wrote:
> >> On Fri, Mar 23, 2018 at 2:11 AM, Thomas Gleixner <[email protected]> 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.