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)
