Hyper-V 虚拟交换机异常导致 WSL2 启动故障的调试

 

2024/8/30,是一个看似平常的周五下午。Windowd Update 告诉我安装了几个无关痛痒的小更新,考虑到已经快两个月没有重启电脑了,我就顺手点了重启。万万没想到,这是一个长达 25 小时的噩梦的开始。

TL;DR:Hyper-V 虚拟交换机的未知异常导致虚拟机无法正常枚举 PCI 设备,因此 WSL2 无法启动。解决方法是从注册表中删除虚拟所有交换机并重启。

问题起源

我的工作站是两年前配的 13900K + NVMe,当然重启很快,然而 WSL 却没一直能起来,表现为 Windows Terminal 里面什么都没有。我本以为又是常见的抽风(不在少数),打算运行 wsl --shutdown 重启,但发现 wsl.exe 除了 --help 之外的命令,都无法任何响应。检查任务管理器,可以看到 WSL2 对应的虚拟机进程 vmmemWSL 也并没有占用 CPU,wslservice.exe 看起来也没什么异常。

此时的我还没有意识到问题的严重性,觉得一定是此前安装的更新搞出来什么问题了———虽说描述里面完全没提到 WSL,但总是有可能的。我去 Windows Update 面板中卸载了最近的几个更新,再次重启,问题依旧。

这下坏了!无法使用 WSL 会给我带来很多麻烦,包括失去趁手的工作环境,以及暂时无法连接部分远程服务器(里面有部分)。没办法,只能硬着头皮开始调试问题。当然,第一步是把我的 ext4.vhdx 先复制出来,以免任何操作让我不慎再丢失数据,那就没有修复的意义了。调试这个问题的一大障碍是,一旦 WSL 启动并卡住,此时很难让它恢复到可用的状态,连注销用户都不行。我一开始的应对措施是重启,但几次之后就感觉厌烦,这总不是个办法。经过多次尝试,发现其实需要杀掉 wsl{,relay,service}.exe 就能强制关闭 WSL2 虚拟机,得以降低了一些时间成本。如果需要的话,也可以用下面的方法直接杀死 Hyper-V 中的虚拟机(但还是需要结束 wslservice.exe):

hcsdiag.exe --list :: 找到名为 WSL 的虚拟机的 GUID 并复制
hcsdiag.exe --kill <WSL_GUID>

暗影重重

我此前在 .wslconfig 里面增加了不少选项,包括使用了自己编译的内核、(曾经)更换过网络模式、虚拟交换机,还打开了 autoMemoryReclaimsparseVhd 等实验性选项。为了排除这些因素,我先直接把所有的配置都注释掉了,但问题还在。我也按照群友的指示关闭了 swap,同样无效。

接下来,我多次以不同的组合、顺序尝试了以下步骤,都没有效果:

  • 检查系统文件损坏(dism /online /cleanup-image /restorehealth);
  • 卸载、重新安装不同版本的 WSL2;
  • 在 Windows 功能中关闭 HyperV、重启,再开启(这一步实际上不会有什么效果,毕竟 Windows 11 本质已经被虚拟化了);
  • 使用 Windows 的重新安装功能,进行原地系统重新安装(其实是升级);

我用多种关键词在 WSL 的 GitHub issue 上进行了搜索,但并没有得到太多结果。我也尝试使用 collect-wsl-logs.ps1 捕获了一些日志,但也没有获得太多有用的信息。

在阅读文档的过程中,我得知 .wslconfig 中可以添加 debugConsole = true,这样任何 WSL 实例启动时,都会弹出窗口显示内核的 dmesg。我因此观察到,无论我进行上面描述的任何改动,其实都没有影响 WSL 的行为。在每一次卡死前,内核其实都已经快启动完了,大约日志如下:

[    1.030360] scsi 0:0:0:0: Direct-Access     Msft     Virtual Disk     1.0  PQ: 0 ANSI: 5
[    1.031463] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.032009] sd 0:0:0:0: [sda] 701248 512-byte logical blocks: (359 MB/342 MiB)
[    1.032571] sd 0:0:0:0: [sda] Write Protect is on
[    1.032892] sd 0:0:0:0: [sda] Mode Sense: 0f 00 80 00
[    1.033382] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    1.349348] sd 0:0:0:0: [sda] Attached SCSI disk
[    1.769105] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x36abb407964, max_idle_ns: 881590690723 ns
[    1.770729] clocksource: Switched to clocksource tsc
[   49.589968] hv_balloon: Max. dynamic memory size: 32638 MB
[  600.869082] EXT4-fs(sda): mounted filesystem without journal. Quota mode: none.
DnsTunellingManager::DnsTurnellingManager - using DNS server IP 10.255.255.254
DnsServer::StartUdpDnsServer - successfully started UDP server on IP 10.255.255.254
DnsServer::StartTcpDnsServer - successfully started TCP server on IP 10.255.255.254
GNS: Processing Next Message 
[ 1200.870985] mini_init(324): drop_caches:1
GNS: Received empty message, exiting
GnsEngine exiting 
[ 1800.894620] WSL(1): Process 326 exited
[ 1800.895013] WSL(1): Process 329 exited
[ 1800.895402] WSL(1): Process 333 exited
[ 1801.029756] kvm: exiting hardware virtualization
[ 1801.032633] ACPI: PM: Preparing to enter system sleep state S5
[ 1801.033425] reboot: Power down
?????????????

也就是说,硬盘 /dev/sda 已经检测完了,此时因为某些不明原因,内核停滞了很久,大概十分钟后才挂上了 root;但大概半小时后,由于某些原因内核被关闭了(大概是 wslservice.exe 的超时机制)。最后的 ?????????????wslservice.exe 在观察到虚拟机关闭后打印的字符串,可能是某位微软工程师上班时心情不佳留下的吧。但不管怎么说,能打印这么多日志,说明了 WSL 内部的 Linux 大概率应该是比较正常的,问题应该出在 Windows 本身或者与 WSL 交互的部分。

在拿这些日志咨询群友之后,群友告诉了我一个比较重要的信息:此时还是 WSL 的 system distro 正在启动,还没有进入到 user distro 的阶段(WSL 具体的引导流程可以看杰哥好文:WSL2 内部实现探究)。此时的进程都来自于 system distro,我们看到的 /dev/sda 也是 system distro 对应的 system.vhd

据此,我又进行了以下的尝试:

  • 更换多个版本的内核,包括不同的 WSL 官方内核(5.5 / 5.15 / 6.6),以及自己根据 WSL2-Linux-Kernel 编译的版本(特此感谢付主席火线救急,在我没有 Linux 环境的情况下帮忙编译了一个内核)。
  • 禁用 WSLg,以跳过部分 system distro 的初始化过程。
  • 更换来自不同版本的 system distro 镜像(感谢 saffah 从他的电脑里面掏了一个出来)。
  • (由于我的 CPU 是 13900K)更新 BIOS 到最新版本,并切换到了最新的 Intel Default Settings。

当然,这些都没有奏效。继续查阅文档,我还发现了 wsl.exe --debug-shell 这一选项。而只有在 system distro 挂上 /dev/sda 后(也就是打开 WSL 十分钟后),通过此命令才能成功得到内部的一个 root shell。但我在里面探索了一会,并没有看出什么问题:没有卡住或者异常高占用率的进程,没有任何 IO 占用异常。但 WSL 此时就是不愿意往下走,继续启动更多的程序、挂载 user distro(理应是 /dev/sdb)。

或许读者会觉得上面的调试过程并不复杂,但事实上,墙上的时钟已经从周五下午四点走到了周六下午快五点。我当然还是正常地吃饭睡觉,但无法运行 WSL 的每一分钟都意味着我的其他工作在往后堆积。我文字中简单的“尝试”可能对应现实中的若干次反复,还有因为记忆不清或者控制变量不全,没有参考意义的重复。我也并不总是有章法地调试,有时候也会闭眼祈祷,希望好运能眷顾我,问题能自己解决——当然是不可能的。

有那么几个瞬间,我真的想推倒整个 Windows 全部重来。这当然一定能解决问题,but at what cost?

云开月明

就在我以为我的八月要以 WSL 的损坏而惨淡收场时,想到了最后一招:是的,对拍,就是 OI 选手最喜欢的对拍(但我并不是)。我找 saffah 要来了他的 WSL 的启动日志,和他换上相同版本的内核,再次观察。在去除了大量相同的内容后,立刻,我注意到他的日志在紧接 sda 检测后的部分:

[    1.041648] hv_pci 14970e84-64c1-49ca-abe6-6b047af9d8bc: PCI VMBus probing: Using version 0x10003
[    1.043796] hv_pci 14970e84-64c1-49ca-abe6-6b047af9d8bc: PCI host bridge to bus 64c1:00
[    1.044246] pci_bus 64c1:00: root bus resource [mem 0xc00000000-0xe00001fff window]
[    1.045335] pci 64c1:00:00.0: [1af4:105a] type 00 class 0x088000
[    1.047635] pci 64c1:00:00.0: reg 0x10: [mem 0xe00000000-0xe00000fff 64bit]
[    1.049840] pci 64c1:00:00.0: reg 0x18: [mem 0xe00001000-0xe00001fff 64bit]
[    1.051919] pci 64c1:00:00.0: reg 0x20: [mem 0xc00000000-0xdffffffff 64bit]
[    1.056181] pci 64c1:00:00.0: BAR 4: assigned [mem 0xc00000000-0xdffffffff 64bit]
[    1.058292] pci 64c1:00:00.0: BAR 0: assigned [mem 0xe00000000-0xe00000fff 64bit]
[    1.060896] pci 64c1:00:00.0: BAR 2: assigned [mem 0xe00001000-0xe00001fff 64bit]
[    1.073023] virtiofs virtio1: Cache len: 0x200000000 @ 0xc00000000
[    1.143491] memmap_init_zone_device initialised 2097152 pages in 20ms
...
[    1.929134] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
...
[    2.369264] scsi 0:0:0:1: Direct-Access     Msft     Virtual Disk     1.0  PQ: 0 ANSI: 5
[    2.370584] sd 0:0:0:1: Attached scsi generic sg1 type 0
[    2.371115] sd 0:0:0:1: [sdb] 536870912 512-byte logical blocks: (275 GB/256 GiB)
[    2.371625] sd 0:0:0:1: [sdb] 4096-byte physical blocks
[    2.372017] sd 0:0:0:1: [sdb] Write Protect is off
[    2.372317] sd 0:0:0:1: [sdb] Mode Sense: 0f 00 00 00
[    2.372730] sd 0:0:0:1: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    2.375018] sd 0:0:0:1: [sdb] Attached SCSI disk

也就是说,WSL 内核很可能卡在 PCI 设备的枚举上了。根据 1af4:105a 进行查询(或者根据下面的 module 名称),可以看到这是 VirtIO FS 的驱动,应当是提供 Windows 和 WSL 之间的文件共享的设施。而如果枚举设备卡住,说明至少 Hyper-V 的设备模拟出现了某些问题,而且很可能和网络或者文件系统相关。

众所周知,WSL 是一个不在 Hyper-V 管理器中显示的隐藏虚拟机。但无论如何我打开了 Hyper-V 的管理控制台,希望获得一些运气。不看不要紧,一看就发现 Hyper-V 的表现也很奇怪:虚拟交换机管理器打开就卡住无法显示内容,创建虚拟机会卡在第一步,而与网络相关的任何 PowerShell 命令也一样会卡住(如 Get-VSwitch, Get-VMNetworkAdapter),很明显不正常。

为了验证,我在 .wslconfig 中增加了 networking = none,意味着完全不使用网络。在此配置下,WSL 奇迹般地没有再卡住了,而是进入了正常的系统(当然没有网卡)。此时的 dmesg 中并没有上面日志中这个 hv_pci 模块的枚举。因此至少从表象上,我已经能断定是此设备的枚举导致的问题。

我在 Windows 的事件日志中对所有的 Hyper-V 相关事件进行了快速筛选和观察,发现 Hyper-V-VmSwitch 中有相当多可疑的日志,比如:

Hyper-V Warning Event

同样通过对比,得知正常的系统中确实会有 OID_GEN_STATISTICS 相关的警告,但这个 IOCTL_XXX 看起来非常可疑。报告“完成时间过长”确实也符合我遇到的各种东西卡住的问题。

考虑到我已经重新开关过 Hyper-V 功能,而我此前创建的 VSwitch 和对应的网卡显然还残留着。我认为大概率就是这些设施导致了问题,但并没有相应公开的资料说明如何清理。有群友推荐我运行 winsock reset,但我觉得有些过于粗暴了。无论如何,我作为一个二十年的 Windows 老用户,魔改系统的胆量还是有一些的:

  • 虚拟网卡:在设备管理器中卸载对应的设备;
  • VSwitch:在注册表中一通搜索,找到了 HKLM\SYSTEM\CurrentControlSet\Services\vmsmp\parameters\SwitchList,备份后直接清空;

接下来就是:重启系统,改回 netwoking = nat,运行 wsl——立刻,日志没有再停下,我熟悉的 Debian 又回来了。Hyper-V 也为自己创建了新的 Default Switch 和 WSL Switch,除了此前的部分网络配置丢失了外,使用上并没有什么区别。但这还重要吗?

根因分析

不知道。

写在最后

写到这里,打开看了一眼股票软件。MSFT 在股价之外,确实也给我带来了一些更大的惊喜。

Microsoft Loves Linux