You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Nagaraju (JIRA)" <ji...@apache.org> on 2015/04/20 12:06:59 UTC
[jira] [Created] (CLOUDSTACK-8392) Unable to power the vms
Nagaraju created CLOUDSTACK-8392:
------------------------------------
Summary: Unable to power the vms
Key: CLOUDSTACK-8392
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8392
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Reporter: Nagaraju
HI
After configuring cloudsatck ,am unable to power the vms ,below are the log details.
2015-04-20 15:12:53,756 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 2-33409: Sending Seq 2-33409: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-04-20 15:12:56,464 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-a1de837f) Checking if any host reservation can be released ...
2015-04-20 15:12:56,471 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-a1de837f) Cannot release reservation, Found 1 VMs Running on host 6
2015-04-20 15:12:56,476 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-a1de837f) Cannot release reservation, Found 2 VMs Running on host 7
2015-04-20 15:12:56,476 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-a1de837f) Done running HostReservationReleaseChecker ...
2015-04-20 15:12:56,719 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-dbc2a146) Found 0 routers to update status.
2015-04-20 15:12:56,720 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-dbc2a146) Found 0 networks to update RvR status.
2015-04-20 15:12:56,830 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Running Capacity Checker ...
2015-04-20 15:12:56,830 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) recalculating system capacity
2015-04-20 15:12:56,830 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Executing cpu/ram capacity update
2015-04-20 15:12:56,834 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) Found 1 VMs on host 6
2015-04-20 15:12:56,836 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) Found 0 VM, not running on host 6
2015-04-20 15:12:56,837 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) No need to calibrate cpu capacity, host:6 usedCpu: 500 reservedCpu: 0
2015-04-20 15:12:56,837 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) No need to calibrate memory capacity, host:6 usedMem: 134217728 reservedMem: 0
2015-04-20 15:12:56,843 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) Found 2 VMs on host 7
2015-04-20 15:12:56,847 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) Found 0 VM, not running on host 7
2015-04-20 15:12:56,848 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) No need to calibrate cpu capacity, host:7 usedCpu: 1000 reservedCpu: 0
2015-04-20 15:12:56,849 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-16e55d88) No need to calibrate memory capacity, host:7 usedMem: 1610612736 reservedMem: 0
2015-04-20 15:12:56,850 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Done executing cpu/ram capacity update
2015-04-20 15:12:56,850 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Executing storage capacity update
2015-04-20 15:12:56,855 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-16e55d88) Found storage pool primary of type NetworkFilesystem with overprovisioning factor 2
2015-04-20 15:12:56,856 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-16e55d88) Total over provisioned capacity calculated is 2 * 365524156416
2015-04-20 15:12:56,856 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-16e55d88) Total over provisioned capacity of the pool primary id: 1 is 731048312832
2015-04-20 15:12:56,857 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-16e55d88) Successfully set Capacity - 731048312832 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1
2015-04-20 15:12:56,857 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Done executing storage capacity update
2015-04-20 15:12:56,857 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Executing capacity updates for public ip and Vlans
2015-04-20 15:12:56,875 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Done capacity updates for public ip and Vlans
2015-04-20 15:12:56,875 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Executing capacity updates for private ip
2015-04-20 15:12:56,881 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Done executing capacity updates for private ip
2015-04-20 15:12:56,881 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Done recalculating system capacity
2015-04-20 15:12:56,897 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-16e55d88) Done running Capacity Checker ...
2015-04-20 15:13:01,894 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-2fde5739) Zone 1 is ready to launch console proxy
2015-04-20 15:13:02,023 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-c42d0f73) Zone 1 is ready to launch secondary storage VM
2015-04-20 15:13:03,752 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 2-33410: Processing Seq 2-33410: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-20 15:13:03,754 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 2-33410: Sending Seq 2-33410: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
^C
[root@ctmgt ~]#
[root@ctmgt ~]# tail -f /var/log/cloudstack/management/management-server.log
2015-04-20 15:14:27,383 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Planner need not allocate a pool for this volume since its READY
2015-04-20 15:14:27,383 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2015-04-20 15:14:27,383 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Checking if host: 7 can access any suitable storage pool for volume: DATADISK
2015-04-20 15:14:27,384 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Host: 7 can access pool: 1
2015-04-20 15:14:27,384 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Checking if host: 7 can access any suitable storage pool for volume: ROOT
2015-04-20 15:14:27,385 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Host: 7 can access pool: 1
2015-04-20 15:14:27,385 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Found a potential host id: 7 name: ctkvm1 and associated storage pools for this VM
2015-04-20 15:14:27,386 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) 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(7)-Storage()]
2015-04-20 15:14:27,395 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Sync job-218 execution on object VmWorkJobQueue.5
2015-04-20 15:14:27,396 WARN [c.c.u.d.Merovingian2] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Was unable to find lock for the key vm_instance5 and thread id 38970364
2015-04-20 15:14:28,759 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-33420: Processing Seq 2-33420: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-20 15:14:28,763 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-33420: Sending Seq 2-33420: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-04-20 15:14:29,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-1dd936d4) Execute sync-queue item: SyncQueueItemVO {id:10, queueId: 4, contentType: AsyncJob, contentId: 218, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Mon Apr 20 15:14:27 IST 2015}
2015-04-20 15:14:29,045 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-1dd936d4) Schedule queued job-218
2015-04-20 15:14:29,051 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Add job-218 into job monitoring
2015-04-20 15:14:29,052 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Executing AsyncJobVO {id:218, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFzcQB-AAgAAAAAAAAAB3BwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 20 15:14:27 IST 2015}
2015-04-20 15:14:29,053 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Run VM work job: com.cloud.vm.VmWorkStart for VM 5, job origin: 217
2015-04-20 15:14:29,055 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":7,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":5,"handlerName":"VirtualMachineManagerImpl"}
2015-04-20 15:14:29,068 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 3 new host id: null host id before state transition: null
2015-04-20 15:14:29,068 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Successfully transitioned to start state for VM[User|i-2-5-VM] reservation id = bcd4661c-78d7-4f01-8d2d-1b634dd70463
2015-04-20 15:14:29,071 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Trying to deploy VM, vm has dcId: 1 and podId: 1
2015-04-20 15:14:29,071 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 7, poolId: null
2015-04-20 15:14:29,071 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Deploy avoids pods: null, clusters: null, hosts: null
2015-04-20 15:14:29,076 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Root volume is ready, need to place VM in volume's cluster
2015-04-20 15:14:29,086 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Deploy avoids pods: [], clusters: [], hosts: []
2015-04-20 15:14:29,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5d93a9de
2015-04-20 15:14:29,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2015-04-20 15:14:29,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Is ROOT volume READY (pool already allocated)?: Yes
2015-04-20 15:14:29,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 7
2015-04-20 15:14:29,089 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2015-04-20 15:14:29,093 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Checking suitable pools for volume (Id, Type): (5,ROOT)
2015-04-20 15:14:29,093 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Volume has pool already allocated, checking if pool can be reused, poolId: 1
2015-04-20 15:14:29,094 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Planner need not allocate a pool for this volume since its READY
2015-04-20 15:14:29,095 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Checking suitable pools for volume (Id, Type): (6,DATADISK)
2015-04-20 15:14:29,095 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Volume has pool already allocated, checking if pool can be reused, poolId: 1
2015-04-20 15:14:29,096 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Planner need not allocate a pool for this volume since its READY
2015-04-20 15:14:29,096 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2015-04-20 15:14:29,097 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Checking if host: 7 can access any suitable storage pool for volume: DATADISK
2015-04-20 15:14:29,098 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Host: 7 can access pool: 1
2015-04-20 15:14:29,098 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Checking if host: 7 can access any suitable storage pool for volume: ROOT
2015-04-20 15:14:29,100 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Host: 7 can access pool: 1
2015-04-20 15:14:29,101 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Found a potential host id: 7 name: ctkvm1 and associated storage pools for this VM
2015-04-20 15:14:29,101 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) 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(7)-Storage()]
2015-04-20 15:14:29,101 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Deployment found - P0=VM[User|i-2-5-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(7)-Storage()]
2015-04-20 15:14:29,112 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 3 new host id: 7 host id before state transition: null
2015-04-20 15:14:29,121 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-20 15:14:29,121 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) We are allocating VM, increasing the used capacity of this host:7
2015-04-20 15:14:29,121 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Current Used CPU: 1000 , Free CPU:20328 ,Requested CPU: 1000
2015-04-20 15:14:29,121 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Current Used RAM: 1610612736 , Free RAM:19347582976 ,Requested RAM: 1073741824
2015-04-20 15:14:29,121 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) CPU STATS after allocation: for host: 7, old used: 1000, old reserved: 0, actual total: 21328, total with overprovisioning: 21328; new used:2000, reserved:0; requested cpu:1000,alloc_from_last:false
2015-04-20 15:14:29,121 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) RAM STATS after allocation: for host: 7, old used: 1610612736, old reserved: 0, total: 20958195712; new used: 2684354560, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2015-04-20 15:14:29,124 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) VM is being created in podId: 1
2015-04-20 15:14:29,134 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Network id=204 is already implemented
2015-04-20 15:14:29,145 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Service SecurityGroup is not supported in the network id=204
2015-04-20 15:14:29,149 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Changing active number of nics for network id=204 on 1
2015-04-20 15:14:29,155 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Asking VirtualRouter to prepare for Nic[12-5-null-10.209.114.149]
2015-04-20 15:14:29,171 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Lock is acquired for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2015-04-20 15:14:29,175 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Lock is released for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2015-04-20 15:14:29,183 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Service SecurityGroup is not supported in the network id=204
2015-04-20 15:14:29,199 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Service SecurityGroup is not supported in the network id=204
2015-04-20 15:14:29,205 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Applying dhcp entry in network Ntwk[6bd20089-c33d-44df-8e49-52b965ec66e0|Guest|7]
2015-04-20 15:14:29,227 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Seq 6-9188469139742660882: Sending { Cmd , MgmtId: 345050277750, via: 6(ctkvm2), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:be:64:00:00:0d","vmIpAddress":"10.209.114.149","vmName":"windows-7","defaultRouter":"10.209.127.254","defaultDns":"10.209.114.148","duid":"00:03:00:01:06:be:64:00:00:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.209.114.148","router.ip":"169.254.1.238","router.name":"r-4-VM"},"wait":0}}] }
2015-04-20 15:14:29,959 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) Ping from 6
2015-04-20 15:14:29,959 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) Process host VM state report from ping process. host: 6
2015-04-20 15:14:29,963 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) Process VM state report. host: 6, number of records in report: 1
2015-04-20 15:14:29,963 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) VM state report. host: 6, vm id: 4, power state: PowerOn
2015-04-20 15:14:29,965 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) VM power state does not change, skip DB writing. vm id: 4
2015-04-20 15:14:29,968 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) Done with process of VM state report. host: 6
2015-04-20 15:14:30,285 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-527afc83) ===START=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523070310
2015-04-20 15:14:30,296 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-527afc83 ctx-6b31c348) ===END=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523070310
2015-04-20 15:14:30,661 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 7
2015-04-20 15:14:30,661 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Process host VM state report from ping process. host: 7
2015-04-20 15:14:30,667 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Process VM state report. host: 7, number of records in report: 2
2015-04-20 15:14:30,667 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) VM state report. host: 7, vm id: 2, power state: PowerOn
2015-04-20 15:14:30,668 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) VM power state does not change, skip DB writing. vm id: 2
2015-04-20 15:14:30,668 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) VM state report. host: 7, vm id: 46, power state: PowerOn
2015-04-20 15:14:30,670 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) VM power state does not change, skip DB writing. vm id: 46
2015-04-20 15:14:30,672 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Run missing VM report. current time: 1429523070672
2015-04-20 15:14:30,673 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Detected missing VM. host: 7, vm id: 5, power state: PowerReportMissing, last state update: 1429523069000
2015-04-20 15:14:30,673 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) vm id: 5 - time since last state update(1672ms) has not passed graceful period yet
2015-04-20 15:14:30,673 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Done with process of VM state report. host: 7
2015-04-20 15:14:31,904 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-b71d9d09) Zone 1 is ready to launch console proxy
2015-04-20 15:14:32,031 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-1c529b01) Zone 1 is ready to launch secondary storage VM
2015-04-20 15:14:33,287 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-9eb039b0) ===START=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523073312
2015-04-20 15:14:33,308 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-9eb039b0 ctx-9aa47835) ===END=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523073312
2015-04-20 15:14:34,778 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-c7209ee7) HostStatsCollector is running...
2015-04-20 15:14:35,370 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-c7209ee7) Seq 6-9188469139742660883: Received: { Ans: , MgmtId: 345050277750, via: 6, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2015-04-20 15:14:35,962 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-c7209ee7) Seq 7-2699907976608618604: Received: { Ans: , MgmtId: 345050277750, via: 7, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2015-04-20 15:14:36,244 DEBUG [c.c.a.t.Request] (AgentManager-Handler-7:null) Seq 6-9188469139742660882: Processing: { Ans: , MgmtId: 345050277750, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"","wait":0}}] }
2015-04-20 15:14:36,244 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Seq 6-9188469139742660882: Received: { Ans: , MgmtId: 345050277750, via: 6, Ver: v1, Flags: 10, { Answer } }
2015-04-20 15:14:36,244 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is unreachable: Unable to apply dhcp entry on router
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:4018)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:3134)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy189.applyDhcpEntry(Unknown Source)
at com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:905)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1221)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1343)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1279)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:986)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(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:460)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-04-20 15:14:36,251 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Cleaning up resources for the vm VM[User|i-2-5-VM] in Starting state
2015-04-20 15:14:36,255 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Seq 7-2699907976608618605: Sending { Cmd , MgmtId: 345050277750, via: 7(ctkvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-5-VM","wait":0}}] }
2015-04-20 15:14:36,287 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-2c724a50) ===START=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523076310
2015-04-20 15:14:36,309 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-2c724a50 ctx-64fb2769) ===END=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523076310
2015-04-20 15:14:36,501 DEBUG [c.c.a.t.Request] (AgentManager-Handler-10:null) Seq 7-2699907976608618605: Processing: { Ans: , MgmtId: 345050277750, via: 7, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-04-20 15:14:36,501 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Seq 7-2699907976608618605: Received: { Ans: , MgmtId: 345050277750, via: 7, Ver: v1, Flags: 10, { StopAnswer } }
2015-04-20 15:14:36,509 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Changing active number of nics for network id=204 on -1
2015-04-20 15:14:36,512 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Successfully released network resources for the vm VM[User|i-2-5-VM]
2015-04-20 15:14:36,512 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Successfully cleanued up resources for the vm VM[User|i-2-5-VM] in Starting state
2015-04-20 15:14:36,515 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Root volume is ready, need to place VM in volume's cluster
2015-04-20 15:14:36,525 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Deploy avoids pods: [], clusters: [], hosts: [7]
2015-04-20 15:14:36,525 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning.
2015-04-20 15:14:36,535 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 3 new host id: null host id before state transition: 7
2015-04-20 15:14:36,542 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-20 15:14:36,542 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Hosts's actual total RAM: 20958195712 and RAM after applying overprovisioning: 20958195712
2015-04-20 15:14:36,542 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) release cpu from host: 7, old used: 2000,reserved: 0, actual total: 21328, total with overprovisioning: 21328; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-20 15:14:36,542 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) release mem from host: 7, old used: 2684354560,reserved: 0, total: 20958195712; new used: 1610612736,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-20 15:14:36,551 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-5-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-20 15:14:36,551 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218 ctx-19adf413) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-5-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-20 15:14:36,551 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 5, job origin: 217
2015-04-20 15:14:36,551 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Unable to complete AsyncJobVO {id:218, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFzcQB-AAgAAAAAAAAAB3BwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 20 15:14:27 IST 2015}, job origin:217
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-5-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:5195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(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:460)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-04-20 15:14:36,555 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Complete async job-218, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAT0pvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItNS1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfd0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAcxxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2015-04-20 15:14:36,566 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Done executing com.cloud.vm.VmWorkStart for job-218
2015-04-20 15:14:36,582 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Sync queue (4) is currently empty
2015-04-20 15:14:36,584 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-10:ctx-fe9195ad job-217/job-218) Remove job-218 from job monitoring
2015-04-20 15:14:36,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Sync job-219 execution on object VmWorkJobQueue.5
2015-04-20 15:14:36,592 WARN [c.c.u.d.Merovingian2] (API-Job-Executor-5:ctx-c579ee6e job-217 ctx-6757eccd) Was unable to find lock for the key vm_instance5 and thread id 38970364
2015-04-20 15:14:37,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-bdfac2c0) Execute sync-queue item: SyncQueueItemVO {id:11, queueId: 4, contentType: AsyncJob, contentId: 219, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Mon Apr 20 15:14:36 IST 2015}
2015-04-20 15:14:37,044 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-bdfac2c0) Schedule queued job-219
2015-04-20 15:14:37,053 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Add job-219 into job monitoring
2015-04-20 15:14:37,055 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Executing AsyncJobVO {id:219, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 20 15:14:36 IST 2015}
2015-04-20 15:14:37,057 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Run VM work job: com.cloud.vm.VmWorkStart for VM 5, job origin: 217
2015-04-20 15:14:37,061 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":5,"handlerName":"VirtualMachineManagerImpl"}
2015-04-20 15:14:37,071 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 3 new host id: null host id before state transition: null
2015-04-20 15:14:37,071 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Successfully transitioned to start state for VM[User|i-2-5-VM] reservation id = dfe7f68d-7688-4912-a291-2f0fe797847b
2015-04-20 15:14:37,074 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Trying to deploy VM, vm has dcId: 1 and podId: 1
2015-04-20 15:14:37,074 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Deploy avoids pods: null, clusters: null, hosts: null
2015-04-20 15:14:37,078 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Root volume is ready, need to place VM in volume's cluster
2015-04-20 15:14:37,078 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Vol[5|vm=5|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2015-04-20 15:14:37,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Deploy avoids pods: [], clusters: [], hosts: []
2015-04-20 15:14:37,089 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5d93a9de
2015-04-20 15:14:37,089 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2015-04-20 15:14:37,089 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Is ROOT volume READY (pool already allocated)?: Yes
2015-04-20 15:14:37,089 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) This VM has last host_id specified, trying to choose the same host: 3
2015-04-20 15:14:37,091 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) The last host of this VM cannot be found
2015-04-20 15:14:37,091 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Cannot choose the last host to deploy this VM
2015-04-20 15:14:37,091 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Searching resources only under specified Cluster: 1
2015-04-20 15:14:37,100 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Checking resources in Cluster: 1 under Pod: 1
2015-04-20 15:14:37,100 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2015-04-20 15:14:37,104 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-7-Routing], Host[-6-Routing]]
2015-04-20 15:14:37,111 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-7-Routing], Host[-6-Routing]]
2015-04-20 15:14:37,112 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2015-04-20 15:14:37,120 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Host: 7 has cpu capability (cpu:8, speed:2666) to support requested CPU: 1 and requested speed: 1000
2015-04-20 15:14:37,120 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2015-04-20 15:14:37,123 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-20 15:14:37,123 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Free CPU: 20328 , Requested CPU: 1000
2015-04-20 15:14:37,123 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Free RAM: 19347582976 , Requested RAM: 1073741824
2015-04-20 15:14:37,123 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-04-20 15:14:37,124 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 1000, reserved: 0, actual total: 21328, total with overprovisioning: 21328; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-04-20 15:14:37,124 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used: 1610612736, reserved: 0, total: 20958195712; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-04-20 15:14:37,124 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
2015-04-20 15:14:37,132 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Host: 6 has cpu capability (cpu:8, speed:2666) to support requested CPU: 1 and requested speed: 1000
2015-04-20 15:14:37,132 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Checking if host: 6 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2015-04-20 15:14:37,135 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-20 15:14:37,135 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Free CPU: 20828 , Requested CPU: 1000
2015-04-20 15:14:37,135 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Free RAM: 33531613184 , Requested RAM: 1073741824
2015-04-20 15:14:37,135 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-04-20 15:14:37,136 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 6, used: 500, reserved: 0, actual total: 21328, total with overprovisioning: 21328; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-04-20 15:14:37,136 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 6, used: 134217728, reserved: 0, total: 33665830912; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-04-20 15:14:37,136 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Found a suitable host, adding to list: 6
2015-04-20 15:14:37,136 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f FirstFitRoutingAllocator) Host Allocator returning 2 suitable hosts
2015-04-20 15:14:37,139 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Checking suitable pools for volume (Id, Type): (5,ROOT)
2015-04-20 15:14:37,139 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Volume has pool already allocated, checking if pool can be reused, poolId: 1
2015-04-20 15:14:37,140 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Planner need not allocate a pool for this volume since its READY
2015-04-20 15:14:37,141 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Checking suitable pools for volume (Id, Type): (6,DATADISK)
2015-04-20 15:14:37,141 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Volume has pool already allocated, checking if pool can be reused, poolId: 1
2015-04-20 15:14:37,142 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Planner need not allocate a pool for this volume since its READY
2015-04-20 15:14:37,142 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2015-04-20 15:14:37,142 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Checking if host: 7 can access any suitable storage pool for volume: DATADISK
2015-04-20 15:14:37,144 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Host: 7 can access pool: 1
2015-04-20 15:14:37,144 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Checking if host: 7 can access any suitable storage pool for volume: ROOT
2015-04-20 15:14:37,145 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Host: 7 can access pool: 1
2015-04-20 15:14:37,146 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Found a potential host id: 7 name: ctkvm1 and associated storage pools for this VM
2015-04-20 15:14:37,148 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) 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(7)-Storage()]
2015-04-20 15:14:37,148 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Deployment found - P0=VM[User|i-2-5-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(7)-Storage()]
2015-04-20 15:14:37,159 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 3 new host id: 7 host id before state transition: null
2015-04-20 15:14:37,166 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-20 15:14:37,166 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) We are allocating VM, increasing the used capacity of this host:7
2015-04-20 15:14:37,166 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Current Used CPU: 1000 , Free CPU:20328 ,Requested CPU: 1000
2015-04-20 15:14:37,167 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Current Used RAM: 1610612736 , Free RAM:19347582976 ,Requested RAM: 1073741824
2015-04-20 15:14:37,167 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) CPU STATS after allocation: for host: 7, old used: 1000, old reserved: 0, actual total: 21328, total with overprovisioning: 21328; new used:2000, reserved:0; requested cpu:1000,alloc_from_last:false
2015-04-20 15:14:37,167 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) RAM STATS after allocation: for host: 7, old used: 1610612736, old reserved: 0, total: 20958195712; new used: 2684354560, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2015-04-20 15:14:37,169 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) VM is being created in podId: 1
2015-04-20 15:14:37,178 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Network id=204 is already implemented
2015-04-20 15:14:37,188 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Service SecurityGroup is not supported in the network id=204
2015-04-20 15:14:37,191 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Changing active number of nics for network id=204 on 1
2015-04-20 15:14:37,197 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Asking VirtualRouter to prepare for Nic[12-5-null-10.209.114.149]
2015-04-20 15:14:37,208 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Lock is acquired for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2015-04-20 15:14:37,212 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Lock is released for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2015-04-20 15:14:37,219 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Service SecurityGroup is not supported in the network id=204
2015-04-20 15:14:37,234 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Service SecurityGroup is not supported in the network id=204
2015-04-20 15:14:37,240 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Applying dhcp entry in network Ntwk[6bd20089-c33d-44df-8e49-52b965ec66e0|Guest|7]
2015-04-20 15:14:37,255 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Seq 6-9188469139742660884: Sending { Cmd , MgmtId: 345050277750, via: 6(ctkvm2), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:be:64:00:00:0d","vmIpAddress":"10.209.114.149","vmName":"windows-7","defaultRouter":"10.209.127.254","defaultDns":"10.209.114.148","duid":"00:03:00:01:06:be:64:00:00:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.209.114.148","router.ip":"169.254.1.238","router.name":"r-4-VM"},"wait":0}}] }
2015-04-20 15:14:38,760 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-33421: Processing Seq 2-33421: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-20 15:14:38,764 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-33421: Sending Seq 2-33421: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-04-20 15:14:39,304 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-49e773af) ===START=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523079315
2015-04-20 15:14:39,324 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-49e773af ctx-9e5ede1b) ===END=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523079315
2015-04-20 15:14:39,490 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 2
2015-04-20 15:14:39,514 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 8
2015-04-20 15:14:42,296 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-60ba378d) ===START=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523082321
2015-04-20 15:14:42,316 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-60ba378d ctx-714f9b4d) ===END=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523082321
2015-04-20 15:14:44,269 DEBUG [c.c.a.t.Request] (AgentManager-Handler-13:null) Seq 6-9188469139742660884: Processing: { Ans: , MgmtId: 345050277750, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"","wait":0}}] }
2015-04-20 15:14:44,270 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Seq 6-9188469139742660884: Received: { Ans: , MgmtId: 345050277750, via: 6, Ver: v1, Flags: 10, { Answer } }
2015-04-20 15:14:44,270 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is unreachable: Unable to apply dhcp entry on router
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:4018)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:3134)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy189.applyDhcpEntry(Unknown Source)
at com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:905)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1221)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1343)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1279)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:986)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(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:460)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-04-20 15:14:44,275 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Cleaning up resources for the vm VM[User|i-2-5-VM] in Starting state
2015-04-20 15:14:44,279 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Seq 7-2699907976608618606: Sending { Cmd , MgmtId: 345050277750, via: 7(ctkvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-5-VM","wait":0}}] }
2015-04-20 15:14:44,525 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) Seq 7-2699907976608618606: Processing: { Ans: , MgmtId: 345050277750, via: 7, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-04-20 15:14:44,526 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Seq 7-2699907976608618606: Received: { Ans: , MgmtId: 345050277750, via: 7, Ver: v1, Flags: 10, { StopAnswer } }
2015-04-20 15:14:44,536 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Changing active number of nics for network id=204 on -1
2015-04-20 15:14:44,539 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Successfully released network resources for the vm VM[User|i-2-5-VM]
2015-04-20 15:14:44,539 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Successfully cleanued up resources for the vm VM[User|i-2-5-VM] in Starting state
2015-04-20 15:14:44,542 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Root volume is ready, need to place VM in volume's cluster
2015-04-20 15:14:44,542 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Vol[5|vm=5|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2015-04-20 15:14:44,552 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Deploy avoids pods: [], clusters: [], hosts: [7]
2015-04-20 15:14:44,552 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning.
2015-04-20 15:14:44,562 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Deploy avoids pods: [], clusters: [], hosts: [7]
2015-04-20 15:14:44,562 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning.
2015-04-20 15:14:44,571 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 3 new host id: null host id before state transition: 7
2015-04-20 15:14:44,577 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-20 15:14:44,577 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Hosts's actual total RAM: 20958195712 and RAM after applying overprovisioning: 20958195712
2015-04-20 15:14:44,578 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) release cpu from host: 7, old used: 2000,reserved: 0, actual total: 21328, total with overprovisioning: 21328; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-20 15:14:44,578 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) release mem from host: 7, old used: 2684354560,reserved: 0, total: 20958195712; new used: 1610612736,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-20 15:14:44,586 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-5-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-20 15:14:44,589 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219 ctx-73298d8f) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-5-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-20 15:14:44,590 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 5, job origin: 217
2015-04-20 15:14:44,590 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Unable to complete AsyncJobVO {id:219, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 20 15:14:36 IST 2015}, job origin:217
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-5-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:5195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(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:460)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-04-20 15:14:44,594 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Complete async job-219, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAT0pvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItNS1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfd0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAcxxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2015-04-20 15:14:44,605 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Done executing com.cloud.vm.VmWorkStart for job-219
2015-04-20 15:14:44,619 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Sync queue (4) is currently empty
2015-04-20 15:14:44,620 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-11:ctx-ab94634b job-217/job-219) Remove job-219 from job monitoring
2015-04-20 15:14:44,625 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-5:ctx-c579ee6e job-217) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin
java.lang.RuntimeException: Job failed due to exception Unable to create a deployment for VM[User|i-2-5-VM]
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(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:460)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-04-20 15:14:44,626 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217) Complete async job-217, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Job failed due to exception Unable to create a deployment for VM[User|i-2-5-VM]"}
2015-04-20 15:14:44,633 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-5:ctx-c579ee6e job-217) Done executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin for job-217
2015-04-20 15:14:44,648 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-5:ctx-c579ee6e job-217) Remove job-217 from job monitoring
2015-04-20 15:14:45,293 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-4218a0ef) ===START=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523085318
2015-04-20 15:14:45,313 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-4218a0ef ctx-cd22cceb) ===END=== 172.21.8.92 -- GET command=queryAsyncJobResult&jobId=fea77966-4f2d-4a13-a2d5-3c8e65d6f012&response=json&sessionkey=9cJarYR91BmpekRgQcBV16Sw2i4%3D&_=1429523085318
2015-04-20 15:14:48,761 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 2-33423: Processing Seq 2-33423: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-20 15:14:48,764 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 2-33423: Sending Seq 2-33423: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-04-20 15:14:49,370 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-2afa5e4c) AutoScaling Monitor is running...
^C
[root@ctmgt ~]#
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)