>From vm manager can you see its deployed ? Sometimes its deployed but due
to networking issue its not showing up 1st check up there
On Mar 9, 2015 8:04 AM, "liuxin" <liu_xin....@neusoft.com> wrote:
> 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.
>
> ---------------------------------------------------------------------------------------------------
>
