I have downloaded a Xen virtual machine image from the appscale project, and I am trying to start it up. However once I run the command;
xm create -c -f xen.conf
The instance immediately crashes and provides no console output. however it produces logs that I have posted below. but this is the error;
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] WARNING (XendDomainInfo:1178) Domain has crashed: name=appscale-1.4b id=10.
I have managed to mount the root.img file locally and verify that it is actually an ext3 file system.
I am running Xen 3.0.3 that is a stock RPM from the CentOS 5 repos;
# rpm -qa | grep -i xen xen-libs-3.0.3-105.el5_5.5
xen-3.0.3-105.el5_5.5
xen-libs-3.0.3-105.el5_5.5
kernel-xen-2.6.18-194.32.1.el5
any suggestions on how to proceed with troubleshooting? (i am a newbie to Xen)
so far I have enabled console logging, but the log file is empty.
==> domain-builder-ng.log <==
xc_dom_allocate: cmdline=" ip=:1.2.3.4::::eth0:dhcp root=/dev/sda1 ro xencons=tty console=tty1 console=hvc0 debugger=y debug=y sync_console", features=""
xc_dom_kernel_file: filename="/boot/vmlinuz-2.6.27-7-server"
xc_dom_malloc_filemap : 2284 kB
xc_dom_ramdisk_file: filename="/boot/initrd.img-2.6.27-7-server"
xc_dom_malloc_filemap : 9005 kB
xc_dom_boot_xen_init: ver 3.1, caps xen-3.0-x86_64 xen-3.0-x86_32p
xc_dom_parse_image: called
xc_dom_find_loader: trying ELF-generic loader ... failed
xc_dom_find_loader: trying Linux bzImage loader ... xc_dom_malloc : 9875 kB
xc_dom_do_gunzip: unzip ok, 0x234bb2 -> 0x9a4de0
OK
elf_parse_binary: phdr: paddr=0x200000 memsz=0x447000
elf_parse_binary: phdr: paddr=0x647000 memsz=0xab888
elf_parse_binary: phdr: paddr=0x6f3000 memsz=0x908
elf_parse_binary: phdr: paddr=0x6f4000 memsz=0x1c2f9c
elf_parse_binary: memory: 0x200000 -> 0x8b6f9c
elf_xen_parse_note: GUEST_OS = "linux"
elf_xen_parse_note: GUEST_VERSION = "2.6"
elf_xen_parse_note: XEN_VERSION = "xen-3.0"
elf_xen_parse_note: VIRT_BASE = 0xffffffff80000000
elf_xen_parse_note: ENTRY = 0xffffffff8071e200
elf_xen_parse_note: HYPERCALL_PAGE = 0xffffffff80209000
elf_xen_parse_note: FEATURES = "!writable_page_tables|pae_pgdir_above_4gb"
elf_xen_parse_note: PAE_MODE = "yes"
elf_xen_parse_note: LOADER = "generic"
elf_xen_parse_note: unknown xen elf note (0xd)
elf_xen_parse_note: SUSPEND_CANCEL = 0x1
elf_xen_parse_note: HV_START_LOW = 0xffff800000000000
elf_xen_parse_note: PADDR_OFFSET = 0x0
elf_xen_addr_calc_check: addresses:
virt_base = 0xffffffff80000000
elf_paddr_offset = 0x0
virt_offset = 0xffffffff80000000
virt_kstart = 0xffffffff80200000
virt_kend = 0xffffffff808b6f9c
virt_entry = 0xffffffff8071e200
xc_dom_parse_elf_kernel: xen-3.0-x86_64: 0xffffffff80200000 -> 0xffffffff808b6f9c
xc_dom_mem_init: mem 1024 MB, pages 0x40000 pages, 4k each
xc_dom_mem_init: 0x40000 pages
xc_dom_boot_mem_init: called
x86_compat: guest xen-3.0-x86_64, address size 64
xc_dom_malloc : 2048 kB
==> xend.log <==
[2011-03-01 12:34:01 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:01 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:01 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:01 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:01 xend.XendDomainInfo 3580] INFO (XendDomainInfo:957) Dev 0 still active, looping...
[2011-03-01 12:34:01 xend.XendDomainInfo 3580] INFO (XendDomainInfo:957) Dev 0 still active, looping...
[2011-03-01 12:34:01 xend.XendDomainInfo 3580] INFO (XendDomainInfo:957) Dev 0 still active, looping...
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] INFO (XendDomainInfo:957) Dev 0 still active, looping...
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:2114) UUID Created: True
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:2115) Devices to release: [], domid = 9
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:2127) Releasing PVFB backend devices ...
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:207) XendDomainInfo.create(['domain', ['domid', 9], ['uuid', 'd5f22dd4-8dc2-f51f-84e9-eea7d71ea1d0'], ['vcpus', 1], ['vcpu_avail', 1], ['cpu_cap', 0], ['cpu_weight', 256], ['memory', 1024], ['shadow_memory', 0], ['maxmem', 1024], ['features', ''], ['name', 'appscale-1.4b'], ['on_poweroff', 'destroy'], ['on_reboot', 'restart'], ['on_crash', 'restart'], ['image', ['linux', ['kernel', '/boot/vmlinuz-2.6.27-7-server'], ['ramdisk', '/boot/initrd.img-2.6.27-7-server'], ['ip', ':1.2.3.4::::eth0:dhcp'], ['root', '/dev/sda1 ro'], ['args', 'xencons=tty console=tty1 console=hvc0 debugger=y debug=y sync_console']]], ['cpus', []], ['device', ['vif', ['backend', 0], ['script', 'vif-bridge'], ['mac', '00:16:3B:72:10:E4']]], ['device', ['vbd', ['backend', 0], ['dev', 'sda1:disk'], ['uname', 'file:/local/xen/domains/appscale1.4/root.img'], ['mode', 'w']]], ['state', '----c-'], ['shutdown_reason', 'crash'], ['cpu_time', 0.000339131], ['online_vcpus', 1], ['up_time', '0.952092885971'], ['start_time', '1299011639.92'], ['store_mfn', 1169289], ['console_mfn', 1169288]])
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:329) parseConfig: config is ['domain', ['domid', 9], ['uuid', 'd5f22dd4-8dc2-f51f-84e9-eea7d71ea1d0'], ['vcpus', 1], ['vcpu_avail', 1], ['cpu_cap', 0], ['cpu_weight', 256], ['memory', 1024], ['shadow_memory', 0], ['maxmem', 1024], ['features', ''], ['name', 'appscale-1.4b'], ['on_poweroff', 'destroy'], ['on_reboot', 'restart'], ['on_crash', 'restart'], ['image', ['linux', ['kernel', '/boot/vmlinuz-2.6.27-7-server'], ['ramdisk', '/boot/initrd.img-2.6.27-7-server'], ['ip', ':1.2.3.4::::eth0:dhcp'], ['root', '/dev/sda1 ro'], ['args', 'xencons=tty console=tty1 console=hvc0 debugger=y debug=y sync_console']]], ['cpus', []], ['device', ['vif', ['backend', 0], ['script', 'vif-bridge'], ['mac', '00:16:3B:72:10:E4']]], ['device', ['vbd', ['backend', 0], ['dev', 'sda1:disk'], ['uname', 'file:/local/xen/domains/appscale1.4/root.img'], ['mode', 'w']]], ['state', '----c-'], ['shutdown_reason', 'crash'], ['cpu_time', 0.000339131], ['online_vcpus', 1], ['up_time', '0.952092885971'], ['start_time', '1299011639.92'], ['store_mfn', 1169289], ['console_mfn', 1169288]]
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:446) parseConfig: result is {'features': '', 'image': ['linux', ['kernel', '/boot/vmlinuz-2.6.27-7-server'], ['ramdisk', '/boot/initrd.img-2.6.27-7-server'], ['ip', ':1.2.3.4::::eth0:dhcp'], ['root', '/dev/sda1 ro'], ['args', 'xencons=tty console=tty1 console=hvc0 debugger=y debug=y sync_console']], 'cpus': [], 'vcpu_avail': 1, 'backend': [], 'uuid': 'd5f22dd4-8dc2-f51f-84e9-eea7d71ea1d0', 'on_reboot': 'restart', 'cpu_weight': 256.0, 'memory': 1024, 'cpu_cap': 0, 'localtime': None, 'timer_mode': None, 'start_time': 1299011639.9200001, 'on_poweroff': 'destroy', 'on_crash': 'restart', 'device': [('vif', ['vif', ['backend', 0], ['script', 'vif-bridge'], ['mac', '00:16:3B:72:10:E4']]), ('vbd', ['vbd', ['backend', 0], ['dev', 'sda1:disk'], ['uname', 'file:/local/xen/domains/appscale1.4/root.img'], ['mode', 'w']])], 'bootloader': None, 'maxmem': 1024, 'shadow_memory': 0, 'name': 'appscale-1.4b', 'bootloader_args': None, 'vcpus': 1, 'cpu': None}
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:1784) XendDomainInfo.construct: None
[2011-03-01 12:34:02 xend 3580] DEBUG (balloon:145) Balloon: 3034420 KiB free; need 4096; done.
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:1953) XendDomainInfo.initDomain: 10 256.0
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:1994) _initDomain:shadow_memory=0x0, maxmem=0x400, memory=0x400.
[2011-03-01 12:34:02 xend 3580] DEBUG (balloon:145) Balloon: 3034412 KiB free; need 1048576; done.
[2011-03-01 12:34:02 xend 3580] INFO (image:139) buildDomain os=linux dom=10 vcpus=1
[2011-03-01 12:34:02 xend 3580] DEBUG (image:208) domid = 10
[2011-03-01 12:34:02 xend 3580] DEBUG (image:209) memsize = 1024
[2011-03-01 12:34:02 xend 3580] DEBUG (image:210) image = /boot/vmlinuz-2.6.27-7-server
[2011-03-01 12:34:02 xend 3580] DEBUG (image:211) store_evtchn = 1
[2011-03-01 12:34:02 xend 3580] DEBUG (image:212) console_evtchn = 2
[2011-03-01 12:34:02 xend 3580] DEBUG (image:213) cmdline = ip=:1.2.3.4::::eth0:dhcp root=/dev/sda1 ro xencons=tty console=tty1 console=hvc0 debugger=y debug=y sync_console
[2011-03-01 12:34:02 xend 3580] DEBUG (image:214) ramdisk = /boot/initrd.img-2.6.27-7-server
[2011-03-01 12:34:02 xend 3580] DEBUG (image:215) vcpus = 1
[2011-03-01 12:34:02 xend 3580] DEBUG (image:216) features =
==> domain-builder-ng.log <==
xc_dom_build_image: called
xc_dom_alloc_segment: kernel : 0xffffffff80200000 -> 0xffffffff808b7000 (pfn 0x200 + 0x6b7 pages)
xc_dom_pfn_to_ptr: domU mapping: pfn 0x200+0x6b7 at 0x2aaaab5f6000
elf_load_binary: phdr 0 at 0x0x2aaaab5f6000 -> 0x0x2aaaaba3d000
elf_load_binary: phdr 1 at 0x0x2aaaaba3d000 -> 0x0x2aaaabae8888
elf_load_binary: phdr 2 at 0x0x2aaaabae9000 -> 0x0x2aaaabae9908
elf_load_binary: phdr 3 at 0x0x2aaaabaea000 -> 0x0x2aaaabb9a004
xc_dom_alloc_segment: ramdisk : 0xffffffff808b7000 -> 0xffffffff82382000 (pfn 0x8b7 + 0x1acb pages)
xc_dom_malloc : 160 kB
xc_dom_pfn_to_ptr: domU mapping: pfn 0x8b7+0x1acb at 0x2aaab0000000
xc_dom_do_gunzip: unzip ok, 0x8cb5e7 -> 0x1aca210
xc_dom_alloc_segment: phys2mach : 0xffffffff82382000 -> 0xffffffff82582000 (pfn 0x2382 + 0x200 pages)
xc_dom_pfn_to_ptr: domU mapping: pfn 0x2382+0x200 at 0x2aaab1acb000
xc_dom_alloc_page : start info : 0xffffffff82582000 (pfn 0x2582)
xc_dom_alloc_page : xenstore : 0xffffffff82583000 (pfn 0x2583)
xc_dom_alloc_page : console : 0xffffffff82584000 (pfn 0x2584)
nr_page_tables: 0x0000ffffffffffff/48: 0xffff000000000000 -> 0xffffffffffffffff, 1 table(s)
nr_page_tables: 0x0000007fffffffff/39: 0xffffff8000000000 -> 0xffffffffffffffff, 1 table(s)
nr_page_tables: 0x000000003fffffff/30: 0xffffffff80000000 -> 0xffffffffbfffffff, 1 table(s)
nr_page_tables: 0x00000000001fffff/21: 0xffffffff80000000 -> 0xffffffff827fffff, 20 table(s)
xc_dom_alloc_segment: page tables : 0xffffffff82585000 -> 0xffffffff8259c000 (pfn 0x2585 + 0x17 pages)
xc_dom_pfn_to_ptr: domU mapping: pfn 0x2585+0x17 at 0x2aaab1ccb000
xc_dom_alloc_page : boot stack : 0xffffffff8259c000 (pfn 0x259c)
xc_dom_build_image : virt_alloc_end : 0xffffffff8259d000
xc_dom_build_image : virt_pgtab_end : 0xffffffff82800000
xc_dom_boot_image: called
arch_setup_bootearly: doing nothing
xc_dom_compat_check: supported guest type: xen-3.0-x86_64 <= matches
xc_dom_compat_check: supported guest type: xen-3.0-x86_32p
xc_dom_update_guest_p2m: dst 64bit, pages 0x40000
clear_page: pfn 0x2584, mfn 0x11d788
clear_page: pfn 0x2583, mfn 0x11d789
xc_dom_pfn_to_ptr: domU mapping: pfn 0x2582+0x1 at 0x2aaab1ce2000
start_info_x86_64: called
setup_hypercall_page: vaddr=0xffffffff80209000 pfn=0x209
domain builder memory footprint
allocated
malloc : 12139 kB
anon mmap : 0 bytes
mapped
file mmap : 11289 kB
domU mmap : 35 MB
arch_setup_bootlate: shared_info: pfn 0x0, mfn 0xd6fe1
shared_info_x86_64: called
vcpu_x86_64: called
vcpu_x86_64: cr3: pfn 0x2585 mfn 0x11d787
launch_vm: called, ctxt=0x97b21f8
xc_dom_release: called
==> xend.log <==
[2011-03-01 12:34:02 xend 3580] DEBUG (DevController:114) DevController: writing {'mac': '00:16:3B:72:10:E4', 'handle': '0', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vif/10/0'} to /local/domain/10/device/vif/0.
[2011-03-01 12:34:02 xend 3580] DEBUG (DevController:116) DevController: writing {'domain': 'appscale-1.4b', 'handle': '0', 'script': '/etc/xen/scripts/vif-bridge', 'state': '1', 'frontend': '/local/domain/10/device/vif/0', 'mac': '00:16:3B:72:10:E4', 'online': '1', 'frontend-id': '10'} to /local/domain/0/backend/vif/10/0.
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:634) Checking for duplicate for uname: /local/xen/domains/appscale1.4/root.img [file:/local/xen/domains/appscale1.4/root.img], dev: sda1:disk, mode: w
[2011-03-01 12:34:02 xend 3580] DEBUG (blkif:27) exception looking up device number for sda1:disk: [Errno 2] No such file or directory: '/dev/sda1:disk'
[2011-03-01 12:34:02 xend 3580] DEBUG (blkif:27) exception looking up device number for sda1: [Errno 2] No such file or directory: '/dev/sda1'
[2011-03-01 12:34:02 xend 3580] DEBUG (DevController:114) DevController: writing {'virtual-device': '2049', 'device-type': 'disk', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vbd/10/2049'} to /local/domain/10/device/vbd/2049.
[2011-03-01 12:34:02 xend 3580] DEBUG (DevController:116) DevController: writing {'domain': 'appscale-1.4b', 'frontend': '/local/domain/10/device/vbd/2049', 'format': 'raw', 'dev': 'sda1', 'state': '1', 'params': '/local/xen/domains/appscale1.4/root.img', 'mode': 'w', 'online': '1', 'frontend-id': '10', 'type': 'file'} to /local/domain/0/backend/vbd/10/2049.
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:993) Storing VM details: {'shadow_memory': '0', 'uuid': 'd5f22dd4-8dc2-f51f-84e9-eea7d71ea1d0', 'on_reboot': 'restart', 'start_time': '1299011642.74', 'on_poweroff': 'destroy', 'name': 'appscale-1.4b', 'xend/restart_count': '0', 'vcpus': '1', 'vcpu_avail': '1', 'memory': '1024', 'on_crash': 'restart', 'image': "(linux (kernel /boot/vmlinuz-2.6.27-7-server) (ramdisk /boot/initrd.img-2.6.27-7-server) (ip :1.2.3.4::::eth0:dhcp) (root '/dev/sda1 ro') (args 'xencons=tty console=tty1 console=hvc0 debugger=y debug=y sync_console'))", 'maxmem': '1024'}
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:1028) Storing domain details: {'console/ring-ref': '1169288', 'console/port': '2', 'name': 'appscale-1.4b', 'console/limit': '1048576', 'vm': '/vm/d5f22dd4-8dc2-f51f-84e9-eea7d71ea1d0', 'domid': '10', 'cpu/0/availability': 'online', 'memory/target': '1048576', 'store/ring-ref': '1169289', 'store/port': '1'}
[2011-03-01 12:34:02 xend 3580] DEBUG (DevController:158) Waiting for devices vif.
[2011-03-01 12:34:02 xend 3580] DEBUG (DevController:164) Waiting for 0.
[2011-03-01 12:34:02 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:1250) XendDomainInfo.handleShutdownWatch
[2011-03-01 12:34:02 xend 3580] DEBUG (DevController:509) hotplugStatusCallback /local/domain/0/backend/vif/10/0/hotplug-status.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:509) hotplugStatusCallback /local/domain/0/backend/vif/10/0/hotplug-status.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:523) hotplugStatusCallback 1.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices usb.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices vbd.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:164) Waiting for 2049.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:509) hotplugStatusCallback /local/domain/0/backend/vbd/10/2049/hotplug-status.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:509) hotplugStatusCallback /local/domain/0/backend/vbd/10/2049/hotplug-status.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:523) hotplugStatusCallback 1.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices irq.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices vkbd.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices vfb.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices pci.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices ioports.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices tap.
[2011-03-01 12:34:03 xend 3580] DEBUG (DevController:158) Waiting for devices vtpm.
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] WARNING (XendDomainInfo:1178) Domain has crashed: name=appscale-1.4b id=10.
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] ERROR (XendDomainInfo:2654) VM appscale-1.4b restarting too fast (2.275545 seconds since the last restart). Refusing to restart to avoid loops.
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:2189) XendDomainInfo.destroy: domid=10
==> xen-hotplug.log <==
Nothing to flush.
==> xend.log <==
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] INFO (XendDomainInfo:2330) Dev 2049 still active, looping...
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:2114) UUID Created: True
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:2115) Devices to release: [], domid = 10
[2011-03-01 12:34:03 xend.XendDomainInfo 3580] DEBUG (XendDomainInfo:2127) Releasing PVFB backend devices ...
And this is the xen.conf file that I am using;
# cat xen.conf
# Configuration file for the Xen instance AppScale, created
# bn VMBuilder
kernel = '/boot/vmlinuz-2.6.27-7-server'
ramdisk = '/boot/initrd.img-2.6.27-7-server'
memory = 1024
vcpus = 1
root = '/dev/sda1 ro'
disk = [
'file:/local/xen/domains/appscale1.4/root.img,sda1,w',
]
name = 'appscale-1.4b'
dhcp = 'dhcp'
vif = [ 'mac=00:16:3B:72:10:E4' ]
on_poweroff = 'destroy'
on_reboot = 'restart'
on_crash = 'restart'
extra = 'xencons=tty console=tty1 console=hvc0 debugger=y debug=y sync_console'
