Xen users - Jul 2013 - "Operation not permitted" error when using "xe vm-start"

Hey!

I am following the steps at
http://wiki.xenproject.org/wiki/XCP_Beginners_Guide for creating a VM.
I''ve setup my test VM with 1GiB min/max memory. I''ve assigned
2GiB of
memory to dom0 (http://wiki.xen.org/wiki/Xen_Best_Practices) . My box
has 12GB of physical memory and runs Ubuntu 13.04.

When I do "xe vm-start", I get the following:

The server failed to handle your request, due to an internal error.
The given message may give details useful for debugging the problem.
message: Xenctrl.Error [ memory 10340716 KiB free; to be scrubbed 0
KiB; total 12286 MiB]: 1: Operation not permitted

Any idea what might be going?

Here are log files that may be relevant:

* xcp-xapi.log

[20130705T23:36:17.922Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|audit] VM.start: VM
''fca13dc3-464e-579e-35be-f320d07c8ca2 (VM1)''
[20130705T23:36:17.927Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Using wlb
recommendations for choosing a host has been disabled or wlb is not
available. Using original algorithm
[20130705T23:36:17.928Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi_ha_vm_failover]
assert_configuration_change_preserves_ha_plan c = configuration_change
= { old_vms_leaving = [  ]; new_vms_arriving = [ d013cbb8 (vmhost)
4f587324 (VM1) ]; hosts_to_disable = [  ]; num_failures = no change;
new_vms = [  ] }
[20130705T23:36:17.931Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|thread_queue]
push(vm_lifecycle_op, VM.start VM.start R:5de44eac7eab): queue = [
VM.start VM.start R:5de44eac7eab ](1)
[20130705T23:36:17.931Z|debug|vmhost|140||thread_queue]
pop(vm_lifecycle_op) = VM.start VM.start R:5de44eac7eab
[20130705T23:36:17.931Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|locking_helpers] Acquired
lock on VM OpaqueRef:4f587324-df89-c095-2c9d-a8978687e520 with token 3
[20130705T23:36:17.931Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] start: making sure the
VM really is halted
[20130705T23:36:17.931Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] start: checking that
VM can run on this host
[20130705T23:36:17.932Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] start: bringing up
domain in the paused state
[20130705T23:36:17.932Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|memory_control]
reserve_memory_range min=1059840 max=1059840
[20130705T23:36:17.932Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenstore-rpc] Checking pid
1972
[20130705T23:36:17.934Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenstore-rpc] Written
request using id: cdc20b6c-f420-8048-7046-d95658e81eaf
[20130705T23:36:17.934Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] watch: watching
xenstore paths: [
/squeezed/rpc/response/reserve-memory-range/cdc20b6c-f420-8048-7046-d95658e81eaf
] with timeout 300.000000 seconds
[20130705T23:36:17.938Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|memory_control]
reserve_memory_range actual = 1059840
[20130705T23:36:17.938Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|memory_control]
reserved_memory = 1059840; min = 1059840; max = 1059840
[20130705T23:36:17.938Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] VM will have 1
hotplugged vcpus out of 1
[20130705T23:36:17.938Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] xen reports max 256
pCPUs
[20130705T23:36:17.938Z| info|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Memory free 10341228; scrub = 0
[20130705T23:36:17.938Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] Regenerating the
xenstored tree under: [/local/domain/2]
[20130705T23:36:17.946Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] Created domain with
id: 2
[20130705T23:36:17.946Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Created domain with
domid: 2
[20130705T23:36:17.946Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|memory_control]
transfer_reservation_to_domain 51271439-5982-8e84-ab01-d8fcd6bd25d3 ->
2
[20130705T23:36:17.946Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenstore-rpc] Checking pid
1972
[20130705T23:36:17.947Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenstore-rpc] Written
request using id: 20c52eae-3d8e-7024-b98b-2fb1173841cb
[20130705T23:36:17.947Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] watch: watching
xenstore paths: [
/squeezed/rpc/response/transfer-reservation-to-domain/20c52eae-3d8e-7024-b98b-2fb1173841cb
] with timeout 300.000000 seconds
[20130705T23:36:17.951Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|memory_control]
delete_reservation 51271439-5982-8e84-ab01-d8fcd6bd25d3
[20130705T23:36:17.951Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenstore-rpc] Checking pid
1972
[20130705T23:36:17.952Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenstore-rpc] Written
request using id: ab7741eb-9e9d-490e-efbb-b0010a65a3c9
[20130705T23:36:17.952Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] watch: watching
xenstore paths: [
/squeezed/rpc/response/delete-reservation/ab7741eb-9e9d-490e-efbb-b0010a65a3c9
] with timeout 300.000000 seconds
[20130705T23:36:17.959Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Verifying VDI records
exist
[20130705T23:36:17.959Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] creating kernel
[20130705T23:36:17.959Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] build hvm
"/usr/lib/xen-4.2/boot/hvmloader" vcpus:1 mem_max:1048576
mem_target:1048576 video_mib:4 MiB timeoffset:0
[20130705T23:36:17.959Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] build_pre domid=2;
max=1025 MiB; shadow=9 MiB; required=1035 MiB
[20130705T23:36:17.960Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|backtrace] Raised at
domain.ml:435.1-73 -> domain.ml:563.32-113 -> vmops.ml:245.13-129 ->
vmops.ml:1067.5-61
[20130705T23:36:17.960Z|error|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Vmops.start_paused
caught: INTERNAL_ERROR: [ Xenctrl.Error("1: Operation not permitted")
]
[20130705T23:36:17.960Z| info|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Memory F 10339748 KiB
S 0 KiB T 12286 MiB
[20130705T23:36:17.960Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] Domain.destroy: all
known devices = [  ]
[20130705T23:36:17.960Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] Domain.destroy
calling Xenctrl.domain_destroy (domid 2)
[20130705T23:36:17.961Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] Domain.destroy: rm
/local/domain/2
[20130705T23:36:17.963Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops] Domain.destroy:
deleting backend paths
[20130705T23:36:17.964Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops]
Xenctrl.domain_getinfo 2 threw: 1: Operation not permitted -- assuming
domain nolonger exists
[20130705T23:36:17.964Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xenops]
Xenctrl.domain_getinfo 2 threw: 1: Operation not permitted -- assuming
domain nolonger exists
[20130705T23:36:17.964Z| info|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|storage_impl] DP.destroy
task:OpaqueRef:5de44eac-7eab-aaeb-24ae-7dc629b8afab dp:vbd/2/1
allow_leak:false
[20130705T23:36:17.969Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
vmops.ml:1141.10-47 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.969Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> xenctrl.ml:115.13-17 ->
xenctrl.ml:115.56-59 -> xapi_vm.ml:234.6-120 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.969Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.969Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|locking_helpers] Released
lock on VM OpaqueRef:4f587324-df89-c095-2c9d-a8978687e520 with token 3
[20130705T23:36:17.969Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.970Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> message_forwarding.ml:233.25-44 ->
message_forwarding.ml:880.15-67 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.973Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.973Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.975Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.978Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|backtrace] Raised at
pervasiveext.ml:26.22-25 -> message_forwarding.ml:1147.4-1023 ->
rbac.ml:229.16-23
[20130705T23:36:17.978Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|backtrace] Raised at
rbac.ml:238.10-15 -> server_helpers.ml:79.11-41
[20130705T23:36:17.978Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|dispatcher]
Server_helpers.exec exception_handler: Got exception INTERNAL_ERROR: [
Xenctrl.Error [ memory 10340716 KiB free; to be scrubbed 0 KiB; total
12286 MiB]: 1: Operation not permitted ]
[20130705T23:36:17.978Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|dispatcher] Raised at
string.ml:150.25-34 -> stringext.ml:108.13-29
[20130705T23:36:17.978Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|backtrace] Raised at
string.ml:150.25-34 -> stringext.ml:108.13-29
[20130705T23:36:17.982Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
server_helpers.ml:94.14-15 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.983Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|VM.start R:5de44eac7eab|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.983Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|dispatch:VM.start D:243c227848e4|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20130705T23:36:17.983Z|debug|vmhost|145 UNIX
/var/lib/xcp/xapi|dispatch:VM.start D:243c227848e4|backtrace] Raised
at pervasiveext.ml:26.22-25 -> server_helpers.ml:153.10-106 ->
server.ml:7936.19-167 -> server_helpers.ml:119.4-7



* xcp-squeezed.log

[20130705T23:36:17.934Z|debug|vmhost|0||xenstore-rpc] Request for
squeezed/reserve-memory-range/cdc20b6c-f420-8048-7046-d95658e81eaf
[20130705T23:36:17.934Z|debug|vmhost|0||xenstore-rpc] listdir
/squeezed/rpc/request/reserve-memory-range/cdc20b6c-f420-8048-7046-d95658e81eaf
[20130705T23:36:17.934Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/reserve-memory-range/cdc20b6c-f420-8048-7046-d95658e81eaf/session_id
[20130705T23:36:17.934Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/reserve-memory-range/cdc20b6c-f420-8048-7046-d95658e81eaf/min
[20130705T23:36:17.935Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/reserve-memory-range/cdc20b6c-f420-8048-7046-d95658e81eaf/max
[20130705T23:36:17.935Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] total_range = 0 gamma = 1.000000 gamma'' inf
[20130705T23:36:17.935Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] Total additional memory over dynamic_min 10332012 KiB;
will set gamma = 1.00 (leaving unallocated 0 KiB)
[20130705T23:36:17.935Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] free_memory_range ideal target = 1059840
[20130705T23:36:17.935Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] change_host_free_memory required_mem 1069056 KiB
[20130705T23:36:17.936Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] total_range = 0 gamma = 1.000000 gamma'' inf
[20130705T23:36:17.936Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] Total additional memory over dynamic_min 9272172 KiB;
will set gamma = 1.00 (leaving unallocated 0 KiB)
[20130705T23:36:17.936Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] Maximum possible free memory if all active
domains balloon down to dynamic_min = 10341228
[20130705T23:36:17.936Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] current host free mem = 10341228 KiB (aiming
for 1069056 KiB); OK; all domain targets reached; allocation phase
[20130705T23:36:17.936Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] F10341228 S0 R0 T12581372; 0 T2097152
A2097152 M0 Bxx
[20130705T23:36:17.936Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenops] Success: Host free memory = 1069056 KiB
[20130705T23:36:17.936Z|debug|vmhost|0|reserve_memory_range(xapi,
1059840, 1059840)|xenstore-rpc] reserved 1059840 kib for reservation
51271439-5982-8e84-ab01-d8fcd6bd25d3
[20130705T23:36:17.948Z|debug|vmhost|0||xenstore-rpc] Request for
squeezed/transfer-reservation-to-domain/20c52eae-3d8e-7024-b98b-2fb1173841cb
[20130705T23:36:17.948Z|debug|vmhost|0||xenstore-rpc] listdir
/squeezed/rpc/request/transfer-reservation-to-domain/20c52eae-3d8e-7024-b98b-2fb1173841cb
[20130705T23:36:17.948Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/transfer-reservation-to-domain/20c52eae-3d8e-7024-b98b-2fb1173841cb/session_id
[20130705T23:36:17.948Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/transfer-reservation-to-domain/20c52eae-3d8e-7024-b98b-2fb1173841cb/reservation_id
[20130705T23:36:17.948Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/transfer-reservation-to-domain/20c52eae-3d8e-7024-b98b-2fb1173841cb/domid
[20130705T23:36:17.949Z|debug|vmhost|0|transfer_reservation_to_domain(51271439-5982-8e84-ab01-d8fcd6bd25d3,
2)|xenops] Xenctrl.domain_setmaxmem domid=2 max=1060864 (was=0)
[20130705T23:36:17.953Z|debug|vmhost|0||xenstore-rpc] Request for
squeezed/delete-reservation/ab7741eb-9e9d-490e-efbb-b0010a65a3c9
[20130705T23:36:17.953Z|debug|vmhost|0||xenstore-rpc] listdir
/squeezed/rpc/request/delete-reservation/ab7741eb-9e9d-490e-efbb-b0010a65a3c9
[20130705T23:36:17.953Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/delete-reservation/ab7741eb-9e9d-490e-efbb-b0010a65a3c9/session_id
[20130705T23:36:17.953Z|debug|vmhost|0||xenstore-rpc] read
/squeezed/rpc/request/delete-reservation/ab7741eb-9e9d-490e-efbb-b0010a65a3c9/reservation_id