Re: BUG: kernel NULL pointer dereference, address: 00 - ida_free+0x76/0x140

From: Naresh Kamboju
Date: Tue Apr 07 2020 - 05:25:44 EST


On Wed, 11 Mar 2020 at 02:16, Brendan Higgins <brendanhiggins@xxxxxxxxxx> wrote:
> > > > > > > > > > Steps reproduce by using kselftests,
> > > > > > > > > >
> > > > > > > > > > - lsmod || true
> > > > > > > > > > - cd /opt/kselftests/default-in-kernel/lib/
> > > > > > > > > > - export PATH=/opt/kselftests/default-in-kernel/kselftest:$PATH
> > > > > > > > > > - ./printf.sh || true
> > > > > > > > > > - ./bitmap.sh || true
> > > > > > > > > > - ./prime_numbers.sh || true
> > > > > > > > > > - ./strscpy.sh || true
> > > > > > > > > >
> > > > > > > > > > x86_64 kernel BUG dump.
> > > > > > > > > > + ./printf.sh
> > > > > > > >
> > > > > > > > Oops, I am wondering if I broke this with my change "Revert "software
> > > > > > > > node: Simplify software_node_release() function"":
> > > > > > > >
> > > > > > > > https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/commit/?id=d1c19322388d6935b534b494a2c223dd089e30dd
> > > > > > > >
> > > > > > > > I am still investigating, will update later.
> > > > > > >
> > > > > > > Okay, yeah, I am pretty sure I caused the breakage. I got an email
> > > > > > > from kernel test robot a couple days ago that I didn't see:
> > > > > > >
> > > > > > > https://lists.01.org/hyperkitty/list/lkp@xxxxxxxxxxxx/thread/N3ZN5XH7HK24JVEJ5WSQD2SK6YCDRILR/
> > > > > > >
> > > > > > > It shows the same breakage after applying this change.
> > > > > > >
> > > > > > > I am still investigating how my change broke it, nevertheless.
> > > > > >
> > > > > > As nodes in the tree are being removed, the code before the patch that
> > > > > > "simplified" the software_node_release() function accessed the node's parent
> > > > > > in its release function.
> > > > > >
> > > > > > And if CONFIG_DEBUG_KOBJECT_RELEASE is defined, the release functions are no
> > > > > > longer necessarily called in order, leading to referencing released memory.
> > > > > > Oops!
> > > > > >
> > > > > > So Heikki's patch actually fixed a bug. :-)
> > > > >
> > > > > Well, I think it just hid the problem. It looks like the core
> > > > > (lib/kobject.c) allows the parent kobject to be released before the
> > > > > last child kobject is released. To be honest, that does not sound
> > > > > right to me...
> > > > >
> > > > > I think we can workaround this problem by taking reference to the
> > > > > parent when the child is added, and then releasing it when the child
> > > > > is released, and in that way be guaranteed that the parent will not
> > > > > disappear before the child is fully released, but that still does not
> > > > > feel right. It feels more like the core is not doing it's job to me.
> > > > > The parent just should not be released before its children.
> > > > >
> > > > > Either I'm wrong about that, and we still should take the reference on
> > > > > the parent, or we revert my patch like Brendan proposed and then fix
> > > >
> > > > Either way, isn't it wrong to release the node ID before deleting the
> > > > sysfs entry? I am not sure that my fix was the correct one, but I
> > > > believe the bug that Heidi and I found is actually a bug.
> >
> > I agree.
> >
> > > > > the core with something like this (warning, I did not even try to
> > > > > compile that):
> > > >
> > > > I will try it out.
> > > >
> > > > > diff --git a/lib/kobject.c b/lib/kobject.c
> > > > > index 83198cb37d8d..ec5774992337 100644
> > > > > --- a/lib/kobject.c
> > > > > +++ b/lib/kobject.c
> > > > > @@ -680,6 +680,12 @@ static void kobject_cleanup(struct kobject *kobj)
> > > > > kobject_uevent(kobj, KOBJ_REMOVE);
> > > > > }
> > > > >
> > > > > + if (t && t->release) {
> > > > > + pr_debug("kobject: '%s' (%p): calling ktype release\n",
> > > > > + kobject_name(kobj), kobj);
> > > > > + t->release(kobj);
> > > > > + }
> > > > > +
> > > > > /* remove from sysfs if the caller did not do it */
> > > > > if (kobj->state_in_sysfs) {
> > > > > pr_debug("kobject: '%s' (%p): auto cleanup kobject_del\n",
> > > > > @@ -687,12 +693,6 @@ static void kobject_cleanup(struct kobject *kobj)
> > > > > kobject_del(kobj);
> > > > > }
> > > > >
> > > > > - if (t && t->release) {
> > > > > - pr_debug("kobject: '%s' (%p): calling ktype release\n",
> > > > > - kobject_name(kobj), kobj);
> > > > > - t->release(kobj);
> > > > > - }
> > > > > -
> > > > > /* free name if we allocated it */
> > > > > if (name) {
> > > > > pr_debug("kobject: '%s': free name\n", name);
> > >
> > > Alright, so I tried it and it looks like Heikki's suggestion worked.
> > >
> > > Is everyone comfortable going this route?
> >
> > Hold on. Another way to fix the problem is to increment the parent's
> > reference count before that kobject_del(kobj) is called, and then
> > decrementing it after t->release(kobj) is called. It may be safer to
> > fix the problem like that.
>
> Right, this was your first suggestion above, right? That actually made
> more sense to me, but you seemed skeptical of it due to it being
> messier, which makes sense.
>
> Nevertheless, having children take a reference seems like the right
> thing to do because the children need to degregister themselves from
> the parent. Calling t->release() ahead of kobject_del() seems to
> reintroduce the problem that I pointed out, albeit *much* more
> briefly. If I understand correctly, it is always wrong to have a sysfs
> entry that points to a partially deallocated kobject. Please correct
> me if I am wrong.
>
> So I think there are two solutions: Either we have to ensure that each
> child is deallocated first so we can preserve the kobject_del() and
> then t->release() ordering, or we have to add some sort of "locking"
> mechanism to prevent the kobject from being accessed by anything other
> than the deallocation code until it is fully deallocated; well, it
> would have to prevent any access at all :-). I think it goes without
> saying that this "locking" idea is pretty flawed.
>
> The problem with just having children take a reference is that the
> kobject children already take a reference to their parent, so it seems
> like the kobject should be smart enough to deallocate children rather
> than having swnode have to keep a separate tally of children, no?
>
> Sorry if this all seems obvious, I am not an expert on this part of the kernel.
>
> > My example above proofs that there is the problem, but it changes the
> > order of execution which I think can always have other consequences.
> >
> > > Also, should I send this fix as a separate patch? Or do people want me
> > > to send an updated revision of my revert patch with the fix?
> >
> > This needs to be send in its own separate patch. Ideally it could be
> > send together with the revert in the same series, but I'm not sure
> > that's possible anymore. Didn't Greg pick the revert already?
>
> Sounds good.
>
> I did already let Greg know when he emailed us on backporting the
> patch to stable, and he acked saying he removed them. So as long as
> these are not in the queue for 5.6 (it is not in Linus' tree yet), we
> should be good.

The reported bug is still noticed on Linux mainline master branch
The Kernel BUG noticed on x86_64 and i386 running selftest on Linux
mainline kernel 5.6.0.

Linux version 5.6.0 (oe-user@oe-host) (gcc version 7.3.0 (GCC)) #1 SMP
Mon Apr 6 17:25:26 UTC 2020
<>
[ 270.580905] BUG: kernel NULL pointer dereference, address: 0000000000000000
[ 270.588978] #PF: supervisor read access in kernel mode
[ 270.594114] #PF: error_code(0x0000) - not-present page
[ 270.599247] PGD 800000026b340067 P4D 800000026b340067 PUD 26b34e067 PMD 0
[ 270.606119] Oops: 0000 [#1] SMP PTI
[ 270.609604] CPU: 1 PID: 4688 Comm: modprobe Tainted: G W
5.6.0 #1
[ 270.616996] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 270.624381] RIP: 0010:ida_free+0x76/0x140
[ 270.628391] Code: 45 d0 00 00 00 00 48 89 45 b0 0f 88 c4 00 00 00
89 f3 e8 0d 51 02 00 48 8d 7d a8 49 89 c6 e8 e1 04 01 00 a8 01 49 89
c5 75 42 <4c> 0f a3 20 72 76 48 8b 7d a8 4c 89 f6 e8 18 53 02 00 89 de
48 c7
[ 270.647128] RSP: 0018:ffffbd8841d07a50 EFLAGS: 00010046
[ 270.652346] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff978be6ac48c0
[ 270.659468] RDX: 0000000000000000 RSI: ffff978beb346780 RDI: ffff978be6ac5138
[ 270.666595] RBP: ffffbd8841d07aa8 R08: 0000000000000001 R09: 0000000000000000
[ 270.673725] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 270.680850] R13: 0000000000000000 R14: 0000000000000246 R15: ffffffffc0383b3c
[ 270.687973] FS: 00007fc8e92c2740(0000) GS:ffff978befa80000(0000)
knlGS:0000000000000000
[ 270.696052] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 270.701790] CR2: 0000000000000000 CR3: 000000021f2b0003 CR4: 00000000003606e0
[ 270.708920] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 270.716043] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 270.723169] Call Trace:
[ 270.725618] software_node_release+0x2b/0xb0
[ 270.729886] kobject_put+0xad/0x1c0
[ 270.733378] kobject_del+0x4a/0x60
[ 270.736776] kobject_put+0x92/0x1c0
[ 270.740270] fwnode_remove_software_node+0x32/0x40
[ 270.745061] software_node_unregister_nodes+0x2a/0x50
[ 270.750114] test_printf_init+0xf30/0x1c16 [test_printf]
[ 270.755422] ? test_hashed+0x75/0x75 [test_printf]
[ 270.760211] ? test_hashed+0x75/0x75 [test_printf]
[ 270.765003] do_one_initcall+0x61/0x2f0
[ 270.768842] ? rcu_read_lock_sched_held+0x4f/0x80
[ 270.773541] ? kmem_cache_alloc_trace+0x282/0x2b0
[ 270.778247] do_init_module+0x5f/0x22b
[ 270.781999] load_module+0x24e6/0x2ac0
[ 270.785754] ? security_kernel_post_read_file+0x3f/0x60
[ 270.790979] __do_sys_finit_module+0xfc/0x120
[ 270.795334] ? __do_sys_finit_module+0xfc/0x120
[ 270.799862] __x64_sys_finit_module+0x1a/0x20
[ 270.804219] do_syscall_64+0x55/0x200
[ 270.807885] entry_SYSCALL_64_after_hwframe+0x49/0xb3
[ 270.812938] RIP: 0033:0x7fc8e8bcaf59
[ 270.816516] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00
00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24
08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 0f ff 2b 00 f7 d8 64 89
01 48
[ 270.835253] RSP: 002b:00007ffe9a4fb6f8 EFLAGS: 00000202 ORIG_RAX:
0000000000000139
[ 270.842810] RAX: ffffffffffffffda RBX: 0000000000cdfaf0 RCX: 00007fc8e8bcaf59
[ 270.849934] RDX: 0000000000000000 RSI: 0000000000418cce RDI: 0000000000000005
[ 270.857057] RBP: 0000000000418cce R08: 0000000000000000 R09: 0000000000000000
[ 270.864180] R10: 0000000000000005 R11: 0000000000000202 R12: 0000000000000000
[ 270.871306] R13: 0000000000040000 R14: 0000000000000000 R15: 0000000000000000
[ 270.878433] Modules linked in: test_printf(+) cls_bpf sch_fq 8021q
sch_ingress veth algif_hash x86_pkg_temp_thermal fuse [last unloaded:
gpio_mockup]
[ 270.891812] CR2: 0000000000000000
[ 270.895130] ---[ end trace 151cfe414205f0bc ]---
[ 270.899742] RIP: 0010:ida_free+0x76/0x140
[ 270.903752] Code: 45 d0 00 00 00 00 48 89 45 b0 0f 88 c4 00 00 00
89 f3 e8 0d 51 02 00 48 8d 7d a8 49 89 c6 e8 e1 04 01 00 a8 01 49 89
c5 75 42 <4c> 0f a3 20 72 76 48 8b 7d a8 4c 89 f6 e8 18 53 02 00 89 de
48 c7
[ 270.922489] RSP: 0018:ffffbd8841d07a50 EFLAGS: 00010046
[ 270.927706] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff978be6ac48c0
[ 270.934831] RDX: 0000000000000000 RSI: ffff978beb346780 RDI: ffff978be6ac5138
[ 270.941954] RBP: ffffbd8841d07aa8 R08: 0000000000000001 R09: 0000000000000000
[ 270.949078] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[ 270.956204] R13: 0000000000000000 R14: 0000000000000246 R15: ffffffffc0383b3c
[ 270.963328] FS: 00007fc8e92c2740(0000) GS:ffff978befa80000(0000)
knlGS:0000000000000000
[ 270.971414] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 270.977158] CR2: 0000000000000000 CR3: 000000021f2b0003 CR4: 00000000003606e0
[ 270.984281] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 270.991407] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 270.998540] BUG: sleeping function called from invalid context at
/usr/src/kernel/include/linux/percpu-rwsem.h:49
[ 271.008782] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid:
4688, name: modprobe
[ 271.016771] INFO: lockdep is turned off.
[ 271.020691] irq event stamp: 4812
[ 271.024011] hardirqs last enabled at (4811): [<ffffffffb5be42f1>]
kfree+0x181/0x2e0
[ 271.031748] hardirqs last disabled at (4812): [<ffffffffb67d2b68>]
_raw_spin_lock_irqsave+0x18/0x50
[ 271.040778] softirqs last enabled at (4496): [<ffffffffb6a00348>]
__do_softirq+0x348/0x459
[ 271.049117] softirqs last disabled at (4487): [<ffffffffb59be298>]
irq_exit+0xb8/0xc0
[ 271.056933] CPU: 1 PID: 4688 Comm: modprobe Tainted: G D W
5.6.0 #1
[ 271.064317] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 271.071702] Call Trace:
[ 271.074147] dump_stack+0x7a/0xa5
[ 271.077465] ___might_sleep+0x163/0x250
[ 271.081296] __might_sleep+0x4a/0x80
[ 271.084868] exit_signals+0x33/0x2f0
[ 271.088446] do_exit+0xb6/0xcd0
[ 271.091586] rewind_stack_do_exit+0x17/0x20
[ 271.095770] RIP: 0033:0x7fc8e8bcaf59
[ 271.099349] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00
00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24
08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 0f ff 2b 00 f7 d8 64 89
01 48
[ 271.118093] RSP: 002b:00007ffe9a4fb6f8 EFLAGS: 00000202 ORIG_RAX:
0000000000000139
[ 271.125649] RAX: ffffffffffffffda RBX: 0000000000cdfaf0 RCX: 00007fc8e8bcaf59
[ 271.132775] RDX: 0000000000000000 RSI: 0000000000418cce RDI: 0000000000000005
[ 271.139897] RBP: 0000000000418cce R08: 0000000000000000 R09: 0000000000000000
[ 271.147022] R10: 0000000000000005 R11: 0000000000000202 R12: 0000000000000000
[ 271.154146] R13: 0000000000040000 R14: 0000000000000000 R15: 0000000000000000
[ 271.161274] note: modprobe[4688] exited with preempt_count 1

Full test log:
https://lkft.validation.linaro.org/scheduler/job/1341945#L8386
https://lkft.validation.linaro.org/scheduler/job/1341969#L8023


- Naresh