i'm using CentOS 6.2 and KVM as hypervisor. My cloudstack version is 4.0.1. I
am able to mount storage at hypervisor.
2013-05-07 10:41:41,278 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) release cpu from host: 3, old used: 1000,reserved: 0,
actual total: 2393, total with overprovisioning: 2393; new used:
500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-05-07 10:41:41,278 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) release mem from host: 3, old used: 1342177280,reserved:
0, total: 2104303616; new used: 268435456,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2013-05-07 10:41:41,280 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.AgentUnavailableException: Resource [Host:3] is
unreachable: Host 3: Unable to start instance due to Unable to get answer that
is of class com.cloud.agent.api.StartAnswer
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to get
answer that is of class com.cloud.agent.api.StartAnswer
at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
... 19 more
2013-05-07 10:41:53,605 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-05-07 10:41:53,605 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Expand console proxy standby capacity for zone basiczoo
2013-05-07 10:41:53,607 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Found a stopped console proxy, bring it up to running
pool. proxy vm id : 2
2013-05-07 10:41:53,612 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) 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
2013-05-07 10:41:53,612 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Successfully transitioned to start state for
VM[ConsoleProxy|v-2-VM] reservation id = 939483a4-32e5-44bf-a5ba-d00ef6c221cf
2013-05-07 10:41:53,616 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-05-07 10:41:53,616 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2013-05-07 10:41:53,617 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
2013-05-07 10:41:53,617 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Vol[2|vm=2|ROOT] is READY, changing deployment plan to
use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2013-05-07 10:41:53,619 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) DeploymentPlanner allocation algorithm: random
2013-05-07 10:41:53,619 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:1, requested cpu: 500, requested ram: 1073741824
2013-05-07 10:41:53,619 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2013-05-07 10:41:53,619 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Searching resources only under specified Cluster: 1
2013-05-07 10:41:53,624 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1
2013-05-07 10:41:53,624 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Calling HostAllocators to find suitable hosts
2013-05-07 10:41:53,624 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1
cluster:1
2013-05-07 10:41:53,625 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-3-Routing]]
2013-05-07 10:41:53,627 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after
prioritization: [Host[-3-Routing]]
2013-05-07 10:41:53,627 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2013-05-07 10:41:53,629 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 3 has enough
capacity for requested CPU: 500 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2013-05-07 10:41:53,630 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 2393 and
CPU after applying overprovisioning: 2393
2013-05-07 10:41:53,630 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 1893 , Requested CPU: 500
2013-05-07 10:41:53,630 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 1835868160 , Requested RAM:
1073741824
2013-05-07 10:41:53,630 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-05-07 10:41:53,630 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 3,
used: 500, reserved: 0, actual total: 2393, total with overprovisioning: 2393;
requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-05-07 10:41:53,630 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 3,
used: 268435456, reserved: 0, total: 2104303616; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-05-07 10:41:53,630 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to
list: 3
2013-05-07 10:41:53,630 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable
hosts
2013-05-07 10:41:53,631 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (2,ROOT)
2013-05-07 10:41:53,631 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Volume is in READY state and has pool already allocated,
checking if pool can be reused, poolId: 202
2013-05-07 10:41:53,632 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Planner need not allocate a pool for this volume since
its READY
2013-05-07 10:41:53,632 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2013-05-07 10:41:53,632 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Checking if host: 3 can access any suitable storage pool
for volume: ROOT
2013-05-07 10:41:53,633 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Host: 3 can access pool: 202
2013-05-07 10:41:53,633 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Found a potential host id: 3 name: cskvm.net.com and
associated storage pools for this VM
2013-05-07 10:41:53,634 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(3)-Storage()]
2013-05-07 10:41:53,634 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Deployment found - P0=VM[ConsoleProxy|v-2-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(3)-Storage()]
2013-05-07 10:41:53,638 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) VM state transitted from :Starting to Starting with
event: OperationRetryvm's original host id: null new host id: 3 host id before
state transition: null
2013-05-07 10:41:53,643 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) Hosts's actual total CPU: 2393 and CPU after applying
overprovisioning: 2393
2013-05-07 10:41:53,643 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) We are allocating VM, increasing the used capacity of
this host:3
2013-05-07 10:41:53,643 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) Current Used CPU: 500 , Free CPU:1893 ,Requested CPU: 500
2013-05-07 10:41:53,643 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) Current Used RAM: 268435456 , Free RAM:1835868160
,Requested RAM: 1073741824
2013-05-07 10:41:53,643 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) CPU STATS after allocation: for host: 3, old used: 500,
old reserved: 0, actual total: 2393, total with overprovisioning: 2393; new
used:1000, reserved:0; requested cpu:500,alloc_from_last:false
2013-05-07 10:41:53,643 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) RAM STATS after allocation: for host: 3, old used:
268435456, old reserved: 0, total: 2104303616; new used: 1342177280, reserved:
0; requested mem: 1073741824,alloc_from_last:false
2013-05-07 10:41:53,645 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) VM is being created in podId: 1
2013-05-07 10:41:53,647 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Lock is acquired for network id 204 as a part of network
implement
2013-05-07 10:41:53,647 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Network id=204 is already implemented
2013-05-07 10:41:53,648 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Lock is released for network id 204 as a part of network
implement
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking JuniperSRX to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking Netscaler to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking F5BigIP to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking VirtualRouter to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking Ovs to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking ExternalDhcpServer to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking BareMetal to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking SecurityGroupProvider to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking VpcVirtualRouter to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,665 WARN [network.element.VpcVirtualRouterElement]
(consoleproxy-1:null) Network Ntwk[204|Guest|6] is not associated with any VPC
2013-05-07 10:41:53,665 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking NiciraNvp to prepare for
Nic[5-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.121]
2013-05-07 10:41:53,668 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Lock is acquired for network id 202 as a part of network
implement
2013-05-07 10:41:53,668 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Network id=202 is already implemented
2013-05-07 10:41:53,669 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Lock is released for network id 202 as a part of network
implement
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking JuniperSRX to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking Netscaler to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking F5BigIP to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking VirtualRouter to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking Ovs to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking ExternalDhcpServer to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking BareMetal to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking SecurityGroupProvider to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking VpcVirtualRouter to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,683 WARN [network.element.VpcVirtualRouterElement]
(consoleproxy-1:null) Network Ntwk[202|Control|3] is not associated with any VPC
2013-05-07 10:41:53,683 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking NiciraNvp to prepare for
Nic[6-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-169.254.3.88]
2013-05-07 10:41:53,684 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Lock is acquired for network id 201 as a part of network
implement
2013-05-07 10:41:53,685 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Network id=201 is already implemented
2013-05-07 10:41:53,685 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Lock is released for network id 201 as a part of network
implement
2013-05-07 10:41:53,704 DEBUG [network.guru.PodBasedNetworkGuru]
(consoleproxy-1:null) Allocated a nic
NicProfile[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102-null for
VM[ConsoleProxy|v-2-VM]
2013-05-07 10:41:53,706 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking JuniperSRX to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,706 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking Netscaler to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,706 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking F5BigIP to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,706 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking VirtualRouter to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,706 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking Ovs to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,706 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking ExternalDhcpServer to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,706 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking BareMetal to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,707 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking SecurityGroupProvider to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,707 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,707 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking VpcVirtualRouter to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,707 WARN [network.element.VpcVirtualRouterElement]
(consoleproxy-1:null) Network Ntwk[201|Management|2] is not associated with any
VPC
2013-05-07 10:41:53,707 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking NiciraNvp to prepare for
Nic[7-2-939483a4-32e5-44bf-a5ba-d00ef6c221cf-10.10.50.102]
2013-05-07 10:41:53,708 DEBUG [cloud.storage.StorageManagerImpl]
(consoleproxy-1:null) Checking if we need to prepare 1 volumes for
VM[ConsoleProxy|v-2-VM]
2013-05-07 10:41:53,708 DEBUG [cloud.storage.StorageManagerImpl]
(consoleproxy-1:null) No need to recreate the volume: Vol[2|vm=2|ROOT], since
it already has a pool assigned: 202, adding disk to VM
2013-05-07 10:41:53,711 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Boot Args for VM[ConsoleProxy|v-2-VM]: template=domP
type=consoleproxy host=localhost port=8250 name=v-2-VM premium=true zone=1
pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=10.10.50.121
eth2mask=255.255.255.0 gateway=10.10.50.90 eth0ip=169.254.3.88
eth0mask=255.255.0.0 eth1ip=10.10.50.102 eth1mask=255.255.255.0
mgmtcidr=10.10.50.0/24 localgw=10.10.50.90 internaldns1=8.8.8.8 dns1=8.8.8.8
2013-05-07 10:41:53,730 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 3-209269381: Waiting for Seq 209269380 Scheduling: { Cmd , MgmtId:
52239894118, via: 3, Ver: v1, Flags: 100111,
[{"StartCommand":{"vm":{"id":2,"name":"v-2-VM","type":"ConsoleProxy","cpus":1,"speed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Debian
GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy
host=localhost port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2
proxy_vm=2 disable_rp_filter=true eth2ip=10.10.50.121 eth2mask=255.255.255.0
gateway=10.10.50.90 eth0ip=169.254.3.88 eth0mask=255.255.0.0
eth1ip=10.10.50.102 eth1mask=255.255.255.0 mgmtcidr=10.10.50.0/24
localgw=10.10.50.90 internaldns1=8.8.8.8
dns1=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"3e1e9f85a48c3ebf","params":{},"uuid":"3dc3e11f-fa1f-4d65-9997-94c1ca437dbc","disks":[{"id":2,"name":"ROOT-2","mountPoint":"/export/primary","path":"0e795981-64ca-477d-92df-f4268313836f","size":0,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"948f11ea-b17e-39b5-86ad-22a85ad3c4c1","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"e29febb7-e074-45a3-a66f-2bc53185d556","ip":"10.10.50.121","netmask":"255.255.255.0","gateway":"10.10.50.90","mac":"06:ca:46:00:00:0d","dns1":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"5d19d7be-c9e0-4475-845b-92e255e5965b","ip":"169.254.3.88","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:58","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"19cfbe11-4b1b-4263-b680-d765b627ee76","ip":"10.10.50.102","netmask":"255.255.255.0","gateway":"10.10.50.90","mac":"06:8d:d0:00:00:03","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.3.88","port":3922,"interval":6,"retries":100,"name":"v-2-VM","wait":0}}]
}
2013-05-07 10:41:54,221 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Running Capacity Checker ...
2013-05-07 10:41:54,221 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) recalculating system capacity
2013-05-07 10:41:54,221 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing cpu/ram capacity update
2013-05-07 10:41:54,225 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 2 VMs on host 3
2013-05-07 10:41:54,226 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 0 VM, not running on host 3
2013-05-07 10:41:54,228 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate cpu capacity, host:3 usedCpu: 1000
reservedCpu: 0
2013-05-07 10:41:54,228 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate memory capacity, host:3 usedMem:
1342177280 reservedMem: 0
2013-05-07 10:41:54,228 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing cpu/ram capacity update
2013-05-07 10:41:54,228 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing storage capacity update
2013-05-07 10:41:54,233 DEBUG [cloud.storage.StorageManagerImpl]
(CapacityChecker:null) Successfully set Capacity - 105689645056 for capacity
type - 3 , DataCenterId - 1, HostOrPoolId - 202, PodId 1
2013-05-07 10:41:54,233 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing storage capacity update
2013-05-07 10:41:54,233 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing capacity updates for public ip and Vlans
2013-05-07 10:41:54,237 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done capacity updates for public ip and Vlans
2013-05-07 10:41:54,237 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing capacity updates for private ip
2013-05-07 10:41:54,241 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing capacity updates for private ip
2013-05-07 10:41:54,241 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done recalculating system capacity
2013-05-07 10:41:54,255 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done running Capacity Checker ...
2013-05-07 10:41:54,434 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers.
2013-05-07 10:41:57,527 DEBUG [agent.transport.Request]
(AgentManager-Handler-2:null) Seq 3-209269380: Processing: { Ans: , MgmtId:
52239894118, via: 3, Ver: v1, Flags: 110,
[{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3943)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2730)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2855)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1061)\n\tat
com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat
com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat
com.cloud.utils.nio.Task.run(Task.java:83)\n\tat
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat
java.lang.Thread.run(Thread.java:679)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped
by previous failure","wait":0}}] }
2013-05-07 10:41:57,527 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-2:null) Seq 3-209269381: Sending now. is current
sequence.
2013-05-07 10:41:57,528 DEBUG [agent.transport.Request] (secstorage-1:null) Seq
3-209269380: Received: { Ans: , MgmtId: 52239894118, via: 3, Ver: v1, Flags:
110, { Answer, Answer } }
2013-05-07 10:41:57,531 ERROR [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Failed to start instance VM[SecondaryStorageVm|s-6675-VM]
com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is
of class com.cloud.agent.api.StartAnswer
at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:257)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:684)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1310)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:119)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:106)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
