[
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)
