Newly created standalone VMs don't start

[3hhh]

Qubes OS version:

4.0
debian 9 template (didn't test fedora)
4.14.35-1 kernel

Affected component(s):

standalone VMs

Steps to reproduce the behavior:

1. qvm-create --class StandaloneVM -l red stest

2. qvm-start stest

Expected behavior:

stest starts

Actual behavior:

stest fails to start

[    0.000000] Linux version 4.14.35-1.pvops.qubes.x86_64 (user@build-fedora4) (gcc version 6.4.1 20170727 (Red Hat 6.4.1-1) (GCC)) #1 SMP Sat Apr 21 15:51:26 UTC 2018
[    0.000000] Command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH rd.plymouth.enable=0 plymouth.enable=0 nopat
[    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] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000000a0000-0x00000000000fefff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000ff000-0x00000000000fffff] ACPI data
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000fa0003ff] usable
[    0.000000] BIOS-e820: [mem 0x00000000fc000000-0x00000000fc007fff] ACPI data
[    0.000000] x86/PAT: PAT support disabled.
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] DMI not present or invalid.
[    0.000000] Hypervisor detected: Xen HVM
[    0.000000] Xen version 4.8.
[    0.000000] Xen Platform PCI: unrecognised magic value
[    0.000000] tsc: Fast TSC calibration failed
[    0.000000] tsc: Unable to calibrate against PIT
[    0.000000] tsc: No reference (HPET/PMTIMER) available
[    0.000000] e820: last_pfn = 0xfa000 max_arch_pfn = 0x400000000
[    0.000000] MTRR: Disabled
[    0.000000] CPU MTRRs all blank - virtualized system.
[    0.000000] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC  
[    0.000000] RAMDISK: [mem 0x02aa5000-0x039e6fff]
[    0.000000] ACPI: Early table checksum verification disabled
[    0.000000] ACPI: RSDP 0x00000000000FFFC0 000024 (v02 Xen   )
[    0.000000] ACPI: XSDT 0x00000000FC007F70 000034 (v01 Xen    HVM      00000000 HVML 00000000)
[    0.000000] ACPI: FACP 0x00000000FC007D70 00010C (v05 Xen    HVM      00000000 HVML 00000000)
[    0.000000] ACPI: DSDT 0x00000000FC001050 006C9B (v05 Xen    HVM      00000000 INTL 20160831)
[    0.000000] ACPI: FACS 0x00000000FC001010 000040
[    0.000000] ACPI: FACS 0x00000000FC001010 000040
[    0.000000] ACPI: APIC 0x00000000FC007E80 00003C (v02 Xen    HVM      00000000 HVML 00000000)
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x00000000f9ffffff]
[    0.000000] NODE_DATA(0) allocated [mem 0xf9fd3000-0xf9ffdfff]
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x00000000f9ffffff]
[    0.000000]   Normal   empty
[    0.000000]   Device   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x00000000f9ffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x00000000f9ffffff]
[    0.000000] ACPI: No IOAPIC entries present
[    0.000000] Using ACPI for processor (LAPIC) configuration information
[    0.000000] smpboot: Allowing 2 CPUs, 0 hotplug CPUs
[    0.000000] e820: [mem 0xfc008000-0xffffffff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on Xen PVH
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.000000] random: fast init done
[    0.000000] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:2 nr_node_ids:1
[    0.000000] percpu: Embedded 44 pages/cpu @ffff8800f9c00000 s139864 r8192 d32168 u1048576
[    0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1007881
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH rd.plymouth.enable=0 plymouth.enable=0 nopat
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Memory: 3986588K/4095612K available (12300K kernel code, 1394K rwdata, 3756K rodata, 2536K init, 1280K bss, 109024K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.000000] Kernel/User page tables isolation: enabled
[    0.000000] ftrace: allocating 35244 entries in 138 pages
[    0.001000] Hierarchical RCU implementation.
[    0.001000] 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=2.
[    0.001000] 	Tasks RCU enabled.
[    0.001000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
[    0.001000] Using NULL legacy PIC
[    0.001000] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 0
[    0.001000] xen:events: Using FIFO-based ABI
[    0.001000] xen:events: Xen HVM callback vector for event delivery is enabled
[    0.001000] 	Offload RCU callbacks from CPUs: .
[    0.001000] Console: colour dummy device 80x25
[    0.001000] console [hvc0] enabled
[    0.001000] tsc: Fast TSC calibration failed
[    0.001000] tsc: Unable to calibrate against PIT
[    0.001000] tsc: No reference (HPET/PMTIMER) available
[    0.001000] tsc: Detected 2893.440 MHz processor
[    0.001000] Calibrating delay loop (skipped), value calculated using timer frequency.. 5786.88 BogoMIPS (lpj=2893440)
[    0.001000] pid_max: default: 32768 minimum: 301
[    0.001000] ACPI: Core revision 20170728
[    0.001000] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.001000] ACPI: setting ELCR to 0200 (from ffff)
[    0.001000] Security Framework initialized
[    0.001000] Yama: becoming mindful.
[    0.001000] AppArmor: AppArmor disabled by boot time parameter
[    0.001000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.001000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.001000] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.001000] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.001000] CPU: Physical Processor ID: 0
[    0.001000] CPU: Processor Core ID: 0
[    0.001000] mce: CPU supports 2 MCE banks
[    0.001000] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
[    0.001000] Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32, 1GB 0
[    0.001000] Spectre V2 : Mitigation: Full generic retpoline
[    0.001000] Spectre V2 : Spectre v2 mitigation: Enabling Indirect Branch Prediction Barrier
[    0.001000] Spectre V2 : Enabling Restricted Speculation for firmware calls
[    0.001000] Freeing SMP alternatives memory: 28K
[    0.001000] smpboot: Max logical packages: 1
[    0.001000] x2apic: IRQ remapping doesn't support X2APIC mode
[    0.001000] clocksource: xen: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.001000] installing Xen timer for CPU 0
[    0.001000] smpboot: CPU0: Intel(R) Core(TM) i5-3380M CPU @ 2.90GHz (family: 0x6, model: 0x3a, stepping: 0x9)
[    0.001000] cpu 0 spinlock event irq 5
[    0.001000] Performance Events: unsupported p6 CPU model 58 no PMU driver, software events only.
[    0.001987] Hierarchical SRCU implementation.
[    0.002710] NMI watchdog: Perf event create on CPU 0 failed with -2
[    0.002732] NMI watchdog: Perf NMI watchdog permanently disabled
[    0.003098] smp: Bringing up secondary CPUs ...
[    0.003302] installing Xen timer for CPU 1
[    0.003389] x86: Booting SMP configuration:
[    0.003404] .... node  #0, CPUs:      #1
[    0.006062] cpu 1 spinlock event irq 11
[    0.006093] smp: Brought up 1 node, 2 CPUs
[    0.006093] smpboot: Total of 2 processors activated (11573.76 BogoMIPS)
[    0.006292] devtmpfs: initialized
[    0.006292] x86/mm: Memory block size: 128MB
[    0.007493] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.007523] futex hash table entries: 512 (order: 3, 32768 bytes)
[    0.007637] pinctrl core: initialized pinctrl subsystem
[    0.027645] RTC time: 165:165:165, date: 165/165/65
[    0.028250] NET: Registered protocol family 16
[    0.028283] xen:grant_table: Grant tables using version 1 layout
[    0.028322] Grant table initialized
[    0.029139] cpuidle: using governor menu
[    0.029274] ACPI: bus type PCI registered
[    0.030023] PCI: Fatal: No config space access function found
[    0.032732] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.033144] ACPI: Added _OSI(Module Device)
[    0.033158] ACPI: Added _OSI(Processor Device)
[    0.033173] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.033186] ACPI: Added _OSI(Processor Aggregator Device)
[    0.033278] ACPI: SCI (ACPI GSI 9) not registered
[    0.043035] ACPI: Interpreter enabled
[    0.043058] ACPI: (supports S0)
[    0.043070] ACPI: Using platform specific model for interrupt routing
[    0.043115] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.043196] ACPI: GPE 0x02 active on init
[    0.043221] ACPI: Enabled 1 GPEs in block 00 to 0F
[    0.052008] xen:balloon: Initialising balloon driver
[    0.069089] vgaarb: loaded
[    0.070049] SCSI subsystem initialized
[    0.081223] ACPI: bus type USB registered
[    0.081283] usbcore: registered new interface driver usbfs
[    0.081316] usbcore: registered new interface driver hub
[    0.081384] usbcore: registered new device driver usb
[    0.082225] EDAC MC: Ver: 3.0.0
[    0.082466] dmi: Firmware registration failed.
[    0.083094] PCI: Using ACPI for IRQ routing
[    0.083120] PCI: System does not support PCI
[    0.083388] NetLabel: Initializing
[    0.083411] NetLabel:  domain hash size = 128
[    0.083438] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.083498] NetLabel:  unlabeled traffic allowed by default
[    0.083877] clocksource: Switched to clocksource xen
[    0.129378] VFS: Disk quotas dquot_6.6.0
[    0.129422] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.129530] pnp: PnP ACPI init
[    0.129627] pnp: PnP ACPI: found 0 devices
[    0.137081] NET: Registered protocol family 2
[    0.138442] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[    0.139396] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[    0.140205] TCP: Hash tables configured (established 32768 bind 32768)
[    0.140359] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[    0.141180] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[    0.141876] NET: Registered protocol family 1
[    0.141973] Unpacking initramfs...
[    0.158809] Freeing initrd memory: 15624K
[    0.165663] audit: initializing netlink subsys (disabled)
[    0.166440] Initialise system trusted keyrings
[    0.166620] Key type blacklist registered
[    0.166718] audit: type=2000 audit(1527843435.935:1): state=initialized audit_enabled=0 res=1
[    0.167061] workingset: timestamp_bits=36 max_order=20 bucket_order=0
[    0.169115] zbud: loaded
[    0.800788] NET: Registered protocol family 38
[    0.800831] Key type asymmetric registered
[    0.800858] Asymmetric key parser 'x509' registered
[    0.800990] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    0.801164] io scheduler noop registered
[    0.801193] io scheduler deadline registered
[    0.801330] io scheduler cfq registered (default)
[    0.801360] io scheduler mq-deadline registered
[    0.802148] atomic64_test: passed for x86-64 platform with CX8 and with SSE
[    0.803512] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[    0.808749] Non-volatile memory driver v1.3
[    0.808821] Linux agpgart interface v0.103
[    0.810206] libphy: Fixed MDIO Bus: probed
[    0.810383] usbcore: registered new interface driver usbserial
[    0.810437] usbcore: registered new interface driver usbserial_generic
[    0.810492] usbserial: USB Serial support registered for generic
[    0.810556] i8042: PNP: No PS/2 controller found.
[    0.810650] mousedev: PS/2 mouse device common for all mice
[    0.811195] device-mapper: uevent: version 1.0.3
[    0.811976] device-mapper: ioctl: 4.37.0-ioctl (2017-09-20) initialised: dm-devel@redhat.com
[    0.812592] dmi-sysfs: dmi entry is absent.
[    0.812624] hidraw: raw HID events driver (C) Jiri Kosina
[    0.812690] usbcore: registered new interface driver usbhid
[    0.812706] usbhid: USB HID core driver
[    0.812830] drop_monitor: Initializing network drop monitor service
[    0.812917] ip_tables: (C) 2000-2006 Netfilter Core Team
[    0.813662] Initializing XFRM netlink socket
[    0.814027] NET: Registered protocol family 10
[    0.819178] Segment Routing with IPv6
[    0.819307] mip6: Mobile IPv6
[    0.819419] NET: Registered protocol family 17
[    0.824297] RAS: Correctable Errors collector initialized.
[    0.824335] AVX version of gcm_enc/dec engaged.
[    0.824350] AES CTR mode by8 optimization enabled
[    0.840124] sched_clock: Marking stable (840010698, 0)->(225474366595, -224634355897)
[    0.841710] registered taskstats version 1
[    0.841911] Loading compiled-in X.509 certificates
[    0.842069] zswap: loaded using pool lzo/zbud
[    0.848439] Key type big_key registered
[    0.850874] Key type encrypted registered
[    0.851061] xenbus_probe_frontend: Device with no driver: device/vbd/51712
[    0.851246] xenbus_probe_frontend: Device with no driver: device/vbd/51728
[    0.851436] xenbus_probe_frontend: Device with no driver: device/vbd/51744
[    0.851659] xenbus_probe_frontend: Device with no driver: device/vbd/51760
[    0.851885] xenbus_probe_frontend: Device with no driver: device/vif/0
[    0.852052]   Magic number: 1:252:3141
[    0.852468] hctosys: unable to open rtc device (rtc0)
[    0.859808] Freeing unused kernel memory: 2536K
[    0.859845] Write protecting the kernel read-only data: 18432k
[    0.862958] Freeing unused kernel memory: 2024K
[    0.866831] Freeing unused kernel memory: 340K
[    0.867004] rodata_test: all tests were successful
Qubes initramfs script here:
[    0.881714] Invalid max_queues (4), will use default max: 2.
[    1.184061] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x29b50e612c8, max_idle_ns: 440795345256 ns
[    1.437873] blkfront: xvda: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.526551] blkfront: xvdb: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.702692] blkfront: xvdc: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.713781] blkfront: xvdd: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
Waiting for /dev/xvda* devices...
Qubes: Doing R/W setup for TemplateVM...
[    1.892729]  xvdc: xvdc1
Setting up swapspace version 1, size = 1024 MiB (1073737728 bytes)
no label, UUID=4e6a01e4-e348-4f47-ba79-cbe7180a4aed
Qubes: done.
mount: wrong fs type, bad option, bad superblock on /dev/xvda,
       missing codepage or helper program, or other error

       In some cases useful info is found in syslog - try
       dmesg | tail or so.
Waiting for /dev/xvdd device...
mount: /dev/xvdd is write-protected, mounting read-only
[    2.029332] EXT4-fs (xvdd): mounting ext3 file system using the ext4 subsystem
[    2.041466] EXT4-fs (xvdd): mounted filesystem with ordered data mode. Opts: (null)
mount: /sysroot not mounted or bad option

       In some cases useful info is found in syslog - try
       dmesg | tail or so.
mount: /sysroot not mounted or bad option

       In some cases useful info is found in syslog - try
       dmesg | tail or so.
switch_root: failed to mount moving /sysroot to /: Invalid argument
switch_root: failed. Sorry.
[    4.383012] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00000100
[    4.383012] 
[    4.383109] CPU: 0 PID: 1 Comm: switch_root Not tainted 4.14.35-1.pvops.qubes.x86_64 #1
[    4.383163] Call Trace:
[    4.383199]  dump_stack+0x5c/0x85
[    4.383238]  panic+0xe4/0x252
[    4.383276]  do_exit+0xba9/0xbb0
[    4.383325]  ? __do_page_fault+0x278/0x4f0
[    4.383380]  do_group_exit+0x3a/0xa0
[    4.383401]  SyS_exit_group+0x10/0x10
[    4.383422]  do_syscall_64+0x74/0x180
[    4.383443]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[    4.383495] RIP: 0033:0x7d29bc2a2bd8
[    4.383528] RSP: 002b:00007ffda6d353e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[    4.383607] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007d29bc2a2bd8
[    4.383691] RDX: 0000000000000001 RSI: 000000000000003c RDI: 0000000000000001
[    4.383723] RBP: 00007d29bc592860 R08: 00000000000000e7 R09: ffffffffffffff98
[    4.383777] R10: 0000000000000003 R11: 0000000000000246 R12: 00007d29bc592860
[    4.383829] R13: 00007d29bc597c00 R14: 0000000000000000 R15: 0000000000000000
[    4.384198] Kernel Offset: disabled

General notes:

Old standalone VMs still start.

I also tried two different kernels and HVM mode (instead of pvh above) - all failed.

Twice the log also mentioned something about the ext4 kernel module not being loaded / existing. Maybe the debian-9 template is missing something required for StandaloneVMs, but not for normal AppVMs?

Related issues:

#3017

[3hhh]

Hmmm ok:
qvm-clone --class StandaloneVM debian-9 stest2 works.

I had thought that this was identical and wonder what qvm-create --class StandaloneVM is then meant to be doing?

Btw stest size is shown as 0 by qubes-qube-manager, stest2 size as the size of debian-9.

[3hhh]

Hmmm ok:
qvm-clone --class StandaloneVM debian-9 stest2 works.

I had thought that this was identical and wonder what qvm-create --class StandaloneVM is then meant to be doing?

Btw stest size is shown as 0 by qubes-qube-manager, stest2 size as the size of debian-9.

[3hhh]

Ahh ok I get it:
qvm-create is for an empty VM for CD installation, qvm-clone for the copy. That is different from 3.2.

I.e. this can be handled as part of #3017.

[3hhh]

Ahh ok I get it:
qvm-create is for an empty VM for CD installation, qvm-clone for the copy. That is different from 3.2.

I.e. this can be handled as part of #3017.