You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Rajani Karuturi (JIRA)" <ji...@apache.org> on 2015/08/12 08:13:45 UTC
[jira] [Commented] (CLOUDSTACK-8442) [VMWARE] VM Cannot be powered
on after restoreVirtualMachine
[ https://issues.apache.org/jira/browse/CLOUDSTACK-8442?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14692982#comment-14692982 ]
Rajani Karuturi commented on CLOUDSTACK-8442:
---------------------------------------------
removing fixVersion from the bugs with empty assignee.
(fixVersion implies fix will be available in this release when open and was available since this release when resolved..
please update the fixVersion only when you plan to work on it or you know that someone is working on it. In that case, please update the assignee as well)
> [VMWARE] VM Cannot be powered on after restoreVirtualMachine
> -------------------------------------------------------------
>
> Key: CLOUDSTACK-8442
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8442
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Management Server
> Affects Versions: 4.5.1
> Environment: ACS 4.5.1, CentOS 6.6
> vSphere 5.5 with NFS for Primary Storage
> Reporter: ilya musayev
> Labels: vmware
>
> While restoreVirtualMachine call is successful, when you try to power on the VM, vSphere fails to find and use proper ROOT volume.
> To recreate this issue, create a project, then deploy a VM with template X in same project, then use restoreVirtualMachine API call to alter the ROOT disk and attempt to power on..
> Same errors are seen in vcenter...
> 2015-05-05 06:38:43,962 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-54:ctx-a7142d34 job-8077) Add job-8077 into job monitoring
> 2015-05-05 06:38:43,969 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-7:ctx-6e032e40 ctx-8bb374e0) submit async job-8077, details: AsyncJobVO {id:8077, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 1350, cmd: org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: {"id":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","response":"json","sessionkey":"EfTBAqeGH5ivA9E7W1q7gcYXWgI\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","projectid":"98b2e16f-1e4f-4b19-866b-154ef5aad53d","_":"1430807923839","uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","ctxAccountId":"2","ctxStartEventId":"17421"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345049223690, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2015-05-05 06:38:43,978 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077) Executing AsyncJobVO {id:8077, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 1350, cmd: org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: {"id":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","response":"json","sessionkey":"EfTBAqeGH5ivA9E7W1q7gcYXWgI\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","projectid":"98b2e16f-1e4f-4b19-866b-154ef5aad53d","_":"1430807923839","uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","ctxAccountId":"2","ctxStartEventId":"17421"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345049223690, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2015-05-05 06:38:43,990 WARN [c.c.a.d.ParamGenericValidationWorker] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Received unknown parameters for command startVirtualMachine. Unknown parameters : projectid
> 2015-05-05 06:38:44,020 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Service SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:44,025 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Service SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:44,045 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Deploy avoids pods: [], clusters: [], hosts: []
> 2015-05-05 06:38:44,046 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@49361de4
> 2015-05-05 06:38:44,046 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 100, requested ram: 2147483648
> 2015-05-05 06:38:44,047 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Is ROOT volume READY (pool already allocated)?: No
> 2015-05-05 06:38:44,047 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) This VM has last host_id specified, trying to choose the same host: 5
> 2015-05-05 06:38:44,055 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking if host: 5 has enough capacity for requested CPU: 100 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
> 2015-05-05 06:38:44,058 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Hosts's actual total CPU: 70208 and CPU after applying overprovisioning: 70208
> 2015-05-05 06:38:44,058 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) We need to allocate to the last host again, so checking if there is enough reserved capacity
> 2015-05-05 06:38:44,058 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Reserved CPU: 100 , Requested CPU: 100
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Reserved RAM: 2147483648 , Requested RAM: 2147483648
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Host has enough CPU and RAM available
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) STATS: Can alloc CPU from host: 5, used: 6000, reserved: 100, actual total: 70208, total with overprovisioning: 70208; requested cpu:100,alloc_from_last_host?:true ,considerReservedCapacity?: true
> 2015-05-05 06:38:44,059 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) STATS: Can alloc MEM from host: 5, used: 177704271872, reserved: 2147483648, total: 1374207606784; requested mem: 2147483648,alloc_from_last_host?:true ,considerReservedCapacity?: true
> 2015-05-05 06:38:44,061 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Host: 5 has cpu capability (cpu:32, speed:2194) to support requested CPU: 1 and requested speed: 100
> 2015-05-05 06:38:44,061 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) The last host of this VM is UP and has enough capacity
> 2015-05-05 06:38:44,061 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Now checking for suitable pools under zone: 1, pod: 1, cluster: 2
> 2015-05-05 06:38:44,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking suitable pools for volume (Id, Type): (1607,ROOT)
> 2015-05-05 06:38:44,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) We need to allocate new storagepool for this volume
> 2015-05-05 06:38:44,068 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Calling StoragePoolAllocators to find suitable pools
> 2015-05-05 06:38:44,070 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2015-05-05 06:38:44,070 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) ClusterScopeStoragePoolAllocator looking for storage pool
> 2015-05-05 06:38:44,070 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Looking for pools in dc: 1 pod:1 cluster:2
> 2015-05-05 06:38:44,072 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Found pools matching tags: [Pool[5|NetworkFilesystem]]
> 2015-05-05 06:38:44,075 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking if storage pool is suitable, name: null ,poolId: 5
> 2015-05-05 06:38:44,077 INFO [c.c.s.StorageManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Storage pool null (5) does not supply IOPS capacity, assuming enough capacity
> 2015-05-05 06:38:44,079 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking pool 5 for storage, totalSize: 8796093022208, usedBytes: 5124216307712, usedPct: 0.5825559478253126, disable threshold: 0.9
> 2015-05-05 06:38:44,102 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Found storage pool Madhouse-Dev-CIC-NFS-primary of type NetworkFilesystem with overprovisioning factor 6
> 2015-05-05 06:38:44,102 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Total over provisioned capacity calculated is 6 * 8796093022208
> 2015-05-05 06:38:44,102 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Total capacity of the pool Madhouse-Dev-CIC-NFS-primary id: 5 is 52776558133248
> 2015-05-05 06:38:44,103 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking pool: 5 for volume allocation [Vol[1607|vm=1350|ROOT]], maxSize : 52776558133248, totalAllocatedSize : 9007464972808, askingSize : 21474836480, allocated disable threshold: 0.9
> 2015-05-05 06:38:44,103 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2015-05-05 06:38:44,103 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2015-05-05 06:38:44,103 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Checking if host: 5 can access any suitable storage pool for volume: ROOT
> 2015-05-05 06:38:44,104 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Host: 5 can access pool: 5
> 2015-05-05 06:38:44,105 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Found a potential host id: 5 name: fed33-madhoused-grv06.zonex.cloudsand.com and associated storage pools for this VM
> 2015-05-05 06:38:44,106 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:44,128 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-54:ctx-a7142d34 job-8077 ctx-b6fc1bbf) Sync job-8078 execution on object VmWorkJobQueue.1350
> 2015-05-05 06:38:45,743 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Add job-8078 into job monitoring
> 2015-05-05 06:38:45,752 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Executing AsyncJobVO {id:8078, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAFRnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJzcQB-AAgAAAAAAAAABXBwcHNxAH4ACAAAAAAAAAABcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345049223690, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue May 05 06:38:44 GMT 2015}
> 2015-05-05 06:38:45,753 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078) Run VM work job: com.cloud.vm.VmWorkStart for VM 1350, job origin: 8077
> 2015-05-05 06:38:45,754 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":2,"hostId":5,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":1350,"handlerName":"VirtualMachineManagerImpl"}
> 2015-05-05 06:38:45,760 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 5 new host id: null host id before state transition: null
> 2015-05-05 06:38:45,761 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Successfully transitioned to start state for VM[User|i-149-1350-VM] reservation id = ae870499-0ca4-4aa0-9c83-8314628bc69f
> 2015-05-05 06:38:45,766 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Trying to deploy VM, vm has dcId: 1 and podId: 1
> 2015-05-05 06:38:45,766 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 2, hostId: 5, poolId: null
> 2015-05-05 06:38:45,766 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Deploy avoids pods: null, clusters: null, hosts: null
> 2015-05-05 06:38:45,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Deploy avoids pods: [], clusters: [], hosts: []
> 2015-05-05 06:38:45,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@49361de4
> 2015-05-05 06:38:45,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:2, requested cpu: 100, requested ram: 2147483648
> 2015-05-05 06:38:45,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Is ROOT volume READY (pool already allocated)?: No
> 2015-05-05 06:38:45,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 5
> 2015-05-05 06:38:45,776 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 2
> 2015-05-05 06:38:45,778 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking suitable pools for volume (Id, Type): (1607,ROOT)
> 2015-05-05 06:38:45,778 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) We need to allocate new storagepool for this volume
> 2015-05-05 06:38:45,780 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Calling StoragePoolAllocators to find suitable pools
> 2015-05-05 06:38:45,780 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2015-05-05 06:38:45,780 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) ClusterScopeStoragePoolAllocator looking for storage pool
> 2015-05-05 06:38:45,780 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Looking for pools in dc: 1 pod:1 cluster:2
> 2015-05-05 06:38:45,781 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Found pools matching tags: [Pool[5|NetworkFilesystem]]
> 2015-05-05 06:38:45,783 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking if storage pool is suitable, name: null ,poolId: 5
> 2015-05-05 06:38:45,784 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Storage pool null (5) does not supply IOPS capacity, assuming enough capacity
> 2015-05-05 06:38:45,785 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking pool 5 for storage, totalSize: 8796093022208, usedBytes: 5124216307712, usedPct: 0.5825559478253126, disable threshold: 0.9
> 2015-05-05 06:38:45,796 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Found storage pool Madhouse-Dev-CIC-NFS-primary of type NetworkFilesystem with overprovisioning factor 6
> 2015-05-05 06:38:45,796 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Total over provisioned capacity calculated is 6 * 8796093022208
> 2015-05-05 06:38:45,796 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Total capacity of the pool Madhouse-Dev-CIC-NFS-primary id: 5 is 52776558133248
> 2015-05-05 06:38:45,797 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking pool: 5 for volume allocation [Vol[1607|vm=1350|ROOT]], maxSize : 52776558133248, totalAllocatedSize : 9007464972808, askingSize : 21474836480, allocated disable threshold: 0.9
> 2015-05-05 06:38:45,797 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2015-05-05 06:38:45,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2015-05-05 06:38:45,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Checking if host: 5 can access any suitable storage pool for volume: ROOT
> 2015-05-05 06:38:45,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Host: 5 can access pool: 5
> 2015-05-05 06:38:45,798 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Found a potential host id: 5 name: fed33-madhoused-grv06.zonex.cloudsand.com and associated storage pools for this VM
> 2015-05-05 06:38:45,798 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,799 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Deployment found - P0=VM[User|i-149-1350-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,843 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 5 new host id: 5 host id before state transition: null
> 2015-05-05 06:38:45,843 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM starting again on the last host it was stopped on
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Hosts's actual total CPU: 70208 and CPU after applying overprovisioning: 70208
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) We are allocating VM, increasing the used capacity of this host:5
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Current Used CPU: 6000 , Free CPU:64108 ,Requested CPU: 100
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Current Used RAM: 177704271872 , Free RAM:1194355851264 ,Requested RAM: 2147483648
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Reserved CPU: 100 , Requested CPU: 100
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Reserved RAM: 2147483648 , Requested RAM: 2147483648
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) CPU STATS after allocation: for host: 5, old used: 6000, old reserved: 100, actual total: 70208, total with overprovisioning: 70208; new used:6100, reserved:0; requested cpu:100,alloc_from_last:true
> 2015-05-05 06:38:45,851 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) RAM STATS after allocation: for host: 5, old used: 177704271872, old reserved: 2147483648, total: 1374207606784; new used: 179851755520, reserved: 0; requested mem: 2147483648,alloc_from_last:true
> 2015-05-05 06:38:45,857 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) VM is being created in podId: 1
> 2015-05-05 06:38:45,864 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Network id=224 is already implemented
> 2015-05-05 06:38:45,874 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:45,878 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Changing active number of nics for network id=224 on 1
> 2015-05-05 06:38:45,885 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Asking VirtualRouter to prepare for Nic[1357-1350-null-172.83.24.37]
> 2015-05-05 06:38:45,895 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Lock is acquired for network id 224 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,898 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Lock is released for network id 224 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(5)-Storage(Volume(1607|ROOT-->Pool(5))]
> 2015-05-05 06:38:45,905 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:45,916 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Service SecurityGroup is not supported in the network id=224
> 2015-05-05 06:38:45,922 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Applying dhcp entry in network Ntwk[224|Guest|7]
> 2015-05-05 06:38:45,935 DEBUG [c.c.a.t.Request] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq 4-3564599105063748816: Sending { Cmd , MgmtId: 345049223690, via: 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:34:d2:00:11:af","vmIpAddress":"172.83.24.37","vmName":"test","defaultRouter":"172.83.24.1","defaultDns":"172.83.24.10","duid":"00:03:00:01:06:34:d2:00:11:af","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.name":"r-1017-VM","router.ip":"10.178.84.38"},"wait":0}}] }
> 2015-05-05 06:38:45,936 DEBUG [c.c.a.t.Request] (Work-Job-Executor-112:ctx-ff983380 job-8077/job-8078 ctx-c097f8e0) Seq 4-3564599105063748816: Executing: { Cmd , MgmtId: 345049223690, via: 4(fed33-madhoused-grv04.zonex.cloudsand.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:34:d2:00:11:af","vmIpAddress":"172.83.24.37","vmName":"test","defaultRouter":"172.83.24.1","defaultDns":"172.83.24.10","duid":"00:03:00:01:06:34:d2:00:11:af","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"172.83.24.10","zone.network.type":"Advanced","router.name":"r-1017-VM","router.ip":"10.178.84.38"},"wait":0}}] }
> 2015-05-05 06:38:45,936 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com, job-8077/job-8078, cmd: DhcpEntryCommand) Use router's private IP for SSH control. IP : 10.178.84.38
> 2015-05-05 06:38:45,936 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com, job-8077/job-8078, cmd: DhcpEntryCommand) Run command on VR: 10.178.84.38, script: edithosts.sh with args: -m 06:34:d2:00:11:af -4 172.83.24.37 -h test -d 172.83.24.1 -n 172.83.24.10
> 2015-05-05 06:38:45,936 INFO [c.c.h.v.u.VmwareContextPool] (DirectAgent-415:ctx-d5cb637f fed33-madhoused-grv04.zonex.cloudsand.com, job-8077/job-8078, cmd: DhcpEntryCommand) Return a VmwareContext from the idle pool: 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":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}}] }
> 2015-05-05 06:39:09,314 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Executing resource StartCommand: {"vm":{"id":1350,"name":"i-149-1350-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":428867584,"maxRam":2147483648,"hostName":"test","arch":"x86_64","os":"Oracle Enterprise Linux 6.0 (64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ntXbYgEqj8YG13Eca+Lbaw==","params":{"memoryOvercommitRatio":"5.0","keyboard":"us","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"1.0","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"true","rootDiskController":"scsi","vmware.reserve.mem":"false"},"uuid":"bb958b5f-a374-4f0a-a7e2-b1ed877ac0e2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7d19a229-3e59-413c-9153-fbb41bc18956","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b0d30331-66f3-361a-bea8-b85e0efe4055","id":5,"poolType":"NetworkFilesystem","host":"vlan2213.ncisi01.zonex.cloudsand.com","path":"/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary","port":2049,"url":"NetworkFilesystem://vlan2213.ncisi01.zonex.cloudsand.com/ifs/madhouse_dev_poccluster_nds01/Madhouse-Dev-CIC/Madhouse-Dev-Master-Zone/primary/?ROLE=Primary&STOREUUID=b0d30331-66f3-361a-bea8-b85e0efe4055"}},"name":"ROOT-1350","size":21474836480,"path":"ROOT-1350","volumeId":1607,"vmName":"i-149-1350-VM","accountId":149,"format":"OVA","provisioningType":"THIN","id":1607,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-1350","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"vlan2213.ncisi01.zonex.cloudsand.com","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}]},"hostIp":"17.169.69.151","executeInSequence":false,"wait":0}
> 2015-05-05 06:39:09,314 INFO [c.c.h.v.u.VmwareContextPool] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Return a VmwareContext from the idle pool: 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: {"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"97580411-7518-4fdb-8403-0b1785f3a4c5","uuid":"79d72acd-d9f0-4f99-ace4-6f9085db8ace","ip":"172.83.24.37","netmask":"255.255.252.0","gateway":"172.83.24.1","mac":"06:34:d2:00:11:af","dns1":"17.170.191.10","dns2":"17.170.128.10","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1151","isolationUri":"vlan://1152","isSecurityGroupEnabled":false}
> 2015-05-05 06:39:11,063 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Prepare network on vmwaresvs vSwitch0 with name prefix: cloud.guest
> 2015-05-05 06:39:11,240 DEBUG [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan: 1151, host: fed33-madhoused-grv03.zonex.cloudsand.com
> 2015-05-05 06:39:11,393 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0 is ready on vSwitch vSwitch0
> 2015-05-05 06:39:11,403 DEBUG [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan: 1151, host: fed33-madhoused-grv04.zonex.cloudsand.com
> 2015-05-05 06:39:11,803 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0 is ready on vSwitch vSwitch0
> 2015-05-05 06:39:11,816 DEBUG [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan: 1151, host: fed33-madhoused-grv08.zonex.cloudsand.com
> 2015-05-05 06:39:11,974 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0 is ready on vSwitch vSwitch0
> 2015-05-05 06:39:11,982 DEBUG [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan: 1151, host: fed33-madhoused-grv07.zonex.cloudsand.com
> 2015-05-05 06:39:12,142 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0 is ready on vSwitch vSwitch0
> 2015-05-05 06:39:12,152 DEBUG [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Prepare network on other host, vlan: 1151, host: fed33-madhoused-grv05.zonex.cloudsand.com
> 2015-05-05 06:39:12,310 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0 is ready on vSwitch vSwitch0
> 2015-05-05 06:39:12,311 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Network cloud.guest.1151.200.1-vSwitch0 is ready on vSwitch vSwitch0
> 2015-05-05 06:39:12,312 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Preparing NIC device on network cloud.guest.1151.200.1-vSwitch0
> 2015-05-05 06:39:12,312 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Prepare NIC at new device {"operation":"ADD","device":{"addressType":"Manual","macAddress":"06:34:d2:00:11:af","key":-3,"backing":{"network":{"value":"network-5856","type":"Network"},"deviceName":"cloud.guest.1151.200.1-vSwitch0"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":0}}
> 2015-05-05 06:39:12,312 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) find VM i-149-1350-VM on host
> 2015-05-05 06:39:12,313 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) VM i-149-1350-VM found in host cache
> 2015-05-05 06:39:12,585 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Configure VNC port for VM i-149-1350-VM, port: 5901, host: fed33-madhoused-grv06.zonex.cloudsand.com
> 2015-05-05 06:39:16,501 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Found existing disk info from volume path: ROOT-1350
> 2015-05-05 06:39:23,042 INFO [c.c.h.v.u.VmwareContextPool] (DirectAgent-420:ctx-f929d6d0 fed33-madhoused-grv06.zonex.cloudsand.com, job-8077/job-8079, cmd: StartCommand) Recycle VmwareContext into idle pool: 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
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)