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)
