[fedora-virt] unable to boot rhel5 guest with 3.19.7-200.fc21.x86_64

Mon Jun 1 16:33:08 UTC 2015

Hi,

The recent kernel update 4.0.4-201.fc21.x86_64 does not exhibit the issue.

* 3.19.5-200.fc21.x86_64 ..... GOOD
* 3.19.7-200.fc21.x86_64 ..... BAD
*   4.0.4-201.fc21.x86_64 ..... GOOD

Since other updates were also applied, i tried back with the bad kernel and the
issue was still there for the bad kernel.

I the issue does come back in  a future kernel i will open a bz.

Cheers.

On Mon, May 25, 2015 at 9:10 PM, Reartes Guillermo <rtguille at gmail.com> wrote:
> Hi,
>
>
> Thanks for answering.
>
> The guest log ( /var/log/libvirt/qemu/$vmname.log) is very similar.
> The only difference is in the line:
> main_channel_handle_parsed: net test: latency 0.754000 ms, bitrate
> 11252747252 bps (10731.456043 Mbps)
>
>
> But on the journal there are subtle differences (not sure if that the issue):
>
>
>>> may 25 20:45:55 ulquiorra.espada dbus[1265]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service'
> i do not see this on the "bad kernel".
>
> HOST: 3.19.5-200.fc21.x86_64 (GOOD)
>
> Journalctl -f:
>
> may 25 20:45:54 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): carrier is OFF
> may 25 20:45:54 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): new Tun device (driver: 'unknown' ifindex: 19)
> may 25 20:45:54 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): exported as /org/freedesktop/NetworkManager/Devices/18
> may 25 20:45:55 ulquiorra.espada kernel: device vnet0 entered promiscuous mode
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (virbr1): bridge port vnet0 was attached
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): enslaved to virbr1
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): device state change: unmanaged -> unavailable (reason
> 'connection-assumed') [10 20 41]
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): link connected
> may 25 20:45:55 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> listening state
> may 25 20:45:55 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> listening state
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): device state change: unavailable -> disconnected (reason
> 'connection-assumed') [20 30 41]
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) starting connection 'vnet0'
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 1 of 5 (Device Prepare) scheduled...
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 1 of 5 (Device Prepare) started...
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): device state change: disconnected -> prepare (reason 'none')
> [30 40 0]
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) scheduled...
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 1 of 5 (Device Prepare) complete.
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) starting...
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): device state change: prepare -> config (reason 'none') [40 50
> 0]
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) successful.
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) complete.
> may 25 20:45:55 ulquiorra.espada dbus[1265]: [system] Activating via
> systemd: service name='org.freedesktop.machine1'
> unit='dbus-org.freedesktop.machine1.service'
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 3 of 5 (IP Configure Start) scheduled.
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 3 of 5 (IP Configure Start) started...
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): device state change: config -> ip-config (reason 'none') [50
> 70 0]
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) Stage 3 of 5 (IP Configure Start) complete.
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): device state change: ip-config -> secondaries (reason 'none')
> [70 90 0]
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> (vnet0): device state change: secondaries -> activated (reason 'none')
> [90 100 0]
> may 25 20:45:55 ulquiorra.espada kernel: SELinux: initialized (dev
> tmpfs, type tmpfs), uses transition SIDs
> may 25 20:45:55 ulquiorra.espada NetworkManager[1366]: <info>
> Activation (vnet0) successful, device activated.
> may 25 20:45:55 ulquiorra.espada dbus[1265]: [system] Activating via
> systemd: service name='org.freedesktop.nm_dispatcher'
> unit='dbus-org.freedesktop.nm-dispatcher.service'
> may 25 20:45:55 ulquiorra.espada dbus[1265]: [system] Successfully
> activated service 'org.freedesktop.nm_dispatcher'
> may 25 20:45:55 ulquiorra.espada nm-dispatcher[3665]: Dispatching
> action 'up' for vnet0
> may 25 20:45:55 ulquiorra.espada systemd[1]: Unit iscsi.service cannot
> be reloaded because it is inactive.
> may 25 20:45:55 ulquiorra.espada dbus[1265]: [system] Successfully
> activated service 'org.freedesktop.machine1'
> may 25 20:45:55 ulquiorra.espada systemd-machined[3664]: New machine
> qemu-Yapsule-02.
> may 25 20:45:55 ulquiorra.espada kernel: kvm: zapping shadow pages for
> mmio generation wraparound
> may 25 20:45:56 ulquiorra.espada avahi-daemon[1247]: Registering new
> address record for fe80::fc54:ff:fe1a:2659 on vnet0.*.
> may 25 20:45:57 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> learning state
> may 25 20:45:59 ulquiorra.espada NetworkManager[1366]: <info>
> (virbr1): link connected
> may 25 20:45:59 ulquiorra.espada kernel: virbr1: topology change
> detected, propagating
> may 25 20:45:59 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> forwarding state
>
> the guest is up, at the login prompt.
>
>
> HOST: 3.19.7-200.fc21.x86_64 (BAD)
>
>
> Journalctl -f:
>
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): carrier is OFF
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): new Tun device (driver: 'unknown' ifindex: 20)
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): exported as /org/freedesktop/NetworkManager/Devices/19
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (virbr1): bridge port vnet0 was attached
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): enslaved to virbr1
> may 25 20:38:52 ulquiorra.espada kernel: device vnet0 entered promiscuous mode
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): device state change: unmanaged -> unavailable (reason
> 'connection-assumed') [10 20 41]
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): link connected
> may 25 20:38:52 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> listening state
> may 25 20:38:52 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> listening state
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): device state change: unavailable -> disconnected (reason
> 'connection-assumed') [20 30 41]
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) starting connection 'vnet0'
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 1 of 5 (Device Prepare) scheduled...
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 1 of 5 (Device Prepare) started...
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): device state change: disconnected -> prepare (reason 'none')
> [30 40 0]
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) scheduled...
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 1 of 5 (Device Prepare) complete.
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) starting...
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): device state change: prepare -> config (reason 'none') [40 50
> 0]
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) successful.
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 2 of 5 (Device Configure) complete.
> may 25 20:38:52 ulquiorra.espada systemd-machined[4223]: New machine
> qemu-Yapsule-02.
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 3 of 5 (IP Configure Start) scheduled.
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 3 of 5 (IP Configure Start) started...
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): device state change: config -> ip-config (reason 'none') [50
> 70 0]
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) Stage 3 of 5 (IP Configure Start) complete.
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): device state change: ip-config -> secondaries (reason 'none')
> [70 90 0]
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> (vnet0): device state change: secondaries -> activated (reason 'none')
> [90 100 0]
> may 25 20:38:52 ulquiorra.espada NetworkManager[1361]: <info>
> Activation (vnet0) successful, device activated.
> may 25 20:38:52 ulquiorra.espada dbus[1271]: [system] Activating via
> systemd: service name='org.freedesktop.nm_dispatcher'
> unit='dbus-org.freedesktop.nm-dispatcher.service'
> may 25 20:38:52 ulquiorra.espada dbus[1271]: [system] Successfully
> activated service 'org.freedesktop.nm_dispatcher'
> may 25 20:38:52 ulquiorra.espada nm-dispatcher[4576]: Dispatching
> action 'up' for vnet0
> may 25 20:38:52 ulquiorra.espada systemd[1]: Unit iscsi.service cannot
> be reloaded because it is inactive.
> may 25 20:38:52 ulquiorra.espada kernel: kvm: zapping shadow pages for
> mmio generation wraparound
> may 25 20:38:54 ulquiorra.espada avahi-daemon[1242]: Registering new
> address record for fe80::fc54:ff:fe1a:2659 on vnet0.*.
> may 25 20:38:54 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> learning state
> may 25 20:38:56 ulquiorra.espada NetworkManager[1361]: <info>
> (virbr1): link connected
> may 25 20:38:56 ulquiorra.espada kernel: virbr1: topology change
> detected, propagating
> may 25 20:38:56 ulquiorra.espada kernel: virbr1: port 2(vnet0) entered
> forwarding state
>
> (manually force shutdown from virt-manager)
>
>
> Just to be clear, the guest reaches grub, grub works ok, it the guest
> kernel that does not initializes properly (no kernel alive message).
>
> I looks like i will need to open a bz, so i probably will do it midweek aprox.
>
> Thanks in advance.
>
>
>
>
>
>
>
>
> On Mon, May 25, 2015 at 5:51 PM, Cole Robinson <crobinso at redhat.com> wrote:
>> On 05/23/2015 07:40 PM, Reartes Guillermo wrote:
>>> Hi,
>>>
>>> Since a couple of days i noticed that i cannot boot a rhel5 guest on
>>> my F21 machine.
>>> Today i was able to test it properly by rebooting a couble of times.
>>> There seems to
>>> be some issue with kernel 3.19.7-200.fc21.x86_64
>>>
>>> Did anybody experienced something similar?
>>>
>>> HOST: FEDORA: 21
>>>       CPU: AMD FX(tm)-6100
>>>
>>> * With KERNEL: 3.19.7-200.fc21.x86_64
>>>   GUEST
>>>    * RHEL5: 5.11
>>>    * KERNEL: 2.6.18-404-el5 (also tried: 2.6.18-400.1.1.el5, 2.6.18-398.el5 )
>>>
>>>    * RESULT: Guest HANGS, with 100% vcpu usage after grub (no nash...
>>> kernel alive, etc)
>>>
>>>    * If i try booting from the RHEL5 5.11 release iso image (cdrom),
>>> it works...
>>>
>>>
>>> * With KERNEL: 3.19.5-200.fc21.x86_64
>>>   GUEST
>>>    * RHEL5: 5.11
>>>    * KERNEL: 2.6.18-404-el5 (also tried: 2.6.18-400.1.1.el5, 2.6.18-398.el5 )
>>>
>>>    * RESULT: Guest boots normally. No known issues. (also booting the
>>> iso also works)
>>>
>>>
>>
>> My AMD machines are all running F22 so I haven't tested. But on the busted
>> kernel can you see if there's any errors after starting the VM in dmesg, or
>> any errors printed in /var/log/libvirt/qemu/$vmname.log (or qemu stderr if not
>> using libvirt)
>>
>> - Cole
>>