Xen project Mailing List

[Xen-users] hotplug scripts not working

To: Xen Users Mailing List <xen-users@xxxxxxxxxxxxxxxxxxx>

From: Igor Serebryany <igor47@xxxxxxxxxxx>

Date: Fri, 8 Oct 2010 15:15:34 -0500

Delivery-date: Fri, 08 Oct 2010 13:16:59 -0700

List-id: Xen user discussion <xen-users.lists.xensource.com>

Hi Friends! I've been having this occasional but persistent problem where Xen hosts which had been working properly will get into a state where I cannot start any new VMs. Attempts will error out with the following message: 'Device 51712 (vbd) could not be connected. Hotplug scripts not working.' I have seen this both on Debian Lenny with Xen 3.2.1 and on Debian Squeeze with Xen 4.0.1 I have scoured the net for this, and it seems for some people the problem is the wrong file name for their backing store -- not the problem in my case -- or something wrong with their network drivers -- also maybe (?) not the problem for me, as it is the disk device I get hung up on. The domains which have trouble starting get created and paused. I am able to unpause and console them, in which case they get to a point in their bootup where a message says: XENBUS: Waiting for devices to initialise: 295s...290s... Eventually the countdown times out and the VM crashes (it will show up as crashed in 'xm list'). Before I fill the rest of the email with tracebacks, I should point out that this happens with several different types of backing stores (raw tap, tap2:aio, file), with several different kinds of booting mechanisms (pygrub, local kernel). The only solution appears to be to reboot the node -- restarting xend, xenconsoled, udev or anything else doesn't seem to help. I would love pointers on how to prevent this issue from happening, or how to resolve it without a reboot once it happens. I'm all out of ideas for how to debug it further. Here is the traceback from the xend log that shows the problem, from the moment I attempt to start the VM to the moment xen finishes cleaning up: [2010-10-08 02:34:09 2481] DEBUG (XendDomainInfo:101) XendDomainInfo.create(['vm', ['name', 'vmprovision.testdomain.net'], ['memory', '500'], ['maxmem', '8057'], ['vcpus', '4'], ['uuid', '29afdd70-8030-db14-f318-d512a43d2d76'], ['description', 'VM ID 29567 Uber ID 173687'], ['on_poweroff', 'destroy'], ['on_reboot', 'destroy'], ['on_crash', 'preserve'], ['image', ['linux', ['kernel', '/tmp/vmlinuz.WelUc'], ['ramdisk', '/tmp/initrd.gz.WelUc']]], ['device', ['vbd', ['dev', 'xvda'], ['uname', 'tap:tapdisk:/distributed/vms/29567/disk.img'], ['mode', 'w']]], ['device', ['vbd', ['dev', 'xvdb'], ['uname', 'phy:/dev/VMSwapParts/vmprovision.testdomain.net'], ['mode', 'w']]], ['device', ['vif', ['mac', '02:00:00:01:cd:fc'], ['bridge', 'xenbr0'], ['script', 'vif-bridge']]], ['device', ['vif', ['mac', '02:00:00:01:cd:fd'], ['bridge', 'vlanbr338'], ['script', 'vif-bridge-vlan']]]]) [2010-10-08 02:34:09 2481] DEBUG (XendDomainInfo:2508) XendDomainInfo.constructDomain [2010-10-08 02:34:09 2481] DEBUG (balloon:220) Balloon: 8033248 KiB free; need 16384; done. [2010-10-08 02:34:09 2481] DEBUG (XendDomain:464) Adding Domain: 30 [2010-10-08 02:34:09 2481] DEBUG (XendDomainInfo:2818) XendDomainInfo.initDomain: 30 256 [2010-10-08 02:34:09 2481] DEBUG (XendDomainInfo:2845) _initDomain:shadow_memory=0x0, memory_static_max=0x1f7900000, memory_static_min=0x0. [2010-10-08 02:34:09 2481] INFO (image:182) buildDomain os=linux dom=30 vcpus=4 [2010-10-08 02:34:09 2481] DEBUG (image:721) domid = 30 [2010-10-08 02:34:09 2481] DEBUG (image:722) memsize = 500 [2010-10-08 02:34:09 2481] DEBUG (image:723) image = /tmp/vmlinuz.WelUc [2010-10-08 02:34:09 2481] DEBUG (image:724) store_evtchn = 1 [2010-10-08 02:34:09 2481] DEBUG (image:725) console_evtchn = 2 [2010-10-08 02:34:09 2481] DEBUG (image:726) cmdline = [2010-10-08 02:34:09 2481] DEBUG (image:727) ramdisk = /tmp/initrd.gz.WelUc [2010-10-08 02:34:09 2481] DEBUG (image:728) vcpus = 4 [2010-10-08 02:34:09 2481] DEBUG (image:729) features = [2010-10-08 02:34:09 2481] DEBUG (image:730) flags = 0 [2010-10-08 02:34:09 2481] DEBUG (image:731) superpages = 0 [2010-10-08 02:34:10 2481] INFO (XendDomainInfo:2367) createDevice: vbd : {'uuid': '7e7e9d2f-a176-2c11-92a4-f90e1e09a1f6', 'bootable': 1, 'driver': 'paravirtualised', 'dev': 'xvda', 'uname': 'tap:tapdisk:/distributed/vms/29567/disk.img', 'mode': 'w'} [2010-10-08 02:34:10 2481] 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/30/51712'} to /local/domain/30/device/vbd/51712. [2010-10-08 02:34:10 2481] DEBUG (DevController:97) DevController: writing {'domain': 'vmprovision.testdomain.net', 'frontend': '/local/domain/30/device/vbd/51712', 'uuid': '7e7e9d2f-a176-2c11-92a4-f90e1e09a1f6', 'bootable': '1', 'dev': 'xvda', 'state': '1', 'params': 'tapdisk:/distributed/vms/29567/disk.img', 'mode': 'w', 'online': '1', 'frontend-id': '30', 'type': 'tap'} to /local/domain/0/backend/vbd/30/51712. [2010-10-08 02:34:10 2481] INFO (XendDomainInfo:2367) createDevice: vbd : {'uuid': '909d2c77-576a-92d4-d7fc-117352f3febe', 'bootable': 0, 'driver': 'paravirtualised', 'dev': 'xvdb', 'uname': 'phy:/dev/VMSwapParts/vmprovision.testdomain.net', 'mode': 'w'} [2010-10-08 02:34:10 2481] DEBUG (DevController:95) DevController: writing {'virtual-device': '51728', 'device-type': 'disk', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vbd/30/51728'} to /local/domain/30/device/vbd/51728. [2010-10-08 02:34:10 2481] DEBUG (DevController:97) DevController: writing {'domain': 'vmprovision.testdomain.net', 'frontend': '/local/domain/30/device/vbd/51728', 'uuid': '909d2c77-576a-92d4-d7fc-117352f3febe', 'bootable': '0', 'dev': 'xvdb', 'state': '1', 'params': '/dev/VMSwapParts/vmprovision.testdomain.net', 'mode': 'w', 'online': '1', 'frontend-id': '30', 'type': 'phy'} to /local/domain/0/backend/vbd/30/51728. [2010-10-08 02:34:10 2481] INFO (XendDomainInfo:2367) createDevice: vif : {'bridge': 'xenbr0', 'mac': '02:00:00:01:cd:fc', 'uuid': 'b444b3f2-a360-4a81-74b8-5e1d9c16ab13', 'script': 'vif-bridge'} [2010-10-08 02:34:10 2481] DEBUG (DevController:95) DevController: writing {'mac': '02:00:00:01:cd:fc', 'handle': '0', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vif/30/0'} to /local/domain/30/device/vif/0. [2010-10-08 02:34:10 2481] DEBUG (DevController:97) DevController: writing {'bridge': 'xenbr0', 'domain': 'vmprovision.testdomain.net', 'handle': '0', 'uuid': 'b444b3f2-a360-4a81-74b8-5e1d9c16ab13', 'script': '/etc/xen/scripts/vif-bridge', 'mac': '02:00:00:01:cd:fc', 'frontend-id': '30', 'state': '1', 'online': '1', 'frontend': '/local/domain/30/device/vif/0'} to /local/domain/0/backend/vif/30/0. [2010-10-08 02:34:10 2481] INFO (XendDomainInfo:2367) createDevice: vif : {'bridge': 'vlanbr338', 'mac': '02:00:00:01:cd:fd', 'uuid': '190b64aa-fb9a-e6de-fc07-b32b4a254588', 'script': 'vif-bridge-vlan'} [2010-10-08 02:34:10 2481] DEBUG (DevController:95) DevController: writing {'mac': '02:00:00:01:cd:fd', 'handle': '1', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vif/30/1'} to /local/domain/30/device/vif/1. [2010-10-08 02:34:10 2481] DEBUG (DevController:97) DevController: writing {'bridge': 'vlanbr338', 'domain': 'vmprovision.testdomain.net', 'handle': '1', 'uuid': '190b64aa-fb9a-e6de-fc07-b32b4a254588', 'script': '/etc/xen/scripts/vif-bridge-vlan', 'mac': '02:00:00:01:cd:fd', 'frontend-id': '30', 'state': '1', 'online': '1', 'frontend': '/local/domain/30/device/vif/1'} to /local/domain/0/backend/vif/30/1. [2010-10-08 02:34:10 2481] DEBUG (XendDomainInfo:3400) Storing VM details: {'on_xend_stop': 'ignore', 'shadow_memory': '0', 'uuid': '29afdd70-8030-db14-f318-d512a43d2d76', 'on_reboot': 'destroy', 'start_time': '1286523250.48', 'on_poweroff': 'destroy', 'bootloader_args': '', 'on_xend_start': 'ignore', 'on_crash': 'preserve', 'xend/restart_count': '0', 'vcpus': '4', 'vcpu_avail': '15', 'bootloader': '', 'image': "(linux (kernel /tmp/vmlinuz.WelUc) (ramdisk /tmp/initrd.gz.WelUc) (superpages 0) (tsc_mode 0) (pci ()) (nomigrate 0) (notes (HV_START_LOW 18446603336221196288) (FEATURES '!writable_page_tables|pae_pgdir_above_4gb') (VIRT_BASE 18446744071562067968) (GUEST_VERSION 2.6) (PADDR_OFFSET 0) (GUEST_OS linux) (HYPERCALL_PAGE 18446744071578882048) (LOADER generic) (SUSPEND_CANCEL 1) (PAE_MODE yes) (ENTRY 18446744071587533312) (XEN_VERSION xen-3.0)))", 'name': 'vmprovision.testdomain.net'} [2010-10-08 02:34:10 2481] DEBUG (XendDomainInfo:1804) Storing domain details: {'console/ring-ref': '2200931', 'image/entry': '18446744071587533312', 'console/port': '2', 'cpu/3/availability': 'online', 'store/ring-ref': '2200932', 'image/loader': 'generic', 'vm': '/vm/29afdd70-8030-db14-f318-d512a43d2d76', 'control/platform-feature-multiprocessor-suspend': '1', 'image/hv-start-low': '18446603336221196288', 'description': 'VM ID 29567 Uber ID 173687', 'cpu/2/availability': 'online', 'cpu/1/availability': 'online', 'image/virt-base': '18446744071562067968', 'memory/target': '512000', 'image/guest-version': '2.6', 'image/pae-mode': 'yes', 'image/guest-os': 'linux', 'console/limit': '1048576', 'image/paddr-offset': '0', 'image/hypercall-page': '18446744071578882048', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'image/features/pae-pgdir-above-4gb': '1', 'image/features/writable-page-tables': '0', 'console/type': 'xenconsoled', 'name': 'vmprovision.testdomain.net', 'domid': '30', 'image/xen-version': 'xen-3.0', 'store/port': '1'} [2010-10-08 02:34:10 2481] DEBUG (DevController:95) DevController: writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/console/30/0'} to /local/domain/30/device/console/0. [2010-10-08 02:34:10 2481] DEBUG (DevController:97) DevController: writing {'domain': 'vmprovision.testdomain.net', 'frontend': '/local/domain/30/device/console/0', 'uuid': 'aa279c46-47df-7512-3655-7fcea7402d02', 'frontend-id': '30', 'state': '1', 'location': '2', 'online': '1', 'protocol': 'vt100'} to /local/domain/0/backend/console/30/0. [2010-10-08 02:34:10 2481] DEBUG (XendDomainInfo:1891) XendDomainInfo.handleShutdownWatch [2010-10-08 02:34:11 2481] DEBUG (DevController:139) Waiting for devices vif2. [2010-10-08 02:34:11 2481] DEBUG (DevController:139) Waiting for devices vif. [2010-10-08 02:34:11 2481] DEBUG (DevController:144) Waiting for 0. [2010-10-08 02:34:11 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vif/30/0/hotplug-status. [2010-10-08 02:34:11 2481] DEBUG (DevController:642) hotplugStatusCallback 1. [2010-10-08 02:34:11 2481] DEBUG (DevController:144) Waiting for 1. [2010-10-08 02:34:11 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vif/30/1/hotplug-status. [2010-10-08 02:34:11 2481] DEBUG (DevController:642) hotplugStatusCallback 1. [2010-10-08 02:34:11 2481] DEBUG (DevController:139) Waiting for devices vscsi. [2010-10-08 02:34:11 2481] DEBUG (DevController:139) Waiting for devices vbd. [2010-10-08 02:34:11 2481] DEBUG (DevController:144) Waiting for 51712. [2010-10-08 02:34:11 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/30/51712/hotplug-status. [2010-10-08 02:35:51 2481] ERROR (SrvBase:88) Request wait_for_devices failed. Traceback (most recent call last): File "/usr/lib/xen-4.0/lib/python/xen/web/SrvBase.py", line 85, in perform return op_method(op, req) File "/usr/lib/xen-4.0/lib/python/xen/xend/server/SrvDomain.py", line 85, in op_wait_for_devices return self.dom.waitForDevices() File "/usr/lib/xen-4.0/lib/python/xen/xend/XendDomainInfo.py", line 1247, in waitForDevices self.getDeviceController(devclass).waitForDevices() File "/usr/lib/xen-4.0/lib/python/xen/xend/server/DevController.py", line 140, in waitForDevices return map(self.waitForDevice, self.deviceIDs()) File "/usr/lib/xen-4.0/lib/python/xen/xend/server/DevController.py", line 155, in waitForDevice (devid, self.deviceClass)) VmError: Device 51712 (vbd) could not be connected. Hotplug scripts not working. [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:3053) XendDomainInfo.destroy: domid=30 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2411) Destroying device model [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2418) Releasing devices [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vif/0 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/0 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vif/1 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/1 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vbd/51712 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/51712 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vbd/51728 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/51728 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing console/0 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = console, device = console/0 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2416) No device model [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2418) Releasing devices [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vif/0 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/0 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vif/1 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/1 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vbd/51712 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/51712 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:2424) Removing vbd/51728 [2010-10-08 02:35:51 2481] DEBUG (XendDomainInfo:1286) XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/51728 [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/30/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/30/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/7/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/8/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/9/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/17/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/18/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/19/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/20/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/21/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/22/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/23/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/24/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/25/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/26/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/27/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/28/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/29/51712/hotplug-status. [2010-10-08 02:35:51 2481] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/30/51712/hotplug-status.

Attachment: signature.asc
Description: Digital signature

_______________________________________________ Xen-users mailing list Xen-users@xxxxxxxxxxxxxxxxxxx http://lists.xensource.com/xen-users

©2013 Xen Project, A Linux Foundation Collaborative Project. All Rights Reserved.
Linux Foundation is a registered trademark of The Linux Foundation.
Xen Project is a trademark of The Linux Foundation.