fails to boot with initrd

[mythi]

my (built-in) device needs firmware blobs from initrd but when adding initrd ... to systemd-boots config file the guest fails to boot:

$ ./cloud-hypervisor/target/release/cloud-hypervisor -v  --kernel ./hypervisor-fw  --disk path=clear-31360-kvm.img --cpus 4 --memory size=1024M  --rng --net tap=,mac=
Cloud Hypervisor Guest
        API server: /run/user/1000/cloud-hypervisor.198578
        vCPUs: 4
        Memory: 1024 MB
        Kernel: Some(KernelConfig { path: "./hypervisor-fw" })
        Kernel cmdline:
        Disk(s): Some([DiskConfig { path: "clear-31360-kvm.img", iommu: false }])
[    0.372353] random: fast init done
[    0.372371] random: crng init done
[    0.374114] loop: module loaded
[    0.374919] virtio_blk virtio1: [vda] 17909679 512-byte logical blocks (9.17 GB/8.54 GiB)
[    0.376266]  vda: vda1 vda2 vda3
[    0.376770] rbd: loaded (major 253)
[    0.377237] tun: Universal TUN/TAP device driver, 1.6
[    0.378909] pcnet32: pcnet32.c:v1.35 21.Apr.2008 tsbogend@alpha.franken.de
[    0.379641] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[    0.380243] e1000: Copyright (c) 1999-2006 Intel Corporation.
[    0.380779] i8042: PNP: No PS/2 controller found.
[    0.381303] mousedev: PS/2 mouse device common for all mice
[    0.381806] usbcore: registered new interface driver usbtouchscreen
[    0.382422] rtc_cmos rtc_cmos: only 24-hr supported
[    0.382947] device-mapper: ioctl: 4.40.0-ioctl (2019-01-18) initialised: dm-devel@redhat.com
[    0.383682] intel_pstate: CPU model not supported
[    0.384634] Initializing XFRM netlink socket
[    0.385072] NET: Registered protocol family 10
[    0.385635] Segment Routing with IPv6
[    0.386062] NET: Registered protocol family 17
[    0.386510] Key type ceph registered
[    0.386901] libceph: loaded (mon/osd proto 15/24)
[    0.387380] AVX2 version of gcm_enc/dec engaged.
[    0.387801] AES CTR mode by8 optimization enabled
[    0.389229] sched_clock: Marking stable (354343119, 34875719)->(401373579, -12154741)
[    0.390022] registered taskstats version 1
[    0.390396] Loading compiled-in X.509 certificates
[    0.391463] Loaded X.509 cert 'Build time autogenerated kernel key: da386d37c59473a2a9013d60d09850e62f9061c5'
[    0.393234] EXT4-fs (vda3): mounted filesystem with ordered data mode. Opts: (null)
[    0.393890] VFS: Mounted root (ext4 filesystem) on device 254:3.
[    0.394615] devtmpfs: mounted
[    0.395374] Freeing unused kernel image memory: 1408K
[    0.414897] Write protecting the kernel read-only data: 18432k
[    0.415880] Freeing unused kernel image memory: 2008K
[    0.416483] Freeing unused kernel image memory: 676K
[    0.416931] Run /usr/sbin/init as init process
cloud-hypervisor: 1.011984678s: ERROR:vm-virtio/src/block.rs:363 -- Failed to parse available descriptor chain: DescriptorChainTooShort
[    0.417610] EXT4-fs error (device vda3): ext4_dx_csum_verify:465: inode #393222: comm swapper/0: dir seems corrupt?  Run e2fsck -D.
[    0.418656] EXT4-fs error (device vda3): dx_probe:761: inode #393222: comm swapper/0: Directory index failed checksum
[    0.419656] Kernel panic - not syncing: Requested init /usr/sbin/init failed (error -74).
[    0.420360] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.3.7-396.kvm #2
[    0.421039] Call Trace:
[    0.421251]  dump_stack+0x47/0x70
[    0.421579]  ? rest_init+0x30/0x9a
[    0.421903]  panic+0xeb/0x2a9
[    0.422156]  ? rest_init+0x9a/0x9a
[    0.422477]  kernel_init+0xa6/0x106
[    0.422801]  ret_from_fork+0x35/0x40
[    0.423209] Kernel Offset: 0x4000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[    0.424070] ---[ end Kernel panic - not syncing: Requested init /usr/sbin/init failed (error -74). ]---

after removing the initrd line it boots again.

[sboeuf]

@mythi what do you mean by (built-in) device? Do you have some specific HW that you're trying to test?
Just asking because if that's the case I would expect that you would use the direct kernel boot to try it out with your custom kernel. And along with this, you would need to pass your device through the VM with VFIO. I might be completely off track here, but please provide more context :)

[sameo]

cloud-hypervisor: 1.011984678s: ERROR:vm-virtio/src/block.rs:363 -- Failed to parse available descriptor chain: DescriptorChainTooShortclt

I suspect this happens when we're trying to read from the initrd image. Have you verified that you can correctly read the image when manually mounting your CL image boot partition?

[rbradford]

@sameo the initrd image is loaded into memory by the firmware.

This looks like it is failing when it tries to run the init from the actual rootfs.

@mythi can you add --console off --serial stdout so we get some more boot messages.

[sameo]

@sameo the initrd image is loaded into memory by the firmware.

Ah you're right. It's not going to be managed by the virtio driver, so the error message I was pointing at is coming from the rootfs, yes...

[mythi]

Some updates from my side and sorry for not being very clear first time.

@sboeuf

@mythi what do you mean by (built-in) device? Do you have some specific HW that you're trying to test?

built-in device driver. I'm using QAT and Clear Linux 'vanilla' images.

grep QAT /usr/lib/kernel/config-5.3.7-396.kvm
CONFIG_CRYPTO_DEV_QAT=y
CONFIG_CRYPTO_DEV_QAT_DH895xCC=y
CONFIG_CRYPTO_DEV_QAT_C3XXX=y
CONFIG_CRYPTO_DEV_QAT_C62X=y
CONFIG_CRYPTO_DEV_QAT_DH895xCCVF=y
CONFIG_CRYPTO_DEV_QAT_C3XXXVF=y
CONFIG_CRYPTO_DEV_QAT_C62XVF=y

My PF device is bound to vfio-pci.

The image has two modifications

1. swupd bundle-add linux-firmware-qat
2. clr-boot-manager update

This results in (all the image partitions are readable from the host from a loop back device):

# cat /mnt/boot/loader/entries/Clear-linux-kvm-5.3.7-396.conf
title Clear Linux OS
linux /EFI/org.clearlinux/kernel-org.clearlinux.kvm.5.3.7-396
initrd /EFI/org.clearlinux/freestanding-qat-firmware.cpio.xz
options root=PARTUUID=9bf148d9-b4f3-4af9-8eb4-e16157593649 console=hvc0 console=tty0 console=ttyS0,115200n8 cryptomgr.notests init=/usr/lib/systemd/systemd-bootchart initcall_debug no_timer_check noreplace-smp page_alloc.shuffle=1 rootfstype=ext4,btrfs,xfs tsc=reliable rw

With qemu, the exact same image boots OK. HOWEVER, the QAT firmware blob from initrd fails to load.

@rbradford

@mythi can you add --console off --serial stdout so we get some more boot messages.

This results in fewer logs:

$ ./cloud-hypervisor/target/release/cloud-hypervisor -v --console off --serial stdout   --kernel ./hypervisor-fw  --disk path=/home/mylinen/Downloads/clear-31360-kvm.img --cpus 4 --memory size=1024M  --rng --net tap=,mac= --device path=/sys/bus/pci/devices/0000\:4e\:00.0/,iommu=on
Failed parsing parameters ParseConsoleParam

[rbradford]

@mythi oops, --console off --serial tty

[mythi]

@mythi oops, --console off --serial tty

I saw my silly user error after I submitted my comment. Here's the log:

$ ./cloud-hypervisor/target/release/cloud-hypervisor -v --console off  --serial tty --kernel ./hypervisor-fw  --disk path=/home/mylinen/Downloads/clear-31360-kvm.img --cpus 4 --memory size=1024M  --rng --net tap=,mac= --device path=/sys/bus/pci/devices/0000\:4e\:00.0/,iommu=on
Cloud Hypervisor Guest
        API server: /run/user/1000/cloud-hypervisor.1689375
        vCPUs: 4
        Memory: 1024 MB
        Kernel: Some(KernelConfig { path: "./hypervisor-fw" })
        Kernel cmdline:
        Disk(s): Some([DiskConfig { path: "/home/mylinen/Downloads/clear-31360-kvm.img", iommu: false }])
cloud-hypervisor: 122.582916ms: ERROR:vfio/src/vfio_device.rs:438 -- Could not get region #8 info
cloud-hypervisor: 226.584628ms: WARN:vfio/src/vfio_device.rs:817 -- region write with invalid parameter, add: 4294967295, size: 4
cloud-hypervisor: 226.653112ms: WARN:vfio/src/vfio_device.rs:817 -- region write with invalid parameter, add: 4294967295, size: 4
Starting..
Page tables setup
Found PCI device vendor=8086 device=d57 in slot=0
Found PCI device vendor=1af4 device=1042 in slot=1
Found PCI device vendor=1af4 device=1041 in slot=2
Found PCI device vendor=1af4 device=1044 in slot=3
Found PCI device vendor=8086 device=37c8 in slot=4
Found PCI device vendor=1af4 device=1057 in slot=5
PCI Device: 0:1.0 1af4:1042
Bar: type=MemorySpace32 address=e7f80000
Bar: type=MemorySpace32 address=0
Bar: type=MemorySpace32 address=0
Bar: type=MemorySpace32 address=0
Bar: type=MemorySpace32 address=0
Bar: type=Unused address=0
Virtio block device configured. Capacity: 17909679 sectors
Found EFI partition
Filesystem ready
Jumping to kernel
[    0.000000] Linux version 5.3.7-396.kvm (mockbuild@kojibld02) (gcc version 9.2.1 20191017 gcc-9-branch@277087 (Clear Linux OS for Intel Architecture)) #2 SMP Thu Oct 17 14:44:45 PDT 2019
[    0.000000] Command line:  root=PARTUUID=9bf148d9-b4f3-4af9-8eb4-e16157593649 console=hvc0 console=tty0 console=ttyS0,115200n8 cryptomgr.notests init=/usr/lib/systemd/systemd-bootchart initcall_debug no_timer_check noreplace-smp page_alloc.shuffle=1 rootfstype=ext4,btrfs,xfs tsc=reliable rw
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003fffffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000e8000000-0x00000000f7ffffff] reserved
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] DMI not present or invalid.
[    0.000000] Hypervisor detected: KVM
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 337ee001, primary cpu clock
[    0.000000] kvm-clock: using sched offset of 815108794 cycles
[    0.000001] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000002] tsc: Detected 2999.972 MHz processor
[    0.000013] last_pfn = 0x40000 max_arch_pfn = 0x400000000
[    0.001314] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT
[    0.002597] found SMP MP-table at [mem 0x0009fc00-0x0009fc0f]
[    0.002626] Using GB pages for direct mapping
[    0.002657] RAMDISK: [mem 0x3ffdd413-0x3fffffff]
[    0.002663] ACPI: Early table checksum verification disabled
[    0.002665] ACPI: RSDP 0x00000000000A0000 000024 (v02 CLOUDH)
[    0.002667] ACPI: XSDT 0x00000000000A0404 000044 (v01 CLOUDH CHXSDT   00000001 CLDH 00000000)
[    0.002669] ACPI: FACP 0x00000000000A01B2 000114 (v06 CLOUDH CHFACP   00000001 CLDH 00000000)
[    0.002672] ACPI: DSDT 0x00000000000A0024 00018E (v06 CLOUDH CHDSDT   00000001 CLDH 00000000)
[    0.002674] ACPI: APIC 0x00000000000A02C6 000062 (v05 CLOUDH CHMADT   00000001 CLDH 00000000)
[    0.002675] ACPI: MCFG 0x00000000000A0328 00003C (v01 CLOUDH CHMCFG   00000001 CLDH 00000000)
[    0.002677] ACPI: IORT 0x00000000000A0364 0000A0 (v01 CLOUDH CHIORT   00000001 CLDH 00000000)
[    0.003193] Zone ranges:
[    0.003194]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.003195]   DMA32    [mem 0x0000000001000000-0x000000003fffffff]
[    0.003196]   Normal   empty
[    0.003196]   Device   empty
[    0.003197] Movable zone start for each node
[    0.003197] Early memory node ranges
[    0.003198]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.003199]   node   0: [mem 0x0000000000100000-0x000000003fffffff]
[    0.003449] Zeroed struct page in unavailable ranges: 97 pages
[    0.003450] Initmem setup node 0 [mem 0x0000000000001000-0x000000003fffffff]
[    0.006435] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.006436] ACPI: INT_SRC_OVR (bus 0 bus_irq 4 global_irq 4 dfl dfl)
[    0.006438] Using ACPI (MADT) for SMP configuration information
[    0.006439] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[    0.006450] KVM setup pv sched yield
[    0.006454] [mem 0x40000000-0xe7ffffff] available for PCI devices
[    0.006455] Booting paravirtualized kernel on KVM
[    0.006457] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.064746] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:4 nr_node_ids:1
[    0.065088] percpu: Embedded 49 pages/cpu s161880 r8192 d30632 u524288
[    0.065103] KVM setup async PF for cpu 0
[    0.065106] kvm-stealtime: cpu 0, msr 3ea15f00
[    0.065108] Built 1 zonelists, mobility grouping on.  Total pages: 257929
[    0.065109] Kernel command line:  root=PARTUUID=9bf148d9-b4f3-4af9-8eb4-e16157593649 console=hvc0 console=tty0 console=ttyS0,115200n8 cryptomgr.notests init=/usr/lib/systemd/systemd-bootchart initcall_debug no_timer_check noreplace-smp page_alloc.shuffle=1 rootfstype=ext4,btrfs,xfs tsc=reliable rw
[    0.065223] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[    0.065253] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.065284] mem auto-init: stack:off, heap alloc:on, heap free:off
[    0.066913] Memory: 1002372K/1048188K available (12304K kernel code, 1080K rwdata, 3420K rodata, 1408K init, 2204K bss, 45816K reserved, 0K cma-reserved)
[    0.067227] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.067231] Kernel/User page tables isolation: enabled
[    0.067239] ftrace: allocating 36319 entries in 142 pages
[    0.076269] rcu: Hierarchical RCU implementation.
[    0.076270] rcu:     RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=4.
[    0.076271] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.076271] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.076347] NR_IRQS: 4352, nr_irqs: 440, preallocated irqs: 0
[    0.076358] rcu:     Offload RCU callbacks from CPUs: (none).
[    0.076400] random: get_random_bytes called from start_kernel+0x37d/0x53e with crng_init=0
[    0.076416] Console: colour dummy device 80x25
[    0.076477] printk: console [tty0] enabled
[    0.124737] printk: console [ttyS0] enabled
[    0.125141] ACPI: Core revision 20190703
[    0.125541] APIC: Switch to symmetric I/O mode setup
[    0.126802] x2apic enabled
[    0.127451] Switched APIC routing to physical x2apic.
[    0.127936] KVM setup pv IPIs
[    0.128238] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2b3e2aac79b, max_idle_ns: 440795262762 ns
[    0.129241] Calibrating delay loop (skipped) preset value.. 5999.94 BogoMIPS (lpj=11999888)
[    0.130042] pid_max: default: 32768 minimum: 301
[    0.130513] LSM: Security Framework initializing
[    0.130970] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.131681] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.132516] *** VALIDATE proc ***
[    0.132872] *** VALIDATE cgroup1 ***
[    0.133224] *** VALIDATE cgroup2 ***
[    0.133240] x86/cpu: User Mode Instruction Prevention (UMIP) activated
[    0.133240] Last level iTLB entries: 4KB 64, 2MB 8, 4MB 8
[    0.133240] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
[    0.133240] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.133240] Spectre V2 : Mitigation: Full generic retpoline
[    0.133240] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.133240] Spectre V2 : Enabling Restricted Speculation for firmware calls
[    0.133240] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
[    0.133240] Spectre V2 : User space: Mitigation: STIBP via seccomp and prctl
[    0.133240] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.133240] MDS: Mitigation: Clear CPU buffers
[    0.133240] Freeing SMP alternatives memory: 24K
[    0.133240] smpboot: CPU0: Intel 06/4f (family: 0x6, model: 0x4f, stepping: 0x1)
[    0.133240] Performance Events: Broadwell events, Intel PMU driver.
[    0.133240] ... version:                2
[    0.133240] ... bit width:              48
[    0.133240] ... generic registers:      4
[    0.133240] ... value mask:             0000ffffffffffff
[    0.133240] ... max period:             000000007fffffff
[    0.133240] ... fixed-purpose events:   3
[    0.133243] ... event mask:             000000070000000f
[    0.133809] rcu: Hierarchical SRCU implementation.
[    0.134677] smp: Bringing up secondary CPUs ...
[    0.135177] x86: Booting SMP configuration:
[    0.135588] .... node  #0, CPUs:      #1
[    0.056878] kvm-clock: cpu 1, msr 337ee041, secondary cpu clock
[    0.137188] KVM setup async PF for cpu 1
[    0.137188] kvm-stealtime: cpu 1, msr 3ea95f00
[    0.137258] MDS CPU bug present and SMT on, data leak possible. See https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/mds.html for more details.
[    0.138604]  #2
[    0.056878] kvm-clock: cpu 2, msr 337ee081, secondary cpu clock
[    0.141780] KVM setup async PF for cpu 2
[    0.142144] kvm-stealtime: cpu 2, msr 3eb15f00
[    0.142575]  #3
[    0.056878] kvm-clock: cpu 3, msr 337ee0c1, secondary cpu clock
[    0.142575] KVM setup async PF for cpu 3
[    0.142575] kvm-stealtime: cpu 3, msr 3eb95f00
[    0.145244] smp: Brought up 1 node, 4 CPUs
[    0.145659] smpboot: Max logical packages: 1
[    0.146077] smpboot: Total of 4 processors activated (23999.77 BogoMIPS)
[    0.149399] devtmpfs: initialized
[    0.149624] x86/mm: Memory block size: 128MB
[    0.150187] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.150301] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.151186] NET: Registered protocol family 16
[    0.151750] cpuidle: using governor ladder
[    0.153252] cpuidle: using governor menu
[    0.153787] KVM setup pv remote TLB flush
[    0.154202] ACPI: bus type PCI registered
[    0.154596] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.155289] PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xe8000000-0xf7ffffff] (base 0xe8000000)
[    0.156192] PCI: MMCONFIG at [mem 0xe8000000-0xf7ffffff] reserved in E820
[    0.156854] PCI: Using configuration type 1 for base access
[    0.157281] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.157920] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.158601] alg: self-tests disabled
[    0.158601] cryptd: max_cpu_qlen set to 1000
[    0.161481] ACPI: Added _OSI(Module Device)
[    0.161701] ACPI: Added _OSI(Processor Device)
[    0.162131] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.162580] ACPI: Added _OSI(Processor Aggregator Device)
[    0.163098] ACPI: Added _OSI(Linux-Dell-Video)
[    0.163522] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.164027] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    0.165284] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.165977] ACPI: Interpreter enabled
[    0.166334] ACPI: (supports S0 S5)
[    0.166662] ACPI: Using IOAPIC for interrupt routing
[    0.167146] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.168144] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.168736] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig Segments MSI HPX-Type3]
[    0.169246] acpi PNP0A08:00: _OSC failed (AE_NOT_FOUND)
[    0.169771] PCI host bridge to bus 0000:00
[    0.170168] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.170818] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.171462] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.172172] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xe7ffffff window]
[    0.173244] pci_bus 0000:00: root bus resource [mem 0x100000000-0x3fffffffffff window]
[    0.173244] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.173797] pci 0000:00:00.0: [8086:0d57] type 00 class 0x060000
[    0.174429] pci 0000:00:00.0: calling  quirk_mmio_always_on+0x0/0x10 @ 1
[    0.175064] pci 0000:00:00.0: quirk_mmio_always_on+0x0/0x10 took 0 usecs
[    0.176079] pci 0000:00:01.0: [1af4:1042] type 00 class 0x018000
[    0.177245] pci 0000:00:01.0: reg 0x10: [mem 0xe7f80000-0xe7ffffff]
[    0.177931] pci 0000:00:02.0: [1af4:1041] type 00 class 0x020000
[    0.178643] pci 0000:00:02.0: reg 0x10: [mem 0x3ffffff80000-0x3fffffffffff 64bit]
[    0.180071] pci 0000:00:03.0: [1af4:1044] type 00 class 0xffff00
[    0.181244] pci 0000:00:03.0: reg 0x10: [mem 0x3ffffff00000-0x3ffffff7ffff 64bit]
[    0.181956] pci 0000:00:04.0: [8086:37c8] type 00 class 0x0b4000
[    0.182796] pci 0000:00:04.0: reg 0x18: [mem 0x3fffffec0000-0x3fffffefffff 64bit]
[    0.183607] pci 0000:00:04.0: reg 0x20: [mem 0x3fffffe80000-0x3fffffebffff 64bit]
[    0.185244] pci 0000:00:05.0: [1af4:1057] type 00 class 0xffff00
[    0.185385] pci 0000:00:05.0: reg 0x10: [mem 0x3fffffe00000-0x3fffffe7ffff 64bit]
[    0.186951] vgaarb: loaded
[    0.186951] SCSI subsystem initialized
[    0.189256] ACPI: bus type USB registered
[    0.189662] usbcore: registered new interface driver usbfs
[    0.190204] usbcore: registered new interface driver hub
[    0.190204] usbcore: registered new device driver usb
[    0.190204] pps_core: LinuxPPS API ver. 1 registered
[    0.190260] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.191148] PTP clock support registered
[    0.191543] PCI: Using ACPI for IRQ routing
[    0.239326] clocksource: Switched to clocksource kvm-clock
[    0.242798] *** VALIDATE hugetlbfs ***
[    0.243206] pnp: PnP ACPI init
[    0.243543] system 00:00: [mem 0xe8000000-0xf7ffffff] has been reserved
[    0.244203] pnp: PnP ACPI: found 2 devices
[    0.245679] thermal_sys: Registered thermal governor 'user_space'
[    0.246283] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    0.246886] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    0.247486] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    0.248150] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xe7ffffff window]
[    0.248820] pci_bus 0000:00: resource 8 [mem 0x100000000-0x3fffffffffff window]
[    0.249561] NET: Registered protocol family 2
[    0.250111] tcp_listen_portaddr_hash hash table entries: 512 (order: 1, 8192 bytes, linear)
[    0.250943] TCP established hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.251709] TCP bind hash table entries: 8192 (order: 5, 131072 bytes, linear)
[    0.252420] TCP: Hash tables configured (established 8192 bind 8192)
[    0.253051] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.253709] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.254419] NET: Registered protocol family 1
[    0.254856] NET: Registered protocol family 44
[    0.255345] PCI: CLS 32 bytes, default 64
[    0.255764] Trying to unpack rootfs image as initramfs...
[    0.268045] ------------[ cut here ]------------
[    0.268528] WARNING: CPU: 1 PID: 1 at arch/x86/mm/init.c:791 free_init_pages.cold+0xc/0x20
[    0.269242] Modules linked in:
[    0.269242] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 5.3.7-396.kvm #2
[    0.269242] RIP: 0010:free_init_pages.cold+0xc/0x20
[    0.269242] Code: 0f b6 0d 93 a4 25 01 ba 08 00 00 00 83 e9 0d 48 d3 e2 48 39 d0 48 0f 47 c2 31 d2 89 d1 c3 48 c7 c7 20 74 05 94 e8 2f c6 0b 00 <0f> 0b 4d 89 f4 48 89 dd e9 97 fe ff ff 90 90 90 90 90 90 90 0f 1f
[    0.269242] RSP: 0000:ffffae2ac000be80 EFLAGS: 00010246
[    0.269242] RAX: 0000000000000024 RBX: ffff99ecfffde000 RCX: 0000000000000000
[    0.269242] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[    0.269242] RBP: ffffffff9469da5d R08: 0000000000000000 R09: 0000000000000000
[    0.269242] R10: 0000000000000000 R11: 0000000000000000 R12: ffff99ecfe4195a8
[    0.269242] R13: ffffffff94056f3a R14: ffff99ed00000000 R15: 0000000000000000
[    0.269242] FS:  0000000000000000(0000) GS:ffff99ecfea80000(0000) knlGS:0000000000000000
[    0.269242] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    0.269242] CR2: 0000000000000000 CR3: 0000000033208001 CR4: 0000000000360ea0
[    0.269242] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[    0.269242] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[    0.269242] Call Trace:
[    0.269242]  ? unpack_to_rootfs+0x2a5/0x2a5
[    0.269242]  populate_rootfs+0x8d/0xaf
[    0.269242]  do_one_initcall+0x46/0x1f4
[    0.269242]  kernel_init_freeable+0x1d5/0x263
[    0.269242]  ? rest_init+0x9a/0x9a
[    0.269242]  kernel_init+0xa/0x106
[    0.269242]  ret_from_fork+0x35/0x40
[    0.269242] ---[ end trace 9119ce0d2d3c722b ]---
[    0.283461] Freeing initrd memory: 136K
[    0.284274] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2b3e2aac79b, max_idle_ns: 440795262762 ns
[    0.285349] clocksource: Switched to clocksource tsc
[    0.285864] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    0.287314] Initialise system trusted keyrings
[    0.287805] workingset: timestamp_bits=46 max_order=18 bucket_order=0
[    0.289229] ntfs: driver 2.1.32 [Flags: R/O].
[    0.292841] NET: Registered protocol family 38
[    0.293306] Key type asymmetric registered
[    0.293719] Asymmetric key parser 'x509' registered
[    0.294205] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    0.295009] io scheduler mq-deadline registered
[    0.295472] io scheduler kyber registered
[    0.295889] io scheduler bfq registered
[    0.296502] virtio-pci 0000:00:01.0: enabling device (0000 -> 0002)
[    0.297619] virtio-pci 0000:00:02.0: enabling device (0000 -> 0002)
[    0.298721] virtio-pci 0000:00:03.0: enabling device (0000 -> 0002)
[    0.299803] virtio-pci 0000:00:05.0: enabling device (0000 -> 0002)
[    0.300961] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[    0.322815] 00:01: ttyS0 at I/O 0x3f8 (irq = 24, base_baud = 115200) is a U6_16550A
[    0.324384] random: fast init done
[    0.324748] random: crng init done
[    0.326305] loop: module loaded
[    0.327124] virtio_blk virtio0: [vda] 17909679 512-byte logical blocks (9.17 GB/8.54 GiB)
[    0.328581]  vda: vda1 vda2 vda3
[    0.329091] rbd: loaded (major 253)
[    0.329569] tun: Universal TUN/TAP device driver, 1.6
[    0.331555] pcnet32: pcnet32.c:v1.35 21.Apr.2008 tsbogend@alpha.franken.de
[    0.332367] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[    0.333048] e1000: Copyright (c) 1999-2006 Intel Corporation.
[    0.333658] i8042: PNP: No PS/2 controller found.
[    0.334189] mousedev: PS/2 mouse device common for all mice
[    0.334764] usbcore: registered new interface driver usbtouchscreen
[    0.335451] rtc_cmos rtc_cmos: only 24-hr supported
[    0.336049] device-mapper: ioctl: 4.40.0-ioctl (2019-01-18) initialised: dm-devel@redhat.com
[    0.336881] intel_pstate: CPU model not supported
[    0.412219] c6xx 0000:00:04.0: Direct firmware load for qat_c62x_mmp.bin failed with error -2
[    0.413054] c6xx 0000:00:04.0: Failed to load MMP firmware qat_c62x_mmp.bin
[    0.413737] c6xx 0000:00:04.0: Failed to load acceleration FW
[    0.414318] c6xx 0000:00:04.0: Resetting device qat_dev0
[    0.625641] c6xx: probe of 0000:00:04.0 failed with error -14
[    0.626622] Initializing XFRM netlink socket
[    0.627098] NET: Registered protocol family 10
[    0.627734] Segment Routing with IPv6
[    0.628220] NET: Registered protocol family 17
[    0.628722] Key type ceph registered
[    0.629156] libceph: loaded (mon/osd proto 15/24)
[    0.629693] AVX2 version of gcm_enc/dec engaged.
[    0.630145] AES CTR mode by8 optimization enabled
[    0.631346] sched_clock: Marking stable (578458635, 52878114)->(658338623, -27001874)
[    0.632291] registered taskstats version 1
[    0.632703] Loading compiled-in X.509 certificates
[    0.633802] Loaded X.509 cert 'Build time autogenerated kernel key: da386d37c59473a2a9013d60d09850e62f9061c5'
cloud-hypervisor: 1.478207196s: ERROR:vm-virtio/src/block.rs:363 -- Failed to parse available descriptor chain: DescriptorChainTooShort
[    0.635314] EXT4-fs (vda3): ext4_check_descriptors: Block bitmap for group 0 overlaps superblock
[    0.636176] EXT4-fs (vda3): group descriptors corrupted!
[    0.636706] VFS: Cannot open root device "PARTUUID=9bf148d9-b4f3-4af9-8eb4-e16157593649" or unknown-block(254,3): error -117
[    0.637801] Please append a correct "root=" boot option; here are the available partitions:
[    0.638612] fe00         8954839 vda
[    0.638613]  driver: virtio_blk
[    0.639287]   fe01          522240 vda1 aa43f4f9-2540-4a76-98da-d166daebf638
[    0.639287]
[    0.640181]   fe02           33792 vda2 5821e577-dac5-4613-8595-b170cfea6fc3
[    0.640181]
[    0.641029]   fe03         8388608 vda3 9bf148d9-b4f3-4af9-8eb4-e16157593649
[    0.641029]
[    0.641887] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(254,3)
[    0.642707] CPU: 1 PID: 1 Comm: swapper/0 Tainted: G        W         5.3.7-396.kvm #2
[    0.643476] Call Trace:
[    0.643725]  dump_stack+0x47/0x70
[    0.644053]  panic+0xeb/0x2a9
[    0.644354]  ? printk+0x48/0x58
[    0.644668]  mount_block_root+0x23f/0x2fa
[    0.645064]  prepare_namespace+0x140/0x176
[    0.645473]  kernel_init_freeable+0x258/0x263
[    0.645901]  ? rest_init+0x9a/0x9a
[    0.646237]  kernel_init+0xa/0x106
[    0.646577]  ret_from_fork+0x35/0x40
[    0.646993] Kernel Offset: 0x12000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[    0.648028] ---[ end Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(254,3) ]---

[mythi]

@rbradford

Found EFI partition
Filesystem ready
Jumping to kernel

looks like systemd-boot is not run?

[rbradford]

@mythi If using FreeDesktop based loading then the firmward loads the bzImage/cmdline/initrd directly

[rbradford]

Looking at that output I can see VFIO errors and initramfs errors.

[sboeuf]

@mythi
The following trace is not important, it happens all the time:

cloud-hypervisor: 122.582916ms: ERROR:vfio/src/vfio_device.rs:438 -- Could not get region #8 info

But this log is more interesting as it seems something is going wrong:

cloud-hypervisor: 226.584628ms: WARN:vfio/src/vfio_device.rs:817 -- region write with invalid parameter, add: 4294967295, size: 4

Could you avoid enabling the virtiual IOMMU by removing iommu=on, because this will cause some issues as you don't have the right patches in your kernel to support it.

[mythi]

@sboeuf leaving --device path=/sys/bus/pci/devices/0000\:4e\:00.0/,iommu=on out does not change the result.

Only if I manually drop the initrd line out makes it to boot again.

[sboeuf]

@rbradford I'm not familiar with systemd-boot but it is a firmware basically, and I simply don't think hypervisor-fw is able to run it, right?

@mythi this is probably unrelated to this issue, but I would really recommend that you never use iommu=on option, otherwise you will end up with bad performances for your device.

[sboeuf]

@mythi also one more thing reading about initrd, it seems like it's usually part of the kernel command line. Could try adding it to the list of options?

# cat /mnt/boot/loader/entries/Clear-linux-kvm-5.3.7-396.conf
title Clear Linux OS
linux /EFI/org.clearlinux/kernel-org.clearlinux.kvm.5.3.7-396
options root=PARTUUID=9bf148d9-b4f3-4af9-8eb4-e16157593649 console=hvc0 console=tty0 console=ttyS0,115200n8 cryptomgr.notests init=/usr/lib/systemd/systemd-bootchart initcall_debug no_timer_check noreplace-smp page_alloc.shuffle=1 rootfstype=ext4,btrfs,xfs tsc=reliable rw initrd=/EFI/org.clearlinux/freestanding-qat-firmware.cpio.xz

[sboeuf]

But globally, you should try getting this to work without the firmware (direct kernel boot), so that you validate you can make it work.