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