[CentOS-virt] Device 0 (vif) could not be connected. Hotplug scripts not working.

Mon Apr 14 15:06:39 UTC 2008
Pierre-Philipp Braun <pbraun at wda-fr.org>

Hi,

I got this error when starting a domU on Centos 5.1 i386,
Device 0 (vif) could not be connected. Hotplug scripts not working.

Why is this happening ?  I should restart the machine to see if this
still happends after a fresh network bridge.  But it's somehow a
production server, I would like not to restart it, if possible.  No domU
is currently running.  I could start domUs a week ago.

Here are the troubbleshooting information I have (everything seems fine),

- Centos 5.1 xen-3.0.3 and kernel 2.6.18-53

- ifconfig -a shows,
eth0, lo, peth0, sit0, veth1, veth2, veth3, vif0.0, vif0.1, vif0.2,
vid0.3 and xenbr0.

- brctl show,
bridge name	bridge id		STP enabled	interfaces
xenbr0		8000.feffffffffff	no		peth0
							vif0.0

- activated/deactivating iptables doesn't change anything.  Note,
securitylevel and SELinux are disabled.  Currently deactivated,
Chain INPUT (policy ACCEPT)
target     prot opt source               destination

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination


- xm list -ll
(domain
    (domid 0)
    (uuid 00000000-0000-0000-0000-000000000000)
    (vcpus 1)
    (cpu_weight 1.0)
    (memory 513)
    (shadow_memory 0)
    (maxmem 513)
    (features )
    (name Domain-0)
    (on_poweroff destroy)
    (on_reboot restart)
    (on_crash restart)
    (state r-----)
    (shutdown_reason poweroff)
    (cpu_time 286092.966925)
    (online_vcpus 1)
)

- loop_max is updated to 20 (which doesn't matter as I've got the vif
issue, not vbd),
kernel: loop: loaded (max 20 devices)

- /etc/udev/rules.d/xen-backend.rules exists,
SUBSYSTEM=="xen-backend", KERNEL=="tap*", RUN+="/etc/xen/scripts/blktap
$env{ACTION}"
SUBSYSTEM=="xen-backend", KERNEL=="vbd*", RUN+="/etc/xen/scripts/block
$env{ACTION}"
SUBSYSTEM=="xen-backend", KERNEL=="vtpm*", RUN+="/etc/xen/scripts/vtpm
$env{ACTION}"
SUBSYSTEM=="xen-backend", KERNEL=="vif*", ACTION=="online",
RUN+="$env{script} online"
SUBSYSTEM=="xen-backend", KERNEL=="vif*", ACTION=="offline",
RUN+="$env{script} offline"
SUBSYSTEM=="xen-backend", ACTION=="remove",
RUN+="/etc/xen/scripts/xen-hotplug-cleanup"
KERNEL=="evtchn", NAME="xen/%k"
KERNEL=="blktap[0-9]*", NAME="xen/%k"

- udev is running,
root     21499  0.0  0.1   2240   624 ?        S<s  15:40   0:01
/sbin/udevd -d
root     22744  0.0  0.1   2044   568 pts/8    S    15:43   0:00 udevmonitor

- hald is running,
68       23539  0.0  0.6   5184  3280 ?        Ss   16:23   0:00 hald
root     23540  0.0  0.1   3128   952 ?        S    16:23   0:00 hald-runner
68       23546  0.0  0.1   1988   776 ?        S    16:23   0:00
hald-addon-keyboard: listening on /dev/input/event0

- /proc/sys/kernel/hotplug is empty (which is ok for Centos, I guess, as
hald is used instead of hotplug)

- udevmonitor doesn't say anything

- /bin/sh correctly links to bash (unlike for the debian folks)

- xend.log,
[2008-04-14 16:23:19 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:200) XendDomainInfo.create(['vm', ['name', 'xmb'],
['memory', '256'], ['on_reboot', 'restart'], ['on_crash', 'restart'],
['vcpus', 1], ['image', ['linux', ['kernel', '/data/xmb/vmlinuz'],
['ramdisk', '/data/xmb/initrd'], ['root', '/dev/hda1'], ['args',
'init=/bin/sh']]], ['device', ['vbd', ['uname',
'file:/data/xmb/xmb.ext3'], ['dev', 'hda1'], ['mode', 'w']]], ['device',
['vbd', ['uname', 'file:/data/xmb/xmb.swap'], ['dev', 'hda2'], ['mode',
'w']]]])
[2008-04-14 16:23:19 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:306) parseConfig: config is ['vm', ['name', 'xmb'],
['memory', '256'], ['on_reboot', 'restart'], ['on_crash', 'restart'],
['vcpus', 1], ['image', ['linux', ['kernel', '/data/xmb/vmlinuz'],
['ramdisk', '/data/xmb/initrd'], ['root', '/dev/hda1'], ['args',
'init=/bin/sh']]], ['device', ['vbd', ['uname',
'file:/data/xmb/xmb.ext3'], ['dev', 'hda1'], ['mode', 'w']]], ['device',
['vbd', ['uname', 'file:/data/xmb/xmb.swap'], ['dev', 'hda2'], ['mode',
'w']]]]
[2008-04-14 16:23:19 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:411) parseConfig: result is {'shadow_memory': None,
'start_time': None, 'uuid': None, 'on_crash': 'restart', 'on_reboot':
'restart', 'localtime': None, 'image': ['linux', ['kernel',
'/data/xmb/vmlinuz'], ['ramdisk', '/data/xmb/initrd'], ['root',
'/dev/hda1'], ['args', 'init=/bin/sh']], 'on_poweroff': None,
'bootloader_args': None, 'cpus': None, 'name': 'xmb', 'backend': [],
'vcpus': 1, 'cpu_weight': None, 'features': None, 'vcpu_avail': None,
'memory': 256, 'device': [('vbd', ['vbd', ['uname',
'file:/data/xmb/xmb.ext3'], ['dev', 'hda1'], ['mode', 'w']]), ('vbd',
['vbd', ['uname', 'file:/data/xmb/xmb.swap'], ['dev', 'hda2'], ['mode',
'w']])], 'bootloader': None, 'cpu': None, 'maxmem': None}
[2008-04-14 16:23:19 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:1349) XendDomainInfo.construct: None
[2008-04-14 16:23:19 xend 14992] DEBUG (balloon:127) Balloon: 487248 KiB
free; need 2048; done.
[2008-04-14 16:23:19 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:1397) XendDomainInfo.initDomain: 51 1.0
[2008-04-14 16:23:19 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:1436) _initDomain:shadow_memory=0x0, maxmem=0x100,
memory=0x100.
[2008-04-14 16:23:19 xend 14992] DEBUG (balloon:127) Balloon: 487248 KiB
free; need 262144; done.
[2008-04-14 16:23:19 xend 14992] INFO (image:136) buildDomain os=linux
dom=51 vcpus=1
[2008-04-14 16:23:19 xend 14992] DEBUG (image:201) domid          = 51
[2008-04-14 16:23:19 xend 14992] DEBUG (image:202) memsize        = 256
[2008-04-14 16:23:19 xend 14992] DEBUG (image:203) image          =
/data/xmb/vmlinuz
[2008-04-14 16:23:19 xend 14992] DEBUG (image:204) store_evtchn   = 1
[2008-04-14 16:23:19 xend 14992] DEBUG (image:205) console_evtchn = 2
[2008-04-14 16:23:19 xend 14992] DEBUG (image:206) cmdline        =
root=/dev/hda1 init=/bin/sh
[2008-04-14 16:23:19 xend 14992] DEBUG (image:207) ramdisk        =
/data/xmb/initrd
[2008-04-14 16:23:19 xend 14992] DEBUG (image:208) vcpus          = 1
[2008-04-14 16:23:19 xend 14992] DEBUG (image:209) features       =
[2008-04-14 16:23:20 xend 14992] DEBUG (blkif:24) exception looking up
device number for hda1: [Errno 2] No such file or directory: '/dev/hda1'
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:110)
DevController: writing {'virtual-device': '769', 'device-type': 'disk',
'protocol': 'x86_32-abi', 'backend-id': '0', 'state': '1', 'backend':
'/local/domain/0/backend/vbd/51/769'} to /local/domain/51/device/vbd/769.
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:112)
DevController: writing {'domain': 'xmb', 'frontend':
'/local/domain/51/device/vbd/769', 'dev': 'hda1', 'state': '1',
'params': '/data/xmb/xmb.ext3', 'mode': 'w', 'online': '1',
'frontend-id': '51', 'type': 'file'} to /local/domain/0/backend/vbd/51/769.
[2008-04-14 16:23:20 xend 14992] DEBUG (blkif:24) exception looking up
device number for hda2: [Errno 2] No such file or directory: '/dev/hda2'
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:110)
DevController: writing {'virtual-device': '770', 'device-type': 'disk',
'protocol': 'x86_32-abi', 'backend-id': '0', 'state': '1', 'backend':
'/local/domain/0/backend/vbd/51/770'} to /local/domain/51/device/vbd/770.
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:112)
DevController: writing {'domain': 'xmb', 'frontend':
'/local/domain/51/device/vbd/770', 'dev': 'hda2', 'state': '1',
'params': '/data/xmb/xmb.swap', 'mode': 'w', 'online': '1',
'frontend-id': '51', 'type': 'file'} to /local/domain/0/backend/vbd/51/770.
[2008-04-14 16:23:20 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:756) Storing VM details: {'shadow_memory': '0', 'uuid':
'196487de-140f-ef22-4b77-131313b013e8', 'on_reboot': 'restart',
'start_time': '1208183000.15', 'on_poweroff': 'destroy', 'name': 'xmb',
'xend/restart_count': '0', 'vcpus': '1', 'vcpu_avail': '1', 'memory':
'256', 'on_crash': 'restart', 'image': "(linux (kernel
/data/xmb/vmlinuz) (ramdisk /data/xmb/initrd) (root /dev/hda1) (args
'init=/bin/sh'))", 'maxmem': '256'}
[2008-04-14 16:23:20 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:791) Storing domain details: {'console/ring-ref':
'145356', 'console/port': '2', 'name': 'xmb', 'console/limit':
'1048576', 'vm': '/vm/196487de-140f-ef22-4b77-131313b013e8', 'domid':
'51', 'cpu/0/availability': 'online', 'memory/target': '262144',
'store/ring-ref': '145357', 'store/port': '1'}
[2008-04-14 16:23:20 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:988) XendDomainInfo.handleShutdownWatch
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:143) Waiting for
devices vif.
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:143) Waiting for
devices usb.
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:143) Waiting for
devices vbd.
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:149) Waiting for 769.
[2008-04-14 16:23:20 xend 14992] DEBUG (DevController:476)
hotplugStatusCallback /local/domain/0/backend/vbd/51/769/hotplug-status.
[2008-04-14 16:25:00 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:1557) XendDomainInfo.destroy: domid=51
[2008-04-14 16:25:00 xend.XendDomainInfo 14992] DEBUG
(XendDomainInfo:1566) XendDomainInfo.destroyDomain(51)


Note, someone reported the bug on RHEL5 x86_64; I guess I shouldn't add
a command as a CentOS user (not mentioning I doubt I could reproduce the
bug), https://bugzilla.redhat.com/show_bug.cgi?id=408901

Anthing I could do to dig some more ?  How to fix this ?  I can't play
around so much on this server, although I already restarted udev and
haldaemon, no changes.  (I might reboot it some day but the problem may
disapear then, after a fresh reboot).

Thanks
-- 
Pierre-Philipp Braun