Hi,
I'm having a problem with one of my VMs after a power outage and primary
storage NFS server dropping. I restarted the XS 6.2 hosts and had issues
reconnecting the NFS server. So I did a "forget" and then recreated the
SR. Thereafter I could see all the VDIs. In CS GUI I can see the volumes
and they're all marked ready. However when I try starting the VMs one
particular VM ( a Windows 2012 R2 server) fails to start. I have checked
to make sure the VDI appears in the NFS share but still it's failing. The
database shows the VDI is still in the table and has a status of up. I
constantly get this error about invalid uuid and don't know how to fix
this. What I noticed in the logs is the fact that CS says it's creating a
VM with a uuid for the VM but the uuid that it's creating for the VM is
different from the actual uuid of the VM both in the GUI and the database.
Is this normal? The relevant log snippet is below. I hope someone can spot
where the issue is.
Kind regards,
2014-09-15 15:20:40,824 DEBUG [c.c.a.q.QueryManagerImpl]
(catalina-exec-1:ctx-5f186e4a ctx-af1e1870) >>>Searching for hosts>>>
2014-09-15 15:20:40,832 DEBUG [c.c.a.q.QueryManagerImpl]
(catalina-exec-1:ctx-5f186e4a ctx-af1e1870) >>>Generating Response>>>
2014-09-15 15:20:40,834 DEBUG [c.c.a.ApiServlet]
(catalina-exec-1:ctx-5f186e4a ctx-af1e1870) ===END=== 10.29.128.147 --
GET
command=listHosts&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&state=Alert&page=1&pageSize=4&_=1410787228314
2014-09-15 15:20:40,847 DEBUG [c.c.a.ApiServlet]
(catalina-exec-25:ctx-33ae4c5e) ===START=== 10.29.128.147 -- GET
command=listCapacity&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&fetchLatest=false&sortBy=usage&page=0&pagesize=8&_=1410787228384
2014-09-15 15:20:40,906 DEBUG [c.c.a.ApiServlet]
(catalina-exec-25:ctx-33ae4c5e ctx-755c277e) ===END=== 10.29.128.147 --
GET
command=listCapacity&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&fetchLatest=false&sortBy=usage&page=0&pagesize=8&_=1410787228384
2014-09-15 15:20:41,501 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-7:null) SeqA 2-48775: Processing Seq 2-48775: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-09-15 15:20:41,523 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-7:null) SeqA 2-48775: Sending Seq 2-48775: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-09-15 15:20:42,827 DEBUG [c.c.a.ApiServlet]
(catalina-exec-7:ctx-f98fd4ee) ===START=== 10.29.128.147 -- GET
command=listVirtualMachines&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&listAll=true&page=1&pagesize=20&_=1410787230321
2014-09-15 15:20:43,303 DEBUG [c.c.a.ApiServlet]
(catalina-exec-7:ctx-f98fd4ee ctx-09995bbd) ===END=== 10.29.128.147 --
GET
command=listVirtualMachines&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&listAll=true&page=1&pagesize=20&_=1410787230321
2014-09-15 15:20:46,501 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 2-48776: Processing Seq 2-48776: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-09-15 15:20:46,521 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 2-48776: Sending Seq 2-48776: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-09-15 15:20:51,502 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 2-48777: Processing Seq 2-48777: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-09-15 15:20:51,518 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 2-48777: Sending Seq 2-48777: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-09-15 15:20:52,094 DEBUG [c.c.a.ApiServlet]
(catalina-exec-4:ctx-c04c94f0) ===START=== 10.29.128.147 -- GET
command=listVirtualMachines&id=fbd594ef-9195-4671-817c-3c48caaaf683&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787239613
2014-09-15 15:20:52,266 DEBUG [c.c.a.ApiServlet]
(catalina-exec-4:ctx-c04c94f0 ctx-371b4a27) ===END=== 10.29.128.147 --
GET
command=listVirtualMachines&id=fbd594ef-9195-4671-817c-3c48caaaf683&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787239613
2014-09-15 15:20:52,388 DEBUG [c.c.a.ApiServlet]
(catalina-exec-10:ctx-0eda32e1) ===START=== 10.29.128.147 -- GET
command=listOsTypes&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787239822
2014-09-15 15:20:53,175 DEBUG [c.c.a.ApiServlet]
(catalina-exec-10:ctx-0eda32e1 ctx-f81e9c55) ===END=== 10.29.128.147 --
GET
command=listOsTypes&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787239822
2014-09-15 15:20:54,667 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-669baba2) Found 0 routers to update status.
2014-09-15 15:20:54,673 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-669baba2) Found 0 networks to update RvR status.
2014-09-15 15:20:55,873 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-10:null) Ping from 2
2014-09-15 15:20:55,950 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-11:null) Ping from 6
2014-09-15 15:20:56,502 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 2-48779: Processing Seq 2-48779: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-09-15 15:20:56,523 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 2-48779: Sending Seq 2-48779: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-09-15 15:21:00,372 DEBUG [c.c.a.ApiServlet]
(catalina-exec-5:ctx-8417c024) ===START=== 10.29.128.147 -- GET
command=startVirtualMachine&id=fbd594ef-9195-4671-817c-3c48caaaf683&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787247891
2014-09-15 15:21:00,512 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-5:ctx-8417c024 ctx-e92b9050) submit async job-733, details:
AsyncJobVO {id:733, userId: 2, accountId: 2, instanceType: VirtualMachine,
instanceId: 60, cmd: org.apache.cloudstack.api.command.user.vm.StartVMCmd,
cmdInfo:
{"id":"fbd594ef-9195-4671-817c-3c48caaaf683","response":"json","sessionkey":"texMswEZiU+v9b9YBnPDe9ZAqh4\u003d","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1410787247891","ctxAccountId":"2","ctxStartEventId":"1482"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 7063056740127, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null}
2014-09-15 15:21:00,516 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-1:ctx-3df833af) Add job-733 into job monitoring
2014-09-15 15:21:00,528 DEBUG [c.c.a.ApiServlet]
(catalina-exec-5:ctx-8417c024 ctx-e92b9050) ===END=== 10.29.128.147 --
GET
command=startVirtualMachine&id=fbd594ef-9195-4671-817c-3c48caaaf683&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787247891
2014-09-15 15:21:00,518 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-1:ctx-3df833af) Executing AsyncJobVO {id:733, userId: 2,
accountId: 2, instanceType: VirtualMachine, instanceId: 60, cmd:
org.apache.cloudstack.api.command.user.vm.StartVMCmd, cmdInfo:
{"id":"fbd594ef-9195-4671-817c-3c48caaaf683","response":"json","sessionkey":"texMswEZiU+v9b9YBnPDe9ZAqh4\u003d","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1410787247891","ctxAccountId":"2","ctxStartEventId":"1482"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 7063056740127, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null}
2014-09-15 15:21:00,837 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deploy avoids pods: [],
clusters: [], hosts: []
2014-09-15 15:21:00,840 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) DeploymentPlanner allocation
algorithm: com.cloud.deploy.UserConcentratedPodPlanner@5bc1d7c6
2014-09-15 15:21:00,841 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to allocate a host and
storage pools from dc:1, pod:1,cluster:1, requested cpu: 2000, requested
ram: 2147483648
2014-09-15 15:21:00,842 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Is ROOT volume READY (pool
already allocated)?: Yes
2014-09-15 15:21:00,842 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) This VM has last host_id
specified, trying to choose the same host: 1
2014-09-15 15:21:00,870 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking if host: 1 has enough
capacity for requested CPU: 2000 and requested RAM: 2147483648 ,
cpuOverprovisioningFactor: 1.0
2014-09-15 15:21:00,883 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Hosts's actual total CPU: 160000
and CPU after applying overprovisioning: 160000
2014-09-15 15:21:00,884 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) We need to allocate to the last
host again, so checking if there is enough reserved capacity
2014-09-15 15:21:00,884 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Reserved CPU: 0 , Requested CPU:
2000
2014-09-15 15:21:00,885 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Reserved RAM: 0 , Requested RAM:
2147483648
2014-09-15 15:21:00,885 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) STATS: Failed to alloc resource
from host: 1 reservedCpu: 0, requested cpu: 2000, reservedMem: 0, requested
mem: 2147483648
2014-09-15 15:21:00,886 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Host does not have enough
reserved CPU available, cannot allocate to this host.
2014-09-15 15:21:00,886 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) The last host of this VM does
not have enough capacity
2014-09-15 15:21:00,887 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Cannot choose the last host to
deploy this VM
2014-09-15 15:21:00,888 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Searching resources only under
specified Cluster: 1
2014-09-15 15:21:00,918 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking resources in Cluster: 1
under Pod: 1
2014-09-15 15:21:00,924 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Looking
for hosts in dc: 1 pod:1 cluster:1
2014-09-15 15:21:00,947 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator)
FirstFitAllocator has 2 hosts to check for allocation: [Host[-1-Routing],
Host[-7-Routing]]
2014-09-15 15:21:00,975 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Found 2
hosts for allocation after prioritization: [Host[-1-Routing],
Host[-7-Routing]]
2014-09-15 15:21:00,976 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Looking
for speed=2000Mhz, Ram=2048
2014-09-15 15:21:01,011 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host: 1
has cpu capability (cpu:64, speed:2500) to support requested CPU: 2 and
requested speed: 1000
2014-09-15 15:21:01,012 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator)
Checking if host: 1 has enough capacity for requested CPU: 2000 and
requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2014-09-15 15:21:01,024 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Hosts's
actual total CPU: 160000 and CPU after applying overprovisioning: 160000
2014-09-15 15:21:01,024 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Free
CPU: 156500 , Requested CPU: 2000
2014-09-15 15:21:01,025 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Free
RAM: 532886487040 , Requested RAM: 2147483648
2014-09-15 15:21:01,026 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host
has enough CPU and RAM available
2014-09-15 15:21:01,026 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) STATS:
Can alloc CPU from host: 1, used: 3500, reserved: 0, actual total: 160000,
total with overprovisioning: 160000; requested
cpu:2000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-09-15 15:21:01,027 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) STATS:
Can alloc MEM from host: 1, used: 3892314112, reserved: 0, total:
536778801152; requested mem: 2147483648,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-09-15 15:21:01,028 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Found a
suitable host, adding to list: 1
2014-09-15 15:21:01,056 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host: 7
has cpu capability (cpu:64, speed:2500) to support requested CPU: 2 and
requested speed: 1000
2014-09-15 15:21:01,056 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator)
Checking if host: 7 has enough capacity for requested CPU: 2000 and
requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2014-09-15 15:21:01,068 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Hosts's
actual total CPU: 160000 and CPU after applying overprovisioning: 160000
2014-09-15 15:21:01,068 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Free
CPU: 160000 , Requested CPU: 2000
2014-09-15 15:21:01,069 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Free
RAM: 536778801152 , Requested RAM: 2147483648
2014-09-15 15:21:01,069 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host
has enough CPU and RAM available
2014-09-15 15:21:01,070 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) STATS:
Can alloc CPU from host: 7, used: 0, reserved: 0, actual total: 160000,
total with overprovisioning: 160000; requested
cpu:2000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-09-15 15:21:01,070 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) STATS:
Can alloc MEM from host: 7, used: 0, reserved: 0, total: 536778801152;
requested mem: 2147483648,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-09-15 15:21:01,071 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Found a
suitable host, adding to list: 7
2014-09-15 15:21:01,071 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host
Allocator returning 2 suitable hosts
2014-09-15 15:21:01,080 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking suitable pools for
volume (Id, Type): (98,ROOT)
2014-09-15 15:21:01,081 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Volume has pool already
allocated, checking if pool can be reused, poolId: 1
2014-09-15 15:21:01,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Planner need not allocate a pool
for this volume since its READY
2014-09-15 15:21:01,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to find a potenial host
and associated storage pools from the suitable host/pool lists for this VM
2014-09-15 15:21:01,092 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking if host: 1 can access
any suitable storage pool for volume: ROOT
2014-09-15 15:21:01,098 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Host: 1 can access pool: 1
2014-09-15 15:21:01,103 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Found a potential host id: 1
name: cloudsrv2.afdb.local and associated storage pools for this VM
2014-09-15 15:21:01,111 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Returning Deployment
Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-09-15 15:21:01,219 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM state transitted from
:Stopped to Starting with event: StartRequestedvm's original host id: 1 new
host id: null host id before state transition: null
2014-09-15 15:21:01,219 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Successfully transitioned to
start state for VM[User|devlab1] reservation id =
bcd3173a-aaa5-4af6-aac3-cbb47ff02269
2014-09-15 15:21:01,233 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to deploy VM, vm has
dcId: 1 and podId: 1
2014-09-15 15:21:01,234 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) advanceStart: DeploymentPlan is
provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
2014-09-15 15:21:01,235 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deploy avoids pods: null,
clusters: null, hosts: null
2014-09-15 15:21:01,253 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Root volume is ready, need to
place VM in volume's cluster
2014-09-15 15:21:01,275 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deploy avoids pods: [],
clusters: [], hosts: []
2014-09-15 15:21:01,275 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) DeploymentPlanner allocation
algorithm: com.cloud.deploy.UserConcentratedPodPlanner@5bc1d7c6
2014-09-15 15:21:01,276 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to allocate a host and
storage pools from dc:1, pod:1,cluster:1, requested cpu: 2000, requested
ram: 2147483648
2014-09-15 15:21:01,276 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Is ROOT volume READY (pool
already allocated)?: Yes
2014-09-15 15:21:01,276 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) DeploymentPlan has host_id
specified, choosing this host and making no checks on this host: 1
2014-09-15 15:21:01,279 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Looking for suitable pools for
this host under zone: 1, pod: 1, cluster: 1
2014-09-15 15:21:01,285 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking suitable pools for
volume (Id, Type): (98,ROOT)
2014-09-15 15:21:01,286 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Volume has pool already
allocated, checking if pool can be reused, poolId: 1
2014-09-15 15:21:01,289 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Planner need not allocate a pool
for this volume since its READY
2014-09-15 15:21:01,289 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to find a potenial host
and associated storage pools from the suitable host/pool lists for this VM
2014-09-15 15:21:01,289 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking if host: 1 can access
any suitable storage pool for volume: ROOT
2014-09-15 15:21:01,292 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Host: 1 can access pool: 1
2014-09-15 15:21:01,295 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Found a potential host id: 1
name: cloudsrv2.afdb.local and associated storage pools for this VM
2014-09-15 15:21:01,295 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Returning Deployment
Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-09-15 15:21:01,295 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deployment found -
P0=VM[User|devlab1],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-09-15 15:21:01,337 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM state transitted from
:Starting to Starting with event: OperationRetryvm's original host id: 1
new host id: 1 host id before state transition: null
2014-09-15 15:21:01,337 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM starting again on the last
host it was stopped on
2014-09-15 15:21:01,359 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Hosts's actual total CPU: 160000
and CPU after applying overprovisioning: 160000
2014-09-15 15:21:01,359 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) We are allocating VM, increasing
the used capacity of this host:1
2014-09-15 15:21:01,359 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Current Used CPU: 3500 , Free
CPU:156500 ,Requested CPU: 2000
2014-09-15 15:21:01,359 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Current Used RAM: 3892314112 ,
Free RAM:532886487040 ,Requested RAM: 2147483648
2014-09-15 15:21:01,360 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) We are allocating VM to the last
host again, so adjusting the reserved capacity if it is not less than
required
2014-09-15 15:21:01,360 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Reserved CPU: 0 , Requested CPU:
2000
2014-09-15 15:21:01,360 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Reserved RAM: 0 , Requested RAM:
2147483648
2014-09-15 15:21:01,360 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) CPU STATS after allocation: for
host: 1, old used: 3500, old reserved: 0, actual total: 160000, total with
overprovisioning: 160000; new used:5500, reserved:0; requested
cpu:2000,alloc_from_last:true
2014-09-15 15:21:01,360 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) RAM STATS after allocation: for
host: 1, old used: 3892314112, old reserved: 0, total: 536778801152; new
used: 6039797760, reserved: 0; requested mem:
2147483648,alloc_from_last:true
2014-09-15 15:21:01,373 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM is being created in podId: 1
2014-09-15 15:21:01,400 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Network id=204 is already
implemented
2014-09-15 15:21:01,478 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Changing active number of nics
for network id=204 on 1
2014-09-15 15:21:01,516 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Asking SecurityGroupProvider to
prepare for Nic[65-60-bcd3173a-aaa5-4af6-aac3-cbb47ff02269-192.168.40.182]
2014-09-15 15:21:01,539 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Asking VirtualRouter to prepare
for Nic[65-60-bcd3173a-aaa5-4af6-aac3-cbb47ff02269-192.168.40.182]
2014-09-15 15:21:01,595 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Lock is acquired for network id
204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-09-15 15:21:01,612 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Lock is released for network id
204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-09-15 15:21:01,760 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Applying dhcp entry in network
Ntwk[204|Guest|6]
2014-09-15 15:21:01,867 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159505: Sending { Cmd
, MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:2b:a4:00:00:0b","vmIpAddress":"192.168.40.182","vmName":"devlab1","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:2b:a4:00:00:0b","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
router.name":"r-4-VM","router.ip":"169.254.1.13"},"wait":0}}] }
2014-09-15 15:21:01,869 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159505: Executing: {
Cmd , MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:2b:a4:00:00:0b","vmIpAddress":"192.168.40.182","vmName":"devlab1","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:2b:a4:00:00:0b","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
router.name":"r-4-VM","router.ip":"169.254.1.13"},"wait":0}}] }
2014-09-15 15:21:01,871 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-38:ctx-5dce503d) Seq 1-292159505: Executing request
2014-09-15 15:21:02,734 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-38:ctx-5dce503d) Seq 1-292159505: Response Received:
2014-09-15 15:21:02,735 DEBUG [c.c.a.t.Request]
(DirectAgent-38:ctx-5dce503d) Seq 1-292159505: Processing: { Ans: ,
MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-09-15 15:21:02,736 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159505: Received: {
Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { Answer } }
2014-09-15 15:21:02,812 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Applying userdata and password
entry in network Ntwk[204|Guest|6]
2014-09-15 15:21:02,912 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159506: Sending { Cmd
, MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name
":"r-4-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name":"r-4-VM"},"wait":0}}] }
2014-09-15 15:21:02,916 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159506: Executing: {
Cmd , MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name
":"r-4-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name":"r-4-VM"},"wait":0}}] }
2014-09-15 15:21:02,918 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-8:ctx-7bb04668) Seq 1-292159506: Executing request
2014-09-15 15:21:03,551 DEBUG [c.c.a.ApiServlet]
(catalina-exec-11:ctx-18a60737) ===START=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=84f6776a-d442-42c0-a04d-c1399af70dae&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787251084
2014-09-15 15:21:03,755 DEBUG [c.c.a.ApiServlet]
(catalina-exec-11:ctx-18a60737 ctx-97165d09) ===END=== 10.29.128.147 --
GET
command=queryAsyncJobResult&jobId=84f6776a-d442-42c0-a04d-c1399af70dae&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787251084
2014-09-15 15:21:04,386 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-8:ctx-7bb04668) Seq 1-292159506: Response Received:
2014-09-15 15:21:04,388 DEBUG [c.c.a.t.Request]
(DirectAgent-8:ctx-7bb04668) Seq 1-292159506: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}]
}
2014-09-15 15:21:04,389 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159506: Received: {
Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { Answer, Answer
} }
2014-09-15 15:21:04,418 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking if we need to prepare 1
volumes for VM[User|devlab1]
2014-09-15 15:21:04,424 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) No need to recreate the volume:
Vol[98|vm=60|ROOT], since it already has a pool assigned: 1, adding disk to
VM
2014-09-15 15:21:04,711 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159507: Sending { Cmd
, MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":60,"name":"i-28-60-VM","bootloader":"PyGrub","type":"User","cpus":2,"minSpeed":1000,"maxSpeed":1000,"minRam":2147483648,"maxRam":2147483648,"arch":"x86_64","os":"Windows
Server 2012 R2
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":true,"vncPassword":"ab2708f053e60810","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:7025","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"fbd594ef-9195-4671-817c-3c48caaaf683","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a1cab116-ff8c-4221-8e31-51b6a76b3b1d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":1,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049,"url":"NetworkFilesystem://
192.168.40.71//fs_nfs1/?ROLE=Primary&STOREUUID=ba737116-8aa6-3644-a595-383d4dc39ed3"}},"name":"ROOT-60","size":64424509440,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","volumeId":98,"vmName":"i-28-60-VM","accountId":28,"format":"VHD","id":98,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"192.168.40.71","volumeSize":"64424509440"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"f66d33a2-b466-4990-9ebf-cd2074c8edf6","ip":"192.168.40.182","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:2b:a4:00:00:0b","dns1":"196.25.1.9","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true}],"vcpuMaxLimit":16},"hostIp":"192.168.40.246","executeInSequence":false,"wait":0}}]
}
2014-09-15 15:21:04,723 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159507: Executing: {
Cmd , MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":60,"name":"i-28-60-VM","bootloader":"PyGrub","type":"User","cpus":2,"minSpeed":1000,"maxSpeed":1000,"minRam":2147483648,"maxRam":2147483648,"arch":"x86_64","os":"Windows
Server 2012 R2
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":true,"vncPassword":"ab2708f053e60810","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:7025","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"fbd594ef-9195-4671-817c-3c48caaaf683","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a1cab116-ff8c-4221-8e31-51b6a76b3b1d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":1,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049,"url":"NetworkFilesystem://
192.168.40.71//fs_nfs1/?ROLE=Primary&STOREUUID=ba737116-8aa6-3644-a595-383d4dc39ed3"}},"name":"ROOT-60","size":64424509440,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","volumeId":98,"vmName":"i-28-60-VM","accountId":28,"format":"VHD","id":98,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"192.168.40.71","volumeSize":"64424509440"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"f66d33a2-b466-4990-9ebf-cd2074c8edf6","ip":"192.168.40.182","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:2b:a4:00:00:0b","dns1":"196.25.1.9","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true}],"vcpuMaxLimit":16},"hostIp":"192.168.40.246","executeInSequence":false,"wait":0}}]
}
2014-09-15 15:21:04,725 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-49:ctx-d33b9f63) Seq 1-292159507: Executing request
2014-09-15 15:21:04,864 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-49:ctx-d33b9f63) 1. The VM i-28-60-VM is in Starting state.
2014-09-15 15:21:04,944 DEBUG [c.c.h.x.r.CitrixHelper]
(DirectAgent-49:ctx-d33b9f63) Can't find the guest os: Windows Server 2012
R2 (64-bit) mapping into XenServer 6.2.0 guestOS type, start it as HVM guest
2014-09-15 15:21:04,971 WARN [c.c.h.x.r.XenServer620Resource]
(DirectAgent-49:ctx-d33b9f63) No recommended value found for dynamic min
2014-09-15 15:21:04,972 WARN [c.c.h.x.r.XenServer620Resource]
(DirectAgent-49:ctx-d33b9f63) No recommended value found for dynamic max,
setting static max and dynamic max equal
2014-09-15 15:21:05,014 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-49:ctx-d33b9f63) Created VM
72b1274b-9b88-b686-7c52-e5013bfd1eef for i-28-60-VM
2014-09-15 15:21:05,037 WARN [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-49:ctx-d33b9f63) Catch Exception: class
com.xensource.xenapi.Types$UuidInvalid due to The uuid you supplied was
invalid.
The uuid you supplied was invalid.
at com.xensource.xenapi.Types.checkResponse(Types.java:927)
at com.xensource.xenapi.Connection.dispatch(Connection.java:368)
at
com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909)
at com.xensource.xenapi.VDI.getByUuid(VDI.java:326)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.mount(CitrixResourceBase.java:1196)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.createVbd(CitrixResourceBase.java:1204)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:1710)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:545)
at
com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
at
com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
at
com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2014-09-15 15:21:05,041 WARN [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-49:ctx-d33b9f63) Unable to start i-28-60-VM due to
The uuid you supplied was invalid.
at com.xensource.xenapi.Types.checkResponse(Types.java:927)
at com.xensource.xenapi.Connection.dispatch(Connection.java:368)
at
com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909)
at com.xensource.xenapi.VDI.getByUuid(VDI.java:326)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.mount(CitrixResourceBase.java:1196)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.createVbd(CitrixResourceBase.java:1204)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:1710)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:545)
at
com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
at
com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
at
com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2014-09-15 15:21:05,087 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-49:ctx-d33b9f63) The VM is in stopped state, detected problem
during startup : i-28-60-VM
2014-09-15 15:21:05,088 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-49:ctx-d33b9f63) Seq 1-292159507: Response Received:
2014-09-15 15:21:05,107 DEBUG [c.c.a.t.Request]
(DirectAgent-49:ctx-d33b9f63) Seq 1-292159507: Processing: { Ans: ,
MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":60,"name":"i-28-60-VM","bootloader":"PyGrub","type":"User","cpus":2,"minSpeed":1000,"maxSpeed":1000,"minRam":2147483648,"maxRam":2147483648,"arch":"x86_64","os":"Windows
Server 2012 R2
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":true,"vncPassword":"ab2708f053e60810","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:7025","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"fbd594ef-9195-4671-817c-3c48caaaf683","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a1cab116-ff8c-4221-8e31-51b6a76b3b1d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":1,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049,"url":"NetworkFilesystem://
192.168.40.71//fs_nfs1/?ROLE=Primary&STOREUUID=ba737116-8aa6-3644-a595-383d4dc39ed3"}},"name":"ROOT-60","size":64424509440,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","volumeId":98,"vmName":"i-28-60-VM","accountId":28,"format":"VHD","id":98,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"192.168.40.71","volumeSize":"64424509440"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"f66d33a2-b466-4990-9ebf-cd2074c8edf6","ip":"192.168.40.182","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:2b:a4:00:00:0b","dns1":"196.25.1.9","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true}],"vcpuMaxLimit":16},"_iqnToPath":{},"result":false,"details":"Unable
to start i-28-60-VM due to ","wait":0}}] }
2014-09-15 15:21:05,108 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159507: Received: {
Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { StartAnswer } }
2014-09-15 15:21:05,124 INFO [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Unable to start VM on
Host[-1-Routing] due to Unable to start i-28-60-VM due to
2014-09-15 15:21:05,138 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Cleaning up resources for the vm
VM[User|devlab1] in Starting state
2014-09-15 15:21:05,152 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159508: Sending { Cmd
, MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-28-60-VM","wait":0}}]
}
2014-09-15 15:21:05,153 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159508: Executing: {
Cmd , MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-28-60-VM","wait":0}}]
}
2014-09-15 15:21:05,155 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-1:ctx-a201025b) Seq 1-292159508: Executing request
2014-09-15 15:21:05,288 INFO [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-1:ctx-a201025b) VM does not exist on
XenServer24eec1a3-1776-4c18-81a9-608d38d94911
2014-09-15 15:21:05,290 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-1:ctx-a201025b) Seq 1-292159508: Response Received:
2014-09-15 15:21:05,292 DEBUG [c.c.a.t.Request]
(DirectAgent-1:ctx-a201025b) Seq 1-292159508: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not
exist","wait":0}}] }
2014-09-15 15:21:05,293 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159508: Received: {
Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
2014-09-15 15:21:05,357 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Changing active number of nics
for network id=204 on -1
2014-09-15 15:21:05,387 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Asking SecurityGroupProvider to
release
NicProfile[65-60-bcd3173a-aaa5-4af6-aac3-cbb47ff02269-192.168.40.182-vlan://untagged
2014-09-15 15:21:05,397 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Asking VirtualRouter to release
NicProfile[65-60-bcd3173a-aaa5-4af6-aac3-cbb47ff02269-192.168.40.182-vlan://untagged
2014-09-15 15:21:05,398 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Successfully released network
resources for the vm VM[User|devlab1]
2014-09-15 15:21:05,398 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Successfully cleanued up
resources for the vm VM[User|devlab1] in Starting state
2014-09-15 15:21:05,411 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Root volume is ready, need to
place VM in volume's cluster
2014-09-15 15:21:05,449 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deploy avoids pods: [],
clusters: [], hosts: [1]
2014-09-15 15:21:05,449 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) DeploymentPlanner allocation
algorithm: com.cloud.deploy.UserConcentratedPodPlanner@5bc1d7c6
2014-09-15 15:21:05,450 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to allocate a host and
storage pools from dc:1, pod:1,cluster:1, requested cpu: 2000, requested
ram: 2147483648
2014-09-15 15:21:05,450 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Is ROOT volume READY (pool
already allocated)?: Yes
2014-09-15 15:21:05,450 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) DeploymentPlan has host_id
specified, choosing this host and making no checks on this host: 1
2014-09-15 15:21:05,457 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) The specified host is in avoid
set
2014-09-15 15:21:05,457 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Cannnot deploy to specified
host, returning.
2014-09-15 15:21:05,507 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM state transitted from
:Starting to Stopped with event: OperationFailedvm's original host id: 1
new host id: null host id before state transition: 1
2014-09-15 15:21:05,539 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Hosts's actual total CPU: 160000
and CPU after applying overprovisioning: 160000
2014-09-15 15:21:05,540 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Hosts's actual total RAM:
536778789120 and RAM after applying overprovisioning: 536778801152
2014-09-15 15:21:05,541 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) release cpu from host: 1, old
used: 5500,reserved: 0, actual total: 160000, total with overprovisioning:
160000; new used: 3500,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2014-09-15 15:21:05,542 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) release mem from host: 1, old
used: 6039797760,reserved: 0, total: 536778801152; new used:
3892314112,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-09-15 15:21:05,626 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM state transitted from
:Stopped to Starting with event: StartRequestedvm's original host id: 1 new
host id: null host id before state transition: null
2014-09-15 15:21:05,627 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Successfully transitioned to
start state for VM[User|devlab1] reservation id =
7c14fd00-c5f3-41ec-b1e9-d657d3575be9
2014-09-15 15:21:05,637 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to deploy VM, vm has
dcId: 1 and podId: 1
2014-09-15 15:21:05,637 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deploy avoids pods: [],
clusters: [], hosts: [1]
2014-09-15 15:21:05,654 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Root volume is ready, need to
place VM in volume's cluster
2014-09-15 15:21:05,655 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Vol[98|vm=60|ROOT] is READY,
changing deployment plan to use this pool's dcId: 1 , podId: 1 , and
clusterId: 1
2014-09-15 15:21:05,693 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deploy avoids pods: [],
clusters: [], hosts: [1]
2014-09-15 15:21:05,694 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) DeploymentPlanner allocation
algorithm: com.cloud.deploy.UserConcentratedPodPlanner@5bc1d7c6
2014-09-15 15:21:05,695 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to allocate a host and
storage pools from dc:1, pod:1,cluster:1, requested cpu: 2000, requested
ram: 2147483648
2014-09-15 15:21:05,695 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Is ROOT volume READY (pool
already allocated)?: Yes
2014-09-15 15:21:05,696 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) This VM has last host_id
specified, trying to choose the same host: 1
2014-09-15 15:21:05,703 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) The last host of this VM is in
avoid set
2014-09-15 15:21:05,703 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Cannot choose the last host to
deploy this VM
2014-09-15 15:21:05,704 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Searching resources only under
specified Cluster: 1
2014-09-15 15:21:05,730 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking resources in Cluster: 1
under Pod: 1
2014-09-15 15:21:05,731 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Looking
for hosts in dc: 1 pod:1 cluster:1
2014-09-15 15:21:05,755 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator)
FirstFitAllocator has 2 hosts to check for allocation: [Host[-7-Routing],
Host[-1-Routing]]
2014-09-15 15:21:05,771 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Found 2
hosts for allocation after prioritization: [Host[-7-Routing],
Host[-1-Routing]]
2014-09-15 15:21:05,771 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Looking
for speed=2000Mhz, Ram=2048
2014-09-15 15:21:05,797 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host: 7
has cpu capability (cpu:64, speed:2500) to support requested CPU: 2 and
requested speed: 1000
2014-09-15 15:21:05,798 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator)
Checking if host: 7 has enough capacity for requested CPU: 2000 and
requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2014-09-15 15:21:05,809 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Hosts's
actual total CPU: 160000 and CPU after applying overprovisioning: 160000
2014-09-15 15:21:05,810 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Free
CPU: 160000 , Requested CPU: 2000
2014-09-15 15:21:05,810 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Free
RAM: 536778801152 , Requested RAM: 2147483648
2014-09-15 15:21:05,811 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host
has enough CPU and RAM available
2014-09-15 15:21:05,811 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) STATS:
Can alloc CPU from host: 7, used: 0, reserved: 0, actual total: 160000,
total with overprovisioning: 160000; requested
cpu:2000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-09-15 15:21:05,812 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) STATS:
Can alloc MEM from host: 7, used: 0, reserved: 0, total: 536778801152;
requested mem: 2147483648,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-09-15 15:21:05,812 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Found a
suitable host, adding to list: 7
2014-09-15 15:21:05,813 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host
name: cloudsrv2.afdb.local, hostId: 1 is in avoid set, skipping this and
trying other available hosts
2014-09-15 15:21:05,814 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050 FirstFitRoutingAllocator) Host
Allocator returning 1 suitable hosts
2014-09-15 15:21:05,821 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking suitable pools for
volume (Id, Type): (98,ROOT)
2014-09-15 15:21:05,822 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Volume has pool already
allocated, checking if pool can be reused, poolId: 1
2014-09-15 15:21:05,828 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Planner need not allocate a pool
for this volume since its READY
2014-09-15 15:21:05,828 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Trying to find a potenial host
and associated storage pools from the suitable host/pool lists for this VM
2014-09-15 15:21:05,829 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking if host: 7 can access
any suitable storage pool for volume: ROOT
2014-09-15 15:21:05,835 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Host: 7 can access pool: 1
2014-09-15 15:21:05,872 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Found a potential host id: 7
name: cloudsrv1.afdb.org and associated storage pools for this VM
2014-09-15 15:21:05,879 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Returning Deployment
Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2014-09-15 15:21:05,879 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Deployment found -
P0=VM[User|devlab1],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2014-09-15 15:21:05,921 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM state transitted from
:Starting to Starting with event: OperationRetryvm's original host id: 1
new host id: 7 host id before state transition: null
2014-09-15 15:21:05,953 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Hosts's actual total CPU: 160000
and CPU after applying overprovisioning: 160000
2014-09-15 15:21:05,953 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) We are allocating VM, increasing
the used capacity of this host:7
2014-09-15 15:21:05,954 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Current Used CPU: 0 , Free
CPU:160000 ,Requested CPU: 2000
2014-09-15 15:21:05,954 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Current Used RAM: 0 , Free
RAM:536778801152 ,Requested RAM: 2147483648
2014-09-15 15:21:05,955 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) CPU STATS after allocation: for
host: 7, old used: 0, old reserved: 0, actual total: 160000, total with
overprovisioning: 160000; new used:2000, reserved:0; requested
cpu:2000,alloc_from_last:false
2014-09-15 15:21:05,956 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) RAM STATS after allocation: for
host: 7, old used: 0, old reserved: 0, total: 536778801152; new used:
2147483648, reserved: 0; requested mem: 2147483648,alloc_from_last:false
2014-09-15 15:21:05,971 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) VM is being created in podId: 1
2014-09-15 15:21:06,013 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Network id=204 is already
implemented
2014-09-15 15:21:06,100 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Changing active number of nics
for network id=204 on 1
2014-09-15 15:21:06,139 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Asking SecurityGroupProvider to
prepare for Nic[65-60-7c14fd00-c5f3-41ec-b1e9-d657d3575be9-192.168.40.182]
2014-09-15 15:21:06,168 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Asking VirtualRouter to prepare
for Nic[65-60-7c14fd00-c5f3-41ec-b1e9-d657d3575be9-192.168.40.182]
2014-09-15 15:21:06,212 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Lock is acquired for network id
204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2014-09-15 15:21:06,225 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Lock is released for network id
204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2014-09-15 15:21:06,343 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Applying dhcp entry in network
Ntwk[204|Guest|6]
2014-09-15 15:21:06,423 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159509: Sending { Cmd
, MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:2b:a4:00:00:0b","vmIpAddress":"192.168.40.182","vmName":"devlab1","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:2b:a4:00:00:0b","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
router.name":"r-4-VM","router.ip":"169.254.1.13"},"wait":0}}] }
2014-09-15 15:21:06,426 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159509: Executing: {
Cmd , MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:2b:a4:00:00:0b","vmIpAddress":"192.168.40.182","vmName":"devlab1","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:2b:a4:00:00:0b","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
router.name":"r-4-VM","router.ip":"169.254.1.13"},"wait":0}}] }
2014-09-15 15:21:06,427 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-51:ctx-f2c4311d) Seq 1-292159509: Executing request
2014-09-15 15:21:06,505 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-13:null) SeqA 2-48780: Processing Seq 2-48780: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-09-15 15:21:06,524 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-13:null) SeqA 2-48780: Sending Seq 2-48780: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-09-15 15:21:06,547 DEBUG [c.c.a.ApiServlet]
(catalina-exec-14:ctx-dd6ef353) ===START=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=84f6776a-d442-42c0-a04d-c1399af70dae&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787254081
2014-09-15 15:21:06,633 DEBUG [c.c.a.ApiServlet]
(catalina-exec-14:ctx-dd6ef353 ctx-d191f2fb) ===END=== 10.29.128.147 --
GET
command=queryAsyncJobResult&jobId=84f6776a-d442-42c0-a04d-c1399af70dae&response=json&sessionkey=texMswEZiU%2Bv9b9YBnPDe9ZAqh4%3D&_=1410787254081
2014-09-15 15:21:07,103 DEBUG [c.c.s.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-04f391e9) Zone 1 is ready to launch secondary storage VM
2014-09-15 15:21:07,256 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-51:ctx-f2c4311d) Seq 1-292159509: Response Received:
2014-09-15 15:21:07,258 DEBUG [c.c.a.t.Request]
(DirectAgent-51:ctx-f2c4311d) Seq 1-292159509: Processing: { Ans: ,
MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-09-15 15:21:07,259 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159509: Received: {
Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { Answer } }
2014-09-15 15:21:07,314 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Applying userdata and password
entry in network Ntwk[204|Guest|6]
2014-09-15 15:21:07,404 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159510: Sending { Cmd
, MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name
":"r-4-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name":"r-4-VM"},"wait":0}}] }
2014-09-15 15:21:07,408 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159510: Executing: {
Cmd , MgmtId: 7063056740127, via: 1(cloudsrv2.afdb.local), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name
":"r-4-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.182","vmName":"devlab1","executeInSequence":false,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.1.13","
router.name":"r-4-VM"},"wait":0}}] }
2014-09-15 15:21:07,410 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-1:ctx-74c53eb8) Seq 1-292159510: Executing request
2014-09-15 15:21:07,749 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-8f69e9aa) Zone 1 is ready to launch console proxy
2014-09-15 15:21:07,922 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-18:ctx-6672887f) Ping from 1(cloudsrv2.afdb.local)
2014-09-15 15:21:08,263 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-40:ctx-7fa683c5) Ping from 7(cloudsrv1.afdb.org)
2014-09-15 15:21:08,895 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-1:ctx-74c53eb8) Seq 1-292159510: Response Received:
2014-09-15 15:21:08,898 DEBUG [c.c.a.t.Request]
(DirectAgent-1:ctx-74c53eb8) Seq 1-292159510: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}]
}
2014-09-15 15:21:08,898 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 1-292159510: Received: {
Ans: , MgmtId: 7063056740127, via: 1, Ver: v1, Flags: 10, { Answer, Answer
} }
2014-09-15 15:21:08,922 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Checking if we need to prepare 1
volumes for VM[User|devlab1]
2014-09-15 15:21:08,928 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) No need to recreate the volume:
Vol[98|vm=60|ROOT], since it already has a pool assigned: 1, adding disk to
VM
2014-09-15 15:21:09,151 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 7-570687506: Sending { Cmd
, MgmtId: 7063056740127, via: 7(cloudsrv1.afdb.org), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":60,"name":"i-28-60-VM","bootloader":"PyGrub","type":"User","cpus":2,"minSpeed":1000,"maxSpeed":1000,"minRam":2147483648,"maxRam":2147483648,"arch":"x86_64","os":"Windows
Server 2012 R2
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":true,"vncPassword":"ab2708f053e60810","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:7025","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"fbd594ef-9195-4671-817c-3c48caaaf683","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a1cab116-ff8c-4221-8e31-51b6a76b3b1d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":1,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049,"url":"NetworkFilesystem://
192.168.40.71//fs_nfs1/?ROLE=Primary&STOREUUID=ba737116-8aa6-3644-a595-383d4dc39ed3"}},"name":"ROOT-60","size":64424509440,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","volumeId":98,"vmName":"i-28-60-VM","accountId":28,"format":"VHD","id":98,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"192.168.40.71","volumeSize":"64424509440"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"f66d33a2-b466-4990-9ebf-cd2074c8edf6","ip":"192.168.40.182","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:2b:a4:00:00:0b","dns1":"196.25.1.9","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true}],"vcpuMaxLimit":16},"hostIp":"192.168.40.245","executeInSequence":false,"wait":0}}]
}
2014-09-15 15:21:09,159 DEBUG [c.c.a.t.Request]
(Job-Executor-1:ctx-3df833af ctx-e92b9050) Seq 7-570687506: Executing: {
Cmd , MgmtId: 7063056740127, via: 7(cloudsrv1.afdb.org), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":60,"name":"i-28-60-VM","bootloader":"PyGrub","type":"User","cpus":2,"minSpeed":1000,"maxSpeed":1000,"minRam":2147483648,"maxRam":2147483648,"arch":"x86_64","os":"Windows
Server 2012 R2
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":true,"vncPassword":"ab2708f053e60810","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:7025","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"fbd594ef-9195-4671-817c-3c48caaaf683","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a1cab116-ff8c-4221-8e31-51b6a76b3b1d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":1,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049,"url":"NetworkFilesystem://
192.168.40.71//fs_nfs1/?ROLE=Primary&STOREUUID=ba737116-8aa6-3644-a595-383d4dc39ed3"}},"name":"ROOT-60","size":64424509440,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","volumeId":98,"vmName":"i-28-60-VM","accountId":28,"format":"VHD","id":98,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"cf1835ad-2693-40cc-b046-36bace82e54c","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"192.168.40.71","volumeSize":"64424509440"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"f66d33a2-b466-4990-9ebf-cd2074c8edf6","ip":"192.168.40.182","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:2b:a4:00:00:0b","dns1":"196.25.1.9","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true}],"vcpuMaxLimit":16},"hostIp":"192.168.40.245","executeInSequence":false,"wait":0}}]
}
2014-09-15 15:21:09,160 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-53:ctx-77f683e9) Seq 7-570687506: Executing request
2014-09-15 15:21:09,350 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-53:ctx-77f683e9) 1. The VM i-28-60-VM is in Starting state.
2014-09-15 15:21:09,355 DEBUG [c.c.h.x.r.CitrixHelper]
(DirectAgent-53:ctx-77f683e9) Can't find the guest os: Windows Server 2012
R2 (64-bit) mapping into XenServer 6.2.0 guestOS type, start it as HVM guest
2014-09-15 15:21:09,379 WARN [c.c.h.x.r.XenServer620Resource]
(DirectAgent-53:ctx-77f683e9) No recommended value found for dynamic min
2014-09-15 15:21:09,381 WARN [c.c.h.x.r.XenServer620Resource]
(DirectAgent-53:ctx-77f683e9) No recommended value found for dynamic max,
setting static max and dynamic max equal
2014-09-15 15:21:09,412 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-53:ctx-77f683e9) Created VM
dd22eb41-dd25-3ecb-1519-ee12fb6eb452 for i-28-60-VM
2014-09-15 15:21:09,432 WARN [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-53:ctx-77f683e9) Catch Exception: class
com.xensource.xenapi.Types$UuidInvalid due to The uuid you supplied was
invalid.
The uuid you supplied was invalid.
at com.xensource.xenapi.Types.checkResponse(Types.java:927)
at com.xensource.xenapi.Connection.dispatch(Connection.java:368)
at
com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909)
at com.xensource.xenapi.VDI.getByUuid(VDI.java:326)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.mount(CitrixResourceBase.java:1196)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.createVbd(CitrixResourceBase.java:1204)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:1710)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:545)
at
com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
at
com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
at
com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2014-09-15 15:21:09,437 WARN [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-53:ctx-77f683e9) Unable to start i-28-60-VM due to
The uuid you supplied was invalid.
at com.xensource.xenapi.Types.checkResponse(Types.java:927)
at com.xensource.xenapi.Connection.dispatch(Connection.java:368)
at
com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909)
at com.xensource.xenapi.VDI.getByUuid(VDI.java:326)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.mount(CitrixResourceBase.java:1196)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.createVbd(CitrixResourceBase.java:1204)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:1710)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:545)
at
com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
at
com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
at
com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
