[one-users] vm still in pending state problem

Wed Nov 10 10:44:41 PST 2010

Dear all,

I think the problem lies here:

Tue Oct 26 16:20:00 2010 [VMM][I]: Error: Had a bootloader specified,
but no disks are bootable

This may go away if in the image template definition of
"Centos_base_image" something like the following is set:

TARGET="sda"

Could you send us the deployment.0 file (in $ONE_LOCATION/var/<vmid>)?

Regards,

-Tino

--
Constantino Vázquez Blanco | dsa-research.org/tinova
Virtualization Technology Engineer / Researcher
OpenNebula Toolkit | opennebula.org

2010/10/26 Saravanan S <dearsaravanan at gmail.com>:
>
> 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
>
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opennebula.org
> http://lists.opennebula.org/listinfo.cgi/users-opennebula.org
>
>