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
