virtme: waiting for virtiofsd to start virtme: use 'microvm' QEMU architecture [ 1.242786][ T1] loop: module loaded [ 1.242829][ T1] BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:322 [ 1.242833][ T1] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 1, name: swapper/0 [ 1.242835][ T1] preempt_count: 1, expected: 0 [ 1.242836][ T1] RCU nest depth: 0, expected: 0 [ 1.242837][ T1] locks held by swapper/0/1: 4, last CPU#0: [ 1.242840][ T1] #0: ffffffff95f7ddc0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x320/0x3e0 [ 1.242855][ T1] #1: ffffffff95f7de38 (console_srcu){....}-{0:0}, at: console_flush_one_record+0x106/0x710 [ 1.242863][ T1] #2: ffffffff95e9d760 (console_owner){....}-{0:0}, at: console_lock_spinning_enable+0x40/0x60 [ 1.242869][ T1] #3: ffffffff95e9d660 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_emit_next_record+0x1df/0x4c0 [ 1.242876][ T1] irq event stamp: 309470 [ 1.242877][ T1] hardirqs last enabled at (309469): [] __down_trylock_console_sem+0x86/0xa0 [ 1.242882][ T1] hardirqs last disabled at (309470): [] console_emit_next_record+0x3d4/0x4c0 [ 1.242885][ T1] softirqs last enabled at (309418): [] bdi_register_va+0x491/0x780 [ 1.242889][ T1] softirqs last disabled at (309416): [] bdi_register_va+0x2ef/0x780 [ 1.242893][ T1] Preemption disabled at: [ 1.242893][ T1] [] vprintk_emit+0x31b/0x3e0 [ 1.242900][ T1] CPU: 0 UID: 0 PID: 1 Comm: swapper/0 Not tainted 7.2.0-virtme #1 PREEMPT(full) [ 1.242904][ T1] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 1.242907][ T1] Call Trace: [ 1.242909][ T1] [ 1.242914][ T1] dump_stack_lvl+0x6f/0xa0 [ 1.242922][ T1] ? vprintk_emit+0x31b/0x3e0 [ 1.242924][ T1] __might_resched.cold+0x1fe/0x2c1 [ 1.242931][ T1] ? perf_trace_sched_switch+0x7c0/0x7c0 [ 1.242937][ T1] ? __kmalloc_noprof+0xdb/0x760 [ 1.242943][ T1] __kmalloc_noprof+0x443/0x760 [ 1.242946][ T1] ? alloc_buf.isra.0+0x4b/0x260 [ 1.242957][ T1] ? do_raw_spin_unlock+0x59/0x250 [ 1.242961][ T1] alloc_buf.isra.0+0x4b/0x260 [ 1.242966][ T1] put_chars+0x1e1/0x2f0 [ 1.242969][ T1] ? desc_read_finalized_seq+0x79/0x120 [ 1.242973][ T1] ? __send_to_port+0x420/0x420 [ 1.242978][ T1] ? rcu_read_lock_any_held+0x3c/0x90 [ 1.242982][ T1] ? validate_chain+0x38b/0xc20 [ 1.242990][ T1] hvc_console_print+0x292/0x780 [ 1.242995][ T1] ? __lock_acquire+0x518/0xc20 [ 1.242997][ T1] ? __lock_acquire+0x518/0xc20 [ 1.243004][ T1] ? hvc_write+0x3a0/0x3a0 [ 1.243004][ T1] ? console_emit_next_record+0x1df/0x4c0 [ 1.243004][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.243004][ T1] ? lock_acquire+0x13c/0x160 [ 1.243004][ T1] console_emit_next_record+0x22f/0x4c0 [ 1.243004][ T1] ? devkmsg_read+0x4b0/0x4b0 [ 1.243004][ T1] ? console_flush_one_record+0x106/0x710 [ 1.243004][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.243004][ T1] ? lock_acquire+0x13c/0x160 [ 1.243004][ T1] console_flush_one_record+0x46f/0x710 [ 1.243004][ T1] ? console_emit_next_record+0x4c0/0x4c0 [ 1.243004][ T1] ? __lock_acquire+0x518/0xc20 [ 1.243004][ T1] console_unlock+0xee/0x1f0 [ 1.243004][ T1] ? console_flush_one_record+0x710/0x710 [ 1.243004][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.243004][ T1] ? lock_acquire+0xe0/0x160 [ 1.243004][ T1] ? __down_trylock_console_sem+0x5e/0xa0 [ 1.243004][ T1] ? vprintk_emit+0x320/0x3e0 [ 1.243004][ T1] vprintk_emit+0x37c/0x3e0 [ 1.243004][ T1] ? wake_up_klogd_work_func+0x90/0x90 [ 1.243004][ T1] ? max_loop_setup+0x30/0x30 [ 1.243004][ T1] _printk+0xc7/0x100 [ 1.243004][ T1] ? snapshot_read.cold+0x21/0x21 [ 1.243004][ T1] ? __mutex_unlock_slowpath+0x14d/0x740 [ 1.243004][ T1] loop_init+0x12a/0x130 [ 1.243004][ T1] do_one_initcall+0x124/0x4f0 [ 1.243004][ T1] ? trace_event_raw_event_initcall_level+0x280/0x280 [ 1.243004][ T1] ? parameq+0x110/0x110 [ 1.243004][ T1] ? kernel_init_freeable+0x3f1/0x630 [ 1.243004][ T1] ? rcu_is_watching+0x16/0xd0 [ 1.243004][ T1] kernel_init_freeable+0x596/0x630 [ 1.243004][ T1] ? rest_init+0x280/0x280 [ 1.243004][ T1] kernel_init+0x21/0x150 [ 1.243004][ T1] ? rest_init+0x280/0x280 [ 1.243004][ T1] ret_from_fork+0x474/0x6b0 [ 1.243004][ T1] ? arch_exit_to_user_mode_prepare.isra.0+0x120/0x120 [ 1.243004][ T1] ? __switch_to+0x5a3/0xe00 [ 1.243004][ T1] ? rest_init+0x280/0x280 [ 1.243004][ T1] ret_from_fork_asm+0x11/0x20 [ 1.243004][ T1] [ 1.293078][ T1] tun: Universal TUN/TAP device driver, 1.6 [ 1.295979][ T1] i8042: PNP: No PS/2 controller found. [ 1.307558][ T1] rtc_cmos PNP0B00:00: registered as rtc0 [ 1.308181][ T1] rtc_cmos PNP0B00:00: setting system clock to 2026-08-28T15:34:24 UTC (1787931264) [ 1.309731][ T1] rtc_cmos PNP0B00:00: alarms up to one day, 242 bytes nvram [ 1.315032][ T1] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev [ 1.327442][ T1] ipip: IPv4 and MPLS over IPv4 tunneling driver [ 1.332550][ T1] IPv4 over IPsec tunneling driver [ 1.338582][ T1] NET: Registered PF_INET6 protocol family [ 1.348224][ T1] Segment Routing with IPv6 [ 1.348546][ T1] RPL Segment Routing with IPv6 [ 1.349255][ T1] In-situ OAM (IOAM) with IPv6 [ 1.354445][ T1] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver [ 1.364547][ T1] NET: Registered PF_PACKET protocol family [ 1.365239][ T1] 8021q: 802.1Q VLAN Support v1.8 [ 1.365891][ T1] sctp: Hash tables configured (bind 32/56) [ 1.366990][ T1] 9pnet: Installing 9P2000 support [ 1.367498][ T1] Key type dns_resolver registered [ 1.368567][ T1] NET: Registered PF_VSOCK protocol family [ 1.375332][ T1] IPI shorthand broadcast: enabled [ 1.496363][ T1] sched_clock: Marking stable (1458002415, 38000239)->(1599752490, -103749836) [ 1.499599][ T1] registered taskstats version 1 [ 1.502861][ T1] Loading compiled-in X.509 certificates [ 1.516015][ T69] kwatchdog (69) used greatest stack depth: 29688 bytes left [ 1.621518][ T1] Demotion targets for Node 0: null [ 1.621888][ T1] kmemleak: Kernel memory leak detector initialized (mem pool available: 11805) [ 1.622224][ T1] page_owner is disabled [ 1.622962][ T1] PM: Magic number: 6:737:589 [ 1.623449][ T1] netconsole: network logging started [ 1.625829][ T1] ALSA device list: [ 1.625992][ T1] No soundcards found. [ 1.626674][ T1] md: Skipping autodetection of RAID arrays. (raid=autodetect will force) [ 1.631051][ T1] VFS: Mounted root (virtiofs filesystem) readonly on device 0:25. [ 1.631894][ T1] devtmpfs: mounted [ 1.632218][ T1] VFS: Pivoted into new rootfs [ 1.664671][ T1] Freeing unused kernel image (initmem) memory: 2624K [ 1.665068][ T1] Write protecting the kernel read-only data: 65536k [ 1.665712][ T1] Freeing unused kernel image (text/rodata gap) memory: 100K [ 1.666233][ T1] Freeing unused kernel image (rodata/data gap) memory: 312K [ 1.667162][ T1] Run /usr/lib/python3.14/site-packages/virtme/guest/bin/virtme-ng-init as init process [ 1.667594][ T1] with arguments: [ 1.667782][ T1] /usr/lib/python3.14/site-packages/virtme/guest/bin/virtme-ng-init [ 1.668157][ T1] with environment: [ 1.668341][ T1] HOME=/ [ 1.668533][ T1] TERM=dumb [ 1.668779][ T1] virtme_hostname=vmksft-net-dbg,debug-threads=on [ 1.669096][ T1] nr_open=2147483584 [ 1.669279][ T1] virtme_link_mods=/srv/vmksft/testing/wt-2/.virtme_mods/lib/modules/0.0.0 [ 1.669692][ T1] virtme_rw_overlay0=/etc [ 1.669947][ T1] virtme_rw_overlay1=/lib [ 1.670194][ T1] virtme_rw_overlay2=/home [ 1.670435][ T1] virtme_rw_overlay3=/opt [ 1.670675][ T1] virtme_rw_overlay4=/srv [ 1.670915][ T1] virtme_rw_overlay5=/usr [ 1.671149][ T1] virtme_rw_overlay6=/var [ 1.671382][ T1] virtme_rw_overlay7=/tmp [ 1.671626][ T1] virtme_console=ttyS0 [ 1.671864][ T1] virtme_chdir=srv/vmksft/testing/wt-2 [ 1.697809][ T1] virtme-ng-init: mount devtmpfs -> /dev: EBUSY: Device or resource busy [ 1.700271][ T1] virtme-ng-init: Setting hostname to vmksft-net-dbg,debug-threads=on... [ 1.712069][ T1] overlayfs: failed to set xattr on upper [ 1.712497][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.712771][ T1] overlayfs: ...falling back to uuid=null. [ 1.715572][ T1] overlayfs: failed to set xattr on upper [ 1.715795][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.716055][ T1] overlayfs: ...falling back to uuid=null. [ 1.718190][ T1] overlayfs: failed to set xattr on upper [ 1.718400][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.718657][ T1] overlayfs: ...falling back to uuid=null. [ 1.720810][ T1] overlayfs: failed to set xattr on upper [ 1.721026][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.721278][ T1] overlayfs: ...falling back to uuid=null. [ 1.724058][ T1] overlayfs: failed to set xattr on upper [ 1.724275][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.724527][ T1] overlayfs: ...falling back to uuid=null. [ 1.726426][ T1] overlayfs: failed to set xattr on upper [ 1.726639][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.726884][ T1] overlayfs: ...falling back to uuid=null. [ 1.729675][ T1] overlayfs: failed to set xattr on upper [ 1.729880][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.730577][ T1] overlayfs: ...falling back to uuid=null. [ 1.732743][ T1] overlayfs: failed to set xattr on upper [ 1.732946][ T1] overlayfs: ...falling back to redirect_dir=nofollow. [ 1.733211][ T1] overlayfs: ...falling back to uuid=null. [ 1.746055][ T1] virtme-ng-init: running systemd-tmpfiles [ 4.215913][ T71] systemd-tmpfile (71) used greatest stack depth: 24592 bytes left [ 4.215937][ T71] BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:322 [ 4.215940][ T71] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 71, name: systemd-tmpfile [ 4.215942][ T71] preempt_count: 2, expected: 0 [ 4.215943][ T71] RCU nest depth: 0, expected: 0 [ 4.215945][ T71] locks held by systemd-tmpfile/71: 5, last CPU#2: [ 4.215947][ T71] #0: ffffffff95e167b8 (low_water_lock){+.+.}-{3:3}, at: do_exit+0x887/0xdc0 [ 4.215962][ T71] #1: ffffffff95f7ddc0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x320/0x3e0 [ 4.215969][ T71] #2: ffffffff95f7de38 (console_srcu){....}-{0:0}, at: console_flush_one_record+0x106/0x710 [ 4.215976][ T71] #3: ffffffff95e9d760 (console_owner){....}-{0:0}, at: console_lock_spinning_enable+0x40/0x60 [ 4.215982][ T71] #4: ffffffff95e9d660 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_emit_next_record+0x1df/0x4c0 [ 4.215988][ T71] irq event stamp: 2273246 [ 4.215990][ T71] hardirqs last enabled at (2273245): [] __down_trylock_console_sem+0x86/0xa0 [ 4.215995][ T71] hardirqs last disabled at (2273246): [] console_emit_next_record+0x3d4/0x4c0 [ 4.215998][ T71] softirqs last enabled at (2272550): [] handle_softirqs+0x67c/0x900 [ 4.216004][ T71] softirqs last disabled at (2271781): [] __irq_exit_rcu+0x145/0x1c0 [ 4.216007][ T71] Preemption disabled at: [ 4.216008][ T71] [<0000000000000000>] 0x0 [ 4.216018][ T71] CPU: 2 UID: 0 PID: 71 Comm: systemd-tmpfile Tainted: G W 7.2.0-virtme #1 PREEMPT(full) [ 4.216023][ T71] Tainted: [W]=WARN [ 4.216024][ T71] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 4.216027][ T71] Call Trace: [ 4.216029][ T71] [ 4.216032][ T71] dump_stack_lvl+0x6f/0xa0 [ 4.216041][ T71] __might_resched.cold+0x1fe/0x2c1 [ 4.216047][ T71] ? perf_trace_sched_switch+0x7c0/0x7c0 [ 4.216053][ T71] ? __kmalloc_noprof+0xdb/0x760 [ 4.216060][ T71] __kmalloc_noprof+0x443/0x760 [ 4.216063][ T71] ? alloc_buf.isra.0+0x4b/0x260 [ 4.216074][ T71] ? do_raw_spin_unlock+0x59/0x250 [ 4.216078][ T71] alloc_buf.isra.0+0x4b/0x260 [ 4.216083][ T71] put_chars+0x1e1/0x2f0 [ 4.216088][ T71] ? __send_to_port+0x420/0x420 [ 4.216090][ T71] ? rcu_lockdep_current_cpu_online+0x3f/0x1b0 [ 4.216095][ T71] ? validate_chain+0x38b/0xc20 [ 4.216105][ T71] hvc_console_print+0x292/0x780 [ 4.216118][ T71] ? hvc_write+0x3a0/0x3a0 [ 4.216122][ T71] ? rcu_is_watching+0x16/0xd0 [ 4.216125][ T71] ? lock_acquire+0x13c/0x160 [ 4.216133][ T71] console_emit_next_record+0x22f/0x4c0 [ 4.216139][ T71] ? devkmsg_read+0x4b0/0x4b0 [ 4.216142][ T71] ? console_flush_one_record+0x106/0x710 [ 4.216148][ T71] ? rcu_is_watching+0x16/0xd0 [ 4.216151][ T71] ? lock_acquire+0x13c/0x160 [ 4.216158][ T71] console_flush_one_record+0x46f/0x710 [ 4.216165][ T71] ? console_emit_next_record+0x4c0/0x4c0 [ 4.216168][ T71] ? __lock_acquire+0x518/0xc20 [ 4.216178][ T71] console_unlock+0xee/0x1f0 [ 4.216183][ T71] ? console_flush_one_record+0x710/0x710 [ 4.216186][ T71] ? rcu_is_watching+0x16/0xd0 [ 4.216189][ T71] ? lock_acquire+0xe0/0x160 [ 4.216195][ T71] ? __down_trylock_console_sem+0x5e/0xa0 [ 4.216198][ T71] ? vprintk_emit+0x320/0x3e0 [ 4.216202][ T71] vprintk_emit+0x37c/0x3e0 [ 4.216205][ T1] virtme-ng-init: Failed to read '/usr/lib/tmpfiles.d/audit.conf': Permission denied [ 4.216205][ T1] Failed to create directory or subvolume "/var/spool/at/spool": Permission denied [ 4.216205][ T1] Failed to create file /var/spool/at/.SEQ: Permission denied [ 4.216205][ T1] Failed to opendir() '/proc/self/fd/6': Permission denied [ 4.216207][ T71] ? wake_up_klogd_work_func+0x90/0x90 [ 4.216212][ T71] ? __lock_acquire+0x518/0xc20 [ 4.216218][ T71] _printk+0xc7/0x100 [ 4.216224][ T71] ? snapshot_read.cold+0x21/0x21 [ 4.216228][ T71] ? do_raw_spin_lock+0x131/0x280 [ 4.216232][ T71] ? __rwlock_init+0x150/0x150 [ 4.216239][ T71] ? do_raw_spin_lock+0x131/0x280 [ 4.216244][ T71] do_exit.cold+0x82/0x9c [ 4.216249][ T71] ? exit_notify+0x890/0x890 [ 4.216252][ T71] ? __lock_release.isra.0+0x69/0x1a0 [ 4.216256][ T71] ? rcu_is_watching+0x16/0xd0 [ 4.216263][ T71] do_group_exit+0xb8/0x370 [ 4.216268][ T71] __x64_sys_exit_group+0x3c/0x50 [ 4.216271][ T71] x64_sys_call+0x1567/0x1570 [ 4.216274][ T71] do_syscall_64+0xff/0x530 [ 4.216279][ T71] ? exc_page_fault+0xee/0x100 [ 4.216284][ T71] entry_SYSCALL_64_after_hwframe+0x4b/0x53 [ 4.216288][ T71] RIP: 0033:0x7f73bf6691b8 [ 4.216291][ T71] Code: Unable to access opcode bytes at 0x7f73bf66918e. [ 4.216293][ T71] RSP: 002b:00007ffedf5e5048 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7 [ 4.216296][ T71] RAX: ffffffffffffffda RBX: 00007f73bf799f88 RCX: 00007f73bf6691b8 [ 4.216298][ T71] RDX: 00007f73beec74c8 RSI: fffffffffffffe90 RDI: 0000000000000049 [ 4.216300][ T71] RBP: 00007ffedf5e50a0 R08: 0000000000000000 R09: 0000000000001000 [ 4.216302][ T71] R10: 00007ffedf5e4e60 R11: 0000000000000246 R12: 0000000000000001 [ 4.216303][ T71] R13: 0000000000000049 R14: 00007f73bf798680 R15: 00007f73bf799fa0 [ 4.216317][ T71] [ 4.234864][ T1] virtme-ng-init: basic initialization done [ 4.285689][ T77] ip (77) used greatest stack depth: 24256 bytes left [ 4.299342][ T73] virtme-ng-init: Starting systemd-udevd version 259.8-1.fc44 [ 4.299766][ T73] virtme-ng-init: triggering udev coldplug [ 7.425149][ T96] nfsrahead (96) used greatest stack depth: 24160 bytes left [ 7.425171][ T96] BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:322 [ 7.425174][ T96] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 96, name: nfsrahead [ 7.425176][ T96] preempt_count: 2, expected: 0 [ 7.425178][ T96] RCU nest depth: 0, expected: 0 [ 7.425179][ T96] locks held by nfsrahead/96: 5, last CPU#3: [ 7.425182][ T96] #0: ffffffff95e167b8 (low_water_lock){+.+.}-{3:3}, at: do_exit+0x887/0xdc0 [ 7.425197][ T96] #1: ffffffff95f7ddc0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x320/0x3e0 [ 7.425205][ T96] #2: ffffffff95f7de38 (console_srcu){....}-{0:0}, at: console_flush_one_record+0x106/0x710 [ 7.425212][ T96] #3: ffffffff95e9d760 (console_owner){....}-{0:0}, at: console_lock_spinning_enable+0x40/0x60 [ 7.425218][ T96] #4: ffffffff95e9d660 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_emit_next_record+0x1df/0x4c0 [ 7.425225][ T96] irq event stamp: 24302 [ 7.425227][ T96] hardirqs last enabled at (24301): [] __down_trylock_console_sem+0x86/0xa0 [ 7.425231][ T96] hardirqs last disabled at (24302): [] console_emit_next_record+0x3d4/0x4c0 [ 7.425234][ T96] softirqs last enabled at (21204): [] unix_release_sock+0x446/0xe60 [ 7.425239][ T96] softirqs last disabled at (21202): [] unix_release_sock+0x39f/0xe60 [ 7.425243][ T96] Preemption disabled at: [ 7.425243][ T96] [<0000000000000000>] 0x0 [ 7.425253][ T96] CPU: 3 UID: 0 PID: 96 Comm: nfsrahead Tainted: G W 7.2.0-virtme #1 PREEMPT(full) [ 7.425257][ T96] Tainted: [W]=WARN [ 7.425259][ T96] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 7.425261][ T96] Call Trace: [ 7.425263][ T96] [ 7.425265][ T96] dump_stack_lvl+0x6f/0xa0 [ 7.425274][ T96] __might_resched.cold+0x1fe/0x2c1 [ 7.425280][ T96] ? perf_trace_sched_switch+0x7c0/0x7c0 [ 7.425286][ T96] ? __kmalloc_noprof+0xdb/0x760 [ 7.425293][ T96] __kmalloc_noprof+0x443/0x760 [ 7.425296][ T96] ? alloc_buf.isra.0+0x4b/0x260 [ 7.425306][ T96] ? do_raw_spin_unlock+0x59/0x250 [ 7.425310][ T96] alloc_buf.isra.0+0x4b/0x260 [ 7.425316][ T96] put_chars+0x1e1/0x2f0 [ 7.425320][ T96] ? __send_to_port+0x420/0x420 [ 7.425322][ T96] ? rcu_lockdep_current_cpu_online+0x3f/0x1b0 [ 7.425328][ T96] ? validate_chain+0x38b/0xc20 [ 7.425338][ T96] hvc_console_print+0x292/0x780 [ 7.425351][ T96] ? hvc_write+0x3a0/0x3a0 [ 7.425355][ T96] ? rcu_is_watching+0x16/0xd0 [ 7.425358][ T96] ? lock_acquire+0x13c/0x160 [ 7.425366][ T96] console_emit_next_record+0x22f/0x4c0 [ 7.425373][ T96] ? devkmsg_read+0x4b0/0x4b0 [ 7.425375][ T96] ? console_flush_one_record+0x106/0x710 [ 7.425381][ T96] ? rcu_is_watching+0x16/0xd0 [ 7.425384][ T96] ? lock_acquire+0x13c/0x160 [ 7.425391][ T96] console_flush_one_record+0x46f/0x710 [ 7.425398][ T96] ? console_emit_next_record+0x4c0/0x4c0 [ 7.425401][ T96] ? __lock_acquire+0x518/0xc20 [ 7.425411][ T96] console_unlock+0xee/0x1f0 [ 7.425416][ T96] ? console_flush_one_record+0x710/0x710 [ 7.425419][ T96] ? rcu_is_watching+0x16/0xd0 [ 7.425422][ T96] ? lock_acquire+0xe0/0x160 [ 7.425434][ T96] ? __down_trylock_console_sem+0x5e/0xa0 [ 7.425437][ T96] ? vprintk_emit+0x320/0x3e0 [ 7.425443][ T96] vprintk_emit+0x37c/0x3e0 [ 7.425448][ T96] ? wake_up_klogd_work_func+0x90/0x90 [ 7.425453][ T96] ? __lock_acquire+0x518/0xc20 [ 7.425460][ T96] _printk+0xc7/0x100 [ 7.425465][ T96] ? snapshot_read.cold+0x21/0x21 [ 7.425470][ T96] ? do_raw_spin_lock+0x131/0x280 [ 7.425474][ T96] ? __rwlock_init+0x150/0x150 [ 7.425481][ T96] ? do_raw_spin_lock+0x131/0x280 [ 7.425486][ T96] do_exit.cold+0x82/0x9c [ 7.425492][ T96] ? exit_notify+0x890/0x890 [ 7.425494][ T96] ? __lock_release.isra.0+0x69/0x1a0 [ 7.425499][ T96] ? rcu_is_watching+0x16/0xd0 [ 7.425506][ T96] do_group_exit+0xb8/0x370 [ 7.425511][ T96] __x64_sys_exit_group+0x3c/0x50 [ 7.425514][ T96] x64_sys_call+0x1567/0x1570 [ 7.425518][ T96] do_syscall_64+0xff/0x530 [ 7.425523][ T96] ? exc_page_fault+0xee/0x100 [ 7.425528][ T96] entry_SYSCALL_64_after_hwframe+0x4b/0x53 [ 7.425532][ T96] RIP: 0033:0x7f7606b8c1b8 [ 7.425536][ T96] Code: Unable to access opcode bytes at 0x7f7606b8c18e. [ 7.425538][ T96] RSP: 002b:00007ffc46b60138 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7 [ 7.425542][ T96] RAX: ffffffffffffffda RBX: 00007f7606cbcf88 RCX: 00007f7606b8c1b8 [ 7.425544][ T96] RDX: 00007f7606978b48 RSI: ffffffffffffffb0 RDI: 00000000ffffffed [ 7.425545][ T96] RBP: 00007ffc46b60190 R08: 0000000000000000 R09: 0000000000000000 [ 7.425547][ T96] R10: 00007ffc46b5ff90 R11: 0000000000000246 R12: 0000000000000001 [ 7.425548][ T96] R13: 00000000ffffffed R14: 00007f7606cbb680 R15: 00007f7606cbcfa0 [ 7.425562][ T96] [ 7.515172][ C0] clocksource: Watchdog remote CPU 1 read timed out [ 7.515269][ C0] [ 7.515271][ C0] ======================================================== [ 7.515273][ C0] WARNING: possible irq lock inversion dependency detected [ 7.515276][ C0] 7.2.0-virtme #1 Tainted: G W [ 7.515278][ C0] -------------------------------------------------------- [ 7.515278][ C0] swapper/0/0 just changed the state of lock: [ 7.515280][ C0] ffffffff95e9d760 (console_owner){..-.}-{0:0}, at: console_lock_spinning_enable+0x40/0x60 [ 7.515296][ C0] but this lock took another, SOFTIRQ-unsafe lock in the past: [ 7.515297][ C0] (fs_reclaim){+.+.}-{0:0} [ 7.515299][ C0] [ 7.515299][ C0] [ 7.515299][ C0] and interrupts could create inverse lock ordering between them. [ 7.515299][ C0] [ 7.515301][ C0] [ 7.515301][ C0] other info that might help us debug this: [ 7.515302][ C0] Possible interrupt unsafe locking scenario: [ 7.515302][ C0] [ 7.515303][ C0] CPU0 CPU1 [ 7.515303][ C0] ---- ---- [ 7.515304][ C0] lock(fs_reclaim); [ 7.515306][ C0] local_irq_disable(); [ 7.515307][ C0] lock(console_owner); [ 7.515309][ C0] lock(fs_reclaim); [ 7.515310][ C0] [ 7.515311][ C0] lock(console_owner); [ 7.515313][ C0] [ 7.515313][ C0] *** DEADLOCK *** [ 7.515313][ C0] [ 7.515313][ C0] locks held by swapper/0/0: 4, last CPU#0: [ 7.515315][ C0] #0: ffa0000000007c90 ((&watchdog_timer)){+.-.}-{0:0}, at: call_timer_fn+0x110/0x4d0 [ 7.515323][ C0] #1: ffffffff95fe29f8 (watchdog_lock){+.-.}-{3:3}, at: clocksource_watchdog+0x15/0x30 [ 7.515329][ C0] #2: ffffffff95f7ddc0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x320/0x3e0 [ 7.515334][ C0] #3: ffffffff95f7de38 (console_srcu){....}-{0:0}, at: console_flush_one_record+0x106/0x710 [ 7.515340][ C0] [ 7.515340][ C0] the shortest dependencies between 2nd lock and 1st lock: [ 7.515346][ C0] -> (fs_reclaim){+.+.}-{0:0} { [ 7.515350][ C0] HARDIRQ-ON-W at: [ 7.515352][ C0] __lock_acquire+0x388/0xc20 [ 7.515356][ C0] lock_acquire.part.0+0xd4/0x280 [ 7.515359][ C0] fs_reclaim_acquire+0xd5/0x120 [ 7.515363][ C0] __kmalloc_cache_noprof+0x6e/0x620 [ 7.515365][ C0] kthread_create_worker_on_node+0xea/0x210 [ 7.515369][ C0] workqueue_init+0x2a/0x680 [ 7.515375][ C0] kernel_init_freeable+0x2fe/0x630 [ 7.515378][ C0] kernel_init+0x21/0x150 [ 7.515383][ C0] ret_from_fork+0x474/0x6b0 [ 7.515387][ C0] ret_from_fork_asm+0x11/0x20 [ 7.515392][ C0] SOFTIRQ-ON-W at: [ 7.515393][ C0] __lock_acquire+0x388/0xc20 [ 7.515395][ C0] lock_acquire.part.0+0xd4/0x280 [ 7.515397][ C0] fs_reclaim_acquire+0xd5/0x120 [ 7.515400][ C0] __kmalloc_cache_noprof+0x6e/0x620 [ 7.515401][ C0] kthread_create_worker_on_node+0xea/0x210 [ 7.515404][ C0] workqueue_init+0x2a/0x680 [ 7.515406][ C0] kernel_init_freeable+0x2fe/0x630 [ 7.515409][ C0] kernel_init+0x21/0x150 [ 7.515411][ C0] ret_from_fork+0x474/0x6b0 [ 7.515413][ C0] ret_from_fork_asm+0x11/0x20 [ 7.515415][ C0] INITIAL USE at: [ 7.515416][ C0] __lock_acquire+0x388/0xc20 [ 7.515419][ C0] lock_acquire.part.0+0xd4/0x280 [ 7.515421][ C0] fs_reclaim_acquire+0xd5/0x120 [ 7.515423][ C0] __kmalloc_cache_noprof+0x6e/0x620 [ 7.515430][ C0] kthread_create_worker_on_node+0xea/0x210 [ 7.515433][ C0] workqueue_init+0x2a/0x680 [ 7.515435][ C0] kernel_init_freeable+0x2fe/0x630 [ 7.515437][ C0] kernel_init+0x21/0x150 [ 7.515440][ C0] ret_from_fork+0x474/0x6b0 [ 7.515442][ C0] ret_from_fork_asm+0x11/0x20 [ 7.515444][ C0] } [ 7.515445][ C0] ... key at: [] __fs_reclaim_map+0x0/0xbe0 [ 7.515450][ C0] ... acquired at: [ 7.515451][ C0] __lock_acquire+0x518/0xc20 [ 7.515453][ C0] lock_acquire.part.0+0xd4/0x280 [ 7.515456][ C0] fs_reclaim_acquire+0xd5/0x120 [ 7.515458][ C0] __kmalloc_noprof+0xd3/0x760 [ 7.515460][ C0] alloc_buf.isra.0+0x4b/0x260 [ 7.515464][ C0] put_chars+0x1e1/0x2f0 [ 7.515466][ C0] hvc_console_print+0x292/0x780 [ 7.515470][ C0] console_emit_next_record+0x22f/0x4c0 [ 7.515473][ C0] console_flush_one_record+0x46f/0x710 [ 7.515475][ C0] console_unlock+0xee/0x1f0 [ 7.515478][ C0] vprintk_emit+0x37c/0x3e0 [ 7.515479][ C0] _printk+0xc7/0x100 [ 7.515483][ C0] loop_init+0x12a/0x130 [ 7.515487][ C0] do_one_initcall+0x124/0x4f0 [ 7.515489][ C0] kernel_init_freeable+0x596/0x630 [ 7.515491][ C0] kernel_init+0x21/0x150 [ 7.515493][ C0] ret_from_fork+0x474/0x6b0 [ 7.515495][ C0] ret_from_fork_asm+0x11/0x20 [ 7.515497][ C0] [ 7.515498][ C0] -> (console_owner){..-.}-{0:0} { [ 7.515501][ C0] IN-SOFTIRQ-W at: [ 7.515503][ C0] __lock_acquire+0x388/0xc20 [ 7.515505][ C0] lock_acquire.part.0+0xd4/0x280 [ 7.515507][ C0] console_lock_spinning_enable+0x5c/0x60 [ 7.515510][ C0] console_emit_next_record+0x1d1/0x4c0 [ 7.515512][ C0] console_flush_one_record+0x46f/0x710 [ 7.515515][ C0] console_unlock+0xee/0x1f0 [ 7.515518][ C0] vprintk_emit+0x37c/0x3e0 [ 7.515520][ C0] _printk+0xc7/0x100 [ 7.515522][ C0] clocksource_watchdog.part.0.cold+0x105/0x1dd [ 7.515526][ C0] call_timer_fn+0x160/0x4d0 [ 7.515529][ C0] __run_timers+0x68f/0xaa0 [ 7.515532][ C0] run_timer_softirq+0xf0/0x160 [ 7.515535][ C0] handle_softirqs+0x1d3/0x900 [ 7.515539][ C0] __irq_exit_rcu+0x145/0x1c0 [ 7.515542][ C0] irq_exit_rcu+0xe/0x30 [ 7.515545][ C0] sysvec_apic_timer_interrupt+0x9d/0xe0 [ 7.515548][ C0] asm_sysvec_apic_timer_interrupt+0x1a/0x20 [ 7.515551][ C0] pv_native_safe_halt+0xf/0x10 [ 7.515554][ C0] default_idle+0x9/0x10 [ 7.515556][ C0] default_idle_call+0x6e/0xb0 [ 7.515559][ C0] cpuidle_idle_call.constprop.0+0x237/0x410 [ 7.515563][ C0] do_idle+0xd8/0x190 [ 7.515565][ C0] cpu_startup_entry+0x53/0x70 [ 7.515568][ C0] rest_init+0x279/0x280 [ 7.515570][ C0] start_kernel+0x3b9/0x3c0 [ 7.515573][ C0] x86_64_start_reservations+0x24/0x30 [ 7.515577][ C0] x86_64_start_kernel+0x12b/0x130 [ 7.515580][ C0] common_startup_64+0x13e/0x148 [ 7.515584][ C0] INITIAL USE at: [ 7.515586][ C0] } [ 7.515587][ C0] ... key at: [] console_owner_dep_map+0x0/0x60 [ 7.515591][ C0] ... acquired at: [ 7.515592][ C0] mark_lock+0x1d7/0xa00 [ 7.515595][ C0] mark_usage+0x42/0x170 [ 7.515597][ C0] __lock_acquire+0x388/0xc20 [ 7.515600][ C0] lock_acquire.part.0+0xd4/0x280 [ 7.515603][ C0] console_lock_spinning_enable+0x5c/0x60 [ 7.515606][ C0] console_emit_next_record+0x1d1/0x4c0 [ 7.515610][ C0] console_flush_one_record+0x46f/0x710 [ 7.515613][ C0] console_unlock+0xee/0x1f0 [ 7.515616][ C0] vprintk_emit+0x37c/0x3e0 [ 7.515618][ C0] _printk+0xc7/0x100 [ 7.515620][ C0] clocksource_watchdog.part.0.cold+0x105/0x1dd [ 7.515623][ C0] call_timer_fn+0x160/0x4d0 [ 7.515626][ C0] __run_timers+0x68f/0xaa0 [ 7.515629][ C0] run_timer_softirq+0xf0/0x160 [ 7.515632][ C0] handle_softirqs+0x1d3/0x900 [ 7.515634][ C0] __irq_exit_rcu+0x145/0x1c0 [ 7.515637][ C0] irq_exit_rcu+0xe/0x30 [ 7.515639][ C0] sysvec_apic_timer_interrupt+0x9d/0xe0 [ 7.515642][ C0] asm_sysvec_apic_timer_interrupt+0x1a/0x20 [ 7.515644][ C0] pv_native_safe_halt+0xf/0x10 [ 7.515646][ C0] default_idle+0x9/0x10 [ 7.515649][ C0] default_idle_call+0x6e/0xb0 [ 7.515651][ C0] cpuidle_idle_call.constprop.0+0x237/0x410 [ 7.515654][ C0] do_idle+0xd8/0x190 [ 7.515656][ C0] cpu_startup_entry+0x53/0x70 [ 7.515658][ C0] rest_init+0x279/0x280 [ 7.515661][ C0] start_kernel+0x3b9/0x3c0 [ 7.515663][ C0] x86_64_start_reservations+0x24/0x30 [ 7.515666][ C0] x86_64_start_kernel+0x12b/0x130 [ 7.515668][ C0] common_startup_64+0x13e/0x148 [ 7.515670][ C0] [ 7.515671][ C0] [ 7.515671][ C0] stack backtrace: [ 7.515675][ C0] CPU: 0 UID: 0 PID: 0 Comm: swapper/0 Tainted: G W 7.2.0-virtme #1 PREEMPT(full) [ 7.515680][ C0] Tainted: [W]=WARN [ 7.515682][ C0] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 7.515684][ C0] Call Trace: [ 7.515686][ C0] [ 7.515688][ C0] dump_stack_lvl+0x6f/0xa0 [ 7.515695][ C0] print_irq_inversion_bug.part.0.cold+0xe6/0x143 [ 7.515699][ C0] mark_lock_irq+0x989/0x9c0 [ 7.515702][ C0] ? add_lock_to_list+0x2c/0x1a0 [ 7.515708][ C0] mark_lock+0x1d7/0xa00 [ 7.515712][ C0] mark_usage+0x42/0x170 [ 7.515715][ C0] __lock_acquire+0x388/0xc20 [ 7.515720][ C0] lock_acquire.part.0+0xd4/0x280 [ 7.515723][ C0] ? console_lock_spinning_enable+0x40/0x60 [ 7.515727][ C0] ? rcu_is_watching+0x16/0xd0 [ 7.515731][ C0] ? lock_acquire+0x13c/0x160 [ 7.515735][ C0] console_lock_spinning_enable+0x5c/0x60 [ 7.515738][ C0] ? console_lock_spinning_enable+0x40/0x60 [ 7.515741][ C0] console_emit_next_record+0x1d1/0x4c0 [ 7.515745][ C0] ? devkmsg_read+0x4b0/0x4b0 [ 7.515748][ C0] ? console_flush_one_record+0x106/0x710 [ 7.515752][ C0] ? rcu_is_watching+0x16/0xd0 [ 7.515755][ C0] ? lock_acquire+0x13c/0x160 [ 7.515759][ C0] console_flush_one_record+0x46f/0x710 [ 7.515763][ C0] ? console_emit_next_record+0x4c0/0x4c0 [ 7.515766][ C0] ? __lock_acquire+0x518/0xc20 [ 7.515771][ C0] console_unlock+0xee/0x1f0 [ 7.515774][ C0] ? console_flush_one_record+0x710/0x710 [ 7.515777][ C0] ? rcu_is_watching+0x16/0xd0 [ 7.515780][ C0] ? lock_acquire+0xe0/0x160 [ 7.515783][ C0] ? __down_trylock_console_sem+0x5e/0xa0 [ 7.515786][ C0] ? vprintk_emit+0x320/0x3e0 [ 7.515789][ C0] vprintk_emit+0x37c/0x3e0 [ 7.515792][ C0] ? wake_up_klogd_work_func+0x90/0x90 [ 7.515796][ C0] ? clocksource_watchdog.part.0+0x450/0x540 [ 7.515800][ C0] _printk+0xc7/0x100 [ 7.515803][ C0] ? snapshot_read.cold+0x21/0x21 [ 7.515806][ C0] ? clocksource_watchdog.part.0+0x450/0x540 [ 7.515809][ C0] ? __lock_release.isra.0+0x69/0x1a0 [ 7.515813][ C0] clocksource_watchdog.part.0.cold+0x105/0x1dd [ 7.515816][ C0] ? clocksource_watchdog.part.0+0x540/0x540 [ 7.515819][ C0] ? clocksource_watchdog.part.0+0x540/0x540 [ 7.515822][ C0] call_timer_fn+0x160/0x4d0 [ 7.515826][ C0] ? detach_if_pending+0x1d0/0x1d0 [ 7.515828][ C0] ? debug_object_active_state+0x430/0x430 [ 7.515832][ C0] ? find_held_lock+0x2b/0x80 [ 7.515835][ C0] ? __lock_release.isra.0+0x69/0x1a0 [ 7.515838][ C0] ? rcu_is_watching+0x16/0xd0 [ 7.515842][ C0] __run_timers+0x68f/0xaa0 [ 7.515844][ C0] ? clocksource_watchdog.part.0+0x540/0x540 [ 7.515849][ C0] ? __bpf_trace_itimer_expire+0x10/0x10 [ 7.515851][ C0] ? __lock_acquire+0x518/0xc20 [ 7.515857][ C0] ? __rwlock_init+0x150/0x150 [ 7.515861][ C0] run_timer_softirq+0xf0/0x160 [ 7.515865][ C0] ? __run_timers+0xaa0/0xaa0 [ 7.515868][ C0] ? trace_irq_enable.constprop.0+0x9b/0x160 [ 7.515872][ C0] ? rcu_is_watching+0x16/0xd0 [ 7.515875][ C0] handle_softirqs+0x1d3/0x900 [ 7.515878][ C0] ? __lock_release.isra.0+0x69/0x1a0 [ 7.515881][ C0] ? _local_bh_enable+0xc0/0xc0 [ 7.515885][ C0] __irq_exit_rcu+0x145/0x1c0 [ 7.515888][ C0] irq_exit_rcu+0xe/0x30 [ 7.515890][ C0] sysvec_apic_timer_interrupt+0x9d/0xe0 [ 7.515893][ C0] [ 7.515894][ C0] [ 7.515895][ C0] ? lockdep_hardirqs_on_prepare.part.0+0x9a/0x160 [ 7.515898][ C0] asm_sysvec_apic_timer_interrupt+0x1a/0x20 [ 7.515901][ C0] RIP: 0010:pv_native_safe_halt+0xf/0x10 [ 7.515905][ C0] Code: 48 8b 3d 94 82 68 02 e8 1f 00 00 00 48 2b 05 58 d3 a0 00 c3 0f 1f 80 00 00 00 00 f3 0f 1e fa eb 07 0f 00 2d 13 06 0e 00 fb f4 0f 1f 40 d6 48 83 ec 20 8b 17 49 89 f8 83 e2 fe 41 89 d2 0f 01 [ 7.515907][ C0] RSP: 0018:ffffffff95c07cf8 EFLAGS: 00000296 [ 7.515910][ C0] RAX: 0000000000021c0f RBX: ffffffff95c30600 RCX: ffffffff92306247 [ 7.515912][ C0] RDX: ffffffff95c30600 RSI: ffffffff95511011 RDI: ffffffff94e949e0 [ 7.515914][ C0] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 7.515915][ C0] R10: 0000000000000000 R11: 0000000000000001 R12: 1ffffffff2b80fa2 [ 7.515917][ C0] R13: 0000000000000000 R14: dffffc0000000000 R15: 0000000000014770 [ 7.515920][ C0] ? cpuidle_idle_call.constprop.0+0x237/0x410 [ 7.515924][ C0] ? lockdep_hardirqs_on+0x91/0x130 [ 7.515926][ C0] default_idle+0x9/0x10 [ 7.515929][ C0] default_idle_call+0x6e/0xb0 [ 7.515931][ C0] cpuidle_idle_call.constprop.0+0x237/0x410 [ 7.515934][ C0] ? arch_cpu_idle_exit+0x40/0x40 [ 7.515937][ C0] ? mark_tsc_async_resets+0x30/0x30 [ 7.515941][ C0] ? rcu_is_watching+0x16/0xd0 [ 7.515944][ C0] do_idle+0xd8/0x190 [ 7.515947][ C0] cpu_startup_entry+0x53/0x70 [ 7.515949][ C0] rest_init+0x279/0x280 [ 7.515952][ C0] ? __cpuidle_text_end+0x3b/0x3b [ 7.515957][ C0] ? rest_init+0x280/0x280 [ 7.515960][ C0] ? acpi_hw_set_mode+0x4a0/0x4a0 [ 7.515965][ C0] ? cpus_read_unlock+0x4f/0xc0 [ 7.515968][ C0] ? acpi_enable+0x1e4/0x330 [ 7.515972][ C0] start_kernel+0x3b9/0x3c0 [ 7.515975][ C0] x86_64_start_reservations+0x24/0x30 [ 7.515977][ C0] x86_64_start_kernel+0x12b/0x130 [ 7.515980][ C0] common_startup_64+0x13e/0x148 [ 7.515986][ C0] [ 7.676610][ T73] virtme-ng-init: waiting for udev to settle [ 7.930425][ T73] virtme-ng-init: udev is done [ 7.933129][ T1] virtme-ng-init: initialization done