hotplug error after several starting multiple VMs

hotplug error after several starting multiple VMs

[Cris Daniluk]

Okay, trying a new combination of Xen release/dom0. I'm running
OpenSLES 11.3 with dist kernel 2.6.34-12-xen using dist
4.0.0_21091_05-6.6.  In general, behavior is good and I am able to
fire and put VMs under load. However, I'm running into hotplug errors
after starting around 20 VMs. I've had very poor results trying to
research this problem given the overwhelming number of people who see
the error message when configuring Xen for the first time, so I'm not
sure where to begin debugging. Everything is running under a single
bridge and I'm using Xen's network-bridge script to manage it. Once I
get into this state, I can't start new VMs, but I can continue to work
with the VMs that are already running. The error is as follows:

linux:/etc/xen/shared/domains # xm create test13
Using config file "./test13".
Error: Device 0 (vif) could not be connected. Hotplug scripts not working.


The xend.log output is below. Nothing is logged to xen-hotplug.log.


(XEN) cpupool_add_domain(dom=25,pool=0) n_dom 20
[2010-08-26 21:02:33 4957] DEBUG (XendDomainInfo:103)
XendDomainInfo.create(['vm', ['name', 'test13'], ['memory', 1024],
['on_reboot', 'restart'], ['on_crash', 'restart'], ['on_xend_start',
'ignore'], ['on_xend_stop', 'ignore'], ['vcpus', 1], ['oos', 1],
['bootloader', '/usr/bin/pygrub'], ['bootloader_args', '-q'],
['image', ['linux', ['videoram', 4], ['tsc_mode', 0], ['nomigrate',
0]]], ['s3_integrity', 1], ['device', ['vbd', ['uname',
'phy:vg_moreover/lv_test_13'], ['dev', 'xvda'], ['mode', 'w']]],
['device', ['vif', ['ip', '192.168.198.62'], ['mac',
'A2:01:02:01:03:13'], ['vifname', 'test13']]]])
[2010-08-26 21:02:33 4957] DEBUG (XendDomainInfo:2543)
XendDomainInfo.constructDomain
[2010-08-26 21:02:33 4957] DEBUG (balloon:239) Balloon: 20835020 KiB
free; need 16384; done.
[2010-08-26 21:02:33 4957] DEBUG (XendDomain:465) Adding Domain: 25
[2010-08-26 21:02:33 4957] DEBUG (XendDomainInfo:2871)
XendDomainInfo.initDomain: 25 256
[2010-08-26 21:02:33 9710] DEBUG (XendBootloader:130) Launching
bootloader as ['/usr/bin/pygrub',
'--output=/var/run/xend/boot/xenbl.24187', '-q',
'/dev/vg_moreover/lv_test_13'].
[2010-08-26 21:02:33 4957] DEBUG (XendDomainInfo:2898)
_initDomain:shadow_memory=0x0, memory_static_max=0x40000000,
memory_static_min=0x0.
[2010-08-26 21:02:33 4957] INFO (image:182) buildDomain os=linux dom=25 vcpus=1
[2010-08-26 21:02:33 4957] DEBUG (image:732) domid          = 25
[2010-08-26 21:02:33 4957] DEBUG (image:733) memsize        = 1024
[2010-08-26 21:02:33 4957] DEBUG (image:734) image          =
/var/run/xend/boot/boot_kernel.HkUPPL
[2010-08-26 21:02:33 4957] DEBUG (image:735) store_evtchn   = 1
[2010-08-26 21:02:33 4957] DEBUG (image:736) console_evtchn = 2
[2010-08-26 21:02:33 4957] DEBUG (image:737) cmdline        = ro
root=/dev/vg_primary/lv_base console=xvc0
[2010-08-26 21:02:33 4957] DEBUG (image:738) ramdisk        =
/var/run/xend/boot/boot_ramdisk.YhgUfY
[2010-08-26 21:02:33 4957] DEBUG (image:739) vcpus          = 1
[2010-08-26 21:02:33 4957] DEBUG (image:740) features       =
[2010-08-26 21:02:33 4957] DEBUG (image:741) flags          = 0
[2010-08-26 21:02:33 4957] DEBUG (image:742) superpages     = 0
[2010-08-26 21:02:34 4957] INFO (XendDomainInfo:2402) createDevice:
vbd : {'uuid': '7bcd27fe-b092-45d7-8edc-3aa23ed655a1', 'bootable': 1,
'driver': 'paravirtualised', 'dev': 'xvda', 'uname':
'phy:vg_moreover/lv_test_13', 'mode': 'w'}
[2010-08-26 21:02:34 4957] DEBUG (DevController:95) DevController:
writing {'virtual-device': '51712', 'device-type': 'disk', 'protocol':
'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend':
'/local/domain/0/backend/vbd/25/51712'} to
/local/domain/25/device/vbd/51712.
[2010-08-26 21:02:34 4957] DEBUG (DevController:97) DevController:
writing {'domain': 'test13', 'frontend':
'/local/domain/25/device/vbd/51712', 'uuid':
'7bcd27fe-b092-45d7-8edc-3aa23ed655a1', 'bootable': '1', 'dev':
'xvda', 'state': '1', 'params': 'vg_moreover/lv_test_13', 'mode': 'w',
'online': '1', 'frontend-id': '25', 'type': 'phy'} to
/local/domain/0/backend/vbd/25/51712.
[2010-08-26 21:02:34 4957] INFO (XendDomainInfo:2402) createDevice:
vif : {'ip': '192.168.198.62', 'mac': 'A2:01:02:01:03:13', 'vifname':
'test13', 'uuid': 'e0e5b831-1400-4997-96a6-e06435754ae1'}
[2010-08-26 21:02:34 4957] DEBUG (DevController:95) DevController:
writing {'mac': 'A2:01:02:01:03:13', 'handle': '0', 'protocol':
'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend':
'/local/domain/0/backend/vif/25/0'} to /local/domain/25/device/vif/0.
[2010-08-26 21:02:34 4957] DEBUG (DevController:97) DevController:
writing {'domain': 'test13', 'handle': '0', 'uuid':
'e0e5b831-1400-4997-96a6-e06435754ae1', 'script':
'/etc/xen/scripts/vif-bridge', 'ip': '192.168.198.62', 'mac':
'A2:01:02:01:03:13', 'frontend-id': '25', 'state': '1', 'vifname':
'test13', 'online': '1', 'frontend': '/local/domain/25/device/vif/0'}
to /local/domain/0/backend/vif/25/0.
[2010-08-26 21:02:34 4957] DEBUG (XendDomainInfo:3470) Storing VM
details: {'on_xend_stop': 'ignore', 'pool_name': 'Pool-0',
'shadow_memory': '0', 'uuid': '5d80c325-8a74-28c5-06fd-80484da1b7e3',
'on_reboot': 'restart', 'start_time': '1282870954.52', 'on_poweroff':
'destroy', 'bootloader_args': '-q', 'on_xend_start': 'ignore',
'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '1',
'vcpu_avail': '1', 'bootloader': '/usr/bin/pygrub', 'image': "(linux
(kernel ) (superpages 0) (videoram 4) (pci ()) (nomigrate 0) (tsc_mode
0) (notes (FEATURES
'writable_page_tables|writable_descriptor_tables|auto_translated_physmap|pae_pgdir_above_4gb|supervisor_mode_kernel')
(VIRT_BASE 18446744071562067968) (GUEST_VERSION 2.6) (PADDR_OFFSET
18446744071562067968) (GUEST_OS linux) (HYPERCALL_PAGE
18446744071564189696) (LOADER generic) (ENTRY 18446744071564165120)
(XEN_VERSION xen-3.0)))", 'name': 'test13'}
[2010-08-26 21:02:34 4957] DEBUG (XendDomainInfo:1835) Storing domain
details: {'console/ring-ref': '5688553', 'image/entry':
'18446744071564165120', 'console/port': '2', 'store/ring-ref':
'5688554', 'image/loader': 'generic', 'vm':
'/vm/5d80c325-8a74-28c5-06fd-80484da1b7e3',
'control/platform-feature-multiprocessor-suspend': '1',
'image/guest-os': 'linux',
'image/features/writable-descriptor-tables': '1', 'image/virt-base':
'18446744071562067968', 'memory/target': '1048576',
'image/guest-version': '2.6', 'image/features/supervisor-mode-kernel':
'1', 'description': '', 'console/limit': '1048576',
'image/paddr-offset': '18446744071562067968', 'image/hypercall-page':
'18446744071564189696', 'cpu/0/availability': 'online',
'image/features/pae-pgdir-above-4gb': '1',
'image/features/writable-page-tables': '1', 'console/type':
'xenconsoled', 'image/features/auto-translated-physmap': '1', 'name':
'test13', 'domid': '25', 'image/xen-version': 'xen-3.0', 'store/port':
'1'}
[2010-08-26 21:02:34 4957] DEBUG (DevController:95) DevController:
writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0',
'backend': '/local/domain/0/backend/console/25/0'} to
/local/domain/25/device/console/0.
[2010-08-26 21:02:34 4957] DEBUG (DevController:97) DevController:
writing {'domain': 'test13', 'frontend':
'/local/domain/25/device/console/0', 'uuid':
'b9c40186-2de9-8fce-2aa5-57311a33797e', 'frontend-id': '25', 'state':
'1', 'location': '2', 'online': '1', 'protocol': 'vt100'} to
/local/domain/0/backend/console/25/0.
[2010-08-26 21:02:34 4957] DEBUG (XendDomainInfo:1922)
XendDomainInfo.handleShutdownWatch
[2010-08-26 21:02:34 4957] DEBUG (DevController:139) Waiting for devices tap2.
[2010-08-26 21:02:34 4957] DEBUG (DevController:139) Waiting for devices vif.
[2010-08-26 21:02:34 4957] DEBUG (DevController:144) Waiting for 0.
[2010-08-26 21:02:34 4957] DEBUG (DevController:653)
hotplugStatusCallback /local/domain/0/backend/vif/25/0/hotplug-status.
(XEN) cpupool_rm_domain(dom=25,pool=0) n_dom 19
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:3111)
XendDomainInfo.destroy: domid=25
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2446) Destroying device model
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2453) Releasing devices
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2459) Removing vif/0
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:1289)
XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/0
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2459) Removing console/0
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:1289)
XendDomainInfo.destroyDevice: deviceClass = console, device =
console/0
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2459) Removing vbd/51712
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:1289)
XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/51712
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2451) No device model
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2453) Releasing devices
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2459) Removing vif/0
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:1289)
XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/0
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:2459) Removing vbd/51712
[2010-08-26 21:04:14 4957] DEBUG (XendDomainInfo:1289)
XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/51712

Re: hotplug error after several starting multiple VMs

[Konrad Rzeszutek Wilk]

On Thu, Aug 26, 2010 at 09:21:40PM -0400, Cris Daniluk wrote:
> Okay, trying a new combination of Xen release/dom0. I'm running
> OpenSLES 11.3 with dist kernel 2.6.34-12-xen using dist
> 4.0.0_21091_05-6.6.  In general, behavior is good and I am able to
> fire and put VMs under load. However, I'm running into hotplug errors
> after starting around 20 VMs. I've had very poor results trying to
> research this problem given the overwhelming number of people who see
> the error message when configuring Xen for the first time, so I'm not
> sure where to begin debugging. Everything is running under a single

It looks as if the hot plug scripts are the ones that fail. Here is what
I would suggest:

 1). Enable all debug options in /etc/sysconfig/xend
 2). Add -x to the hotplug scripts, as so:
[konrad@phenom /]$ diff -uNr /etc/xen/scripts/block.orig
/etc/xen/scripts/block
--- /etc/xen/scripts/block.orig 2010-08-27 12:05:05.383410805 -0400
+++ /etc/xen/scripts/block      2010-08-27 12:05:09.438365152 -0400
@@ -1,4 +1,4 @@
-#!/bin/bash
+#!/bin/bash -x
 
 dir=$(dirname "$0")
 . "$dir/block-common.sh"

That will make the output of whatever the script is doing and as well
all the errors it encountered be logged in /var/log/xen/xen-hotplug.log

You probably want to add the -x to the network-bridge script.

> bridge and I'm using Xen's network-bridge script to manage it. Once I
> get into this state, I can't start new VMs, but I can continue to work
> with the VMs that are already running. The error is as follows:
> 
> linux:/etc/xen/shared/domains # xm create test13
> Using config file "./test13".
> Error: Device 0 (vif) could not be connected. Hotplug scripts not working.
> 
> 
> The xend.log output is below. Nothing is logged to xen-hotplug.log.

Try the -x trick and that file should be filled with data.