<br><div class="gmail_quote">From: <b class="gmail_sendername">Saravanan S</b> <span dir="ltr"><<a href="mailto:dearsaravanan@gmail.com">dearsaravanan@gmail.com</a>></span><br>Date: 2010/10/26<br>Subject: Re: [one-users] vm still in pending state problem<br>
To: Łukasz Oleś <<a href="mailto:lukaszoles@gmail.com">lukaszoles@gmail.com</a>><br><br><br>Hi,<br><br>Please find the logs below, to create vm and dmesg<br><br># cat /var/log/one/4.log<br>Tue Oct 26 16:18:07 2010 [DiM][I]: New VM state is ACTIVE.<br>
Tue Oct 26 16:18:07 2010 [LCM][I]: New VM state is PROLOG.<br>Tue Oct 26 16:18:07 2010 [VM][I]: Virtual Machine has no context<br>
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<br>Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: DST: /srv/cloud/one/var/4/images/disk.0<br>
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Creating directory /srv/cloud/one/var/4/images<br>Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Executed "mkdir -p /srv/cloud/one/var/4/images".<br>Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w /srv/cloud/one/var/4/images".<br>
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Cloning /var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4<br>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".<br>
Tue Oct 26 16:18:27 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w /srv/cloud/one/var/4/images/disk.0".<br>Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Creating directory /srv/cloud/one/var/4/images<br>Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "mkdir -p /srv/cloud/one/var/4/images".<br>
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w /srv/cloud/one/var/4/images".<br>Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Creating 512Mb image in /srv/cloud/one/var/4/images/disk.1<br>
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".<br>Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Initializing swap space<br>
Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "/sbin/mkswap /srv/cloud/one/var/4/images/disk.1".<br>Tue Oct 26 16:18:28 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w /srv/cloud/one/var/4/images/disk.1".<br>
Tue Oct 26 16:18:28 2010 [LCM][I]: New VM state is BOOT<br>Tue Oct 26 16:18:28 2010 [VMM][I]: Generating deployment file: /var/lib/one/4/deployment.0<br>Tue Oct 26 16:18:29 2010 [VMM][I]: <b>Command execution fail:</b> /lib/remotes/vmm/xen/deploy 127.0.0.1 /var/lib/one/4/deployment.0<br>
Tue Oct 26 16:18:29 2010 [VMM][I]: STDERR follows.<br>Tue Oct 26 16:18:29 2010 [VMM][I]: Error: Had a bootloader specified, but no disks are bootable<br>Tue Oct 26 16:18:29 2010 [VMM][I]: ExitCode: 1<br>Tue Oct 26 16:18:29 2010 [VMM][E]: Error deploying virtual machine<br>
Tue Oct 26 16:18:30 2010 [DiM][I]: New VM state is FAILED<br>Tue Oct 26 16:18:30 2010 [TM][W]: Ignored: LOG - 4 tm_delete.sh: Deleting /srv/cloud/one/var/4/images<br><br>Tue Oct 26 16:18:30 2010 [TM][W]: Ignored: LOG - 4 tm_delete.sh: Executed "rm -rf /srv/cloud/one/var/4/images".<br>
<br>Tue Oct 26 16:18:30 2010 [TM][W]: Ignored: TRANSFER SUCCESS 4 -<br><br># cat /var/log/one/5.log<br>Tue Oct 26 16:19:37 2010 [DiM][I]: New VM state is ACTIVE.<br>Tue Oct 26 16:19:37 2010 [LCM][I]: New VM state is PROLOG.<br>
Tue Oct 26 16:19:37 2010 [VM][I]: Virtual Machine has no context<br>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<br>
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: DST: /srv/cloud/one/var/5/images/disk.0<br>Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Creating directory /srv/cloud/one/var/5/images<br>Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Executed "mkdir -p /srv/cloud/one/var/5/images".<br>
Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w /srv/cloud/one/var/5/images".<br>Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Cloning /var/lib/one//images/c25a93f8b92350dd5a95b28e39a10e7cd9c992f4<br>
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".<br>Tue Oct 26 16:19:58 2010 [TM][I]: tm_clone.sh: Executed "chmod a+w /srv/cloud/one/var/5/images/disk.0".<br>
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Creating directory /srv/cloud/one/var/5/images<br>Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "mkdir -p /srv/cloud/one/var/5/images".<br>Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w /srv/cloud/one/var/5/images".<br>
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Creating 512Mb image in /srv/cloud/one/var/5/images/disk.1<br>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".<br>
Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Initializing swap space<br>Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "/sbin/mkswap /srv/cloud/one/var/5/images/disk.1".<br>Tue Oct 26 16:19:59 2010 [TM][I]: tm_mkswap.sh: Executed "chmod a+w /srv/cloud/one/var/5/images/disk.1".<br>
Tue Oct 26 16:19:59 2010 [LCM][I]: New VM state is BOOT<br>Tue Oct 26 16:19:59 2010 [VMM][I]: Generating deployment file: /var/lib/one/5/deployment.0<br>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<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: STDERR follows.<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ dirname /lib/remotes/vmm/xen/deploy<br>Tue Oct 26 16:20:00 2010 [VMM][I]: + source /lib/remotes/vmm/xen/xenrc<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export XM_PATH=/usr/sbin/xm<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_PATH=/usr/sbin/xm<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_CANCEL=sudo /usr/sbin/xm destroy'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_CANCEL='sudo /usr/sbin/xm destroy'<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_CREATE=sudo /usr/sbin/xm create'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_CREATE='sudo /usr/sbin/xm create'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_CREDITS=sudo /usr/sbin/xm sched-cred'<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_CREDITS='sudo /usr/sbin/xm sched-cred'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_MIGRATE=sudo /usr/sbin/xm migrate -l'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_MIGRATE='sudo /usr/sbin/xm migrate -l'<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_SAVE=sudo /usr/sbin/xm save'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_SAVE='sudo /usr/sbin/xm save'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_RESTORE=sudo /usr/sbin/xm restore'<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_RESTORE='sudo /usr/sbin/xm restore'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_LIST=sudo /usr/sbin/xm list'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_LIST='sudo /usr/sbin/xm list'<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_SHUTDOWN=sudo /usr/sbin/xm shutdown'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_SHUTDOWN='sudo /usr/sbin/xm shutdown'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ export 'XM_POLL=sudo /usr/sbin/xentop -bi2'<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ++ XM_POLL='sudo /usr/sbin/xentop -bi2'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: + domain=127.0.0.1<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ dirname 127.0.0.1<br>Tue Oct 26 16:20:00 2010 [VMM][I]: + mkdir -p .<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: + cat<br>Tue Oct 26 16:20:00 2010 [VMM][I]: ++ sudo /usr/sbin/xm create 127.0.0.1<br>Tue Oct 26 16:20:00 2010 [VMM][I]: Error: Had a bootloader specified, but no disks are bootable<br>Tue Oct 26 16:20:00 2010 [VMM][I]: + output='Using config file "./<a href="http://127.0.0.1" target="_blank">127.0.0.1</a>".'<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: + error_exit 1<br>Tue Oct 26 16:20:00 2010 [VMM][I]: + exit_code=1<br>Tue Oct 26 16:20:00 2010 [VMM][I]: + '[' x1 '!=' x0 ']'<br>Tue Oct 26 16:20:00 2010 [VMM][I]: + exit 1<br>
Tue Oct 26 16:20:00 2010 [VMM][I]: ExitCode: 1<br>Tue Oct 26 16:20:00 2010 [VMM][E]: Error deploying virtual machine<br>Tue Oct 26 16:20:00 2010 [DiM][I]: New VM state is FAILED<br>Tue Oct 26 16:20:00 2010 [TM][W]: Ignored: LOG - 5 tm_delete.sh: Deleting /srv/cloud/one/var/5/images<br>
<br>Tue Oct 26 16:20:00 2010 [TM][W]: Ignored: LOG - 5 tm_delete.sh: Executed "rm -rf /srv/cloud/one/var/5/images".<br><br>Tue Oct 26 16:20:00 2010 [TM][W]: Ignored: TRANSFER SUCCESS 5 -<br><br><br><br># cat /var/log/xen/xen-hotplug.log<br>
Nothing to flush.<br>Nothing to flush.<br>Nothing to flush.<br>Nothing to flush.<br>Nothing to flush.<br>Nothing to flush.<br>Nothing to flush.<br>xenstore-read: couldn't read path backend/vbd/22/768/node<br>xenstore-read: couldn't read path backend/vbd/23/2049/node<br>
xenstore-read: couldn't read path backend/vbd/24/2049/node<br>xenstore-read: couldn't read path backend/vbd/25/2049/node<br><br>#dmesg<br><br><snip><br>usb 5-2: new low speed USB device using uhci_hcd and address 2<br>
usb 5-2: configuration #1 chosen from 1 choice<br>input: CHICONY HP Basic USB Keyboard as /class/input/input1<br>input: USB HID v1.10 Keyboard [CHICONY HP Basic USB Keyboard] on usb-0000:00:1d.0-2<br>device vif7.0 entered promiscuous mode<br>
type=1700 audit(1288075113.797:5): dev=vif7.0 prom=256 old_prom=0 auid=4294967295 ses=4294967295<br>ADDRCONF(NETDEV_UP): vif7.0: link is not ready<br>eth0: port 2(vif7.0) entering disabled state<br>device vif7.0 left promiscuous mode<br>
type=1700 audit(1288075137.923:6): dev=vif7.0 prom=0 old_prom=256 auid=4294967295 ses=4294967295<br>eth0: port 2(vif7.0) entering disabled state<br>device vif8.0 entered promiscuous mode<br>type=1700 audit(1288075171.413:7): dev=vif8.0 prom=256 old_prom=0 auid=4294967295 ses=4294967295<br>
ADDRCONF(NETDEV_UP): vif8.0: link is not ready<br>eth0: port 2(vif8.0) entering disabled state<br>device vif8.0 left promiscuous mode<br>type=1700 audit(1288075195.515:8): dev=vif8.0 prom=0 old_prom=256 auid=4294967295 ses=4294967295<br>
eth0: port 2(vif8.0) entering disabled state<br>tap tap-9-768: 2 getting info<br>tap tap-9-5696: 2 getting info<br>device vif10.0 entered promiscuous mode<br>type=1700 audit(1288075532.276:9): dev=vif10.0 prom=256 old_prom=0 auid=4294967295 ses=4294967295<br>
ADDRCONF(NETDEV_UP): vif10.0: link is not ready<br>eth0: port 2(vif10.0) entering disabled state<br>device vif10.0 left promiscuous mode<br>type=1700 audit(1288075556.365:10): dev=vif10.0 prom=0 old_prom=256 auid=4294967295 ses=4294967295<br>
eth0: port 2(vif10.0) entering disabled state<br>usb 5-1: new low speed USB device using uhci_hcd and address 3<br>usb 5-1: configuration #1 chosen from 1 choice<br>input: Logitech USB Optical Mouse as /class/input/input2<br>
input: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:1d.0-1<br>usb 5-2: USB disconnect, address 2<br>usb 5-1: USB disconnect, address 3<br>device vif11.0 entered promiscuous mode<br>type=1700 audit(1288076866.271:11): dev=vif11.0 prom=256 old_prom=0 auid=4294967295 ses=4294967295<br>
ADDRCONF(NETDEV_UP): vif11.0: link is not ready<br>eth0: port 2(vif11.0) entering disabled state<br>device vif11.0 left promiscuous mode<br>type=1700 audit(1288076890.380:12): dev=vif11.0 prom=0 old_prom=256 auid=4294967295 ses=4294967295<br>
eth0: port 2(vif11.0) entering disabled state<br>device vif12.0 entered promiscuous mode<br>type=1700 audit(1288077654.564:13): dev=vif12.0 prom=256 old_prom=0 auid=4294967295 ses=4294967295<br>ADDRCONF(NETDEV_UP): vif12.0: link is not ready<br>
blkback: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)<br>ADDRCONF(NETDEV_CHANGE): vif12.0: link becomes ready<br>eth0: topology change detected, propagating<br>eth0: port 2(vif12.0) entering forwarding state<br>vif12.0: no IPv6 routers present<br>
eth0: port 2(vif12.0) entering disabled state<br>device vif12.0 left promiscuous mode<br>type=1700 audit(1288077748.886:14): dev=vif12.0 prom=0 old_prom=256 auid=4294967295 ses=4294967295<br>eth0: port 2(vif12.0) entering disabled state<br>
tap tap-13-51712: 2 getting info<br>device vif13.0 entered promiscuous mode<br>type=1700 audit(1288078048.069:15): dev=vif13.0 prom=256 old_prom=0 auid=4294967295 ses=4294967295<br>ADDRCONF(NETDEV_UP): vif13.0: link is not ready<br>
ADDRCONF(NETDEV_CHANGE): vif13.0: link becomes ready<br>eth0: topology change detected, propagating<br>eth0: port 2(vif13.0) entering forwarding state<br>blktap: ring-ref 770, event-channel 9, protocol 2 (x86_32-abi)<br>
vif13.0: no IPv6 routers present<br>
tap tap-14-768: 2 getting info<br>tap tap-14-5696: 2 getting info<br>eth0: port 2(vif13.0) entering disabled state<br>device vif13.0 left promiscuous mode<br>type=1700 audit(1288078186.041:16): dev=vif13.0 prom=0 old_prom=256 auid=4294967295 ses=4294967295<br>
eth0: port 2(vif13.0) entering disabled state<br>Removing netfilter NETLINK layer.<br>tap tap-15-768: 2 getting info<br>tap tap-15-5696: 2 getting info<br>tap tap-16-768: 2 getting info<br>tap tap-16-5696: 2 getting info<br>
tap tap-17-768: 2 getting info<br>tap tap-17-5696: 2 getting info<br>device vif18.0 entered promiscuous mode<br>type=1700 audit(1288082984.257:17): dev=vif18.0 prom=256 old_prom=0 auid=4294967295 ses=4294967295<br>ADDRCONF(NETDEV_UP): vif18.0: link is not ready<br>
blkback: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)<br>ADDRCONF(NETDEV_CHANGE): vif18.0: link becomes ready<br>eth0: topology change detected, propagating<br>eth0: port 2(vif18.0) entering forwarding state<br>vif18.0: no IPv6 routers present<br>
tap tap-19-768: 2 getting info<br>tap tap-19-5696: 2 getting info<br>eth0: port 2(vif18.0) entering disabled state<br>device vif18.0 left promiscuous mode<br>type=1700 audit(1288083547.757:18): dev=vif18.0 prom=0 old_prom=256 auid=4294967295 ses=4294967295<br>
eth0: port 2(vif18.0) entering disabled state<br>tap tap-20-768: 2 getting info<br>tap tap-20-5696: 2 getting info<br>tap tap-21-768: 2 getting info<br>blkback: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)<br>tap tap-27-5696: 2 getting info<br>
blktap: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)<br>tap tap-28-5696: 2 getting info<br>blktap: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)<br>tap tap-29-5696: 2 getting info<br>blktap: ring-ref 8, event-channel 6, protocol 2 (x86_32-abi)<br>
tap tap-30-768: 2 getting info<br>tap tap-30-5696: 2 getting info<br>tap tap-31-768: 2 getting info<br>tap tap-31-5696: 2 getting info<br>tap tap-32-768: 2 getting info<br>tap tap-32-5696: 2 getting info<br><snip><br>
<br><br clear="all">Saravanan Sundaramoorthy<div><div></div><div class="h5"><br><br><div class="gmail_quote">2010/10/26 Łukasz Oleś <span dir="ltr"><<a href="mailto:lukaszoles@gmail.com" target="_blank">lukaszoles@gmail.com</a>></span><br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
W dniu 26 października 2010 09:43 użytkownik Saravanan S<br>
<<a href="mailto:dearsaravanan@gmail.com" target="_blank">dearsaravanan@gmail.com</a>> napisał:<br>
<div>> Hi,<br>
><br>
> 2010/10/26 Łukasz Oleś <<a href="mailto:lukaszoles@gmail.com" target="_blank">lukaszoles@gmail.com</a>><br>
>><br>
>> 2010/10/26 Saravanan S <<a href="mailto:dearsaravanan@gmail.com" target="_blank">dearsaravanan@gmail.com</a>>:<br>
>> > Tue Oct 26 10:46:21 2010 [VMM][I]: STDERR follows.<br>
>> > Tue Oct 26 10:46:21 2010 [VMM][I]: Error: Device 768 (tap) could not be<br>
>> > connecte d. File<br>
>> > not<br>
>> > found.<br>
>><br>
>> In Xen, Opennebula uses blktap driver. Try 'modprobe blktap'.<br>
><br>
> # modprobe blktap<br>
><br>
> no output with the above command.<br>
<br>
</div>Did you try create VM again? Should work now.<br>
<br>
If it stiil doesn't work post your dmesg output and xen-hotplug.log<br></blockquote></div><br>
</div></div></div><br>