[
https://issues.apache.org/jira/browse/CLOUDSTACK-8442?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Daan Hoogland updated CLOUDSTACK-8442:
--------------------------------------
Fix Version/s: (was: 4.5.1)
4.5.2
> [VMWARE] VM Cannot be powered on after restoreVirtualMachine
> -------------------------------------------------------------
>
> Key: CLOUDSTACK-8442
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8442
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Management Server
> Affects Versions: 4.5.1
> Environment: ACS 4.5.1, CentOS 6.6
> vSphere 5.5 with NFS for Primary Storage
> Reporter: ilya musayev
> Labels: vmware
> Fix For: 4.5.2
>
>
> While restoreVirtualMachine call is successful, when you try to power on the
> VM, vSphere fails to find and use proper ROOT volume.
> To recreate this issue, create a project, then deploy a VM with template X in
> same project, then use restoreVirtualMachine API call to alter the ROOT disk
> and attempt to power on..
> Same errors are seen in vcenter...
> 2015-05-05 06:38:43,962 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (API-Job-Executor-54:ctx-a7142d34 job-8077) Add job-8077 into job monitoring
> 2015-05-05 06:38:43,969 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (catalina-exec-7:ctx-6e032e40 ctx-8bb374e0) submit async job-8077, details:
> AsyncJobVO {id:8077, userId: 2, accountId: 2, instanceType: VirtualMachine,
> instanceId: 1350, cmd:
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo:
> {"id":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","response":"json","sessionkey":"EfTBAqeGH5ivA9E7W1q7gcYXWgI\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","projectid":"98b2e16f-1e4f-4b19-866b-154ef5aad53d","_":"1430807923839","uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","ctxAccountId":"2","ctxStartEventId":"17421"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 345049223690, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: null}
> 2015-05-05 06:38:43,978 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077) Executing AsyncJobVO {id:8077,
> userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 1350, cmd:
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo:
> {"id":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","response":"json","sessionkey":"EfTBAqeGH5ivA9E7W1q7gcYXWgI\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","projectid":"98b2e16f-1e4f-4b19-866b-154ef5aad53d","_":"1430807923839","uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","ctxAccountId":"2","ctxStartEventId":"17421"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 345049223690, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: null}
> 2015-05-05 06:38:43,990 WARN [c.c.a.d.ParamGenericValidationWorker]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Received unknown
> parameters for command startVirtualMachine. Unknown parameters : projectid
> 2015-05-05 06:38:44,020 DEBUG [c.c.n.NetworkModelImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:44,025 DEBUG [c.c.n.NetworkModelImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:44,045 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Deploy avoids pods:
> [], clusters: [], hosts: []
> 2015-05-05 06:38:44,046 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) DeploymentPlanner
> allocation algorithm: com.cloud.deploy.FirstFitPlanner@49361de4
> 2015-05-05 06:38:44,046 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Trying to allocate a
> host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 100,
> requested ram: 2147483648
> 2015-05-05 06:38:44,047 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Is ROOT volume READY
> (pool already allocated)?: No
> 2015-05-05 06:38:44,047 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) This VM has last
> host_id specified, trying to choose the same host: 5
> 2015-05-05 06:38:44,055 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking if host: 5
> has enough capacity for requested CPU: 100 and requested RAM: 2147483648 ,
> cpuOverprovisioningFactor: 1.0
> 2015-05-05 06:38:44,058 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Hosts's actual total
> CPU: 70208 and CPU after applying overprovisioning: 70208
> 2015-05-05 06:38:44,058 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) We need to allocate
> to the last host again, so checking if there is enough reserved capacity
> 2015-05-05 06:38:44,058 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Reserved CPU: 100 ,
> Requested CPU: 100
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Reserved RAM:
> 2147483648 , Requested RAM: 2147483648
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Host has enough CPU
> and RAM available
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) STATS: Can alloc CPU
> from host: 5, used: 6000, reserved: 100, actual total: 70208, total with
> overprovisioning: 70208; requested cpu:100,alloc_from_last_host?:true
> ,considerReservedCapacity?: true
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) STATS: Can alloc MEM
> from host: 5, used: 177704271872, reserved: 2147483648, total: 1374207606784;
> requested mem: 2147483648,alloc_from_last_host?:true
> ,considerReservedCapacity?: true
> 2015-05-05 06:38:44,061 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Host: 5 has cpu
> capability (cpu:32, speed:2194) to support requested CPU: 1 and requested
> speed: 100
> 2015-05-05 06:38:44,061 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) The last host of
> this VM is UP and has enough capacity
> 2015-05-05 06:38:44,061 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Now checking for
> suitable pools under zone: 1, pod: 1, cluster: 2
> 2015-05-05 06:38:44,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking suitable
> pools for volume (Id, Type): (1607,ROOT)
> 2015-05-05 06:38:44,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) We need to allocate
> new storagepool for this volume
> 2015-05-05 06:38:44,068 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Calling
> StoragePoolAllocators to find suitable pools
> 2015-05-05 06:38:44,070 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf)
> LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2015-05-05 06:38:44,070 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf)
> ClusterScopeStoragePoolAllocator looking for storage pool
> 2015-05-05 06:38:44,070 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Looking for pools in
> dc: 1 pod:1 cluster:2
> 2015-05-05 06:38:44,072 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Found pools matching
> tags: [Pool[5|NetworkFilesystem]]
> 2015-05-05 06:38:44,075 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking if storage
> pool is suitable, name: null ,poolId: 5
> 2015-05-05 06:38:44,077 INFO [c.c.s.StorageManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Storage pool null
> (5) does not supply IOPS capacity, assuming enough capacity
> 2015-05-05 06:38:44,079 DEBUG [c.c.s.StorageManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking pool 5 for
> storage, totalSize: 8796093022208, usedBytes: 5124216307712, usedPct:
> 0.5825559478253126, disable threshold: 0.9
> 2015-05-05 06:38:44,102 DEBUG [c.c.s.StorageManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Found storage pool
> Madhouse-Dev-CIC-NFS-primary of type NetworkFilesystem with overprovisioning
> factor 6
> 2015-05-05 06:38:44,102 DEBUG [c.c.s.StorageManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Total over
> provisioned capacity calculated is 6 * 8796093022208
> 2015-05-05 06:38:44,102 DEBUG [c.c.s.StorageManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Total capacity of
> the pool Madhouse-Dev-CIC-NFS-primary id: 5 is 52776558133248
> 2015-05-05 06:38:44,103 DEBUG [c.c.s.StorageManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking pool: 5 for
> volume allocation [Vol[1607|vm=1350|ROOT]], maxSize : 52776558133248,
> totalAllocatedSize : 9007464972808, askingSize : 21474836480, allocated
> disable threshold: 0.9
> 2015-05-05 06:38:44,103 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf)
> ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2015-05-05 06:38:44,103 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Trying to find a
> potenial host and associated storage pools from the suitable host/pool lists
> for this VM
> 2015-05-05 06:38:44,103 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking if host: 5
> can access any suitable storage pool for volume: ROOT
> 2015-05-05 06:38:44,104 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Host: 5 can access
> pool: 5
> 2015-05-05 06:38:44,105 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Found a potential
> host id: 5 name: fed33-madhoused-grv06.zonex.cloudsand.com and associated
> storage pools for this VM
> 2015-05-05 06:38:44,106 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Returning Deployment
> Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:44,128 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Sync job-8078
> execution on object VmWorkJobQueue.1350
> 2015-05-05 06:38:45,743 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Add job-8078 into job
> monitoring
> 2015-05-05 06:38:45,752 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Executing AsyncJobVO
> {id:8078, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
> com.cloud.vm.VmWorkStart, cmdInfo:
> rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAFRnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJzcQB-AAgAAAAAAAAABXBwcHNxAH4ACAAAAAAAAAABcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 345049223690, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: Tue May 05 06:38:44 GMT 2015}
> 2015-05-05 06:38:45,753 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Run VM work job:
> com.cloud.vm.VmWorkStart for VM 1350, job origin: 8077
> 2015-05-05 06:38:45,754 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Execute
> VM work job:
> com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":2,"hostId":5,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":1350,"handlerName":"VirtualMachineManagerImpl"}
> 2015-05-05 06:38:45,760 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM state
> transitted from :Stopped to Starting with event: StartRequestedvm's original
> host id: 5 new host id: null host id before state transition: null
> 2015-05-05 06:38:45,761 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> Successfully transitioned to start state for VM[User|i-149-1350-VM]
> reservation id = ae870499-0ca4-4aa0-9c83-8314628bc69f
> 2015-05-05 06:38:45,766 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Trying to
> deploy VM, vm has dcId: 1 and podId: 1
> 2015-05-05 06:38:45,766 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId:
> 2, hostId: 5, poolId: null
> 2015-05-05 06:38:45,766 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Deploy
> avoids pods: null, clusters: null, hosts: null
> 2015-05-05 06:38:45,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Deploy
> avoids pods: [], clusters: [], hosts: []
> 2015-05-05 06:38:45,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> DeploymentPlanner allocation algorithm:
> com.cloud.deploy.FirstFitPlanner@49361de4
> 2015-05-05 06:38:45,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Trying to
> allocate a host and storage pools from dc:1, pod:1,cluster:2, requested cpu:
> 100, requested ram: 2147483648
> 2015-05-05 06:38:45,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Is ROOT
> volume READY (pool already allocated)?: No
> 2015-05-05 06:38:45,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> DeploymentPlan has host_id specified, choosing this host and making no checks
> on this host: 5
> 2015-05-05 06:38:45,776 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Looking
> for suitable pools for this host under zone: 1, pod: 1, cluster: 2
> 2015-05-05 06:38:45,778 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking
> suitable pools for volume (Id, Type): (1607,ROOT)
> 2015-05-05 06:38:45,778 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) We need
> to allocate new storagepool for this volume
> 2015-05-05 06:38:45,780 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Calling
> StoragePoolAllocators to find suitable pools
> 2015-05-05 06:38:45,780 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2015-05-05 06:38:45,780 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> ClusterScopeStoragePoolAllocator looking for storage pool
> 2015-05-05 06:38:45,780 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Looking
> for pools in dc: 1 pod:1 cluster:2
> 2015-05-05 06:38:45,781 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Found
> pools matching tags: [Pool[5|NetworkFilesystem]]
> 2015-05-05 06:38:45,783 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking
> if storage pool is suitable, name: null ,poolId: 5
> 2015-05-05 06:38:45,784 INFO [c.c.s.StorageManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Storage
> pool null (5) does not supply IOPS capacity, assuming enough capacity
> 2015-05-05 06:38:45,785 DEBUG [c.c.s.StorageManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking
> pool 5 for storage, totalSize: 8796093022208, usedBytes: 5124216307712,
> usedPct: 0.5825559478253126, disable threshold: 0.9
> 2015-05-05 06:38:45,796 DEBUG [c.c.s.StorageManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Found
> storage pool Madhouse-Dev-CIC-NFS-primary of type NetworkFilesystem with
> overprovisioning factor 6
> 2015-05-05 06:38:45,796 DEBUG [c.c.s.StorageManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Total
> over provisioned capacity calculated is 6 * 8796093022208
> 2015-05-05 06:38:45,796 DEBUG [c.c.s.StorageManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Total
> capacity of the pool Madhouse-Dev-CIC-NFS-primary id: 5 is 52776558133248
> 2015-05-05 06:38:45,797 DEBUG [c.c.s.StorageManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking
> pool: 5 for volume allocation [Vol[1607|vm=1350|ROOT]], maxSize :
> 52776558133248, totalAllocatedSize : 9007464972808, askingSize : 21474836480,
> allocated disable threshold: 0.9
> 2015-05-05 06:38:45,797 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2015-05-05 06:38:45,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Trying to
> find a potenial host and associated storage pools from the suitable host/pool
> lists for this VM
> 2015-05-05 06:38:45,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking
> if host: 5 can access any suitable storage pool for volume: ROOT
> 2015-05-05 06:38:45,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Host: 5
> can access pool: 5
> 2015-05-05 06:38:45,798 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Found a
> potential host id: 5 name: fed33-madhoused-grv06.zonex.cloudsand.com and
> associated storage pools for this VM
> 2015-05-05 06:38:45,798 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Returning
> Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,799 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> Deployment found - P0=VM[User|i-149-1350-VM],
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,843 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM state
> transitted from :Starting to Starting with event: OperationRetryvm's original
> host id: 5 new host id: 5 host id before state transition: null
> 2015-05-05 06:38:45,843 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM
> starting again on the last host it was stopped on
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Hosts's
> actual total CPU: 70208 and CPU after applying overprovisioning: 70208
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) We are
> allocating VM, increasing the used capacity of this host:5
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Current
> Used CPU: 6000 , Free CPU:64108 ,Requested CPU: 100
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Current
> Used RAM: 177704271872 , Free RAM:1194355851264 ,Requested RAM: 2147483648
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) We are
> allocating VM to the last host again, so adjusting the reserved capacity if
> it is not less than required
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Reserved
> CPU: 100 , Requested CPU: 100
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Reserved
> RAM: 2147483648 , Requested RAM: 2147483648
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) CPU STATS
> after allocation: for host: 5, old used: 6000, old reserved: 100, actual
> total: 70208, total with overprovisioning: 70208; new used:6100, reserved:0;
> requested cpu:100,alloc_from_last:true
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) RAM STATS
> after allocation: for host: 5, old used: 177704271872, old reserved:
> 2147483648, total: 1374207606784; new used: 179851755520, reserved: 0;
> requested mem: 2147483648,alloc_from_last:true
> 2015-05-05 06:38:45,857 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM is
> being created in podId: 1
> 2015-05-05 06:38:45,864 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Network
> id=224 is already implemented
> 2015-05-05 06:38:45,874 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:45,878 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Changing
> active number of nics for network id=224 on 1
> 2015-05-05 06:38:45,885 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Asking
> VirtualRouter to prepare for Nic[1357-1350-null-172.83.24.37]
> 2015-05-05 06:38:45,895 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Lock is
> acquired for network id 224 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(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,898 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Lock is
> released for network id 224 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(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,905 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:45,916 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:45,922 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Applying
> dhcp entry in network Ntwk[224|Guest|7]
> 2015-05-05 06:38:45,935 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 4-3564599105063748816: Sending { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:34:d2:00:11:af","vmIpAddress":"172.83.24.37","vmName":"test","defaultRouter":"172.83.24.1","defaultDns":"172.83.24.10","duid":"00:03:00:01:06:34:d2:00:11:af","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.name":"r-1017-VM","router.ip":"10.178.84.38"},"wait":0}}]
> }
> 2015-05-05 06:38:45,936 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 4-3564599105063748816: Executing: { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:34:d2:00:11:af","vmIpAddress":"172.83.24.37","vmName":"test","defaultRouter":"172.83.24.1","defaultDns":"172.83.24.10","duid":"00:03:00:01:06:34:d2:00:11:af","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.name":"r-1017-VM","router.ip":"10.178.84.38"},"wait":0}}]
> }
> 2015-05-05 06:38:45,936 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: DhcpEntryCommand) Use router's private IP for SSH
> control. IP : 10.178.84.38
> 2015-05-05 06:38:45,936 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: DhcpEntryCommand) Run command on VR: 10.178.84.38,
> script: edithosts.sh with args: -m 06:34:d2:00:11:af -4 172.83.24.37 -h test
> -d 172.83.24.1 -n 172.83.24.10
> 2015-05-05 06:38:45,936 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: DhcpEntryCommand) Return a VmwareContext from the
> idle pool: [email protected]. current pool
> size: 6, outstanding count: 8
> 2015-05-05 06:38:46,461 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: DhcpEntryCommand) edithosts.sh execution result: true
> 2015-05-05 06:38:46,461 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: DhcpEntryCommand) Recycle VmwareContext into idle
> pool: [email protected], current idle pool
> size: 7, outstanding count: 8
> 2015-05-05 06:38:46,461 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 4-3564599105063748816: Received: { Ans: , MgmtId: 345049223690, via: 4, Ver:
> v1, Flags: 10, { Answer } }
> 2015-05-05 06:38:46,489 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:46,504 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Applying
> userdata and password entry in network Ntwk[224|Guest|7]
> 2015-05-05 06:38:46,537 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 4-3564599105063748817: Sending { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}}]
> }
> 2015-05-05 06:38:46,543 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 4-3564599105063748817: Executing: { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}}]
> }
> 2015-05-05 06:38:46,543 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: SavePasswordCommand) Use router's private IP for SSH
> control. IP : 10.178.84.38
> 2015-05-05 06:38:46,543 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: SavePasswordCommand) Run command on VR: 10.178.84.38,
> script: savepassword.sh with args: -v 172.83.24.37 -p saved_password
> 2015-05-05 06:38:46,543 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: SavePasswordCommand) Return a VmwareContext from the
> idle pool: [email protected]. current pool
> size: 6, outstanding count: 8
> 2015-05-05 06:38:46,920 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: SavePasswordCommand) savepassword.sh execution
> result: true
> 2015-05-05 06:38:46,920 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: SavePasswordCommand) Recycle VmwareContext into idle
> pool: [email protected], current idle pool
> size: 6, outstanding count: 8
> 2015-05-05 06:38:46,921 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: VmDataCommand) Use router's private IP for SSH
> control. IP : 10.178.84.38
> 2015-05-05 06:38:46,921 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: VmDataCommand) Run command on VR: 10.178.84.38,
> script: vmdata.py with args: -d
> eyIxMC4xODUuMjQuMzciOltbInVzZXJkYXRhIiwidXNlci1kYXRhIixudWxsXSxbIm1ldGFkYXRhIiwic2VydmljZS1vZmZlcmluZyIsIlNtYWxsIDFDUFV4MkdCIl0sWyJtZXRhZGF0YSIsImF2YWlsYWJpbGl0eS16b25lIiwiTW9uc29vbi1EZXYtQ0lDLXpvbmUiXSxbIm1ldGFkYXRhIiwibG9jYWwtaXB2NCIsIjEwLjE4NS4yNC4zNyJdLFsibWV0YWRhdGEiLCJsb2NhbC1ob3N0bmFtZSIsInRlc3QiXSxbIm1ldGFkYXRhIiwicHVibGljLWlwdjQiLCIxMC4xODUuMjQuMzciXSxbIm1ldGFkYXRhIiwicHVibGljLWhvc3RuYW1lIixudWxsXSxbIm1ldGFkYXRhIiwiaW5zdGFuY2UtaWQiLCJiYjk1OGI1Zi1hMzc0LTRmMGEtYTdlMi1iMWVkODc3YWMwZTIiXSxbIm1ldGFkYXRhIiwidm0taWQiLCJiYjk1OGI1Zi1hMzc0LTRmMGEtYTdlMi1iMWVkODc3YWMwZTIiXSxbIm1ldGFkYXRhIiwicHVibGljLWtleXMiLG51bGxdLFsibWV0YWRhdGEiLCJjbG91ZC1pZGVudGlmaWVyIiwiQ2xvdWRTdGFjay17NjIxMGQ2YzMtYmM4Mi00MjAwLTg3M2QtOGI2NjVjYjM5YjdmfSJdXX0=
> 2015-05-05 06:38:46,921 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: VmDataCommand) Return a VmwareContext from the idle
> pool: [email protected]. current pool size: 5,
> outstanding count: 8
> 2015-05-05 06:38:47,491 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: VmDataCommand) vmdata.py execution result: true
> 2015-05-05 06:38:47,491 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-414:ctx-b48e6903 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8078, cmd: VmDataCommand) Recycle VmwareContext into idle pool:
> [email protected], current idle pool size: 7,
> outstanding count: 8
> 2015-05-05 06:38:47,492 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 4-3564599105063748817: Received: { Ans: , MgmtId: 345049223690, via: 4, Ver:
> v1, Flags: 10, { Answer, Answer } }
> 2015-05-05 06:38:47,494 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:47,497 DEBUG [o.a.c.e.o.VolumeOrchestrator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking
> if we need to prepare 1 volumes for VM[User|i-149-1350-VM]
> 2015-05-05 06:38:47,534 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) template
> 274 is already in store:2, type:Image
> 2015-05-05 06:38:47,539 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) template
> 274 is already in store:5, type:Primary
> 2015-05-05 06:38:47,563 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) copyAsync
> inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME
> 2015-05-05 06:38:47,583 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 1-2157787171463890287: Sending { Cmd , MgmtId: 345049223690, via:
> 1(fed33-madhoused-grv08.zonex.cloudsand.com), Ver: v1, Flags: 100111,
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"cd7d90f6cd963cbe8690d1050406d80f","origUrl":"http://17.161.41.9/OL6.5-AppVM-CIC-Networkable-v2.ova","uuid":"bcbcadb7-3621-4721-8bd3-4e18403d23bd","id":274,"format":"OVA","accountId":2,"checksum":"888149bbce59ffc424c8cf938bcdfe74","hvm":true,"displayText":"OL6.5-AppVM-CIC-Networkable-v2","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"274-2-f276aaee-3cde-36ea-b499-d73c1be1d2f3","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"executeInSequence":true,"options":{},"wait":0}}]
> }
> 2015-05-05 06:38:47,584 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 1-2157787171463890287: Executing: { Cmd , MgmtId: 345049223690, via:
> 1(fed33-madhoused-grv08.zonex.cloudsand.com), Ver: v1, Flags: 100111,
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"cd7d90f6cd963cbe8690d1050406d80f","origUrl":"http://17.161.41.9/OL6.5-AppVM-CIC-Networkable-v2.ova","uuid":"bcbcadb7-3621-4721-8bd3-4e18403d23bd","id":274,"format":"OVA","accountId":2,"checksum":"888149bbce59ffc424c8cf938bcdfe74","hvm":true,"displayText":"OL6.5-AppVM-CIC-Networkable-v2","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"274-2-f276aaee-3cde-36ea-b499-d73c1be1d2f3","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"executeInSequence":true,"options":{},"wait":0}}]
> }
> 2015-05-05 06:38:47,585 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-417:ctx-04dda96f fed33-madhoused-grv08.zonex.cloudsand.com,
> job-8077/job-8078, cmd: CopyCommand) Return a VmwareContext from the idle
> pool: [email protected]. current pool size: 6,
> outstanding count: 8
> 2015-05-05 06:38:47,825 INFO [c.c.s.r.VmwareStorageProcessor]
> (DirectAgent-417:ctx-04dda96f fed33-madhoused-grv08.zonex.cloudsand.com,
> job-8077/job-8078, cmd: CopyCommand) creating linked clone from template
> 2015-05-05 06:38:55,594 INFO [c.c.s.r.VmwareStorageProcessor]
> (DirectAgent-417:ctx-04dda96f fed33-madhoused-grv08.zonex.cloudsand.com,
> job-8077/job-8078, cmd: CopyCommand) Move volume out of volume-wrapper VM
> 2015-05-05 06:38:57,266 INFO [c.c.s.r.VmwareStorageProcessor]
> (DirectAgent-417:ctx-04dda96f fed33-madhoused-grv08.zonex.cloudsand.com,
> job-8077/job-8078, cmd: CopyCommand) detach disks from volume-wrapper VM
> ROOT-1350
> 2015-05-05 06:38:59,239 INFO [c.c.s.r.VmwareStorageProcessor]
> (DirectAgent-417:ctx-04dda96f fed33-madhoused-grv08.zonex.cloudsand.com,
> job-8077/job-8078, cmd: CopyCommand) destroy volume-wrapper VM ROOT-1350
> 2015-05-05 06:39:00,607 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-417:ctx-04dda96f fed33-madhoused-grv08.zonex.cloudsand.com,
> job-8077/job-8078, cmd: CopyCommand) Folder i-149-1350-VM does not exist on
> datastore
> 2015-05-05 06:39:00,608 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-417:ctx-04dda96f fed33-madhoused-grv08.zonex.cloudsand.com,
> job-8077/job-8078, cmd: CopyCommand) Recycle VmwareContext into idle pool:
> [email protected], current idle pool size: 8,
> outstanding count: 8
> 2015-05-05 06:39:00,609 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 1-2157787171463890287: Received: { Ans: , MgmtId: 345049223690, via: 1, Ver:
> v1, Flags: 110, { CopyCmdAnswer } }
> 2015-05-05 06:39:00,665 DEBUG [c.c.h.g.VMwareGuru]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Nested
> virtualization requested, adding flag to vm configuration
> 2015-05-05 06:39:00,697 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 5-1317865840959292782: Sending { Cmd , MgmtId: 345049223690, via:
> 5(fed33-madhoused-grv06.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StartCommand":{"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle
> Enterprise Linux 6.0
> (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}}]
> }
> 2015-05-05 06:39:00,699 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 5-1317865840959292782: Executing: { Cmd , MgmtId: 345049223690, via:
> 5(fed33-madhoused-grv06.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StartCommand":{"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle
> Enterprise Linux 6.0
> (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}}]
> }
> 2015-05-05 06:39:00,701 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Executing resource StartCommand:
> {"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle
> Enterprise Linux 6.0
> (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}
> 2015-05-05 06:39:00,701 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Return a VmwareContext from the idle
> pool: [email protected]. current pool size: 7,
> outstanding count: 8
> 2015-05-05 06:39:00,853 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) find VM i-149-1350-VM on host
> 2015-05-05 06:39:00,853 INFO [c.c.h.v.m.HostMO]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) VM i-149-1350-VM not found in host cache
> 2015-05-05 06:39:00,854 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) load VM cache on host
> 2015-05-05 06:39:00,886 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) VM i-149-1350-VM already exists, tear
> down devices for reconfiguration
> 2015-05-05 06:39:03,781 WARN [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Guest OS mapping name is not set for
> guest os: Oracle Enterprise Linux 6.0 (64-bit)
> 2015-05-05 06:39:04,125 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Nested Virtualization enabled in
> configuration, checking hypervisor capability
> 2015-05-05 06:39:04,160 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Hypervisor supports nested
> virtualization, enabling for VM i-149-1350-VM
> 2015-05-05 06:39:04,200 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare ISO volume at existing device
> {"key":3000,"deviceInfo":{"label":"CD/DVD drive 1","summary":"Remote
> device"},"backing":{"exclusive":false,"deviceName":""},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":0}
> 2015-05-05 06:39:04,244 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Found existing disk info from volume
> path: ROOT-1350
> 2015-05-05 06:39:04,244 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Chose disk controller based on existing
> information: scsi0:0
> 2015-05-05 06:39:04,255 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare volume at new device
> {"capacityInKB":0,"key":-2,"backing":{"diskMode":"persistent","parent":{"diskMode":"persistent","fileName":"[b0d3033166f3361abea8b85e0efe4055]
>
> c3eb55bcaea139e5a4bfa1cc265e3255/c3eb55bcaea139e5a4bfa1cc265e3255.vmdk","datastore":{"value":"datastore-823","type":"Datastore"}},"fileName":"[b0d3033166f3361abea8b85e0efe4055]
>
> test/ROOT-1350.vmdk","datastore":{"value":"datastore-823","type":"Datastore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":1000,"unitNumber":0}
> 2015-05-05 06:39:04,255 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) VM i-149-1350-VM will be started with
> NIC device type: Vmxnet3
> 2015-05-05 06:39:04,256 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare NIC device based on NicTO:
> {"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}
> 2015-05-05 06:39:04,265 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare network on vmwaresvs vSwitch0
> with name prefix: cloud.guest
> 2015-05-05 06:39:04,454 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv03.zonex.cloudsand.com
> 2015-05-05 06:39:04,589 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:04,599 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv04.zonex.cloudsand.com
> 2015-05-05 06:39:05,001 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:05,010 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv08.zonex.cloudsand.com
> 2015-05-05 06:39:05,416 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:05,427 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv07.zonex.cloudsand.com
> 2015-05-05 06:39:05,585 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:05,602 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv05.zonex.cloudsand.com
> 2015-05-05 06:39:05,787 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:05,788 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:05,788 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Preparing NIC device on network
> cloud.guest.1151.200.1-vSwitch0
> 2015-05-05 06:39:05,789 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Prepare NIC at new device
> {"operation":"ADD","device":{"addressType":"Manual","macAddress":"06:34:d2:00:11:af","key":-3,"backing":{"network":{"value":"network-5856","type":"Network"},"deviceName":"cloud.guest.1151.200.1-vSwitch0"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":0}}
> 2015-05-05 06:39:05,789 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) find VM i-149-1350-VM on host
> 2015-05-05 06:39:05,790 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) VM i-149-1350-VM found in host cache
> 2015-05-05 06:39:06,093 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Configure VNC port for VM
> i-149-1350-VM, port: 5948, host: fed33-madhoused-grv06.zonex.cloudsand.com
> 2015-05-05 06:39:06,551 WARN [c.c.h.v.r.VmwareResource]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) StartCommand failed due to Exception:
> java.lang.RuntimeException
> java.lang.RuntimeException: File
> []/vmfs/volumes/31a4cab6-db4ef888/test/ROOT-1350.vmdk was not found
> at
> com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:335)
> at
> com.cloud.hypervisor.vmware.mo.VirtualMachineMO.configureVm(VirtualMachineMO.java:939)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:1736)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:450)
> at
> com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:302)
> 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)
> 2015-05-05 06:39:06,554 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-209:ctx-ab65bdde fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StartCommand) Recycle VmwareContext into idle pool:
> [email protected], current idle pool size: 8,
> outstanding count: 8
> 2015-05-05 06:39:06,556 DEBUG [c.c.a.t.Request]
> (DirectAgent-209:ctx-ab65bdde) Seq 5-1317865840959292782: Processing: { Ans:
> , MgmtId: 345049223690, via: 5, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle
> Enterprise Linux 6.0
> (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"result":false,"details":"StartCommand
> failed due to Exception: java.lang.RuntimeException\nMessage: File
> []/vmfs/volumes/31a4cab6-db4ef888/test/ROOT-1350.vmdk was not
> found\n","wait":0}}] }
> 2015-05-05 06:39:06,556 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 5-1317865840959292782: Received: { Ans: , MgmtId: 345049223690, via: 5, Ver:
> v1, Flags: 10, { StartAnswer } }
> 2015-05-05 06:39:06,567 INFO [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Unable to
> start VM on Host[-5-Routing] due to StartCommand failed due to Exception:
> java.lang.RuntimeException
> 2015-05-05 06:39:06,572 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Cleaning
> up resources for the vm VM[User|i-149-1350-VM] in Starting state
> 2015-05-05 06:39:06,577 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 5-1317865840959292783: Sending { Cmd , MgmtId: 345049223690, via:
> 5(fed33-madhoused-grv06.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-149-1350-VM","wait":0}}]
> }
> 2015-05-05 06:39:06,577 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 5-1317865840959292783: Executing: { Cmd , MgmtId: 345049223690, via:
> 5(fed33-madhoused-grv06.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-149-1350-VM","wait":0}}]
> }
> 2015-05-05 06:39:06,578 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-418:ctx-bf67511e fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StopCommand) Executing resource StopCommand:
> {"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-149-1350-VM","wait":0}
> 2015-05-05 06:39:06,578 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-418:ctx-bf67511e fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StopCommand) Return a VmwareContext from the idle
> pool: [email protected]. current pool size: 7,
> outstanding count: 8
> 2015-05-05 06:39:06,603 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-418:ctx-bf67511e fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StopCommand) find VM i-149-1350-VM on host
> 2015-05-05 06:39:06,603 INFO [c.c.h.v.m.HostMO]
> (DirectAgent-418:ctx-bf67511e fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StopCommand) VM i-149-1350-VM not found in host cache
> 2015-05-05 06:39:06,603 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-418:ctx-bf67511e fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StopCommand) load VM cache on host
> 2015-05-05 06:39:06,724 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-418:ctx-bf67511e fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StopCommand) VM i-149-1350-VM is already in stopped
> state
> 2015-05-05 06:39:06,725 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-418:ctx-bf67511e fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8078, cmd: StopCommand) Recycle VmwareContext into idle pool:
> [email protected], current idle pool size: 8,
> outstanding count: 8
> 2015-05-05 06:39:06,726 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq
> 5-1317865840959292783: Received: { Ans: , MgmtId: 345049223690, via: 5, Ver:
> v1, Flags: 10, { StopAnswer } }
> 2015-05-05 06:39:06,737 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Changing
> active number of nics for network id=224 on -1
> 2015-05-05 06:39:06,747 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> Successfully released network resources for the vm VM[User|i-149-1350-VM]
> 2015-05-05 06:39:06,747 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> Successfully cleanued up resources for the vm VM[User|i-149-1350-VM] in
> Starting state
> 2015-05-05 06:39:06,750 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Root
> volume is ready, need to place VM in volume's cluster
> 2015-05-05 06:39:06,768 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Deploy
> avoids pods: [], clusters: [], hosts: [5]
> 2015-05-05 06:39:06,769 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> DeploymentPlanner allocation algorithm:
> com.cloud.deploy.FirstFitPlanner@49361de4
> 2015-05-05 06:39:06,769 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Trying to
> allocate a host and storage pools from dc:1, pod:1,cluster:2, requested cpu:
> 100, requested ram: 2147483648
> 2015-05-05 06:39:06,770 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Is ROOT
> volume READY (pool already allocated)?: Yes
> 2015-05-05 06:39:06,770 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> DeploymentPlan has host_id specified, choosing this host and making no checks
> on this host: 5
> 2015-05-05 06:39:06,771 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) The
> specified host is in avoid set
> 2015-05-05 06:39:06,772 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Cannnot
> deploy to specified host, returning.
> 2015-05-05 06:39:06,795 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM state
> transitted from :Starting to Stopped with event: OperationFailedvm's original
> host id: 5 new host id: null host id before state transition: 5
> 2015-05-05 06:39:06,802 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Hosts's
> actual total CPU: 70208 and CPU after applying overprovisioning: 70208
> 2015-05-05 06:39:06,803 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Hosts's
> actual total RAM: 274841534464 and RAM after applying overprovisioning:
> 1374207606784
> 2015-05-05 06:39:06,803 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) release
> cpu from host: 5, old used: 6100,reserved: 0, actual total: 70208, total with
> overprovisioning: 70208; new used: 6000,reserved:0; movedfromreserved:
> false,moveToReserveredfalse
> 2015-05-05 06:39:06,803 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) release
> mem from host: 5, old used: 179851755520,reserved: 0, total: 1374207606784;
> new used: 177704271872,reserved:0; movedfromreserved:
> false,moveToReserveredfalse
> 2015-05-05 06:39:06,834 ERROR [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0)
> Invocation exception, caused by:
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a
> deployment for VM[User|i-149-1350-VM]Scope=interface com.cloud.dc.DataCenter;
> id=1
> 2015-05-05 06:39:06,834 INFO [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Rethrow
> exception com.cloud.exception.InsufficientServerCapacityException: Unable to
> create a deployment for VM[User|i-149-1350-VM]Scope=interface
> com.cloud.dc.DataCenter; id=1
> 2015-05-05 06:39:06,835 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Done with run of VM
> work job: com.cloud.vm.VmWorkStart for VM 1350, job origin: 8077
> 2015-05-05 06:39:06,835 ERROR [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Unable to complete
> AsyncJobVO {id:8078, userId: 2, accountId: 2, instanceType: null, instanceId:
> null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
> rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAFRnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJzcQB-AAgAAAAAAAAABXBwcHNxAH4ACAAAAAAAAAABcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 345049223690, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: Tue May 05 06:38:44 GMT 2015}, job origin:8077
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:941)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4471)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:601)
> at
> com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
> com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4627)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:537)
> 2015-05-05 06:39:06,839 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Complete async
> job-8078, jobStatus: FAILED, resultCode: 0, result:
> rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA4VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0xNDktMTM1MC1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABVzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AAp4cAAAA610ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEAABF3cQB-ABNxAH4AFHEAfgAVc3EAfgAR_____3QAJnN1bi5yZWZsZWN0LkdlbmVyYXRlZE1ldGhvZEFjY2Vzc29yNDUxcHQABmludm9rZXNxAH4AEQAAACt0AChzdW4ucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABlzcQB-ABEAAAJZdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AGXNxAH4AEQAAAGt0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JzcQB-ABEAABITcQB-ABNxAH4AFHEAfgAjc3EAfgARAAAAZ3QAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgARAAACGXQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4AEQAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4AEQAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-ABEAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgAzdAAPY2FsbFdpdGhDb250ZXh0c3EAfgARAAAANXEAfgA2cQB-ADN0AA5ydW5XaXRoQ29udGV4dHNxAH4AEQAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AL3EAfgAwc3EAfgARAAAB7nEAfgAqcQB-ACtxAH4AMHNxAH4AEQAAAdd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4ANHNxAH4AEQAAAU50ACRqYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrJFN5bmN0AA9GdXR1cmVUYXNrLmphdmF0AAhpbm5lclJ1bnNxAH4AEQAAAKZ0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrcQB-AEJxAH4AMHNxAH4AEQAABFZ0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAlt0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEhxAH4AMHNxAH4AEQAAAtJ0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AMHNyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFR4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcQB-AFMAAAAAdwQAAAAKeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFYAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlcrLxCuun53i-AgAAeHAA
> 2015-05-05 06:39:06,841 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Publish async job-8078
> complete on message bus
> 2015-05-05 06:39:06,841 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Wake up jobs related
> to job-8078
> 2015-05-05 06:39:06,841 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Update db status for
> job-8078
> 2015-05-05 06:39:06,844 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Wake up jobs joined
> with job-8078 and disjoin all subjobs created from job- 8078
> 2015-05-05 06:39:06,857 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Done executing
> com.cloud.vm.VmWorkStart for job-8078
> 2015-05-05 06:39:06,862 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Sync queue (2149) is
> currently empty
> 2015-05-05 06:39:06,864 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Remove job-8078 from
> job monitoring
> 2015-05-05 06:39:06,881 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Sync job-8079
> execution on object VmWorkJobQueue.1350
> 2015-05-05 06:39:07,751 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079) Add job-8079 into job
> monitoring
> 2015-05-05 06:39:07,766 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079) Executing AsyncJobVO
> {id:8079, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
> com.cloud.vm.VmWorkStart, cmdInfo:
> rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAFRnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 345049223690, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: Tue May 05 06:39:06 GMT 2015}
> 2015-05-05 06:39:07,768 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079) Run VM work job:
> com.cloud.vm.VmWorkStart for VM 1350, job origin: 8077
> 2015-05-05 06:39:07,770 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Execute
> VM work job:
> com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":1350,"handlerName":"VirtualMachineManagerImpl"}
> 2015-05-05 06:39:07,781 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) VM state
> transitted from :Stopped to Starting with event: StartRequestedvm's original
> host id: 5 new host id: null host id before state transition: null
> 2015-05-05 06:39:07,781 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71)
> Successfully transitioned to start state for VM[User|i-149-1350-VM]
> reservation id = 28f5ac3f-b8bf-4adf-9437-3c8000d1e59a
> 2015-05-05 06:39:07,787 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Trying to
> deploy VM, vm has dcId: 1 and podId: 1
> 2015-05-05 06:39:07,787 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Deploy
> avoids pods: null, clusters: null, hosts: null
> 2015-05-05 06:39:07,791 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Root
> volume is ready, need to place VM in volume's cluster
> 2015-05-05 06:39:07,791 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71)
> Vol[1607|vm=1350|ROOT] is READY, changing deployment plan to use this pool's
> dcId: 1 , podId: 1 , and clusterId: 2
> 2015-05-05 06:39:07,801 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Deploy
> avoids pods: [], clusters: [], hosts: []
> 2015-05-05 06:39:07,802 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71)
> DeploymentPlanner allocation algorithm:
> com.cloud.deploy.FirstFitPlanner@49361de4
> 2015-05-05 06:39:07,803 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Trying to
> allocate a host and storage pools from dc:1, pod:1,cluster:2, requested cpu:
> 100, requested ram: 2147483648
> 2015-05-05 06:39:07,803 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Is ROOT
> volume READY (pool already allocated)?: Yes
> 2015-05-05 06:39:07,803 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) This VM
> has last host_id specified, trying to choose the same host: 5
> 2015-05-05 06:39:07,811 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Checking
> if host: 5 has enough capacity for requested CPU: 100 and requested RAM:
> 2147483648 , cpuOverprovisioningFactor: 1.0
> 2015-05-05 06:39:07,814 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Hosts's
> actual total CPU: 70208 and CPU after applying overprovisioning: 70208
> 2015-05-05 06:39:07,814 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) We need
> to allocate to the last host again, so checking if there is enough reserved
> capacity
> 2015-05-05 06:39:07,814 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Reserved
> CPU: 0 , Requested CPU: 100
> 2015-05-05 06:39:07,814 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Reserved
> RAM: 0 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,814 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) STATS:
> Failed to alloc resource from host: 5 reservedCpu: 0, requested cpu: 100,
> reservedMem: 0, requested mem: 2147483648
> 2015-05-05 06:39:07,814 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Host does
> not have enough reserved CPU available, cannot allocate to this host.
> 2015-05-05 06:39:07,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) The last
> host of this VM does not have enough capacity
> 2015-05-05 06:39:07,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Cannot
> choose the last host to deploy this VM
> 2015-05-05 06:39:07,815 DEBUG [c.c.d.FirstFitPlanner]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Searching
> resources only under specified Cluster: 2
> 2015-05-05 06:39:07,826 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Checking
> resources in Cluster: 2 under Pod: 1
> 2015-05-05 06:39:07,826 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:2
> 2015-05-05 06:39:07,832 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) FirstFitAllocator has 6 hosts to check for
> allocation: [Host[-5-Routing], Host[-4-Routing], Host[-7-Routing],
> Host[-2-Routing], Host[-6-Routing], Host[-1-Routing]]
> 2015-05-05 06:39:07,847 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Found 6 hosts for allocation after prioritization:
> [Host[-5-Routing], Host[-4-Routing], Host[-7-Routing], Host[-2-Routing],
> Host[-6-Routing], Host[-1-Routing]]
> 2015-05-05 06:39:07,847 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Looking for speed=100Mhz, Ram=2048
> 2015-05-05 06:39:07,856 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host: 5 has cpu capability (cpu:32, speed:2194) to
> support requested CPU: 1 and requested speed: 100
> 2015-05-05 06:39:07,856 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Checking if host: 5 has enough capacity for
> requested CPU: 100 and requested RAM: 2147483648 , cpuOverprovisioningFactor:
> 1.0
> 2015-05-05 06:39:07,859 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Hosts's actual total CPU: 70208 and CPU after
> applying overprovisioning: 70208
> 2015-05-05 06:39:07,859 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free CPU: 64208 , Requested CPU: 100
> 2015-05-05 06:39:07,859 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free RAM: 1196503334912 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,859 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2015-05-05 06:39:07,860 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 5, used: 6000,
> reserved: 0, actual total: 70208, total with overprovisioning: 70208;
> requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,860 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 5, used:
> 177704271872, reserved: 0, total: 1374207606784; requested mem:
> 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,860 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Found a suitable host, adding to list: 5
> 2015-05-05 06:39:07,869 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host: 4 has cpu capability (cpu:32, speed:2194) to
> support requested CPU: 1 and requested speed: 100
> 2015-05-05 06:39:07,869 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Checking if host: 4 has enough capacity for
> requested CPU: 100 and requested RAM: 2147483648 , cpuOverprovisioningFactor:
> 1.0
> 2015-05-05 06:39:07,872 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Hosts's actual total CPU: 70208 and CPU after
> applying overprovisioning: 70208
> 2015-05-05 06:39:07,872 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free CPU: 63608 , Requested CPU: 100
> 2015-05-05 06:39:07,873 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free RAM: 1193282109440 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,873 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2015-05-05 06:39:07,873 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 4, used: 6600,
> reserved: 0, actual total: 70208, total with overprovisioning: 70208;
> requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,873 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 4, used:
> 180925497344, reserved: 0, total: 1374207606784; requested mem:
> 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,873 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Found a suitable host, adding to list: 4
> 2015-05-05 06:39:07,883 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host: 7 has cpu capability (cpu:32, speed:2194) to
> support requested CPU: 1 and requested speed: 100
> 2015-05-05 06:39:07,883 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for
> requested CPU: 100 and requested RAM: 2147483648 , cpuOverprovisioningFactor:
> 1.0
> 2015-05-05 06:39:07,886 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Hosts's actual total CPU: 70208 and CPU after
> applying overprovisioning: 70208
> 2015-05-05 06:39:07,886 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free CPU: 63908 , Requested CPU: 100
> 2015-05-05 06:39:07,886 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free RAM: 1220930961408 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,886 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2015-05-05 06:39:07,886 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 6300,
> reserved: 0, actual total: 70208, total with overprovisioning: 70208;
> requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,886 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used:
> 153276645376, reserved: 0, total: 1374207606784; requested mem:
> 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,887 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
> 2015-05-05 06:39:07,896 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host: 2 has cpu capability (cpu:32, speed:2194) to
> support requested CPU: 1 and requested speed: 100
> 2015-05-05 06:39:07,896 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for
> requested CPU: 100 and requested RAM: 2147483648 , cpuOverprovisioningFactor:
> 1.0
> 2015-05-05 06:39:07,899 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Hosts's actual total CPU: 70208 and CPU after
> applying overprovisioning: 70208
> 2015-05-05 06:39:07,899 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free CPU: 62608 , Requested CPU: 100
> 2015-05-05 06:39:07,899 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free RAM: 1152211484672 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,899 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2015-05-05 06:39:07,899 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 7600,
> reserved: 0, actual total: 70208, total with overprovisioning: 70208;
> requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,899 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used:
> 221996122112, reserved: 0, total: 1374207606784; requested mem:
> 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,899 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Found a suitable host, adding to list: 2
> 2015-05-05 06:39:07,908 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host: 6 has cpu capability (cpu:32, speed:2194) to
> support requested CPU: 1 and requested speed: 100
> 2015-05-05 06:39:07,909 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Checking if host: 6 has enough capacity for
> requested CPU: 100 and requested RAM: 2147483648 , cpuOverprovisioningFactor:
> 1.0
> 2015-05-05 06:39:07,911 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Hosts's actual total CPU: 70208 and CPU after
> applying overprovisioning: 70208
> 2015-05-05 06:39:07,912 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free CPU: 65308 , Requested CPU: 100
> 2015-05-05 06:39:07,912 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free RAM: 1079465476096 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,912 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2015-05-05 06:39:07,912 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 6, used: 4900,
> reserved: 0, actual total: 70208, total with overprovisioning: 70208;
> requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,912 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 6, used:
> 294742130688, reserved: 0, total: 1374207606784; requested mem:
> 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,912 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Found a suitable host, adding to list: 6
> 2015-05-05 06:39:07,921 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:32, speed:2194) to
> support requested CPU: 1 and requested speed: 100
> 2015-05-05 06:39:07,922 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for
> requested CPU: 100 and requested RAM: 2147483648 , cpuOverprovisioningFactor:
> 1.0
> 2015-05-05 06:39:07,925 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Hosts's actual total CPU: 70208 and CPU after
> applying overprovisioning: 70208
> 2015-05-05 06:39:07,925 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free CPU: 64108 , Requested CPU: 100
> 2015-05-05 06:39:07,925 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Free RAM: 828478324736 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,925 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2015-05-05 06:39:07,925 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 6100,
> reserved: 0, actual total: 70208, total with overprovisioning: 70208;
> requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,925 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used:
> 545729282048, reserved: 0, total: 1374207606784; requested mem:
> 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-05 06:39:07,925 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
> 2015-05-05 06:39:07,926 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71
> FirstFitRoutingAllocator) Host Allocator returning 6 suitable hosts
> 2015-05-05 06:39:07,929 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Checking
> suitable pools for volume (Id, Type): (1607,ROOT)
> 2015-05-05 06:39:07,929 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Volume
> has pool already allocated, checking if pool can be reused, poolId: 5
> 2015-05-05 06:39:07,931 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Planner
> need not allocate a pool for this volume since its READY
> 2015-05-05 06:39:07,931 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Trying to
> find a potenial host and associated storage pools from the suitable host/pool
> lists for this VM
> 2015-05-05 06:39:07,931 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Checking
> if host: 5 can access any suitable storage pool for volume: ROOT
> 2015-05-05 06:39:07,932 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Host: 5
> can access pool: 5
> 2015-05-05 06:39:07,934 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Found a
> potential host id: 5 name: fed33-madhoused-grv06.zonex.cloudsand.com and
> associated storage pools for this VM
> 2015-05-05 06:39:07,936 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Returning
> Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage()]
> 2015-05-05 06:39:07,936 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71)
> Deployment found - P0=VM[User|i-149-1350-VM],
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage()]
> 2015-05-05 06:39:07,972 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) VM state
> transitted from :Starting to Starting with event: OperationRetryvm's original
> host id: 5 new host id: 5 host id before state transition: null
> 2015-05-05 06:39:07,973 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) VM
> starting again on the last host it was stopped on
> 2015-05-05 06:39:07,977 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Hosts's
> actual total CPU: 70208 and CPU after applying overprovisioning: 70208
> 2015-05-05 06:39:07,977 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) We are
> allocating VM, increasing the used capacity of this host:5
> 2015-05-05 06:39:07,977 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Current
> Used CPU: 6000 , Free CPU:64208 ,Requested CPU: 100
> 2015-05-05 06:39:07,977 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Current
> Used RAM: 177704271872 , Free RAM:1196503334912 ,Requested RAM: 2147483648
> 2015-05-05 06:39:07,978 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) We are
> allocating VM to the last host again, so adjusting the reserved capacity if
> it is not less than required
> 2015-05-05 06:39:07,978 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Reserved
> CPU: 0 , Requested CPU: 100
> 2015-05-05 06:39:07,978 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Reserved
> RAM: 0 , Requested RAM: 2147483648
> 2015-05-05 06:39:07,978 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) CPU STATS
> after allocation: for host: 5, old used: 6000, old reserved: 0, actual total:
> 70208, total with overprovisioning: 70208; new used:6100, reserved:0;
> requested cpu:100,alloc_from_last:true
> 2015-05-05 06:39:07,978 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) RAM STATS
> after allocation: for host: 5, old used: 177704271872, old reserved: 0,
> total: 1374207606784; new used: 179851755520, reserved: 0; requested mem:
> 2147483648,alloc_from_last:true
> 2015-05-05 06:39:07,982 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) VM is
> being created in podId: 1
> 2015-05-05 06:39:07,988 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Network
> id=224 is already implemented
> 2015-05-05 06:39:07,993 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:39:07,996 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Changing
> active number of nics for network id=224 on 1
> 2015-05-05 06:39:08,002 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Asking
> VirtualRouter to prepare for Nic[1357-1350-null-172.83.24.37]
> 2015-05-05 06:39:08,008 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Lock is
> acquired for network id 224 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(2)-Host(5)-Storage()]
> 2015-05-05 06:39:08,011 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Lock is
> released for network id 224 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(2)-Host(5)-Storage()]
> 2015-05-05 06:39:08,015 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:39:08,023 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:39:08,027 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Applying
> dhcp entry in network Ntwk[224|Guest|7]
> 2015-05-05 06:39:08,039 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 4-3564599105063748818: Sending { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:34:d2:00:11:af","vmIpAddress":"172.83.24.37","vmName":"test","defaultRouter":"172.83.24.1","defaultDns":"172.83.24.10","duid":"00:03:00:01:06:34:d2:00:11:af","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.name":"r-1017-VM","router.ip":"10.178.84.38"},"wait":0}}]
> }
> 2015-05-05 06:39:08,039 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 4-3564599105063748818: Executing: { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:34:d2:00:11:af","vmIpAddress":"172.83.24.37","vmName":"test","defaultRouter":"172.83.24.1","defaultDns":"172.83.24.10","duid":"00:03:00:01:06:34:d2:00:11:af","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.name":"r-1017-VM","router.ip":"10.178.84.38"},"wait":0}}]
> }
> 2015-05-05 06:39:08,039 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-210:ctx-c3c50d74 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: DhcpEntryCommand) Use router's private IP for SSH
> control. IP : 10.178.84.38
> 2015-05-05 06:39:08,040 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-210:ctx-c3c50d74 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: DhcpEntryCommand) Run command on VR: 10.178.84.38,
> script: edithosts.sh with args: -m 06:34:d2:00:11:af -4 172.83.24.37 -h test
> -d 172.83.24.1 -n 172.83.24.10
> 2015-05-05 06:39:08,040 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-210:ctx-c3c50d74 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: DhcpEntryCommand) Return a VmwareContext from the
> idle pool: [email protected]. current pool
> size: 7, outstanding count: 8
> 2015-05-05 06:39:08,471 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-210:ctx-c3c50d74 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: DhcpEntryCommand) edithosts.sh execution result: true
> 2015-05-05 06:39:08,471 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-210:ctx-c3c50d74 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: DhcpEntryCommand) Recycle VmwareContext into idle
> pool: [email protected], current idle pool
> size: 8, outstanding count: 8
> 2015-05-05 06:39:08,472 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 4-3564599105063748818: Received: { Ans: , MgmtId: 345049223690, via: 4, Ver:
> v1, Flags: 10, { Answer } }
> 2015-05-05 06:39:08,490 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:39:08,505 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Applying
> userdata and password entry in network Ntwk[224|Guest|7]
> 2015-05-05 06:39:08,530 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 4-3564599105063748819: Sending { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}}]
> }
> 2015-05-05 06:39:08,534 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 4-3564599105063748819: Executing: { Cmd , MgmtId: 345049223690, via:
> 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"172.83.24.37","vmName":"test","executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.ip":"10.178.84.38","router.name":"r-1017-VM"},"wait":0}}]
> }
> 2015-05-05 06:39:08,535 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: SavePasswordCommand) Use router's private IP for SSH
> control. IP : 10.178.84.38
> 2015-05-05 06:39:08,535 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: SavePasswordCommand) Run command on VR: 10.178.84.38,
> script: savepassword.sh with args: -v 172.83.24.37 -p saved_password
> 2015-05-05 06:39:08,535 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: SavePasswordCommand) Return a VmwareContext from the
> idle pool: [email protected]. current pool
> size: 7, outstanding count: 8
> 2015-05-05 06:39:08,857 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: SavePasswordCommand) savepassword.sh execution
> result: true
> 2015-05-05 06:39:08,857 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: SavePasswordCommand) Recycle VmwareContext into idle
> pool: [email protected], current idle pool
> size: 8, outstanding count: 8
> 2015-05-05 06:39:08,857 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: VmDataCommand) Use router's private IP for SSH
> control. IP : 10.178.84.38
> 2015-05-05 06:39:08,858 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: VmDataCommand) Run command on VR: 10.178.84.38,
> script: vmdata.py with args: -d
> eyIxMC4xODUuMjQuMzciOltbInVzZXJkYXRhIiwidXNlci1kYXRhIixudWxsXSxbIm1ldGFkYXRhIiwic2VydmljZS1vZmZlcmluZyIsIlNtYWxsIDFDUFV4MkdCIl0sWyJtZXRhZGF0YSIsImF2YWlsYWJpbGl0eS16b25lIiwiTW9uc29vbi1EZXYtQ0lDLXpvbmUiXSxbIm1ldGFkYXRhIiwibG9jYWwtaXB2NCIsIjEwLjE4NS4yNC4zNyJdLFsibWV0YWRhdGEiLCJsb2NhbC1ob3N0bmFtZSIsInRlc3QiXSxbIm1ldGFkYXRhIiwicHVibGljLWlwdjQiLCIxMC4xODUuMjQuMzciXSxbIm1ldGFkYXRhIiwicHVibGljLWhvc3RuYW1lIixudWxsXSxbIm1ldGFkYXRhIiwiaW5zdGFuY2UtaWQiLCJiYjk1OGI1Zi1hMzc0LTRmMGEtYTdlMi1iMWVkODc3YWMwZTIiXSxbIm1ldGFkYXRhIiwidm0taWQiLCJiYjk1OGI1Zi1hMzc0LTRmMGEtYTdlMi1iMWVkODc3YWMwZTIiXSxbIm1ldGFkYXRhIiwicHVibGljLWtleXMiLG51bGxdLFsibWV0YWRhdGEiLCJjbG91ZC1pZGVudGlmaWVyIiwiQ2xvdWRTdGFjay17NjIxMGQ2YzMtYmM4Mi00MjAwLTg3M2QtOGI2NjVjYjM5YjdmfSJdXX0=
> 2015-05-05 06:39:08,858 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: VmDataCommand) Return a VmwareContext from the idle
> pool: [email protected]. current pool size: 7,
> outstanding count: 8
> 2015-05-05 06:39:09,219 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: VmDataCommand) vmdata.py execution result: true
> 2015-05-05 06:39:09,220 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-106:ctx-a304ee33 fed33-madhoused-grv04.zonex.cloudsand.com,
> job-8077/job-8079, cmd: VmDataCommand) Recycle VmwareContext into idle pool:
> [email protected], current idle pool size: 8,
> outstanding count: 8
> 2015-05-05 06:39:09,220 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 4-3564599105063748819: Received: { Ans: , MgmtId: 345049223690, via: 4, Ver:
> v1, Flags: 10, { Answer, Answer } }
> 2015-05-05 06:39:09,222 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:39:09,226 DEBUG [o.a.c.e.o.VolumeOrchestrator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Checking
> if we need to prepare 1 volumes for VM[User|i-149-1350-VM]
> 2015-05-05 06:39:09,282 DEBUG [c.c.h.g.VMwareGuru]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Nested
> virtualization requested, adding flag to vm configuration
> 2015-05-05 06:39:09,310 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 5-1317865840959292784: Sending { Cmd , MgmtId: 345049223690, via:
> 5(fed33-madhoused-grv06.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StartCommand":{"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle
> Enterprise Linux 6.0
> (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}}]
> }
> 2015-05-05 06:39:09,311 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 5-1317865840959292784: Executing: { Cmd , MgmtId: 345049223690, via:
> 5(fed33-madhoused-grv06.zonex.cloudsand.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StartCommand":{"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle
> Enterprise Linux 6.0
> (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}}]
> }
> 2015-05-05 06:39:09,314 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Executing resource StartCommand:
> {"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle
> Enterprise Linux 6.0
> (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}
> 2015-05-05 06:39:09,314 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Return a VmwareContext from the idle
> pool: [email protected]. current pool size: 7,
> outstanding count: 8
> 2015-05-05 06:39:09,467 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) find VM i-149-1350-VM on host
> 2015-05-05 06:39:09,468 INFO [c.c.h.v.m.HostMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) VM i-149-1350-VM not found in host cache
> 2015-05-05 06:39:09,468 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) load VM cache on host
> 2015-05-05 06:39:09,504 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) VM i-149-1350-VM already exists, tear
> down devices for reconfiguration
> 2015-05-05 06:39:09,565 WARN [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Guest OS mapping name is not set for
> guest os: Oracle Enterprise Linux 6.0 (64-bit)
> 2015-05-05 06:39:10,000 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Nested Virtualization enabled in
> configuration, checking hypervisor capability
> 2015-05-05 06:39:10,038 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Hypervisor supports nested
> virtualization, enabling for VM i-149-1350-VM
> 2015-05-05 06:39:10,072 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare ISO volume at existing device
> {"key":3000,"deviceInfo":{"label":"CD/DVD drive 1","summary":"Remote
> device"},"backing":{"exclusive":false,"deviceName":""},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":0}
> 2015-05-05 06:39:10,112 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Chose disk controller for vol ROOT ->
> scsi, based on root disk controller settings: scsi
> 2015-05-05 06:39:10,199 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Folder test exists on datastore
> 2015-05-05 06:39:10,207 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Search file ROOT-1350.vmdk on
> [b0d3033166f3361abea8b85e0efe4055]
> 2015-05-05 06:39:10,282 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) File [b0d3033166f3361abea8b85e0efe4055]
> ROOT-1350.vmdk exists on datastore
> 2015-05-05 06:39:10,292 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Search file ROOT-1350-flat.vmdk on
> [b0d3033166f3361abea8b85e0efe4055]
> 2015-05-05 06:39:10,355 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) File [b0d3033166f3361abea8b85e0efe4055]
> ROOT-1350-flat.vmdk does not exist on datastore
> 2015-05-05 06:39:10,364 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Search file ROOT-1350-delta.vmdk on
> [b0d3033166f3361abea8b85e0efe4055]
> 2015-05-05 06:39:10,434 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) File [b0d3033166f3361abea8b85e0efe4055]
> ROOT-1350-delta.vmdk exists on datastore
> 2015-05-05 06:39:10,435 INFO [c.c.s.r.VmwareStorageLayoutHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) sync [b0d3033166f3361abea8b85e0efe4055]
> ROOT-1350-delta.vmdk->[b0d3033166f3361abea8b85e0efe4055]
> test/ROOT-1350-delta.vmdk
> 2015-05-05 06:39:10,725 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Search file ROOT-1350.vmdk on
> [b0d3033166f3361abea8b85e0efe4055]
> 2015-05-05 06:39:10,790 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) File [b0d3033166f3361abea8b85e0efe4055]
> ROOT-1350.vmdk exists on datastore
> 2015-05-05 06:39:10,790 INFO [c.c.s.r.VmwareStorageLayoutHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) sync [b0d3033166f3361abea8b85e0efe4055]
> ROOT-1350.vmdk->[b0d3033166f3361abea8b85e0efe4055] test/ROOT-1350.vmdk
> 2015-05-05 06:39:10,980 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Search file ROOT-1350.vmdk on
> [b0d3033166f3361abea8b85e0efe4055] test
> 2015-05-05 06:39:11,041 INFO [c.c.h.v.m.DatastoreMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) File [b0d3033166f3361abea8b85e0efe4055]
> test/ROOT-1350.vmdk exists on datastore
> 2015-05-05 06:39:11,054 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare volume at new device
> {"capacityInKB":0,"key":-2,"backing":{"diskMode":"persistent","fileName":"[b0d3033166f3361abea8b85e0efe4055]
>
> test/ROOT-1350.vmdk","datastore":{"value":"datastore-823","type":"Datastore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":1000,"unitNumber":0}
> 2015-05-05 06:39:11,054 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) VM i-149-1350-VM will be started with
> NIC device type: Vmxnet3
> 2015-05-05 06:39:11,055 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare NIC device based on NicTO:
> {"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}
> 2015-05-05 06:39:11,063 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare network on vmwaresvs vSwitch0
> with name prefix: cloud.guest
> 2015-05-05 06:39:11,240 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv03.zonex.cloudsand.com
> 2015-05-05 06:39:11,393 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:11,403 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv04.zonex.cloudsand.com
> 2015-05-05 06:39:11,803 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:11,816 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv08.zonex.cloudsand.com
> 2015-05-05 06:39:11,974 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:11,982 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv07.zonex.cloudsand.com
> 2015-05-05 06:39:12,142 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:12,152 DEBUG [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan:
> 1151, host: fed33-madhoused-grv05.zonex.cloudsand.com
> 2015-05-05 06:39:12,310 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:12,311 INFO [c.c.h.v.m.HypervisorHostHelper]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0
> is ready on vSwitch vSwitch0
> 2015-05-05 06:39:12,312 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Preparing NIC device on network
> cloud.guest.1151.200.1-vSwitch0
> 2015-05-05 06:39:12,312 DEBUG [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Prepare NIC at new device
> {"operation":"ADD","device":{"addressType":"Manual","macAddress":"06:34:d2:00:11:af","key":-3,"backing":{"network":{"value":"network-5856","type":"Network"},"deviceName":"cloud.guest.1151.200.1-vSwitch0"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":0}}
> 2015-05-05 06:39:12,312 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) find VM i-149-1350-VM on host
> 2015-05-05 06:39:12,313 DEBUG [c.c.h.v.m.HostMO]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) VM i-149-1350-VM found in host cache
> 2015-05-05 06:39:12,585 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Configure VNC port for VM
> i-149-1350-VM, port: 5901, host: fed33-madhoused-grv06.zonex.cloudsand.com
> 2015-05-05 06:39:16,501 INFO [c.c.h.v.r.VmwareResource]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Found existing disk info from volume
> path: ROOT-1350
> 2015-05-05 06:39:23,042 INFO [c.c.h.v.u.VmwareContextPool]
> (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com,
> job-8077/job-8079, cmd: StartCommand) Recycle VmwareContext into idle pool:
> [email protected], current idle pool size: 8,
> outstanding count: 8
> 2015-05-05 06:39:23,044 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Seq
> 5-1317865840959292784: Received: { Ans: , MgmtId: 345049223690, via: 5, Ver:
> v1, Flags: 10, { StartAnswer } }
> 2015-05-05 06:39:23,073 INFO [o.a.c.e.o.VolumeOrchestrator]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Update
> volume disk chain info. vol: 1607, ROOT-1350 -> ROOT-1350, null ->
> {"diskDeviceBusName":"scsi0:0","diskChain":["[b0d3033166f3361abea8b85e0efe4055]
> test/ROOT-1350.vmdk","[b0d3033166f3361abea8b85e0efe4055]
> cd7d90f6cd963cbe8690d1050406d80f/cd7d90f6cd963cbe8690d1050406d80f.vmdk"]}
> 2015-05-05 06:39:23,108 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:39:23,113 DEBUG [c.c.n.NetworkModelImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Service
> SecurityGroup is not supported in the network id=224
> 2015-05-05 06:39:23,130 DEBUG [c.c.c.CapacityManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) VM state
> transitted from :Starting to Running with event: OperationSucceededvm's
> original host id: 5 new host id: 5 host id before state transition: 5
> 2015-05-05 06:39:23,133 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Start
> completed for VM VM[User|i-149-1350-VM]
> 2015-05-05 06:39:23,134 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Done
> executing VM work job:
> com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":1350,"handlerName":"VirtualMachineManagerImpl"}
> 2015-05-05 06:39:23,134 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Complete
> async job-8079, jobStatus: SUCCEEDED, resultCode: 0, result: null
> 2015-05-05 06:39:23,135 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Publish
> async job-8079 complete on message bus
> 2015-05-05 06:39:23,136 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Wake up
> jobs related to job-8079
> 2015-05-05 06:39:23,136 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Update db
> status for job-8079
> 2015-05-05 06:39:23,137 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079 ctx-6e1bff71) Wake up
> jobs joined with job-8079 and disjoin all subjobs created from job- 8079
> 2015-05-05 06:39:23,151 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079) Done with run of VM
> work job: com.cloud.vm.VmWorkStart for VM 1350, job origin: 8077
> 2015-05-05 06:39:23,151 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079) Done executing
> com.cloud.vm.VmWorkStart for job-8079
> 2015-05-05 06:39:23,162 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079) Sync queue (2149) is
> currently empty
> 2015-05-05 06:39:23,163 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-113:ctx-e236ca61 job-8077/job-8079) Remove job-8079 from
> job monitoring
> 2015-05-05 06:39:23,193 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Complete async
> job-8077, jobStatus: SUCCEEDED, resultCode: 0, result:
> org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","name":"test","displayname":"test","projectid":"98b2e16f-1e4f-4b19-866b-154ef5aad53d","project":"mve02","domainid":"c5073484-b111-11e3-b7ee-00505689520a","domain":"ROOT","created":"2015-05-05T06:35:15+0000","state":"Running","haenable":false,"zoneid":"0a81f11b-90ce-4f24-92a0-5a2710f42bd2","zonename":"Madhouse-Dev-CIC-zone","hostid":"0a929069-5b4b-4130-82e3-45a0b571f783","hostname":"fed33-madhoused-grv06.zonex.cloudsand.com","templateid":"bcbcadb7-3621-4721-8bd3-4e18403d23bd","templatename":"OL6.5-AppVM-CIC-Networkable-v2","templatedisplaytext":"OL6.5-AppVM-CIC-Networkable-v2","passwordenabled":false,"serviceofferingid":"9bf47fc8-030e-4c23-a136-de36c8e57d87","serviceofferingname":"Small
>
> 1CPUx2GB","cpunumber":1,"cpuspeed":100,"memory":2048,"guestosid":"c5494284-b111-11e3-b7ee-00505689520a","rootdeviceid":0,"rootdevicetype":"ROOT","securitygroup":[],"nic":[{"id":"97580411-7518-4fdb-8403-0b1785f3a4c5","networkid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","networkname":"Guest
>
> 1151","netmask":"255.255.252.0","gateway":"172.83.24.1","ipaddress":"172.83.24.37","isolationuri":"vlan://1152","broadcasturi":"vlan://1151","traffictype":"Guest","type":"Shared","isdefault":true,"macaddress":"06:34:d2:00:11:af"}],"hypervisor":"VMware","instancename":"i-149-1350-VM","tags":[],"affinitygroup":[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":148,"jobid":"c8490707-706f-4267-8520-0514ead44777","jobstatus":0}
> 2015-05-05 06:39:23,196 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Publish async
> job-8077 complete on message bus
> 2015-05-05 06:39:23,196 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Wake up jobs related
> to job-8077
> 2015-05-05 06:39:23,196 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Update db status for
> job-8077
> 2015-05-05 06:39:23,200 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Wake up jobs joined
> with job-8077 and disjoin all subjobs created from job- 8077
> 2015-05-05 06:39:23,207 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-54:ctx-a7142d34 job-8077) Done executing
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin for job-8077
> 2015-05-05 06:39:23,207 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (API-Job-Executor-54:ctx-a7142d34 job-8077) Remove job-8077 from job
> monitoring
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
