Bug 207159
| Summary: | Kernel trace at crypto_wait_for_test with follow-up lockups for kernel task cryptomgr_probe and systemd-udev | ||
|---|---|---|---|
| Product: | Platform Specific/Hardware | Reporter: | Kai Lüke (kai) |
| Component: | x86-64 | Assignee: | platform_x86_64 (platform_x86_64) |
| Status: | NEW --- | ||
| Severity: | high | CC: | aros, bp, carnil, ebiggers3, gerow, herbert, kai, navyasheregar |
| Priority: | P1 | ||
| Hardware: | Other | ||
| OS: | Linux | ||
| Kernel Version: | 5.6.2 | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
|
Description
Kai Lüke
2020-04-08 09:05:33 UTC
I've seen what looks like the same issue come up on 5.6.7 and 5.6.14. This kernel includes some debian patches, for what it's worth. I rebuilt it with lock debugging and it looks like some notifier-related semaphore lock is being held by a bunch of different tasks.
[ 183.821049] WARNING: CPU: 0 PID: 138 at crypto/algapi.c:404 crypto_wait_for_test+0x59/0x70
[ 183.829429] Modules linked in: crc32c_intel(+) efivarfs crc_t10dif(+) crct10dif_generic crct10dif_pclmul crct10dif_common virtio_scsi scsi_mod virtio_net net_failover failover aesni_intel(+) libaes crypto_simd cryptd glue_helper virtio_pci i2c_piix4 psmouse virtio_ring virtio button
[ 183.854635] CPU: 0 PID: 138 Comm: systemd-udevd Not tainted 5.6.14 #1
[ 183.861296] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[ 183.870633] RIP: 0010:crypto_wait_for_test+0x59/0x70
[ 183.875710] Code: 8d fd ff ff 48 8d bd 88 01 00 00 e8 21 fc 48 00 85 c0 75 16 48 89 ee bf 02 00 00 00 e8 40 db ff ff 48 89 ef 5d e9 67 e0 ff ff <0f> 0b eb f3 0f 0b eb ef 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40
[ 183.894612] RSP: 0018:ffff9fb44022fc08 EFLAGS: 00010286
[ 183.899948] RAX: 00000000fffffe00 RBX: ffffffffc02342b8 RCX: 0000000000000000
[ 183.907200] RDX: 00000000fffffe00 RSI: 0000000000000006 RDI: ffff8d805a5f0040
[ 183.914447] RBP: ffff8d7ff4822c00 R08: 0000000000000000 R09: 0000000000000000
[ 183.921706] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 183.928957] R13: ffffffffc023423a R14: ffff8d8047dec000 R15: ffffffffc0234200
[ 183.936205] FS: 00007fe19d5f1880(0000) GS:ffff8d805a400000(0000) knlGS:0000000000000000
[ 183.944421] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 183.950289] CR2: 000056440e23f070 CR3: 0000000134888006 CR4: 00000000003606f0
[ 183.957550] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 183.964799] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 183.972046] Call Trace:
[ 183.974610] crypto_register_alg+0x56/0x70
[ 183.978833] simd_aead_create_compat+0x15d/0x180 [crypto_simd]
[ 183.984784] simd_register_aeads_compat+0x64/0x630 [crypto_simd]
[ 183.990905] ? 0xffffffffc0242000
[ 183.994349] aesni_init+0xff/0x1000 [aesni_intel]
[ 183.999171] ? do_one_initcall+0x5d/0x2c0
[ 184.003304] ? do_init_module+0x23/0x230
[ 184.007341] ? rcu_read_lock_sched_held+0x52/0x60
[ 184.012155] ? do_init_module+0x23/0x230
[ 184.016200] ? kmem_cache_alloc_trace+0x260/0x2a0
[ 184.021017] ? do_init_module+0x5c/0x230
[ 184.025062] ? load_module+0x2381/0x2570
[ 184.029109] ? __do_sys_finit_module+0xaa/0x110
[ 184.033761] ? __do_sys_finit_module+0xaa/0x110
[ 184.038421] ? do_syscall_64+0x5a/0x230
[ 184.042379] ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 184.047724] irq event stamp: 9906
[ 184.051148] hardirqs last enabled at (9905): [<ffffffff8ecdbb54>] _raw_spin_unlock_irq+0x24/0x30
[ 184.060137] hardirqs last disabled at (9906): [<ffffffff8e40391c>] trace_hardirqs_off_thunk+0x1a/0x1c
[ 184.069471] softirqs last enabled at (9782): [<ffffffff8f00035d>] __do_softirq+0x35d/0x3f1
[ 184.077957] softirqs last disabled at (9767): [<ffffffff8e494949>] irq_exit+0xb9/0xc0
[ 184.085958] ---[ end trace ec497009adfc1f9a ]---
[ 242.923659] INFO: task systemd-udevd:137 blocked for more than 120 seconds.
[ 242.931295] Tainted: G W 5.6.14 #1
[ 242.936766] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.944731] systemd-udevd D 0 137 124 0x80004004
[ 242.950390] Call Trace:
[ 242.953007] ? __schedule+0x370/0x960
[ 242.956805] ? schedule+0x4a/0xb0
[ 242.960287] ? rwsem_down_write_slowpath+0x32c/0x640
[ 242.965431] ? blocking_notifier_chain_register+0x26/0x60
[ 242.970997] ? blocking_notifier_chain_register+0x26/0x60
[ 242.976562] ? 0xffffffffc0188000
[ 242.980043] ? crc_t10dif_mod_init+0xc/0x1000 [crc_t10dif]
[ 242.985665] ? do_one_initcall+0x5d/0x2c0
[ 242.989806] ? do_init_module+0x23/0x230
[ 242.993911] ? rcu_read_lock_sched_held+0x52/0x60
[ 242.998819] ? do_init_module+0x23/0x230
[ 243.002877] ? kmem_cache_alloc_trace+0x260/0x2a0
[ 243.007754] ? do_init_module+0x5c/0x230
[ 243.011815] ? load_module+0x2381/0x2570
[ 243.015925] ? __do_sys_finit_module+0xaa/0x110
[ 243.020675] ? __do_sys_finit_module+0xaa/0x110
[ 243.025438] ? do_syscall_64+0x5a/0x230
[ 243.029439] ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 243.034808] INFO: task cryptomgr_probe:201 blocked for more than 120 seconds.
[ 243.042116] Tainted: G W 5.6.14 #1
[ 243.047472] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 243.055559] cryptomgr_probe D 0 201 2 0x80004000
[ 243.061211] Call Trace:
[ 243.063824] ? __schedule+0x370/0x960
[ 243.067622] ? schedule+0x4a/0xb0
[ 243.071060] ? rwsem_down_read_slowpath+0x27e/0x600
[ 243.076112] ? down_read+0x99/0x120
[ 243.079788] ? down_read+0x99/0x120
[ 243.083430] ? blocking_notifier_call_chain+0x34/0x70
[ 243.088769] ? crypto_probing_notify+0x20/0x50
[ 243.093456] ? crypto_wait_for_test+0x50/0x70
[ 243.097949] ? crypto_register_instance+0xe9/0x110
[ 243.102882] ? cryptd_create+0x450/0x490 [cryptd]
[ 243.107724] ? cryptomgr_probe+0x38/0xc0
[ 243.111783] ? kthread+0xf9/0x130
[ 243.115229] ? cryptomgr_notify+0x580/0x580
[ 243.119582] ? kthread_park+0x90/0x90
[ 243.123504] ? ret_from_fork+0x3a/0x50
[ 243.127475]
[ 243.127475] Showing all locks held in the system:
[ 243.133797] 1 lock held by khungtaskd/18:
[ 243.138058] #0: ffffffff8f85fd00 (rcu_read_lock){....}, at: debug_show_all_locks+0x15/0x161
[ 243.146786] 1 lock held by systemd-udevd/137:
[ 243.151905] #0: ffffffff8f8d4568 ((crypto_chain).rwsem){++++}, at: blocking_notifier_chain_register+0x26/0x60
[ 243.162332] 1 lock held by cryptomgr_test/195:
[ 243.167107] #0: ffffffff8f8d4568 ((crypto_chain).rwsem){++++}, at: blocking_notifier_call_chain+0x34/0x70
[ 243.176922] 1 lock held by cryptomgr_probe/201:
[ 243.181591] #0: ffffffff8f8d4568 ((crypto_chain).rwsem){++++}, at: blocking_notifier_call_chain+0x34/0x70
[ 243.191427] 1 lock held by modprobe/255:
[ 243.195480] #0: ffffffff8f8d4568 ((crypto_chain).rwsem){++++}, at: blocking_notifier_call_chain+0x34/0x70
[ 243.205274]
[ 243.206884] =============================================
Worryingly blocking_notifier_chain_register gets a write lock while blocking_notifier_call_chain gets a read lock, which if I'm reading the "held locks" lines correctly that means the semaphore is simultaneously held by read holders and write holders (it's entirely possible I'm reading this wrong and all these tasks are just simultaneously waiting for something else).
Can you blacklist crc-t10dif and see if this still happens? There is a race condition in crc-t10dif in that it registers the notifier too early and it may race against its own crypto alloc call. > Can you blacklist crc-t10dif and see if this still happens? There is a race
> condition in crc-t10dif in that it registers the notifier too early and it
> may race against its own crypto alloc call.
I don't think that can be it, because the stack traces show that crc_t10dif_mod_init() is blocked on crypto_register_notifier(). So it never got to crypto_alloc_shash().
I'm more inclined to blame the fact that cryptomgr_schedule_probe() waits for the requested module to be loaded, while it holds crypto_chain.rwsem for read via blocking_notifier_call_chain().
That will deadlock if loading the requested module needs to wait for crc-t10dif.ko to also be loaded, for any reason. I don't immediately see why that would happen, as crc-t10dif.ko is a library module, not a crypto API module. Maybe userspace is serializing the module loading? It would be helpful to have a way to reproduce this.
Also, I'm guessing that crc-t10dif.ko is being inserted as a dependency of the SCSI disk module sd.ko, so blacklisting it wouldn't work.
Can you try this patch?
diff --git a/crypto/algboss.c b/crypto/algboss.c
index 535f1f87e6c1..5ebccbd6b74e 100644
--- a/crypto/algboss.c
+++ b/crypto/algboss.c
@@ -178,8 +178,6 @@ static int cryptomgr_schedule_probe(struct crypto_larval *larval)
if (IS_ERR(thread))
goto err_put_larval;
- wait_for_completion_interruptible(&larval->completion);
-
return NOTIFY_STOP;
Applying that patch seems to fix the lockup for me. I can look to try and find a minimal repro. I have other configurations that run in GCE that don't hit this lockup, so something unique about the order modules are loaded or userspace comes up sounds like a plausible trigger. OK, after some more experimentation I think the trigger here was Debian moving some of the CRYPTO_* libs into modules. Moving them back into the kernel image seems to make the problem go away. Which I guess still means there might be a bug here, but unfortunately I can't bound it within v5.5..v5.6 because the trigger wasn't a commit but a config change. I'll add another comment once I figure out what the actual config changes are. Thanks Eric. Your patch looks correct, I have no idea why I put that wait in there at all :) The actual larval users would be waiting after the notify returns anyway. Please send it to the list when you're ready. Ah, I assumed the patch was just for debugging purposes, if that's the actual fix that's fantastic. Thanks a lot! I am observing crash in 5.4.164. ------------[ cut here ]------------ [ 191.375044] WARNING: CPU: 1 PID: 157 at crypto/algapi.c:375 crypto_wait_for_test+0x74/0x7c [ 191.378691] Modules linked in: wifi_3_0(O+) qca_ol(O) qca_spectral(O) umac(O) qdf(O) mem_manager(O) nls_utf8 xhci_plat_hcd xhci_hcd sd_mod usb_storage scp [ 191.378877] iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c ip6table_mangle ip6table_filter ip6t_REJECT nf_reject_ipv6 nls_iso88e [ 191.474222] CPU: 1 PID: 157 Comm: systemd-udevd Tainted: G O 5.4.164-yocto-standard #1 [ 191.494057] Hardware name: Qualcomm Technologies, Inc. IPQ8074/AP-HK09 (DT) [ 191.503167] pstate: 60400005 (nZCv daif +PAN -UAO) [ 191.509933] pc : crypto_wait_for_test+0x74/0x7c [ 191.514789] lr : crypto_wait_for_test+0x70/0x7c [ 191.519214] sp : ffffff803b25f890 [ 191.523724] x29: ffffff803b25f890 x28: ffffffc00a7b155f [ 191.527205] x27: ffffff803b8501b8 x26: ffffffc00a7af5a4 [ 191.532587] x25: ffffffc00a7af0f8 x24: ffffffc0108fe890 [ 191.537880] x23: 0000000000000002 x22: ffffff803b9d6c80 [ 191.543177] x21: ffffffc0109d7138 x20: ffffff803b852400 [ 191.548472] x19: ffffff803b852400 x18: 0000000000000000 [ 191.553765] x17: 0000000000000000 x16: 0000000000000000 [ 191.559060] x15: 0000000000000000 x14: 0000000000000000 [ 191.564356] x13: 0000000000000000 x12: 0000000000000001 [ 191.569652] x11: 0000000000000001 x10: 0000000000000870 [ 191.574947] x9 : ffffff803b25f6c0 x8 : ffffff803b1ed250 [ 191.580243] x7 : ffffff803b852610 x6 : 0000000000000000 [ 191.585538] x5 : 0000000000000000 x4 : 0000000000000000 [ 191.590833] x3 : 0000000000000000 x2 : 0000000000000001 [ 191.596127] x1 : ffffff803b1ec980 x0 : 00000000fffffe00 [ 191.601423] Call trace: [ 191.606712] crypto_wait_for_test+0x74/0x7c [ 191.608887] crypto_register_alg+0x78/0x7c [ 191.613053] crypto_register_ahash+0x44/0x54 [ 191.617236] qce_ahash_register+0x168/0x20c [qcrypto] [ 191.621658] qce_crypto_probe+0x228/0x258 [qcrypto] [ 191.626600] platform_drv_probe+0x50/0x9c [ 191.631284] really_probe+0x2b0/0x3d8 [ 191.635447] driver_probe_device+0x110/0x120 [ 191.639096] device_driver_attach+0x40/0x68 [ 191.643433] __driver_attach+0x130/0x134 [ 191.647344] bus_for_each_dev+0x6c/0xb4 [ 191.651507] driver_attach+0x20/0x28 [ 191.655066] bus_add_driver+0x19c/0x1e0 [ 191.658885] driver_register+0xac/0xe4 [ 191.662445] __platform_driver_register+0x48/0x50 [ 191.666276] qce_crypto_driver_init+0x1c/0x1000 [qcrypto] [ 191.671046] do_one_initcall+0x68/0x17c [ 191.676421] do_init_module+0x58/0x1d4 [ 191.680065] load_module+0x1a54/0x1fc4 [ 191.683885] __do_sys_finit_module+0xd0/0xec [ 191.687620] __arm64_sys_finit_module+0x18/0x20 [ 191.692051] el0_svc_common.constprop.0+0x94/0x110 [ 191.696304] el0_svc_handler+0x18/0x20 [ 191.701158] el0_svc+0x8/0x1b4 [ 191.704889] ---[ end trace 5646b584c1b70dca ]--- [ 191.708106] ------------[ cut here ]------------ [ 191.712721] WARNING: CPU: 1 PID: 157 at crypto/algapi.c:369 crypto_wait_for_test+0x2c/0x7c [ 191.717320] Modules linked in: wifi_3_0(O+) qca_ol(O) qca_spectral(O) umac(O) qdf(O) mem_manager(O) nls_utf8 xhci_plat_hcd xhci_hcd sd_mod usb_storage scp [ 191.717500] iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c ip6table_mangle ip6table_filter ip6t_REJECT nf_reject_ipv6 nls_iso88e [ 191.812851] CPU: 1 PID: 157 Comm: systemd-udevd Tainted: G W O 5.4.164-yocto-standard #1 [ 191.832687] Hardware name: Qualcomm Technologies, Inc. IPQ8074/AP-HK09 (DT) [ 191.841796] pstate: 80400005 (Nzcv daif +PAN -UAO) [ 191.848560] pc : crypto_wait_for_test+0x2c/0x7c [ 191.853417] lr : crypto_wait_for_test+0x1c/0x7c [ 191.857842] sp : ffffff803b25f890 [ 191.862353] x29: ffffff803b25f890 x28: ffffffc00a7b155f [ 191.865833] x27: ffffff8037017db8 x26: ffffffc00a7af5a4 [ 191.871215] x25: ffffffc00a7af0f8 x24: ffffffc0108fe890 [ 191.876509] x23: 0000000000000003 x22: ffffff803b9d6c80 [ 191.881805] x21: ffffffc0109d7138 x20: ffffff8037017800 [ 191.887099] x19: ffffff8037017800 x18: 0000000000000000 [ 191.892395] x17: 0000000000000000 x16: 0000000000000000 [ 191.897692] x15: 0000000000000000 x14: 0000000000000000 [ 191.902985] x13: 0000000000000000 x12: 0000000000000000 [ 191.908279] x11: 0000000000000000 x10: 0000000000000000 [ 191.913576] x9 : 0000000000000000 x8 : 0000000000000000 [ 191.918870] x7 : ffffff803b25f6b0 x6 : 0000000000000000 [ 191.924166] x5 : 0000000000000000 x4 : ffffffc0109d7160 [ 191.929462] x3 : 0000000000000000 x2 : 0000000000000000 [ 191.934757] x1 : 0000000000008001 x0 : 0000000000000001 [ 191.940050] Call trace: [ 191.945340] crypto_wait_for_test+0x2c/0x7c [ 191.947516] crypto_register_alg+0x78/0x7c [ 191.951683] crypto_register_ahash+0x44/0x54 [ 191.955864] qce_ahash_register+0x168/0x20c [qcrypto] [ 191.960286] qce_crypto_probe+0x228/0x258 [qcrypto] [ 191.965229] platform_drv_probe+0x50/0x9c [ 191.969910] really_probe+0x2b0/0x3d8 [ 191.974076] driver_probe_device+0x110/0x120 [ 191.977725] device_driver_attach+0x40/0x68 [ 191.982063] __driver_attach+0x130/0x134 [ 191.985972] bus_for_each_dev+0x6c/0xb4 [ 191.990130] driver_attach+0x20/0x28 [ 191.993693] bus_add_driver+0x19c/0x1e0 [ 191.997513] driver_register+0xac/0xe4 [ 192.001073] __platform_driver_register+0x48/0x50 [ 192.004905] qce_crypto_driver_init+0x1c/0x1000 [qcrypto] [ 192.009674] do_one_initcall+0x68/0x17c [ 192.015051] do_init_module+0x58/0x1d4 [ 192.018694] load_module+0x1a54/0x1fc4 [ 192.022514] __do_sys_finit_module+0xd0/0xec [ 192.026249] __arm64_sys_finit_module+0x18/0x20 [ 192.030677] el0_svc_common.constprop.0+0x94/0x110 [ 192.034931] el0_svc_handler+0x18/0x20 [ 192.039788] el0_svc+0x8/0x1b4 [ 192.043517] ---[ end trace 5646b584c1b70dcb ]--- Is this reproducible in 6.8.9 or 6.6.30? |