Re: [PATCH] kernel/trace: Stop and wait for kthread on preempt irq module unload

From: Xiao Yang
Date: Wed Apr 29 2020 - 07:37:27 EST

Next message: Alexander Filippov: "[PATCH v7] ARM: DTS: Aspeed: Add YADRO Nicole BMC"
Previous message: Michael Ellerman: "Re: [PATCH v7 5/5] powerpc/hv-24x7: Update post_mobility_fixup() to handle migration"
In reply to: Joel Fernandes: "Re: [PATCH] kernel/trace: Stop and wait for kthread on preempt irq module unload"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi Joel, Steven

First of all, the previous dmesg may not be reliable and I often got the
following dmesg by inserting and remving preemptirq_delay_test in loops:
(btw: I think these dmesgs are caused by the same bug).
---------------------------------------------------
[ 178.484520] ------------[ cut here ]------------
[ 178.510058] refcount_t: addition on 0; use-after-free.
[ 178.511663] WARNING: CPU: 0 PID: 2389 at lib/refcount.c:25
refcount_warn_saturate+0x9c/0x140
[ 178.512266] Modules linked in: preemptirq_delay_test(-) sunrpc vfat
fat ext4 mbcache jbd2 crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce
ip_tables xfs libcrc32c virtio_net net_failover virtio_mmio failover
virtio_blk [last unloaded: preemptirq_delay_test]
[ 178.514061] CPU: 0 PID: 2389 Comm: rmmod Not tainted 5.6.0-rc7+ #18
[ 178.514389] Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0
02/06/2015
[ 178.514988] pstate: 40000005 (nZcv daif -PAN -UAO)
[ 178.515259] pc : refcount_warn_saturate+0x9c/0x140
[ 178.515562] lr : refcount_warn_saturate+0x9c/0x140
[ 178.515865] sp : fffffe001300fd70
[ 178.516082] x29: fffffe001300fd70 x28: fffffc004533e380
[ 178.516366] x27: 0000000000000000 x26: 0000000000000000
[ 178.516611] x25: 0000000000000000 x24: fffffe00115bbbf0
[ 178.516847] x23: 0000000000000000 x22: 0000000000000200
[ 178.517121] x21: fffffe0011273988 x20: fffffc007cf7af28
[ 178.517554] x19: fffffc007cf7af00 x18: 0000000000000010
[ 178.517795] x17: 0000000000000000 x16: 0000000000000000
[ 178.518044] x15: ffffffffffffffff x14: fffffe0011273988
[ 178.518279] x13: fffffe009300fa97 x12: fffffe001300fa9f
[ 178.518518] x11: fffffe00112b0000 x10: fffffe001300fa20
[ 178.518885] x9 : 00000000ffffffd0 x8 : 75203b30206e6f20
[ 178.519316] x7 : 000000000000014e x6 : fffffe001127cf50
[ 178.519661] x5 : fffffe001127c000 x4 : 0000000000000000
[ 178.519978] x3 : fffffe001127cf50 x2 : 0000000000000000
[ 178.520245] x1 : cecd1d29479b5500 x0 : 0000000000000000
[ 178.520659] Call trace:
[ 178.520850] refcount_warn_saturate+0x9c/0x140
[ 178.521084] kthread_stop+0x48/0x278
[ 178.521703] preemptirq_delay_exit+0x28/0xfc8c [preemptirq_delay_test]
[ 178.522006] __arm64_sys_delete_module+0x14c/0x298
[ 178.522226] do_el0_svc+0xf8/0x1e0
[ 178.522403] el0_sync_handler+0x134/0x1bc
[ 178.522598] el0_sync+0x140/0x180
[ 178.522862] ---[ end trace 437c7bc9df5e92dd ]---
[ 178.524159] ------------[ cut here ]------------
[ 178.524420] refcount_t: underflow; use-after-free.
[ 178.524734] WARNING: CPU: 0 PID: 2389 at lib/refcount.c:28
refcount_warn_saturate+0xf0/0x140
[ 178.525079] Modules linked in: preemptirq_delay_test(-) sunrpc vfat
fat ext4 mbcache jbd2 crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce
ip_tables xfs libcrc32c virtio_net net_failover virtio_mmio failover
virtio_blk [last unloaded: preemptirq_delay_test]
[ 178.526190] CPU: 0 PID: 2389 Comm: rmmod Tainted: G W
5.6.0-rc7+ #18
[ 178.526541] Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0
02/06/2015
[ 178.526836] pstate: 40000005 (nZcv daif -PAN -UAO)
[ 178.527060] pc : refcount_warn_saturate+0xf0/0x140
[ 178.527269] lr : refcount_warn_saturate+0xf0/0x140
[ 178.527484] sp : fffffe001300fd70
[ 178.527643] x29: fffffe001300fd70 x28: fffffc004533e380
[ 178.527905] x27: 0000000000000000 x26: 0000000000000000
[ 178.528166] x25: 0000000000000000 x24: fffffe00115bbbf0
[ 178.528489] x23: 0000000000000000 x22: 0000000000000200
[ 178.528808] x21: 0000000000000000 x20: fffffc007cf7af28
[ 178.529080] x19: fffffc007cf7af00 x18: 0000000000000010
[ 178.529429] x17: 0000000000000000 x16: 0000000000000000
[ 178.529747] x15: ffffffffffffffff x14: 0720072007200720
[ 178.530100] x13: 0720072007200720 x12: 0720072007200720
[ 178.530366] x11: 0720072007200720 x10: 0720072007200720
[ 178.530632] x9 : 0720072007200720 x8 : 072007200720072e
[ 178.530891] x7 : 0000000000000170 x6 : fffffe001127cf50
[ 178.531154] x5 : fffffe001127c000 x4 : 0000000000000000
[ 178.531431] x3 : fffffe001127cf50 x2 : 0000000000000000
[ 178.531705] x1 : cecd1d29479b5500 x0 : 0000000000000000
[ 178.532003] Call trace:
[ 178.532166] refcount_warn_saturate+0xf0/0x140
[ 178.532434] kthread_stop+0x254/0x278
[ 178.532644] preemptirq_delay_exit+0x28/0xfc8c [preemptirq_delay_test]
[ 178.532963] __arm64_sys_delete_module+0x14c/0x298
[ 178.533210] do_el0_svc+0xf8/0x1e0
[ 178.533415] el0_sync_handler+0x134/0x1bc
[ 178.533627] el0_sync+0x140/0x180
[ 178.533807] ---[ end trace 437c7bc9df5e92de ]---
[ 178.626471] Unable to handle kernel paging request at virtual address
0000fffffc0043ca
[ 178.627253] Mem abort info:
[ 178.627539] ESR = 0x96000004
[ 178.627927] EC = 0x25: DABT (current EL), IL = 32 bits
[ 178.628414] SET = 0, FnV = 0
[ 178.628806] EA = 0, S1PTW = 0
[ 178.629090] Data abort info:
[ 178.639723] ISV = 0, ISS = 0x00000004
[ 178.640182] CM = 0, WnR = 0
[ 178.640530] [0000fffffc0043ca] address between user and kernel
address ranges
[ 178.641300] Internal error: Oops: 96000004 [#1] PREEMPT SMP
[ 178.641931] Modules linked in: sunrpc vfat fat ext4 mbcache jbd2
crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce ip_tables xfs
libcrc32c virtio_net net_failover virtio_mmio failover virtio_blk [last
unloaded: preemptirq_delay_test]
[ 178.643547] CPU: 1 PID: 2394 Comm: pmlogger_check Tainted: G W
5.6.0-rc7+ #18
[ 178.644219] Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0
02/06/2015
[ 178.644782] pstate: 60000005 (nZCv daif -PAN -UAO)
[ 178.645219] pc : __kmalloc+0xc8/0x2e8
[ 178.645538] lr : __kmalloc+0x9c/0x2e8
[ 178.645841] sp : fffffe001312fc20
[ 178.646127] x29: fffffe001312fc20 x28: fffffc0042a0af00
[ 178.646532] x27: fffffc005a7ad000 x26: 00000000cc79f001
[ 178.647037] x25: fffffc0042a0af00 x24: fffffc007d76fc00
[ 178.647431] x23: fffffe00103e95e4 x22: 000000000000001b
[ 178.647895] x21: 0000000000000cc0 x20: fffffc007d76fc00
[ 178.648276] x19: 0000fffffc0043ca x18: 0000000000000000
[ 178.648673] x17: 0000000000000000 x16: 0000000000000000
[ 178.649077] x15: 0000000000000000 x14: 0000000000000010
[ 178.649608] x13: 0000000000000000 x12: 0000000000000000
[ 178.649963] x11: 0000000000000000 x10: 0000000000000000
[ 178.650337] x9 : 0000000000000000 x8 : 0000000000001f18
[ 178.650683] x7 : 0000000000001f18 x6 : fffffc005a7ad1f8
[ 178.651099] x5 : 0000000000000000 x4 : 0000000000000000
[ 178.651557] x3 : 0000000000000000 x2 : fffffe001021d1e0
[ 178.652006] x1 : 0000000000000000 x0 : 0000000000000001
[ 178.652407] Call trace:
[ 178.652694] __kmalloc+0xc8/0x2e8
[ 178.652972] load_elf_binary+0xdc/0xdb8
[ 178.653286] search_binary_handler+0x98/0x268
[ 178.653626] __do_execve_file+0x4ec/0x7c8
[ 178.653985] __arm64_sys_execve+0x40/0x50
[ 178.654310] do_el0_svc+0xf8/0x1e0
[ 178.654578] el0_sync_handler+0x134/0x1bc
[ 178.654962] el0_sync+0x140/0x180
[ 178.655509] Code: b4001073 b9402281 b9401380 11000400 (f8616a7b)
[ 178.656543] ---[ end trace 437c7bc9df5e92df ]---
[ 178.657100] Kernel panic - not syncing: Fatal exception
[ 178.657630] SMP: stopping secondary CPUs
[ 178.658237] Kernel Offset: disabled
[ 178.658644] CPU features: 0x10002,20006082
[ 178.658903] Memory Limit: none
[ 178.659263] ---[ end Kernel panic - not syncing: Fatal exception ]---
---------------------------------------------------

Thanks,
Xiao Yang
On 2020/4/28 18:19, Xiao Yang wrote:
> Hi Joel,
>
> Thanks for your quick fix.
>
> Unfortunately, it fixes my original panic but introduces other
> issues(two wanings and one panic) on my arm64 vm, as below:
> --------------------------------------------------------------------
> [ 3465.434942] ------------[ cut here ]------------
> [ 3465.435481] refcount_t: addition on 0; use-after-free.
> [ 3465.437071] WARNING: CPU: 1 PID: 6708 at lib/refcount.c:25
> refcount_warn_saturate+0x9c/0x140
> [ 3465.437720] Modules linked in: preemptirq_delay_test(O-) sunrpc vfat
> fat ext4 mbcache jbd2 crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce
> ip_tables xfs libcrc32c virtio_net net_failover failover virtio_mmio
> virtio_blk
> [ 3465.439787] CPU: 1 PID: 6708 Comm: rmmod Tainted: G O
> 5.6.0-rc7+ #18
> [ 3465.440316] Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0
> 02/06/2015
> [ 3465.440967] pstate: 40000005 (nZcv daif -PAN -UAO)
> [ 3465.441297] pc : refcount_warn_saturate+0x9c/0x140
> [ 3465.441592] lr : refcount_warn_saturate+0x9c/0x140
> [ 3465.441919] sp : fffffe001382fd70
> [ 3465.442160] x29: fffffe001382fd70 x28: fffffc004876d200
> [ 3465.442649] x27: 0000000000000000 x26: 0000000000000000
> [ 3465.443071] x25: 0000000000000000 x24: fffffe00115bbbf0
> [ 3465.443670] x23: 0000000000000000 x22: 0000000000000200
> [ 3465.444194] x21: fffffe0011273988 x20: fffffc0063fdd228
> [ 3465.444576] x19: fffffc0063fdd200 x18: 0000000000000010
> [ 3465.444939] x17: 0000000000000000 x16: 0000000000000000
> [ 3465.445329] x15: ffffffffffffffff x14: fffffe0011273988
> [ 3465.445698] x13: fffffe009382fa97 x12: fffffe001382fa9f
> [ 3465.446116] x11: fffffe00112b0000 x10: fffffe001382fa20
> [ 3465.446498] x9 : 00000000ffffffd0 x8 : 6572662d72657466
> [ 3465.446941] x7 : 0000000000000149 x6 : fffffe001127cf50
> [ 3465.447375] x5 : fffffe001127c000 x4 : 0000000000000000
> [ 3465.447757] x3 : fffffe001127cf50 x2 : 0000000000000000
> [ 3465.448161] x1 : 2e36d2803fe6b700 x0 : 0000000000000000
> [ 3465.448702] Call trace:
> [ 3465.448979] refcount_warn_saturate+0x9c/0x140
> [ 3465.449330] kthread_stop+0x48/0x278
> [ 3465.450144] preemptirq_delay_exit+0x28/0xfc8c [preemptirq_delay_test]
> [ 3465.450625] __arm64_sys_delete_module+0x14c/0x298
> [ 3465.450998] do_el0_svc+0xf8/0x1e0
> [ 3465.451372] el0_sync_handler+0x134/0x1bc
> [ 3465.451701] el0_sync+0x140/0x180
> [ 3465.452099] ---[ end trace 1a8ec2201af5e8c7 ]---
> [ 3465.478208] ------------[ cut here ]------------
> [ 3465.478696] WARNING: CPU: 1 PID: 6708 at kernel/kthread.c:400
> __kthread_bind_mask+0x34/0x90
> [ 3465.479210] Modules linked in: preemptirq_delay_test(O-) sunrpc vfat
> fat ext4 mbcache jbd2 crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce
> ip_tables xfs libcrc32c virtio_net net_failover failover virtio_mmio
> virtio_blk
> [ 3465.480509] CPU: 1 PID: 6708 Comm: rmmod Tainted: G W O
> 5.6.0-rc7+ #18
> [ 3465.480966] Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0
> 02/06/2015
> [ 3465.481465] pstate: 40000005 (nZcv daif -PAN -UAO)
> [ 3465.481821] pc : __kthread_bind_mask+0x34/0x90
> [ 3465.482129] lr : __kthread_bind_mask+0x30/0x90
> [ 3465.482419] sp : fffffe001382fd30
> [ 3465.482639] x29: fffffe001382fd30 x28: fffffc004876d200
> [ 3465.483017] x27: 0000000000000000 x26: 0000000000000000
> [ 3465.483385] x25: 0000000000000000 x24: fffffe00115bbbf0
> [ 3465.483795] x23: 0000000000000000 x22: 0000000000000200
> [ 3465.484251] x21: fffffe0010a9cb88 x20: 0000000000000040
> [ 3465.484599] x19: fffffc0063fdd200 x18: 0000000000000010
> [ 3465.484957] x17: 0000000000000000 x16: 0000000000000000
> [ 3465.485347] x15: ffffffffffffffff x14: fffffe0011273988
> [ 3465.485714] x13: fffffe009382fa97 x12: fffffe001382fa9f
> [ 3465.486210] x11: fffffe00112b0000 x10: fffffe001382fa20
> [ 3465.486599] x9 : 00000000ffffffd0 x8 : 6572662d72657466
> [ 3465.487039] x7 : 0000000000000149 x6 : fffffe001127cf50
> [ 3465.487447] x5 : fffffe001127c000 x4 : 0000000000000001
> [ 3465.487868] x3 : fffffe001127cf50 x2 : 2e36d2803fe6b700
> [ 3465.488252] x1 : 0000000000000000 x0 : 0000000000000000
> [ 3465.488628] Call trace:
> [ 3465.488851] __kthread_bind_mask+0x34/0x90
> [ 3465.489192] kthread_unpark+0xa0/0xb0
> [ 3465.489456] kthread_stop+0x8c/0x278
> [ 3465.489736] preemptirq_delay_exit+0x28/0xfc8c [preemptirq_delay_test]
> [ 3465.490216] __arm64_sys_delete_module+0x14c/0x298
> [ 3465.490594] do_el0_svc+0xf8/0x1e0
> [ 3465.490850] el0_sync_handler+0x134/0x1bc
> [ 3465.491157] el0_sync+0x140/0x180
> [ 3465.491413] ---[ end trace 1a8ec2201af5e8c8 ]---
> [ 3465.504614] Unable to handle kernel NULL pointer dereference at
> virtual address 0000000000000000
> [ 3465.505340] Mem abort info:
> [ 3465.505553] ESR = 0x96000006
> [ 3465.505855] EC = 0x25: DABT (current EL), IL = 32 bits
> [ 3465.506234] SET = 0, FnV = 0
> [ 3465.506525] EA = 0, S1PTW = 0
> [ 3465.506786] Data abort info:
> [ 3465.507037] ISV = 0, ISS = 0x00000006
> [ 3465.507304] CM = 0, WnR = 0
> [ 3465.507685] user pgtable: 64k pages, 42-bit VAs, pgdp=0000000082450000
> [ 3465.508225] [0000000000000000] pgd=0000000000000000,
> pud=0000000000000000, pmd=0000000000000000
> [ 3465.509049] Internal error: Oops: 96000006 [#1] PREEMPT SMP
> [ 3465.509527] Modules linked in: preemptirq_delay_test(O-) sunrpc vfat
> fat ext4 mbcache jbd2 crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce
> ip_tables xfs libcrc32c virtio_net net_failover failover virtio_mmio
> virtio_blk
> [ 3465.510964] CPU: 1 PID: 6708 Comm: rmmod Tainted: G W O
> 5.6.0-rc7+ #18
> [ 3465.511527] Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0
> 02/06/2015
> [ 3465.512031] pstate: 60000085 (nZCv daIf -PAN -UAO)
> [ 3465.512392] pc : __list_add_valid+0x18/0xa0
> [ 3465.512740] lr : wait_for_completion+0xc8/0x178
> [ 3465.513085] sp : fffffe001382fd00
> [ 3465.513362] x29: fffffe001382fd00 x28: fffffc004876d200
> [ 3465.513769] x27: 0000000000000000 x26: 0000000000000000
> [ 3465.514205] x25: 0000000000000000 x24: fffffc0076e616c8
> [ 3465.514638] x23: fffffe001382fd68 x22: 0000000000000000
> [ 3465.515030] x21: fffffe0011273988 x20: fffffc0076e616c0
> [ 3465.515444] x19: fffffc0076e616b8 x18: 0000000000000010
> [ 3465.515826] x17: 0000000000000000 x16: 0000000000000000
> [ 3465.516184] x15: ffffffffffffffff x14: fffffe0011273988
> [ 3465.516584] x13: fffffe009382fa97 x12: fffffe001382fa9f
> [ 3465.516976] x11: fffffe00112b0000 x10: fffffe001382fa20
> [ 3465.517351] x9 : 00000000ffffffd0 x8 : 6572662d72657466
> [ 3465.517750] x7 : 0000000000000149 x6 : fffffe001127cf50
> [ 3465.518169] x5 : 0000000000000001 x4 : fffffc0076e616c8
> [ 3465.518454] x3 : fffffe0010128b38 x2 : 0000000000000000
> [ 3465.518711] x1 : 0000000000000000 x0 : fffffe001382fd68
> [ 3465.518985] Call trace:
> [ 3465.519157] __list_add_valid+0x18/0xa0
> [ 3465.519351] wait_for_completion+0xc8/0x178
> [ 3465.519578] kthread_stop+0x9c/0x278
> [ 3465.519779] preemptirq_delay_exit+0x28/0xfc8c [preemptirq_delay_test]
> [ 3465.520109] __arm64_sys_delete_module+0x14c/0x298
> [ 3465.520342] do_el0_svc+0xf8/0x1e0
> [ 3465.520520] el0_sync_handler+0x134/0x1bc
> [ 3465.520718] el0_sync+0x140/0x180
> [ 3465.521177] Code: 910003fd f9400442 eb01005f 54000141 (f9400041)
> [ 3465.522258] ---[ end trace 1a8ec2201af5e8c9 ]---
> [ 3465.522746] Kernel panic - not syncing: Fatal exception
> [ 3465.523242] SMP: stopping secondary CPUs
> [ 3465.523898] Kernel Offset: disabled
> [ 3465.524423] CPU features: 0x10002,20006082
> [ 3465.524939] Memory Limit: none
> [ 3465.525534] ---[ end Kernel panic - not syncing: Fatal exception ]---
> --------------------------------------------------------------------
>
> I am looking into these issues.
>
> Thanks,
> Xiao Yang
> On 2020/4/25 6:36, Joel Fernandes (Google) wrote:
>> Kthread running the test needs to be stopped or it can continue
>> executing code unloaded by module causing a crash.
>>
>> Suggested-by: Steven Rostedt<rostedt@xxxxxxxxxxx>
>> Reported-by: Xiao Yang<yangx.jy@xxxxxxxxxxxxxx>
>> Link: http://lore.kernel.org/r/5EA2B0C8.2080706@xxxxxxxxxxxxxx
>> Signed-off-by: Joel Fernandes (Google)<joel@xxxxxxxxxxxxxxxxx>
>> ---
>> kernel/trace/preemptirq_delay_test.c | 5 ++++-
>> 1 file changed, 4 insertions(+), 1 deletion(-)
>>
>> diff --git a/kernel/trace/preemptirq_delay_test.c b/kernel/trace/preemptirq_delay_test.c
>> index 31c0fad4cb9e1..1c28ca20e30b6 100644
>> --- a/kernel/trace/preemptirq_delay_test.c
>> +++ b/kernel/trace/preemptirq_delay_test.c
>> @@ -145,10 +145,10 @@ static struct attribute_group attr_group = {
>> };
>>
>> static struct kobject *preemptirq_delay_kobj;
>> +static struct task_struct *test_task;
>>
>> static int __init preemptirq_delay_init(void)
>> {
>> - struct task_struct *test_task;
>> int retval;
>>
>> test_task = preemptirq_start_test();
>> @@ -171,6 +171,9 @@ static int __init preemptirq_delay_init(void)
>> static void __exit preemptirq_delay_exit(void)
>> {
>> kobject_put(preemptirq_delay_kobj);
>> +
>> + if (test_task)
>> + kthread_stop(test_task);
>> }
>>
>> module_init(preemptirq_delay_init)
>

Next message: Alexander Filippov: "[PATCH v7] ARM: DTS: Aspeed: Add YADRO Nicole BMC"
Previous message: Michael Ellerman: "Re: [PATCH v7 5/5] powerpc/hv-24x7: Update post_mobility_fixup() to handle migration"
In reply to: Joel Fernandes: "Re: [PATCH] kernel/trace: Stop and wait for kthread on preempt irq module unload"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]