[ https://issues.apache.org/jira/browse/CLOUDSTACK-8442?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14618330#comment-14618330 ]
Daan Hoogland commented on CLOUDSTACK-8442: ------------------------------------------- [~serverchief] I don't see activity on this so moving it out to 4.6.0 ( as we didn't plan for 4.5.3 yet) > [VMWARE] VM Cannot be powered on after restoreVirtualMachine > ------------------------------------------------------------- > > Key: CLOUDSTACK-8442 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8442 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the > default.) > Components: Management Server > Affects Versions: 4.5.1 > Environment: ACS 4.5.1, CentOS 6.6 > vSphere 5.5 with NFS for Primary Storage > Reporter: ilya musayev > Labels: vmware > Fix For: 4.6.0 > > > 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: r...@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: r...@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: r...@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: r...@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: r...@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: > r...@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: r...@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: > r...@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: r...@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: > r...@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: r...@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: > r...@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: r...@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: r...@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: r...@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: r...@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: r...@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: > r...@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: r...@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: > r...@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)