cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Nagaraju (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-8472) primary secondary storage is not even started
Date Fri, 15 May 2015 05:59:00 GMT
Nagaraju created CLOUDSTACK-8472:
------------------------------------

             Summary: primary secondary storage is not even started
                 Key: CLOUDSTACK-8472
                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8472
             Project: CloudStack
          Issue Type: Bug
      Security Level: Public (Anyone can view this level - this is the default.)
            Reporter: Nagaraju


Getting the Error in the log ,

primary secondary storage is not even started


2015-05-15 11:27:05,055 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7b7b7cc9) Found 0 routers to update status. 
2015-05-15 11:27:05,056 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7b7b7cc9) Found 0 networks to update RvR status. 
2015-05-15 11:27:14,538 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-f83eb124) AutoScaling Monitor is running...
2015-05-15 11:27:15,659 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-15d5573f) VmStatsCollector is running...
2015-05-15 11:27:20,723 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 1
2015-05-15 11:27:20,724 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-10:null) Process host VM state report from ping process. host: 1
2015-05-15 11:27:20,724 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-10:null) Process VM state report. host: 1, number of records in report: 0
2015-05-15 11:27:20,725 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-10:null) Done with process of VM state report. host: 1
2015-05-15 11:27:22,615 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-4a1abd9a) Zone 1 is ready to launch console proxy
2015-05-15 11:27:22,615 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-4a1abd9a) Expand console proxy standby capacity for zone zone1
2015-05-15 11:27:22,618 INFO  [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-4a1abd9a) Found a stopped console proxy, bring it up to running pool. proxy vm id : 1
2015-05-15 11:27:22,626 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (consoleproxy-1:ctx-4a1abd9a) Sync job-3583 execution on object VmWorkJobQueue.1
2015-05-15 11:27:22,628 WARN  [c.c.u.d.Merovingian2] (consoleproxy-1:ctx-4a1abd9a) Was unable to find lock for the key vm_instance1 and thread id 1669597660
2015-05-15 11:27:22,699 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-d4167499) Zone 1 is ready to launch secondary storage VM
2015-05-15 11:27:22,703 INFO  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-d4167499) No running secondary storage vms found in datacenter id=1, starting one
2015-05-15 11:27:22,706 INFO  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-d4167499) No stopped secondary storage vm is available, need to allocate a new secondary storage vm
2015-05-15 11:27:22,708 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-d4167499) Assign secondary storage vm from a newly started instance for request from data center : 1
2015-05-15 11:27:22,719 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Found existing network configuration for offering [Network Offering [1-Public-System-Public-Network]: Ntwk[cce8f53e-fa6b-43e7-a279-e0e6c2966d4e|Public|1]
2015-05-15 11:27:22,719 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
2015-05-15 11:27:22,722 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Found existing network configuration for offering [Network Offering [3-Control-System-Control-Network]: Ntwk[98b87bbe-1ab3-4446-b411-06a5877740fb|Control|3]
2015-05-15 11:27:22,722 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
2015-05-15 11:27:22,724 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Found existing network configuration for offering [Network Offering [2-Management-System-Management-Network]: Ntwk[14ca8f59-26d9-4337-9661-bc0af27e2449|Management|2]
2015-05-15 11:27:22,724 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
2015-05-15 11:27:22,727 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Found existing network configuration for offering [Network Offering [4-Storage-System-Storage-Network]: Ntwk[d2272035-8082-4e0e-969f-c4e90a966e93|Storage|4]
2015-05-15 11:27:22,727 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
2015-05-15 11:27:22,739 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-d4167499) Allocating entries for VM: VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:22,741 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-d4167499) Allocating nics for VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:22,742 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Allocating nic for vm VM[SecondaryStorageVm|s-710-VM] in network Ntwk[cce8f53e-fa6b-43e7-a279-e0e6c2966d4e|Public|1] with requested profile NicProfile[0-0-null-null-null
2015-05-15 11:27:22,753 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Allocating nic for vm VM[SecondaryStorageVm|s-710-VM] in network Ntwk[98b87bbe-1ab3-4446-b411-06a5877740fb|Control|3] with requested profile null
2015-05-15 11:27:22,757 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Allocating nic for vm VM[SecondaryStorageVm|s-710-VM] in network Ntwk[14ca8f59-26d9-4337-9661-bc0af27e2449|Management|2] with requested profile null
2015-05-15 11:27:22,763 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-d4167499) Allocating nic for vm VM[SecondaryStorageVm|s-710-VM] in network Ntwk[d2272035-8082-4e0e-969f-c4e90a966e93|Storage|4] with requested profile null
2015-05-15 11:27:22,769 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-d4167499) Allocating disks for VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:22,772 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-d4167499) Allocation completed for VM: VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:22,775 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-d4167499) received secondary storage vm alert
2015-05-15 11:27:22,775 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-d4167499) New secondary storage vm created, zone: zone1, secStorageVm: s-710-VM, public IP: null, private IP: null
2015-05-15 11:27:22,783 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:ctx-d4167499) Sync job-3584 execution on object VmWorkJobQueue.710
2015-05-15 11:27:22,785 WARN  [c.c.u.d.Merovingian2] (secstorage-1:ctx-d4167499) Was unable to find lock for the key vm_instance710 and thread id 1631880416
2015-05-15 11:27:23,038 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f75ce52a) Execute sync-queue item: SyncQueueItemVO {id:3544, queueId: 1, contentType: AsyncJob, contentId: 3583, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Fri May 15 11:27:22 IST 2015}
2015-05-15 11:27:23,039 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f75ce52a) Schedule queued job-3583
2015-05-15 11:27:23,041 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f75ce52a) Execute sync-queue item: SyncQueueItemVO {id:3545, queueId: 3545, contentType: AsyncJob, contentId: 3584, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Fri May 15 11:27:22 IST 2015}
2015-05-15 11:27:23,041 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Add job-3583 into job monitoring
2015-05-15 11:27:23,042 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Executing AsyncJobVO {id:3583, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAAXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri May 15 11:27:22 IST 2015}
2015-05-15 11:27:23,042 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Run VM work job: com.cloud.vm.VmWorkStart for VM 1, job origin: 7
2015-05-15 11:27:23,042 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f75ce52a) Schedule queued job-3584
2015-05-15 11:27:23,043 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":1,"handlerName":"VirtualMachineManagerImpl"}
2015-05-15 11:27:23,045 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Add job-3584 into job monitoring
2015-05-15 11:27:23,046 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Executing AsyncJobVO {id:3584, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAACxnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri May 15 11:27:22 IST 2015}
2015-05-15 11:27:23,046 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Run VM work job: com.cloud.vm.VmWorkStart for VM 710, job origin: 8
2015-05-15 11:27:23,047 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":710,"handlerName":"VirtualMachineManagerImpl"}
2015-05-15 11:27:23,049 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) 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-05-15 11:27:23,049 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Successfully transitioned to start state for VM[ConsoleProxy|v-1-VM] reservation id = 2753544c-205b-4843-91f9-2c61d3ca56c6
2015-05-15 11:27:23,051 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Trying to deploy VM, vm has dcId: 1 and podId: 1
2015-05-15 11:27:23,051 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Deploy avoids pods: null, clusters: null, hosts: null
2015-05-15 11:27:23,054 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Deploy avoids pods: null, clusters: null, hosts: null
2015-05-15 11:27:23,055 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@469aa43a
2015-05-15 11:27:23,055 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) 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-05-15 11:27:23,055 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Successfully transitioned to start state for VM[SecondaryStorageVm|s-710-VM] reservation id = 5d84134b-d97e-4cc7-88b8-cef2fa99f724
2015-05-15 11:27:23,055 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 1073741824
2015-05-15 11:27:23,055 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Is ROOT volume READY (pool already allocated)?: No
2015-05-15 11:27:23,055 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Searching resources only under specified Pod: 1
2015-05-15 11:27:23,055 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2015-05-15 11:27:23,057 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Trying to deploy VM, vm has dcId: 1 and podId: null
2015-05-15 11:27:23,057 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Deploy avoids pods: null, clusters: null, hosts: null
2015-05-15 11:27:23,060 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Deploy avoids pods: null, clusters: null, hosts: null
2015-05-15 11:27:23,061 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@469aa43a
2015-05-15 11:27:23,061 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2015-05-15 11:27:23,061 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Is ROOT volume READY (pool already allocated)?: No
2015-05-15 11:27:23,061 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Searching all possible resources under this Zone: 1
2015-05-15 11:27:23,062 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2015-05-15 11:27:23,062 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Checking resources in Cluster: 1 under Pod: 1
2015-05-15 11:27:23,062 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2015-05-15 11:27:23,064 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2015-05-15 11:27:23,067 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2015-05-15 11:27:23,067 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2015-05-15 11:27:23,069 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Checking resources in Cluster: 1 under Pod: 1
2015-05-15 11:27:23,069 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2015-05-15 11:27:23,071 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2015-05-15 11:27:23,072 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:40, speed:2299) to support requested CPU: 1 and requested speed: 500
2015-05-15 11:27:23,072 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2015-05-15 11:27:23,074 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
2015-05-15 11:27:23,074 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Free CPU: 91960 , Requested CPU: 500
2015-05-15 11:27:23,074 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Free RAM: 270766178304 , Requested RAM: 1073741824
2015-05-15 11:27:23,074 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-05-15 11:27:23,074 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 91960, total with overprovisioning: 91960; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-05-15 11:27:23,074 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 270766178304; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-05-15 11:27:23,074 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2015-05-15 11:27:23,074 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2015-05-15 11:27:23,074 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2015-05-15 11:27:23,074 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2015-05-15 11:27:23,075 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Checking suitable pools for volume (Id, Type): (1,ROOT)
2015-05-15 11:27:23,075 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) We need to allocate new storagepool for this volume
2015-05-15 11:27:23,076 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Calling StoragePoolAllocators to find suitable pools
2015-05-15 11:27:23,077 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2015-05-15 11:27:23,077 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) ClusterScopeStoragePoolAllocator looking for storage pool
2015-05-15 11:27:23,077 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Looking for pools in dc: 1  pod:1  cluster:1
2015-05-15 11:27:23,077 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Found pools matching tags: []
2015-05-15 11:27:23,078 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) No storage pools available for shared volume allocation, returning
2015-05-15 11:27:23,078 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) ZoneWideStoragePoolAllocator to find storage pool
2015-05-15 11:27:23,080 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:40, speed:2299) to support requested CPU: 1 and requested speed: 500
2015-05-15 11:27:23,080 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2015-05-15 11:27:23,081 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Removing pool Pool[1|SharedMountPoint] from avoid set, must have been inserted when searching for another disk's tag
2015-05-15 11:27:23,082 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
2015-05-15 11:27:23,082 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Free CPU: 91960 , Requested CPU: 500
2015-05-15 11:27:23,082 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Free RAM: 270766178304 , Requested RAM: 536870912
2015-05-15 11:27:23,082 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-05-15 11:27:23,082 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 91960, total with overprovisioning: 91960; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-05-15 11:27:23,082 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 270766178304; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-05-15 11:27:23,082 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2015-05-15 11:27:23,082 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2015-05-15 11:27:23,083 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Checking suitable pools for volume (Id, Type): (710,ROOT)
2015-05-15 11:27:23,083 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) We need to allocate new storagepool for this volume
2015-05-15 11:27:23,083 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Checking pool 1 for storage, totalSize: 3246640242688, usedBytes: 382304256, usedPct: 1.1775380929901792E-4, disable threshold: 0.85
2015-05-15 11:27:23,084 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Calling StoragePoolAllocators to find suitable pools
2015-05-15 11:27:23,085 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2015-05-15 11:27:23,085 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) ClusterScopeStoragePoolAllocator looking for storage pool
2015-05-15 11:27:23,085 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Looking for pools in dc: 1  pod:1  cluster:1
2015-05-15 11:27:23,086 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Found pools matching tags: []
2015-05-15 11:27:23,086 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Found storage pool primary of type SharedMountPoint
2015-05-15 11:27:23,086 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Total capacity of the pool primary id: 1 is 3246640242688
2015-05-15 11:27:23,087 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Checking pool: 1 for volume allocation [Vol[1|vm=1|ROOT]], maxSize : 3246640242688, totalAllocatedSize : 0, askingSize : 0, allocated disable threshold: 0.85
2015-05-15 11:27:23,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2015-05-15 11:27:23,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2015-05-15 11:27:23,087 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) No storage pools available for shared volume allocation, returning
2015-05-15 11:27:23,087 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) ZoneWideStoragePoolAllocator to find storage pool
2015-05-15 11:27:23,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Host: 1 can access pool: 1
2015-05-15 11:27:23,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Found a potential host id: 1 name: cstkvm1 and associated storage pools for this VM
2015-05-15 11:27:23,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(1|ROOT-->Pool(1))]
2015-05-15 11:27:23,088 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Deployment found  - P0=VM[ConsoleProxy|v-1-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(1|ROOT-->Pool(1))]
2015-05-15 11:27:23,090 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Removing pool Pool[1|SharedMountPoint] from avoid set, must have been inserted when searching for another disk's tag
2015-05-15 11:27:23,093 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Checking pool 1 for storage, totalSize: 3246640242688, usedBytes: 382304256, usedPct: 1.1775380929901792E-4, disable threshold: 0.85
2015-05-15 11:27:23,093 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2015-05-15 11:27:23,095 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Found storage pool primary of type SharedMountPoint
2015-05-15 11:27:23,095 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Total capacity of the pool primary id: 1 is 3246640242688
2015-05-15 11:27:23,096 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Checking pool: 1 for volume allocation [Vol[710|vm=710|ROOT]], maxSize : 3246640242688, totalAllocatedSize : 0, askingSize : 0, allocated disable threshold: 0.85
2015-05-15 11:27:23,096 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2015-05-15 11:27:23,096 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2015-05-15 11:27:23,096 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Host: 1 can access pool: 1
2015-05-15 11:27:23,097 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Found a potential host id: 1 name: cstkvm1 and associated storage pools for this VM
2015-05-15 11:27:23,097 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(710|ROOT-->Pool(1))]
2015-05-15 11:27:23,097 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Deployment found  - P0=VM[SecondaryStorageVm|s-710-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(710|ROOT-->Pool(1))]
2015-05-15 11:27:23,098 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
2015-05-15 11:27:23,098 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) We are allocating VM, increasing the used capacity of this host:1
2015-05-15 11:27:23,098 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Current Used CPU: 0 , Free CPU:91960 ,Requested CPU: 500
2015-05-15 11:27:23,098 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Current Used RAM: 0 , Free RAM:270766178304 ,Requested RAM: 1073741824
2015-05-15 11:27:23,098 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 0, actual total: 91960, total with overprovisioning: 91960; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2015-05-15 11:27:23,098 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 0, total: 270766178304; new used: 1073741824, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2015-05-15 11:27:23,099 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) VM is being created in podId: 1
2015-05-15 11:27:23,102 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Network id=200 is already implemented
2015-05-15 11:27:23,102 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2015-05-15 11:27:23,108 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
2015-05-15 11:27:23,108 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) We are allocating VM, increasing the used capacity of this host:1
2015-05-15 11:27:23,108 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Current Used CPU: 500 , Free CPU:91460 ,Requested CPU: 500
2015-05-15 11:27:23,108 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Current Used RAM: 1073741824 , Free RAM:269692436480 ,Requested RAM: 536870912
2015-05-15 11:27:23,108 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 0, actual total: 91960, total with overprovisioning: 91960; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false
2015-05-15 11:27:23,108 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) RAM STATS after allocation: for host: 1, old used: 1073741824, old reserved: 0, total: 270766178304; new used: 1610612736, reserved: 0; requested mem: 536870912,alloc_from_last:false
2015-05-15 11:27:23,109 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) VM is being created in podId: 1
2015-05-15 11:27:23,112 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Network id=200 is already implemented
2015-05-15 11:27:23,114 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Network id=202 is already implemented
2015-05-15 11:27:23,124 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Network id=202 is already implemented
2015-05-15 11:27:23,128 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Network id=201 is already implemented
2015-05-15 11:27:23,139 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Allocated a nic NicProfile[3-1-2753544c-205b-4843-91f9-2c61d3ca56c6-10.204.196.171-null for VM[ConsoleProxy|v-1-VM]
2015-05-15 11:27:23,140 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Network id=201 is already implemented
2015-05-15 11:27:23,142 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-1-VM]
2015-05-15 11:27:23,150 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) template 3 is already in store:1, type:Image
2015-05-15 11:27:23,153 DEBUG [o.a.c.s.d.PrimaryDataStoreImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Not found (templateId:3poolId:1) in template_spool_ref, persisting it
2015-05-15 11:27:23,154 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Allocated a nic NicProfile[2838-710-5d84134b-d97e-4cc7-88b8-cef2fa99f724-10.204.196.180-null for VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:23,156 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) template 3 is already in store:1, type:Primary
2015-05-15 11:27:23,157 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Found template routing-3 in storage pool 1 with VMTemplateStoragePool id: 1420
2015-05-15 11:27:23,158 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Acquire lock on VMTemplateStoragePool 1420 with timeout 3600 seconds
2015-05-15 11:27:23,159 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Network id=203 is already implemented
2015-05-15 11:27:23,159 INFO  [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) lock is acquired for VMTemplateStoragePool 1420
2015-05-15 11:27:23,162 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE
2015-05-15 11:27:23,168 DEBUG [c.c.a.t.Request] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Seq 1-8742894251609691688: Sending  { Cmd , MgmtId: 345050283799, via: 1(cstkvm1), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/1/3/","origUrl":"http://cloudstack.apt-get.eu/systemvm/4.4/systemvm64template-4.4.0-6-kvm.qcow2.bz2","uuid":"ffbb0fe0-f406-11e4-8193-005056997f17","id":3,"format":"QCOW2","accountId":1,"checksum":"770a7d3b727ca15e511c33521ef5b8ba","hvm":false,"displayText":"SystemVM Template (KVM)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.204.206.8/home/secondary","_role":"Image"}},"name":"routing-3","hypervisorType":"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":"ffbb0fe0-f406-11e4-8193-005056997f17","id":3,"format":"QCOW2","accountId":1,"checksum":"770a7d3b727ca15e511c33521ef5b8ba","hvm":false,"displayText":"SystemVM Template (KVM)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"efae004a-16dc-4b3f-ab3e-1991d0f7e4c3","id":1,"poolType":"SharedMountPoint","host":"localhost","path":"/cst/primary","port":0,"url":"SharedMountPoint://localhost/cst/primary/?ROLE=Primary&STOREUUID=efae004a-16dc-4b3f-ab3e-1991d0f7e4c3"}},"name":"routing-3","hypervisorType":"KVM"}},"executeInSequence":false,"options":{},"wait":10800}}] }
2015-05-15 11:27:23,174 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Allocated a nic NicProfile[2839-710-5d84134b-d97e-4cc7-88b8-cef2fa99f724-10.204.196.231-null for VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:23,178 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Checking if we need to prepare 1 volumes for VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:23,187 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) template 3 is already in store:1, type:Image
2015-05-15 11:27:23,191 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) template 3 is already in store:1, type:Primary
2015-05-15 11:27:23,192 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Found template routing-3 in storage pool 1 with VMTemplateStoragePool id: 1420
2015-05-15 11:27:23,193 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Acquire lock on VMTemplateStoragePool 1420 with timeout 3600 seconds
2015-05-15 11:27:23,312 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null) Seq 1-8742894251609691688: Processing:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: storage vol already exists","wait":0}}] }
2015-05-15 11:27:23,312 DEBUG [c.c.a.t.Request] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Seq 1-8742894251609691688: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { CopyCmdAnswer } }
2015-05-15 11:27:23,317 INFO  [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) releasing lock for VMTemplateStoragePool 1420
2015-05-15 11:27:23,317 WARN  [c.c.u.d.Merovingian2] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Was unable to find lock for the key template_spool_ref1420 and thread id 188604503
2015-05-15 11:27:23,317 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Unable to create Vol[1|vm=1|ROOT]:com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: storage vol already exists
2015-05-15 11:27:23,317 INFO  [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[1|vm=1|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:1212)
        at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1264)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:988)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5201)
        at sun.reflect.GeneratedMethodAccessor232.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.java:107)
        at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5346)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:459)
        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:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
2015-05-15 11:27:23,319 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Cleaning up resources for the vm VM[ConsoleProxy|v-1-VM] in Starting state
2015-05-15 11:27:23,322 DEBUG [c.c.a.t.Request] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Seq 1-8742894251609691689: Sending  { Cmd , MgmtId: 345050283799, via: 1(cstkvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"v-1-VM","wait":0}}] }
2015-05-15 11:27:23,473 DEBUG [c.c.a.t.Request] (AgentManager-Handler-12:null) Seq 1-8742894251609691689: Processing:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-05-15 11:27:23,473 DEBUG [c.c.a.t.Request] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Seq 1-8742894251609691689: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
2015-05-15 11:27:23,480 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Released nic: NicProfile[2-1-null-null-null
2015-05-15 11:27:23,488 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Releasing ip address for reservationId=2753544c-205b-4843-91f9-2c61d3ca56c6, instance=3
2015-05-15 11:27:23,488 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Released nic: NicProfile[3-1-null-null-null
2015-05-15 11:27:23,490 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Successfully released network resources for the vm VM[ConsoleProxy|v-1-VM]
2015-05-15 11:27:23,490 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-1-VM] in Starting state
2015-05-15 11:27:23,492 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Deploy avoids pods: null, clusters: null, hosts: [1]
2015-05-15 11:27:23,493 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@469aa43a
2015-05-15 11:27:23,493 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 1073741824
2015-05-15 11:27:23,493 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Is ROOT volume READY (pool already allocated)?: No
2015-05-15 11:27:23,493 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Searching resources only under specified Pod: 1
2015-05-15 11:27:23,493 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2015-05-15 11:27:23,500 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Checking resources in Cluster: 1 under Pod: 1
2015-05-15 11:27:23,500 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2015-05-15 11:27:23,502 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2015-05-15 11:27:23,505 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2015-05-15 11:27:23,505 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2015-05-15 11:27:23,505 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Host name: cstkvm1, hostId: 1 is in avoid set, skipping this and trying other available hosts
2015-05-15 11:27:23,505 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2015-05-15 11:27:23,505 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) No suitable hosts found
2015-05-15 11:27:23,505 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) No suitable hosts found under this Cluster: 1
2015-05-15 11:27:23,506 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
2015-05-15 11:27:23,506 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Searching resources only under specified Pod: 1
2015-05-15 11:27:23,507 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2015-05-15 11:27:23,509 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Removing from the clusterId list these clusters from avoid set: [1]
2015-05-15 11:27:23,510 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2015-05-15 11:27:23,515 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2015-05-15 11:27:23,519 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
2015-05-15 11:27:23,519 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Hosts's actual total RAM: 270766170112 and RAM after applying overprovisioning: 270766178304
2015-05-15 11:27:23,519 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 91960, total with overprovisioning: 91960; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-05-15 11:27:23,519 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) release mem from host: 1, old used: 1610612736,reserved: 0, total: 270766178304; new used: 536870912,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-05-15 11:27:23,521 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-1-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-05-15 11:27:23,521 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583 ctx-805fabf9) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-1-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-05-15 11:27:23,521 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 1, job origin: 7
2015-05-15 11:27:23,521 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Unable to complete AsyncJobVO {id:3583, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAAXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri May 15 11:27:22 IST 2015}, job origin:7
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-1-VM]Scope=interface com.cloud.dc.DataCenter; id=1
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:947)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5201)
        at sun.reflect.GeneratedMethodAccessor232.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.java:107)
        at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5346)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:459)
        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:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
2015-05-15 11:27:23,522 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Complete async job-3583, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAVUpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bQ29uc29sZVByb3h5fHYtMS1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfZ0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAActxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2015-05-15 11:27:23,526 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Done executing com.cloud.vm.VmWorkStart for job-3583
2015-05-15 11:27:23,532 WARN  [c.c.v.SystemVmLoadScanner] (consoleproxy-1:ctx-4a1abd9a) Unexpected exception Job failed due to exception Unable to create a deployment for VM[ConsoleProxy|v-1-VM]
java.lang.RuntimeException: Job failed due to exception Unable to create a deployment for VM[ConsoleProxy|v-1-VM]
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:459)
        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:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
2015-05-15 11:27:23,533 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Sync queue (1) is currently empty
2015-05-15 11:27:23,534 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-58:ctx-eea1a834 job-7/job-3583) Remove job-3583 from job monitoring
2015-05-15 11:27:25,498 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-a799e655) StorageCollector is running...
2015-05-15 11:27:25,502 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-a799e655) There is no secondary storage VM for secondary storage host secondary
2015-05-15 11:27:25,504 INFO  [c.c.a.t.Request] (StatsCollector-3:ctx-a799e655) not building log message for '[{}]', _cmds.length == 1
2015-05-15 11:27:25,511 INFO  [c.c.a.t.Request] (AgentManager-Handler-14:null) not building log message for '[{}]', _cmds.length == 1
2015-05-15 11:27:25,511 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-a799e655) Seq 1-8742894251609691690: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2015-05-15 11:27:28,196 INFO  [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Unable to acquire lock on VMTemplateStoragePool 1420
2015-05-15 11:27:28,197 ERROR [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Failed to start instance VM[SecondaryStorageVm|s-710-VM]
com.cloud.utils.exception.CloudRuntimeException: Unable to acquire lock on VMTemplateStoragePool: 1420
        at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:486)
        at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:745)
        at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume(VolumeOrchestrator.java:1200)
        at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1264)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:988)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5201)
        at sun.reflect.GeneratedMethodAccessor232.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.java:107)
        at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5346)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:459)
        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:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
2015-05-15 11:27:28,201 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Cleaning up resources for the vm VM[SecondaryStorageVm|s-710-VM] in Starting state
2015-05-15 11:27:28,204 DEBUG [c.c.a.t.Request] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Seq 1-8742894251609691691: Sending  { Cmd , MgmtId: 345050283799, via: 1(cstkvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"s-710-VM","wait":0}}] }
2015-05-15 11:27:28,356 DEBUG [c.c.a.t.Request] (AgentManager-Handler-13:null) Seq 1-8742894251609691691: Processing:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-05-15 11:27:28,356 DEBUG [c.c.a.t.Request] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Seq 1-8742894251609691691: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
2015-05-15 11:27:28,364 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Released nic: NicProfile[2837-710-null-null-null
2015-05-15 11:27:28,371 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Releasing ip address for reservationId=5d84134b-d97e-4cc7-88b8-cef2fa99f724, instance=2838
2015-05-15 11:27:28,372 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Released nic: NicProfile[2838-710-null-null-null
2015-05-15 11:27:28,379 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Releasing ip address for reservationId=5d84134b-d97e-4cc7-88b8-cef2fa99f724, instance=2839
2015-05-15 11:27:28,380 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Released nic: NicProfile[2839-710-null-null-null
2015-05-15 11:27:28,382 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Successfully released network resources for the vm VM[SecondaryStorageVm|s-710-VM]
2015-05-15 11:27:28,382 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-710-VM] in Starting state
2015-05-15 11:27:28,389 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2015-05-15 11:27:28,394 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
2015-05-15 11:27:28,394 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Hosts's actual total RAM: 270766170112 and RAM after applying overprovisioning: 270766178304
2015-05-15 11:27:28,394 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) release cpu from host: 1, old used: 500,reserved: 0, actual total: 91960, total with overprovisioning: 91960; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-05-15 11:27:28,394 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) release mem from host: 1, old used: 536870912,reserved: 0, total: 270766178304; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-05-15 11:27:28,396 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Invocation exception, caused by: com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to acquire lock on VMTemplateStoragePool: 1420
2015-05-15 11:27:28,396 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584 ctx-ac70274e) Rethrow exception com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to acquire lock on VMTemplateStoragePool: 1420
2015-05-15 11:27:28,396 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 710, job origin: 8
2015-05-15 11:27:28,396 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Unable to complete AsyncJobVO {id:3584, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAACxnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri May 15 11:27:22 IST 2015}, job origin:8
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to acquire lock on VMTemplateStoragePool: 1420
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1109)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5201)
        at sun.reflect.GeneratedMethodAccessor232.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.java:107)
        at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5346)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:459)
        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:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to acquire lock on VMTemplateStoragePool: 1420
        at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:486)
        at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:745)
        at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume(VolumeOrchestrator.java:1200)
        at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1264)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:988)
        ... 19 more
2015-05-15 11:27:28,397 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Complete async job-3584, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAm0pvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBSZXNvdXJjZSBbSG9zdDoxXSBpcyB1bnJlYWNoYWJsZTogSG9zdCAxOiBVbmFibGUgdG8gc3RhcnQgaW5zdGFuY2UgZHVlIHRvIFVuYWJsZSB0byBhY3F1aXJlIGxvY2sgb24gVk1UZW1wbGF0ZVN0b3JhZ2VQb29sOiAxNDIwdXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH2dAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHLcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAAABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3NxAH4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAGeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
2015-05-15 11:27:28,401 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Done executing com.cloud.vm.VmWorkStart for job-3584
2015-05-15 11:27:28,406 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Sync queue (3545) is currently empty
2015-05-15 11:27:28,407 WARN  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-d4167499) Exception while trying to start secondary storage vm
java.lang.RuntimeException: Job failed due to exception Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to acquire lock on VMTemplateStoragePool: 1420
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:459)
        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:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
2015-05-15 11:27:28,407 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-59:ctx-323ea5a0 job-8/job-3584) Remove job-3584 from job monitoring
2015-05-15 11:27:28,407 INFO  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-d4167499) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 710, will recycle it and start a new one
2015-05-15 11:27:28,407 INFO  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-d4167499) Primary secondary storage is not even started, wait until next turn
^C
[root@cstmgt ~]# 







--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message