[one-users] vm still in pending state problem

Tue Oct 26 04:11:03 PDT 2010

From: Saravanan S <dearsaravanan at gmail.com>
Date: 2010/10/26
Subject: Re: [one-users] vm still in pending state problem
To: Łukasz Oleś <lukaszoles at gmail.com>

Hi,

Please find the logs below, to create vm and dmesg

# cat /var/log/one/4.log
Tue Oct 26 16:18:07 2010 [DiM][I]: New VM state is ACTIVE.
Tue Oct 26 16:18:07 2010 [LCM][I]: New VM state is PROLOG.
Tue Oct 26 16:18:07 2010 [VM][I]: Virtual Machine has no context
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh:
test2.sios.com:/var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4
127.0.0.1:/srv/cloud/one/var/4/images/disk.0
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: DST:
/srv/cloud/one/var/4/images/disk.0
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Creating directory
/srv/cloud/one/var/4/images
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Executed "mkdir -p
/srv/cloud/one/var/4/images".
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w
/srv/cloud/one/var/4/images".
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Cloning
/var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Executed "cp -r
/var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4
/srv/cloud/one/var/4/images/disk.0".
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w
/srv/cloud/one/var/4/images/disk.0".
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Creating directory
/srv/cloud/one/var/4/images
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "mkdir -p
/srv/cloud/one/var/4/images".
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w
/srv/cloud/one/var/4/images".
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Creating 512Mb image in
/srv/cloud/one/var/4/images/disk.1
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "/bin/dd
if=/dev/zero of=/srv/cloud/one/var/4/images/disk.1 bs=1 count=1 seek=512M".
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Initializing swap space
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "/sbin/mkswap
/srv/cloud/one/var/4/images/disk.1".
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w
/srv/cloud/one/var/4/images/disk.1".
Tue Oct 26 16:18:28 2010 [LCM][I]: New VM state is BOOT
Tue Oct 26 16:18:28 2010 [VMM][I]: Generating deployment file:
/var/lib/one/4/deployment.0
Tue Oct 26 16:18:29 2010 [VMM][I]: *Command execution
fail:*/lib/remotes/vmm/xen/deploy 127.0.0.1
/var/lib/one/4/deployment.0
Tue Oct 26 16:18:29 2010 [VMM][I]: STDERR follows.
Tue Oct 26 16:18:29 2010 [VMM][I]: Error: Had a bootloader specified, but no
disks are bootable
Tue Oct 26 16:18:29 2010 [VMM][I]: ExitCode: 1
Tue Oct 26 16:18:29 2010 [VMM][E]: Error deploying virtual machine
Tue Oct 26 16:18:30 2010 [DiM][I]: New VM state is FAILED
Tue Oct 26 16:18:30 2010 [TM][W]: Ignored: LOG - 4 tm_delete.sh: Deleting
/srv/cloud/one/var/4/images

Tue Oct 26 16:18:30 2010 [TM][W]: Ignored: LOG - 4 tm_delete.sh: Executed
"rm -rf /srv/cloud/one/var/4/images".

Tue Oct 26 16:18:30 2010 [TM][W]: Ignored: TRANSFER SUCCESS 4 -

# cat /var/log/one/5.log
Tue Oct 26 16:19:37 2010 [DiM][I]: New VM state is ACTIVE.
Tue Oct 26 16:19:37 2010 [LCM][I]: New VM state is PROLOG.
Tue Oct 26 16:19:37 2010 [VM][I]: Virtual Machine has no context
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh:
test2.sios.com:/var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4
127.0.0.1:/srv/cloud/one/var/5/images/disk.0
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: DST:
/srv/cloud/one/var/5/images/disk.0
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Creating directory
/srv/cloud/one/var/5/images
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Executed "mkdir -p
/srv/cloud/one/var/5/images".
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w
/srv/cloud/one/var/5/images".
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Cloning
/var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Executed "cp -r
/var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4
/srv/cloud/one/var/5/images/disk.0".
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w
/srv/cloud/one/var/5/images/disk.0".
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Creating directory
/srv/cloud/one/var/5/images
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "mkdir -p
/srv/cloud/one/var/5/images".
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w
/srv/cloud/one/var/5/images".
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Creating 512Mb image in
/srv/cloud/one/var/5/images/disk.1
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "/bin/dd
if=/dev/zero of=/srv/cloud/one/var/5/images/disk.1 bs=1 count=1 seek=512M".
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Initializing swap space
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "/sbin/mkswap
/srv/cloud/one/var/5/images/disk.1".
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w
/srv/cloud/one/var/5/images/disk.1".
Tue Oct 26 16:19:59 2010 [LCM][I]: New VM state is BOOT
Tue Oct 26 16:19:59 2010 [VMM][I]: Generating deployment file:
/var/lib/one/5/deployment.0
Tue Oct 26 16:20:00 2010 [VMM][I]: Command execution fail:
/lib/remotes/vmm/xen/deploy 127.0.0.1 /var/lib/one/5/deployment.0
Tue Oct 26 16:20:00 2010 [VMM][I]: STDERR follows.
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ dirname /lib/remotes/vmm/xen/deploy
Tue Oct 26 16:20:00 2010 [VMM][I]: + source /lib/remotes/vmm/xen/xenrc
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export XM_PATH=/usr/sbin/xm
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_PATH=/usr/sbin/xm
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_CANCEL=sudo /usr/sbin/xm
destroy'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_CANCEL='sudo /usr/sbin/xm destroy'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_CREATE=sudo /usr/sbin/xm
create'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_CREATE='sudo /usr/sbin/xm create'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_CREDITS=sudo /usr/sbin/xm
sched-cred'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_CREDITS='sudo /usr/sbin/xm
sched-cred'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_MIGRATE=sudo /usr/sbin/xm
migrate -l'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_MIGRATE='sudo /usr/sbin/xm migrate
-l'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_SAVE=sudo /usr/sbin/xm
save'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_SAVE='sudo /usr/sbin/xm save'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_RESTORE=sudo /usr/sbin/xm
restore'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_RESTORE='sudo /usr/sbin/xm restore'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_LIST=sudo /usr/sbin/xm
list'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_LIST='sudo /usr/sbin/xm list'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_SHUTDOWN=sudo /usr/sbin/xm
shutdown'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_SHUTDOWN='sudo /usr/sbin/xm
shutdown'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_POLL=sudo /usr/sbin/xentop
-bi2'
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_POLL='sudo /usr/sbin/xentop -bi2'
Tue Oct 26 16:20:00 2010 [VMM][I]: + domain=127.0.0.1
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ dirname 127.0.0.1
Tue Oct 26 16:20:00 2010 [VMM][I]: + mkdir -p .
Tue Oct 26 16:20:00 2010 [VMM][I]: + cat
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ sudo /usr/sbin/xm create 127.0.0.1
Tue Oct 26 16:20:00 2010 [VMM][I]: Error: Had a bootloader specified, but no
disks are bootable
Tue Oct 26 16:20:00 2010 [VMM][I]: + output='Using config file "./127.0.0.1
".'
Tue Oct 26 16:20:00 2010 [VMM][I]: + error_exit 1
Tue Oct 26 16:20:00 2010 [VMM][I]: + exit_code=1
Tue Oct 26 16:20:00 2010 [VMM][I]: + '[' x1 '!=' x0 ']'
Tue Oct 26 16:20:00 2010 [VMM][I]: + exit 1
Tue Oct 26 16:20:00 2010 [VMM][I]: ExitCode: 1
Tue Oct 26 16:20:00 2010 [VMM][E]: Error deploying virtual machine
Tue Oct 26 16:20:00 2010 [DiM][I]: New VM state is FAILED
Tue Oct 26 16:20:00 2010 [TM][W]: Ignored: LOG - 5 tm_delete.sh: Deleting
/srv/cloud/one/var/5/images

Tue Oct 26 16:20:00 2010 [TM][W]: Ignored: LOG - 5 tm_delete.sh: Executed
"rm -rf /srv/cloud/one/var/5/images".

Tue Oct 26 16:20:00 2010 [TM][W]: Ignored: TRANSFER SUCCESS 5 -

# cat /var/log/xen/xen-hotplug.log
Nothing to flush.
Nothing to flush.
Nothing to flush.
Nothing to flush.
Nothing to flush.
Nothing to flush.
Nothing to flush.
xenstore-read: couldn't read path backend/vbd/22/768/node
xenstore-read: couldn't read path backend/vbd/23/2049/node
xenstore-read: couldn't read path backend/vbd/24/2049/node
xenstore-read: couldn't read path backend/vbd/25/2049/node

#dmesg

<snip>
usb 5-2: new low speed USB device using uhci_hcd and address 2
usb 5-2: configuration #1 chosen from 1 choice
input: CHICONY HP Basic USB Keyboard as /class/input/input1
input: USB HID v1.10 Keyboard [CHICONY HP Basic USB Keyboard] on
usb-0000:00:1d.0-2
device vif7.0 entered promiscuous mode
type=1700 audit(1288075113.797:5): dev=vif7.0 prom=256 old_prom=0
auid=4294967295 ses=4294967295
ADDRCONF(NETDEV_UP): vif7.0: link is not ready
eth0: port 2(vif7.0) entering disabled state
device vif7.0 left promiscuous mode
type=1700 audit(1288075137.923:6): dev=vif7.0 prom=0 old_prom=256
auid=4294967295 ses=4294967295
eth0: port 2(vif7.0) entering disabled state
device vif8.0 entered promiscuous mode
type=1700 audit(1288075171.413:7): dev=vif8.0 prom=256 old_prom=0
auid=4294967295 ses=4294967295
ADDRCONF(NETDEV_UP): vif8.0: link is not ready
eth0: port 2(vif8.0) entering disabled state
device vif8.0 left promiscuous mode
type=1700 audit(1288075195.515:8): dev=vif8.0 prom=0 old_prom=256
auid=4294967295 ses=4294967295
eth0: port 2(vif8.0) entering disabled state
tap tap-9-768: 2 getting info
tap tap-9-5696: 2 getting info
device vif10.0 entered promiscuous mode
type=1700 audit(1288075532.276:9): dev=vif10.0 prom=256 old_prom=0
auid=4294967295 ses=4294967295
ADDRCONF(NETDEV_UP): vif10.0: link is not ready
eth0: port 2(vif10.0) entering disabled state
device vif10.0 left promiscuous mode
type=1700 audit(1288075556.365:10): dev=vif10.0 prom=0 old_prom=256
auid=4294967295 ses=4294967295
eth0: port 2(vif10.0) entering disabled state
usb 5-1: new low speed USB device using uhci_hcd and address 3
usb 5-1: configuration #1 chosen from 1 choice
input: Logitech USB Optical Mouse as /class/input/input2
input: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on
usb-0000:00:1d.0-1
usb 5-2: USB disconnect, address 2
usb 5-1: USB disconnect, address 3
device vif11.0 entered promiscuous mode
type=1700 audit(1288076866.271:11): dev=vif11.0 prom=256 old_prom=0
auid=4294967295 ses=4294967295
ADDRCONF(NETDEV_UP): vif11.0: link is not ready
eth0: port 2(vif11.0) entering disabled state
device vif11.0 left promiscuous mode
type=1700 audit(1288076890.380:12): dev=vif11.0 prom=0 old_prom=256
auid=4294967295 ses=4294967295
eth0: port 2(vif11.0) entering disabled state
device vif12.0 entered promiscuous mode
type=1700 audit(1288077654.564:13): dev=vif12.0 prom=256 old_prom=0
auid=4294967295 ses=4294967295
ADDRCONF(NETDEV_UP): vif12.0: link is not ready
blkback: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)
ADDRCONF(NETDEV_CHANGE): vif12.0: link becomes ready
eth0: topology change detected, propagating
eth0: port 2(vif12.0) entering forwarding state
vif12.0: no IPv6 routers present
eth0: port 2(vif12.0) entering disabled state
device vif12.0 left promiscuous mode
type=1700 audit(1288077748.886:14): dev=vif12.0 prom=0 old_prom=256
auid=4294967295 ses=4294967295
eth0: port 2(vif12.0) entering disabled state
tap tap-13-51712: 2 getting info
device vif13.0 entered promiscuous mode
type=1700 audit(1288078048.069:15): dev=vif13.0 prom=256 old_prom=0
auid=4294967295 ses=4294967295
ADDRCONF(NETDEV_UP): vif13.0: link is not ready
ADDRCONF(NETDEV_CHANGE): vif13.0: link becomes ready
eth0: topology change detected, propagating
eth0: port 2(vif13.0) entering forwarding state
blktap: ring-ref 770, event-channel 9, protocol 2 (x86_32-abi)
vif13.0: no IPv6 routers present
tap tap-14-768: 2 getting info
tap tap-14-5696: 2 getting info
eth0: port 2(vif13.0) entering disabled state
device vif13.0 left promiscuous mode
type=1700 audit(1288078186.041:16): dev=vif13.0 prom=0 old_prom=256
auid=4294967295 ses=4294967295
eth0: port 2(vif13.0) entering disabled state
Removing netfilter NETLINK layer.
tap tap-15-768: 2 getting info
tap tap-15-5696: 2 getting info
tap tap-16-768: 2 getting info
tap tap-16-5696: 2 getting info
tap tap-17-768: 2 getting info
tap tap-17-5696: 2 getting info
device vif18.0 entered promiscuous mode
type=1700 audit(1288082984.257:17): dev=vif18.0 prom=256 old_prom=0
auid=4294967295 ses=4294967295
ADDRCONF(NETDEV_UP): vif18.0: link is not ready
blkback: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)
ADDRCONF(NETDEV_CHANGE): vif18.0: link becomes ready
eth0: topology change detected, propagating
eth0: port 2(vif18.0) entering forwarding state
vif18.0: no IPv6 routers present
tap tap-19-768: 2 getting info
tap tap-19-5696: 2 getting info
eth0: port 2(vif18.0) entering disabled state
device vif18.0 left promiscuous mode
type=1700 audit(1288083547.757:18): dev=vif18.0 prom=0 old_prom=256
auid=4294967295 ses=4294967295
eth0: port 2(vif18.0) entering disabled state
tap tap-20-768: 2 getting info
tap tap-20-5696: 2 getting info
tap tap-21-768: 2 getting info
blkback: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)
tap tap-27-5696: 2 getting info
blktap: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)
tap tap-28-5696: 2 getting info
blktap: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)
tap tap-29-5696: 2 getting info
blktap: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)
tap tap-30-768: 2 getting info
tap tap-30-5696: 2 getting info
tap tap-31-768: 2 getting info
tap tap-31-5696: 2 getting info
tap tap-32-768: 2 getting info
tap tap-32-5696: 2 getting info
<snip>

Saravanan Sundaramoorthy

2010/10/26 Łukasz Oleś <lukaszoles at gmail.com>

> W dniu 26 października 2010 09:43 użytkownik Saravanan S
> <dearsaravanan at gmail.com> napisał:
> > Hi,
> >
> > 2010/10/26 Łukasz Oleś <lukaszoles at gmail.com>
> >>
> >> 2010/10/26 Saravanan S <dearsaravanan at gmail.com>:
> >> > Tue Oct 26 10:46:21 2010 [VMM][I]: STDERR follows.
> >> > Tue Oct 26 10:46:21 2010 [VMM][I]: Error: Device 768 (tap) could not
> be
> >> > connecte                                                         d.
> File
> >> > not
> >> > found.
> >>
> >> In Xen, Opennebula uses blktap driver.  Try 'modprobe blktap'.
> >
> > # modprobe blktap
> >
> > no output with the above command.
>
> Did you try create VM again? Should work now.
>
> If it stiil doesn't work post your dmesg output and xen-hotplug.log
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opennebula.org/pipermail/users-opennebula.org/attachments/20101026/f285e46c/attachment-0003.htm>