On Thu, Sep 15, 2022 at 03:47:51PM +0530, Naresh Kamboju wrote:
[Please ignore this email if it is already reported] Following kernel warning and BUG have been found while running kselftests gpio test case on arm64 Raspberry Pi 4 Model B device running 6.0.0-rc5.
Reported-by: Linux Kernel Functional Testing lkft@linaro.org
crash log:
[ 53.796405] kselftest: Running tests in gpio TAP version 13 1..2 # selftests: gpio: gpio-mockup.sh # 1. Module load tests # 1.1. dynamic allocation of gpio [ 55.416786] [ 55.418311] ============================= [ 55.422371] WARNING: suspicious RCU usage [ 55.426431] 6.0.0-rc5 #1 Not tainted [ 55.430052] ----------------------------- [ 55.434112] kernel/sched/core.c:9854 Illegal context switch in RCU-bh read-side critical section!
This is exactly what it says on the label: Something failed to get out of an RCU read-side critical section before scheduling.
In this case, it was an RCU-bh read-side critical section, that is, an unmatched call to rcu_read_lock_bh(), local_bh_disable(), spin_lock_bh(), and so on. In the case of spin_lock_bh(), the lock might have been released using spin_unlock().
However...
[ 55.443108] other info that might help us debug this: [ 55.443108] [ 55.451222] [ 55.451222] rcu_scheduler_active = 2, debug_locks = 1 [ 55.457839] 1 lock held by modprobe/563: [ 55.461812] #0: ffff00004cf450f8 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0x50/0x290 [ 55.471632] [ 55.471632] stack backtrace: [ 55.476046] CPU: 2 PID: 563 Comm: modprobe Not tainted 6.0.0-rc5 #1 [ 55.482401] Hardware name: Raspberry Pi 4 Model B (DT) [ 55.487607] Call trace: [ 55.490079] dump_backtrace+0xe4/0x130 [ 55.493879] show_stack+0x30/0x70 [ 55.497235] dump_stack_lvl+0x8c/0xb8 [ 55.500947] dump_stack+0x18/0x34 [ 55.504303] lockdep_rcu_suspicious+0xf8/0x10c [ 55.508806] __might_resched+0xd0/0x240 [ 55.512694] __might_sleep+0x58/0xb0 [ 55.516316] do_page_fault+0x244/0x4d0 [ 55.520116] do_translation_fault+0xd8/0x100
...did this really take a page fault while attempting to acquire a semaphore? That does sound like a symptom of something pretty ugly happening.
Maybe a use-after-free bug? Maybe try reproducing with KASAN?
And of course there is always bisection.
Thanx, Paul
[ 55.524443] do_mem_abort+0x58/0xb0 [ 55.527979] el1_abort+0x44/0x70 [ 55.531248] el1h_64_sync_handler+0xa4/0xd0 [ 55.535487] el1h_64_sync+0x64/0x68 [ 55.539020] __lock_acquire+0x53c/0x2040 [ 55.542995] lock_acquire.part.0+0xe8/0x24c [ 55.547233] lock_acquire+0x84/0xa0 [ 55.550766] down_write+0x60/0xc4 [ 55.554123] simple_recursive_removal+0x58/0x290 [ 55.558803] debugfs_remove+0x5c/0x80 [ 55.562516] gpio_mockup_debugfs_cleanup+0x24/0x34 [gpio_mockup] [ 55.568614] devm_action_release+0x24/0x3c [ 55.572764] release_nodes+0x64/0x9c [ 55.576384] devres_release_all+0x94/0xec [ 55.580447] device_unbind_cleanup+0x24/0x74 [ 55.584773] device_release_driver_internal+0x240/0x290 [ 55.590070] driver_detach+0x5c/0xf0 [ 55.593691] bus_remove_driver+0x6c/0x10c [ 55.597753] driver_unregister+0x38/0x6c [ 55.601728] platform_driver_unregister+0x24/0x34 [ 55.606497] gpio_mockup_exit+0x24/0x20c [gpio_mockup] [ 55.611707] __arm64_sys_delete_module+0x184/0x2f0 [ 55.616562] invoke_syscall+0x8c/0x120 [ 55.620362] el0_svc_common.constprop.0+0x104/0x124 [ 55.625307] do_el0_svc+0x44/0xc0 [ 55.628664] el0_svc+0x48/0xc0 [ 55.631757] el0t_64_sync_handler+0xbc/0x140 [ 55.636084] el0t_64_sync+0x18c/0x190 [ 55.639793] [ 55.641298] ============================= [ 55.645356] WARNING: suspicious RCU usage [ 55.649417] 6.0.0-rc5 #1 Not tainted [ 55.653037] ----------------------------- [ 55.657096] kernel/sched/core.c:9854 Illegal context switch in RCU-sched read-side critical section! [ 55.666356] [ 55.666356] other info that might help us debug this: [ 55.666356] [ 55.674469] [ 55.674469] rcu_scheduler_active = 2, debug_locks = 1 [ 55.681084] 1 lock held by modprobe/563: [ 55.685057] #0: ffff00004cf450f8 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0x50/0x290 [ 55.694863] [ 55.694863] stack backtrace: [ 55.699275] CPU: 2 PID: 563 Comm: modprobe Not tainted 6.0.0-rc5 #1 [ 55.705628] Hardware name: Raspberry Pi 4 Model B (DT) [ 55.710834] Call trace: [ 55.713306] dump_backtrace+0xe4/0x130 [ 55.717103] show_stack+0x30/0x70 [ 55.720459] dump_stack_lvl+0x8c/0xb8 [ 55.724170] dump_stack+0x18/0x34 [ 55.727526] lockdep_rcu_suspicious+0xf8/0x10c [ 55.732029] __might_resched+0x214/0x240 [ 55.736003] __might_sleep+0x58/0xb0 [ 55.739625] do_page_fault+0x244/0x4d0 [ 55.743424] do_translation_fault+0xd8/0x100 [ 55.747751] do_mem_abort+0x58/0xb0 [ 55.751286] el1_abort+0x44/0x70 [ 55.754556] el1h_64_sync_handler+0xa4/0xd0 [ 55.758794] el1h_64_sync+0x64/0x68 [ 55.762326] __lock_acquire+0x53c/0x2040 [ 55.766301] lock_acquire.part.0+0xe8/0x24c [ 55.770538] lock_acquire+0x84/0xa0 [ 55.774072] down_write+0x60/0xc4 [ 55.777428] simple_recursive_removal+0x58/0x290 [ 55.782107] debugfs_remove+0x5c/0x80 [ 55.785818] gpio_mockup_debugfs_cleanup+0x24/0x34 [gpio_mockup] [ 55.791911] devm_action_release+0x24/0x3c [ 55.796061] release_nodes+0x64/0x9c [ 55.799682] devres_release_all+0x94/0xec [ 55.803743] device_unbind_cleanup+0x24/0x74 [ 55.808070] device_release_driver_internal+0x240/0x290 [ 55.813367] driver_detach+0x5c/0xf0 [ 55.816988] bus_remove_driver+0x6c/0x10c [ 55.821050] driver_unregister+0x38/0x6c [ 55.825025] platform_driver_unregister+0x24/0x34 [ 55.829793] gpio_mockup_exit+0x24/0x20c [gpio_mockup] [ 55.835002] __arm64_sys_delete_module+0x184/0x2f0 [ 55.839858] invoke_syscall+0x8c/0x120 [ 55.843657] el0_svc_common.constprop.0+0x104/0x124 [ 55.848602] do_el0_svc+0x44/0xc0 [ 55.851958] el0_svc+0x48/0xc0 [ 55.855051] el0t_64_sync_handler+0xbc/0x140 [ 55.859378] el0t_64_sync+0x18c/0x190 [ 55.863087] BUG: sleeping function called from invalid context at arch/arm64/mm/fault.c:593 [ 55.871554] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 563, name: modprobe [ 55.879757] preempt_count: 0, expected: 0 [ 55.883816] RCU nest depth: 0, expected: 0 [ 55.887965] 1 lock held by modprobe/563: [ 55.891936] #0: ffff00004cf450f8 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0x50/0x290 [ 55.901743] irq event stamp: 10213 [ 55.905185] hardirqs last enabled at (10213): [<ffff8000096e2e74>] _raw_spin_unlock_irqrestore+0x84/0xa0 [ 55.914888] hardirqs last disabled at (10212): [<ffff8000096e3314>] _raw_spin_lock_irqsave+0xa4/0xb0 [ 55.924151] softirqs last enabled at (9742): [<ffff800008010be4>] __do_softirq+0x514/0x62c [ 55.932618] softirqs last disabled at (9737): [<ffff8000080b4768>] __irq_exit_rcu+0x164/0x19c [ 55.941265] CPU: 2 PID: 563 Comm: modprobe Not tainted 6.0.0-rc5 #1 [ 55.947618] Hardware name: Raspberry Pi 4 Model B (DT) [ 55.952823] Call trace: [ 55.955296] dump_backtrace+0xe4/0x130 [ 55.959093] show_stack+0x30/0x70 [ 55.962448] dump_stack_lvl+0x8c/0xb8 [ 55.966159] dump_stack+0x18/0x34 [ 55.969515] __might_resched+0x1c4/0x240 [ 55.973490] __might_sleep+0x58/0xb0 [ 55.977111] do_page_fault+0x244/0x4d0 [ 55.980910] do_translation_fault+0xd8/0x100 [ 55.985238] do_mem_abort+0x58/0xb0 [ 55.988774] el1_abort+0x44/0x70 [ 55.992043] el1h_64_sync_handler+0xa4/0xd0 [ 55.996281] el1h_64_sync+0x64/0x68 [ 55.999814] __lock_acquire+0x53c/0x2040 [ 56.003789] lock_acquire.part.0+0xe8/0x24c [ 56.008028] lock_acquire+0x84/0xa0 [ 56.011560] down_write+0x60/0xc4 [ 56.014916] simple_recursive_removal+0x58/0x290 [ 56.019594] debugfs_remove+0x5c/0x80 [ 56.023306] gpio_mockup_debugfs_cleanup+0x24/0x34 [gpio_mockup] [ 56.029400] devm_action_release+0x24/0x3c [ 56.033549] release_nodes+0x64/0x9c [ 56.037170] devres_release_all+0x94/0xec [ 56.041232] device_unbind_cleanup+0x24/0x74 [ 56.045559] device_release_driver_internal+0x240/0x290 [ 56.050855] driver_detach+0x5c/0xf0 [ 56.054477] bus_remove_driver+0x6c/0x10c [ 56.058539] driver_unregister+0x38/0x6c [ 56.062513] platform_driver_unregister+0x24/0x34 [ 56.067281] gpio_mockup_exit+0x24/0x20c [gpio_mockup] [ 56.072490] __arm64_sys_delete_module+0x184/0x2f0 [ 56.077346] invoke_syscall+0x8c/0x120 [ 56.081145] el0_svc_common.constprop.0+0x104/0x124 [ 56.086089] do_el0_svc+0x44/0xc0 [ 56.089446] el0_svc+0x48/0xc0 [ 56.092539] el0t_64_sync_handler+0xbc/0x140 [ 56.096866] el0t_64_sync+0x18c/0x190 [ 56.100584] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000150 [ 56.109495] Mem abort info: [ 56.112320] ESR = 0x0000000096000006 [ 56.116116] EC = 0x25: DABT (current EL), IL = 32 bits [ 56.121499] SET = 0, FnV = 0 [ 56.124589] EA = 0, S1PTW = 0 [ 56.127767] FSC = 0x06: level 2 translation fault [ 56.132708] Data abort info: [ 56.135622] ISV = 0, ISS = 0x00000006 [ 56.139505] CM = 0, WnR = 0 [ 56.142506] user pgtable: 4k pages, 48-bit VAs, pgdp=000000004adb5000 [ 56.149035] [0000000000000150] pgd=08000000469d2003, p4d=08000000469d2003, pud=0800000046b70003, pmd=0000000000000000 [ 56.159807] Internal error: Oops: 96000006 [#1] PREEMPT SMP [ 56.165455] Modules linked in: gpio_mockup(-) algif_hash aes_neon_bs aes_neon_blk xhci_pci raspberrypi_cpufreq snd_soc_hdmi_codec xhci_pci_renesas brcmfmac brcmutil hci_uart btqca btbcm cfg80211 bluetooth reset_raspberrypi crct10dif_ce clk_raspberrypi raspberrypi_hwmon rfkill iproc_rng200 pwm_bcm2835 v3d rng_core i2c_bcm2835 drm_shmem_helper vc4 bcm2711_thermal cec drm_display_helper drm_cma_helper gpu_sched pcie_brcmstb drm_kms_helper fuse drm [ 56.205467] CPU: 2 PID: 563 Comm: modprobe Tainted: G W 6.0.0-rc5 #1 [ 56.213318] Hardware name: Raspberry Pi 4 Model B (DT) [ 56.218523] pstate: 600000c5 (nZCv daIF -PAN -UAO -TCO -DIT -SSBS BTYPE=--) [ 56.225582] pc : __lock_acquire+0x53c/0x2040 [ 56.229910] lr : lock_acquire.part.0+0xe8/0x24c [ 56.234499] sp : ffff80000d03b8a0 [ 56.237852] x29: ffff80000d03b8a0 x28: ffff800008456678 x27: 0000000000000000 [ 56.245091] x26: ffff800008456678 x25: 0000000000000150 x24: 0000000000000000 [ 56.252329] x23: ffff00004c200040 x22: 0000000000000000 x21: 0000000000000001 [ 56.259567] x20: 0000000000000000 x19: 0000000000000000 x18: 0000000000000000 [ 56.266804] x17: ffff800008b93ed0 x16: 0000000000000000 x15: 0000000000000028 [ 56.274041] x14: 000000000004ffff x13: ffff80000b40dd00 x12: ffff80000802cff8 [ 56.281279] x11: ffff80000b40d840 x10: ffff80000802cdfc x9 : 0000000100000000 [ 56.288517] x8 : ffff00004c200040 x7 : ffff800008456678 x6 : 0000000000000000 [ 56.295755] x5 : 0000000000000001 x4 : 0000000000000001 x3 : 0000000000000000 [ 56.302992] x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff80000aeb6000 [ 56.310230] Call trace: [ 56.312701] __lock_acquire+0x53c/0x2040 [ 56.316674] lock_acquire.part.0+0xe8/0x24c [ 56.320911] lock_acquire+0x84/0xa0 [ 56.324444] down_write+0x60/0xc4 [ 56.327799] simple_recursive_removal+0x58/0x290 [ 56.332477] debugfs_remove+0x5c/0x80 [ 56.336186] gpio_mockup_debugfs_cleanup+0x24/0x34 [gpio_mockup] [ 56.342276] devm_action_release+0x24/0x3c [ 56.346425] release_nodes+0x64/0x9c [ 56.350043] devres_release_all+0x94/0xec [ 56.354104] device_unbind_cleanup+0x24/0x74 [ 56.358430] device_release_driver_internal+0x240/0x290 [ 56.363725] driver_detach+0x5c/0xf0 [ 56.367346] bus_remove_driver+0x6c/0x10c [ 56.371407] driver_unregister+0x38/0x6c [ 56.375380] platform_driver_unregister+0x24/0x34 [ 56.380147] gpio_mockup_exit+0x24/0x20c [gpio_mockup] [ 56.385356] __arm64_sys_delete_module+0x184/0x2f0 [ 56.390211] invoke_syscall+0x8c/0x120 [ 56.394009] el0_svc_common.constprop.0+0x104/0x124 [ 56.398952] do_el0_svc+0x44/0xc0 [ 56.402308] el0_svc+0x48/0xc0 [ 56.405400] el0t_64_sync_handler+0xbc/0x140 [ 56.409725] el0t_64_sync+0x18c/0x190 [ 56.413435] Code: 6b01001f 54002668 a94573fb 1400003d (f9400321) [ 56.419613] ---[ end trace 0000000000000000 ]---
Full test log, https://lkft.validation.linaro.org/scheduler/job/5528616#L1360
metadata: git_ref: master git_repo: https://gitlab.com/Linaro/lkft/mirrors/torvalds/linux-mainline git_sha: 3245cb65fd91cd514801bf91f5a3066d562f0ac4 git_describe: v6.0-rc5-25-g3245cb65fd91 kernel_version: 6.0.0-rc5 kernel-config: https://builds.tuxbuild.com/2EkryDJF2MJ3zNyYOYb016CJbRv/config vmlinux.xz: https://builds.tuxbuild.com/2EkryDJF2MJ3zNyYOYb016CJbRv/vmlinux.xz System.map: https://builds.tuxbuild.com/2EkryDJF2MJ3zNyYOYb016CJbRv/System.map build-url: https://gitlab.com/Linaro/lkft/mirrors/torvalds/linux-mainline/-/pipelines/6... artifact-location: https://builds.tuxbuild.com/2EkryDJF2MJ3zNyYOYb016CJbRv toolchain: gcc-11
-- Linaro LKFT https://lkft.linaro.org