I am using CS v-4.3.0 with KVM.
You can see the logs below. There is Exception that the storage pool is
unreachable.
2015-07-30 12:01:43,472 DEBUG [c.c.a.ApiServlet]
(catalina-exec-1:ctx-d97b1e9d) ===START=== 10.129.28.236 -- GET
command=deployVirtualMachine&response=json&sessionkey=e8WA8mYwZyXdjzfH6dwAw9JXmOU%3D&zoneid=f64b5a68-2c69-4034-b025-ce702d171b0c&templateid=6001f2ac-0ea9-43ae-b097-3ac2738eb5f2&hypervisor=KVM&serviceofferingid=744ab882-9ae0-4e29-9c40-816f2957ccf3&securitygroupids=3dbdbff7-8f0c-11e3-af72-00151710ce88&displayname=communitytest&name=communitytest&_=1438237736024
2015-07-30 12:01:43,479 DEBUG [c.c.a.ApiDispatcher]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2015-07-30 12:01:43,482 DEBUG [c.c.a.ApiDispatcher]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2015-07-30 12:01:43,484 DEBUG [c.c.a.ApiDispatcher]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) ControlledEntity name
is:com.cloud.network.security.SecurityGroup
2015-07-30 12:01:43,631 DEBUG [c.c.v.UserVmManagerImpl]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) Allocating in the DB for vm
2015-07-30 12:01:43,642 DEBUG [c.c.v.VirtualMachineManagerImpl]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) Allocating entries for VM:
VM[User|communitytest]
2015-07-30 12:01:43,642 DEBUG [c.c.v.VirtualMachineManagerImpl]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) Allocating nics for
VM[User|communitytest]
2015-07-30 12:01:43,643 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) Allocating nic for vm
VM[User|communitytest] in network Ntwk[204|Guest|6] with requested profile
NicProfile[0-0-null-null-null
2015-07-30 12:01:43,650 DEBUG [c.c.v.VirtualMachineManagerImpl]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) Allocating disks for
VM[User|communitytest]
2015-07-30 12:01:43,659 DEBUG [c.c.v.VirtualMachineManagerImpl]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) Allocation completed for VM:
VM[User|communitytest]
2015-07-30 12:01:43,659 DEBUG [c.c.v.UserVmManagerImpl]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) Successfully allocated DB entry
for VM[User|communitytest]
2015-07-30 12:01:44,642 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) submit async job-13662,
details: AsyncJobVO {id:13662, userId: 2, accountId: 2, instanceType:
VirtualMachine, instanceId: 677, cmd:
org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdInfo:
{"serviceofferingid":"744ab882-9ae0-4e29-9c40-816f2957ccf3","sessionkey":"e8WA8mYwZyXdjzfH6dwAw9JXmOU\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"f64b5a68-2c69-4034-b025-ce702d171b0c","httpmethod":"GET","templateid":"6001f2ac-0ea9-43ae-b097-3ac2738eb5f2","securitygroupids":"3dbdbff7-8f0c-11e3-af72-00151710ce88","response":"json","id":"677","hypervisor":"KVM","name":"communitytest","_":"1438237736024","ctxAccountId":"2","ctxStartEventId":"14447","displayname":"communitytest"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 90581290632, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2015-07-30 12:01:44,643 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-25:ctx-5591097d) Add job-13662 into job monitoring
2015-07-30 12:01:44,643 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-25:ctx-5591097d) Executing AsyncJobVO {id:13662, userId: 2,
accountId: 2, instanceType: VirtualMachine, instanceId: 677, cmd:
org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdInfo:
{"serviceofferingid":"744ab882-9ae0-4e29-9c40-816f2957ccf3","sessionkey":"e8WA8mYwZyXdjzfH6dwAw9JXmOU\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"f64b5a68-2c69-4034-b025-ce702d171b0c","httpmethod":"GET","templateid":"6001f2ac-0ea9-43ae-b097-3ac2738eb5f2","securitygroupids":"3dbdbff7-8f0c-11e3-af72-00151710ce88","response":"json","id":"677","hypervisor":"KVM","name":"communitytest","_":"1438237736024","ctxAccountId":"2","ctxStartEventId":"14447","displayname":"communitytest"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 90581290632, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2015-07-30 12:01:44,644 DEBUG [c.c.a.ApiServlet]
(catalina-exec-1:ctx-d97b1e9d ctx-fefabef3) ===END=== 10.129.28.236 --
GET
command=deployVirtualMachine&response=json&sessionkey=e8WA8mYwZyXdjzfH6dwAw9JXmOU%3D&zoneid=f64b5a68-2c69-4034-b025-ce702d171b0c&templateid=6001f2ac-0ea9-43ae-b097-3ac2738eb5f2&hypervisor=KVM&serviceofferingid=744ab882-9ae0-4e29-9c40-816f2957ccf3&securitygroupids=3dbdbff7-8f0c-11e3-af72-00151710ce88&displayname=communitytest&name=communitytest&_=1438237736024
2015-07-30 12:01:44,649 DEBUG [c.c.a.ApiDispatcher]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2015-07-30 12:01:44,650 DEBUG [c.c.a.ApiDispatcher]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2015-07-30 12:01:44,653 DEBUG [c.c.a.ApiDispatcher]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) ControlledEntity name
is:com.cloud.network.security.SecurityGroup
2015-07-30 12:01:44,868 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Deploy avoids pods: [],
clusters: [], hosts: []
2015-07-30 12:01:44,869 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) DeploymentPlanner allocation
algorithm: com.cloud.deploy.FirstFitPlanner@2db45934
2015-07-30 12:01:44,869 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Trying to allocate a host and
storage pools from dc:1, pod:null,cluster:null, requested cpu: 500,
requested ram: 536870912
2015-07-30 12:01:44,870 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Is ROOT volume READY (pool
already allocated)?: No
2015-07-30 12:01:44,870 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Searching all possible
resources under this Zone: 1
2015-07-30 12:01:44,870 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Listing clusters in order of
aggregate capacity, that have (atleast one host with) enough CPU and RAM
capacity under this Zone: 1
2015-07-30 12:01:44,874 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Removing from the clusterId
list these clusters from avoid set: []
2015-07-30 12:01:44,881 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking resources in Cluster:
2 under Pod: 1
2015-07-30 12:01:44,882 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Looking for hosts in dc: 1 pod:1 cluster:2
2015-07-30 12:01:44,884 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
FirstFitAllocator has 3 hosts to check for allocation: [Host[-33-Routing],
Host[-35-Routing], Host[-43-Routing]]
2015-07-30 12:01:44,887 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Found
3 hosts for allocation after prioritization: [Host[-33-Routing],
Host[-35-Routing], Host[-43-Routing]]
2015-07-30 12:01:44,887 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Looking for speed=500Mhz, Ram=512
2015-07-30 12:01:44,892 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Host:
33 has cpu capability (cpu:8, speed:2261) to support requested CPU: 1 and
requested speed: 500
2015-07-30 12:01:44,892 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Checking if host: 33 has enough capacity for requested CPU: 500 and
requested RAM: 536870912 , cpuOverprovisioningFactor: 4.0
2015-07-30 12:01:44,894 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Hosts's actual total CPU: 18088 and CPU after applying overprovisioning:
72352
2015-07-30 12:01:44,894 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Free
CPU: 70352 , Requested CPU: 500
2015-07-30 12:01:44,894 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Free
RAM: 97864122368 , Requested RAM: 536870912
2015-07-30 12:01:44,894 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Host
has enough CPU and RAM available
2015-07-30 12:01:44,894 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) STATS:
Can alloc CPU from host: 33, used: 1000, reserved: 1000, actual total:
18088, total with overprovisioning: 72352; requested
cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-07-30 12:01:44,894 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) STATS:
Can alloc MEM from host: 33, used: 2147483648, reserved: 1073741824, total:
101085347840; requested mem: 536870912,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-07-30 12:01:44,894 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Found
a suitable host, adding to list: 33
2015-07-30 12:01:44,899 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Host:
35 has cpu capability (cpu:8, speed:2261) to support requested CPU: 1 and
requested speed: 500
2015-07-30 12:01:44,899 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Checking if host: 35 has enough capacity for requested CPU: 500 and
requested RAM: 536870912 , cpuOverprovisioningFactor: 4.0
2015-07-30 12:01:44,901 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Hosts's actual total CPU: 18088 and CPU after applying overprovisioning:
72352
2015-07-30 12:01:44,901 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Free
CPU: 72352 , Requested CPU: 500
2015-07-30 12:01:44,901 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Free
RAM: 101086199808 , Requested RAM: 536870912
2015-07-30 12:01:44,901 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Host
has enough CPU and RAM available
2015-07-30 12:01:44,901 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) STATS:
Can alloc CPU from host: 35, used: 0, reserved: 0, actual total: 18088,
total with overprovisioning: 72352; requested
cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-07-30 12:01:44,901 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) STATS:
Can alloc MEM from host: 35, used: 0, reserved: 0, total: 101086199808;
requested mem: 536870912,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-07-30 12:01:44,901 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Found
a suitable host, adding to list: 35
2015-07-30 12:01:44,906 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Host:
43 has cpu capability (cpu:8, speed:2261) to support requested CPU: 1 and
requested speed: 500
2015-07-30 12:01:44,906 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Checking if host: 43 has enough capacity for requested CPU: 500 and
requested RAM: 536870912 , cpuOverprovisioningFactor: 4.0
2015-07-30 12:01:44,908 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator)
Hosts's actual total CPU: 18088 and CPU after applying overprovisioning:
72352
2015-07-30 12:01:44,908 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Free
CPU: 72352 , Requested CPU: 500
2015-07-30 12:01:44,908 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Free
RAM: 101092589568 , Requested RAM: 536870912
2015-07-30 12:01:44,908 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Host
has enough CPU and RAM available
2015-07-30 12:01:44,908 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) STATS:
Can alloc CPU from host: 43, used: 0, reserved: 0, actual total: 18088,
total with overprovisioning: 72352; requested
cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-07-30 12:01:44,908 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) STATS:
Can alloc MEM from host: 43, used: 0, reserved: 0, total: 101092589568;
requested mem: 536870912,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-07-30 12:01:44,908 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Found
a suitable host, adding to list: 43
2015-07-30 12:01:44,908 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3 FirstFitRoutingAllocator) Host
Allocator returning 3 suitable hosts
2015-07-30 12:01:44,909 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking suitable pools for
volume (Id, Type): (874,ROOT)
2015-07-30 12:01:44,909 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) We need to allocate new
storagepool for this volume
2015-07-30 12:01:44,910 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Calling StoragePoolAllocators
to find suitable pools
2015-07-30 12:01:44,911 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) LocalStoragePoolAllocator
trying to find storage pool to fit the vm
2015-07-30 12:01:44,911 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3)
ClusterScopeStoragePoolAllocator looking for storage pool
2015-07-30 12:01:44,911 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Looking for pools in dc: 1
pod:1 cluster:2
2015-07-30 12:01:44,912 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Found pools matching tags:
[Pool[11|NetworkFilesystem]]
2015-07-30 12:01:44,913 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Removing pool
Pool[11|NetworkFilesystem] from avoid set, must have been inserted when
searching for another disk's tag
2015-07-30 12:01:44,914 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking if storage pool is
suitable, name: null ,poolId: 11
2015-07-30 12:01:44,917 DEBUG [c.c.s.StorageManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking pool 11 for storage,
totalSize: 7034645184512, usedBytes: 34200616960, usedPct:
0.004861740153618356, disable threshold: 0.85
2015-07-30 12:01:44,922 DEBUG [c.c.s.StorageManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking pool: 11 for volume
allocation [Vol[874|vm=677|ROOT]], maxSize : 7034645184512,
totalAllocatedSize : 276899561472, askingSize : 21474836480, allocated
disable threshold: 0.85
2015-07-30 12:01:44,922 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3)
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2015-07-30 12:01:44,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Trying to find a potenial host
and associated storage pools from the suitable host/pool lists for this VM
2015-07-30 12:01:44,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking if host: 33 can access
any suitable storage pool for volume: ROOT
2015-07-30 12:01:44,923 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Host: 33 can access pool: 11
2015-07-30 12:01:44,923 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Found a potential host id: 33
name: host7 and associated storage pools for this VM
2015-07-30 12:01:44,924 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Returning Deployment
Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(1)-Pod(1)-Cluster(2)-Host(33)-Storage(Volume(874|ROOT-->Pool(11))]
2015-07-30 12:01:45,117 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) SeqA 38-124648: Processing Seq 38-124648: {
Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2015-07-30 12:01:45,182 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) VM state transitted from
:Stopped to Starting with event: StartRequestedvm's original host id: null
new host id: null host id before state transition: null
2015-07-30 12:01:45,182 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Successfully transitioned to
start state for VM[User|communitytest] reservation id =
98cd02e2-659a-434c-83a1-72318f96a5a4
2015-07-30 12:01:45,284 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) SeqA 38-124648: Sending Seq 38-124648: {
Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-07-30 12:01:45,317 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Trying to deploy VM, vm has
dcId: 1 and podId: null
2015-07-30 12:01:45,317 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) advanceStart: DeploymentPlan is
provided, using dcId:1, podId: 1, clusterId: 2, hostId: 33, poolId: null
2015-07-30 12:01:45,317 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Deploy avoids pods: null,
clusters: null, hosts: null
2015-07-30 12:01:45,324 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Deploy avoids pods: [],
clusters: [], hosts: []
2015-07-30 12:01:45,325 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) DeploymentPlanner allocation
algorithm: com.cloud.deploy.FirstFitPlanner@2db45934
2015-07-30 12:01:45,325 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Trying to allocate a host and
storage pools from dc:1, pod:1,cluster:2, requested cpu: 500, requested
ram: 536870912
2015-07-30 12:01:45,325 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Is ROOT volume READY (pool
already allocated)?: No
2015-07-30 12:01:45,325 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) DeploymentPlan has host_id
specified, choosing this host and making no checks on this host: 33
2015-07-30 12:01:45,326 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Looking for suitable pools for
this host under zone: 1, pod: 1, cluster: 2
2015-07-30 12:01:45,328 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking suitable pools for
volume (Id, Type): (874,ROOT)
2015-07-30 12:01:45,328 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) We need to allocate new
storagepool for this volume
2015-07-30 12:01:45,328 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Calling StoragePoolAllocators
to find suitable pools
2015-07-30 12:01:45,328 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) LocalStoragePoolAllocator
trying to find storage pool to fit the vm
2015-07-30 12:01:45,328 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3)
ClusterScopeStoragePoolAllocator looking for storage pool
2015-07-30 12:01:45,328 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Looking for pools in dc: 1
pod:1 cluster:2
2015-07-30 12:01:45,329 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Found pools matching tags:
[Pool[11|NetworkFilesystem]]
2015-07-30 12:01:45,329 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Removing pool
Pool[11|NetworkFilesystem] from avoid set, must have been inserted when
searching for another disk's tag
2015-07-30 12:01:45,330 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking if storage pool is
suitable, name: null ,poolId: 11
2015-07-30 12:01:45,333 DEBUG [c.c.s.StorageManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking pool 11 for storage,
totalSize: 7034645184512, usedBytes: 34200616960, usedPct:
0.004861740153618356, disable threshold: 0.85
2015-07-30 12:01:45,336 DEBUG [c.c.s.StorageManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking pool: 11 for volume
allocation [Vol[874|vm=677|ROOT]], maxSize : 7034645184512,
totalAllocatedSize : 276899561472, askingSize : 21474836480, allocated
disable threshold: 0.85
2015-07-30 12:01:45,336 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3)
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2015-07-30 12:01:45,337 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Trying to find a potenial host
and associated storage pools from the suitable host/pool lists for this VM
2015-07-30 12:01:45,337 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking if host: 33 can access
any suitable storage pool for volume: ROOT
2015-07-30 12:01:45,337 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Host: 33 can access pool: 11
2015-07-30 12:01:45,338 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Found a potential host id: 33
name: host7 and associated storage pools for this VM
2015-07-30 12:01:45,338 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Returning Deployment
Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(1)-Pod(1)-Cluster(2)-Host(33)-Storage(Volume(874|ROOT-->Pool(11))]
2015-07-30 12:01:45,338 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Deployment found -
P0=VM[User|communitytest],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(1)-Pod(1)-Cluster(2)-Host(33)-Storage(Volume(874|ROOT-->Pool(11))]
2015-07-30 12:01:45,810 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) VM state transitted from
:Starting to Starting with event: OperationRetryvm's original host id: null
new host id: 33 host id before state transition: null
2015-07-30 12:01:45,815 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Hosts's actual total CPU: 18088
and CPU after applying overprovisioning: 72352
2015-07-30 12:01:45,815 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) We are allocating VM,
increasing the used capacity of this host:33
2015-07-30 12:01:45,815 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Current Used CPU: 1000 , Free
CPU:70352 ,Requested CPU: 500
2015-07-30 12:01:45,815 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Current Used RAM: 2147483648 ,
Free RAM:97864122368 ,Requested RAM: 536870912
2015-07-30 12:01:45,816 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) CPU STATS after allocation: for
host: 33, old used: 1000, old reserved: 1000, actual total: 18088, total
with overprovisioning: 72352; new used:1500, reserved:1000; requested
cpu:500,alloc_from_last:false
2015-07-30 12:01:45,816 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) RAM STATS after allocation: for
host: 33, old used: 2147483648, old reserved: 1073741824, total:
101085347840; new used: 2684354560, reserved: 1073741824; requested mem:
536870912,alloc_from_last:false
2015-07-30 12:01:45,885 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) VM is being created in podId: 1
2015-07-30 12:01:45,890 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Network id=204 is already
implemented
2015-07-30 12:01:46,061 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Changing active number of nics
for network id=204 on 1
2015-07-30 12:01:46,146 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Asking VirtualRouter to prepare
for Nic[712-677-98cd02e2-659a-434c-83a1-72318f96a5a4-10.129.34.66]
2015-07-30 12:01:46,154 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) 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(2)-Host(33)-Storage(Volume(874|ROOT-->Pool(11))]
2015-07-30 12:01:46,171 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) 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(2)-Host(33)-Storage(Volume(874|ROOT-->Pool(11))]
2015-07-30 12:01:46,190 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Applying dhcp entry in network
Ntwk[204|Guest|6]
2015-07-30 12:01:46,204 DEBUG [c.c.a.t.Request]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Seq 33-1972700916: Sending {
Cmd , MgmtId: 90581290632, via: 33(host7), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:7f:c2:00:00:2f","vmIpAddress":"10.129.34.66","vmName":"communitytest","defaultRouter":"10.129.250.1","defaultDns":"10.129.34.34","duid":"00:03:00:01:06:7f:c2:00:00:2f","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"10.129.34.34","zone.network.type":"Basic","
router.name":"r-670-VM","router.ip":"169.254.2.95"},"wait":0}}] }
2015-07-30 12:01:46,534 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-11:null) Seq 33-1972700916: Processing: { Ans: ,
MgmtId: 90581290632, via: 33, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2015-07-30 12:01:46,534 DEBUG [c.c.a.m.AgentAttache]
(AgentManager-Handler-11:null) Seq 33-1972700916: No more commands found
2015-07-30 12:01:46,534 DEBUG [c.c.a.t.Request]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Seq 33-1972700916: Received: {
Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 110, { Answer } }
2015-07-30 12:01:46,542 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Applying userdata and password
entry in network Ntwk[204|Guest|6]
2015-07-30 12:01:46,555 DEBUG [c.c.a.t.Request]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Seq 33-1972700917: Sending {
Cmd , MgmtId: 90581290632, via: 33(host7), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.129.34.66","vmName":"communitytest","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.129.34.34","zone.network.type":"Basic","router.ip":"169.254.2.95","
router.name
":"r-670-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.129.34.66","vmName":"communitytest","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.129.34.34","zone.network.type":"Basic","router.ip":"169.254.2.95","
router.name":"r-670-VM"},"wait":0}}] }
2015-07-30 12:01:46,886 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-8:null) Seq 33-1972700917: Processing: { Ans: ,
MgmtId: 90581290632, via: 33, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}]
}
2015-07-30 12:01:46,886 DEBUG [c.c.a.m.AgentAttache]
(AgentManager-Handler-8:null) Seq 33-1972700917: No more commands found
2015-07-30 12:01:46,886 DEBUG [c.c.a.t.Request]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Seq 33-1972700917: Received: {
Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 110, { Answer, Answer
} }
2015-07-30 12:01:46,888 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Asking SecurityGroupProvider to
prepare for Nic[712-677-98cd02e2-659a-434c-83a1-72318f96a5a4-10.129.34.66]
2015-07-30 12:01:46,893 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Checking if we need to prepare
1 volumes for VM[User|communitytest]
2015-07-30 12:01:46,901 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) template 291 is already in
store:1, type:Image
2015-07-30 12:01:46,905 DEBUG [o.a.c.s.d.PrimaryDataStoreImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Not found
(templateId:291poolId:11) in template_spool_ref, persisting it
2015-07-30 12:01:46,996 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) template 291 is already in
store:11, type:Primary
2015-07-30 12:01:46,997 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Found template
e3d670a2-e2a3-48f6-b6d0-7a48767e6a68 in storage pool 11 with
VMTemplateStoragePool id: 190
2015-07-30 12:01:47,007 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Acquire lock on
VMTemplateStoragePool 190 with timeout 3600 seconds
2015-07-30 12:01:47,008 INFO [o.a.c.s.v.VolumeServiceImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) lock is acquired for
VMTemplateStoragePool 190
2015-07-30 12:01:47,153 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) copyAsync inspecting src type
TEMPLATE copyAsync inspecting dest type TEMPLATE
2015-07-30 12:01:47,161 DEBUG [c.c.a.t.Request]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Seq 33-1972700918: Sending {
Cmd , MgmtId: 90581290632, via: 33(host7), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/291/e3d670a2-e2a3-48f6-b6d0-7a48767e6a68.qcow2","uuid":"6001f2ac-0ea9-43ae-b097-3ac2738eb5f2","id":291,"format":"QCOW2","accountId":2,"hvm":true,"displayText":"Ubuntu
Server ","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
10.129.34.15/export/secondary","_role":"Image"}},"name":"e3d670a2-e2a3-48f6-b6d0-7a48767e6a68","hypervisorType":"KVM"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"uuid":"6001f2ac-0ea9-43ae-b097-3ac2738eb5f2","id":291,"format":"QCOW2","accountId":2,"hvm":true,"displayText":"Ubuntu
Server
","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c2bb5697-d753-3a55-9bfb-83aca5d2cdc1","id":11,"poolType":"NetworkFilesystem","host":"10.129.34.13","path":"/share/CACHEDEV2_DATA/NFSShare2","port":2049,"url":"NetworkFilesystem://
10.129.34.13//share/CACHEDEV2_DATA/NFSShare2/?ROLE=Primary&STOREUUID=c2bb5697-d753-3a55-9bfb-83aca5d2cdc1"}},"name":"e3d670a2-e2a3-48f6-b6d0-7a48767e6a68","hypervisorType":"KVM"}},"executeInSequence":false,"options":{},"wait":10800}}]
}
2015-07-30 12:01:47,392 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-14:null) Seq 33-1972700918: Processing: { Ans: ,
MgmtId: 90581290632, via: 33, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: storage volume
'6001f2ac-0ea9-43ae-b097-3ac2738eb5f2' exists already","wait":0}}] }
2015-07-30 12:01:47,392 DEBUG [c.c.a.t.Request]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Seq 33-1972700918: Received: {
Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 10, { CopyCmdAnswer } }
2015-07-30 12:01:47,562 INFO [o.a.c.s.v.VolumeServiceImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) releasing lock for
VMTemplateStoragePool 190
2015-07-30 12:01:47,562 WARN [c.c.u.d.Merovingian2]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Was unable to find lock for the
key template_spool_ref190 and thread id 265373936
2015-07-30 12:01:47,563 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Unable to create
Vol[874|vm=677|ROOT]:com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: storage volume
'6001f2ac-0ea9-43ae-b097-3ac2738eb5f2' exists already
2015-07-30 12:01:47,563 INFO [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:11]
is unreachable: Unable to create
Vol[874|vm=677|ROOT]:com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: storage volume
'6001f2ac-0ea9-43ae-b097-3ac2738eb5f2' exists already
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume(VolumeOrchestrator.java:1202)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1254)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:962)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:601)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:228)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:207)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3581)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3161)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3147)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:622)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy169.startVirtualMachine(Unknown Source)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:443)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at
com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at
com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
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
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:509)
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.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2015-07-30 12:01:47,645 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-25:ctx-5591097d ctx-fefabef3) Cleaning up resources for the
vm VM[User|communitytest] in Starting state
Gagandeep S. Chhabra
Reasearch Assitant, IITB
Mob: +91 97049 28427
On Thu, Jul 30, 2015 at 11:31 AM, Carlos Reátegui <create...@gmail.com>
wrote:
> Hi Gagan,
>
> I have found that the “insufficient capacity” error can be misleading.
> What version of CloudStack are you using and what hypervisor are your hosts?
>
> With CS 4.5.1 + XenServer 6.5, I just saw “insufficient capacity” when
> trying to start a stopped instance but the problem was actually a
> bootloader problem on the bad instance.
>
> The best thing to do would be to tail the management log while trying to
> create the new instance to see what the error in the log is. That is how I
> found what the actual error was in my case.
>
> regards,
> -Carlos
>
> > On Jul 29, 2015, at 10:27 PM, gagan chhabra <gagan.13031...@gmail.com>
> wrote:
> >
> > I am just trying to get the Env up and running and its just private to my
> > Institute. There are 4 instances which are being used. There are other
> > stopped VMs which need not be affected during resolving the issues. So
> > cannot wipe everything clean and do a fresh installation.
> >
> > I had been looking into it and 3 hosts are up now. I am able to start the
> > old VMs but cannot create new instances(encounter insufficient capacity
> > error), although almost entire primary storage and secondary storage is
> > unused.
> > Major issues are now:
> > 1. I had management server restart once, but I found one Exception
> (cannot
> > ping mgmt-server at 9090).
> > 2. The primary storage usage on admin dashboard is different and in
> > storage_pool is different(it shows almost complete used up in database).
> > May be this causes insufficient capacity error.
> >
> > Gagandeep S. Chhabra
> > Reasearch Assitant, IITB
> > Mob: +91 97049 28427
> >
> >
> > On Tue, Jul 28, 2015 at 7:34 PM, Daan Hoogland <daan.hoogl...@gmail.com>
> > wrote:
> >
> >> yeah, what Dag said but not as diplomatic ;)
> >>
> >> On Tue, Jul 28, 2015 at 4:01 PM, Dag Sonstebo
> >> <dag.sonst...@shapeblue.com> wrote:
> >>> Hi Gagan,
> >>>
> >>> Sounds like you might have a number of problems in your environment.
> >>> Before starting to dig too deep can you clarify what you are actually
> >>> trying to recover? I.e. are you just trying to get the CloudStack
> >>> environment up and running again or do you have production VM instances
> >>> running which you need to recover?
> >>>
> >>> Regards,
> >>> Dag Sonstebo
> >>> Cloud Architect
> >>> ShapeBlue
> >>>
> >>>
> >>>
> >>> On 28/07/2015 14:54, "gagan chhabra" <gagan.13031...@gmail.com> wrote:
> >>>
> >>>> I have been given an already set-up Cloud stack environment with 6
> hosts
> >>>> (2
> >>>> clusters with 3 hosts each) ,1 management server and one NFS storage
> as
> >>>> primary storage. So in total there are 8 physical machines (6 hosts +
> 1
> >>>> cloudstack-mgmt-server + 1 NFS:13TBytes). Management server's storage
> >>>> space
> >>>> is used as secondary storage.
> >>>>
> >>>> I just have one host up and running in cluster-2 and there is no host
> >>>> working in cluster-1. People who worked before me, may have messed up
> >> with
> >>>> persistent tier changing values of states, status for
> hosts,vms,storage
> >>>> etc
> >>>> for their testing administering the cloudstack-setup . So now Admin UI
> >>>> always shows error in notifications area, unable to change state to
> >>>> maintenance, cannot expunge vms, cannot create VMs and what not.
> >>>> *One major issue is for primary storage, used_bytes in storage_pool
> table
> >>>> is set to high value in MySQL database but on admin-dashboard it shows
> >>>> 540GB used(total capacity being 13TB). So while creating VMs,
> >> insufficient
> >>>> capacity error is encountered. *
> >>>>
> >>>> Any suggestion where to start for this? Doing everything from the
> scratch
> >>>> will be plan-B.
> >>>>
> >>>>
> >>>> Gagandeep S. Chhabra
> >>>> Mob: +91 97049 28427
> >>>
> >>> Find out more about ShapeBlue and our range of CloudStack related
> >> services
> >>>
> >>> IaaS Cloud Design & Build<
> >> http://shapeblue.com/iaas-cloud-design-and-build//>
> >>> CSForge – rapid IaaS deployment framework<
> http://shapeblue.com/csforge/>
> >>> CloudStack Consulting<http://shapeblue.com/cloudstack-consultancy/>
> >>> CloudStack Software Engineering<
> >> http://shapeblue.com/cloudstack-software-engineering/>
> >>> CloudStack Infrastructure Support<
> >> http://shapeblue.com/cloudstack-infrastructure-support/>
> >>> CloudStack Bootcamp Training Courses<
> >> http://shapeblue.com/cloudstack-training/>
> >>>
> >>> This email and any attachments to it may be confidential and are
> >> intended solely for the use of the individual to whom it is addressed.
> Any
> >> views or opinions expressed are solely those of the author and do not
> >> necessarily represent those of Shape Blue Ltd or related companies. If
> you
> >> are not the intended recipient of this email, you must neither take any
> >> action based upon its contents, nor copy or show it to anyone. Please
> >> contact the sender if you believe you have received this email in error.
> >> Shape Blue Ltd is a company incorporated in England & Wales. ShapeBlue
> >> Services India LLP is a company incorporated in India and is operated
> under
> >> license from Shape Blue Ltd. Shape Blue Brasil Consultoria Ltda is a
> >> company incorporated in Brasil and is operated under license from Shape
> >> Blue Ltd. ShapeBlue SA Pty Ltd is a company registered by The Republic
> of
> >> South Africa and is traded under license from Shape Blue Ltd. ShapeBlue
> is
> >> a registered trademark.
> >>
> >>
> >>
> >> --
> >> Daan
> >>
>
>
