Bug 207159 - Kernel trace at crypto_wait_for_test with follow-up lockups for kernel task cryptomgr_probe and systemd-udev
Summary: Kernel trace at crypto_wait_for_test with follow-up lockups for kernel task c...
Status: NEW
Alias: None
Product: Platform Specific/Hardware
Classification: Unclassified
Component: x86-64 (show other bugs)
Hardware: Other Linux
: P1 high
Assignee: platform_x86_64@kernel-bugs.osdl.org
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-04-08 09:05 UTC by Kai Lüke
Modified: 2020-04-08 09:05 UTC (History)
1 user (show)

See Also:
Kernel Version: 5.6.2
Tree: Mainline
Regression: No


Attachments

Description Kai Lüke 2020-04-08 09:05:33 UTC
We observed the following crashes in 5.6.0 and 5.6.2 on multiple runs, both on bare metal and on GCE.



The GCE traces look like this:

[  182.906051] ------------[ cut here ]------------
[  182.910956] WARNING: CPU: 0 PID: 306 at ../../../../../../../../usr/src/linux-5.6.2-coreos/crypto/algapi.c:404 crypto_wait_for_test+0x59/0x70
[  182.923933] Modules linked in: crc_t10dif(+) crct10dif_generic crct10dif_common aesni_intel(+) virtio_scsi glue_helper libaes crypto_simd virtio_net scsi_mod cryptd net_failover failover dm_mirror dm_region_hash dm_log dm_mod
[  182.944397] CPU: 0 PID: 306 Comm: systemd-udevd Not tainted 5.6.2-flatcar #1
[  182.951604] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[  182.960969] RIP: 0010:crypto_wait_for_test+0x59/0x70
[  182.966089] Code: 9d fd ff ff 48 8d bb 88 01 00 00 e8 f1 aa 39 00 85 c0 75 16 48 89 de bf 02 00 00 00 e8 40 df ff ff 48 89 df 5b e9 17 e2 ff ff <0f> 0b eb f3 0f 0b eb ef 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40
[  182.984974] RSP: 0018:ffffbf35801cfbe0 EFLAGS: 00010286
[  182.990371] RAX: 00000000fffffe00 RBX: ffffa077614bcc00 RCX: 0000000000000000
[  182.997711] RDX: 00000000fffffe00 RSI: 0000000000000000 RDI: ffffa077614bcd90
[  183.004965] RBP: 0000000000000000 R08: 00005f8940000000 R09: 0000000000000101
[  183.012219] R10: 0000000000000139 R11: 0000000000000000 R12: ffffffffc04e777a
[  183.019483] R13: ffffffffc04e77fa R14: fffffffffffffff4 R15: ffffffffc04e7740
[  183.026946] FS:  00007fdcbf39b940(0000) GS:ffffa0776c000000(0000) knlGS:0000000000000000
[  183.035156] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  183.041132] CR2: 0000561c782e30c8 CR3: 00000001227de001 CR4: 00000000001606f0
[  183.048414] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  183.055763] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  183.063574] Call Trace:
[  183.066241]  crypto_register_alg+0x59/0x60
[  183.070658]  simd_skcipher_create_compat+0x16d/0x190 [crypto_simd]
[  183.077076]  simd_register_skciphers_compat+0x7e/0xe0 [crypto_simd]
[  183.083463]  ? 0xffffffffc04ea000
[  183.086896]  init_module+0xdd/0x1000 [aesni_intel]
[  183.091852]  ? do_one_initcall+0x46/0x200
[  183.095995]  ? _cond_resched+0x15/0x30
[  183.099861]  ? kmem_cache_alloc_trace+0x155/0x220
[  183.104730]  ? do_init_module+0x5a/0x220
[  183.108777]  ? load_module+0x20e7/0x2380
[  183.112822]  ? ima_post_read_file+0xf4/0x100
[  183.117391]  ? __do_sys_finit_module+0xa8/0x110
[  183.122050]  ? __do_sys_finit_module+0xa8/0x110
[  183.127066]  ? do_syscall_64+0x4e/0x160
[  183.131056]  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  183.136435] ---[ end trace 0b335532e6f66ae6 ]---
[  183.024765] systemd-udevd[257]: cpu0: Worker [306] processing SEQNUM=820 killed
[  183.788715] systemd-udevd[257]: 0:0:1:0: Worker [310] processing SEQNUM=974 killed
[…]
[  246.946745] INFO: task systemd-udevd:310 blocked for more than 122 seconds.
[  246.953880]       Tainted: G        W         5.6.2-flatcar #1
[  246.959832] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  246.967774] systemd-udevd   D    0   310    257 0x800041a4
[  246.973391] Call Trace:
[  246.975966]  ? __schedule+0x2db/0x700
[  246.979789]  ? kvm_sched_clock_read+0xd/0x20
[  246.984218]  schedule+0x40/0xb0
[  246.987495]  rwsem_down_write_slowpath+0x2ed/0x4a0
[  246.992441]  ? __switch_to_asm+0x40/0x70
[  246.996480]  ? __switch_to_asm+0x40/0x70
[  247.000550]  ? __switch_to_asm+0x34/0x70
[  247.004596]  blocking_notifier_chain_register+0x22/0x50
[  247.009939]  ? 0xffffffffc0486000
[  247.013386]  init_module+0xc/0x1000 [crc_t10dif]
[  247.018132]  do_one_initcall+0x46/0x200
[  247.022097]  ? _cond_resched+0x15/0x30
[  247.025961]  ? kmem_cache_alloc_trace+0x155/0x220
[  247.030805]  do_init_module+0x5a/0x220
[  247.034699]  load_module+0x20e7/0x2380
[  247.038583]  ? ima_post_read_file+0xf4/0x100
[  247.042974]  ? __do_sys_finit_module+0xa8/0x110
[  247.047670]  __do_sys_finit_module+0xa8/0x110
[  247.052215]  do_syscall_64+0x4e/0x160
[  247.057154]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  247.062335] RIP: 0033:0x7fdcbfb35389
[  247.066035] Code: Bad RIP value.
[  247.069377] RSP: 002b:00007ffcb1814e98 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[  247.077062] RAX: ffffffffffffffda RBX: 00005595495df080 RCX: 00007fdcbfb35389
[  247.084322] RDX: 0000000000000000 RSI: 00007fdcbfc9386d RDI: 000000000000000f
[  247.091590] RBP: 00007fdcbfc9386d R08: 0000000000000000 R09: 0000000000000001
[  247.098840] R10: 000000000000000f R11: 0000000000000246 R12: 0000000000000000
[  247.106101] R13: 00005595495b0f70 R14: 0000000000020000 R15: 00005595495df080
[  247.113870] INFO: task cryptomgr_probe:353 blocked for more than 123 seconds.
[  247.121139]       Tainted: G        W         5.6.2-flatcar #1
[  247.127122] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  247.135114] cryptomgr_probe D    0   353      2 0x80004080
[  247.140814] Call Trace:
[  247.143426]  ? __schedule+0x2db/0x700
[  247.147296]  ? update_load_avg+0x7e/0x5e0
[  247.151532]  schedule+0x40/0xb0
[  247.154794]  rwsem_down_read_slowpath+0x370/0x470
[  247.159647]  blocking_notifier_call_chain+0x27/0x60
[  247.164751]  crypto_probing_notify+0x1f/0x50
[  247.169158]  crypto_wait_for_test+0x1a/0x70
[  247.173550]  crypto_register_instance+0xed/0x110
[  247.178336]  cryptd_alloc_aead+0xabf/0xbb0 [cryptd]
[  247.183461]  ? crypto_alg_put+0x40/0x40
[  247.187413]  cryptomgr_probe+0x3f/0x80
[  247.191333]  kthread+0x112/0x130
[  247.194691]  ? kthread_park+0x80/0x80
[  247.198471]  ret_from_fork+0x35/0x40






The bare-metal trace looks like this:
[  186.655173] ------------[ cut here ]------------
[  186.686097] WARNING: CPU: 0 PID: 328 at ../../../../../../../../usr/src/linux-5.6.0-coreos/crypto/algapi.c:404 crypto_wait_for_test+0x59/0x70
[  186.686098] Modules linked in: hid_generic usbhid hid crc_t10dif(+) ehci_pci crct10dif_generic crct10dif_common ehci_hcd aesni_intel(+) glue_helper libaes crypto_simd usbcore igb ahci libahci libata i2c_algo_bit i2c_core hwmon cryptd ptp scsi_mod usb_common pps_core dm_mirror dm_region_hash dm_log dm_mod
[  185.880994] systemd-udevd[282]: cpu0: Worker [328] processing SEQNUM=944 killed
[  186.864494] CPU: 0 PID: 328 Comm: systemd-udevd Not tainted 5.6.0-flatcar #1
[  186.864495] Hardware name: Supermicro MBI-6418A-T5H/B1SA4-2550F, BIOS 2.0a 05/05/2015
[  186.005178] systemd-udevd[282]: cpu3: Worker [334] processing SEQNUM=947 killed
[  186.864498] RIP: 0010:crypto_wait_for_test+0x59/0x70
[  186.864501] Code: 9d fd ff ff 48 8d bb 88 01 00 00 e8 91 a9 39 00 85 c0 75 16 48 89 de bf 02 00 00 00 e8 40 df ff ff 48 89 df 5b e9 17 e2 ff ff <0f> 0b eb f3 0f 0b eb ef 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40
[  186.864503] RSP: 0018:ffff99be4023bbe0 EFLAGS: 00010286
[  186.864505] RAX: 00000000fffffe00 RBX: ffff8ebce1586800 RCX: 0000000000000000
[  186.864506] RDX: 00000000fffffe00 RSI: 0000000000000000 RDI: ffff8ebce1586990
[  186.864507] RBP: 0000000000000000 R08: ffffffffb3403e30 R09: 0000002b47532412
[  186.864508] R10: 0000000000000000 R11: 0000002b47532412 R12: ffffffffc051d5ba
[  186.864509] R13: ffffffffc051d63a R14: fffffffffffffff4 R15: ffffffffc051d580
[  186.864511] FS:  00007ff85b0bd940(0000) GS:ffff8ebe37c00000(0000) knlGS:0000000000000000
[  186.864516] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  187.325607] CR2: 00005648b9c810c8 CR3: 00000001217b0000 CR4: 00000000001006f0
[  187.325608] Call Trace:
[  186.133412] systemd-udevd[282]: cpu2: Worker [339] processing SEQNUM=946 killed
[  187.325617]  crypto_register_alg+0x59/0x60
[  187.325622]  simd_skcipher_create_compat+0x16d/0x190 [crypto_simd]
[  187.325629]  simd_register_skciphers_compat+0x7e/0xe0 [crypto_simd]
[  187.325632]  ? 0xffffffffc03e5000
[  187.325639]  init_module+0xdd/0x1000 [aesni_intel]
[  187.552585]  ? do_one_initcall+0x46/0x200
[  187.552589]  ? _cond_resched+0x15/0x30
[  186.588969] systemd-udevd[282]: cpu1: Worker [344] processing SEQNUM=945 killed
[  187.552592]  ? kmem_cache_alloc_trace+0x155/0x220
[  187.552596]  ? do_init_module+0x5a/0x220
[  187.552598]  ? load_module+0x20e7/0x2380
[  187.552603]  ? ima_post_read_file+0xf4/0x100
[  187.552607]  ? __do_sys_finit_module+0xa8/0x110
[  187.751720]  ? __do_sys_finit_module+0xa8/0x110
[  187.751725]  ? do_syscall_64+0x4e/0x160
[  187.751728]  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  187.751731] ---[ end trace 0e8a1e38d3de29a9 ]---
[…]
[  370.585075] INFO: task systemd-udevd:328 blocked for more than 122 seconds.
[  370.603822]       Tainted: G        W         5.6.0-flatcar #1
[  370.621569] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  370.641648] systemd-udevd   D    0   328    282 0x80004184
[  370.659432] Call Trace:
[  370.674173]  ? __schedule+0x2db/0x700
[  370.690328]  ? __switch_to_asm+0x34/0x70
[  370.706657]  ? __switch_to_asm+0x34/0x70
[  370.722748]  schedule+0x40/0xb0
[  370.737961]  rwsem_down_read_slowpath+0x370/0x470
[  370.754854]  ? kmem_cache_alloc_trace+0x155/0x220
[  370.771806]  blocking_notifier_call_chain+0x27/0x60
[  370.788960]  crypto_probing_notify+0x1f/0x50
[  370.805479]  crypto_wait_for_test+0x1a/0x70
[  370.821924]  crypto_register_alg+0x59/0x60
[  370.838214]  simd_skcipher_create_compat+0x16d/0x190 [crypto_simd]
[  370.856856]  simd_register_skciphers_compat+0x7e/0xe0 [crypto_simd]
[  370.875667]  ? 0xffffffffc03e5000
[  370.891457]  init_module+0xdd/0x1000 [aesni_intel]
[  370.908800]  ? do_one_initcall+0x46/0x200
[  370.925287]  ? _cond_resched+0x15/0x30
[  370.941503]  ? kmem_cache_alloc_trace+0x155/0x220
[  370.958544]  ? do_init_module+0x5a/0x220
[  370.974573]  ? load_module+0x20e7/0x2380
[  370.990475]  ? ima_post_read_file+0xf4/0x100
[  371.006690]  ? __do_sys_finit_module+0xa8/0x110
[  371.023239]  ? __do_sys_finit_module+0xa8/0x110
[  371.039622]  ? do_syscall_64+0x4e/0x160
[  371.055079]  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
Press Enter for emergency shell or wait 0 minutes 30 seconds for reboot.      
[  371.071924] INFO: task systemd-udevd:342 blocked for more than 246 seconds.
[  371.090560]       Tainted: G        W         5.6.0-flatcar #1
[  371.107917] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  371.127621] systemd-udevd   D    0   342    282 0x80004184
[  371.145080] Call Trace:
[  371.159355]  ? __schedule+0x2db/0x700
[  371.174913]  schedule+0x40/0xb0
[  371.189863]  rwsem_down_write_slowpath+0x2ed/0x4a0
[  371.206560]  ? __switch_to_asm+0x40/0x70
[  371.222327]  ? __switch_to_asm+0x40/0x70
[  371.237907]  ? __switch_to_asm+0x34/0x70
[  371.253358]  blocking_notifier_chain_register+0x22/0x50
[  371.270297]  ? 0xffffffffc0443000
[  371.285267]  init_module+0xc/0x1000 [crc_t10dif]
[  371.301604]  do_one_initcall+0x46/0x200
[  371.317149]  ? _cond_resched+0x15/0x30
[  371.332540]  ? kmem_cache_alloc_trace+0x155/0x220
[  371.349015]  do_init_module+0x5a/0x220
[  371.364551]  load_module+0x20e7/0x2380
[  371.379860]  ? ima_post_read_file+0xf4/0x100
[  371.395554]  ? __do_sys_finit_module+0xa8/0x110
[  371.411298]  __do_sys_finit_module+0xa8/0x110
[  371.426644]  do_syscall_64+0x4e/0x160
[  371.441253]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  371.457429] RIP: 0033:0x7ff85b857389
[  371.472144] Code: Bad RIP value.
[  371.486624] RSP: 002b:00007ffd23810dd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[  371.505960] RAX: ffffffffffffffda RBX: 0000558347a0e990 RCX: 00007ff85b857389
[  371.524997] RDX: 0000000000000000 RSI: 00007ff85b9b586d RDI: 000000000000000f
[  371.544130] RBP: 00007ff85b9b586d R08: 0000000000000000 R09: 0000000000000001
[  371.563228] R10: 000000000000000f R11: 0000000000000246 R12: 0000000000000000
[  371.582236] R13: 0000558347a330b0 R14: 0000000000020000 R15: 0000558347a0e990
[  371.601322] INFO: task cryptomgr_probe:389 blocked for more than 246 seconds.
[  371.620605]       Tainted: G        W         5.6.0-flatcar #1
[  371.638550] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  371.658770] cryptomgr_probe D    0   389      2 0x80004080
[  371.676575] Call Trace:
[  371.691114]  ? __schedule+0x2db/0x700
[  371.706879]  ? sched_clock_cpu+0xc/0xb0
[  371.722818]  schedule+0x40/0xb0
[  371.737961]  rwsem_down_read_slowpath+0x370/0x470
[  371.754787]  blocking_notifier_call_chain+0x27/0x60
[  371.771881]  ? wake_up_q+0xa0/0xa0
[  371.787480]  crypto_probing_notify+0x1f/0x50
[  371.803986]  crypto_wait_for_test+0x50/0x70
[  371.820544]  crypto_register_instance+0xed/0x110
[  371.837526]  cryptd_alloc_aead+0xabf/0xbb0 [cryptd]
[  371.854728]  ? crypto_alg_put+0x40/0x40
[  371.870669]  cryptomgr_probe+0x3f/0x80
[  371.886325]  kthread+0x112/0x130
[  371.901170]  ? kthread_park+0x80/0x80
[  371.916212]  ret_from_fork+0x35/0x40

Note You need to log in before you can comment on or make changes to this bug.