Hi,
Could you paste the agent.log on Host 3 (you can get the hostname in host
table) in this period?
2013/5/8 zzz天蓝 <734664...@qq.com>
> 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.comand
> 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)
