Bug 1345964 - qemu / kernel hangs when loading ata_piix.ko kernel module when using nested KVM
Summary: qemu / kernel hangs when loading ata_piix.ko kernel module when using nested KVM
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: qemu-kvm-rhev
Version: 7.2
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: rc
: 7.2
Assignee: Hai Huang
QA Contact: Virtualization Bugs
URL:
Whiteboard:
Depends On:
Blocks: TRACKER-bugs-affecting-libguestfs
TreeView+ depends on / blocked
 
Reported: 2016-06-13 14:04 UTC by Matt Flusche
Modified: 2016-06-14 13:50 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-06-14 07:28:06 UTC
Target Upstream Version:


Attachments (Terms of Use)

Description Matt Flusche 2016-06-13 14:04:27 UTC
Description of problem:
In the Red Hat Ravello training environment for Openstack we are having issues with instances taking excessive time to launch.  

We see the following in the Nova Compute debug logs:

2016-06-10 18:51:45.050 10785 WARNING nova.virt.disk.api [req-252af4f0-6f37-43be-b4cd-5018353ccfe8 2da0a755cd244db8835b2b35bcc9fece 4d3c12
75b7f741c5beba7a40172c5214 - - -] Unable to mount image /var/lib/nova/instances/95162d34-db8a-405f-ba80-b5f143463107/disk with error libgu
estfs installed but not usable (guestfs_launch failed.
This usually means the libguestfs appliance failed to start or crashed.
See http://libguestfs.org/guestfs-faq.1.html#debugging-libguestfs
or run 'libguestfs-test-tool' and post the *complete* output into a
bug report or message to the libguestfs mailing list.). Cannot resize.
2016-06-10 18:51:45.051 10785 DEBUG oslo_concurrency.lockutils [req-252af4f0-6f37-43be-b4cd-5018353ccfe8 2da0a755cd244db8835b2b35bcc9fece 
4d3c1275b7f741c5beba7a40172c5214 - - -] Releasing file lock "/var/lib/nova/instances/locks/nova-bf4bacec6d4bc0e05d7dc35d5555269a517c4427" 
after holding it for 3997.506s release /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:227
2016-06-10 18:51:45.052 10785 DEBUG oslo_concurrency.lockutils [req-252af4f0-6f37-43be-b4cd-5018353ccfe8 2da0a755cd244db8835b2b35bcc9fece 4d3c1275b7f741c5beba7a40172c5214 - - -] Lock "bf4bacec6d4bc0e05d7dc35d5555269a517c4427" released by "copy_qcow2_image" :: held 3997.507s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:456



Version-Release number of selected component (if applicable):
libguestfs-1.28.1-1.55.el7_2.4.x86_64

How reproducible:
100% in Ravello environment


Steps to Reproduce:
1. Launch VM instance in this specific Ravello Openstack training environment
2.
3.

Actual results:

Instances will take about 90 minutes to launch.

Expected results:

Instances launch in several seconds.

Additional info:

# libguestfs-test-tool 
     ************************************************************
     *                    IMPORTANT NOTICE
     *
     * When reporting bugs, include the COMPLETE, UNEDITED
     * output below in your bug report.
     *
     ************************************************************
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin
SELinux: Enforcing
guestfs_get_append: (null)
guestfs_get_autosync: 1
guestfs_get_backend: libvirt
guestfs_get_backend_settings: []
guestfs_get_cachedir: /var/tmp
guestfs_get_direct: 0
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_selinux: 0
guestfs_get_smp: 1
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.28.1rhel=7,release=1.55.el7_2.4,libvirt
libguestfs: launch: backend registered: unix
libguestfs: launch: backend registered: uml
libguestfs: launch: backend registered: libvirt
libguestfs: launch: backend registered: direct
libguestfs: launch: backend=libvirt
libguestfs: launch: tmpdir=/tmp/libguestfsaABnL2
libguestfs: launch: umask=0022
libguestfs: launch: euid=0
libguestfs: libvirt version = 1002017 (1.2.17)
libguestfs: guest random name = guestfs-d1q9u0g3eu656mmn
libguestfs: [00001ms] connect to libvirt
libguestfs: opening libvirt handle: URI = qemu:///system, auth = default+wrapper, flags = 0
libguestfs: successfully opened libvirt handle: conn = 0x7f01daff5b90
libguestfs: qemu version (reported by libvirt) = 2003000 (2.3.0)
libguestfs: [00013ms] get libvirt capabilities
libguestfs: [00021ms] parsing capabilities XML
libguestfs: [00023ms] build appliance
libguestfs: [00024ms] begin building supermin appliance
libguestfs: [00024ms] 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-0/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-0/appliance.d
supermin: version: 5.1.10
supermin: rpm: detected RPM version 4.11
supermin: package handler: fedora/rpm
supermin: acquiring lock on /var/tmp/.guestfs-0/lock
supermin: if-newer: output does not need rebuilding
libguestfs: [00084ms] finished building supermin appliance
libguestfs: command: run: qemu-img
libguestfs: command: run: \ create
libguestfs: command: run: \ -f qcow2
libguestfs: command: run: \ -o backing_file=/var/tmp/.guestfs-0/appliance.d/root,backing_fmt=raw
libguestfs: command: run: \ /tmp/libguestfsaABnL2/overlay2
Formatting '/tmp/libguestfsaABnL2/overlay2', fmt=qcow2 size=4294967296 backing_file='/var/tmp/.guestfs-0/appliance.d/root' backing_fmt='raw' encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
libguestfs: [00219ms] create libvirt XML
libguestfs: libvirt XML:\n<?xml version="1.0"?>\n<domain type="kvm" xmlns:qemu="http://libvirt.org/schemas/domain/qemu/1.0">\n  <name>guestfs-d1q9u0g3eu656mmn</name>\n  <memory unit="MiB">500</memory>\n  <currentMemory unit="MiB">500</currentMemory>\n  <cpu mode="host-passthrough">\n    <model fallback="allow"/>\n  </cpu>\n  <vcpu>1</vcpu>\n  <clock offset="utc">\n    <timer name="rtc" tickpolicy="catchup"/>\n    <timer name="pit" tickpolicy="delay"/>\n    <timer name="hpet" present="no"/>\n  </clock>\n  <os>\n    <type>hvm</type>\n    <kernel>/var/tmp/.guestfs-0/appliance.d/kernel</kernel>\n    <initrd>/var/tmp/.guestfs-0/appliance.d/initrd</initrd>\n    <cmdline>panic=1 console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1 TERM=xterm-256color</cmdline>\n    <bios useserial="yes"/>\n  </os>\n  <on_reboot>destroy</on_reboot>\n  <devices>\n    <controller type="scsi" index="0" model="virtio-scsi"/>\n    <disk device="disk" type="file">\n      <source file="/tmp/libguestfsaABnL2/scratch.1"/>\n      <target dev="sda" bus="scsi"/>\n      <driver name="qemu" type="raw" cache="unsafe"/>\n      <address type="drive" controller="0" bus="0" target="0" unit="0"/>\n    </disk>\n    <disk type="file" device="disk">\n      <source file="/tmp/libguestfsaABnL2/overlay2"/>\n      <target dev="sdb" bus="scsi"/>\n      <driver name="qemu" type="qcow2" cache="unsafe"/>\n      <address type="drive" controller="0" bus="0" target="1" unit="0"/>\n      <shareable/>\n    </disk>\n    <serial type="unix">\n      <source mode="connect" path="/tmp/libguestfsaABnL2/console.sock"/>\n      <target port="0"/>\n    </serial>\n    <channel type="unix">\n      <source mode="connect" path="/tmp/libguestfsaABnL2/guestfsd.sock"/>\n      <target type="virtio" name="org.libguestfs.channel.0"/>\n    </channel>\n  </devices>\n  <qemu:commandline>\n    <qemu:env name="TMPDIR" value="/var/tmp"/>\n  </qemu:commandline>\n</domain>\n
libguestfs: command: run: ls
libguestfs: command: run: \ -a
libguestfs: command: run: \ -l
libguestfs: command: run: \ -Z /var/tmp/.guestfs-0
libguestfs: drwxr-xr-x. root root unconfined_u:object_r:user_tmp_t:s0 .
libguestfs: drwxrwxrwt. root root system_u:object_r:tmp_t:s0       ..
libguestfs: drwxr-xr-x. root root unconfined_u:object_r:user_tmp_t:s0 appliance.d
libguestfs: -rw-r--r--. root root unconfined_u:object_r:user_tmp_t:s0 lock
libguestfs: command: run: ls
libguestfs: command: run: \ -a
libguestfs: command: run: \ -l
libguestfs: command: run: \ -Z /tmp/libguestfsaABnL2
libguestfs: drwxr-xr-x. root root unconfined_u:object_r:user_tmp_t:s0 .
libguestfs: drwxrwxrwt. root root system_u:object_r:tmp_t:s0       ..
libguestfs: srw-rw----. root qemu unconfined_u:object_r:user_tmp_t:s0 console.sock
libguestfs: srw-rw----. root qemu unconfined_u:object_r:user_tmp_t:s0 guestfsd.sock
libguestfs: -rw-r--r--. root root unconfined_u:object_r:user_tmp_t:s0 overlay2
libguestfs: -rw-r--r--. root root unconfined_u:object_r:user_tmp_t:s0 scratch.1
libguestfs: -rwxr-xr-x. root root unconfined_u:object_r:user_tmp_t:s0 umask-check
libguestfs: [00251ms] launch libvirt guest
\x1b[1;256r\x1b[256;256H\x1b[6n
Google, Inc.
Serial Graphics Adapter 12/29/13
SGABIOS $Id: sgabios.S 8 2010-04-22 00:03:40Z nlaredo $ (mockbuild@) Sun Dec 29 03:43:06 UTC 2013
Term: 80x24
4 0
SeaBIOS (version seabios-1.7.5-11.el7)
Machine UUID 6512843e-b1b0-5d4e-8564-bfac084319e0
Booting from ROM...
Probing EDD (edd=off to disable)... ok
\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-327.10.1.el7.x86_64 (mockbuild@x86-021.build.eng.bos.redhat.com) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-4) (GCC) ) #1 SMP Sat Jan 23 04:54:55 EST 2016
[    0.000000] Command line: panic=1 console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1 TERM=xterm-256color
[    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-0x000000001f3fffff] usable
[    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.8 present.
[    0.000000] Hypervisor detected: KVM
[    0.000000] AGP: No AGP bridge found
[    0.000000] e820: last_pfn = 0x1f400 max_arch_pfn = 0x400000000
[    0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[    0.000000] found SMP MP-table at [mem 0x000f2060-0x000f206f] mapped at [ffff8800000f2060]
[    0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
[    0.000000] init_memory_mapping: [mem 0x1ee00000-0x1effffff]
[    0.000000] init_memory_mapping: [mem 0x1c000000-0x1edfffff]
[    0.000000] init_memory_mapping: [mem 0x00100000-0x1bffffff]
[    0.000000] init_memory_mapping: [mem 0x1f000000-0x1f3fffff]
[    0.000000] RAMDISK: [mem 0x1f0d0000-0x1f3fffff]
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000001f3fffff]
[    0.000000] Initmem setup node 0 [mem 0x00000000-0x1f3fffff]
[    0.000000]   NODE_DATA [mem 0x1f0a9000-0x1f0cffff]
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 0:1f059001, 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-0x1f3fffff]
[    0.000000] SFI: Simple Firmware Interface v0.81 http://simplefirmware.org
[    0.000000] Intel MultiProcessor Specification v1.4
[    0.000000] MPTABLE: OEM ID: BOCHSCPU
[    0.000000] MPTABLE: Product ID: 0.1         
[    0.000000] MPTABLE: APIC at: 0xFEE00000
[    0.000000] Processor #0 (Bootup-CPU)
[    0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.000000] Processors: 1
[    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 31 pages/cpu @ffff88001ee00000 s87168 r8192 d31616 u2097152
[    0.000000] KVM setup async PF for cpu 0
[    0.000000] kvm-stealtime: cpu 0, msr 1ee0d240
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 125881
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: panic=1 console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1 TERM=xterm-256color
[    0.000000] Disabling memory control group subsystem
[    0.000000] PID hash table entries: 2048 (order: 2, 16384 bytes)
[    0.000000] AGP: Checking aperture...
[    0.000000] AGP: No AGP bridge found
[    0.000000] Memory: 483644k/512000k available (6440k kernel code, 392k absent, 27964k reserved, 4266k data, 1620k init)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] \tRCU restricting CPUs from NR_CPUS=5120 to nr_cpu_ids=1.
[    0.000000] \tOffload RCU callbacks from all CPUs
[    0.000000] \tOffload RCU callbacks from CPUs: 0.
[    0.000000] NR_IRQS:327936 nr_irqs:256 0
[    0.000000] Console: colour *CGA 80x25
[    0.000000] console [ttyS0] enabled
[    0.000000] tsc: Detected 2499.998 MHz processor
[    0.006000] Calibrating delay loop (skipped) preset value.. 4999.99 BogoMIPS (lpj=2499998)
[    0.007138] pid_max: default: 32768 minimum: 301
[    0.009568] Security Framework initialized
[    0.012621] SELinux:  Disabled at boot.
[    0.015769] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.018367] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes)
[    0.020391] Mount-cache hash table entries: 4096
[    0.030344] Initializing cgroup subsys memory
[    0.032141] Initializing cgroup subsys devices
[    0.033281] Initializing cgroup subsys freezer
[    0.034239] Initializing cgroup subsys net_cls
[    0.035113] Initializing cgroup subsys blkio
[    0.036099] Initializing cgroup subsys perf_event
[    0.037122] Initializing cgroup subsys hugetlb
[    0.042230] mce: CPU supports 10 MCE banks
[    0.044530] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.044530] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.044530] tlb_flushall_shift: -1
[    0.264711] Freeing SMP alternatives: 28k freed
[    0.323528] ftrace: allocating 24591 entries in 97 pages
[    0.367000] Enabling x2apic
[    0.367000] Enabled x2apic
[    0.368168] Switched APIC routing to physical x2apic.
[    0.388732] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.389154] smpboot: CPU0: AMD Intel(R) Xeon(R) CPU @ 2.50GHz (fam: 06, model: 3e, stepping: 04)
[    0.395000] Performance Events: AMD PMU driver.
[    0.395000] ... version:                0
[    0.395000] ... bit width:              48
[    0.395000] ... generic registers:      4
[    0.395000] ... value mask:             0000ffffffffffff
[    0.395000] ... max period:             00007fffffffffff
[    0.395000] ... fixed-purpose events:   0
[    0.395000] ... event mask:             000000000000000f
[    0.395000] KVM setup paravirtual spinlock
[    0.395000] Brought up 1 CPUs
[    0.395000] smpboot: Total of 1 processors activated (4999.99 BogoMIPS)
[    0.395000] NMI watchdog: disabled (cpu0): hardware events not enabled
[    0.395000] devtmpfs: initialized
[    0.395000] EVM: security.selinux
[    0.395000] EVM: security.ima
[    0.395000] EVM: security.capability
[    0.395000] atomic64 test passed for x86-64 platform with CX8 and with SSE
[    0.395000] NET: Registered protocol family 16
[    0.395000] PCI: Using configuration type 1 for base access
[    0.395000] ACPI: Interpreter disabled.
[    0.395000] vgaarb: loaded
[    0.395000] SCSI subsystem initialized
[    0.395000] usbcore: registered new interface driver usbfs
[    0.395000] usbcore: registered new interface driver hub
[    0.395000] usbcore: registered new device driver usb
[    0.395000] PCI: Probing PCI hardware
[    0.395000] PCI host bridge to bus 0000:00
[    0.395000] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[    0.395000] pci_bus 0000:00: root bus resource [mem 0x00000000-0x3fffffffffff]
[    0.395000] pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
[    0.395000] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
[    0.395000] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
[    0.395000] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
[    0.395000] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
[    0.395000] pci 0000:00:01.0: PIIX/ICH IRQ router [8086:7000]
[    0.395000] NetLabel: Initializing
[    0.395000] NetLabel:  domain hash size = 128
[    0.395000] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.395000] NetLabel:  unlabeled traffic allowed by default
[    0.395000] Switching to clocksource kvm-clock
[    0.395000] pnp: PnP ACPI: disabled
[    0.395000] NET: Registered protocol family 2
[    0.395000] TCP established hash table entries: 4096 (order: 3, 32768 bytes)
[    0.395000] TCP bind hash table entries: 4096 (order: 4, 65536 bytes)
[    0.395000] TCP: Hash tables configured (established 4096 bind 4096)
[    0.395000] TCP: reno registered
[    0.395000] UDP hash table entries: 256 (order: 1, 8192 bytes)
[    0.395000] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
[    0.395000] NET: Registered protocol family 1
[    0.395000] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.395000] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[    0.395000] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    0.395000] pci 0000:00:01.2: PCI->APIC IRQ transform: INT D -> IRQ 25
[    0.395000] Unpacking initramfs...
[    0.395000] Freeing initrd memory: 3264k freed
[    0.395000] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    0.395000] microcode: AMD CPU family 0x6 not supported
[    0.395000] sha1_ssse3: Neither AVX nor AVX2 nor SSSE3 is available/usable.
[    0.395000] sha256_ssse3: Neither AVX nor SSSE3 is available/usable.
[    0.395000] futex hash table entries: 256 (order: 2, 16384 bytes)
[    0.395000] Initialise system trusted keyring
[    0.395000] audit: initializing netlink socket (disabled)
[    0.395000] type=2000 audit(1466080899.084:1): initialized
[    0.395000] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.395000] zpool: loaded
[    0.395000] zbud: loaded
[    0.395000] VFS: Disk quotas dquot_6.5.2
[    0.395000] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.395000] msgmni has been set to 951
[    0.395000] Key type big_key registered
[    0.395000] NET: Registered protocol family 38
[    0.395000] Key type asymmetric registered
[    0.395000] Asymmetric key parser 'x509' registered
[    0.395000] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    0.395000] io scheduler noop registered
[    0.395000] io scheduler deadline registered (default)
[    0.395000] io scheduler cfq registered
[    0.395000] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.395000] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.395000] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.395000] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.395000] Non-volatile memory driver v1.3
[    0.395000] Linux agpgart interface v0.103
[    0.395000] crash memory driver: version 1.1
[    0.395000] rdac: device handler registered
[    0.395000] hp_sw: device handler registered
[    0.395000] emc: device handler registered
[    0.395000] alua: device handler registered
[    0.395000] libphy: Fixed MDIO Bus: probed
[    0.395000] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.395000] ehci-pci: EHCI PCI platform driver
[    0.395000] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.395000] ohci-pci: OHCI PCI platform driver
[    0.395000] uhci_hcd: USB Universal Host Controller Interface driver
[    0.395000] uhci_hcd 0000:00:01.2: PCI->APIC IRQ transform: INT D -> IRQ 25
[    0.395000] uhci_hcd 0000:00:01.2: UHCI Host Controller
[    0.395000] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1
[    0.395000] uhci_hcd 0000:00:01.2: detected 2 ports
[    0.395000] uhci_hcd 0000:00:01.2: irq 25, io base 0x0000c040
[    0.395000] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001
[    0.395000] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.395000] usb usb1: Product: UHCI Host Controller
[    0.395000] usb usb1: Manufacturer: Linux 3.10.0-327.10.1.el7.x86_64 uhci_hcd
[    0.395000] usb usb1: SerialNumber: 0000:00:01.2
[    0.395000] hub 1-0:1.0: USB hub found
[    0.395000] hub 1-0:1.0: 2 ports detected
[    0.395000] usbcore: registered new interface driver usbserial
[    0.395000] usbcore: registered new interface driver usbserial_generic
[    0.395000] usbserial: USB Serial support registered for generic
[    0.395000] i8042: PNP: No PS/2 controller found. Probing ports directly.
[    0.395000] serio: i8042 KBD port at 0x60,0x64 irq 1
[    0.395000] serio: i8042 AUX port at 0x60,0x64 irq 12
[    0.395000] mousedev: PS/2 mouse device common for all mice
[    0.395000] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
[    0.395000] rtc_cmos rtc_cmos: alarms up to one day, 114 bytes nvram
[    0.395000] cpuidle: using governor menu
[    0.395000] hidraw: raw HID events driver (C) Jiri Kosina
[    0.395000] usbcore: registered new interface driver usbhid
[    0.395000] usbhid: USB HID core driver
[    0.395000] drop_monitor: Initializing network drop monitor service
[    0.395000] TCP: cubic registered
[    0.395000] Initializing XFRM netlink socket
[    0.395000] NET: Registered protocol family 10
[    0.395000] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    0.395000] NET: Registered protocol family 17
[    0.395000] Loading compiled-in X.509 certificates
[    0.395000] Loaded X.509 cert 'Red Hat Enterprise Linux Driver Update Program (key 3): bf57f3e87362bc7229d9f465321773dfd1f77a80'
[    0.395000] Loaded X.509 cert 'Red Hat Enterprise Linux kpatch signing key: 4d38fd864ebe18c5f0b72e3852e2014c3a676fc8'
[    0.395000] Loaded X.509 cert 'Red Hat Enterprise Linux kernel signing key: e39a6c00a1de4dfaf590628cabecbceb0766328a'
[    0.395000] registered taskstats version 1
[    0.395000] Key type trusted registered
[    0.395000] Key type encrypted registered
[    0.395000] IMA: No TPM chip found, activating TPM-bypass!
[    0.395000] rtc_cmos rtc_cmos: setting system clock to 2016-06-13 13:47:11 UTC (1465825631)
[    0.395000] Freeing unused kernel memory: 1620k freed
supermin: mounting /proc
supermin: uptime: 1.62 0.35
supermin: ext2 mini initrd starting up: 5.1.10 zlib
supermin: cmdline: panic=1 console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1 TERM=xterm-256color
supermin: mounting /sys
supermin: internal insmod crc32-pclmul.ko
[    0.395000] PCLMULQDQ-NI instructions are not detected.
insmod: init_module: crc32-pclmul.ko: No such device
supermin: internal insmod crc32c-intel.ko
insmod: init_module: crc32c-intel.ko: No such device
supermin: internal insmod crct10dif_common.ko
supermin: internal insmod crct10dif-pclmul.ko
insmod: init_module: crct10dif-pclmul.ko: No such device
supermin: internal insmod crc32.ko
[    0.395000] alg: No test for crc32 (crc32-table)
supermin: internal insmod crct10dif_generic.ko
supermin: internal insmod libata.ko
supermin: internal insmod ata_piix.ko
[    0.395000] scsi host0: ata_piix
[    0.395000] scsi host1: ata_piix
[    0.395000] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14
[    0.395000] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15
Alarm clock

Comment 1 Richard W.M. Jones 2016-06-13 14:48:17 UTC
This is definitely not supposed to happen.  It looks like a
kernel or qemu bug, with either the kernel or qemu hanging during
boot.

Probably the simplest thing to check is if there is a new
kernel available.  Just installing a new kernel and rerunning
libguestfs-test-tool will tell you if it's a known kernel bug
which has been fixed already.

Second thing would be to check if there is a newer qemu, install
that and repeat the libguestfs-test-tool command.

You can also send me log-in details for the machine where this
happens so I can take a closer look (either by email or by
private comment on this BZ).

Comment 2 Richard W.M. Jones 2016-06-13 14:50:03 UTC
Another thing to check is if you have enough free space on
/tmp, /var/tmp and/or $TMPDIR if set.  qemu hangs if it runs
out of space, rather than giving an error.

Comment 3 Matt Flusche 2016-06-13 15:24:44 UTC
I've tested again with the latest Kernel and qemu-kvm (same results):

kernel-3.10.0-327.18.2.el7.x86_64

qemu-kvm-rhev-2.3.0-31.el7_2.13.x86_64

It doesn't seem to be a disk space issue:

 df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/sda2        25G  5.9G   20G  24% /
devtmpfs        7.8G     0  7.8G   0% /dev
tmpfs           7.8G     0  7.8G   0% /dev/shm
tmpfs           7.8G  384K  7.8G   1% /run
tmpfs           7.8G     0  7.8G   0% /sys/fs/cgroup
tmpfs           1.6G     0  1.6G   0% /run/user/1000

I'll follow up with access to this env.

Thanks for your help.

Comment 5 Richard W.M. Jones 2016-06-13 15:36:12 UTC
qemu-kvm-rhev-2.3.0-31.el7_2.13.x86_64

This kernel & qemu combo hang when loading the ata_piix.ko module.

Note this is under TCG, I have not tested KVM yet.

Comment 6 Richard W.M. Jones 2016-06-13 15:37:43 UTC
The last messages before the hang are:

[    3.244850] input: PC Speaker as /devices/platform/pcspkr/input/input1
[    3.244850] Error: Driver 'pcspkr' is already registered, aborting...
[    3.244850] scsi host1: ata_piix
[    3.244850] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    3.244850] sd 0:0:1:0: Attached scsi generic sg1 type 0
[    3.244850] scsi host2: ata_piix
[    3.244850] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14
[    3.244850] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15

Comment 7 Richard W.M. Jones 2016-06-13 15:44:47 UTC
Fails with
 - qemu-kvm-rhev-2.3.0-31.el7_2.7.x86_64
 - qemu-kvm-rhev-2.3.0-31.el7_2.13.x86_64
 - kernel-3.10.0-327.10.1.el7.x86_64
 - kernel-3.10.0-327.18.2.el7.x86_64

Comment 8 Richard W.M. Jones 2016-06-13 16:33:17 UTC
Also fails with
 - qemu-kvm-rhev-2.1.2-23.el7_1.12.x86_64

I tried to get a stack trace using gdb, but it didn't seem to
make sense.

With full debugging:

[    0.600000] calling  piix_init+0x0/0x1000 [ata_piix] @ 1
[    0.600000] ata_piix 0000:00:01.1: version 2.13
[    0.600000] scsi host0: ata_piix
[    0.600000] scsi host1: ata_piix
[    0.600000] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14
[    0.600000] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15
[    0.600000] initcall piix_init+0x0/0x1000 [ata_piix] returned 0 after 50474 usecs
<-- hangs here

Comment 9 Richard W.M. Jones 2016-06-13 16:55:46 UTC
OK, I believe this is a nested KVM issue.

I was able to make the test succeed by forcing TCG:

  LIBGUESTFS_BACKEND_SETTINGS=force_tcg libguestfs-test-tool

Matt, could you confirm that nested KVM is being used?  You will
need to log into the KVM hypervisor host and see if the nested=1
flag is set on the kvm_intel module -- look at the contents of
/sys/module/kvm_intel/parameters/nested on the host.

I'm afraid that since it seems to be nested KVM, this scenario
is both not supported and known to be very troublesome.  The
only solution is to disable nested KVM.

Comment 11 Matt Flusche 2016-06-13 17:36:52 UTC
Yes this is nested kvm.  This is a training environment and unfortunately requires virtual environments.

Comment 12 Richard W.M. Jones 2016-06-13 18:09:38 UTC
(In reply to Matt Flusche from comment #11)
> Yes this is nested kvm.  This is a training environment and unfortunately
> requires virtual environments.

Sure, but you don't need nested KVM to have nested virtual environments.
Turn that setting off and see if it fixes things.

Comment 13 Matt Flusche 2016-06-13 18:58:16 UTC
Correct; dropping the kvm module; things work better.  I believe we will be able to proceed with this configuration.  Thanks for your help.

# rmmod kvm_amd
# time libguestfs-test-tool
     ************************************************************
     *                    IMPORTANT NOTICE
     *
     * When reporting bugs, include the COMPLETE, UNEDITED
     * output below in your bug report.
     *
     ************************************************************
...
===== TEST FINISHED OK =====

real	0m32.259s
user	0m0.130s
sys	0m0.472s

Comment 14 Richard W.M. Jones 2016-06-14 07:28:06 UTC
Closing WONTFIX per comment 9 - not a supported configuration.


Note You need to log in before you can comment on or make changes to this bug.