cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "siddharth khadke (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CLOUDSTACK-7768) After creating a non persistent isolated network, and creating LXC instance, VR boots in LXC hypervisor instead of kvm hypervisor
Date Wed, 22 Oct 2014 18:14:33 GMT

     [ 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 instead of kvm hypervisor  (was: After creating a non persistent
isolated network, and creating LXC instance, VR boots in LXC hypervisor)

> After creating a non persistent isolated network, and creating LXC instance, VR boots
in LXC hypervisor instead of kvm 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)

Mime
View raw message