Qemu master branch - RHEL 6.1 guest fails to boot

[Lucas Meneghel Rodrigues]

Guest: RHEL 6.1 64 bit DVD

Kernel: Latest Fedora, also reproduces with Avi's kvm.git kernel based on 3.1: 2.6.40.6-0.fc15.x86_64

qemu version:

11/04 00:25:30 DEBUG|virt_utils:2587| Git repo qemu uri: git://git.qemu.org/qemu.git
11/04 00:25:30 DEBUG|virt_utils:2590| Git repo qemu branch: master
11/04 00:25:30 DEBUG|virt_utils:3189| Configure options for git_repo_qemu: ['--target-list=x86_64-softmmu']
11/04 00:25:30 DEBUG|virt_utils:2496| Initializing new git repo at /usr/local/autotest/tests/kvm/src/qemu for receiving git repo 11/04 00:25:30 INFO |virt_utils:2505| Fetching git [REP 'git://git.qemu.org/qemu.git' BRANCH 'master'] -> /usr/local/autotest/tests/kvm/src/qemu
11/04 00:25:30 DEBUG|base_utils:0074| Running 'git fetch -q -f -u -t git://git.qemu.org/qemu.git master:master'
11/04 00:34:41 INFO |virt_utils:2531| Commit hash for qemu is 932eacc158c064935c7bab920c88a93a629e1ca4 (no tag found)

On guest boot screenshots (one of them attached), you can see the message

"Bringing up interface eth0: Device eth0 does not seem to be present, delaying initialization"

Network card info
11/04 00:44:55 DEBUG| virt_test:0041| bridge = virbr0
11/04 00:44:55 DEBUG| virt_test:0041| nic_mode = tap
11/04 00:44:55 DEBUG| virt_test:0041| nic_model = virtio

Commented excerpt of the test log:

11/04 00:44:57 INFO | kvm_vm:0790| Running qemu command:
/usr/local/autotest/tests/kvm/qemu -name 'vm1' -nodefaults -vga std -monitor unix:'/tmp/monitor-humanmonitor1-20111104-003602-LPJY',server,nowait -qmp unix:'/tmp/monitor-qmpmonitor1-20111104-003602-LPJY',server,nowait -serial unix:'/tmp/serial-20111104-003602-LPJY',server,nowait -drive file='/tmp/kvm_autotest_root/images/rhel6.1-64.qcow2',index=0,if=virtio,cache=none -device virtio-net-pci,netdev=id3HQgQx,mac='9a:16:a5:3c:05:25',id='id0AfUVE' -netdev tap,id=id3HQgQx,fd=23 -m 2048 -smp 2 -vnc :0 -enable-kvm
11/04 00:44:59 DEBUG|kvm_monito:0624| (monitor qmpmonitor1) Sending command 'qmp_capabilities'
11/04 00:44:59 DEBUG| kvm_vm:0851| VM appears to be alive with PID 9827
11/04 00:44:59 DEBUG|virt_env_p:0318| Starting screendump thread
11/04 00:44:59 DEBUG| virt_vm:0654| Attempting to log into 'vm1' (timeout 720s)

... here it starts booting ...

11/04 00:44:59 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:01 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:03 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:05 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:07 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:09 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:11 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:13 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:15 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:17 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:19 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:21 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25
11/04 00:45:23 DEBUG| virt_vm:0660| Cannot find IP address for MAC address 9a:16:a5:3c:05:25

... here it gets an IP from the DHCP server ...

11/04 00:45:24 DEBUG|virt_env_p:0438| (address cache) Adding cache entry: 9a:16:a5:3c:05:25 ---> 192.168.122.195

... ok, let's try to login ...

11/04 00:45:25 DEBUG|virt_utils:0710| Trying to login with command 'ssh -o UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22 root@192.168.122.195'

... ouch, not possible to login ...

11/04 00:45:25 DEBUG| virt_vm:0660| Client said 'connection refused' (output: 'ssh: connect to host 192.168.122.195 port 22: Connection refused\n')

... message above repeats until ...

11/04 00:56:59 ERROR| virt_test:0095| Test failed: LoginError: Client said 'connection refused' (output: 'ssh: connect to host 192.168.122.195 port 22: Connection refused\n')
11/04 00:56:59 DEBUG|virt_env_p:0147| Postprocessing VM 'vm1'
11/04 00:56:59 DEBUG|virt_env_p:0166| Param 'kill_vm' specified, killing VM
11/04 00:56:59 DEBUG| kvm_vm:0885| Destroying VM with PID 9827
11/04 00:56:59 DEBUG| kvm_vm:0889| Trying to shutdown VM with shell command
11/04 00:56:59 DEBUG|virt_utils:0710| Trying to login with command 'ssh -o UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22 root@192.168.122.195'
11/04 00:56:59 DEBUG| kvm_vm:0893| Client said 'connection refused' (output: 'ssh: connect to host 192.168.122.195 port 22: Connection refused\n')
11/04 00:56:59 DEBUG| kvm_vm:0908| Trying to kill VM with monitor command
11/04 00:56:59 INFO | aexpect:0783| [qemu output] (Process terminated with status 0)
11/04 00:57:00 DEBUG| kvm_vm:0916| VM is down
11/04 00:57:00 DEBUG| virt_vm:0318| Checking image file /tmp/kvm_autotest_root/images/rhel6.1-64.qcow2
11/04 00:57:00 DEBUG|base_utils:0074| Running '/usr/local/autotest/tests/kvm/qemu-img'
11/04 00:57:00 DEBUG|base_utils:0074| Running '/usr/local/autotest/tests/kvm/qemu-img info /tmp/kvm_autotest_root/images/rhel6.1-64.qcow2'
11/04 00:57:00 DEBUG|base_utils:0106| [stdout] image: /tmp/kvm_autotest_root/images/rhel6.1-64.qcow2
11/04 00:57:00 DEBUG|base_utils:0106| [stdout] file format: qcow2
11/04 00:57:00 DEBUG|base_utils:0106| [stdout] virtual size: 10G (10737418240 bytes)
11/04 00:57:00 DEBUG|base_utils:0106| [stdout] disk size: 2.1G
11/04 00:57:00 DEBUG|base_utils:0106| [stdout] cluster_size: 65536
11/04 00:57:00 DEBUG|base_utils:0074| Running '/usr/local/autotest/tests/kvm/qemu-img check /tmp/kvm_autotest_root/images/rhel6.1-64.qcow2'

[Lucas Meneghel Rodrigues (lmr)]

We are currently investigating the failure. One of our suspects is that on kvm autotest, each new qemu process instance might have a new NIC mac address, and that might be triggering some condition in qemu in conjunction to the guest init scripts.

It is important to note that this problem does not affect qemu-kvm.git, or RHEL based branches for that matter.

[Anthony Liguori (anthony-codemonkey)]

I can't reproduce this with an Ubuntu guest. I suspect it has something to do with how you're configuring networking.

[Lucas Meneghel Rodrigues (lmr)]

A little more investigation shows that empty ssh keys are being generated on the first boot, so now it doesn't look like a network problem anymore. now we are trying to figure out just on qemu this phenomenon is happening.

[Lucas Meneghel Rodrigues (lmr)]

We've identified that the following commit resolved the issue

 commit 47113ab6b8c5659ad94c69aacca572f731ebb0ac
 Author: Wen Congyang <email address hidden>
 Date: Fri Nov 4 10:45:58 2011 +0800
     reenable vm_clock when resuming all vcpus

     We disable vm_clock when pausing all vcpus, but we forget to
     reenable it when resuming all vcpus. It will cause that the
     guest can not be rebooted.

     Tested-by: Zhi Yong Wu <email address hidden>
     Reviewed-by: Paolo Bonzini <email address hidden>
     Signed-off-by: Wen Congyang <email address hidden>
     Signed-off-by: Anthony Liguori <email address hidden>

That's good, you can close the issue.

[Thomas Huth (th-huth)]

Marking as fixed, according to comment #5