kevin: lockdep splat sometimes when you get a warning |
||||||
Issue descriptionWith lockdep turned on it appears that you always get a confusing lockdep splat whenever you run a WARN in the kernel. Specifically, I saw this warning hit in netfilter: WARN(1, "nf_unregister_net_hook: hook not found!\n"); ...that needs to debugged separately, but the problem I'm worried about here is that the act of running the warning caused a lockdep splat. It looked like this: [ 11.979073] nf_unregister_net_hook: hook not found! [ 11.986339] DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled) [ 11.991661] ------------[ cut here ]------------ [ 11.996471] WARNING: at /mnt/host/source/src/third_party/kernel/v4.4/kernel/locking/lockdep.c:3519 [ 12.005427] Modules linked in: cfg80211(+) ip6table_filter cdc_ether joydev [ 12.012457] [ 12.013954] CPU: 4 PID: 121 Comm: kworker/u12:3 Not tainted 4.4.86 #47 [ 12.020478] Hardware name: Google Kevin (DT) [ 12.024757] Workqueue: netns cleanup_net [ 12.028694] task: ffffffc0e9a7c500 ti: ffffffc0e9c48000 task.ti: ffffffc0e9c48000 [ 12.036189] PC is at check_flags+0x178/0x190 [ 12.040462] LR is at check_flags+0x178/0x190 [ 12.044732] pc : [<ffffffc00027106c>] lr : [<ffffffc00027106c>] pstate: 600003c5 [ 12.052125] sp : ffffffc0e9c4b800 [ 12.055439] x29: ffffffc0e9c4b810 x28: ffffffc0e9c48000 [ 12.060774] x27: ffffffc0e9c48000 x26: ffffffc00134c5e0 [ 12.066128] x25: 0000000000000000 x24: 00000000000003c0 [ 12.071466] x23: 0000000000000000 x22: 0000000000000002 [ 12.076803] x21: 0000000000000000 x20: 0000000000000000 [ 12.082140] x19: ffffffc001386000 x18: 0000000000000007 [ 12.087477] x17: 0000000000000400 x16: 0000000000000000 [ 12.092815] x15: ffffffc0ee24e448 x14: 00000000ffffffd0 [ 12.098150] x13: ffffffc0020e35e9 x12: 00000000000003f0 [ 12.103486] x11: fffffffffffca235 x10: 0000000000000000 [ 12.108814] x9 : cb88537fdc8ba656 x8 : 0000000000000000 [ 12.114141] x7 : ffffffc001375ac0 x6 : ffffffc00027f208 [ 12.119477] x5 : 0000000000000000 x4 : 0000000000000001 [ 12.124813] x3 : 0000000000000000 x2 : ffffffc00027f220 [ 12.130150] x1 : 0000000000000001 x0 : 000000000000002e ... ... [ 13.152467] ---[ end trace 3936d5660bf8115a ]--- [ 13.157082] Call trace: [ 13.159534] [<ffffffc00027106c>] check_flags+0x178/0x190 [ 13.164844] [<ffffffc0002719e4>] lock_acquire+0x60/0x240 [ 13.170156] [<ffffffc000202360>] rcu_lock_acquire+0x30/0x38 [ 13.175734] [<ffffffc000202284>] rcu_read_lock+0x1c/0x64 [ 13.181055] [<ffffffc000202194>] brk_handler+0x3c/0x110 [ 13.186285] [<ffffffc0002004a4>] do_debug_exception+0x5c/0xe4 [ 13.192040] Exception stack(0xffffffc0e9c4ba60 to 0xffffffc0e9c4bb90) [ 13.198487] ba60: 0000000000000027 0000000000000001 ffffffc00025322c 0000000000000000 [ 13.206323] ba80: 0000000000000001 0000000000000000 ffffffc000253200 ffffffc00029d23c [ 13.214160] baa0: 0000000000000000 cb88537fdc8ba656 0000000000000000 ffffffc0e9a7d6f0 [ 13.222000] bac0: 00000000000011e8 ffffffc0ee24edf0 00000000000c0013 ffffffc0ee24e448 [ 13.229838] bae0: 0000000000000000 0000000000000400 0000000000000007 ffffffc0da306000 [ 13.237672] bb00: ffffffc0d9a83270 ffffffc0da306fa8 00000000ffffffff ffffffc0da306fa8 [ 13.245506] bb20: ffffffc0e9c4bc48 dead000000000200 ffffffc0013e13f8 ffffffc0e9c4bc48 [ 13.253336] bb40: ffffffc0013e13f8 ffffffc0e9c4bbc0 ffffffc0008549ec ffffffc0e9c4bb90 [ 13.261167] bb60: ffffffc0008549ec 0000000080000145 ffffffc0d9a83270 ffffffc0da306000 [ 13.268997] bb80: ffffffffffffffff ffffffc0008549ec [ 13.273876] [<ffffffc0002035e0>] el1_dbg+0x18/0x74 [ 13.278666] [<ffffffc000855320>] netfilter_net_exit+0x38/0x68 [ 13.284408] [<ffffffc000817520>] ops_exit_list+0x38/0x64 [ 13.289717] [<ffffffc0008177ac>] cleanup_net+0x180/0x238 [ 13.295027] [<ffffffc00023c4c8>] process_one_work+0x310/0x5b8 [ 13.300768] [<ffffffc00023bde8>] worker_thread+0x190/0x2b0 [ 13.306250] [<ffffffc000241400>] kthread+0xe4/0xf4 [ 13.311039] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40 [ 13.316347] possible reason: unannotated irqs-off. --- This appears to be fixed upstream by: 6afedcd23cfd arm64: mm: Add trace_irqflags annotations to do_debug_exception()
,
Oct 10 2017
> Specifically, I saw this warning hit in netfilter: > > WARN(1, "nf_unregister_net_hook: hook not found!\n"); > > ...that needs to debugged separately This has been open forever: https://b.corp.google.com/issues/35586952 Maybe we should just migrate it to crbug...
,
Oct 10 2017
> This has been open forever: > > https://b.corp.google.com/issues/35586952 Yup. Ah, right. I was going to try to look for it since I knew we'd talked about it before. In any case, it's got me in the bad habit of ignoring all the warnings that happen at bootup which I'm trying to correct. This happens all the time for me, so I'm seeing if there's something obvious I can do about it... > Maybe we should just migrate it to crbug... Let me see if there's some obvious way to fix it. If so maybe we can just close it out instead of having to migrate it.
,
Oct 11 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/kernel/+/b04db86fe9aeac1b9c7dd74bcb31ef8d911e2213 commit b04db86fe9aeac1b9c7dd74bcb31ef8d911e2213 Author: James Morse <james.morse@arm.com> Date: Wed Oct 11 02:49:38 2017 UPSTREAM: arm64: mm: Add trace_irqflags annotations to do_debug_exception() With CONFIG_PROVE_LOCKING, CONFIG_DEBUG_LOCKDEP and CONFIG_TRACE_IRQFLAGS enabled, lockdep will compare current->hardirqs_enabled with the flags from local_irq_save(). When a debug exception occurs, interrupts are disabled in entry.S, but lockdep isn't told, resulting in: DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled) ------------[ cut here ]------------ WARNING: at ../kernel/locking/lockdep.c:3523 Modules linked in: CPU: 3 PID: 1752 Comm: perf Not tainted 4.5.0-rc4+ #2204 Hardware name: ARM Juno development board (r1) (DT) task: ffffffc974868000 ti: ffffffc975f40000 task.ti: ffffffc975f40000 PC is at check_flags.part.35+0x17c/0x184 LR is at check_flags.part.35+0x17c/0x184 pc : [<ffffff80080fc93c>] lr : [<ffffff80080fc93c>] pstate: 600003c5 [...] ---[ end trace 74631f9305ef5020 ]--- Call trace: [<ffffff80080fc93c>] check_flags.part.35+0x17c/0x184 [<ffffff80080ffe30>] lock_acquire+0xa8/0xc4 [<ffffff8008093038>] breakpoint_handler+0x118/0x288 [<ffffff8008082434>] do_debug_exception+0x3c/0xa8 [<ffffff80080854b4>] el1_dbg+0x18/0x6c [<ffffff80081e82f4>] do_filp_open+0x64/0xdc [<ffffff80081d6e60>] do_sys_open+0x140/0x204 [<ffffff80081d6f58>] SyS_openat+0x10/0x18 [<ffffff8008085d30>] el0_svc_naked+0x24/0x28 possible reason: unannotated irqs-off. irq event stamp: 65857 hardirqs last enabled at (65857): [<ffffff80081fb1c0>] lookup_mnt+0xf4/0x1b4 hardirqs last disabled at (65856): [<ffffff80081fb188>] lookup_mnt+0xbc/0x1b4 softirqs last enabled at (65790): [<ffffff80080bdca4>] __do_softirq+0x1f8/0x290 softirqs last disabled at (65757): [<ffffff80080be038>] irq_exit+0x9c/0xd0 This patch adds the annotations to do_debug_exception(), while trying not to call trace_hardirqs_off() if el1_dbg() interrupted a task that already had irqs disabled. BUG= chromium:773355 TEST=Add fake WARN to netfilter_net_exit() and no more lockdep splat Change-Id: I79a84d1e08c4bc6059fa1ca4335ce00af2db1815 Signed-off-by: James Morse <james.morse@arm.com> Signed-off-by: Will Deacon <will.deacon@arm.com> Signed-off-by: Douglas Anderson <dianders@chromium.org> (cherry picked from commit 6afedcd23cfd7ac56c011069e4a8db37b46e4623) Reviewed-on: https://chromium-review.googlesource.com/709918 Reviewed-by: Guenter Roeck <groeck@chromium.org> [modify] https://crrev.com/b04db86fe9aeac1b9c7dd74bcb31ef8d911e2213/arch/arm64/mm/fault.c
,
Oct 11 2017
,
Jan 22 2018
,
Jan 23 2018
|
||||||
►
Sign in to add a comment |
||||||
Comment 1 by diand...@chromium.org
, Oct 10 2017