virtme: waiting for virtiofsd to start virtme: use 'microvm' QEMU architecture [ 1.021052][ T1] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev [ 1.021084][ T1] BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:322 [ 1.021086][ T1] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 1, name: swapper/0 [ 1.021087][ T1] preempt_count: 1, expected: 0 [ 1.021088][ T1] RCU nest depth: 0, expected: 0 [ 1.021089][ T1] locks held by swapper/0/1: 4, last CPU#0: [ 1.021091][ T1] #0: ffffffffad769cc0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x320/0x3e0 [ 1.021104][ T1] #1: ffffffffad769d38 (console_srcu){....}-{0:0}, at: console_flush_one_record+0x106/0x710 [ 1.021108][ T1] #2: ffffffffad689660 (console_owner){....}-{0:0}, at: console_lock_spinning_enable+0x40/0x60 [ 1.021112][ T1] #3: ffffffffad689560 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_emit_next_record+0x1df/0x4c0 [ 1.021116][ T1] irq event stamp: 311166 [ 1.021117][ T1] hardirqs last enabled at (311165): [] __down_trylock_console_sem+0x86/0xa0 [ 1.021119][ T1] hardirqs last disabled at (311166): [] console_emit_next_record+0x3d4/0x4c0 [ 1.021121][ T1] softirqs last enabled at (309640): [] handle_softirqs+0x67c/0x900 [ 1.021125][ T1] softirqs last disabled at (309459): [] __irq_exit_rcu+0x145/0x1c0 [ 1.021127][ T1] Preemption disabled at: [ 1.021127][ T1] [] vprintk_emit+0x31b/0x3e0 [ 1.021133][ T1] CPU: 0 UID: 0 PID: 1 Comm: swapper/0 Not tainted 7.2.0-virtme #1 PREEMPT(full) [ 1.021136][ T1] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 1.021137][ T1] Call Trace: [ 1.021139][ T1] [ 1.021142][ T1] dump_stack_lvl+0x6f/0xa0 [ 1.021148][ T1] ? vprintk_emit+0x31b/0x3e0 [ 1.021150][ T1] __might_resched.cold+0x1fe/0x2c1 [ 1.021155][ T1] ? perf_trace_sched_switch+0x7c0/0x7c0 [ 1.021159][ T1] ? __kmalloc_noprof+0xdb/0x760 [ 1.021164][ T1] __kmalloc_noprof+0x443/0x760 [ 1.021166][ T1] ? alloc_buf.isra.0+0x4b/0x260 [ 1.021172][ T1] ? do_raw_spin_unlock+0x59/0x250 [ 1.021175][ T1] alloc_buf.isra.0+0x4b/0x260 [ 1.021178][ T1] put_chars+0x1e1/0x2f0 [ 1.021179][ T1] ? prb_final_commit+0x50/0x50 [ 1.021181][ T1] ? __send_to_port+0x420/0x420 [ 1.021184][ T1] ? rcu_lockdep_current_cpu_online+0x3f/0x1b0 [ 1.021189][ T1] ? rcu_read_lock_any_held+0x3c/0x90 [ 1.021191][ T1] ? validate_chain+0x38b/0xc20 [ 1.021195][ T1] hvc_console_print+0x292/0x780 [ 1.021197][ T1] ? mark_usage+0x61/0x170 [ 1.021199][ T1] ? __lock_acquire+0x518/0xc20 [ 1.021200][ T1] ? __lock_acquire+0x518/0xc20 [ 1.021204][ T1] ? hvc_write+0x3a0/0x3a0 [ 1.021206][ T1] ? console_emit_next_record+0x1df/0x4c0 [ 1.021209][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.021212][ T1] ? lock_acquire+0x13c/0x160 [ 1.021216][ T1] console_emit_next_record+0x22f/0x4c0 [ 1.021219][ T1] ? devkmsg_read+0x4b0/0x4b0 [ 1.021221][ T1] ? console_flush_one_record+0x106/0x710 [ 1.021224][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.021226][ T1] ? lock_acquire+0x13c/0x160 [ 1.021230][ T1] console_flush_one_record+0x46f/0x710 [ 1.021234][ T1] ? console_emit_next_record+0x4c0/0x4c0 [ 1.021236][ T1] ? __lock_acquire+0x518/0xc20 [ 1.021241][ T1] console_unlock+0xee/0x1f0 [ 1.021244][ T1] ? console_flush_one_record+0x710/0x710 [ 1.021246][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.021248][ T1] ? lock_acquire+0x60/0x160 [ 1.021252][ T1] ? __down_trylock_console_sem+0x5e/0xa0 [ 1.021253][ T1] ? vprintk_emit+0x320/0x3e0 [ 1.021257][ T1] vprintk_emit+0x37c/0x3e0 [ 1.021260][ T1] ? wake_up_klogd_work_func+0x90/0x90 [ 1.021263][ T1] ? misc_register+0x151/0x670 [ 1.021267][ T1] ? md_run_setup+0x90/0x90 [ 1.021272][ T1] _printk+0xc7/0x100 [ 1.021275][ T1] ? snapshot_read.cold+0x21/0x21 [ 1.021277][ T1] ? md_run_setup+0x90/0x90 [ 1.021282][ T1] ? md_run_setup+0x90/0x90 [ 1.021286][ T1] dm_interface_init+0x50/0x60 [ 1.021288][ T1] dm_init+0x51/0xd0 [ 1.021290][ T1] ? md_run_setup+0x90/0x90 [ 1.021292][ T1] do_one_initcall+0x124/0x4f0 [ 1.021295][ T1] ? trace_event_raw_event_initcall_level+0x280/0x280 [ 1.021297][ T1] ? parameq+0x110/0x110 [ 1.021302][ T1] ? kernel_init_freeable+0x3f1/0x630 [ 1.021305][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.021308][ T1] kernel_init_freeable+0x596/0x630 [ 1.021311][ T1] ? rest_init+0x280/0x280 [ 1.021316][ T1] kernel_init+0x21/0x150 [ 1.021319][ T1] ? rest_init+0x280/0x280 [ 1.021320][ T1] ret_from_fork+0x474/0x6b0 [ 1.021324][ T1] ? arch_exit_to_user_mode_prepare.isra.0+0x120/0x120 [ 1.021328][ T1] ? __switch_to+0x5a3/0xe00 [ 1.021331][ T1] ? rest_init+0x280/0x280 [ 1.021334][ T1] ret_from_fork_asm+0x11/0x20 [ 1.021341][ T1] [ 1.047710][ T1] NET: Registered PF_INET6 protocol family [ 1.052179][ T1] Segment Routing with IPv6 [ 1.052569][ T1] In-situ OAM (IOAM) with IPv6 [ 1.052930][ T1] NET: Registered PF_PACKET protocol family [ 1.053255][ T1] 9pnet: Installing 9P2000 support [ 1.053622][ T1] Key type dns_resolver registered [ 1.054355][ T1] NET: Registered PF_VSOCK protocol family [ 1.058945][ T1] IPI shorthand broadcast: enabled [ 1.161153][ T1] sched_clock: Marking stable (1122001744, 38768700)->(1263927962, -103157518) [ 1.163383][ T1] registered taskstats version 1 [ 1.165191][ T1] Loading compiled-in X.509 certificates [ 1.268604][ T1] Demotion targets for Node 0: null [ 1.268971][ T1] kmemleak: Kernel memory leak detector initialized (mem pool available: 12236) [ 1.269261][ T1] page_owner is disabled [ 1.270424][ T1] PM: Magic number: 6:307:779 [ 1.270898][ T1] netconsole: network logging started [ 1.272309][ T1] ALSA device list: [ 1.273386][ T1] No soundcards found. [ 1.274937][ T1] md: Skipping autodetection of RAID arrays. (raid=autodetect will force) [ 1.277875][ T1] VFS: Mounted root (virtiofs filesystem) readonly on device 0:24. [ 1.278749][ T1] devtmpfs: mounted [ 1.279069][ T1] VFS: Pivoted into new rootfs [ 1.308205][ T1] Freeing unused kernel image (initmem) memory: 2544K [ 1.308438][ T1] Write protecting the kernel read-only data: 55296k [ 1.308935][ T1] Freeing unused kernel image (text/rodata gap) memory: 328K [ 1.309355][ T1] Freeing unused kernel image (rodata/data gap) memory: 556K [ 1.309971][ T1] Run /usr/lib/python3.14/site-packages/virtme/guest/bin/virtme-ng-init as init process [ 1.310232][ T1] with arguments: [ 1.310362][ T1] /usr/lib/python3.14/site-packages/virtme/guest/bin/virtme-ng-init [ 1.310588][ T1] with environment: [ 1.310712][ T1] HOME=/ [ 1.310852][ T1] TERM=dumb [ 1.310967][ T1] virtme_hostname=vmksft-forwarding-dbg,debug-threads=on [ 1.311196][ T1] nr_open=2147483584 [ 1.311318][ T1] virtme_link_mods=/srv/vmksft/testing/wt-4/.virtme_mods/lib/modules/0.0.0 [ 1.311584][ T1] virtme_rw_overlay0=/etc [ 1.311745][ T1] virtme_rw_overlay1=/lib [ 1.311910][ T1] virtme_rw_overlay2=/home [ 1.312110][ T1] virtme_rw_overlay3=/opt [ 1.312267][ T1] virtme_rw_overlay4=/srv [ 1.312426][ T1] virtme_rw_overlay5=/usr [ 1.312575][ T1] virtme_rw_overlay6=/var [ 1.312731][ T1] virtme_rw_overlay7=/tmp [ 1.312906][ T1] virtme_console=ttyS0 [ 1.313056][ T1] virtme_chdir=srv/vmksft/testing/wt-4 [ 1.328608][ T1] virtme-ng-init: mount devtmpfs -> /dev: EBUSY: Device or resource busy [ 1.329831][ T1] virtme-ng-init: Setting hostname to vmksft-forwarding-dbg,debug-threads=on... [ 1.341540][ T1] overlayfs: failed to set xattr on upper [ 1.341828][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.342100][ T1] overlayfs: ...falling back to uuid=null. [ 1.344374][ T1] overlayfs: failed to set xattr on upper [ 1.344575][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.344823][ T1] overlayfs: ...falling back to uuid=null. [ 1.346712][ T1] overlayfs: failed to set xattr on upper [ 1.346929][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.347160][ T1] overlayfs: ...falling back to uuid=null. [ 1.348975][ T1] overlayfs: failed to set xattr on upper [ 1.349178][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.349410][ T1] overlayfs: ...falling back to uuid=null. [ 1.351288][ T1] overlayfs: failed to set xattr on upper [ 1.351480][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.351721][ T1] overlayfs: ...falling back to uuid=null. [ 1.353341][ T1] overlayfs: failed to set xattr on upper [ 1.353532][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.353787][ T1] overlayfs: ...falling back to uuid=null. [ 1.356054][ T1] overlayfs: failed to set xattr on upper [ 1.356256][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.356490][ T1] overlayfs: ...falling back to uuid=null. [ 1.358297][ T1] overlayfs: failed to set xattr on upper [ 1.358497][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.358740][ T1] overlayfs: ...falling back to uuid=null. [ 1.370317][ T1] virtme-ng-init: running systemd-tmpfiles [ 1.419629][ T72] kwatchdog (72) used greatest stack depth: 29688 bytes left [ 3.769583][ T71] systemd-tmpfile (71) used greatest stack depth: 25152 bytes left [ 3.769601][ T71] BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:322 [ 3.769603][ T71] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 71, name: systemd-tmpfile [ 3.769605][ T71] preempt_count: 2, expected: 0 [ 3.769605][ T71] RCU nest depth: 0, expected: 0 [ 3.769606][ T71] locks held by systemd-tmpfile/71: 5, last CPU#3: [ 3.769609][ T71] #0: ffffffffad6027b8 (low_water_lock){+.+.}-{3:3}, at: do_exit+0x887/0xdc0 [ 3.769621][ T71] #1: ffffffffad769cc0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x320/0x3e0 [ 3.769627][ T71] #2: ffffffffad769d38 (console_srcu){....}-{0:0}, at: console_flush_one_record+0x106/0x710 [ 3.769631][ T71] #3: ffffffffad689660 (console_owner){....}-{0:0}, at: console_lock_spinning_enable+0x40/0x60 [ 3.769635][ T71] #4: ffffffffad689560 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_emit_next_record+0x1df/0x4c0 [ 3.769639][ T71] irq event stamp: 2413538 [ 3.769640][ T71] hardirqs last enabled at (2413537): [] __down_trylock_console_sem+0x86/0xa0 [ 3.769642][ T71] hardirqs last disabled at (2413538): [] console_emit_next_record+0x3d4/0x4c0 [ 3.769644][ T71] softirqs last enabled at (2411342): [] handle_softirqs+0x67c/0x900 [ 3.769646][ T71] softirqs last disabled at (2411335): [] __irq_exit_rcu+0x145/0x1c0 [ 3.769648][ T71] Preemption disabled at: [ 3.769649][ T71] [<0000000000000000>] 0x0 [ 3.769656][ T71] CPU: 3 UID: 0 PID: 71 Comm: systemd-tmpfile Tainted: G W 7.2.0-virtme #1 PREEMPT(full) [ 3.769660][ T71] Tainted: [W]=WARN [ 3.769661][ T71] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 3.769663][ T71] Call Trace: [ 3.769664][ T71] [ 3.769666][ T71] dump_stack_lvl+0x6f/0xa0 [ 3.769672][ T71] __might_resched.cold+0x1fe/0x2c1 [ 3.769677][ T71] ? perf_trace_sched_switch+0x7c0/0x7c0 [ 3.769681][ T71] ? __kmalloc_noprof+0xdb/0x760 [ 3.769686][ T71] __kmalloc_noprof+0x443/0x760 [ 3.769688][ T71] ? alloc_buf.isra.0+0x4b/0x260 [ 3.769694][ T71] ? do_raw_spin_unlock+0x59/0x250 [ 3.769697][ T71] alloc_buf.isra.0+0x4b/0x260 [ 3.769700][ T71] put_chars+0x1e1/0x2f0 [ 3.769703][ T71] ? __send_to_port+0x420/0x420 [ 3.769704][ T71] ? rcu_lockdep_current_cpu_online+0x3f/0x1b0 [ 3.769708][ T71] ? validate_chain+0x38b/0xc20 [ 3.769713][ T71] hvc_console_print+0x292/0x780 [ 3.769719][ T71] ? hvc_write+0x3a0/0x3a0 [ 3.769722][ T71] ? rcu_is_watching+0x16/0xd0 [ 3.769724][ T71] ? lock_acquire+0x13c/0x160 [ 3.769728][ T71] console_emit_next_record+0x22f/0x4c0 [ 3.769732][ T71] ? devkmsg_read+0x4b0/0x4b0 [ 3.769733][ T71] ? console_flush_one_record+0x106/0x710 [ 3.769736][ T71] ? rcu_is_watching+0x16/0xd0 [ 3.769739][ T71] ? lock_acquire+0x13c/0x160 [ 3.769742][ T71] console_flush_one_record+0x46f/0x710 [ 3.769746][ T71] ? console_emit_next_record+0x4c0/0x4c0 [ 3.769748][ T71] ? __lock_acquire+0x518/0xc20 [ 3.769753][ T71] console_unlock+0xee/0x1f0 [ 3.769756][ T71] ? console_flush_one_record+0x710/0x710 [ 3.769758][ T71] ? rcu_is_watching+0x16/0xd0 [ 3.769760][ T71] ? lock_acquire+0x60/0x160 [ 3.769763][ T71] ? __down_trylock_console_sem+0x5e/0xa0 [ 3.769765][ T71] ? vprintk_emit+0x320/0x3e0 [ 3.769775][ T71] vprintk_emit+0x37c/0x3e0 [ 3.769778][ T71] ? wake_up_klogd_work_func+0x90/0x90 [ 3.769782][ T71] ? __lock_acquire+0x518/0xc20 [ 3.769785][ T71] _printk+0xc7/0x100 [ 3.769789][ T71] ? snapshot_read.cold+0x21/0x21 [ 3.769792][ T71] ? do_raw_spin_lock+0x131/0x280 [ 3.769794][ T71] ? __rwlock_init+0x150/0x150 [ 3.769798][ T71] ? do_raw_spin_lock+0x131/0x280 [ 3.769801][ T71] do_exit.cold+0x82/0x9c [ 3.769804][ T71] ? exit_notify+0x890/0x890 [ 3.769806][ T71] ? __lock_release.isra.0+0x69/0x1a0 [ 3.769809][ T71] ? rcu_is_watching+0x16/0xd0 [ 3.769813][ T71] do_group_exit+0xb8/0x370 [ 3.769816][ T71] __x64_sys_exit_group+0x3c/0x50 [ 3.769817][ T71] x64_sys_call+0x1567/0x1570 [ 3.769820][ T71] do_syscall_64+0xff/0x530 [ 3.769823][ T71] ? exc_page_fault+0xee/0x100 [ 3.769826][ T71] entry_SYSCALL_64_after_hwframe+0x4b/0x53 [ 3.769828][ T71] RIP: 0033:0x7fec7164a1b8 [ 3.769830][ T71] Code: Unable to access opcode bytes at 0x7fec7164a18e. [ 3.769831][ T71] RSP: 002b:00007ffe343dd238 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7 [ 3.769834][ T71] RAX: ffffffffffffffda RBX: 00007fec7177af88 RCX: 00007fec7164a1b8 [ 3.769835][ T71] RDX: 00007fec70ea84c8 RSI: fffffffffffffe90 RDI: 0000000000000049 [ 3.769836][ T71] RBP: 00007ffe343dd290 R08: 0000000000000000 R09: 0000000000001000 [ 3.769837][ T71] R10: 00007ffe343dd050 R11: 0000000000000246 R12: 0000000000000001 [ 3.769837][ T71] R13: 0000000000000049 R14: 00007fec71779680 R15: 00007fec7177afa0 [ 3.769844][ T71] [ 3.769932][ T1] virtme-ng-init: Failed to read '/usr/lib/tmpfiles.d/audit.conf': Permission denied [ 3.769932][ T1] Failed to create directory or subvolume "/var/spool/at/spool": Permission denied [ 3.769932][ T1] Failed to create file /var/spool/at/.SEQ: Permission denied [ 3.769932][ T1] Failed to opendir() '/proc/self/fd/6': Permission denied [ 3.803950][ T1] virtme-ng-init: basic initialization done [ 3.844113][ T78] ip (78) used greatest stack depth: 24440 bytes left [ 3.862416][ T74] virtme-ng-init: Starting systemd-udevd version 259.8-1.fc44 [ 3.862862][ T74] virtme-ng-init: triggering udev coldplug [ 6.364068][ T74] virtme-ng-init: waiting for udev to settle [ 6.364088][ T74] BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:322 [ 6.364092][ T74] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 74, name: virtme-ng-init [ 6.364095][ T74] preempt_count: 1, expected: 0 [ 6.364096][ T74] RCU nest depth: 0, expected: 0 [ 6.364098][ T74] locks held by virtme-ng-init/74: 4, last CPU#3: [ 6.364101][ T74] #0: ffffffffad769cc0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x320/0x3e0 [ 6.364119][ T74] #1: ffffffffad769d38 (console_srcu){....}-{0:0}, at: console_flush_one_record+0x106/0x710 [ 6.364126][ T74] #2: ffffffffad689660 (console_owner){....}-{0:0}, at: console_lock_spinning_enable+0x40/0x60 [ 6.364133][ T74] #3: ffffffffad689560 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_emit_next_record+0x1df/0x4c0 [ 6.364141][ T74] irq event stamp: 4518 [ 6.364142][ T74] hardirqs last enabled at (4517): [] __down_trylock_console_sem+0x86/0xa0 [ 6.364146][ T74] hardirqs last disabled at (4518): [] console_emit_next_record+0x3d4/0x4c0 [ 6.364150][ T74] softirqs last enabled at (4510): [] handle_softirqs+0x67c/0x900 [ 6.364154][ T74] softirqs last disabled at (3155): [] __irq_exit_rcu+0x145/0x1c0 [ 6.364158][ T74] Preemption disabled at: [ 6.364159][ T74] [] vprintk_emit+0x31b/0x3e0 [ 6.364168][ T74] CPU: 3 UID: 0 PID: 74 Comm: virtme-ng-init Tainted: G W 7.2.0-virtme #1 PREEMPT(full) [ 6.364173][ T74] Tainted: [W]=WARN [ 6.364175][ T74] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 6.364177][ T74] Call Trace: [ 6.364180][ T74] [ 6.364182][ T74] dump_stack_lvl+0x6f/0xa0 [ 6.364190][ T74] ? vprintk_emit+0x31b/0x3e0 [ 6.364194][ T74] __might_resched.cold+0x1fe/0x2c1 [ 6.364201][ T74] ? perf_trace_sched_switch+0x7c0/0x7c0 [ 6.364207][ T74] ? __kmalloc_noprof+0xdb/0x760 [ 6.364216][ T74] __kmalloc_noprof+0x443/0x760 [ 6.364220][ T74] ? alloc_buf.isra.0+0x4b/0x260 [ 6.364229][ T74] ? do_raw_spin_unlock+0x59/0x250 [ 6.364233][ T74] alloc_buf.isra.0+0x4b/0x260 [ 6.364239][ T74] put_chars+0x1e1/0x2f0 [ 6.364244][ T74] ? __send_to_port+0x420/0x420 [ 6.364246][ T74] ? rcu_lockdep_current_cpu_online+0x3f/0x1b0 [ 6.364254][ T74] ? validate_chain+0x38b/0xc20 [ 6.364265][ T74] hvc_console_print+0x292/0x780 [ 6.364276][ T74] ? hvc_write+0x3a0/0x3a0 [ 6.364280][ T74] ? rcu_is_watching+0x16/0xd0 [ 6.364284][ T74] ? lock_acquire+0x13c/0x160 [ 6.364292][ T74] console_emit_next_record+0x22f/0x4c0 [ 6.364299][ T74] ? devkmsg_read+0x4b0/0x4b0 [ 6.364302][ T74] ? console_flush_one_record+0x106/0x710 [ 6.364308][ T74] ? rcu_is_watching+0x16/0xd0 [ 6.364312][ T74] ? lock_acquire+0x13c/0x160 [ 6.364320][ T74] console_flush_one_record+0x46f/0x710 [ 6.364328][ T74] ? console_emit_next_record+0x4c0/0x4c0 [ 6.364332][ T74] ? __lock_acquire+0x518/0xc20 [ 6.364343][ T74] console_unlock+0xee/0x1f0 [ 6.364348][ T74] ? console_flush_one_record+0x710/0x710 [ 6.364350][ T74] ? rcu_is_watching+0x16/0xd0 [ 6.364354][ T74] ? lock_acquire+0x60/0x160 [ 6.364362][ T74] ? __down_trylock_console_sem+0x5e/0xa0 [ 6.364365][ T74] ? vprintk_emit+0x320/0x3e0 [ 6.364371][ T74] vprintk_emit+0x37c/0x3e0 [ 6.364378][ T74] ? wake_up_klogd_work_func+0x90/0x90 [ 6.364384][ T74] ? _copy_from_iter+0x1bb/0x1810 [ 6.364394][ T74] devkmsg_emit.constprop.0+0xbc/0xf1 [ 6.364400][ T74] ? vprintk_emit.cold+0x107/0x107 [ 6.364403][ T74] ? simple_strntoull+0x10f/0x140 [ 6.364409][ T74] ? date_str+0x1e0/0x1e0 [ 6.364416][ T74] ? devkmsg_write+0xd1/0x2c0 [ 6.364425][ T74] devkmsg_write.cold+0x5a/0x8b [ 6.364430][ T74] ? vprintk_default+0x20/0x20 [ 6.364439][ T74] ? vprintk_default+0x20/0x20 [ 6.364443][ T74] new_sync_write+0x33e/0x760 [ 6.364449][ T74] ? kasan_quarantine_put+0x42/0x2b0 [ 6.364455][ T74] ? new_sync_read+0x750/0x750 [ 6.364463][ T74] ? __lock_release.isra.0+0x69/0x1a0 [ 6.364473][ T74] ? __fget_files+0x1e3/0x460 [ 6.364480][ T74] vfs_write+0x6a2/0xbd0 [ 6.364488][ T74] ksys_write+0x116/0x250 [ 6.364494][ T74] ? __ia32_sys_read+0xc0/0xc0 [ 6.364500][ T74] ? rcu_is_watching+0x16/0xd0 [ 6.364507][ T74] do_syscall_64+0xff/0x530 [ 6.364512][ T74] ? irq_exit_rcu+0x1a/0x30 [ 6.364518][ T74] entry_SYSCALL_64_after_hwframe+0x4b/0x53 [ 6.364522][ T74] RIP: 0033:0x7f039499fed2 [ 6.364528][ T74] Code: 08 0f 85 51 ec ff ff 49 89 fb 48 89 f0 48 89 d7 48 89 ce 4c 89 c2 4d 89 ca 4c 8b 44 24 08 4c 8b 4c 24 10 4c 89 5c 24 08 0f 05 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 f3 0f 1e fa 55 48 89 e5 [ 6.364530][ T74] RSP: 002b:00007f03948e6c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 [ 6.364535][ T74] RAX: ffffffffffffffda RBX: 000000000000002e RCX: 00007f039499fed2 [ 6.364537][ T74] RDX: 000000000000002e RSI: 00007f03900012c0 RDI: 0000000000000003 [ 6.364539][ T74] RBP: 00007f03948e6c90 R08: 0000000000000000 R09: 0000000000000000 [ 6.364540][ T74] R10: 0000000000000000 R11: 0000000000000246 R12: 00007f0394a2a0a0 [ 6.364542][ T74] R13: 00007f03949283e0 R14: 00007f03900012c0 R15: 00007f03948e6da8 [ 6.364557][ T74] [ 6.418917][ C0] clocksource: Watchdog remote CPU 3 read timed out [ 6.418944][ C0] [ 6.418946][ C0] ======================================================== [ 6.418948][ C0] WARNING: possible irq lock inversion dependency detected [ 6.418950][ C0] 7.2.0-virtme #1 Tainted: G W [ 6.418951][ C0] -------------------------------------------------------- [ 6.418952][ C0] (udev-worker)/84 just changed the state of lock: [ 6.418953][ C0] ffffffffad689660 (console_owner){..-.}-{0:0}, at: console_trylock_spinning+0xa4/0x1e0 [ 6.418966][ C0] but this lock took another, SOFTIRQ-unsafe lock in the past: [ 6.418968][ C0] (fs_reclaim){+.+.}-{0:0} [ 6.418969][ C0] [ 6.418969][ C0] [ 6.418969][ C0] and interrupts could create inverse lock ordering between them. [ 6.418969][ C0] [ 6.418970][ C0] [ 6.418970][ C0] other info that might help us debug this: [ 6.418970][ C0] Possible interrupt unsafe locking scenario: [ 6.418970][ C0] [ 6.418971][ C0] CPU0 CPU1 [ 6.418971][ C0] ---- ---- [ 6.418972][ C0] lock(fs_reclaim); [ 6.418973][ C0] local_irq_disable(); [ 6.418973][ C0] lock(console_owner); [ 6.418974][ C0] lock(fs_reclaim); [ 6.418975][ C0] [ 6.418975][ C0] lock(console_owner); [ 6.418976][ C0] [ 6.418976][ C0] *** DEADLOCK *** [ 6.418976][ C0] [ 6.418976][ C0] locks held by (udev-worker)/84: 2, last CPU#0: [ 6.418978][ C0] #0: ffa0000000007c90 ((&watchdog_timer)){+.-.}-{0:0}, at: call_timer_fn+0x110/0x4d0 [ 6.418983][ C0] #1: ffffffffad7ce8b8 (watchdog_lock){+.-.}-{3:3}, at: clocksource_watchdog+0x15/0x30 [ 6.418987][ C0] [ 6.418987][ C0] the shortest dependencies between 2nd lock and 1st lock: [ 6.418991][ C0] -> (fs_reclaim){+.+.}-{0:0} { [ 6.418994][ C0] HARDIRQ-ON-W at: [ 6.418995][ C0] __lock_acquire+0x388/0xc20 [ 6.418998][ C0] lock_acquire.part.0+0xd4/0x280 [ 6.419000][ C0] fs_reclaim_acquire+0xd5/0x120 [ 6.419003][ C0] __kmalloc_cache_noprof+0x6e/0x620 [ 6.419005][ C0] kthread_create_worker_on_node+0xea/0x210 [ 6.419008][ C0] workqueue_init+0x2a/0x680 [ 6.419012][ C0] kernel_init_freeable+0x2fe/0x630 [ 6.419014][ C0] kernel_init+0x21/0x150 [ 6.419017][ C0] ret_from_fork+0x474/0x6b0 [ 6.419020][ C0] ret_from_fork_asm+0x11/0x20 [ 6.419023][ C0] SOFTIRQ-ON-W at: [ 6.419024][ C0] __lock_acquire+0x388/0xc20 [ 6.419025][ C0] lock_acquire.part.0+0xd4/0x280 [ 6.419027][ C0] fs_reclaim_acquire+0xd5/0x120 [ 6.419028][ C0] __kmalloc_cache_noprof+0x6e/0x620 [ 6.419029][ C0] kthread_create_worker_on_node+0xea/0x210 [ 6.419031][ C0] workqueue_init+0x2a/0x680 [ 6.419032][ C0] kernel_init_freeable+0x2fe/0x630 [ 6.419033][ C0] kernel_init+0x21/0x150 [ 6.419035][ C0] ret_from_fork+0x474/0x6b0 [ 6.419036][ C0] ret_from_fork_asm+0x11/0x20 [ 6.419037][ C0] INITIAL USE at: [ 6.419038][ C0] __lock_acquire+0x388/0xc20 [ 6.419039][ C0] lock_acquire.part.0+0xd4/0x280 [ 6.419041][ C0] fs_reclaim_acquire+0xd5/0x120 [ 6.419042][ C0] __kmalloc_cache_noprof+0x6e/0x620 [ 6.419043][ C0] kthread_create_worker_on_node+0xea/0x210 [ 6.419045][ C0] workqueue_init+0x2a/0x680 [ 6.419046][ C0] kernel_init_freeable+0x2fe/0x630 [ 6.419047][ C0] kernel_init+0x21/0x150 [ 6.419048][ C0] ret_from_fork+0x474/0x6b0 [ 6.419049][ C0] ret_from_fork_asm+0x11/0x20 [ 6.419051][ C0] } [ 6.419051][ C0] ... key at: [] __fs_reclaim_map+0x0/0xbe0 [ 6.419055][ C0] ... acquired at: [ 6.419056][ C0] __lock_acquire+0x518/0xc20 [ 6.419058][ C0] lock_acquire.part.0+0xd4/0x280 [ 6.419059][ C0] fs_reclaim_acquire+0xd5/0x120 [ 6.419060][ C0] __kmalloc_noprof+0xd3/0x760 [ 6.419061][ C0] alloc_buf.isra.0+0x4b/0x260 [ 6.419064][ C0] put_chars+0x1e1/0x2f0 [ 6.419066][ C0] hvc_console_print+0x292/0x780 [ 6.419067][ C0] console_emit_next_record+0x22f/0x4c0 [ 6.419069][ C0] console_flush_one_record+0x46f/0x710 [ 6.419071][ C0] console_unlock+0xee/0x1f0 [ 6.419073][ C0] vprintk_emit+0x37c/0x3e0 [ 6.419074][ C0] _printk+0xc7/0x100 [ 6.419078][ C0] dm_interface_init+0x50/0x60 [ 6.419080][ C0] dm_init+0x51/0xd0 [ 6.419081][ C0] do_one_initcall+0x124/0x4f0 [ 6.419082][ C0] kernel_init_freeable+0x596/0x630 [ 6.419083][ C0] kernel_init+0x21/0x150 [ 6.419085][ C0] ret_from_fork+0x474/0x6b0 [ 6.419086][ C0] ret_from_fork_asm+0x11/0x20 [ 6.419087][ C0] [ 6.419088][ C0] -> (console_owner){..-.}-{0:0} { [ 6.419090][ C0] IN-SOFTIRQ-W at: [ 6.419090][ C0] __lock_acquire+0x388/0xc20 [ 6.419092][ C0] lock_acquire.part.0+0xd4/0x280 [ 6.419093][ C0] console_trylock_spinning+0xb5/0x1e0 [ 6.419095][ C0] vprintk_emit+0x320/0x3e0 [ 6.419096][ C0] _printk+0xc7/0x100 [ 6.419098][ C0] clocksource_watchdog.part.0.cold+0x105/0x1dd [ 6.419100][ C0] call_timer_fn+0x160/0x4d0 [ 6.419102][ C0] __run_timers+0x68f/0xaa0 [ 6.419103][ C0] run_timer_softirq+0xf0/0x160 [ 6.419105][ C0] handle_softirqs+0x1d3/0x900 [ 6.419107][ C0] __irq_exit_rcu+0x145/0x1c0 [ 6.419109][ C0] irq_exit_rcu+0xe/0x30 [ 6.419110][ C0] sysvec_apic_timer_interrupt+0x9d/0xe0 [ 6.419112][ C0] asm_sysvec_apic_timer_interrupt+0x1a/0x20 [ 6.419114][ C0] lock_release+0xdc/0x1f0 [ 6.419115][ C0] kmem_cache_alloc_noprof+0x73/0x5c0 [ 6.419117][ C0] __alloc_object+0x30/0x260 [ 6.419119][ C0] __create_object+0x30/0x110 [ 6.419121][ C0] kmem_cache_alloc_node_noprof+0x4ce/0x660 [ 6.419123][ C0] kmalloc_reserve+0x103/0x2d0 [ 6.419126][ C0] __alloc_skb+0x11e/0x5f0 [ 6.419128][ C0] netlink_sendmsg+0x573/0xc60 [ 6.419130][ C0] ____sys_sendmsg+0x415/0x880 [ 6.419133][ C0] ___sys_sendmsg+0x14e/0x1d0 [ 6.419134][ C0] __sys_sendmsg+0x12c/0x1d0 [ 6.419136][ C0] do_syscall_64+0xff/0x530 [ 6.419137][ C0] entry_SYSCALL_64_after_hwframe+0x4b/0x53 [ 6.419139][ C0] INITIAL USE at: [ 6.419139][ C0] } [ 6.419140][ C0] ... key at: [] console_owner_dep_map+0x0/0x60 [ 6.419143][ C0] ... acquired at: [ 6.419143][ C0] mark_lock+0x1d7/0xa00 [ 6.419144][ C0] mark_usage+0x42/0x170 [ 6.419146][ C0] __lock_acquire+0x388/0xc20 [ 6.419147][ C0] lock_acquire.part.0+0xd4/0x280 [ 6.419149][ C0] console_trylock_spinning+0xb5/0x1e0 [ 6.419150][ C0] vprintk_emit+0x320/0x3e0 [ 6.419152][ C0] _printk+0xc7/0x100 [ 6.419153][ C0] clocksource_watchdog.part.0.cold+0x105/0x1dd [ 6.419154][ C0] call_timer_fn+0x160/0x4d0 [ 6.419156][ C0] __run_timers+0x68f/0xaa0 [ 6.419157][ C0] run_timer_softirq+0xf0/0x160 [ 6.419159][ C0] handle_softirqs+0x1d3/0x900 [ 6.419160][ C0] __irq_exit_rcu+0x145/0x1c0 [ 6.419161][ C0] irq_exit_rcu+0xe/0x30 [ 6.419163][ C0] sysvec_apic_timer_interrupt+0x9d/0xe0 [ 6.419164][ C0] asm_sysvec_apic_timer_interrupt+0x1a/0x20 [ 6.419165][ C0] lock_release+0xdc/0x1f0 [ 6.419166][ C0] kmem_cache_alloc_noprof+0x73/0x5c0 [ 6.419168][ C0] __alloc_object+0x30/0x260 [ 6.419169][ C0] __create_object+0x30/0x110 [ 6.419171][ C0] kmem_cache_alloc_node_noprof+0x4ce/0x660 [ 6.419172][ C0] kmalloc_reserve+0x103/0x2d0 [ 6.419174][ C0] __alloc_skb+0x11e/0x5f0 [ 6.419175][ C0] netlink_sendmsg+0x573/0xc60 [ 6.419176][ C0] ____sys_sendmsg+0x415/0x880 [ 6.419178][ C0] ___sys_sendmsg+0x14e/0x1d0 [ 6.419179][ C0] __sys_sendmsg+0x12c/0x1d0 [ 6.419180][ C0] do_syscall_64+0xff/0x530 [ 6.419181][ C0] entry_SYSCALL_64_after_hwframe+0x4b/0x53 [ 6.419183][ C0] [ 6.419183][ C0] [ 6.419183][ C0] stack backtrace: [ 6.419186][ C0] CPU: 0 UID: 0 PID: 84 Comm: (udev-worker) Tainted: G W 7.2.0-virtme #1 PREEMPT(full) [ 6.419189][ C0] Tainted: [W]=WARN [ 6.419190][ C0] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 6.419192][ C0] Call Trace: [ 6.419193][ C0] [ 6.419194][ C0] dump_stack_lvl+0x6f/0xa0 [ 6.419199][ C0] print_irq_inversion_bug.part.0.cold+0xe6/0x143 [ 6.419201][ C0] mark_lock_irq+0x989/0x9c0 [ 6.419203][ C0] ? add_lock_to_list+0x2c/0x1a0 [ 6.419206][ C0] mark_lock+0x1d7/0xa00 [ 6.419207][ C0] mark_usage+0x42/0x170 [ 6.419209][ C0] __lock_acquire+0x388/0xc20 [ 6.419211][ C0] lock_acquire.part.0+0xd4/0x280 [ 6.419213][ C0] ? console_trylock_spinning+0xa4/0x1e0 [ 6.419215][ C0] ? rcu_is_watching+0x16/0xd0 [ 6.419218][ C0] ? lock_acquire+0x13c/0x160 [ 6.419220][ C0] console_trylock_spinning+0xb5/0x1e0 [ 6.419222][ C0] ? console_trylock_spinning+0xa4/0x1e0 [ 6.419224][ C0] vprintk_emit+0x320/0x3e0 [ 6.419226][ C0] ? wake_up_klogd_work_func+0x90/0x90 [ 6.419229][ C0] ? clocksource_watchdog.part.0+0x450/0x540 [ 6.419230][ C0] _printk+0xc7/0x100 [ 6.419232][ C0] ? snapshot_read.cold+0x21/0x21 [ 6.419234][ C0] ? clocksource_watchdog.part.0+0x450/0x540 [ 6.419236][ C0] ? __lock_release.isra.0+0x69/0x1a0 [ 6.419238][ C0] clocksource_watchdog.part.0.cold+0x105/0x1dd [ 6.419240][ C0] ? clocksource_watchdog.part.0+0x540/0x540 [ 6.419241][ C0] ? clocksource_watchdog.part.0+0x540/0x540 [ 6.419243][ C0] call_timer_fn+0x160/0x4d0 [ 6.419245][ C0] ? detach_if_pending+0x1d0/0x1d0 [ 6.419247][ C0] ? debug_object_active_state+0x430/0x430 [ 6.419250][ C0] ? find_held_lock+0x2b/0x80 [ 6.419252][ C0] ? __lock_release.isra.0+0x69/0x1a0 [ 6.419254][ C0] ? rcu_is_watching+0x16/0xd0 [ 6.419256][ C0] __run_timers+0x68f/0xaa0 [ 6.419258][ C0] ? clocksource_watchdog.part.0+0x540/0x540 [ 6.419260][ C0] ? __bpf_trace_itimer_expire+0x10/0x10 [ 6.419262][ C0] ? __lock_acquire+0x518/0xc20 [ 6.419264][ C0] ? __rwlock_init+0x150/0x150 [ 6.419267][ C0] run_timer_softirq+0xf0/0x160 [ 6.419269][ C0] ? __run_timers+0xaa0/0xaa0 [ 6.419271][ C0] ? trace_irq_enable.constprop.0+0x9b/0x160 [ 6.419273][ C0] ? rcu_is_watching+0x16/0xd0 [ 6.419275][ C0] handle_softirqs+0x1d3/0x900 [ 6.419276][ C0] ? __lock_release.isra.0+0x69/0x1a0 [ 6.419278][ C0] ? _local_bh_enable+0xc0/0xc0 [ 6.419280][ C0] __irq_exit_rcu+0x145/0x1c0 [ 6.419282][ C0] irq_exit_rcu+0xe/0x30 [ 6.419283][ C0] sysvec_apic_timer_interrupt+0x9d/0xe0 [ 6.419285][ C0] [ 6.419285][ C0] [ 6.419286][ C0] asm_sysvec_apic_timer_interrupt+0x1a/0x20 [ 6.419288][ C0] RIP: 0010:lock_release+0xdc/0x1f0 [ 6.419291][ C0] Code: a0 38 04 83 f8 01 0f 85 fc 00 00 00 9c 58 f6 c4 02 0f 85 11 01 00 00 41 f7 c7 00 02 00 00 0f 84 c7 00 00 00 fb 4c 8b 7c 24 18 <48> 8b 5c 24 08 4c 8b 74 24 10 48 83 c4 20 c3 65 8b 05 36 5b 38 04 [ 6.419292][ C0] RSP: 0018:ffa0000000567830 EFLAGS: 00000206 [ 6.419295][ C0] RAX: 0000000000000046 RBX: ffffffffad985160 RCX: 0000000000000001 [ 6.419296][ C0] RDX: 0000000000000000 RSI: ffffffffad221b20 RDI: ffffffffacc8d8e0 [ 6.419297][ C0] RBP: 0000000000092cc0 R08: 0000000000000001 R09: ff11000009b62eb8 [ 6.419298][ C0] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000092cc0 [ 6.419299][ C0] R13: 00000000ffffffff R14: ffffffffaad2d003 R15: 0000000000000001 [ 6.419300][ C0] ? kmem_cache_alloc_noprof+0x73/0x5c0 [ 6.419303][ C0] kmem_cache_alloc_noprof+0x73/0x5c0 [ 6.419305][ C0] ? __alloc_object+0x30/0x260 [ 6.419307][ C0] __alloc_object+0x30/0x260 [ 6.419309][ C0] __create_object+0x30/0x110 [ 6.419311][ C0] ? kasan_save_track+0x14/0x30 [ 6.419314][ C0] kmem_cache_alloc_node_noprof+0x4ce/0x660 [ 6.419316][ C0] ? kmalloc_reserve+0x103/0x2d0 [ 6.419318][ C0] kmalloc_reserve+0x103/0x2d0 [ 6.419320][ C0] __alloc_skb+0x11e/0x5f0 [ 6.419321][ C0] ? __alloc_skb+0x4c2/0x5f0 [ 6.419323][ C0] ? napi_skb_cache_get+0x830/0x830 [ 6.419325][ C0] ? rcu_is_watching+0x16/0xd0 [ 6.419327][ C0] ? cap_capable+0x1d7/0x3d0 [ 6.419330][ C0] ? __lock_acquire+0x518/0xc20 [ 6.419333][ C0] netlink_sendmsg+0x573/0xc60 [ 6.419335][ C0] ? netlink_unicast+0x750/0x750 [ 6.419336][ C0] ? __might_fault+0x97/0x140 [ 6.419340][ C0] ____sys_sendmsg+0x415/0x880 [ 6.419342][ C0] ? copy_msghdr_from_user+0x279/0x420 [ 6.419344][ C0] ? get_timestamp.constprop.0+0x390/0x390 [ 6.419345][ C0] ? move_addr_to_kernel+0x40/0x40 [ 6.419347][ C0] ? rcu_lockdep_current_cpu_online+0x3f/0x1b0 [ 6.419349][ C0] ? rcu_read_lock_any_held+0x66/0x90 [ 6.419351][ C0] ? stack_depot_save_flags+0x38e/0x790 [ 6.419355][ C0] ___sys_sendmsg+0x14e/0x1d0 [ 6.419356][ C0] ? copy_msghdr_from_user+0x420/0x420 [ 6.419358][ C0] ? kasan_save_free_info+0x3b/0x60 [ 6.419360][ C0] ? kmem_cache_free+0xf8/0x550 [ 6.419361][ C0] ? __x64_sys_unlink+0x4e/0x60 [ 6.419365][ C0] ? do_syscall_64+0xff/0x530 [ 6.419369][ C0] __sys_sendmsg+0x12c/0x1d0 [ 6.419371][ C0] ? __sys_sendmsg_sock+0x20/0x20 [ 6.419373][ C0] ? trace_irq_enable.constprop.0+0x9b/0x160 [ 6.419375][ C0] ? rcu_is_watching+0x16/0xd0 [ 6.419377][ C0] do_syscall_64+0xff/0x530 [ 6.419378][ C0] ? irq_exit_rcu+0x1a/0x30 [ 6.419380][ C0] entry_SYSCALL_64_after_hwframe+0x4b/0x53 [ 6.419381][ C0] RIP: 0033:0x7fee2673b54e [ 6.419384][ C0] Code: 4d 89 d8 e8 b4 bd 00 00 4c 8b 5d f8 41 8b 93 08 03 00 00 59 5e 48 83 f8 fc 74 11 c9 c3 0f 1f 80 00 00 00 00 48 8b 45 10 0f 05 c3 83 e2 39 83 fa 08 75 e7 e8 03 ff ff ff 0f 1f 00 f3 0f 1e fa [ 6.419385][ C0] RSP: 002b:00007ffe52607b80 EFLAGS: 00000202 ORIG_RAX: 000000000000002e [ 6.419387][ C0] RAX: ffffffffffffffda RBX: 000055a3e54298a0 RCX: 00007fee2673b54e [ 6.419388][ C0] RDX: 0000000000000000 RSI: 00007ffe52607c10 RDI: 000000000000000d [ 6.419388][ C0] RBP: 00007ffe52607b90 R08: 0000000000000000 R09: 0000000000000000 [ 6.419389][ C0] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000000000 [ 6.419390][ C0] R13: 0000000000000000 R14: 000055a3e52d27f0 R15: 000055a3c3794296 [ 6.419392][ C0] [ 6.813068][ T74] virtme-ng-init: udev is done [ 6.815219][ T1] virtme-ng-init: initialization done