Ease debugging Xen issues

[marmarek]

On laptops lacking physical serial console, collecting logs of a crashed Xen (or dom0 kernel) is hard. One method is to use kexec to extract them from the RAM. Currently this requires several non-trivial changes to the system. This issue is to ease preparing system for such debugging.

Details from the original issue:

Isn't there tweaks that can be added from boot command line which would make logs saved synchronously and permit to troubleshoot this for everyone without a need of external additional devices @marmarek?

Sadly, not. When Xen panic, dom0 has no chance to execute anything anymore. And it's dom0 who writes logs to the disk (or anything else for that matter).

@marmarek @fepitre
From this comment:

As for collecting logs, I do have a method for that, but it's quite adventurous - make Xen kexec Linux on panic, to dump the memory content, and then to extract logs from there. It requires custom rebuilding Xen (because we have kexec disabled by default), kexec-tools (because the one in Fedora isn't built with Xen), build initramfs that dump the memory (kdump package helps with that, but requires few tweaks to make it work), and finally have some place to save the dump too - if using the main disk, you need to configure LUKS with a key file + allocate quite a lot of RAM for the crashkernel (because of memory-hard Argon2i in LUKS2). When having the dump, extracting messages is relatively easy - I use strings for that. Theoretically the crash utility can do that more conveniently, but it didn't work for me.

This exact QubesOS 4.1 ISO deployment (debug iso with all above dependencies preconfigured) would help to debug so many corner cases for QubesOS project, including this one? Instruct a willing tester to install QubesOS on spare drive and report results without having to go through the burden of customizing such testing testbed? Should that be discussed in a separate issue (with more details on doing this manual and then automate the process, maybe?)

if using the main disk, you need to configure LUKS with a key file + allocate quite a lot of RAM for the crashkernel (because of memory-hard Argon2i in LUKS2)

@marmarek / @fepitre : Random thought, but if there is enough space affected to /boot in the default partitition scheme of that debug iso, dumping said logs from kexec'ed linux kernel to dump memory under /boot would work around a lot of the complexity added dumping needed logs and go faster into having what logs we need, easily, from an additioanl boot of said debug ISO in Read Only rescue mode from boot options.

Originally posted by @tlaurion in #6066 (comment)

[tlaurion]

It was discussed briefly off issue that a debug ISO would miss the point, where having a different xen-debug source tree, clearly differentiable from the Xen standard target, would make it easier to maintain and deploy from testing repository when needed.

That Xen + linux emergency kernel to be kexec'ed + kexec dependencies for dom0 should make its way into a grub clearly separated entree for users to select and as wished end result, be able to extract needed information from the memory dump (saved under /boot? which was why I talked about a debug ISO at the first place, so that /boot is big enough to dump memory content? Saved under swap? As Marek stated, having the emergency kernel dump into root would require LUKS key to be passed, which in most user cases is not possible.)

Thoughts on better approaches?

[fepitre]

I'm inclined to help into this and maybe a specific ISO_FLAVOR could be weekly built.

[DemiMarie]

Dumping into /boot has the obvious problem that it is unencrypted. Could some form of asymmetric encryption be used?

[marmarek]

I'd rather embed LUKS key into the initramfs that is loaded to be kexec'ed. Such initramfs would be sensitive then, so storing it in /boot is out of the question. Not sure what's better:

• inject LUKS key at the load time
• store it somewhere within dom0 encrypted root (/root? /var/lib/something?)

Since Argon used by LUKS2 needs more RAM than its useful to assign for the crash kernel (*), I consider injecting the actual LUKS master key. This may need some initramfs adjustments.

Alternative option is to dump into some USB stick. But that's way less reliable (especially if kexec'ed Linux won't undo IOMMU setup done by Xen).

(*) This memory needs to be reserved at the boot time, and cannot be used for anything else - if you need 1.5GB for the crash kernel, you'd have that much less for the actual system.

[DemiMarie]

• inject LUKS key at the load time

This definitely seems like the better option. Having the key be in a file on disk risks it leaking, which would be bad. I would much prefer for it to remain entirely in-memory.

[marmarek]

If neither the thunderbolt nor expresscard are available and the machine is recent enough to have one or more M.2 slots, and you don't mind sessions with the laptop case off (or potentially ribbon cables dangling out of the case), there's this clever solution. After all, an M.2 device is just a pcie device:

https://www.ebay.com/itm/4-Port-RS-232-DB9-Serial-M-2-B-M-Key-2280-Controller-Card-Asix99100-Chipset-/274780227172?mkcid=16&mkevt=1&_trksid=p2349624.m46890.l6249&mkrid=711-127632-2357-0

Excellent idea @brendanhoar! After few tweaks and hitting unrelated bug, I got this working :) Debugging suspend issues should be much easier (for me, at least) now.

[marmarek]

I consider injecting the actual LUKS master key.

I wanted to extract the master key from the running kernel, but this is actually impossible on R4.1, because cryptsetup loads it into kernel keyring as a "logon" key - which can be read only by the kernel. I mean, technically there surely is some hack to extract it, but not a proper API. This means, we either need to store a keyfile somewhere on the disk, or ask the user for disk passphrase the second time during boot (or more precisely: when loading crash kernel).

[DemiMarie]

I consider injecting the actual LUKS master key.

I wanted to extract the master key from the running kernel, but this is actually impossible on R4.1, because cryptsetup loads it into kernel keyring as a "logon" key - which can be read only by the kernel. I mean, technically there surely is some hack to extract it, but not a proper API. This means, we either need to store a keyfile somewhere on the disk, or ask the user for disk passphrase the second time during boot (or more precisely: when loading crash kernel).

Patch cryptsetup?

[marmarek]

Patch cryptsetup?

No, I don't want to weaken security feature for everyone, just to make debugging easier for few.
I'd rather consider saving keyfile somewhere on the root fs - which would affect only those who opt-in for debug setup.

[DemiMarie]

Patch cryptsetup?

No, I don't want to weaken security feature for everyone, just to make debugging easier for few.
I'd rather consider saving keyfile somewhere on the root fs - which would affect only those who opt-in for debug setup.

Serious question: how is this security feature useful in Qubes OS? Once someone has code exec in dom0 it is game over anyway.

[marmarek]

Since QubesOS/qubes-vmm-xen#138 is merged, here is how to use it to get Xen's console:

0. Your system needs to support "xHCI Debug Capability". The easiest way to check is to look for /sys/bus/pci/devices/*/dbc file in sys-usb, if it's there and says "disabled", it's okay.
1. You need a second computer with USB3 controller. This second computer doesn't need debug capability. Raspberry Pi 4 is enough (and probably clones that have USB3 too).
2. Get a USB3 cable with "A" plug on both ends - for example https://www.datapro.net/products/usb-3-0-super-speed-a-a-debugging-cable.html or https://www.amazon.com/EXLUWOR-Windbg-Super-Speed-Debugging-windbg/dp/B08XYXZ4PG
3. If that's a generic A-A cable (not specifically "debug" cable), tape over VBUS, D+ and D- connectors on one end (see https://pinoutguide.com/Slots/usb_3_0_connector_pinout.shtml for example)
4. Plug the cable to both computers.
5. Add dbgp=xhci,share=yes console=vga,xhci to Xen's cmdline (either in grub menu directly - the line with multiboot2 /xen-*.gz, or in /etc/default/grub in GRUB_CMDLINE_XEN_DEFAULT option). If your system have multiple USB3 controllers, you may need to specify it explicitly - for example dbgp=xhci@pci00:14.0,share=yes console=vga,xhci - see lspci command.
6. Restart the system
7. Look for /dev/ttyUSB0 on the second computer - it should appear when Xen starts.
8. Get console output by picocom -b 115200 /dev/ttyUSB0 (or similar program - minicom, cutecom or even cat works).

[3hhh]

So if I understand share=yes correctly, the device can even be assigned to sys-usb at the same time? That's awesome!

Too bad that my T530 apparently has no dbc/debug port... -_-

[DemiMarie]

So if I understand share=yes correctly, the device can even be assigned to sys-usb at the same time? That's awesome!

It can be, but doing so allows sys-usb to take control of the system.

[3hhh]

On 10/31/22 09:07, Demi Marie Obenour wrote: > So if I understand `share=yes` correctly, the device can even be assigned to `sys-usb` at the same time? That's awesome! It can be, but doing so allows `sys-usb` to take control of the system.

Ok, so a dedicated dom0 USB device/port is more optimal after all...

[3hhh]

Btw is serial port debugging still supported and will it remain supported?

I'm asking because I don't see CONFIG_SERIAL_8250_CONSOLE here or anywhere else and those Express Card UART adapters for Thinkpads aren't too cheap to try either... (40-60 EUR)

[marmarek]

So if I understand share=yes correctly, the device can even be assigned to sys-usb at the same time? That's awesome!

As Demi noted, this has some risks associated. If you want, you can use share=no, in which case only Xen will have access to the controller (and sys-usb will likely fail to start). Or you can use share=hwdom (or no share option at all), in which case dom0 will have access to the controller and not sys-usb (but if you use sys-usb, then dom0 avoids touching the controller anyway).

Btw is serial port debugging still supported and will it remain supported?

Yes. But it's increasingly hard to have an actual serial port in a laptop.

I'm asking because I don't see CONFIG_SERIAL_8250_CONSOLE here or anywhere else and those Express Card UART adapters for Thinkpads aren't too cheap to try either... (40-60 EUR)

I think you're confusing Linux config with Xen config.

[3hhh]

I got dom0 kernel logs via UART running by adding GRUB_CMDLINE_LINUX="$GRUB_CMDLINE_LINUX console=ttyUSB0,115200" to /etc/default/grub.

Do these include the Xen logs?

The Xen instructions didn't work for me (I tried GRUB_CMDLINE_XEN_DEFAULT="$GRUB_CMDLINE_XEN_DEFAULT console=com1 com1=115200,8n1 loglvl=all guest_loglvl=all"). I fear it's because the PCI Express Card apparently is a USB hub which just runs the RS232 port as USB client which Xen doesn't support, but the Linux kernel does. Of course such details aren't documented by the Express Card manufacturer...

[brendanhoar]

Yeah the pci card/expresscard needs to be a real UART serial port, not a usb port + usb serial device.

Even then I think @marmarek ran into some issues getting Xen to use a real one, IIRC.

B

[biergaizi]

Even then I think @marmarek ran into some issues getting Xen to use a real one, IIRC.

Help! I'm trying to debug a Xen crash using a PCIe-to-serial adapter, but I'm unable to activate it in Xen. I tried passing com1=115200,8n1,pci console=com1,vga to Xen, but the serial port has no output. On the next boot, Dom0's Linux kernel still takes over the serial port (which I assume means that Xen itself didn't detect the port). I also tried passing com1=115200,8n1,pci,port-bdf=23:00.0 or com1=115200,8n1,d000,120, but it didn't do anything either.

Is there anything else I can do to enable this port? Or does it mean that this serial port is incompatible due to missing hardware quirks, and cannot be used?

This PCIe adapter shows up in Dom0 as:

23:00.0 Serial controller: Asix Electronics Corporation AX99100 PCIe to Multi I/O Controller (prog-if 02 [16550])
        Subsystem: Asix Electronics Corporation (Wrong ID) Serial Port
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx+
        Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0, Cache Line Size: 64 bytes
        Interrupt: pin A routed to IRQ 120
        Region 0: I/O ports at d000 [size=8]
        Region 1: Memory at fc501000 (32-bit, non-prefetchable) [size=4K]
        Region 5: Memory at fc500000 (32-bit, non-prefetchable) [size=4K]
        Capabilities: [50] MSI: Enable+ Count=1/8 Maskable- 64bit+
                Address: 00000000fee00000  Data: 4000
        Capabilities: [78] Power Management version 3
                Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=375mA PME(D0+,D1+,D2+,D3hot+,D3cold+)
                Status: D0 NoSoftRst+ PME-Enable- DSel=0 DScale=0 PME-
        Capabilities: [80] Express (v2) Legacy Endpoint, MSI 00
                DevCap: MaxPayload 512 bytes, PhantFunc 0, Latency L0s <1us, L1 <2us
                        ExtTag- AttnBtn- AttnInd- PwrInd- RBE+ FLReset-
                DevCtl: CorrErr- NonFatalErr- FatalErr- UnsupReq-
                        RlxdOrd+ ExtTag- PhantFunc- AuxPwr- NoSnoop+
                        MaxPayload 128 bytes, MaxReadReq 512 bytes
                DevSta: CorrErr- NonFatalErr- FatalErr- UnsupReq- AuxPwr+ TransPend-
                LnkCap: Port #1, Speed 2.5GT/s, Width x1, ASPM L0s, Exit Latency L0s unlimited
                        ClockPM+ Surprise- LLActRep- BwNot- ASPMOptComp-
                LnkCtl: ASPM Disabled; RCB 64 bytes, Disabled- CommClk+
                        ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
                LnkSta: Speed 2.5GT/s, Width x1
                        TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
                DevCap2: Completion Timeout: Not Supported, TimeoutDis- NROPrPrP- LTR-
                         10BitTagComp- 10BitTagReq- OBFF Not Supported, ExtFmt- EETLPPrefix-
                         EmergencyPowerReduction Not Supported, EmergencyPowerReductionInit-
                         FRS-
                         AtomicOpsCap: 32bit- 64bit- 128bitCAS-
                DevCtl2: Completion Timeout: 50us to 50ms, TimeoutDis- LTR- 10BitTagReq- OBFF Disabled,
                         AtomicOpsCtl: ReqEn-
                LnkCtl2: Target Link Speed: 2.5GT/s, EnterCompliance- SpeedDis-
                         Transmit Margin: Normal Operating Range, EnterModifiedCompliance- ComplianceSOS-
                         Compliance Preset/De-emphasis: -6dB de-emphasis, 0dB preshoot
                LnkSta2: Current De-emphasis Level: -3.5dB, EqualizationComplete- EqualizationPhase1-
                         EqualizationPhase2- EqualizationPhase3- LinkEqualizationRequest-
                         Retimer- 2Retimers- CrosslinkRes: unsupported
        Capabilities: [100 v1] Virtual Channel
                Caps:   LPEVC=0 RefClk=100ns PATEntryBits=1
                Arb:    Fixed- WRR32- WRR64- WRR128-
                Ctrl:   ArbSelect=Fixed
                Status: InProgress-
                VC0:    Caps:   PATOffset=00 MaxTimeSlots=1 RejSnoopTrans-
                        Arb:    Fixed- WRR32- WRR64- WRR128- TWRR128- WRR256-
                        Ctrl:   Enable+ ID=0 ArbSelect=Fixed TC/VC=01
                        Status: NegoPending- InProgress-
        Capabilities: [800 v1] Advanced Error Reporting
                UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
                UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
                UESvrt: DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
                CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr-
                CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr+
                AERCap: First Error Pointer: 00, ECRCGenCap- ECRCGenEn- ECRCChkCap- ECRCChkEn-
                        MultHdrRecCap- MultHdrRecEn- TLPPfxPres- HdrLogCap-
                HeaderLog: 00000000 00000000 00000000 00000000
        Kernel driver in use: serial

[biergaizi]

Update: I forgot to check something really basic, which is typing "AX99100 Xen" into a search engine. After I tried, I found this:

On Mon, Feb 19, 2024 at 12:13:18PM +0100, Marek Marczykowski-Górecki wrote:
> On Mon, Feb 19, 2024 at 09:57:49AM +0100, Jan Beulich wrote:
> > On 18.02.2024 02:34, Marek Marczykowski-Górecki wrote:
> > > @@ -1170,6 +1177,11 @@ static const struct ns16550_config __initconst uart_config[] =
> > >          .dev_id = 0x7adc,
> > >          .param = param_intel_lpss
> > >      },
> > > +    {
> > > +        .vendor_id = PCI_VENDOR_ID_ASIX,
> > > +        .dev_id = 9100,
> > 
> > As per Linux this is 0x9100.
> 
> Right... but then, maybe the patch isn't needed at all, as it does work
> for me. Maybe what's needed instead is some other patch already in
> staging. Initial attempt that did not work was with 4.17.something.
> I guess setting the fifo size isn't that important.

Indeed, the patch is not needed after all, plain "master" from today
works.

According to this comment, it can't be used on Xen 4.17, but it works the development version... Could the support be backported to Xen 4.17? Finally, which PCIe chipset should I hunt for in order to work with Xen 4.17?

[marmarek]

If you use Xen 4.17 package from Qubes, it does work with this specific card. The cmdline option would be com1=115200,8n1,pci,msi,23:00.0 console=vga,com1. This specific card has 4 ports, check others ones, the mapping may be not obvious.

[apparatius]

@biergaizi I used the same card and it worked for me in Qubes OS 4.1 (Xen 4.14).
There were two ports for me, it was something like:

23:00.0 Serial controller: Asix Electronics Corporation AX99100 PCIe to Multi I/O Controller (prog-if 02 [16550])
...
        Region 0: I/O ports at d000 [size=8]
        Interrupt: pin A routed to IRQ 120
...
23:00.1 Serial controller: Asix Electronics Corporation AX99100 PCIe to Multi I/O Controller (prog-if 02 [16550])
...
        Region 0: I/O ports at d008 [size=8]
        Interrupt: pin B routed to IRQ 121
...

And it worked with com1=115200,8n1,0xd008,121.
Try to use device with pin B.

[biergaizi]

If you use Xen 4.17 package from Qubes, it does work with this specific card. The cmdline option would be com1=115200,8n1,pci,msi,23:00.0 console=vga,com1.

I'm still unable to get even a single byte of Xen log from the serial port. For completeness, the boot configuration I'm using right now is:

menuentry 'Qubes, with Xen hypervisor' --class qubes --class gnu-linux --class gnu --class os --class xen $menuentry_id_option 'xen-gnulinux-simple-/dev/mapper/qubes_dom0-root' {
	insmod part_gpt
	insmod ext2
	search --no-floppy --fs-uuid --set=root 2bd7d851-c10f-4efa-b7fc-85cf451c3caf
	echo	'Loading Xen 4.17.5 ...'
        if [ "$grub_platform" = "pc" -o "$grub_platform" = "" ]; then
            xen_rm_opts=
        else
            xen_rm_opts="no-real-mode edd=off"
        fi
	insmod multiboot2
	multiboot2	/xen-4.17.5.gz placeholder  loglvl=all dom0_mem=min:1024M \
                              dom0_mem=max:4096M ucode=scan smt=off gnttab_max_frames=2048 \
                              gnttab_max_maptrack_frames=4096 com1=115200,8n1,msi,23:00.0 \
                              console=vga,com1 loglvl=all guest_loglvl=all sync_console=true \
                              sched_debug iommu=verbose apic_verbosity=debug console_timestamps ${xen_rm_opts}
	echo	'Loading Linux 6.11.2-1.qubes.fc37.x86_64 ...'
	module2	/vmlinuz-6.11.2-1.qubes.fc37.x86_64 placeholder \
                              root=/dev/mapper/qubes_dom0-root ro root=/dev/mapper/qubes_dom0-root \
                              rd.luks.uuid=luks-[REDACTED] rd.lvm.lv=qubes_dom0/root rd.lvm.lv=qubes_dom0/swap rhgb \
                              verbose usbcore.authorized_default=0 plymouth.ignore-serial-consoles pcie-aspm=off \
                              i915.force_probe='4908' usbcore.authorized_default=0 \
                              console=hvc0 earlyprintk=xen 
	echo	'Loading initial ramdisk ...'
	insmod multiboot2
	module2	--nounzip   /initramfs-6.11.2-1.qubes.fc37.x86_64.img
}

@marmarek: This specific card has 4 ports, check others ones, the mapping may be not obvious.
@apparatius: There were two ports for me

My card only has 1 port.

# lspci | grep Serial
23:00.0 Serial controller: Asix Electronics Corporation AX99100 PCIe to Multi I/O Controller

# dmesg | grep ttyS
[    0.991742] 0000:23:00.0: ttyS4 at I/O 0xd000 (irq = 120, base_baud = 115200) is a 16550A

It does work under Dom0 if I do this:

# stty -F /dev/ttyS4 115200
# echo "Hello, world!" > /dev/ttyS4

Remote host can receive "Hello, world":

$ cat /dev/ttyUSB0
Hello, world!

$ stty -F /dev/ttyUSB0 --all
speed 115200 baud; rows 0; columns 0; line = 0;
intr = ^C; quit = ^\; erase = ^?; kill = ^U; eof = ^D; eol = <undef>;
eol2 = <undef>; swtch = <undef>; start = ^Q; stop = ^S; susp = ^Z; rprnt = ^R;
werase = ^W; lnext = ^V; discard = ^O; min = 1; time = 0;
-parenb -parodd -cmspar cs8 hupcl -cstopb cread clocal -crtscts
-ignbrk -brkint -ignpar -parmrk -inpck -istrip -inlcr -igncr icrnl -ixon -ixoff
-iuclc -ixany -imaxbel -iutf8
opost -olcuc -ocrnl onlcr -onocr -onlret -ofill -ofdel nl0 cr0 tab0 bs0 vt0 ff0
isig icanon iexten echo echoe echok -echonl -noflsh -xcase -tostop -echoprt
echoctl echoke -flusho -extproc

[apparatius]

@biergaizi Try to boot from some Live Linux (Fedora/Debian/etc) and check how this device is seen there (check its Region 0 address and IRQ number or maybe you'll see multiple PCI devices for it).
For some reason when I boot in dom0 with this PCI card I have IRQ = 0 instead of the real IRQ number e.g. in dom0 I had:

23:00.0 Serial controller: Asix Electronics Corporation AX99100 PCIe to Multi I/O Controller (prog-if 02 [16550])
...
        Region 0: I/O ports at d000 [size=8]
        Interrupt: pin A routed to IRQ 0
...
23:00.1 Serial controller: Asix Electronics Corporation AX99100 PCIe to Multi I/O Controller (prog-if 02 [16550])
...
        Region 0: I/O ports at d008 [size=8]
        Interrupt: pin B routed to IRQ 0
...

But when I boot in another OS (I've checked it in Qubes OS installer) then the real IRQ was shown that worked for me.
Maybe there is some issue with device information available in dom0.

[marmarek]

Is it perhaps behind a bridge that needs to be enabled too? Check lspci -t, and try to add bridge to the option too.

If not that, I'm afraid I'm out of ideas. It does work for me here: https://openqa.qubes-os.org/tests/116354/logfile?filename=serial0.txt ...

If I'd have to debug it further, I'd probably add some debug prints around console init code, especially checking PCI_COMMAND etc registers at that time. You can extract those messages with xl dmesg once the system starts (I assume it does start eventually).

[biergaizi]

Problem solved.

com1=115200,8n1,msi,23:00.0

should be:

com1=115200,8n1,pci,msi,23:00.0

In other words, the original argument suggested by @marmarek worked as advertised, thanks for the help. It's easy to miss this typo after you keep rebooting the machine mindlessly for an hour... Lesson learned: Always double check both xl info | grep xen_commandline and /proc/cmdline...