Message-ID: <CA+G9fYuwv+TEhgi46pjs2-GCe0mmMHyki9nAokvGCEA2syK5Dg@mail.gmail.com>
Date:   Tue, 7 Apr 2020 14:55:26 +0530
From:   Naresh Kamboju <naresh.kamboju@...aro.org>
To:     Brendan Higgins <brendanhiggins@...gle.com>
Cc:     Heikki Krogerus <heikki.krogerus@...ux.intel.com>,
        Sakari Ailus <sakari.ailus@...ux.intel.com>,
        Andy Shevchenko <andy.shevchenko@...il.com>,
        Hans de Goede <hdegoede@...hat.com>,
        "rafael.j.wysocki" <rafael.j.wysocki@...el.com>,
        open list <linux-kernel@...r.kernel.org>,
        "open list:KERNEL SELFTEST FRAMEWORK" 
        <linux-kselftest@...r.kernel.org>,
        Steven Rostedt <rostedt@...dmis.org>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Andy Shevchenko <andriy.shevchenko@...ux.intel.com>,
        Shuah Khan <shuah@...nel.org>,
        Anders Roxell <anders.roxell@...aro.org>,
        lkft-triage@...ts.linaro.org,
        Rasmus Villemoes <linux@...musvillemoes.dk>
Subject: Re: BUG: kernel NULL pointer dereference, address: 00 - ida_free+0x76/0x140

On Wed, 11 Mar 2020 at 02:16, Brendan Higgins <brendanhiggins@...gle.com> 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@lists.01.org/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@...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

Powered by blists - more mailing lists