Libguestfs - Oct 2018 - guestfs launch failed in CentOS 7.5

Hello,

I am using https://github.com/clalancette/oz/tree/v0.16.0 to customise
qcow2 images. In CentOS 7.5.1804 (yum updated to latest) the image
customisation fails during guestfs launch. Following is the output
of libguestfs-test-tool run. Please help in debugging the problem -


     ************************************************************
     *                    IMPORTANT NOTICE
     *
     * When reporting bugs, include the COMPLETE, UNEDITED
     * output below in your bug report.
     *
     ************************************************************
LIBGUESTFS_BACKEND=direct
PATH=/home/ciuser/gradle-2.4/bin:/home/ciuser/JAVA/jdk1.8.0_77/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/etc/oz:/home/ciuser/.local/bin:/home/ciuser/bin
XDG_RUNTIME_DIR=/run/user/1000
SELinux: Enforcing
guestfs_get_append: (null)
guestfs_get_autosync: 1
guestfs_get_backend: direct
guestfs_get_backend_settings: []
guestfs_get_cachedir: /var/tmp
guestfs_get_hv: /usr/libexec/qemu-kvm
guestfs_get_memsize: 500
guestfs_get_network: 0
guestfs_get_path: /usr/lib64/guestfs
guestfs_get_pgroup: 0
guestfs_get_program: libguestfs-test-tool
guestfs_get_recovery_proc: 1
guestfs_get_smp: 1
guestfs_get_sockdir: /run/user/1000
guestfs_get_tmpdir: /tmp
guestfs_get_trace: 0
guestfs_get_verbose: 1
host_cpu: x86_64
Launching appliance, timeout set to 600 seconds.
libguestfs: launch: program=libguestfs-test-tool
libguestfs: launch: version=1.36.10rhel=7,release=6.el7_5.2,libvirt
libguestfs: launch: backend registered: unix
libguestfs: launch: backend registered: uml
libguestfs: launch: backend registered: libvirt
libguestfs: launch: backend registered: direct
libguestfs: launch: backend=direct
libguestfs: launch: tmpdir=/tmp/libguestfsIHeKLD
libguestfs: launch: umask=0002
libguestfs: launch: euid=1000
libguestfs: begin building supermin appliance
libguestfs: run supermin
libguestfs: command: run: /usr/bin/supermin5
libguestfs: command: run: \ --build
libguestfs: command: run: \ --verbose
libguestfs: command: run: \ --if-newer
libguestfs: command: run: \ --lock /var/tmp/.guestfs-1000/lock
libguestfs: command: run: \ --copy-kernel
libguestfs: command: run: \ -f ext2
libguestfs: command: run: \ --host-cpu x86_64
libguestfs: command: run: \ /usr/lib64/guestfs/supermin.d
libguestfs: command: run: \ -o /var/tmp/.guestfs-1000/appliance.d
supermin: version: 5.1.19
supermin: rpm: detected RPM version 4.11
supermin: package handler: fedora/rpm
supermin: acquiring lock on /var/tmp/.guestfs-1000/lock
supermin: if-newer: output does not need rebuilding
libguestfs: finished building supermin appliance
libguestfs: begin testing qemu features
libguestfs: checking for previously cached test results of
/usr/libexec/qemu-kvm, in /var/tmp/.guestfs-1000
libguestfs: loading previously cached test results
libguestfs: QMP parse error: parse error: premature EOF\n
                     \n                     (right here) ------^\n (ignored)
libguestfs: qemu version: 1.5
libguestfs: qemu mandatory locking: no
libguestfs: finished testing qemu features
[00034ms] /usr/libexec/qemu-kvm \
    -global virtio-blk-pci.scsi=off \
    -nodefconfig \
    -enable-fips \
    -nodefaults \
    -display none \
    -machine accel=kvm:tcg \
    -cpu host \
    -m 500 \
    -no-reboot \
    -rtc driftfix=slew \
    -no-hpet \
    -global kvm-pit.lost_tick_policy=discard \
    -kernel /var/tmp/.guestfs-1000/appliance.d/kernel \
    -initrd /var/tmp/.guestfs-1000/appliance.d/initrd \
    -object rng-random,filename=/dev/urandom,id=rng0 \
    -device virtio-rng-pci,rng=rng0 \
    -device virtio-scsi-pci,id=scsi \
    -drive
file=/tmp/libguestfsIHeKLD/scratch1.img,cache=unsafe,format=raw,id=hd0,if=none
\
    -device scsi-hd,drive=hd0 \
    -drive
file=/var/tmp/.guestfs-1000/appliance.d/root,snapshot=on,id=appliance,cache=unsafe,if=none,format=raw
\
    -device scsi-hd,drive=appliance \
    -device virtio-serial-pci \
    -serial stdio \
    -device sga \
    -chardev
socket,path=/run/user/1000/libguestfsoBqGwV/guestfsd.sock,id=channel0 \
    -device virtserialport,chardev=channel0,name=org.libguestfs.channel.0 \
    -append 'panic=1 console=ttyS0 edd=off udevtimeout=6000
udev.event-timeout=6000 no_timer_check printk.time=1 cgroup_disable=memory
usbcore.nousb cryptomgr.notests tsc=reliable 8250.nr_uarts=1 root=/dev/sdb
selinux=0 guestfs_verbose=1 TERM=xterm'
\x1b[1;256r\x1b[256;256H\x1b[6n
Google, Inc.
Serial Graphics Adapter 06/09/14
SGABIOS $Id: sgabios.S 8 2010-04-22 00:03:40Z nlaredo $ (mockbuild@) Mon
Jun  9 21:33:48 UTC 2014
Term: 80x24
4 0
SeaBIOS (version 1.11.0-2.el7)
Booting from ROM...
\x1b[2J[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 3.10.0-862.14.4.el7.x86_64 (
mockbuild@kbuilder.bsys.centos.org) (gcc version 4.8.5 20150623 (Red Hat
4.8.5-28) (GCC) ) #1 SMP Wed Sep 26 15:12:11 UTC 2018
[    0.000000] Command line: panic=1 console=ttyS0 edd=off udevtimeout=6000
udev.event-timeout=6000 no_timer_check printk.time=1 cgroup_disable=memory
usbcore.nousb cryptomgr.notests tsc=reliable 8250.nr_uarts=1 root=/dev/sdb
selinux=0 guestfs_verbose=1 TERM=xterm
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009f7ff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009f800-0x000000000009ffff]
reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff]
reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000001f3fbfff] usable
[    0.000000] BIOS-e820: [mem 0x000000001f3fc000-0x000000001f3fffff]
reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff]
reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff]
reserved
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.4 present.
[    0.000000] Hypervisor detected: KVM
[    0.000000] e820: last_pfn = 0x1f3fc max_arch_pfn = 0x400000000
[    0.000000] PAT configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- UC
[    0.000000] found SMP MP-table at [mem 0x000f63b0-0x000f63bf] mapped at
[ffffffffff2003b0]
[    0.000000] RAMDISK: [mem 0x1f0c0000-0x1f3effff]
[    0.000000] Early table checksum verification disabled
[    0.000000] ACPI: RSDP 00000000000f6210 00014 (v00 BOCHS )
[    0.000000] ACPI: RSDT 000000001f3ffad7 00030 (v01 BOCHS  BXPCRSDT
00000001 BXPC 00000001)
[    0.000000] ACPI: FACP 000000001f3ff177 00074 (v01 BOCHS  BXPCFACP
00000001 BXPC 00000001)
[    0.000000] ACPI: DSDT 000000001f3fe040 01137 (v01 BOCHS  BXPCDSDT
00000001 BXPC 00000001)
[    0.000000] ACPI: FACS 000000001f3fe000 00040
[    0.000000] ACPI: SSDT 000000001f3ff1eb 00874 (v01 BOCHS  BXPCSSDT
00000001 BXPC 00000001)
[    0.000000] ACPI: APIC 000000001f3ffa5f 00078 (v01 BOCHS  BXPCAPIC
00000001 BXPC 00000001)
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000001f3fbfff]
[    0.000000] NODE_DATA(0) allocated [mem 0x1f099000-0x1f0bffff]
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 0:1f049001, primary cpu clock
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x00001000-0x00ffffff]
[    0.000000]   DMA32    [mem 0x01000000-0xffffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x00001000-0x0009efff]
[    0.000000]   node   0: [mem 0x00100000-0x1f3fbfff]
[    0.000000] Initmem setup node 0 [mem 0x00001000-0x1f3fbfff]
[    0.000000] ACPI: PM-Timer IO Port: 0x608
[    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.000000] ACPI: IOAPIC (id[0x00] address[0xfec00000] gsi_base[0])
[    0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI
0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
[    0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
[    0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[    0.000000] e820: [mem 0x1f400000-0xfeffbfff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on KVM
[    0.000000] setup_percpu: NR_CPUS:5120 nr_cpumask_bits:1 nr_cpu_ids:1
nr_node_ids:1
[    0.000000] PERCPU: Embedded 35 pages/cpu @ffff93c95ee00000 s104920
r8192 d30248 u2097152
[    0.000000] KVM setup async PF for cpu 0
[    0.000000] kvm-stealtime: cpu 0, msr 1ee13500
[    0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.
Total pages: 125877
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: panic=1 console=ttyS0 edd=off
udevtimeout=6000 udev.event-timeout=6000 no_timer_check printk.time=1
cgroup_disable=memory usbcore.nousb cryptomgr.notests tsc=reliable
8250.nr_uarts=1 root=/dev/sdb selinux=0 guestfs_verbose=1 TERM=xterm
[    0.000000] Disabling memory control group subsystem
[    0.000000] PID hash table entries: 2048 (order: 2, 16384 bytes)
[    0.000000] x86/fpu: xstate_offset[2]: 0240, xstate_sizes[2]: 0100
[    0.000000] xsave: enabled xstate_bv 0x7, cntxt size 0x340 using
standard form
[    0.000000] Memory: 480520k/511984k available (7348k kernel code, 392k
absent, 31072k reserved, 6281k data, 1844k init)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] x86/pti: Unmapping kernel while in userspace
[    0.000000] Hierarchical RCU implementation.
[    0.000000] \tRCU restricting CPUs from NR_CPUS=5120 to nr_cpu_ids=1.
[    0.000000] NR_IRQS:327936 nr_irqs:256 0
[    0.000000] Console: colour *CGA 80x25
[    0.000000] console [ttyS0] enabled
[    0.000000] tsc: Detected 2494.218 MHz processor
[    0.098000] Calibrating delay loop (skipped) preset value.. 4988.43
BogoMIPS (lpj=2494218)
[    0.104230] pid_max: default: 32768 minimum: 301
[    0.110254] Security Framework initialized
[    0.116237] SELinux:  Disabled at boot.
[    0.117234] Yama: becoming mindful.
[    0.131312] Dentry cache hash table entries: 65536 (order: 7, 524288
bytes)
[    0.141311] Inode-cache hash table entries: 32768 (order: 6, 262144
bytes)
[    0.153253] Mount-cache hash table entries: 1024 (order: 1, 8192 bytes)
[    0.157238] Mountpoint-cache hash table entries: 1024 (order: 1, 8192
bytes)
[    0.162358] Initializing cgroup subsys memory
[    0.168236] Initializing cgroup subsys devices
[    0.192231] Initializing cgroup subsys freezer
[    0.211226] Initializing cgroup subsys net_cls
[    0.229237] Initializing cgroup subsys blkio
[    0.240227] Initializing cgroup subsys perf_event
[    0.242232] Initializing cgroup subsys hugetlb
[    0.256002] random: fast init done
[    0.281241] Initializing cgroup subsys pids
[    0.297210] Initializing cgroup subsys net_prio
[    0.857224] mce: CPU supports 10 MCE banks
[    1.161221] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    1.175212] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0
[    1.189209] tlb_flushall_shift: 6
[    1.198225] Speculative Store Bypass: Vulnerable
[    1.206223] FEATURE SPEC_CTRL Not Present
[    1.218208] FEATURE IBPB_SUPPORT Not Present
[    4.853233] Spectre V2 : Vulnerable: Retpoline without IBPB
[   13.376012] random: crng init done
[  101.375237] Freeing SMP alternatives: 24k freed
[  110.720007] BUG: unable to handle kernel NULL pointer dereference at
0000000000000102
[  110.721000] IP: [<ffffffffad8b3ef2>] __queue_work+0x32/0x3e0
[  110.721000] PGD 0
[  110.721000] Oops: 0000 [#1] SMP
[  110.721000] Modules linked in:
[  110.721000] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
3.10.0-862.14.4.el7.x86_64 #1
[  110.721000] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
[  110.721000] task: ffffffffae416480 ti: ffffffffae400000 task.ti:
ffffffffae400000
[  110.721000] RIP: 0010:[<ffffffffad8b3ef2>]  [<ffffffffad8b3ef2>]
__queue_work+0x32/0x3e0
[  110.721000] RSP: 0000:ffff93c95ee03e20  EFLAGS: 00010046
[  110.721000] RAX: 0000000000000082 RBX: 0000000000000087 RCX:
0000000000000000
[  110.721000] RDX: ffffffffae4e0340 RSI: 0000000000000000 RDI:
0000000000001400
[  110.721000] RBP: ffff93c95ee03e58 R08: 0000000000000000 R09:
0000000000004000
[  110.721000] R10: ffffffffaea17998 R11: 0000000000007ffe R12:
ffffffffae4e0340
[  110.721000] R13: 0000000000001400 R14: 0000000000000000 R15:
ffffffffae2b3a62
[  110.721000] FS:  0000000000000000(0000) GS:ffff93c95ee00000(0000)
knlGS:0000000000000000
[  110.721000] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  110.721000] CR2: 0000000000000102 CR3: 000000001200e000 CR4:
00000000001606f0
[  110.721000] Call Trace:
[  110.721000]  <IRQ>
[  110.721000]  [<ffffffffad8b44f5>] queue_work_on+0x45/0x50
[  110.721000]  [<ffffffffadc564d6>] credit_entropy_bits+0x1c6/0x290
[  110.721000]  [<ffffffffadc571c4>] ?
add_interrupt_randomness+0x1c4/0x230
[  110.721000]  [<ffffffffadc571c4>] add_interrupt_randomness+0x1c4/0x230
[  110.721000]  [<ffffffffad943f7f>] handle_irq_event_percpu+0x3f/0x80
[  110.721000]  [<ffffffffad943ffc>] handle_irq_event+0x3c/0x60
[  110.721000]  [<ffffffffad9470a3>] handle_level_irq+0x73/0xd0
[  110.721000]  [<ffffffffad82e504>] handle_irq+0xe4/0x1a0
[  110.721000]  [<ffffffffad89cf08>] ? __local_bh_enable+0x28/0x90
[  110.721000]  [<ffffffffadf29f9d>] do_IRQ+0x4d/0xf0
[  110.721000]  [<ffffffffadf28c83>] ? simd_coprocessor_error+0x3/0x30
[  110.721000]  [<ffffffffadf1c362>] common_interrupt+0x162/0x162
[  110.721000]  <EOI>
[  110.721000]  [<ffffffffad877b80>] ? __native_set_fixmap+0x40/0x40
[  110.721000]  [<ffffffffad86b14c>] ?
end_pv_cpu_ops_usergs_sysret32+0x3/0x3
[  110.721000]  [<ffffffffadf28c83>] ? simd_coprocessor_error+0x3/0x30
[  110.721000]  [<ffffffffad86a4b6>] ? native_restore_fl+0x6/0x10
[  110.721000]  [<ffffffffad833126>] text_poke_early+0x36/0x40
[  110.721000]  [<ffffffffad833383>] apply_paravirt+0xb3/0xe0
[  110.721000]  [<ffffffffad8973f4>] ? vprintk_emit+0x3c4/0x510
[  110.721000]  [<ffffffffad9a00e6>] ? free_hot_cold_page+0x106/0x160
[  110.721000]  [<ffffffffad99bc6d>] ? adjust_managed_page_count+0x5d/0x80
[  110.721000]  [<ffffffffad86fc6a>] ? free_init_pages+0x15a/0x1b0
[  110.721000]  [<ffffffffae579537>] alternative_instructions+0xc3/0xca
[  110.721000]  [<ffffffffae57b0cb>] check_bugs+0x25f/0x2b6
[  110.721000]  [<ffffffffae56c19d>] start_kernel+0x422/0x46c
[  110.721000]  [<ffffffffae56bb7b>] ? repair_env_string+0x5c/0x5c
[  110.721000]  [<ffffffffae56b120>] ? early_idt_handler_array+0x120/0x120
[  110.721000]  [<ffffffffae56b72f>] x86_64_start_reservations+0x24/0x26
[  110.721000]  [<ffffffffae56b885>] x86_64_start_kernel+0x154/0x177
[  110.721000]  [<ffffffffad8000d5>] start_cpu+0x5/0x14
[  110.721000] Code: 89 e5 41 57 41 56 49 89 f6 41 55 41 89 fd 41 54 49 89
d4 53 48 83 ec 10 89 7d d4 ff 14 25 00 07 43 ae f6 c4 02 0f 85 de 02 00 00
<41> f6 86 02 01 00 00 01 0f 85 78 02 00 00 49 c7 c7 08 5a 01 00
[  110.721000] RIP  [<ffffffffad8b3ef2>] __queue_work+0x32/0x3e0
[  110.721000]  RSP <ffff93c95ee03e20>
[  110.721000] CR2: 0000000000000102
[  110.721000] ---[ end trace aaa07a7d70f6c07b ]---
[  110.721000] Kernel panic - not syncing: Fatal exception in interrupt
[  110.721000] Rebooting in 1 seconds..libguestfs: error: appliance closed
the connection unexpectedly, see earlier error messages
libguestfs: child_cleanup: 0x55690ed44c60: child process died
libguestfs: sending SIGTERM to process 31847
libguestfs: qemu maxrss 96256K
libguestfs: error: guestfs_launch failed, see earlier error messages
libguestfs: closing guestfs handle 0x55690ed44c60 (state 0)
libguestfs: command: run: rm
libguestfs: command: run: \ -rf /tmp/libguestfsIHeKLD
libguestfs: command: run: rm
libguestfs: command: run: \ -rf /run/user/1000/libguestfsoBqGwV


This is running on a VM with nested virtualization enabled.
rpm -qa | grep kernel
kernel-tools-3.10.0-862.14.4.el7.x86_64
kernel-tools-libs-3.10.0-862.14.4.el7.x86_64
kernel-3.10.0-862.14.4.el7.x86_64
kernel-3.10.0-862.el7.x86_64
kernel-3.10.0-862.9.1.el7.x86_64

rpm -qa | grep supermin
supermin5-5.1.19-1.el7.x86_64


Possibly similar issue reported in CentOS
https://bugzilla.redhat.com/show_bug.cgi?id=1535973 ?

Thanks,
Sarbajit

Thanks for the detailed debugging information.  I believe you are
hitting this bug:

https://bugzilla.redhat.com/show_bug.cgi?id=1613277#c7

This was a bug in qemu-kvm-rhev-2.12.0-11.el7.x86_64 and should be
fixed in qemu-kvm-rhev-2.12.0 >= -13.el7.x86_64 which will be
available in RHEL 7.6 very soon.
> Possibly similar issue reported in CentOS
> https://bugzilla.redhat.com/show_bug.cgi?id=1535973 ?
No I think that's something else.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-top is 'top' for virtual machines.  Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://people.redhat.com/~rjones/virt-top

Thanks for the response. One question I have is - my host machine is
running CentOS 7.5 and the guest image is based on RHEL 7.5. I did check
following on the host machine and there is no package called qemu-kvm-rhev
installed.

rpm -qa | grep qemu-kvm
qemu-kvm-1.5.3-156.el7_5.5.x86_64
qemu-kvm-common-1.5.3-156.el7_5.5.x86_64

Same results for RHEL 7.5 guest VM, it doesn't have qemu-kvm-rhev
installed. Though the bug mentioned by you (id = 1613277) looks similar, it
is reported on RHEL 7.6.
Is it same for CentOS 7.5 as well? And will there be a fix for CentOS based
systems?

Thanks,
Sarbajit


On Tue, Oct 30, 2018 at 12:42 AM Richard W.M. Jones <rjones@redhat.com>
wrote:
> Thanks for the detailed debugging information.  I believe you are
> hitting this bug:
>
> https://bugzilla.redhat.com/show_bug.cgi?id=1613277#c7
>
> This was a bug in qemu-kvm-rhev-2.12.0-11.el7.x86_64 and should be
> fixed in qemu-kvm-rhev-2.12.0 >= -13.el7.x86_64 which will be
> available in RHEL 7.6 very soon.
>
> > Possibly similar issue reported in CentOS
> > https://bugzilla.redhat.com/show_bug.cgi?id=1535973 ?
>
> No I think that's something else.
>
> Rich.
>
> --
> Richard Jones, Virtualization Group, Red Hat
> http://people.redhat.com/~rjones
> Read my programming and virtualization blog: http://rwmj.wordpress.com
> virt-top is 'top' for virtual machines.  Tiny program with many
> powerful monitoring features, net stats, disk stats, logging, etc.
> http://people.redhat.com/~rjones/virt-top
>