Subject: First Experience with Xen3 on amd64 (Thanks, Bouyer!)
To: None <port-xen@NetBSD.org>
From: Marco Poli <poli-bsd@latenter.com>
List: port-xen
Date: 12/19/2007 21:18:55
Hello world,


I must confess I have been waiting for the release of the amd64 port for 
asome months now... to be precise since I bought this Xeon 5120 in this 
PowerEdge 1900 server, around june I guess.

Since the release I have built up a testing environment using -daily 
from 20071215 (kernel 4.99.42). And the latest  xenkernel3 and xentools3 
packages. I did make my own kernel with VT100, Veriexec and CGD support, 
based on the config of the XEN3_DOM0 kernel.

For this test I have:

kern.securelevel=-1
kern.veriexec.setric=0


So far so good. The problem appears when trying to bring the first DomU 
up, with the following config file:

kernel = "/netbsd-INSTALL_XEN3_DOMU.gz"
memory = 128
name = "machine"
vif = [ '' ]
disk = [ 'file:/mnt/virtual/netbsd-common.img,hda1,w' ]


When bringing up xend, in the logs I have:

xend-debug.log:

Xend started at Wed Dec 19 21:41:22 2007.
brctl: not found
brctl: not found



xend.log:

[2007-12-19 21:41:22 674] INFO (SrvDaemon:331) Xend Daemon started
[2007-12-19 21:41:22 674] INFO (SrvDaemon:335) Xend changeset: unavailable.
[2007-12-19 21:41:22 674] INFO (SrvDaemon:342) Xend version: Unknown.
[2007-12-19 21:41:22 674] DEBUG (XendDomainInfo:132) XendDomainInfo.recreate({'max_vcpu_id': 1, 'cpu_time': 26016713305L, 'ssidref': 0, 'hvm': 0, 'shutdown_reason': 0, 'dying': 0, 'online_vcpus': 1, 'domid': 0, 'paused': 0, 'crashed': 0, 'running': 1, 'maxmem_kb': 17179869180L, 'shutdown': 0, 'mem_kb': 131072L, 'handle': [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], 'blocked': 0, 'name': 'Domain-0'})
[2007-12-19 21:41:22 674] INFO (XendDomainInfo:148) Recreating domain 0, UUID 00000000-0000-0000-0000-000000000000. at /local/domain/0
[2007-12-19 21:41:23 674] DEBUG (XendDomain:434) Adding Domain: 0
[2007-12-19 21:41:23 674] DEBUG (XendDomain:379) number of vcpus to use is 0
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VBD.set_device not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VBD.set_type not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VM.get_auto_power_on not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VM.set_auto_power_on not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: debug.get_all not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: console.get_other_config not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: console.set_other_config not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.get_network not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.set_device not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.set_MAC not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.set_MTU not found
[2007-12-19 21:41:23 674] DEBUG (XendDomainInfo:991) XendDomainInfo.handleShutdownWatch
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: session.get_all_records not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: event.get_record not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: event.get_all not found
[2007-12-19 21:41:23 674] INFO (XMLRPCServer:149) Opening Unix domain socket XML-RPC server on /var/run/xend/xen-api.sock; authentication has been disabled for this server.

[2007-12-19 21:41:23 674] INFO (XMLRPCServer:149) Opening Unix domain socket XML-RPC server on /var/run/xend/xmlrpc.sock


Now when tryng to bring to the "machine" machine, I get on the stderror:

vnd0: dos partition I/O error
xbd backend: attach device vnd0d (size 2097152) for domain 8
xvif8.0: Ethernet address 00:16:3e:0c:0d:de
Dec 19 22:58:36 xenserver xenbackendd[1765] Failed to read 
/local/domain/0/backend/console/8/0/script (No such file or directory)
Dec 19 23:00:16 xenserver xenbackendd[1765]: Failed to read 
/local/domain/0/backend/console/8/0/script (No such file or directory)
xbd backend: detach device vnd0d for domain 8
xvif8.0: disconnecting

And right after the xm create end execution, in the same tty:

Error: Device 0 (vif) could not be connected. Hotplug scripts not working.

On /var/log/xenbackendd.log:


xenstore-read: couldn't read path /local/domain/0/backend/vif/8/0/bridge
xenstore-read: couldn't read path /local/domain/0/backend/vif/8/0/bridge
Failed to read /local/domain/0/backend/console/8/0/script (No such file 
or directory)
Failed to read /local/domain/0/backend/console/8/0/script (No such file 
or directory)

/var/log/domain-builder-ng.log:

### ----- xc domain builder logfile opened -----
xc_dom_allocate: cmdline="", features=""
xc_dom_kernel_file: filename="/netbsd-INSTALL_XEN3_DOMU.gz"
xc_dom_malloc_filemap    : 2145 kB
xc_dom_malloc            : 8508 kB
xc_dom_do_gunzip: unzip ok, 0x2186db -> 0x84f0c7
xc_dom_boot_xen_init: ver 3.1, caps xen-3.0-x86_64 xen-3.0-x86_32p hvm-3.0-x86_32 hvm-3.0-x86_32p hvm-3.0-x86_64 
xc_dom_parse_image: called
xc_dom_find_loader: trying ELF-generic loader ... OK
elf_parse_binary: phdr: paddr=0xffffffff80100000 memsz=0x202fc0
elf_parse_binary: phdr: paddr=0xffffffff80402fc0 memsz=0x5302f8
elf_parse_binary: memory: 0xffffffff80100000 -> 0xffffffff809332b8
elf_xen_parse: __xen_guest: "GUEST_OS=NetBSD,GUEST_VER=4.99,XEN_VER=xen-3.0,LOADER=generic,VIRT_BASE=0xffffffff80000000,ELF_PADDR_OFFSET=0xffffffff80000000,VIRT_ENTRY=0xffffffff80100000,HYPERCALL_PAGE=0x00000101,BSD_SYMTAB=yes"
elf_xen_parse_guest_info: GUEST_OS="NetBSD"
elf_xen_parse_guest_info: GUEST_VER="4.99"
elf_xen_parse_guest_info: XEN_VER="xen-3.0"
elf_xen_parse_guest_info: LOADER="generic"
elf_xen_parse_guest_info: VIRT_BASE="0xffffffff80000000"
elf_xen_parse_guest_info: ELF_PADDR_OFFSET="0xffffffff80000000"
elf_xen_parse_guest_info: VIRT_ENTRY="0xffffffff80100000"
elf_xen_parse_guest_info: HYPERCALL_PAGE="0x00000101"
elf_xen_parse_guest_info: BSD_SYMTAB="yes"
elf_xen_addr_calc_check: addresses:
    virt_base        = 0xffffffff80000000
    elf_paddr_offset = 0xffffffff80000000
    virt_offset      = 0x0
    virt_kstart      = 0xffffffff80100000
    virt_kend        = 0xffffffff809332b8
    virt_entry       = 0xffffffff80100000
xc_dom_load_elf_symtab/parse: bsd_symtab_start=ffffffff809332b8, kernel.end=0xffffffff809332b8 -- symtab=0xffffffff809332bc, maxaddr=0xffffffff809338c0
xc_dom_load_elf_symtab: h=21 symtab, size=0x30d38, maxaddr=0xffffffff809645f8
xc_dom_load_elf_symtab: h=22 strtab, size=0x2012f, maxaddr=0xffffffff80984728
xc_dom_parse_elf_kernel: xen-3.0-x86_64: 0xffffffff80100000 -> 0xffffffff80984728
xc_dom_mem_init: mem 128 MB, pages 0x8000 pages, 4k each
xc_dom_mem_init: 0x8000 pages
xc_dom_boot_mem_init: called
x86_compat: guest xen-3.0-x86_64, address size 64
xc_dom_malloc            : 256 kB
xc_dom_build_image: called
xc_dom_alloc_segment:   kernel       : 0xffffffff80100000 -> 0xffffffff80985000  (pfn 0x100 + 0x885 pages)
xc_dom_pfn_to_ptr: domU mapping: pfn 0x100+0x885 at 0x7f7ff627b000
elf_load_binary: phdr 0 at 0x0x7f7ff627b000 -> 0x0x7f7ff647dfc0
elf_load_binary: phdr 1 at 0x0x7f7ff657dfc0 -> 0x0x7f7ff6a6b2e0
xc_dom_load_elf_symtab/load: bsd_symtab_start=ffffffff809332b8, kernel.end=0xffffffff80985000 -- symtab=0xffffffff809332bc, maxaddr=0xffffffff809338c0
xc_dom_load_elf_symtab: h=21 symtab, size=0x30d38, maxaddr=0xffffffff809645f8
xc_dom_load_elf_symtab: h=22 strtab, size=0x2012f, maxaddr=0xffffffff80984728
xc_dom_alloc_segment:   phys2mach    : 0xffffffff80985000 -> 0xffffffff809c5000  (pfn 0x985 + 0x40 pages)
xc_dom_pfn_to_ptr: domU mapping: pfn 0x985+0x40 at 0x7f7ffdf9e000
xc_dom_alloc_page   :   start info   : 0xffffffff809c5000 (pfn 0x9c5)
xc_dom_alloc_page   :   xenstore     : 0xffffffff809c6000 (pfn 0x9c6)
xc_dom_alloc_page   :   console      : 0xffffffff809c7000 (pfn 0x9c7)
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 -> 0xffffffff80bfffff, 6 table(s)
xc_dom_alloc_segment:   page tables  : 0xffffffff809c8000 -> 0xffffffff809d1000  (pfn 0x9c8 + 0x9 pages)
xc_dom_pfn_to_ptr: domU mapping: pfn 0x9c8+0x9 at 0x7f7ffdf95000
xc_dom_alloc_page   :   boot stack   : 0xffffffff809d1000 (pfn 0x9d1)
xc_dom_build_image  : virt_alloc_end : 0xffffffff809d2000
xc_dom_build_image  : virt_pgtab_end : 0xffffffff80c00000
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_compat_check: supported guest type: hvm-3.0-x86_32
xc_dom_compat_check: supported guest type: hvm-3.0-x86_32p
xc_dom_compat_check: supported guest type: hvm-3.0-x86_64
xc_dom_update_guest_p2m: dst 64bit, pages 0x8000 
clear_page: pfn 0x9c7, mfn 0x129bff
clear_page: pfn 0x9c6, mfn 0x129c00
xc_dom_pfn_to_ptr: domU mapping: pfn 0x9c5+0x1 at 0x7f7ffdf94000
start_info_x86_64: called
setup_hypercall_page: vaddr=0xffffffff80101000 pfn=0x101
domain builder memory footprint
   allocated
      malloc             : 8821 kB
      anon mmap          : 0 bytes
   mapped
      file mmap          : 2145 kB
      domU mmap          : 9020 kB
arch_setup_bootlate: shared_info: pfn 0x0, mfn 0xcefc9
shared_info_x86_64: called
vcpu_x86_64: called
vcpu_x86_64: cr3: pfn 0x9c8 mfn 0x129bfe
launch_vm: called, ctxt=0x7f7ff779e018
xc_dom_release: called



/var/log/xend.log:

[2007-12-19 21:41:22 674] INFO (SrvDaemon:331) Xend Daemon started
[2007-12-19 21:41:22 674] INFO (SrvDaemon:335) Xend changeset: unavailable.
[2007-12-19 21:41:22 674] INFO (SrvDaemon:342) Xend version: Unknown.
[2007-12-19 21:41:22 674] DEBUG (XendDomainInfo:132) XendDomainInfo.recreate({'max_vcpu_id': 1, 'cpu_time': 26016713305L, 'ssidref': 0, 'hvm': 0, 'shutdown_reason': 0, 'dying': 0, 'online_vcpus': 1, 'domid': 0, 'paused': 0, 'crashed': 0, 'running': 1, 'maxmem_kb': 17179869180L, 'shutdown': 0, 'mem_kb': 131072L, 'handle': [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], 'blocked': 0, 'name': 'Domain-0'})
[2007-12-19 21:41:22 674] INFO (XendDomainInfo:148) Recreating domain 0, UUID 00000000-0000-0000-0000-000000000000. at /local/domain/0
[2007-12-19 21:41:23 674] DEBUG (XendDomain:434) Adding Domain: 0
[2007-12-19 21:41:23 674] DEBUG (XendDomain:379) number of vcpus to use is 0
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VBD.set_device not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VBD.set_type not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VM.get_auto_power_on not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VM.set_auto_power_on not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: debug.get_all not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: console.get_other_config not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: console.set_other_config not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.get_network not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.set_device not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.set_MAC not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: VIF.set_MTU not found
[2007-12-19 21:41:23 674] DEBUG (XendDomainInfo:991) XendDomainInfo.handleShutdownWatch
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: session.get_all_records not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: event.get_record not found
[2007-12-19 21:41:23 674] WARNING (XendAPI:672) API call: event.get_all not found
[2007-12-19 21:41:23 674] INFO (XMLRPCServer:149) Opening Unix domain socket XML-RPC server on /var/run/xend/xen-api.sock; authentication has been disabled for this server.
[2007-12-19 21:41:23 674] INFO (XMLRPCServer:149) Opening Unix domain socket XML-RPC server on /var/run/xend/xmlrpc.sock.
[2007-12-19 22:58:35 674] DEBUG (XendDomainInfo:84) XendDomainInfo.create(['vm', ['name', 'milena'], ['memory', 128], ['vcpus', 1], ['on_xend_start', 'ignore'], ['on_xend_stop', 'ignore'], ['image', ['linux', ['kernel', '/netbsd-INSTALL_XEN3_DOMU.gz']]], ['device', ['vbd', ['uname', 'file:/mnt/virtual/netbsd-common.img'], ['dev', 'hda1'], ['mode', 'w']]], ['device', ['vif']]])
[2007-12-19 22:58:35 674] DEBUG (XendDomainInfo:1506) XendDomainInfo.constructDomain
[2007-12-19 22:58:36 674] DEBUG (balloon:115) Balloon: 3980376 KiB free; need 2048; done.
[2007-12-19 22:58:36 674] DEBUG (XendDomain:434) Adding Domain: 8
[2007-12-19 22:58:36 674] DEBUG (XendDomainInfo:1560) XendDomainInfo.initDomain: 8 256
[2007-12-19 22:58:36 674] DEBUG (XendDomainInfo:1591) _initDomain:shadow_memory=0x0, memory_static_max=0x8000000, memory_static_min=0x0.
[2007-12-19 22:58:36 674] DEBUG (balloon:115) Balloon: 3980368 KiB free; need 131072; done.
[2007-12-19 22:58:36 674] INFO (image:128) buildDomain os=linux dom=8 vcpus=1
[2007-12-19 22:58:36 674] DEBUG (image:197) domid          = 8
[2007-12-19 22:58:36 674] DEBUG (image:198) memsize        = 128
[2007-12-19 22:58:36 674] DEBUG (image:199) image          = /netbsd-INSTALL_XEN3_DOMU.gz
[2007-12-19 22:58:36 674] DEBUG (image:200) store_evtchn   = 1
[2007-12-19 22:58:36 674] DEBUG (image:201) console_evtchn = 2
[2007-12-19 22:58:36 674] DEBUG (image:202) cmdline        = 
[2007-12-19 22:58:36 674] DEBUG (image:203) ramdisk        = 
[2007-12-19 22:58:36 674] DEBUG (image:204) vcpus          = 1
[2007-12-19 22:58:36 674] DEBUG (image:205) features       = 
[2007-12-19 22:58:36 674] INFO (XendDomainInfo:1409) createDevice: vbd : {'uuid': 'd75e0ac2-8ad4-4092-2c23-e8d7615e1ef5', 'bootable': 1, 'driver': 'paravirtualised', 'dev': 'hda1', 'uname': 'file:/mnt/virtual/netbsd-common.img', 'mode': 'w'}
[2007-12-19 22:58:36 674] DEBUG (DevController:117) DevController: writing {'virtual-device': '769', 'device-type': 'disk', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vbd/8/769'} to /local/domain/8/device/vbd/769.
[2007-12-19 22:58:36 674] DEBUG (DevController:119) DevController: writing {'domain': 'milena', 'frontend': '/local/domain/8/device/vbd/769', 'uuid': 'd75e0ac2-8ad4-4092-2c23-e8d7615e1ef5', 'dev': 'hda1', 'state': '1', 'params': '/mnt/virtual/netbsd-common.img', 'mode': 'w', 'online': '1', 'frontend-id': '8', 'type': 'file'} to /local/domain/0/backend/vbd/8/769.
[2007-12-19 22:58:36 674] INFO (XendDomainInfo:1409) createDevice: vif : {'mac': '00:16:3e:0b:0d:de', 'uuid': '949948ef-4b30-f684-d4a0-84e46e393ead'}
[2007-12-19 22:58:36 674] DEBUG (DevController:117) DevController: writing {'mac': '00:16:3e:0b:0d:de', 'handle': '0', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vif/8/0'} to /local/domain/8/device/vif/0.
[2007-12-19 22:58:36 674] DEBUG (DevController:119) DevController: writing {'domain': 'milena', 'handle': '0', 'uuid': '949948ef-4b30-f684-d4a0-84e46e393ead', 'script': '/usr/pkg/etc/xen/scripts/vif-bridge', 'state': '1', 'frontend': '/local/domain/8/device/vif/0', 'mac': '00:16:3e:0b:0d:de', 'online': '1', 'frontend-id': '8'} to /local/domain/0/backend/vif/8/0.
[2007-12-19 22:58:36 674] DEBUG (XendDomainInfo:2067) Storing VM details: {'on_xend_stop': 'ignore', 'shadow_memory': '0', 'uuid': '7037daca-fd37-8c60-85ba-14cb8028506d', 'on_reboot': 'restart', 'start_time': '1198105116.44', 'on_poweroff': 'destroy', 'on_xend_start': 'ignore', 'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '1', 'vcpu_avail': '1', 'image': '(linux (kernel /netbsd-INSTALL_XEN3_DOMU.gz) (notes))', 'name': 'milena'}
[2007-12-19 22:58:36 674] DEBUG (XendDomainInfo:907) Storing domain details: {'console/ring-ref': '1219583', 'console/port': '2', 'name': 'machine', 'console/limit': '1048576', 'vm': '/vm/7037daca-fd37-8c60-85ba-14cb8028506d', 'domid': '8', 'cpu/0/availability': 'online', 'memory/target': '131072', 'control/platform-feature-multiprocessor-suspend': '1', 'store/ring-ref': '1219584', 'store/port': '1'}
[2007-12-19 22:58:36 674] DEBUG (DevController:117) DevController: writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/console/8/0'} to /local/domain/8/device/console/0.
[2007-12-19 22:58:36 674] DEBUG (DevController:119) DevController: writing {'domain': 'machine', 'protocol': 'vt100', 'uuid': '873837de-f0d1-59c2-7490-2d7eaab38331', 'frontend': '/local/domain/8/device/console/0', 'state': '1', 'location': '2', 'online': '1', 'frontend-id': '8'} to /local/domain/0/backend/console/8/0.
[2007-12-19 22:58:36 674] DEBUG (XendDomainInfo:991) XendDomainInfo.handleShutdownWatch
[2007-12-19 22:58:36 674] DEBUG (DevController:150) Waiting for devices vif.
[2007-12-19 22:58:36 674] DEBUG (DevController:155) Waiting for 0.
[2007-12-19 22:58:36 674] DEBUG (DevController:577) hotplugStatusCallback /local/domain/0/backend/vif/8/0/hotplug-status.
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:1753) XendDomainInfo.destroy: domid=8
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:1772) XendDomainInfo.destroyDomain(8)
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:1430) Removing vif/0
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:569) XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/0
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:1430) Removing vbd/769
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:569) XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/769
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:1430) Removing console/0
[2007-12-19 23:00:16 674] DEBUG (XendDomainInfo:569) XendDomainInfo.destroyDevice: deviceClass = console, device = console/0
[2007-12-19 23:00:16 674] DEBUG (DevController:577) hotplugStatusCallback /local/domain/0/backend/vif/8/0/hotplug-status.

And /var/log/xend-debug.log:

Xend started at Wed Dec 19 21:41:22 2007.
brctl: not found
brctl: not found



I cannot see any messages of the DomU kernel booting, and the xm create 
-c machine command exits about 1 minute after being ran.


Any ideas?


Thanks!