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

Tue May 26 00:10:36 UTC 2015

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
>