[CLOUDSTACK-8442] [VMWARE] VM Cannot be powered on after restoreVirtualMachine - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Open
Priority: Major
Resolution: Unresolved
Affects Version/s: 4.5.1
Fix Version/s: None
Component/s: Management Server
Security Level: Public (Anyone can view this level - this is the default.)
Labels:
- vmware
Environment:
ACS 4.5.1, CentOS 6.6
vSphere 5.5 with NFS for Primary Storage

Description

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,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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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":

]},"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":

]},"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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com. 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:

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: root@fed33-madhousedev-lvc01.zonex.cloudsand.com, 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

Attachments

Activity

People

Assignee:: Unassigned

Reporter:: ilya musayev

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 05/May/15 07:05

Updated:: 12/Aug/15 06:13