[one-users] Nebula 4.0.1 Xen 4.1.4 Debian Wheezy - VM stuck in BOOT state

Jacek Jarosiewicz nebula at supermedia.pl
Wed Jun 5 00:16:33 PDT 2013


Hi,

I've searched google and this list but with no luck..

I have setup an opennebula cloud (4.0.1) with xen (4.1) on debian 
wheezy. My problem is that vm's are deployed correctly (vm is running, 
networking is set up, I can ssh to it, run programs within it etc.) but 
opennebula shows vm stuck in boot state and i can't do anything with it 
from either sunstone nor with the onevm command.

I can only delete the vm.

The VM is debian squeeze from marketplace ( 
http://marketplace.c12g.com/appliance/4fec9fb28fb81d2ebc000002 )

no errors in oned.log - only monitoring stuff.. any help is appreciated!

The deployment.0 file is:

name = 'one-19'
memory  = '2048'
vcpus  = '1'
bootloader = "/usr/lib/xen-4.1/bin/pygrub"
disk = [
     'tap2:tapdisk:aio:/var/lib/one//datastores/0/19/disk.0,xvda,w',
     'tap2:tapdisk:aio:/var/lib/one//datastores/0/19/disk.1,xvdb,r',
]
vif = [
     ' mac=02:00:12:a8:01:0a,ip=192.168.1.10,bridge=br0',
]
vfb = ['type=vnc,vnclisten=0.0.0.0,vncdisplay=19']
device_model = '/usr/lib/xen-4.1/bin/qemu-dm'

xm list command output:

root at nebula1:/var/log/xen# xm list
Name                                        ID   Mem VCPUs      State 
Time(s)
Domain-0                                     0  1023     4     r----- 
1194.4
one-19                                       5  2048     1     -b---- 
    1.7


onevm list command output:

oneadmin at nebula0:~$ onevm list
     ID USER     GROUP    NAME            STAT UCPU    UMEM HOST 
      TIME
     19 oneadmin oneadmin deb1            boot    0      2G nebula1 
  0d 01h05


vm log:

Wed Jun  5 08:09:59 2013 [DiM][I]: New VM state is ACTIVE.
Wed Jun  5 08:09:59 2013 [LCM][I]: New VM state is PROLOG.
Wed Jun  5 08:13:20 2013 [LCM][E]: monitor_done_action, VM in a wrong state
Wed Jun  5 08:18:37 2013 [LCM][E]: monitor_done_action, VM in a wrong state
Wed Jun  5 08:22:26 2013 [TM][I]: clone: Cloning 
nebula0:/var/lib/one/datastores/1/78b6cd5fe55967f183d9eabfd9cd7a28 in 
/var/lib/one/datastores/0/19/disk.0
Wed Jun  5 08:22:26 2013 [TM][I]: ExitCode: 0
Wed Jun  5 08:22:27 2013 [TM][I]: context: Generating context block 
device at nebula1:/var/lib/one//datastores/0/19/disk.1
Wed Jun  5 08:22:27 2013 [TM][I]: ExitCode: 0
Wed Jun  5 08:22:27 2013 [LCM][I]: New VM state is BOOT
Wed Jun  5 08:22:27 2013 [VMM][I]: Generating deployment file: 
/var/lib/one/vms/19/deployment.0
Wed Jun  5 08:22:28 2013 [VMM][I]: ExitCode: 0
Wed Jun  5 08:22:28 2013 [VMM][I]: Successfully execute network driver 
operation: pre.
Wed Jun  5 08:22:31 2013 [VMM][D]: deploy: Credits set to 256
Wed Jun  5 08:22:31 2013 [VMM][I]: ExitCode: 0
Wed Jun  5 08:22:31 2013 [VMM][I]: Successfully execute virtualization 
driver operation: deploy.

xend.log:

[2013-06-05 08:22:31 2847] DEBUG (XendDomainInfo:103) 
XendDomainInfo.create(['vm', ['name', 'one-19'], ['memory', '2048'], 
['on_xend_start', 'ignore'], ['on_xend_stop', 'ignore'], ['vcpus', '1'], 
['oos', 1], ['bootloader', '/usr/lib/xen-4.1/bin/pygrub'], 
['bootloader_args', '-q'], ['image', ['linux', ['videoram', 4], 
['tsc_mode', 0], ['nomigrate', 0]]], ['s3_integrity', 1], ['device', 
['tap2', ['uname', 
'tap2:tapdisk:aio:/var/lib/one//datastores/0/19/disk.0'], ['dev', 
'xvda'], ['mode', 'w']]], ['device', ['tap2', ['uname', 
'tap2:tapdisk:aio:/var/lib/one//datastores/0/19/disk.1'], ['dev', 
'xvdb'], ['mode', 'r']]], ['device', ['vif', ['ip', '192.168.1.10'], 
['mac', '02:00:12:a8:01:0a'], ['bridge', 'br0']]], ['device', ['vkbd']], 
['device', ['vfb', ['vnc', '1'], ['vnclisten', '0.0.0.0'], 
['vncdisplay', '19'], ['xauthority', '/root/.Xauthority']]]])
[2013-06-05 08:22:31 2847] DEBUG (XendDomainInfo:2498) 
XendDomainInfo.constructDomain
[2013-06-05 08:22:31 2847] DEBUG (balloon:187) Balloon: 3089336 KiB 
free; need 16384; done.
[2013-06-05 08:22:31 2847] DEBUG (XendDomain:476) Adding Domain: 3
[2013-06-05 08:22:31 2847] DEBUG (XendDomainInfo:2836) 
XendDomainInfo.initDomain: 3 256
[2013-06-05 08:22:31 21477] DEBUG (XendBootloader:113) Launching 
bootloader as ['/usr/lib/xen-4.1/bin/pygrub', 
'--output=/var/run/xend/boot/xenbl.11474', '-q', 
'/var/lib/one//datastores/0/19/disk.0'].
[2013-06-05 08:22:32 2847] DEBUG (image:339) No VNC passwd configured 
for vfb access
[2013-06-05 08:22:32 2847] DEBUG (XendDomainInfo:2863) 
_initDomain:shadow_memory=0x0, memory_static_max=0x80000000, 
memory_static_min=0x0.
[2013-06-05 08:22:32 2847] INFO (image:182) buildDomain os=linux dom=3 
vcpus=1
[2013-06-05 08:22:32 2847] DEBUG (image:721) domid          = 3
[2013-06-05 08:22:32 2847] DEBUG (image:722) memsize        = 2048
[2013-06-05 08:22:32 2847] DEBUG (image:723) image          = 
/var/run/xend/boot/boot_kernel.Nu5QrO
[2013-06-05 08:22:32 2847] DEBUG (image:724) store_evtchn   = 1
[2013-06-05 08:22:32 2847] DEBUG (image:725) console_evtchn = 2
[2013-06-05 08:22:32 2847] DEBUG (image:726) cmdline        = 
root=UUID=5309b3f9-2b10-40a4-aa03-0ff45a6dab7f ro  quiet
[2013-06-05 08:22:32 2847] DEBUG (image:727) ramdisk        = 
/var/run/xend/boot/boot_ramdisk.MvCdMG
[2013-06-05 08:22:32 2847] DEBUG (image:728) vcpus          = 1
[2013-06-05 08:22:32 2847] DEBUG (image:729) features       =
[2013-06-05 08:22:32 2847] DEBUG (image:730) flags          = 0
[2013-06-05 08:22:32 2847] DEBUG (image:731) superpages     = 0
[2013-06-05 08:22:32 2847] INFO (XendDomainInfo:2357) createDevice: vkbd 
: {'uuid': '51fad786-2987-9721-5297-2f5b4251f823'}
[2013-06-05 08:22:32 2847] DEBUG (DevController:95) DevController: 
writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0', 
'backend': '/local/domain/0/backend/vkbd/3/0'} to 
/local/domain/3/device/vkbd/0.
[2013-06-05 08:22:32 2847] DEBUG (DevController:97) DevController: 
writing {'frontend-id': '3', 'domain': 'one-19', 'frontend': 
'/local/domain/3/device/vkbd/0', 'state': '1', 'online': '1'} to 
/local/domain/0/backend/vkbd/3/0.
[2013-06-05 08:22:32 2847] INFO (XendDomainInfo:2357) createDevice: vfb 
: {'other_config': {'vnclisten': '0.0.0.0', 'vnc': '1', 'vncdisplay': 
'19', 'xauthority': '/root/.Xauthority'}, 'vnc': '1', 'xauthority': 
'/root/.Xauthority', 'vnclisten': '0.0.0.0', 'vncdisplay': '19', 'uuid': 
'798de277-63b4-ff7a-e166-9e230c9e5934'}
[2013-06-05 08:22:32 2847] DEBUG (DevController:95) DevController: 
writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0', 
'backend': '/local/domain/0/backend/vfb/3/0'} to 
/local/domain/3/device/vfb/0.
[2013-06-05 08:22:32 2847] DEBUG (DevController:97) DevController: 
writing {'domain': 'one-19', 'frontend': '/local/domain/3/device/vfb/0', 
'uuid': '798de277-63b4-ff7a-e166-9e230c9e5934', 'frontend-id': '3', 
'vnclisten': '0.0.0.0', 'vncdisplay': '19', 'state': '1', 'online': '1', 
'vnc': '1', 'xauthority': '/root/.Xauthority'} to 
/local/domain/0/backend/vfb/3/0.
[2013-06-05 08:22:32 2847] INFO (XendDomainInfo:2357) createDevice: tap2 
: {'bootable': 1, 'uname': 
'tap2:tapdisk:aio:/var/lib/one//datastores/0/19/disk.0', 'mode': 'w', 
'dev': 'xvda', 'uuid': '05ff560d-4e79-1b48-1af8-9885fa82ada7'}
[2013-06-05 08:22:32 2847] 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/3/51712'} to /local/domain/3/device/vbd/51712.
[2013-06-05 08:22:32 2847] DEBUG (DevController:97) DevController: 
writing {'domain': 'one-19', 'frontend': 
'/local/domain/3/device/vbd/51712', 'uuid': 
'05ff560d-4e79-1b48-1af8-9885fa82ada7', 'bootable': '1', 'dev': 'xvda', 
'state': '1', 'params': '/dev/xen/blktap-2/tapdev0', 'mode': 'w', 
'online': '1', 'frontend-id': '3', 'type': 'phy', 'tapdisk-params': 
'tapdisk:aio:/var/lib/one//datastores/0/19/disk.0'} to 
/local/domain/0/backend/vbd/3/51712.
[2013-06-05 08:22:32 2847] INFO (XendDomainInfo:2357) createDevice: tap2 
: {'bootable': 0, 'uname': 
'tap2:tapdisk:aio:/var/lib/one//datastores/0/19/disk.1', 'mode': 'r', 
'dev': 'xvdb', 'uuid': '29791995-b50e-0d36-d941-c0941ba1c95c'}
[2013-06-05 08:22:32 2847] 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/3/51728'} to /local/domain/3/device/vbd/51728.
[2013-06-05 08:22:32 2847] DEBUG (DevController:97) DevController: 
writing {'domain': 'one-19', 'frontend': 
'/local/domain/3/device/vbd/51728', 'uuid': 
'29791995-b50e-0d36-d941-c0941ba1c95c', 'bootable': '0', 'dev': 'xvdb', 
'state': '1', 'params': '/dev/xen/blktap-2/tapdev1', 'mode': 'r', 
'online': '1', 'frontend-id': '3', 'type': 'phy', 'tapdisk-params': 
'tapdisk:aio:/var/lib/one//datastores/0/19/disk.1'} to 
/local/domain/0/backend/vbd/3/51728.
[2013-06-05 08:22:32 2847] INFO (XendDomainInfo:2357) createDevice: vif 
: {'ip': '192.168.1.10', 'mac': '02:00:12:a8:01:0a', 'uuid': 
'a41816d8-c751-72e0-2d0e-98b09fba4212', 'bridge': 'br0'}
[2013-06-05 08:22:32 2847] DEBUG (DevController:95) DevController: 
writing {'mac': '02:00:12:a8:01:0a', 'handle': '0', 'protocol': 
'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': 
'/local/domain/0/backend/vif/3/0'} to /local/domain/3/device/vif/0.
[2013-06-05 08:22:32 2847] DEBUG (DevController:97) DevController: 
writing {'bridge': 'br0', 'domain': 'one-19', 'handle': '0', 'uuid': 
'a41816d8-c751-72e0-2d0e-98b09fba4212', 'script': 
'/etc/xen/scripts/vif-openvswitch', 'ip': '192.168.1.10', 'mac': 
'02:00:12:a8:01:0a', 'frontend-id': '3', 'state': '1', 'online': '1', 
'frontend': '/local/domain/3/device/vif/0'} to 
/local/domain/0/backend/vif/3/0.
[2013-06-05 08:22:32 2847] INFO (image:418) spawning device models: 
/usr/lib/xen-4.1/bin/qemu-dm ['/usr/lib/xen-4.1/bin/qemu-dm', '-d', '3', 
'-serial', 'pty', '-domain-name', 'one-19', '-videoram', '4', '-vnc', 
'0.0.0.0:19', '-vncunused', '-M', 'xenpv']
[2013-06-05 08:22:32 2847] INFO (image:467) device model pid: 21522
[2013-06-05 08:22:32 2847] INFO (image:590) waiting for sentinel_fifo
[2013-06-05 08:22:32 2847] DEBUG (XendDomainInfo:3420) Storing VM 
details: {'on_xend_stop': 'ignore', 'pool_name': 'Pool-0', 
'shadow_memory': '0', 'uuid': 'b64f31a0-357e-8ce3-17e9-77ce159d67eb', 
'on_reboot': 'restart', 'start_time': '1370413352.7', 'on_poweroff': 
'destroy', 'bootloader_args': '-q', 'on_xend_start': 'ignore', 
'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '1', 
'vcpu_avail': '1', 'bootloader': '/usr/lib/xen-4.1/bin/pygrub', 'image': 
"(linux (kernel '') (superpages 0) (videoram 4) (pci ()) (nomigrate 0) 
(tsc_mode 0) (device_model /usr/lib/xen-4.1/bin/qemu-dm) (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 18446744071584203264) 
(XEN_VERSION xen-3.0)))", 'name': 'one-19'}
[2013-06-05 08:22:32 2847] DEBUG (XendDomainInfo:1794) Storing domain 
details: {'console/ring-ref': '799913', 'image/entry': 
'18446744071584203264', 'console/port': '2', 'store/ring-ref': '799914', 
'image/loader': 'generic', 'vm': 
'/vm/b64f31a0-357e-8ce3-17e9-77ce159d67eb', 
'control/platform-feature-multiprocessor-suspend': '1', 
'image/hv-start-low': '18446603336221196288', 'image/guest-os': 'linux', 
'image/virt-base': '18446744071562067968', 'memory/target': '2097152', 
'image/guest-version': '2.6', 'image/pae-mode': 'yes', 'description': 
'', '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': 'ioemu', 
'name': 'one-19', 'domid': '3', 'image/xen-version': 'xen-3.0', 
'store/port': '1'}
[2013-06-05 08:22:32 2847] DEBUG (DevController:95) DevController: 
writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0', 
'backend': '/local/domain/0/backend/console/3/0'} to 
/local/domain/3/device/console/0.
[2013-06-05 08:22:32 2847] DEBUG (DevController:97) DevController: 
writing {'domain': 'one-19', 'frontend': 
'/local/domain/3/device/console/0', 'uuid': 
'1d1d7212-114e-5715-55b0-dd12377f16d1', 'frontend-id': '3', 'state': 
'1', 'location': '2', 'online': '1', 'protocol': 'vt100'} to 
/local/domain/0/backend/console/3/0.
[2013-06-05 08:22:32 2847] DEBUG (XendDomainInfo:1881) 
XendDomainInfo.handleShutdownWatch
[2013-06-05 08:22:32 2847] DEBUG (DevController:139) Waiting for devices 
tap2.
[2013-06-05 08:22:32 2847] DEBUG (DevController:144) Waiting for 51712.
[2013-06-05 08:22:32 2847] DEBUG (DevController:628) 
hotplugStatusCallback /local/domain/0/backend/vbd/3/51712/hotplug-status.
[2013-06-05 08:22:33 2847] DEBUG (DevController:628) 
hotplugStatusCallback /local/domain/0/backend/vbd/3/51712/hotplug-status.
[2013-06-05 08:22:33 2847] DEBUG (DevController:642) 
hotplugStatusCallback 1.
[2013-06-05 08:22:33 2847] DEBUG (DevController:144) Waiting for 51728.
[2013-06-05 08:22:33 2847] DEBUG (DevController:628) 
hotplugStatusCallback /local/domain/0/backend/vbd/3/51728/hotplug-status.
[2013-06-05 08:22:33 2847] DEBUG (DevController:628) 
hotplugStatusCallback /local/domain/0/backend/vbd/3/51728/hotplug-status.
[2013-06-05 08:22:33 2847] DEBUG (DevController:642) 
hotplugStatusCallback 1.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vif.
[2013-06-05 08:22:34 2847] DEBUG (DevController:144) Waiting for 0.
[2013-06-05 08:22:34 2847] DEBUG (DevController:628) 
hotplugStatusCallback /local/domain/0/backend/vif/3/0/hotplug-status.
[2013-06-05 08:22:34 2847] DEBUG (DevController:642) 
hotplugStatusCallback 1.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vkbd.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
ioports.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
tap.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vif2.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
console.
[2013-06-05 08:22:34 2847] DEBUG (DevController:144) Waiting for 0.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vscsi.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vbd.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
irq.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vfb.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
pci.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vusb.
[2013-06-05 08:22:34 2847] DEBUG (DevController:139) Waiting for devices 
vtpm.
[2013-06-05 08:22:34 2847] INFO (XendDomain:1225) Domain one-19 (3) 
unpaused.
[2013-06-05 08:22:34 2847] WARNING (XendDomainInfo:581) Could not 
unpause blktap disk: ('unpause', '-p21487', '-m0') failed (5632  )

Cheers,
J

-- 
Jacek Jarosiewicz


More information about the Users mailing list