Hi,
I have build cloudstack environment and want to config advanced network.
Once advanced network buided success,system vm can not deploy,the log as
follows:
2015-03-09 09:40:08,962 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-685da440) Zone 6 is ready to launch secondary storage VM
2015-03-09 09:40:08,964 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl]
(secstorage-1:ctx-685da440) No running secondary storage vms found in
datacenter id=6, starting one
2015-03-09 09:40:08,967 INFO [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-685da440) No stopped secondary storage vm is available,
need to allocate a new secondary storage vm
2015-03-09 09:40:08,968 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-685da440) Assign secondary storage vm from a newly started
instance for request from data center : 6
2015-03-09 09:40:09,163 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Found existing network configuration for
offering [Network Offering [1-Public-System-Public-Network]:
Ntwk[3e77ef5f-ff11-4b42-912c-41199fde39ab|Public|1]
2015-03-09 09:40:09,163 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Releasing lock for
Acct[51ea928c-c3aa-11e4-93bf-0026553efe08-system]
2015-03-09 09:40:09,165 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Found existing network configuration for
offering [Network Offering [3-Control-System-Control-Network]:
Ntwk[6094a7a2-2b1a-4cea-b2b1-6279e4f4f48a|Control|3]
2015-03-09 09:40:09,165 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Releasing lock for
Acct[51ea928c-c3aa-11e4-93bf-0026553efe08-system]
2015-03-09 09:40:09,167 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Found existing network configuration for
offering [Network Offering [2-Management-System-Management-Network]:
Ntwk[bb0bf147-dacd-454c-9d54-03ecfc875b3c|Management|2]
2015-03-09 09:40:09,167 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Releasing lock for
Acct[51ea928c-c3aa-11e4-93bf-0026553efe08-system]
2015-03-09 09:40:09,169 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Found existing network configuration for
offering [Network Offering [4-Storage-System-Storage-Network]:
Ntwk[52df400a-5de7-460d-a09d-9af2cb16d482|Storage|4]
2015-03-09 09:40:09,169 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Releasing lock for
Acct[51ea928c-c3aa-11e4-93bf-0026553efe08-system]
2015-03-09 09:40:09,329 DEBUG [c.c.v.VirtualMachineManagerImpl]
(secstorage-1:ctx-685da440) Allocating entries for VM:
VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:09,410 DEBUG [c.c.v.VirtualMachineManagerImpl]
(secstorage-1:ctx-685da440) Allocating nics for
VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:09,411 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Allocating nic for vm
VM[SecondaryStorageVm|s-340-VM] in network
Ntwk[3e77ef5f-ff11-4b42-912c-41199fde39ab|Public|1] with requested profile
NicProfile[0-0-null-null-null
2015-03-09 09:40:09,420 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Allocating nic for vm
VM[SecondaryStorageVm|s-340-VM] in network
Ntwk[6094a7a2-2b1a-4cea-b2b1-6279e4f4f48a|Control|3] with requested profile
null
2015-03-09 09:40:09,424 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Allocating nic for vm
VM[SecondaryStorageVm|s-340-VM] in network
Ntwk[bb0bf147-dacd-454c-9d54-03ecfc875b3c|Management|2] with requested
profile null
2015-03-09 09:40:09,429 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(secstorage-1:ctx-685da440) Allocating nic for vm
VM[SecondaryStorageVm|s-340-VM] in network
Ntwk[52df400a-5de7-460d-a09d-9af2cb16d482|Storage|4] with requested profile
null
2015-03-09 09:40:09,433 DEBUG [c.c.v.VirtualMachineManagerImpl]
(secstorage-1:ctx-685da440) Allocating disks for
VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:09,520 DEBUG [c.c.v.VirtualMachineManagerImpl]
(secstorage-1:ctx-685da440) Allocation completed for VM:
VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:09,522 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
(secstorage-1:ctx-685da440) received secondary storage vm alert
2015-03-09 09:40:09,522 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
(secstorage-1:ctx-685da440) New secondary storage vm created, zone: zone1,
secStorageVm: s-340-VM, public IP: null, private IP: null
2015-03-09 09:40:09,529 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(secstorage-1:ctx-685da440) Sync job-1773 execution on object
VmWorkJobQueue.340
2015-03-09 09:40:09,531 WARN [c.c.u.d.Merovingian2]
(secstorage-1:ctx-685da440) Was unable to find lock for the key
vm_instance340 and thread id 263842882
2015-03-09 09:40:10,486 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-a2dd1272) Execute sync-queue item:
SyncQueueItemVO {id:27, queueId: 1629, contentType: AsyncJob, contentId:
1772, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null,
created: Mon Mar 09 09:40:08 CST 2015}
2015-03-09 09:40:10,487 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-a2dd1272) Schedule queued job-1772
2015-03-09 09:40:10,554 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-a2dd1272) Execute sync-queue item:
SyncQueueItemVO {id:28, queueId: 1655, contentType: AsyncJob, contentId:
1773, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null,
created: Mon Mar 09 09:40:09 CST 2015}
2015-03-09 09:40:10,555 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Add job-1772 into job
monitoring
2015-03-09 09:40:10,555 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Executing AsyncJobVO
{id:1772, userId: 1, accountId: 1, instanceType: null, instanceId: null,
cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p
ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj
bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA
EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-
AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h
cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE
SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAB
AAAAAAAAAAEAAAAAAAABTnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw
cHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode:
0, result: null, initMsid: 164638948872, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Mar 09 09:40:08 CST 2015}
2015-03-09 09:40:10,555 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-a2dd1272) Schedule queued job-1773
2015-03-09 09:40:10,556 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Run VM work job:
com.cloud.vm.VmWorkStart for VM 334, job origin: 1726
2015-03-09 09:40:10,557 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Execute
VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":334,"handl
erName":"VirtualMachineManagerImpl"}
2015-03-09 09:40:10,563 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) 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-03-09 09:40:10,563 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
Successfully transitioned to start state for VM[ConsoleProxy|v-334-VM]
reservation id = dd45e90e-6cb9-4096-98c6-4ffa9c23ce79
2015-03-09 09:40:10,633 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773) Add job-1773 into job
monitoring
2015-03-09 09:40:10,634 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773) Executing AsyncJobVO
{id:1773, userId: 1, accountId: 1, instanceType: null, instanceId: null,
cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p
ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj
bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA
EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-
AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h
cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE
SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAB
AAAAAAAAAAEAAAAAAAABVHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw
cHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode:
0, result: null, initMsid: 164638948872, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Mar 09 09:40:09 CST 2015}
2015-03-09 09:40:10,635 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773) Run VM work job:
com.cloud.vm.VmWorkStart for VM 340, job origin: 1727
2015-03-09 09:40:10,636 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Execute
VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":340,"handl
erName":"VirtualMachineManagerImpl"}
2015-03-09 09:40:10,642 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) 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-03-09 09:40:10,642 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
Successfully transitioned to start state for VM[SecondaryStorageVm|s-340-VM]
reservation id = e742a220-b5fc-47dc-9137-b6613a78eea9
2015-03-09 09:40:10,705 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Trying to
deploy VM, vm has dcId: 6 and podId: 6
2015-03-09 09:40:10,705 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Deploy
avoids pods: null, clusters: null, hosts: null
2015-03-09 09:40:10,707 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Deploy
avoids pods: null, clusters: null, hosts: null
2015-03-09 09:40:10,708 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@19c1e544
2015-03-09 09:40:10,708 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Trying to
allocate a host and storage pools from dc:6, pod:6,cluster:null, requested
cpu: 500, requested ram: 1073741824
2015-03-09 09:40:10,708 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Is ROOT
volume READY (pool already allocated)?: No
2015-03-09 09:40:10,708 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Searching
resources only under specified Pod: 6
2015-03-09 09:40:10,708 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Pod: 6
2015-03-09 09:40:10,715 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Checking
resources in Cluster: 4 under Pod: 6
2015-03-09 09:40:10,715 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Looking for hosts in dc: 6 pod:6 cluster:4
2015-03-09 09:40:10,717 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
allocation: [Host[-7-Routing]]
2015-03-09 09:40:10,720 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization:
[Host[-7-Routing]]
2015-03-09 09:40:10,720 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2015-03-09 09:40:10,723 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Host: 7 has cpu capability (cpu:6, speed:2000) to
support requested CPU: 1 and requested speed: 500
2015-03-09 09:40:10,723 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for
requested CPU: 500 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2015-03-09 09:40:10,725 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Hosts's actual total CPU: 12000 and CPU after
applying overprovisioning: 12000
2015-03-09 09:40:10,725 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Free CPU: 12000 , Requested CPU: 500
2015-03-09 09:40:10,725 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Free RAM: 8149745664 , Requested RAM: 1073741824
2015-03-09 09:40:10,725 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-03-09 09:40:10,725 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 0,
reserved: 0, actual total: 12000, total with overprovisioning: 12000;
requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2015-03-09 09:40:10,725 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used: 0,
reserved: 0, total: 8149745664; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-03-09 09:40:10,725 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
2015-03-09 09:40:10,725 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2015-03-09 09:40:10,726 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Checking
suitable pools for volume (Id, Type): (334,ROOT)
2015-03-09 09:40:10,726 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) We need
to allocate new storagepool for this volume
2015-03-09 09:40:10,727 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Calling
StoragePoolAllocators to find suitable pools
2015-03-09 09:40:10,727 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2015-03-09 09:40:10,727 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
ClusterScopeStoragePoolAllocator looking for storage pool
2015-03-09 09:40:10,727 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Looking
for pools in dc: 6 pod:6 cluster:4
2015-03-09 09:40:10,728 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Found
pools matching tags: []
2015-03-09 09:40:10,729 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) No
storage pools available for shared volume allocation, returning
2015-03-09 09:40:10,729 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
ZoneWideStoragePoolAllocator to find storage pool
2015-03-09 09:40:10,731 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Removing
pool Pool[6|NetworkFilesystem] from avoid set, must have been inserted when
searching for another disk's tag
2015-03-09 09:40:10,733 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Checking
pool 6 for storage, totalSize: 52710866944, usedBytes: 1959788544, usedPct:
0.03717997175197438, disable threshold: 0.85
2015-03-09 09:40:10,736 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Found
storage pool master of type NetworkFilesystem with overprovisioning factor 2
2015-03-09 09:40:10,736 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Total
over provisioned capacity calculated is 2 * 52710866944
2015-03-09 09:40:10,736 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Total
capacity of the pool master id: 6 is 105421733888
2015-03-09 09:40:10,736 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Checking
pool: 6 for volume allocation [Vol[334|vm=334|ROOT]], maxSize :
105421733888, totalAllocatedSize : 0, askingSize : 0, allocated disable
threshold: 0.85
2015-03-09 09:40:10,737 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Trying to
find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2015-03-09 09:40:10,737 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Checking
if host: 7 can access any suitable storage pool for volume: ROOT
2015-03-09 09:40:10,737 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Host: 7
can access pool: 6
2015-03-09 09:40:10,738 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Found a
potential host id: 7 name: cloudagent.neu.com and associated storage pools
for this VM
2015-03-09 09:40:10,739 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Returning
Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id)
)] :
Dest[Zone(6)-Pod(6)-Cluster(4)-Host(7)-Storage(Volume(334|ROOT-->Pool(6))]
2015-03-09 09:40:10,739 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
Deployment found - P0=VM[ConsoleProxy|v-334-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(6)-Pod(6)-Cluster(4)-Host(7)-Storage(Volume(334|ROOT-->Pool(6))]
2015-03-09 09:40:10,772 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Trying to
deploy VM, vm has dcId: 6 and podId: null
2015-03-09 09:40:10,772 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Deploy
avoids pods: null, clusters: null, hosts: null
2015-03-09 09:40:10,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Deploy
avoids pods: null, clusters: null, hosts: null
2015-03-09 09:40:10,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@19c1e544
2015-03-09 09:40:10,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Trying to
allocate a host and storage pools from dc:6, pod:null,cluster:null,
requested cpu: 500, requested ram: 536870912
2015-03-09 09:40:10,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Is ROOT
volume READY (pool already allocated)?: No
2015-03-09 09:40:10,775 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Searching
all possible resources under this Zone: 6
2015-03-09 09:40:10,776 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Zone: 6
2015-03-09 09:40:10,781 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Checking
resources in Cluster: 4 under Pod: 6
2015-03-09 09:40:10,781 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Looking for hosts in dc: 6 pod:6 cluster:4
2015-03-09 09:40:10,783 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
allocation: [Host[-7-Routing]]
2015-03-09 09:40:10,785 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization:
[Host[-7-Routing]]
2015-03-09 09:40:10,785 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2015-03-09 09:40:10,789 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Host: 7 has cpu capability (cpu:6, speed:2000) to
support requested CPU: 1 and requested speed: 500
2015-03-09 09:40:10,789 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for
requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor:
1.0
2015-03-09 09:40:10,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Hosts's actual total CPU: 12000 and CPU after
applying overprovisioning: 12000
2015-03-09 09:40:10,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Free CPU: 12000 , Requested CPU: 500
2015-03-09 09:40:10,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Free RAM: 8149745664 , Requested RAM: 536870912
2015-03-09 09:40:10,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-03-09 09:40:10,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 0,
reserved: 0, actual total: 12000, total with overprovisioning: 12000;
requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2015-03-09 09:40:10,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used: 0,
reserved: 0, total: 8149745664; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-03-09 09:40:10,790 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
2015-03-09 09:40:10,790 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c
FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2015-03-09 09:40:10,791 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Checking
suitable pools for volume (Id, Type): (340,ROOT)
2015-03-09 09:40:10,791 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) We need
to allocate new storagepool for this volume
2015-03-09 09:40:10,792 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Calling
StoragePoolAllocators to find suitable pools
2015-03-09 09:40:10,793 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2015-03-09 09:40:10,793 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
ClusterScopeStoragePoolAllocator looking for storage pool
2015-03-09 09:40:10,793 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Looking
for pools in dc: 6 pod:6 cluster:4
2015-03-09 09:40:10,793 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Found
pools matching tags: []
2015-03-09 09:40:10,794 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) No
storage pools available for shared volume allocation, returning
2015-03-09 09:40:10,794 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
ZoneWideStoragePoolAllocator to find storage pool
2015-03-09 09:40:10,796 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Removing
pool Pool[6|NetworkFilesystem] from avoid set, must have been inserted when
searching for another disk's tag
2015-03-09 09:40:10,798 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Checking
pool 6 for storage, totalSize: 52710866944, usedBytes: 1959788544, usedPct:
0.03717997175197438, disable threshold: 0.85
2015-03-09 09:40:10,801 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Found
storage pool master of type NetworkFilesystem with overprovisioning factor 2
2015-03-09 09:40:10,801 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Total
over provisioned capacity calculated is 2 * 52710866944
2015-03-09 09:40:10,801 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Total
capacity of the pool master id: 6 is 105421733888
2015-03-09 09:40:10,801 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Checking
pool: 6 for volume allocation [Vol[340|vm=340|ROOT]], maxSize :
105421733888, totalAllocatedSize : 0, askingSize : 0, allocated disable
threshold: 0.85
2015-03-09 09:40:10,801 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Trying to
find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2015-03-09 09:40:10,802 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Checking
if host: 7 can access any suitable storage pool for volume: ROOT
2015-03-09 09:40:10,802 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Host: 7
can access pool: 6
2015-03-09 09:40:10,802 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Found a
potential host id: 7 name: cloudagent.neu.com and associated storage pools
for this VM
2015-03-09 09:40:10,803 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Returning
Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id)
)] :
Dest[Zone(6)-Pod(6)-Cluster(4)-Host(7)-Storage(Volume(340|ROOT-->Pool(6))]
2015-03-09 09:40:10,803 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
Deployment found - P0=VM[SecondaryStorageVm|s-340-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(6)-Pod(6)-Cluster(4)-Host(7)-Storage(Volume(340|ROOT-->Pool(6))]
2015-03-09 09:40:10,871 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) VM state
transitted from :Starting to Starting with event: OperationRetryvm's
original host id: null new host id: 7 host id before state transition: null
2015-03-09 09:40:10,876 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Hosts's
actual total CPU: 12000 and CPU after applying overprovisioning: 12000
2015-03-09 09:40:10,876 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) We are
allocating VM, increasing the used capacity of this host:7
2015-03-09 09:40:10,876 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Current
Used CPU: 0 , Free CPU:12000 ,Requested CPU: 500
2015-03-09 09:40:10,876 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Current
Used RAM: 0 , Free RAM:8149745664 ,Requested RAM: 1073741824
2015-03-09 09:40:10,876 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) CPU STATS
after allocation: for host: 7, old used: 0, old reserved: 0, actual total:
12000, total with overprovisioning: 12000; new used:500, reserved:0;
requested cpu:500,alloc_from_last:false
2015-03-09 09:40:10,876 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) RAM STATS
after allocation: for host: 7, old used: 0, old reserved: 0, total:
8149745664; new used: 1073741824, reserved: 0; requested mem:
1073741824,alloc_from_last:false
2015-03-09 09:40:10,938 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) VM state
transitted from :Starting to Starting with event: OperationRetryvm's
original host id: null new host id: 7 host id before state transition: null
2015-03-09 09:40:10,972 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Hosts's
actual total CPU: 12000 and CPU after applying overprovisioning: 12000
2015-03-09 09:40:10,972 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) We are
allocating VM, increasing the used capacity of this host:7
2015-03-09 09:40:10,972 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Current
Used CPU: 500 , Free CPU:11500 ,Requested CPU: 500
2015-03-09 09:40:10,972 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Current
Used RAM: 1073741824 , Free RAM:7076003840 ,Requested RAM: 536870912
2015-03-09 09:40:10,972 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) CPU STATS
after allocation: for host: 7, old used: 500, old reserved: 0, actual total:
12000, total with overprovisioning: 12000; new used:1000, reserved:0;
requested cpu:500,alloc_from_last:false
2015-03-09 09:40:10,972 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) RAM STATS
after allocation: for host: 7, old used: 1073741824, old reserved: 0, total:
8149745664; new used: 1610612736, reserved: 0; requested mem:
536870912,alloc_from_last:false
2015-03-09 09:40:11,005 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) VM is
being created in podId: 6
2015-03-09 09:40:11,008 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Network
id=220 is already implemented
2015-03-09 09:40:11,105 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) VM is
being created in podId: 6
2015-03-09 09:40:11,108 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Network
id=220 is already implemented
2015-03-09 09:40:11,174 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Network
id=222 is already implemented
2015-03-09 09:40:11,241 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Network
id=222 is already implemented
2015-03-09 09:40:11,576 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Network
id=221 is already implemented
2015-03-09 09:40:11,660 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Network
id=221 is already implemented
2015-03-09 09:40:11,991 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Allocated
a nic
NicProfile[1329-334-dd45e90e-6cb9-4096-98c6-4ffa9c23ce79-192.168.80.223-null
for VM[ConsoleProxy|v-334-VM]
2015-03-09 09:40:12,066 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Allocated
a nic
NicProfile[1352-340-e742a220-b5fc-47dc-9137-b6613a78eea9-192.168.80.212-null
for VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:12,168 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Checking
if we need to prepare 1 volumes for VM[ConsoleProxy|v-334-VM]
2015-03-09 09:40:12,176 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) template
3 is already in store:4, type:Image
2015-03-09 09:40:12,178 DEBUG [o.a.c.s.d.PrimaryDataStoreImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Not found
(templateId:3poolId:6) in template_spool_ref, persisting it
2015-03-09 09:40:12,235 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Network
id=223 is already implemented
2015-03-09 09:40:12,311 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) template
3 is already in store:6, type:Primary
2015-03-09 09:40:12,312 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Found
template routing-3 in storage pool 6 with VMTemplateStoragePool id: 11
2015-03-09 09:40:12,313 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Acquire
lock on VMTemplateStoragePool 11 with timeout 3600 seconds
2015-03-09 09:40:12,314 INFO [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) lock is
acquired for VMTemplateStoragePool 11
2015-03-09 09:40:12,453 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) copyAsync
inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE
2015-03-09 09:40:12,462 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Seq
7-8489285297593385008: Sending { Cmd , MgmtId: 164638948872, via:
7(cloudagent.neu.com), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/1/3/","origUr
l":"http://cloudstack.apt-get.eu/systemvm/4.4/systemvm64template-4.4.0-6-kvm
.qcow2.bz2","uuid":"df1b6da4-c3a8-11e4-aa6d-0026553efe08","id":3,"format":"Q
COW2","accountId":1,"checksum":"770a7d3b727ca15e511c33521ef5b8ba","hvm":fals
e,"displayText":"SystemVM Template
(KVM)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.1
68.80.120/export/secondary","_role":"Image"}},"name":"routing-3","hypervisor
Type":"KVM"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":
{"origUrl":"http://cloudstack.apt-get.eu/systemvm/4.4/systemvm64template-4.4
.0-6-kvm.qcow2.bz2","uuid":"df1b6da4-c3a8-11e4-aa6d-0026553efe08","id":3,"fo
rmat":"QCOW2","accountId":1,"checksum":"770a7d3b727ca15e511c33521ef5b8ba","h
vm":false,"displayText":"SystemVM Template
(KVM)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreT
O":{"uuid":"2048476b-09a8-3add-a5cb-963495de3fc6","id":6,"poolType":"Network
Filesystem","host":"192.168.80.121","path":"/mnt/primary","port":2049,"url":
"NetworkFilesystem://192.168.80.121/mnt/primary/?ROLE=Primary&STOREUUID=2048
476b-09a8-3add-a5cb-963495de3fc6"}},"name":"routing-3","hypervisorType":"KVM
"}},"executeInSequence":false,"options":{},"wait":10800}}] }
2015-03-09 09:40:12,519 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Allocated
a nic
NicProfile[1353-340-e742a220-b5fc-47dc-9137-b6613a78eea9-192.168.80.221-null
for VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:12,604 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Checking
if we need to prepare 1 volumes for VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:12,610 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) template
3 is already in store:4, type:Image
2015-03-09 09:40:12,614 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) template
3 is already in store:6, type:Primary
2015-03-09 09:40:12,614 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Found
template routing-3 in storage pool 6 with VMTemplateStoragePool id: 11
2015-03-09 09:40:12,615 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Acquire
lock on VMTemplateStoragePool 11 with timeout 3600 seconds
2015-03-09 09:40:12,744 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-5:null) Seq 7-8489285297593385008: Processing: { Ans:
, MgmtId: 164638948872, via: 7, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"det
ails":"com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: Storage volume not found: storage vol already
exists","wait":0}}] }
2015-03-09 09:40:12,744 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Seq
7-8489285297593385008: Received: { Ans: , MgmtId: 164638948872, via: 7,
Ver: v1, Flags: 10, { CopyCmdAnswer } }
2015-03-09 09:40:12,878 INFO [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) releasing
lock for VMTemplateStoragePool 11
2015-03-09 09:40:12,879 WARN [c.c.u.d.Merovingian2]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Was
unable to find lock for the key template_spool_ref11 and thread id 355036656
2015-03-09 09:40:12,879 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Unable to
create Vol[334|vm=334|ROOT]:com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: Storage volume not found: storage vol already
exists
2015-03-09 09:40:12,879 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Unable to
contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:6] is
unreachable: Unable to create
Vol[334|vm=334|ROOT]:com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: Storage volume not found: storage vol already
exists
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume
(VolumeOrchestrator.java:1205)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(Volume
Orchestrator.java:1257)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:988)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5195)
at sun.reflect.GeneratedMethodAccessor268.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5340)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2015-03-09 09:40:12,953 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Cleaning
up resources for the vm VM[ConsoleProxy|v-334-VM] in Starting state
2015-03-09 09:40:12,956 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Seq
7-8489285297593385009: Sending { Cmd , MgmtId: 164638948872, via:
7(cloudagent.neu.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal
se,"checkBeforeCleanup":false,"vmName":"v-334-VM","wait":0}}] }
2015-03-09 09:40:13,240 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-6:null) Seq 7-8489285297593385009: Processing: { Ans:
, MgmtId: 164638948872, via: 7, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-03-09 09:40:13,240 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Seq
7-8489285297593385009: Received: { Ans: , MgmtId: 164638948872, via: 7,
Ver: v1, Flags: 10, { StopAnswer } }
2015-03-09 09:40:13,314 DEBUG [c.c.n.g.ControlNetworkGuru]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Released
nic: NicProfile[1328-334-null-null-null
2015-03-09 09:40:13,423 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Releasing
ip address for reservationId=dd45e90e-6cb9-4096-98c6-4ffa9c23ce79,
instance=1329
2015-03-09 09:40:13,424 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Released
nic: NicProfile[1329-334-null-null-null
2015-03-09 09:40:13,504 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
Successfully released network resources for the vm VM[ConsoleProxy|v-334-VM]
2015-03-09 09:40:13,505 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
Successfully cleanued up resources for the vm VM[ConsoleProxy|v-334-VM] in
Starting state
2015-03-09 09:40:13,506 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Deploy
avoids pods: null, clusters: null, hosts: [7]
2015-03-09 09:40:13,507 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@19c1e544
2015-03-09 09:40:13,507 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Trying to
allocate a host and storage pools from dc:6, pod:6,cluster:null, requested
cpu: 500, requested ram: 1073741824
2015-03-09 09:40:13,507 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Is ROOT
volume READY (pool already allocated)?: No
2015-03-09 09:40:13,507 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Searching
resources only under specified Pod: 6
2015-03-09 09:40:13,507 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Pod: 6
2015-03-09 09:40:13,512 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Checking
resources in Cluster: 4 under Pod: 6
2015-03-09 09:40:13,512 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Looking for hosts in dc: 6 pod:6 cluster:4
2015-03-09 09:40:13,514 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
allocation: [Host[-7-Routing]]
2015-03-09 09:40:13,516 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization:
[Host[-7-Routing]]
2015-03-09 09:40:13,516 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2015-03-09 09:40:13,516 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Host name: cloudagent.neu.com, hostId: 7 is in
avoid set, skipping this and trying other available hosts
2015-03-09 09:40:13,516 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d
FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2015-03-09 09:40:13,516 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) No
suitable hosts found
2015-03-09 09:40:13,516 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) No
suitable hosts found under this Cluster: 4
2015-03-09 09:40:13,517 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Could not
find suitable Deployment Destination for this VM under any clusters,
returning.
2015-03-09 09:40:13,518 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Searching
resources only under specified Pod: 6
2015-03-09 09:40:13,518 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Pod: 6
2015-03-09 09:40:13,520 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Removing
from the clusterId list these clusters from avoid set: [4]
2015-03-09 09:40:13,520 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) No
clusters found after removing disabled clusters and clusters in avoid list,
returning.
2015-03-09 09:40:13,671 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) VM state
transitted from :Starting to Stopped with event: OperationFailedvm's
original host id: null new host id: null host id before state transition: 7
2015-03-09 09:40:13,675 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Hosts's
actual total CPU: 12000 and CPU after applying overprovisioning: 12000
2015-03-09 09:40:13,675 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Hosts's
actual total RAM: 8149745664 and RAM after applying overprovisioning:
8149745664
2015-03-09 09:40:13,675 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) release
cpu from host: 7, old used: 1000,reserved: 0, actual total: 12000, total
with overprovisioning: 12000; new used: 500,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2015-03-09 09:40:13,675 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) release
mem from host: 7, old used: 1610612736,reserved: 0, total: 8149745664; new
used: 536870912,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-03-09 09:40:13,755 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d)
Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[ConsoleProxy|v-334-VM]Scope=interface
com.cloud.dc.DataCenter; id=6
2015-03-09 09:40:13,756 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772 ctx-f2cea25d) Rethrow
exception com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[ConsoleProxy|v-334-VM]Scope=interface
com.cloud.dc.DataCenter; id=6
2015-03-09 09:40:13,756 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Done with run of VM
work job: com.cloud.vm.VmWorkStart for VM 334, job origin: 1726
2015-03-09 09:40:13,756 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Unable to complete
AsyncJobVO {id:1772, userId: 1, accountId: 1, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p
ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj
bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA
EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-
AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h
cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE
SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAB
AAAAAAAAAAEAAAAAAAABTnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw
cHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode:
0, result: null, initMsid: 164638948872, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Mar 09 09:40:08 CST 2015}, job
origin:1726
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[ConsoleProxy|v-334-VM]Scope=interface
com.cloud.dc.DataCenter; id=6
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:947)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5195)
at sun.reflect.GeneratedMethodAccessor268.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5340)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2015-03-09 09:40:13,757 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Complete async
job-1772, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFu
Zy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARM
AAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9s
YW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7
TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAV0pvYiBm
YWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3Ig
Vk1bQ29uc29sZVByb3h5fHYtMzM0LVZNXXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVu
dDsCRio8PP0iOQIAAHhwAAAADXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbd
hQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAETAAIZmlsZU5hbWVxAH4ABEwA
Cm1ldGhvZE5hbWVxAH4ABHhwAAAAcnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVy
dAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgALAAAB93QAP29yZy5hcGFj
aGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQA
GEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4ACwAAADF0AD5vcmcu
YXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUk
MXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4ACwAAADh0AEJvcmcuYXBh
Y2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0
JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-AAsAAABndABAb3JnLmFw
YWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4
dHEAfgAadAAPY2FsbFdpdGhDb250ZXh0c3EAfgALAAAANXEAfgAdcQB-ABp0AA5ydW5XaXRoQ29u
dGV4dHNxAH4ACwAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1h
bmFnZWRDb250ZXh0UnVubmFibGVxAH4AFnEAfgAXc3EAfgALAAABzHEAfgARcQB-ABJxAH4AF3Nx
AH4ACwAAAdd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVy
dAAORXhlY3V0b3JzLmphdmFxAH4AG3NxAH4ACwAAAQZ0AB9qYXZhLnV0aWwuY29uY3VycmVudC5G
dXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ABdzcQB-AAsAAAR5dAAnamF2YS51dGlsLmNv
bmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAly
dW5Xb3JrZXJzcQB-AAsAAAJndAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1
dG9yJFdvcmtlcnEAfgAscQB-ABdzcQB-AAsAAALpdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVh
ZC5qYXZhcQB-ABdzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUx
teyOEAIAAUwABGxpc3RxAH4ABnhyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxl
Q29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNq
YXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgA4eA
2015-03-09 09:40:13,847 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Done executing
com.cloud.vm.VmWorkStart for job-1772
2015-03-09 09:40:14,025 WARN [c.c.v.SystemVmLoadScanner]
(consoleproxy-1:ctx-808a32fe) Unexpected exception Job failed due to
exception Unable to create a deployment for VM[ConsoleProxy|v-334-VM]
java.lang.RuntimeException: Job failed due to exception Unable to create a
deployment for VM[ConsoleProxy|v-334-VM]
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2015-03-09 09:40:14,107 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Sync queue (1629) is
currently empty
2015-03-09 09:40:14,107 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-27:ctx-80268771 job-1726/job-1772) Remove job-1772 from
job monitoring
2015-03-09 09:40:14,812 DEBUG [c.c.s.StatsCollector]
(StatsCollector-2:ctx-7ecb8df3) VmStatsCollector is running...
2015-03-09 09:40:15,111 DEBUG [c.c.s.StatsCollector]
(StatsCollector-4:ctx-29f8d049) AutoScaling Monitor is running...
2015-03-09 09:40:15,377 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-06611b06) StorageCollector is running...
2015-03-09 09:40:15,379 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-06611b06) There is no secondary storage VM for
secondary storage host nfs://192.168.80.120/export/secondary
2015-03-09 09:40:15,404 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-06611b06) Seq 7-8489285297593385010: Received: { Ans:
, MgmtId: 164638948872, via: 7, Ver: v1, Flags: 10, { GetStorageStatsAnswer
} }
2015-03-09 09:40:17,617 INFO [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Unable to
acquire lock on VMTemplateStoragePool 11
2015-03-09 09:40:17,617 ERROR [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Failed to
start instance VM[SecondaryStorageVm|s-340-VM]
com.cloud.utils.exception.CloudRuntimeException: Unable to acquire lock on
VMTemplateStoragePool: 11
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(
VolumeServiceImpl.java:486)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTempl
ateAsync(VolumeServiceImpl.java:745)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume
(VolumeOrchestrator.java:1193)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(Volume
Orchestrator.java:1257)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:988)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5195)
at sun.reflect.GeneratedMethodAccessor268.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5340)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2015-03-09 09:40:17,737 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Cleaning
up resources for the vm VM[SecondaryStorageVm|s-340-VM] in Starting state
2015-03-09 09:40:17,739 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Seq
7-8489285297593385011: Sending { Cmd , MgmtId: 164638948872, via:
7(cloudagent.neu.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal
se,"checkBeforeCleanup":false,"vmName":"s-340-VM","wait":0}}] }
2015-03-09 09:40:18,061 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-7:null) Seq 7-8489285297593385011: Processing: { Ans:
, MgmtId: 164638948872, via: 7, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-03-09 09:40:18,061 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Seq
7-8489285297593385011: Received: { Ans: , MgmtId: 164638948872, via: 7,
Ver: v1, Flags: 10, { StopAnswer } }
2015-03-09 09:40:18,087 DEBUG [c.c.s.StatsCollector]
(StatsCollector-1:ctx-dfd57693) HostStatsCollector is running...
2015-03-09 09:40:18,131 DEBUG [c.c.n.g.ControlNetworkGuru]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Released
nic: NicProfile[1351-340-null-null-null
2015-03-09 09:40:18,200 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Releasing
ip address for reservationId=e742a220-b5fc-47dc-9137-b6613a78eea9,
instance=1352
2015-03-09 09:40:18,200 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Released
nic: NicProfile[1352-340-null-null-null
2015-03-09 09:40:18,268 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Releasing
ip address for reservationId=e742a220-b5fc-47dc-9137-b6613a78eea9,
instance=1353
2015-03-09 09:40:18,268 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Released
nic: NicProfile[1353-340-null-null-null
2015-03-09 09:40:18,331 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
Successfully released network resources for the vm
VM[SecondaryStorageVm|s-340-VM]
2015-03-09 09:40:18,331 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
Successfully cleanued up resources for the vm
VM[SecondaryStorageVm|s-340-VM] in Starting state
2015-03-09 09:40:18,464 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) VM state
transitted from :Starting to Stopped with event: OperationFailedvm's
original host id: null new host id: null host id before state transition: 7
2015-03-09 09:40:18,468 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Hosts's
actual total CPU: 12000 and CPU after applying overprovisioning: 12000
2015-03-09 09:40:18,468 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Hosts's
actual total RAM: 8149745664 and RAM after applying overprovisioning:
8149745664
2015-03-09 09:40:18,468 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) release
cpu from host: 7, old used: 500,reserved: 0, actual total: 12000, total with
overprovisioning: 12000; new used: 0,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2015-03-09 09:40:18,468 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) release
mem from host: 7, old used: 536870912,reserved: 0, total: 8149745664; new
used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-03-09 09:40:18,532 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c)
Invocation exception, caused by:
com.cloud.exception.AgentUnavailableException: Resource [Host:7] is
unreachable: Host 7: Unable to start instance due to Unable to acquire lock
on VMTemplateStoragePool: 11
2015-03-09 09:40:18,532 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773 ctx-fd8af67c) Rethrow
exception com.cloud.exception.AgentUnavailableException: Resource [Host:7]
is unreachable: Host 7: Unable to start instance due to Unable to acquire
lock on VMTemplateStoragePool: 11
2015-03-09 09:40:18,532 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773) Done with run of VM
work job: com.cloud.vm.VmWorkStart for VM 340, job origin: 1727
2015-03-09 09:40:18,532 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773) Unable to complete
AsyncJobVO {id:1773, userId: 1, accountId: 1, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p
ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj
bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA
EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-
AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h
cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE
SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAB
AAAAAAAAAAEAAAAAAAABVHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw
cHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode:
0, result: null, initMsid: 164638948872, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Mar 09 09:40:09 CST 2015}, job
origin:1727
com.cloud.exception.AgentUnavailableException: Resource [Host:7] is
unreachable: Host 7: Unable to start instance due to Unable to acquire lock
on VMTemplateStoragePool: 11
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:1106)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5195)
at sun.reflect.GeneratedMethodAccessor268.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5340)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to
acquire lock on VMTemplateStoragePool: 11
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(
VolumeServiceImpl.java:486)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTempl
ateAsync(VolumeServiceImpl.java:745)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume
(VolumeOrchestrator.java:1193)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(Volume
Orchestrator.java:1257)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:988)
... 19 more
2015-03-09 09:40:18,533 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-28:ctx-86a87979 job-1727/job-1773) Complete async
job-1773, jobStatus: FAILED, resultCode: 0, result:
---------------------------------------------------------------------------------------------------
Confidentiality Notice: The information contained in this e-mail and any
accompanying attachment(s)
is intended only for the use of the intended recipient and may be confidential
and/or privileged of
Neusoft Corporation, its subsidiaries and/or its affiliates. If any reader of
this communication is
not the intended recipient, unauthorized use, forwarding, printing, storing,
disclosure or copying
is strictly prohibited, and may be unlawful.If you have received this
communication in error,please
immediately notify the sender by return e-mail, and delete the original message
and all copies from
your system. Thank you.
---------------------------------------------------------------------------------------------------
