siddharth khadke created CLOUDSTACK-7768: --------------------------------------------
Summary: After creating a non persistent isolated network, and creating LXC vm, VR boots in LXC hypervisor Key: CLOUDSTACK-7768 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7768 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the default.) Components: Management Server Affects Versions: 4.3.0 Reporter: siddharth khadke I created an isolated network and then created an LXC instance in the network. The VR is getting booted on the LXC hypervisor instead of the KVM hypervisor. Obviously the VR keeps rebooting and never really settles down because the VR though booting from the LXC system vm template, is a qcow2 image. Here are the logs I collected :- 2014-10-22 10:54:22,376 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-12065: Processing Seq 3-12065: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-10-22 10:54:22,415 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-12065: Sending Seq 3-12065: { Ans: , MgmtId: 275619426470144, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-10-22 10:54:23,567 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-89223c72) ===START=== 135.227.144.121 -- GET command=deployVirtualMachine&response=json&sessionkey=zuoHi8H%2Fi7cvRTBpnBcbc4aZ2I0%3D&zoneid=b6b8057d-e314-48cb-87d2-2c68b4f679ba&templateid=b3599661-80ee-4f85-94e1-570fd66e9c13&hypervisor=LXC&serviceofferingid=2008a901-3550-48a8-b862-debc0be0c9f8&networkids=60a9b5cb-62d9-469a-ad94-dfd49daaa763&_=1414000463549 2014-10-22 10:54:23,579 DEBUG [c.c.a.ApiDispatcher] (catalina-exec-1:ctx-89223c72 ctx-981623fd) InfrastructureEntity name is:com.cloud.offering.ServiceOffering 2014-10-22 10:54:23,584 DEBUG [c.c.a.ApiDispatcher] (catalina-exec-1:ctx-89223c72 ctx-981623fd) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate 2014-10-22 10:54:23,587 DEBUG [c.c.a.ApiDispatcher] (catalina-exec-1:ctx-89223c72 ctx-981623fd) ControlledEntity name is:com.cloud.network.Network 2014-10-22 10:54:23,603 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:23,659 DEBUG [c.c.v.UserVmManagerImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Allocating in the DB for vm 2014-10-22 10:54:23,690 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Allocating entries for VM: VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6] 2014-10-22 10:54:23,691 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Allocating nics for VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6] 2014-10-22 10:54:23,692 DEBUG [o.a.c.e.o.NetworkOrchestrator] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Allocating nic for vm VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6] in network Ntwk[207|Guest|15] with requested profile NicProfile[0-0-null-null-null 2014-10-22 10:54:23,740 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:23,741 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Allocating disks for VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6] 2014-10-22 10:54:23,753 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Allocation completed for VM: VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6] 2014-10-22 10:54:23,753 DEBUG [c.c.v.UserVmManagerImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Successfully allocated DB entry for VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6] 2014-10-22 10:54:23,814 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:23,819 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:23,944 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-1:ctx-89223c72 ctx-981623fd) submit async job-66, details: AsyncJobVO {id:66, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 9, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdInfo: {"serviceofferingid":"2008a901-3550-48a8-b862-debc0be0c9f8","sessionkey":"zuoHi8H/i7cvRTBpnBcbc4aZ2I0\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"b6b8057d-e314-48cb-87d2-2c68b4f679ba","httpmethod":"GET","templateid":"b3599661-80ee-4f85-94e1-570fd66e9c13","networkids":"60a9b5cb-62d9-469a-ad94-dfd49daaa763","response":"json","id":"9","hypervisor":"LXC","_":"1414000463549","ctxAccountId":"2","ctxStartEventId":"134"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 275619426470144, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2014-10-22 10:54:23,945 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-17:ctx-5568f635) Add job-66 into job monitoring 2014-10-22 10:54:23,945 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-17:ctx-5568f635) Executing AsyncJobVO {id:66, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 9, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdInfo: {"serviceofferingid":"2008a901-3550-48a8-b862-debc0be0c9f8","sessionkey":"zuoHi8H/i7cvRTBpnBcbc4aZ2I0\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"b6b8057d-e314-48cb-87d2-2c68b4f679ba","httpmethod":"GET","templateid":"b3599661-80ee-4f85-94e1-570fd66e9c13","networkids":"60a9b5cb-62d9-469a-ad94-dfd49daaa763","response":"json","id":"9","hypervisor":"LXC","_":"1414000463549","ctxAccountId":"2","ctxStartEventId":"134"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 275619426470144, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2014-10-22 10:54:23,945 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-89223c72 ctx-981623fd) ===END=== 135.227.144.121 -- GET command=deployVirtualMachine&response=json&sessionkey=zuoHi8H%2Fi7cvRTBpnBcbc4aZ2I0%3D&zoneid=b6b8057d-e314-48cb-87d2-2c68b4f679ba&templateid=b3599661-80ee-4f85-94e1-570fd66e9c13&hypervisor=LXC&serviceofferingid=2008a901-3550-48a8-b862-debc0be0c9f8&networkids=60a9b5cb-62d9-469a-ad94-dfd49daaa763&_=1414000463549 2014-10-22 10:54:23,949 DEBUG [c.c.a.ApiDispatcher] (Job-Executor-17:ctx-5568f635 ctx-981623fd) InfrastructureEntity name is:com.cloud.offering.ServiceOffering 2014-10-22 10:54:23,951 DEBUG [c.c.a.ApiDispatcher] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate 2014-10-22 10:54:23,953 DEBUG [c.c.a.ApiDispatcher] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ControlledEntity name is:com.cloud.network.Network 2014-10-22 10:54:23,999 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:24,000 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:24,008 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Deploy avoids pods: [], clusters: [], hosts: [] 2014-10-22 10:54:24,008 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@105d7554 2014-10-22 10:54:24,008 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912 2014-10-22 10:54:24,008 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Is ROOT volume READY (pool already allocated)?: No 2014-10-22 10:54:24,008 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Searching all possible resources under this Zone: 1 2014-10-22 10:54:24,009 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1 2014-10-22 10:54:24,010 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Removing from the clusterId list these clusters from avoid set: [] 2014-10-22 10:54:24,014 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking resources in Cluster: 2 under Pod: 1 2014-10-22 10:54:24,014 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:2 2014-10-22 10:54:24,015 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-5-Routing]] 2014-10-22 10:54:24,017 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-5-Routing]] 2014-10-22 10:54:24,017 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512 2014-10-22 10:54:24,019 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Host: 5 has cpu capability (cpu:7, speed:3300) to support requested CPU: 1 and requested speed: 500 2014-10-22 10:54:24,019 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Checking if host: 5 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0 2014-10-22 10:54:24,020 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Hosts's actual total CPU: 23100 and CPU after applying overprovisioning: 23100 2014-10-22 10:54:24,020 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Free CPU: 23100 , Requested CPU: 500 2014-10-22 10:54:24,020 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Free RAM: 29702463488 , Requested RAM: 536870912 2014-10-22 10:54:24,020 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Host has enough CPU and RAM available 2014-10-22 10:54:24,020 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 5, used: 0, reserved: 0, actual total: 23100, total with overprovisioning: 23100; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2014-10-22 10:54:24,020 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 5, used: 0, reserved: 0, total: 29702463488; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true 2014-10-22 10:54:24,020 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Found a suitable host, adding to list: 5 2014-10-22 10:54:24,020 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts 2014-10-22 10:54:24,021 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking suitable pools for volume (Id, Type): (11,ROOT) 2014-10-22 10:54:24,021 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) We need to allocate new storagepool for this volume 2014-10-22 10:54:24,021 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Calling StoragePoolAllocators to find suitable pools 2014-10-22 10:54:24,021 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2014-10-22 10:54:24,021 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ClusterScopeStoragePoolAllocator looking for storage pool 2014-10-22 10:54:24,022 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Looking for pools in dc: 1 pod:1 cluster:2 2014-10-22 10:54:24,022 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found pools matching tags: [Pool[2|SharedMountPoint]] 2014-10-22 10:54:24,023 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Removing pool Pool[2|SharedMountPoint] from avoid set, must have been inserted when searching for another disk's tag 2014-10-22 10:54:24,023 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking if storage pool is suitable, name: null ,poolId: 2 2014-10-22 10:54:24,025 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking pool 2 for storage, totalSize: 18462044160, usedBytes: 2297782272, usedPct: 0.12445979719723517, disable threshold: 0.85 2014-10-22 10:54:24,027 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking pool: 2 for volume allocation [Vol[11|vm=9|ROOT]], maxSize : 18462044160, totalAllocatedSize : 1073741824, askingSize : 0, allocated disable threshold: 0.85 2014-10-22 10:54:24,027 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools 2014-10-22 10:54:24,027 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2014-10-22 10:54:24,027 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking if host: 5 can access any suitable storage pool for volume: ROOT 2014-10-22 10:54:24,027 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Host: 5 can access pool: 2 2014-10-22 10:54:24,141 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found a potential host id: 5 name: ovs-3.mvdcdev44.us.alcatel-lucent.com and associated storage pools for this VM 2014-10-22 10:54:24,143 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) 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(11|ROOT-->Pool(2))] 2014-10-22 10:54:24,182 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null 2014-10-22 10:54:24,183 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Successfully transitioned to start state for VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6] reservation id = 790036e5-b4d7-43dd-91dd-2eee03b0ba71 2014-10-22 10:54:24,216 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to deploy VM, vm has dcId: 1 and podId: null 2014-10-22 10:54:24,216 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 2, hostId: 5, poolId: null 2014-10-22 10:54:24,216 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Deploy avoids pods: null, clusters: null, hosts: null 2014-10-22 10:54:24,224 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Deploy avoids pods: [], clusters: [], hosts: [] 2014-10-22 10:54:24,225 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@105d7554 2014-10-22 10:54:24,225 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:2, requested cpu: 500, requested ram: 536870912 2014-10-22 10:54:24,225 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Is ROOT volume READY (pool already allocated)?: No 2014-10-22 10:54:24,225 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 5 2014-10-22 10:54:24,225 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 2 2014-10-22 10:54:24,240 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking suitable pools for volume (Id, Type): (11,ROOT) 2014-10-22 10:54:24,240 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) We need to allocate new storagepool for this volume 2014-10-22 10:54:24,240 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Calling StoragePoolAllocators to find suitable pools 2014-10-22 10:54:24,240 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2014-10-22 10:54:24,241 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ClusterScopeStoragePoolAllocator looking for storage pool 2014-10-22 10:54:24,241 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Looking for pools in dc: 1 pod:1 cluster:2 2014-10-22 10:54:24,242 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found pools matching tags: [Pool[2|SharedMountPoint]] 2014-10-22 10:54:24,243 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Removing pool Pool[2|SharedMountPoint] from avoid set, must have been inserted when searching for another disk's tag 2014-10-22 10:54:24,244 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking if storage pool is suitable, name: null ,poolId: 2 2014-10-22 10:54:24,248 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking pool 2 for storage, totalSize: 18462044160, usedBytes: 2297782272, usedPct: 0.12445979719723517, disable threshold: 0.85 2014-10-22 10:54:24,252 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking pool: 2 for volume allocation [Vol[11|vm=9|ROOT]], maxSize : 18462044160, totalAllocatedSize : 1073741824, askingSize : 0, allocated disable threshold: 0.85 2014-10-22 10:54:24,252 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools 2014-10-22 10:54:24,252 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2014-10-22 10:54:24,252 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking if host: 5 can access any suitable storage pool for volume: ROOT 2014-10-22 10:54:24,252 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Host: 5 can access pool: 2 2014-10-22 10:54:24,253 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found a potential host id: 5 name: ovs-3.mvdcdev44.us.alcatel-lucent.com and associated storage pools for this VM 2014-10-22 10:54:24,253 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) 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(11|ROOT-->Pool(2))] 2014-10-22 10:54:24,253 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Deployment found - P0=VM[User|VM-6e4e7d31-9b6f-4ed3-a61f-f4b8b072c1c6], 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(11|ROOT-->Pool(2))] 2014-10-22 10:54:24,350 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 5 host id before state transition: null 2014-10-22 10:54:24,355 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Hosts's actual total CPU: 23100 and CPU after applying overprovisioning: 23100 2014-10-22 10:54:24,355 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) We are allocating VM, increasing the used capacity of this host:5 2014-10-22 10:54:24,355 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Current Used CPU: 0 , Free CPU:23100 ,Requested CPU: 500 2014-10-22 10:54:24,355 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Current Used RAM: 0 , Free RAM:29702463488 ,Requested RAM: 536870912 2014-10-22 10:54:24,355 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) CPU STATS after allocation: for host: 5, old used: 0, old reserved: 0, actual total: 23100, total with overprovisioning: 23100; new used:500, reserved:0; requested cpu:500,alloc_from_last:false 2014-10-22 10:54:24,355 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) RAM STATS after allocation: for host: 5, old used: 0, old reserved: 0, total: 29702463488; new used: 536870912, reserved: 0; requested mem: 536870912,alloc_from_last:false 2014-10-22 10:54:24,392 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) VM is being created in podId: 1 2014-10-22 10:54:24,395 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Lock is acquired for network id 207 as a part of network implement 2014-10-22 10:54:24,395 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Asking NuageVspGuestNetworkGuru to implement Ntwk[207|Guest|15] 2014-10-22 10:54:24,784 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-cc8aabf2) Zone 1 is ready to launch secondary storage VM 2014-10-22 10:54:24,819 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-66f0d4ae) Zone 1 is ready to launch console proxy 2014-10-22 10:54:26,107 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 4 2014-10-22 10:54:26,531 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Asking VirtualRouter to implemenet Ntwk[207|Guest|15] 2014-10-22 10:54:26,535 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Lock is acquired for network id 207 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(11|ROOT-->Pool(2))] 2014-10-22 10:54:26,543 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Adding nic for Virtual Router in Guest network Ntwk[207|Guest|15] 2014-10-22 10:54:26,544 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) First ipv4 null in network id=207 is already allocated, can't use it for domain router; will get random ip address from the range 2014-10-22 10:54:26,544 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Adding nic for Virtual Router in Control network 2014-10-22 10:54:26,545 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found existing network configuration for offering [Network Offering [3-Control-System-Control-Network]: Ntwk[202|Control|3] 2014-10-22 10:54:26,545 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Releasing lock for Acct[ce381da2-5977-11e4-a957-faaca6020900-system] 2014-10-22 10:54:26,618 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Allocating the VR i=10 in datacenter com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$baeb9bfc@1with the hypervisor type LXC 2014-10-22 10:54:26,689 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Allocating entries for VM: VM[DomainRouter|r-10-VM] 2014-10-22 10:54:26,860 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Allocating nics for VM[DomainRouter|r-10-VM] 2014-10-22 10:54:26,863 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Allocating nic for vm VM[DomainRouter|r-10-VM] in network Ntwk[207|Guest|15] with requested profile NicProfile[0-0-null-null-null 2014-10-22 10:54:26,945 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:26,945 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Allocating nic for vm VM[DomainRouter|r-10-VM] in network Ntwk[202|Control|3] with requested profile null 2014-10-22 10:54:26,947 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Allocating disks for VM[DomainRouter|r-10-VM] 2014-10-22 10:54:27,027 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-29477447) ===START=== 135.227.144.121 -- GET command=queryAsyncJobResult&jobId=6d65c60f-ab3a-467b-9793-eee4122fcdef&response=json&sessionkey=zuoHi8H%2Fi7cvRTBpnBcbc4aZ2I0%3D&_=1414000467024 2014-10-22 10:54:27,291 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Allocation completed for VM: VM[DomainRouter|r-10-VM] 2014-10-22 10:54:27,379 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-12066: Processing Seq 3-12066: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-10-22 10:54:27,379 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-29477447 ctx-7a5f9169) ===END=== 135.227.144.121 -- GET command=queryAsyncJobResult&jobId=6d65c60f-ab3a-467b-9793-eee4122fcdef&response=json&sessionkey=zuoHi8H%2Fi7cvRTBpnBcbc4aZ2I0%3D&_=1414000467024 2014-10-22 10:54:27,603 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Lock is released for network id 207 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(11|ROOT-->Pool(2))] 2014-10-22 10:54:27,603 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Starting router VM[DomainRouter|r-10-VM] 2014-10-22 10:54:27,606 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null 2014-10-22 10:54:27,606 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Successfully transitioned to start state for VM[DomainRouter|r-10-VM] reservation id = cc731104-137d-4156-b768-21b8c0d62379 2014-10-22 10:54:27,711 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-12066: Sending Seq 3-12066: { Ans: , MgmtId: 275619426470144, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-10-22 10:54:27,770 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to deploy VM, vm has dcId: 1 and podId: null 2014-10-22 10:54:27,770 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Deploy avoids pods: null, clusters: null, hosts: null 2014-10-22 10:54:27,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Deploy avoids pods: null, clusters: null, hosts: null 2014-10-22 10:54:27,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@105d7554 2014-10-22 10:54:27,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 134217728 2014-10-22 10:54:27,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Is ROOT volume READY (pool already allocated)?: No 2014-10-22 10:54:27,775 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Searching all possible resources under this Zone: 1 2014-10-22 10:54:27,777 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1 2014-10-22 10:54:27,788 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking resources in Cluster: 2 under Pod: 1 2014-10-22 10:54:27,788 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:2 2014-10-22 10:54:27,791 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-5-Routing]] 2014-10-22 10:54:27,794 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-5-Routing]] 2014-10-22 10:54:27,794 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=128 2014-10-22 10:54:27,798 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Host: 5 has cpu capability (cpu:7, speed:3300) to support requested CPU: 1 and requested speed: 500 2014-10-22 10:54:27,798 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Checking if host: 5 has enough capacity for requested CPU: 500 and requested RAM: 134217728 , cpuOverprovisioningFactor: 1.0 2014-10-22 10:54:27,799 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Hosts's actual total CPU: 23100 and CPU after applying overprovisioning: 23100 2014-10-22 10:54:27,799 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Free CPU: 22600 , Requested CPU: 500 2014-10-22 10:54:27,799 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Free RAM: 29165592576 , Requested RAM: 134217728 2014-10-22 10:54:27,799 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Host has enough CPU and RAM available 2014-10-22 10:54:27,799 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 5, used: 500, reserved: 0, actual total: 23100, total with overprovisioning: 23100; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2014-10-22 10:54:27,799 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 5, used: 536870912, reserved: 0, total: 29702463488; requested mem: 134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true 2014-10-22 10:54:27,799 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Found a suitable host, adding to list: 5 2014-10-22 10:54:27,800 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts 2014-10-22 10:54:27,800 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking suitable pools for volume (Id, Type): (12,ROOT) 2014-10-22 10:54:27,800 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) We need to allocate new storagepool for this volume 2014-10-22 10:54:27,800 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Calling StoragePoolAllocators to find suitable pools 2014-10-22 10:54:27,801 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2014-10-22 10:54:27,801 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ClusterScopeStoragePoolAllocator looking for storage pool 2014-10-22 10:54:27,801 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Looking for pools in dc: 1 pod:1 cluster:2 2014-10-22 10:54:27,802 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found pools matching tags: [Pool[2|SharedMountPoint]] 2014-10-22 10:54:27,802 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Removing pool Pool[2|SharedMountPoint] from avoid set, must have been inserted when searching for another disk's tag 2014-10-22 10:54:27,803 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking if storage pool is suitable, name: null ,poolId: 2 2014-10-22 10:54:27,805 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking pool 2 for storage, totalSize: 18462044160, usedBytes: 2297782272, usedPct: 0.12445979719723517, disable threshold: 0.85 2014-10-22 10:54:27,807 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking pool: 2 for volume allocation [Vol[12|vm=10|ROOT]], maxSize : 18462044160, totalAllocatedSize : 1073741824, askingSize : 2621440000, allocated disable threshold: 0.85 2014-10-22 10:54:27,807 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools 2014-10-22 10:54:27,807 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2014-10-22 10:54:27,807 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking if host: 5 can access any suitable storage pool for volume: ROOT 2014-10-22 10:54:27,807 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Host: 5 can access pool: 2 2014-10-22 10:54:27,808 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found a potential host id: 5 name: ovs-3.mvdcdev44.us.alcatel-lucent.com and associated storage pools for this VM 2014-10-22 10:54:27,808 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) 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(12|ROOT-->Pool(2))] 2014-10-22 10:54:27,808 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Deployment found - P0=VM[DomainRouter|r-10-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(12|ROOT-->Pool(2))] 2014-10-22 10:54:28,295 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 5 host id before state transition: null 2014-10-22 10:54:28,301 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Hosts's actual total CPU: 23100 and CPU after applying overprovisioning: 23100 2014-10-22 10:54:28,301 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) We are allocating VM, increasing the used capacity of this host:5 2014-10-22 10:54:28,302 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Current Used CPU: 500 , Free CPU:22600 ,Requested CPU: 500 2014-10-22 10:54:28,302 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Current Used RAM: 536870912 , Free RAM:29165592576 ,Requested RAM: 134217728 2014-10-22 10:54:28,302 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) CPU STATS after allocation: for host: 5, old used: 500, old reserved: 0, actual total: 23100, total with overprovisioning: 23100; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false 2014-10-22 10:54:28,302 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) RAM STATS after allocation: for host: 5, old used: 536870912, old reserved: 0, total: 29702463488; new used: 671088640, reserved: 0; requested mem: 134217728,alloc_from_last:false 2014-10-22 10:54:28,446 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) VM is being created in podId: 1 2014-10-22 10:54:28,449 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Network id=207 is already implemented 2014-10-22 10:54:28,531 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:28,949 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Asking VirtualRouter to prepare for Nic[18-10-cc731104-137d-4156-b768-21b8c0d62379-10.2.0.2] 2014-10-22 10:54:28,951 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Asking NuageVspElement to prepare for Nic[18-10-cc731104-137d-4156-b768-21b8c0d62379-10.2.0.2] 2014-10-22 10:54:28,953 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Service SecurityGroup is not supported in the network id=207 2014-10-22 10:54:28,954 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Network id=202 is already implemented 2014-10-22 10:54:29,102 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Checking if we need to prepare 1 volumes for VM[DomainRouter|r-10-VM] 2014-10-22 10:54:29,107 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) template 10 is already in store:1, type:Image 2014-10-22 10:54:29,108 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) template 10 is already in store:2, type:Primary 2014-10-22 10:54:29,202 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Job-Executor-17:ctx-5568f635 ctx-981623fd) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME 2014-10-22 10:54:29,211 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Seq 5-925963743: Sending { Cmd , MgmtId: 275619426470144, via: 5(ovs-3.mvdcdev44.us.alcatel-lucent.com), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"a232ec46-5977-11e4-a957-faaca6020900","origUrl":"http://download.cloud.com/templates/4.3/systemvm64template-2014-01-14-master-kvm.qcow2.bz2","uuid":"a232ec46-5977-11e4-a957-faaca6020900","id":10,"format":"QCOW2","accountId":1,"checksum":"85a1bed07bf43cbf022451cb2ecae4ff","hvm":false,"displayText":"SystemVM Template (LXC)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"911c8d4b-7627-4f56-935c-eadcfd87b003","id":2,"poolType":"SharedMountPoint","host":"10.31.32.63","path":"/root","port":0,"url":"SharedMountPoint://10.31.32.63//root/?ROLE=Primary&STOREUUID=911c8d4b-7627-4f56-935c-eadcfd87b003"}},"name":"routing-10","hypervisorType":"LXC"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"59392642-f989-450e-8ff2-1b1d825517b9","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"911c8d4b-7627-4f56-935c-eadcfd87b003","id":2,"poolType":"SharedMountPoint","host":"10.31.32.63","path":"/root","port":0,"url":"SharedMountPoint://10.31.32.63//root/?ROLE=Primary&STOREUUID=911c8d4b-7627-4f56-935c-eadcfd87b003"}},"name":"ROOT-10","size":2621440000,"volumeId":12,"vmName":"r-10-VM","accountId":2,"id":12,"deviceId":0,"hypervisorType":"LXC"}},"executeInSequence":false,"options":{},"wait":0}}] } 2014-10-22 10:54:29,593 DEBUG [c.c.a.t.Request] (AgentManager-Handler-4:null) Seq 5-925963743: Processing: { Ans: , MgmtId: 275619426470144, via: 5, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"size":2621440000,"path":"59392642-f989-450e-8ff2-1b1d825517b9","accountId":0,"format":"QCOW2","id":0}},"result":true,"wait":0}}] } 2014-10-22 10:54:29,593 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Seq 5-925963743: Received: { Ans: , MgmtId: 275619426470144, via: 5, Ver: v1, Flags: 10, { CopyCmdAnswer } } 2014-10-22 10:54:29,678 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Boot Args for VM[DomainRouter|r-10-VM]: template=domP name=r-10-VM eth0ip=10.2.0.2 eth0mask=255.255.0.0 gateway=10.2.0.1 dhcprange=10.2.0.1 eth1ip=169.254.0.250 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true 2014-10-22 10:54:29,739 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Resending ipAssoc, port forwarding, load balancing rules as a part of Virtual router start 2014-10-22 10:54:29,747 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Found 0 firewall Egress rule(s) to apply as a part of domR VM[DomainRouter|r-10-VM] start. 2014-10-22 10:54:29,751 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Reapplying vm data (userData and metaData) entries as a part of domR VM[DomainRouter|r-10-VM] start... 2014-10-22 10:54:29,755 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Creating monitoring services on VM[DomainRouter|r-10-VM] start... 2014-10-22 10:54:29,802 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-5568f635 ctx-981623fd) Seq 5-925963744: Sending { Cmd , MgmtId: 275619426470144, via: 5(ovs-3.mvdcdev44.us.alcatel-lucent.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":10,"name":"r-10-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP name=r-10-VM eth0ip=10.2.0.2 eth0mask=255.255.0.0 gateway=10.2.0.1 dhcprange=10.2.0.1 eth1ip=169.254.0.250 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"409785edbad5cfa3","params":{},"uuid":"9be9620d-4258-4940-babb-a53ae95e8d8e","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"59392642-f989-450e-8ff2-1b1d825517b9","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"911c8d4b-7627-4f56-935c-eadcfd87b003","id":2,"poolType":"SharedMountPoint","host":"10.31.32.63","path":"/root","port":0,"url":"SharedMountPoint://10.31.32.63//root/?ROLE=Primary&STOREUUID=911c8d4b-7627-4f56-935c-eadcfd87b003"}},"name":"ROOT-10","size":2621440000,"path":"59392642-f989-450e-8ff2-1b1d825517b9","volumeId":12,"vmName":"r-10-VM","accountId":2,"format":"QCOW2","id":12,"deviceId":0,"hypervisorType":"LXC"}},"diskSeq":0,"path":"59392642-f989-450e-8ff2-1b1d825517b9","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"10.31.32.63","volumeSize":"2621440000"}}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3965dc75-1f3a-423f-b67e-d724ebb621c3","ip":"10.2.0.2","netmask":"255.255.0.0","gateway":"10.2.0.1","mac":"02:00:29:ba:00:02","dns1":"128.251.10.29","dns2":"","broadcastType":"Vsp","type":"Guest","broadcastUri":"vsp://3aba635d-c8c7-4713-b8c9-d066e534e50b/10.2.0.2","isolationUri":"vsp://3aba635d-c8c7-4713-b8c9-d066e534e50b/10.2.0.2","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"8a25964d-3534-412c-8682-ca39b4303dd7","ip":"169.254.0.250","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:00:fa","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"hostIp":"10.100.100.13","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.0.250","port":3922,"interval":6,"retries":100,"name":"r-10-VM","wait":0}},{"com.cloud.agent.api.GetDomRVersionCmd":{"accessDetails":{"router.ip":"169.254.0.250","router.name":"r-10-VM"},"wait":0}},{},{"com.cloud.agent.api.routing.SetMonitorServiceCommand":{"services":[{"id":0,"service":"ssh","processname":"sshd","serviceName":"ssh","servicePath":"/var/run/sshd.pid","pidFile":"/var/run/sshd.pid","isDefault":true},{"id":0,"service":"webserver","processname":"apache2","serviceName":"apache2","servicePath":"/var/run/apache2.pid","pidFile":"/var/run/apache2.pid","isDefault":true}],"accessDetails":{"router.name":"r-10-VM","router.ip":"169.254.0.250","router.guest.ip":"10.2.0.2"},"wait":0}}] } 2014-10-22 10:54:30,014 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-dc76dff0) ===START=== 135.227.144.121 -- GET command=queryAsyncJobResult&jobId=6d65c60f-ab3a-467b-9793-eee4122fcdef&response=json&sessionkey=zuoHi8H%2Fi7cvRTBpnBcbc4aZ2I0%3D&_=1414000470011 2014-10-22 10:54:30,101 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-dc76dff0 ctx-001b433b) ===END=== 135.227.144.121 -- GET command=queryAsyncJobResult&jobId=6d65c60f-ab3a-467b-9793-eee4122fcdef&response=json&sessionkey=zuoHi8H%2Fi7cvRTBpnBcbc4aZ2I0%3D&_=1414000470011 2014-10-22 10:54:31,663 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-586762e4) Found 2 routers to update status. 2014-10-22 10:54:31,665 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-586762e4) Found 0 networks to update RvR status. -- This message was sent by Atlassian JIRA (v6.3.4#6332)