You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "siddharth khadke (JIRA)" <ji...@apache.org> on 2014/10/22 20:14:33 UTC
[jira] [Updated] (CLOUDSTACK-7768) After creating a non persistent
isolated network, and creating LXC instance, VR boots in LXC hypervisor
[ https://issues.apache.org/jira/browse/CLOUDSTACK-7768?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
siddharth khadke updated CLOUDSTACK-7768:
-----------------------------------------
Summary: After creating a non persistent isolated network, and creating LXC instance, VR boots in LXC hypervisor (was: After creating a non persistent isolated network, and creating LXC vm, VR boots in LXC hypervisor)
> After creating a non persistent isolated network, and creating LXC instance, 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)