6.1.28 kernel trace on 5.15.0-0-rc3

[gkamathh]

On fedora-35 with self-built kernel-5.15.0-0-rc3 from rawhide. 5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64

I downloaded and installed latest rpmfusion koji build for Virtualbox 6.1.28 . ​https://koji.rpmfusion.org/koji/packageinfo?packageID=260 I did akmod build of kmod. During boot I get the following dmesg kernel trace. After logging in, using virtualbox-manager, can't start vbox VMs, also gives another kernel trace Its possible that even though Virtualbox says in its release notes for 6.1.28 includes 5.15, it might not as kernel-5.15 is still in rc and will be released in december. Still, it would be good to see this work as early as possible.

Info included below

• rpms installed on fedora-35
• dmesg_op_on_boot.txt Kernel trace on vboxdrv load on boot
• dmesg_op_on_start.txt Kernel trace on attempting to start a vbox vm
• vbox_manager_log.txt Log from VirtualBox Manager failed vm start

[root@sirius gana]# rpm -qa | grep -Ei "kernel-5.15|VirtualBox" |sort
akmod-VirtualBox-6.1.28-1.fc35.x86_64
kernel-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
kmod-VirtualBox-5.13.19-200.fc34.x86_64-6.1.28-1.fc35.x86_64
kmod-VirtualBox-5.14.9-300.fc35.x86_64-6.1.28-1.fc35.x86_64
kmod-VirtualBox-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64-6.1.28-1.fc35.x86_64
kmod-VirtualBox-6.1.28-1.fc35.x86_64
VirtualBox-6.1.28-1.fc35.x86_64
virtualbox-guest-additions-6.1.26-1.fc35.x86_64
VirtualBox-kmodsrc-6.1.28-1.fc35.noarch
VirtualBox-server-6.1.28-1.fc35.x86_64

dmesg_op_on_boot.txt

	== dmesg op on boot
[   19.750473] vboxdrv: loading out-of-tree module taints kernel.
[   19.761501] vboxdrv: Found 8 processor cores
[   19.789709] vboxdrv: TSC mode is Invariant, tentative frequency 2394436401 Hz
[   19.789717] vboxdrv: Successfully loaded version 6.1.28_rpmfusion r147628 (interface 0x00320000)
[   19.796985] ------------[ cut here ]------------
[   19.796991] WARNING: CPU: 7 PID: 1182 at kernel/smp.c:876 smp_call_function_many_cond+0x1c7/0x3c0
[   19.797004] Modules linked in: vboxdrv(O) ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw iptable_security ip_set nf_tables nfnetlink ip6table_filter ip6_tables iptable_filter qrtr ns bnep sunrpc vfat fat ntfs3 intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp at24 iTCO_wdt intel_pmc_bxt mei_hdcp iTCO_vendor_support kvm_intel kvm irqbypass rapl intel_cstate intel_uncore snd_ctl_led snd_hda_codec_idt snd_hda_codec_generic ledtrig_audio pcspkr snd_hda_codec_hdmi iwlmvm snd_hda_intel uvcvideo mac80211 snd_intel_dspcfg videobuf2_vmalloc btusb snd_intel_sdw_acpi hp_wmi sparse_keymap btrtl libarc4 joydev videobuf2_memops snd_hda_codec btbcm platform_profile btintel videobuf2_v4l2 videobuf2_common bluetooth snd_seq videodev iwlwifi wmi_bmof snd_seq_device snd_hda_core i2c_i801 mc snd_hwdep ecdh_generic i2c_smbus snd_pcm cfg80211 snd_timer lpc_ich mei_me snd rfkill
[   19.797214]  mei soundcore hp_accel wireless_hotkey lis3lv02d zram ip_tables rtsx_pci_sdmmc mmc_core nouveau crct10dif_pclmul i915 crc32_pclmul drm_ttm_helper crc32c_intel ghash_clmulni_intel mxm_wmi i2c_algo_bit ttm drm_kms_helper serio_raw cec r8169 drm rtsx_pci wmi video hid_multitouch ipmi_devintf ipmi_msghandler fuse
[   19.797290] CPU: 7 PID: 1182 Comm: iprt-VBoxTscThr Tainted: G           O     --------- ---  5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64 #1
[   19.797295] Hardware name: Hewlett-Packard HP ENVY TS 17 Notebook PC/1966, BIOS F.70 10/20/2017
[   19.797299] RIP: 0010:smp_call_function_many_cond+0x1c7/0x3c0
[   19.797306] Code: ff ff 0f 0b e9 c8 fe ff ff 65 8b 05 63 bb e5 50 a9 ff ff ff 7f 0f 85 8e fe ff ff 65 8b 05 dd c7 e5 50 85 c0 0f 84 7f fe ff ff <0f> 0b 44 3b 35 74 e1 0b 02 0f 82 7d fe ff ff 0f 0b e9 76 fe ff ff
[   19.797310] RSP: 0018:ffffbe3dc23f7d28 EFLAGS: 00010202
[   19.797315] RAX: 0000000000000001 RBX: ffffffffc151ba50 RCX: 0000000000000001
[   19.797319] RDX: ffffbe3dc23f7db0 RSI: 0000000000000001 RDI: ffff99b3c84d7410
[   19.797323] RBP: ffffbe3dc23f7e08 R08: 0000000000000000 R09: ffff99b3c84d7410
[   19.797326] R10: ffffffffaf78170b R11: 0000000000000000 R12: 0000000000000000
[   19.797330] R13: ffffbe3dc23f7db0 R14: 0000000000000007 R15: 0000000000000000
[   19.797333] FS:  0000000000000000(0000) GS:ffff99b70f200000(0000) knlGS:0000000000000000
[   19.797337] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   19.797341] CR2: 0000561641f38cf8 CR3: 0000000109056002 CR4: 00000000001706e0
[   19.797346] Call Trace:
[   19.797352]  ? rtmpLinuxWrapper+0x30/0x30 [vboxdrv]
[   19.797395]  ? supdrvTscMeasureDeltaCallbackUnwrapped.isra.0+0xa70/0xa70 [vboxdrv]
[   19.797425]  VBoxHost_RTMpOnPair+0x147/0x230 [vboxdrv]
[   19.797456]  ? supdrvTscMeasureDeltaCallbackUnwrapped.isra.0+0xa70/0xa70 [vboxdrv]
[   19.797494]  supdrvTscMeasureDeltaOne+0x3b6/0x450 [vboxdrv]
[   19.797519]  ? destroy_timer_on_stack+0x20/0x20
[   19.797536]  supdrvTscDeltaThread+0x3ad/0x5e0 [vboxdrv]
[   19.797567]  ? VBoxHost_RTThreadSleepNoLog+0x40/0x40 [vboxdrv]
[   19.797601]  rtThreadMain+0x3e/0x90 [vboxdrv]
[   19.797631]  rtThreadNativeMain+0x1b/0x20 [vboxdrv]
[   19.797660]  kthread+0x149/0x170
[   19.797666]  ? set_kthread_struct+0x40/0x40
[   19.797686]  ret_from_fork+0x22/0x30
[   19.797716] irq event stamp: 965
[   19.797719] hardirqs last  enabled at (971): [<ffffffffaf172980>] __up_console_sem+0x60/0x70
[   19.797726] hardirqs last disabled at (976): [<ffffffffaf172965>] __up_console_sem+0x45/0x70
[   19.797731] softirqs last  enabled at (0): [<ffffffffaf0e22a2>] copy_process+0x7e2/0x1fe0
[   19.797739] softirqs last disabled at (0): [<0000000000000000>] 0x0
[   19.797744] ---[ end trace 9a75e80b54325f72 ]---
[   19.852286] VBoxNetFlt: Successfully started.
[   19.878033] VBoxNetAdp: Successfully started.
[   21.425883] powercap intel-rapl:0: package locked by BIOS, monitoring only
[   24.086465] systemd-udevd (662) used greatest stack depth: 11200 bytes left
[   25.432027] intel_powerclamp: Start idle injection to reduce power

[   25.432945] ======================================================
[   25.433792] WARNING: possible circular locking dependency detected
[   25.434639] 5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64 #1 Tainted: G        W  O     --------- ---
[   25.435521] ------------------------------------------------------
[   25.436403] thermald/1071 is trying to acquire lock:
[   25.437274] ffffffffb0e6cd40 (cpu_hotplug_lock){++++}-{0:0}, at: powerclamp_set_cur_state.cold+0x17/0xb5 [intel_powerclamp]
[   25.438199]
               but task is already holding lock:
[   25.440013] ffff99b43d21ee38 (&cdev->lock){+.+.}-{3:3}, at: cur_state_store+0x48/0xb0
[   25.440943]
               which lock already depends on the new lock.

[   25.443691]
               the existing dependency chain (in reverse order) is:
[   25.445519]
               -> #3 (&cdev->lock){+.+.}-{3:3}:
[   25.447340]        __mutex_lock+0x92/0x8c0
[   25.448257]        thermal_zone_bind_cooling_device+0x307/0x450
[   25.449185]        acpi_thermal_cooling_device_cb+0xc7/0x1e0
[   25.450118]        thermal_zone_device_register+0x644/0x6c0
[   25.451056]        acpi_thermal_add+0x2ee/0x4c0
[   25.451996]        acpi_device_probe+0x47/0x160
[   25.452932]        really_probe+0x1f5/0x3f0
[   25.453867]        __driver_probe_device+0xfe/0x180
[   25.454798]        driver_probe_device+0x1e/0x90
[   25.455724]        __driver_attach+0xc4/0x1d0
[   25.456631]        bus_for_each_dev+0x67/0x90
[   25.457555]        bus_add_driver+0x12e/0x1f0
[   25.458465]        driver_register+0x8f/0xe0
[   25.459347]        acpi_thermal_init+0x5e/0x82
[   25.460228]        do_one_initcall+0x67/0x320
[   25.461106]        kernel_init_freeable+0x27d/0x2c9
[   25.461985]        kernel_init+0x16/0x120
[   25.462850]        ret_from_fork+0x22/0x30
[   25.463719]
               -> #2 (&tz->lock){+.+.}-{3:3}:
[   25.465446]        __mutex_lock+0x92/0x8c0
[   25.466300]        thermal_zone_device_update+0x28/0x4c0
[   25.467138]        thermal_zone_device_register+0x67b/0x6c0
[   25.467979]        pkg_thermal_cpu_online+0x204/0x2d0 [x86_pkg_temp_thermal]
[   25.468830]        cpuhp_invoke_callback+0x141/0x390
[   25.469709]        cpuhp_thread_fun+0xd6/0x1e0
[   25.470576]        smpboot_thread_fn+0xf2/0x1d0
[   25.471447]        kthread+0x149/0x170
[   25.472307]        ret_from_fork+0x22/0x30
[   25.473167]
               -> #1 (cpuhp_state-up){+.+.}-{0:0}:
[   25.474870]        cpuhp_thread_fun+0x90/0x1e0
[   25.475726]        smpboot_thread_fn+0xf2/0x1d0
[   25.476624]        kthread+0x149/0x170
[   25.477514]        ret_from_fork+0x22/0x30
[   25.478403]
               -> #0 (cpu_hotplug_lock){++++}-{0:0}:
[   25.480153]        __lock_acquire+0x11fe/0x1e00
[   25.481041]        lock_acquire+0xc4/0x2e0
[   25.481922]        cpus_read_lock+0x3e/0xb0
[   25.482803]        powerclamp_set_cur_state.cold+0x17/0xb5 [intel_powerclamp]
[   25.483708]        cur_state_store+0x5f/0xb0
[   25.484602]        kernfs_fop_write_iter+0x134/0x1d0
[   25.485491]        new_sync_write+0x10e/0x190
[   25.486380]        vfs_write+0x27a/0x390
[   25.487266]        ksys_write+0x58/0xd0
[   25.488143]        do_syscall_64+0x3b/0x90
[   25.489021]        entry_SYSCALL_64_after_hwframe+0x44/0xae
[   25.489892]
               other info that might help us debug this:

[   25.492401] Chain exists of:
                 cpu_hotplug_lock --> &tz->lock --> &cdev->lock

[   25.494817]  Possible unsafe locking scenario:

[   25.496369]        CPU0                    CPU1
[   25.497112]        ----                    ----
[   25.497846]   lock(&cdev->lock);
[   25.498566]                                lock(&tz->lock);
[   25.499286]                                lock(&cdev->lock);
[   25.499999]   lock(cpu_hotplug_lock);
[   25.500703]
                *** DEADLOCK ***

[   25.502787] 5 locks held by thermald/1071:
[   25.503481]  #0: ffff99b427b50100 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x4d/0x60
[   25.504203]  #1: ffff99b3c5619498 (sb_writers#4){.+.+}-{0:0}, at: ksys_write+0x58/0xd0
[   25.504931]  #2: ffff99b406555290 (&of->mutex){+.+.}-{3:3}, at: kernfs_fop_write_iter+0x100/0x1d0
[   25.505668]  #3: ffff99b4278ea8f8 (kn->active#184){.+.+}-{0:0}, at: kernfs_fop_write_iter+0x108/0x1d0
[   25.506417]  #4: ffff99b43d21ee38 (&cdev->lock){+.+.}-{3:3}, at: cur_state_store+0x48/0xb0
[   25.507169]
               stack backtrace:
[   25.508654] CPU: 7 PID: 1071 Comm: thermald Tainted: G        W  O     --------- ---  5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64 #1
[   25.509451] Hardware name: Hewlett-Packard HP ENVY TS 17 Notebook PC/1966, BIOS F.70 10/20/2017
[   25.510278] Call Trace:
[   25.511112]  dump_stack_lvl+0x57/0x72
[   25.511952]  check_noncircular+0xdf/0x100
[   25.512792]  __lock_acquire+0x11fe/0x1e00
[   25.513634]  lock_acquire+0xc4/0x2e0
[   25.514470]  ? powerclamp_set_cur_state.cold+0x17/0xb5 [intel_powerclamp]
[   25.515325]  ? lock_is_held_type+0xa7/0x120
[   25.516181]  cpus_read_lock+0x3e/0xb0
[   25.517038]  ? powerclamp_set_cur_state.cold+0x17/0xb5 [intel_powerclamp]
[   25.517915]  powerclamp_set_cur_state.cold+0x17/0xb5 [intel_powerclamp]
[   25.518801]  cur_state_store+0x5f/0xb0
[   25.519686]  kernfs_fop_write_iter+0x134/0x1d0
[   25.520574]  new_sync_write+0x10e/0x190
[   25.521458]  vfs_write+0x27a/0x390
[   25.522347]  ksys_write+0x58/0xd0
[   25.523232]  do_syscall_64+0x3b/0x90
[   25.524100]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   25.524980] RIP: 0033:0x7f2b815e58ef
[   25.525851] Code: 89 54 24 18 48 89 74 24 10 89 7c 24 08 e8 29 88 f8 ff 48 8b 54 24 18 48 8b 74 24 10 41 89 c0 8b 7c 24 08 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 44 24 08 e8 6c 88 f8 ff 48
[   25.526822] RSP: 002b:00007f2b737ba5b0 EFLAGS: 00000293 ORIG_RAX: 0000000000000001
[   25.527810] RAX: ffffffffffffffda RBX: 00005557fd10ce90 RCX: 00007f2b815e58ef
[   25.528806] RDX: 0000000000000001 RSI: 00007f2b737ba650 RDI: 0000000000000009
[   25.529808] RBP: 0000000000000009 R08: 0000000000000000 R09: 00007f2b6c0015f0
[   25.530813] R10: 0000000000000000 R11: 0000000000000293 R12: 00007f2b737ba640
[   25.531811] R13: 00005557fd10cea0 R14: 00007f2b737ba680 R15: 00007f2b737ba640
[   26.391799] NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #80!!!
[   26.392874] NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #80!!!
[   26.393910] NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #80!!!
[   26.394936] NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #80!!!
[   26.395935] NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #80!!!
[   26.396930] NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #80!!!

dmesg_op_on_vmstart.txt

== Kernel trace on attempting to start a vbox vm

[ 2614.761830] SUPR0GipMap: fGetGipCpu=0x1b
[ 2615.808846] BUG: kernel NULL pointer dereference, address: 0000000000000000
[ 2615.808854] #PF: supervisor read access in kernel mode
[ 2615.808856] #PF: error_code(0x0000) - not-present page
[ 2615.808858] PGD 80000003ad370067 P4D 80000003ad370067 PUD 378fa6067 PMD 0
[ 2615.808865] Oops: 0000 [#1] SMP PTI
[ 2615.808868] CPU: 1 PID: 4868 Comm: EMT Tainted: G        W  O     --------- ---  5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64 #1
[ 2615.808870] Hardware name: Hewlett-Packard HP ENVY TS 17 Notebook PC/1966, BIOS F.70 10/20/2017
[ 2615.808872] RIP: 0010:do_raw_spin_trylock+0x5/0x40
[ 2615.808878] Code: c6 94 57 5f b0 48 89 ef e8 c8 fe ff ff eb a9 89 c6 48 89 ef e8 cc f4 ff ff 66 90 eb a9 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 <8b> 07 85 c0 75 28 ba 01 00 00 00 f0 0f b1 17 75 1d 65 8b 05 eb b6
[ 2615.808880] RSP: 0018:ffffbe3dc3de3d00 EFLAGS: 00010282
[ 2615.808882] RAX: 0000000000000001 RBX: ffffbe3dc3de3de8 RCX: 0000000000000000
[ 2615.808883] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[ 2615.808885] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000000
[ 2615.808886] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000018
[ 2615.808887] R13: 0000000000000001 R14: ffffbe3dc7b41000 R15: ffff99b3c01f41e8
[ 2615.808889] FS:  00007fd68ac4e640(0000) GS:ffff99b70e600000(0000) knlGS:0000000000000000
[ 2615.808891] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2615.808893] CR2: 0000000000000000 CR3: 0000000378f24005 CR4: 00000000001706e0
[ 2615.808894] Call Trace:
[ 2615.808896]  _raw_spin_lock+0x39/0x80
[ 2615.808900]  ? __apply_to_page_range+0x6c9/0x870
[ 2615.808905]  __apply_to_page_range+0x6c9/0x870
[ 2615.808909]  ? rtR0MemObjLinuxConvertProt+0xd0/0xd0 [vboxdrv]
[ 2615.808935]  rtR0MemObjNativeProtect+0x65/0x90 [vboxdrv]
[ 2615.808951]  VBoxHost_RTR0MemObjProtect+0x86/0xc0 [vboxdrv]
[ 2615.808964]  supdrvIOCtl+0x3192/0x36f0 [vboxdrv]
[ 2615.808977]  VBoxDrvLinuxIOCtl_6_1_28+0x11e/0x220 [vboxdrv]
[ 2615.808988]  __x64_sys_ioctl+0x82/0xb0
[ 2615.808993]  do_syscall_64+0x3b/0x90
[ 2615.808996]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 2615.808999] RIP: 0033:0x7fd6d23b537b
[ 2615.809002] Code: ff ff ff 85 c0 79 9b 49 c7 c4 ff ff ff ff 5b 5d 4c 89 e0 41 5c c3 66 0f 1f 84 00 00 00 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 7d 2a 0f 00 f7 d8 64 89 01 48
[ 2615.809003] RSP: 002b:00007fd68ac4cbd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 2615.809005] RAX: ffffffffffffffda RBX: 00007fd68a768010 RCX: 00007fd6d23b537b
[ 2615.809007] RDX: 00007fd68a768010 RSI: 0000000000005684 RDI: 0000000000000007
[ 2615.809008] RBP: 00007fd68ac4cbe0 R08: 0000000000000000 R09: 0000000000000000
[ 2615.809009] R10: 00007fd6d22029a0 R11: 0000000000000246 R12: 00007fd6ab7424df
[ 2615.809011] R13: 00007fd68ac4d040 R14: 00007fd68ac4cd40 R15: 0000000000000000
[ 2615.809014] Modules linked in: uinput rfcomm snd_seq_dummy snd_hrtimer xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp bridge stp llc nft_objref nf_conntrack_netbios_ns nf_conntrack_broadcast nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct vboxnetadp(O) vboxnetflt(O) nft_chain_nat vboxdrv(O) ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw iptable_security ip_set nf_tables nfnetlink ip6table_filter ip6_tables iptable_filter qrtr ns bnep sunrpc vfat fat ntfs3 intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp at24 iTCO_wdt intel_pmc_bxt mei_hdcp iTCO_vendor_support kvm_intel kvm irqbypass rapl intel_cstate intel_uncore snd_ctl_led snd_hda_codec_idt snd_hda_codec_generic ledtrig_audio pcspkr snd_hda_codec_hdmi iwlmvm snd_hda_intel uvcvideo mac80211 snd_intel_dspcfg
[ 2615.809060]  videobuf2_vmalloc btusb snd_intel_sdw_acpi hp_wmi sparse_keymap btrtl libarc4 joydev videobuf2_memops snd_hda_codec btbcm platform_profile btintel videobuf2_v4l2 videobuf2_common bluetooth snd_seq videodev iwlwifi wmi_bmof snd_seq_device snd_hda_core i2c_i801 mc snd_hwdep ecdh_generic i2c_smbus snd_pcm cfg80211 snd_timer lpc_ich mei_me snd rfkill mei soundcore hp_accel wireless_hotkey lis3lv02d zram ip_tables rtsx_pci_sdmmc mmc_core nouveau crct10dif_pclmul i915 crc32_pclmul drm_ttm_helper crc32c_intel ghash_clmulni_intel mxm_wmi i2c_algo_bit ttm drm_kms_helper serio_raw cec r8169 drm rtsx_pci wmi video hid_multitouch ipmi_devintf ipmi_msghandler fuse
[ 2615.809099] CR2: 0000000000000000
[ 2615.809101] ---[ end trace 9a75e80b54325f73 ]---
[ 2615.809102] RIP: 0010:do_raw_spin_trylock+0x5/0x40
[ 2615.809106] Code: c6 94 57 5f b0 48 89 ef e8 c8 fe ff ff eb a9 89 c6 48 89 ef e8 cc f4 ff ff 66 90 eb a9 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 <8b> 07 85 c0 75 28 ba 01 00 00 00 f0 0f b1 17 75 1d 65 8b 05 eb b6
[ 2615.809108] RSP: 0018:ffffbe3dc3de3d00 EFLAGS: 00010282
[ 2615.809110] RAX: 0000000000000001 RBX: ffffbe3dc3de3de8 RCX: 0000000000000000
[ 2615.809111] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[ 2615.809113] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000000
[ 2615.809114] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000018
[ 2615.809115] R13: 0000000000000001 R14: ffffbe3dc7b41000 R15: ffff99b3c01f41e8
[ 2615.809116] FS:  00007fd68ac4e640(0000) GS:ffff99b70e600000(0000) knlGS:0000000000000000
[ 2615.809118] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2615.809119] CR2: 0000000000000000 CR3: 0000000378f24005 CR4: 00000000001706e0
[ 2615.809121] note: EMT[4868] exited with preempt_count 1
[ 2615.809123] BUG: sleeping function called from invalid context at include/linux/percpu-rwsem.h:49
[ 2615.809124] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 4868, name: EMT
[ 2615.809126] INFO: lockdep is turned off.
[ 2615.809127] irq event stamp: 0
[ 2615.809128] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[ 2615.809130] hardirqs last disabled at (0): [<ffffffffaf0e22a2>] copy_process+0x7e2/0x1fe0
[ 2615.809134] softirqs last  enabled at (0): [<ffffffffaf0e22a2>] copy_process+0x7e2/0x1fe0
[ 2615.809137] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 2615.809138] CPU: 1 PID: 4868 Comm: EMT Tainted: G      D W  O     --------- ---  5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64 #1
[ 2615.809140] Hardware name: Hewlett-Packard HP ENVY TS 17 Notebook PC/1966, BIOS F.70 10/20/2017
[ 2615.809142] Call Trace:
[ 2615.809143]  dump_stack_lvl+0x57/0x72
[ 2615.809147]  ___might_sleep.cold+0xb6/0xc6
[ 2615.809151]  exit_signals+0x1c/0x2d0
[ 2615.809155]  do_exit+0xba/0xc00
[ 2615.809157]  ? __x64_sys_ioctl+0x82/0xb0
[ 2615.809161]  rewind_stack_do_exit+0x17/0x20
[ 2615.809166] RIP: 0033:0x7fd6d23b537b
[ 2615.809167] Code: ff ff ff 85 c0 79 9b 49 c7 c4 ff ff ff ff 5b 5d 4c 89 e0 41 5c c3 66 0f 1f 84 00 00 00 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 7d 2a 0f 00 f7 d8 64 89 01 48
[ 2615.809169] RSP: 002b:00007fd68ac4cbd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 2615.809171] RAX: ffffffffffffffda RBX: 00007fd68a768010 RCX: 00007fd6d23b537b
[ 2615.809172] RDX: 00007fd68a768010 RSI: 0000000000005684 RDI: 0000000000000007
[ 2615.809173] RBP: 00007fd68ac4cbe0 R08: 0000000000000000 R09: 0000000000000000
[ 2615.809175] R10: 00007fd6d22029a0 R11: 0000000000000246 R12: 00007fd6ab7424df
[ 2615.809176] R13: 00007fd68ac4d040 R14: 00007fd68ac4cd40 R15: 0000000000000000

vboxmanager log

The VM session was aborted.


Result Code: 
NS_ERROR_FAILURE (0x80004005)
Component: 
SessionMachine
Interface: 
ISession {c0447716-ff5a-4795-b57a-ecd5fffa18a4}


00:00:00.999384 VirtualBox VM 6.1.28_rpmfusion r147628 linux.amd64 (Oct 20 2021 00:00:00) release log
00:00:00.999386 Log opened 2021-10-22T15:51:22.418377000Z
00:00:00.999387 Build Type: release
00:00:00.999390 OS Product: Linux
00:00:00.999391 OS Release: 5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
00:00:00.999393 OS Version: #1 SMP Fri Oct 15 15:21:42 IST 2021
00:00:00.999429 DMI Product Name: HP ENVY TS 17 Notebook PC
00:00:00.999446 DMI Product Version: 097E110000405E00000620100
00:00:00.999455 Firmware type: UEFI
00:00:01.000420 Secure Boot: Enabled
00:00:01.000494 Host RAM: 15886MB (15.5GB) total, 12664MB (12.3GB) available
00:00:01.000499 Executable: /usr/lib64/virtualbox/VirtualBoxVM
00:00:01.000500 Process ID: 4901
00:00:01.000500 Package type: LINUX_64BITS_GENERIC (OSE)
00:00:01.010401 Installed Extension Packs:
00:00:01.010428   None installed!
00:00:01.011816 Console: Machine state changed to 'Starting'
00:00:01.012181 Qt version: 5.15.2
00:00:01.012201 X11 Window Manager code: 2
00:00:01.023547 SUP: seg #0: R   0x00000000 LB 0x0004d000
00:00:01.023579 SUP: seg #1: R X 0x0004d000 LB 0x0011a000
00:00:01.023591 SUP: seg #2: R   0x00167000 LB 0x00060000
00:00:01.023601 SUP: seg #3: RW  0x001c7000 LB 0x000350a0
00:00:01.023959 GUI: UIMediumEnumerator: Medium-enumeration finished!
00:00:01.027343 X Server details: vendor: The X.Org Foundation, release: 12101002, protocol version: 11.0, display string: :0
00:00:01.027373 Using known keycode mapping for keycode to scan code conversion
00:00:01.030671 GUI: UIDesktopWidgetWatchdog::sltHandleHostScreenAvailableGeometryCalculated: Screen 0 work area is actually resized to: 0x32 x 1920x1048
00:04:45.134014 VirtualBoxClient: detected unresponsive VBoxSVC (rc=NS_ERROR_CALL_FAILED)
00:05:05.310617 GUI: Request to power VM off due to VBoxSVC is unavailable.
00:05:05.310651 GUI: Passing request to power VM off from machine-logic to UI session.
00:05:05.310664 GUI: Powering VM down on UI session power off request...
00:05:05.310683 ERROR [COM]: aRC=VBOX_E_INVALID_VM_STATE (0x80bb0002) aIID={872da645-4a9b-1727-bee2-5585105b9eed} aComponent={ConsoleWrap} aText={Invalid machine state: Starting (must be Running, Paused or Stuck)}, preserve=false aResultDetail=0

[galitsyn]

Hi gkamathh,

It looks you are running debug kernel on a host side. Do you see the issue if you disable Lock Debugging in kernel config?

[sergiomb]

Good tip , maybe

dnf install kernel-devel-$(uname -r)   
dnf remove kernel-debug-devel
akmods-shutdown

​https://rpmfusion.org/Howto/VirtualBox#I_had_install_kernel-debug-devel_but_I_need_kernel-devel

[gkamathh]

Thankyou to galitsyn, sergiomb. I read sergiomb-s howto link after rebuilding. That was very informative.

yup, it was because it was an non-release RC-kernel and I build using rpmbuild from the kernel rpm-src file. The SPEC file for the rpm-build process has options enabled by default for compiling with all debugs. Perhaps the howto should also mention the unexpectedness that the rpmbuild of RC kernels will have debugs enabled via the SPEC file.

Additionally, if vboxdrv while loading after detecting lock-acquisition failure could possibly also give human readable hint that it won't load with kernel config lock debugging enabled, or link to a url with known possible causes.

more specifically, it might have been one of CONFIG_DEBUG_LOCK_ALLOC=y CONFIG_DEBUG_SPINLOCK=y

Virtualbox starts and boots now !! Sorry for filing non-bug, thanks for the help.

I will try close this issue; please do so if I can't.

vboxdrv still finding some unknown debug symbols pertaining to locks. But, I am happy as Virtualbox is working. It will probably smoothen out and go away when a 5.15.0 release kernel comes out.

== first disabled integrated debug kernel by changing in rpmbuild SPEC file rpmbuild/SPECS/kernel.spec

# Set debugbuildsenabled to 1 to build separate base and debug kernels
#  (on supported architectures). The kernel-debug-* subpackages will
#  contain the debug kernel.
# Set debugbuildsenabled to 0 to not build a separate debug kernel, but
#  to build the base kernel using the debug configuration. (Specifying
#  the --with-release option overrides this setting.)
%define debugbuildsenabled 1

# then re-compiled kernel with
[gana@sirius ~]$ date ; rpmbuild -ba ~/rpmbuild/SPECS/kernel.spec --nodebuginfo --target=x86_64 --without debug ; date

== kernel-config on a previously built RC kernel
[gana@sirius ~]$ cat boot_kern1_config-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64 | grep -E DEBUG | grep -E "[^B]LOCK"
CONFIG_DM_DEBUG_BLOCK_MANAGER_LOCKING=y
CONFIG_LOCK_DEBUGGING_SUPPORT=y
CONFIG_DEBUG_SPINLOCK=y
CONFIG_DEBUG_LOCK_ALLOC=y
# CONFIG_DEBUG_LOCKDEP is not set
# CONFIG_DEBUG_LOCKING_API_SELFTESTS is not set
# CONFIG_CSD_LOCK_WAIT_DEBUG is not set

== kernel-config on a regular fedora release kernel 
[gana@sirius ~]$ cat /boot/config-5.14.9-300.fc35.x86_64 | grep DEBUG | grep -E "[^B]LOCK"
CONFIG_DM_DEBUG_BLOCK_MANAGER_LOCKING=y
CONFIG_LOCK_DEBUGGING_SUPPORT=y
# CONFIG_DEBUG_SPINLOCK is not set
# CONFIG_DEBUG_LOCK_ALLOC is not set
# CONFIG_DEBUG_LOCKING_API_SELFTESTS is not set
# CONFIG_CSD_LOCK_WAIT_DEBUG is not set

== kernel-config on the freshly built fedora RC kernel 
[gana@sirius ~]$ cat /boot/config-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64 | grepDEBUG | grep -E "[^B]LOCK"
CONFIG_DM_DEBUG_BLOCK_MANAGER_LOCKING=y
CONFIG_LOCK_DEBUGGING_SUPPORT=y
# CONFIG_DEBUG_SPINLOCK is not set
# CONFIG_DEBUG_LOCK_ALLOC is not set
# CONFIG_DEBUG_LOCKING_API_SELFTESTS is not set
# CONFIG_CSD_LOCK_WAIT_DEBUG is not set

== on kernel boot
[  236.717250] vboxdrv: Unknown symbol trace_hardirqs_off (err -2)
[  236.717303] vboxdrv: Unknown symbol __raw_spin_lock_init (err -2)
[  236.717321] vboxdrv: Unknown symbol lockdep_init_map_type (err -2)
[  236.717343] vboxdrv: Unknown symbol _raw_spin_unlock_irq (err -2)
[  236.717367] vboxdrv: Unknown symbol __init_work (err -2)
[  236.717384] vboxdrv: Unknown symbol trace_hardirqs_on (err -2)
[  236.717409] vboxdrv: Unknown symbol _raw_spin_unlock (err -2)
[  236.783661] vboxdrv: Unknown symbol trace_hardirqs_off (err -2)
[  236.783716] vboxdrv: Unknown symbol __raw_spin_lock_init (err -2)
[  236.783737] vboxdrv: Unknown symbol lockdep_init_map_type (err -2)
[  236.783759] vboxdrv: Unknown symbol _raw_spin_unlock_irq (err -2)
[  236.783784] vboxdrv: Unknown symbol __init_work (err -2)
[  236.783800] vboxdrv: Unknown symbol trace_hardirqs_on (err -2)
[  236.783826] vboxdrv: Unknown symbol _raw_spin_unlock (err -2)
[  236.848900] vboxdrv: Unknown symbol trace_hardirqs_off (err -2)
[  236.848955] vboxdrv: Unknown symbol __raw_spin_lock_init (err -2)
[  236.848975] vboxdrv: Unknown symbol lockdep_init_map_type (err -2)
[  236.848996] vboxdrv: Unknown symbol _raw_spin_unlock_irq (err -2)
[  236.849020] vboxdrv: Unknown symbol __init_work (err -2)
[  236.849036] vboxdrv: Unknown symbol trace_hardirqs_on (err -2)
[  236.849062] vboxdrv: Unknown symbol _raw_spin_unlock (err -2)
[  359.192711] vboxdrv: Found 8 processor cores
[  359.209043] vboxdrv: TSC mode is Invariant, tentative frequency 2394433569 Hz
[  359.209045] vboxdrv: Successfully loaded version 6.1.28_rpmfusion r147628 (interface 0x00320000)
[  359.218200] VBoxNetAdp: Successfully started.
[  359.235565] VBoxNetFlt: Successfully started.

== on vm load
[ 1058.788438] vboxdrv: 000000006ca43b5a VMMR0.r0
[ 1058.870175] vboxdrv: 00000000005a9619 VBoxDDR0.r0 

== rpms 
[gana@sirius ~]$ rpm -qa | egrep -i "5.15.0|VirtualBox" | sort
akmod-VirtualBox-6.1.28-1.fc35.x86_64
kernel-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
kernel-core-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
kernel-devel-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
kernel-modules-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
kernel-modules-extra-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
kernel-modules-internal-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64
kmod-VirtualBox-5.13.19-200.fc34.x86_64-6.1.28-1.fc35.x86_64
kmod-VirtualBox-5.14.9-300.fc35.x86_64-6.1.28-1.fc35.x86_64
kmod-VirtualBox-5.15.0-0.rc3.20211001git4de593fb965f.30.fc35.x86_64-6.1.28-1.fc35.x86_64
kmod-VirtualBox-6.1.28-1.fc35.x86_64
VirtualBox-6.1.28-1.fc35.x86_64
virtualbox-guest-additions-6.1.26-1.fc35.x86_64
VirtualBox-kmodsrc-6.1.28-1.fc35.noarch
VirtualBox-server-6.1.28-1.fc35.x86_64