Please find the Host and mgmt server logs attached
thanks
On 07/19/2012 08:10 PM, Edison Su wrote:
Do you have more logs, both mgt server log and agent log?
I put a wiki page about how to debug KVM issues:
http://wiki.cloudstack.org/display/COMM/KVM+agent+debug
-----Original Message-----
From: Ahmad Saif [mailto:ahmad.abos...@gmail.com]
Sent: Thursday, July 19, 2012 12:59 AM
To: cloudstack-users@incubator.apache.org
Subject: Failed to add tap interface
Hello there,
I've problem starting one of my instances, and I got very weird error
"Failed to add tap interface'
I've tried to restart the hypervisor, and force reconnect it but with
no
luck at all,
Here is a error form the log file:
WARN [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-48:null) Cleanup failed due to Failed to add tap
interface to bridge 'cloudVirBr306': No such device
DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-48:null) Seq
11-2002067480: No more commands found
DEBUG [agent.transport.Request] (Job-Executor-23:job-233) Seq
11-2002067480: Received: { Ans: , MgmtId: 20792849212874, via: 11, Ver:
v1, Flags: 110, { StartAnswer } }
WARN [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-23:job-233)
Cleanup failed due to Failed to add tap interface to bridge
'cloudVirBr306': No such device
INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-23:job-233)
Unable to start VM on Host[-11-Routing] due to Failed to add tap
interface to bridge 'cloudVirBr306': No such device
Have any one faced issue like this before ?
--
Thanks
2012-07-22 09:49:15,423 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-24:null) submit async job-253, details: AsyncJobVO {id:253, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 17, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator: null, cmdInfo: {"response":"json","id":"0a5eabd6-3089-478e-8123-102d6566b367","sessionkey":"MVsz3I+hW5L3Myru7YLZt4IPv5A\u003d","ctxUserId":"2","_":"1342943364337","ctxAccountId":"2","ctxStartEventId":"1012"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 20792849212874, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2012-07-22 09:49:15,426 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-58:job-253) Executing com.cloud.api.commands.StartVMCmd for job-253
2012-07-22 09:49:15,489 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=205
2012-07-22 09:49:15,511 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=210
2012-07-22 09:49:15,520 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=205
2012-07-22 09:49:15,531 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=210
2012-07-22 09:49:15,538 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 11 new host id: null host id before state transition: null
2012-07-22 09:49:15,538 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Successfully transitioned to start state for VM[User|i-2-17-VM] reservation id = be7ee577-4563-4ad5-a266-1b207d7752f3
2012-07-22 09:49:15,550 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Trying to deploy VM, vm has dcId: 1 and podId: 1
2012-07-22 09:49:15,551 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Deploy avoids pods: null, clusters: null, hosts: null
2012-07-22 09:49:15,554 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Root volume is ready, need to place VM in volume's cluster
2012-07-22 09:49:15,554 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Vol[17|vm=17|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2012-07-22 09:49:15,556 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) DeploymentPlanner allocation algorithm: random
2012-07-22 09:49:15,556 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 8000, requested ram: 8589934592
2012-07-22 09:49:15,556 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Is ROOT volume READY (pool already allocated)?: Yes
2012-07-22 09:49:15,556 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) This VM has last host_id specified, trying to choose the same host: 11
2012-07-22 09:49:15,559 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Checking if host: 11 has enough capacity for requested CPU: 8000 and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2012-07-22 09:49:15,563 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Hosts's actual total CPU: 64008 and CPU after applying overprovisioning: 128016
2012-07-22 09:49:15,564 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) We need to allocate to the last host again, so checking if there is enough reserved capacity
2012-07-22 09:49:15,564 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Reserved CPU: 0 , Requested CPU: 8000
2012-07-22 09:49:15,564 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Reserved RAM: 0 , Requested RAM: 8589934592
2012-07-22 09:49:15,564 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) STATS: Failed to alloc resource from host: 11 reservedCpu: 0, requested cpu: 8000, reservedMem: 0, requested mem: 8589934592
2012-07-22 09:49:15,564 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Host does not have enough reserved CPU available, cannot allocate to this host.
2012-07-22 09:49:15,564 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) The last host of this VM does not have enough capacity
2012-07-22 09:49:15,564 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Cannot choose the last host to deploy this VM
2012-07-22 09:49:15,564 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Searching resources only under specified Cluster: 1
2012-07-22 09:49:15,574 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Checking resources in Cluster: 1 under Pod: 1
2012-07-22 09:49:15,574 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Calling HostAllocators to find suitable hosts
2012-07-22 09:49:15,574 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-07-22 09:49:15,577 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-11-Routing]]
2012-07-22 09:49:15,580 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-11-Routing]]
2012-07-22 09:49:15,580 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Looking for speed=8000Mhz, Ram=8192
2012-07-22 09:49:15,583 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Checking if host: 11 has enough capacity for requested CPU: 8000 and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2012-07-22 09:49:15,586 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Hosts's actual total CPU: 64008 and CPU after applying overprovisioning: 128016
2012-07-22 09:49:15,587 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Free CPU: 106667 , Requested CPU: 8000
2012-07-22 09:49:15,587 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Free RAM: 45941731328 , Requested RAM: 8589934592
2012-07-22 09:49:15,587 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2012-07-22 09:49:15,587 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 11, used: 21349, reserved: 0, actual total: 64008, total with overprovisioning: 128016; requested cpu:8000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2012-07-22 09:49:15,587 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 11, used: 21604859904, reserved: 0, total: 67546591232; requested mem: 8589934592,alloc_from_last_host?:false ,considerReservedCapacity?: true
2012-07-22 09:49:15,587 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Found a suitable host, adding to list: 11
2012-07-22 09:49:15,587 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2012-07-22 09:49:15,589 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Checking suitable pools for volume (Id, Type): (17,ROOT)
2012-07-22 09:49:15,589 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 200
2012-07-22 09:49:15,591 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Planner need not allocate a pool for this volume since its READY
2012-07-22 09:49:15,591 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2012-07-22 09:49:15,591 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Checking if host: 11 can access any suitable storage pool for volume: ROOT
2012-07-22 09:49:15,593 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Host: 11 can access pool: 200
2012-07-22 09:49:15,593 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Found a potential host id: 11 name: hv1.cloudusa.serveex.com and associated storage pools for this VM
2012-07-22 09:49:15,595 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) 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(11)-Storage()]
2012-07-22 09:49:15,595 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Deployment found - P0=VM[User|i-2-17-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(11)-Storage()]
2012-07-22 09:49:15,645 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 11 new host id: 11 host id before state transition: null
2012-07-22 09:49:15,649 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) VM starting again on the last host it was stopped on
2012-07-22 09:49:15,655 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Hosts's actual total CPU: 64008 and CPU after applying overprovisioning: 128016
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) We are allocating VM, increasing the used capacity of this host:11
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Current Used CPU: 21349 , Free CPU:106667 ,Requested CPU: 8000
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Current Used RAM: 21604859904 , Free RAM:45941731328 ,Requested RAM: 8589934592
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Reserved CPU: 0 , Requested CPU: 8000
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Reserved RAM: 0 , Requested RAM: 8589934592
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) CPU STATS after allocation: for host: 11, old used: 21349, old reserved: 0, actual total: 64008, total with overprovisioning: 128016; new used:29349, reserved:0; requested cpu:8000,alloc_from_last:true
2012-07-22 09:49:15,656 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) RAM STATS after allocation: for host: 11, old used: 21604859904, old reserved: 0, total: 67546591232; new used: 30194794496, reserved: 0; requested mem: 8589934592,alloc_from_last:true
2012-07-22 09:49:15,695 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) VM is being started in podId: 1
2012-07-22 09:49:15,700 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Network id=205 is already implemented
2012-07-22 09:49:15,729 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=205
2012-07-22 09:49:15,741 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Changing active number of nics for network id=205 on 1
2012-07-22 09:49:15,752 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking JuniperSRX to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:15,761 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking Netscaler to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:15,767 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking F5BigIp to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:15,771 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking VirtualRouter to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:15,794 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-58:job-253) Starting a router for Ntwk[205|Guest|7] in datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$9e1eef90@1
2012-07-22 09:49:15,818 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=205
2012-07-22 09:49:15,854 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082122: Sending { Cmd , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"02:00:0d:8e:00:0a","vmIpAddress":"10.1.1.148","vmName":"0a5eabd6-3089-478e-8123-102d6566b367","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.1.103","router.name":"r-23-VM"},"wait":0}}] }
2012-07-22 09:49:17,965 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082122: Received: { Ans: , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 110, { Answer } }
2012-07-22 09:49:17,965 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Cleanup succeeded. Details null
2012-07-22 09:49:17,977 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=205
2012-07-22 09:49:18,000 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082123: Sending { Cmd , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.1.1.148","vmName":"0a5eabd6-3089-478e-8123-102d6566b367","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.1.103","router.name":"r-23-VM"},"wait":0}}] }
2012-07-22 09:49:24,206 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082123: Received: { Ans: , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 110, { Answer } }
2012-07-22 09:49:24,206 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Cleanup succeeded. Details null
2012-07-22 09:49:24,206 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking Ovs to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:24,206 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking ExternalDhcpServer to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:24,212 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking BareMetal to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:24,212 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking ElasticLoadBalancerVm to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:24,218 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking SecurityGroupProvider to prepare for Nic[36-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.148]
2012-07-22 09:49:24,224 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=205
2012-07-22 09:49:24,227 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking ExternalGuestNetworkGuru to implement Ntwk[210|Guest|13]
2012-07-22 09:49:24,346 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Reprogramming network Ntwk[210|Guest|13] as a part of network implement
2012-07-22 09:49:24,357 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-58:job-253) There are no static nat to apply for network id=210
2012-07-22 09:49:24,359 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-58:job-253) There are no firewall rules to apply for ip id=[]
2012-07-22 09:49:24,360 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-58:job-253) There are no port forwarding rules to apply for network id=210
2012-07-22 09:49:24,362 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-58:job-253) There are no static nat rules to apply for network id=210
2012-07-22 09:49:24,364 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) There are no rules to forward to the network elements
2012-07-22 09:49:24,410 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=210
2012-07-22 09:49:24,427 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Changing active number of nics for network id=210 on 1
2012-07-22 09:49:24,435 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking JuniperSRX to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,438 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking Netscaler to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,441 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking F5BigIp to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,443 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking VirtualRouter to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,450 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking Ovs to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,450 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking ExternalDhcpServer to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,452 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking BareMetal to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,452 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking ElasticLoadBalancerVm to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,455 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Asking SecurityGroupProvider to prepare for Nic[37-17-be7ee577-4563-4ad5-a266-1b207d7752f3-10.1.1.196]
2012-07-22 09:49:24,459 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=210
2012-07-22 09:49:24,461 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-58:job-253) Checking if we need to prepare 1 volumes for VM[User|i-2-17-VM]
2012-07-22 09:49:24,461 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-58:job-253) No need to recreate the volume: Vol[17|vm=17|ROOT], since it already has a pool assigned: 200, adding disk to VM
2012-07-22 09:49:24,495 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082124: Sending { Cmd , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":17,"name":"i-2-17-VM","type":"User","cpus":8,"speed":1000,"minRam":8589934592,"maxRam":8589934592,"arch":"x86_64","os":"Windows Server 2008 R2 (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"vncPassword":"240db493a70b7c67","params":{},"disks":[{"id":17,"name":"ROOT-17","mountPoint":"/vmstore","path":"d0d5af3c-ada2-461a-bd40-72417ec1fa86","size":214748364800,"type":"ROOT","storagePoolType":"SharedMountPoint","storagePoolUuid":"767b39b9-2efd-421f-97c0-d3a71d5afc83","deviceId":0},{"id":17,"name":"Windows Server 2008 R2_64","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.1.1.148","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:0d:8e:00:0a","dns1":"8.8.8.8","dns2":"4.2.2.6","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://301","isolationUri":"vlan://301","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":1,"networkRateMbps":200,"defaultNic":false,"ip":"10.1.1.196","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:1b:73:00:06","dns1":"8.8.8.8","dns2":"4.2.2.6","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://386","isolationUri":"vlan://386","isSecurityGroupEnabled":false,"name":"cloudbr0"}]},"wait":0}}] }
2012-07-22 09:49:25,098 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082124: Received: { Ans: , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 110, { StartAnswer } }
2012-07-22 09:49:25,104 WARN [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Cleanup failed due to Failed to add tap interface to bridge 'cloudVirBr306': No such device
2012-07-22 09:49:25,175 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Unable to start VM on Host[-11-Routing] due to Failed to add tap interface to bridge 'cloudVirBr306': No such device
2012-07-22 09:49:25,237 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Cleaning up resources for the vm VM[User|i-2-17-VM] in Starting state
2012-07-22 09:49:25,240 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082125: Sending { Cmd , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-17-VM","wait":0}}] }
2012-07-22 09:49:25,343 DEBUG [agent.transport.Request] (Job-Executor-58:job-253) Seq 11-2002082125: Received: { Ans: , MgmtId: 20792849212874, via: 11, Ver: v1, Flags: 110, { StopAnswer } }
2012-07-22 09:49:25,343 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Cleanup succeeded. Details null
2012-07-22 09:49:25,415 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=205
2012-07-22 09:49:25,426 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Changing active number of nics for network id=205 on -1
2012-07-22 09:49:25,442 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Service SecurityGroup is not supported in the network id=210
2012-07-22 09:49:25,455 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-58:job-253) Changing active number of nics for network id=210 on -1
2012-07-22 09:49:25,465 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Successfully cleanued up resources for the vm VM[User|i-2-17-VM] in Starting state
2012-07-22 09:49:25,469 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Root volume is ready, need to place VM in volume's cluster
2012-07-22 09:49:25,469 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-58:job-253) Vol[17|vm=17|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2012-07-22 09:49:25,471 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) DeploymentPlanner allocation algorithm: random
2012-07-22 09:49:25,471 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 8000, requested ram: 8589934592
2012-07-22 09:49:25,471 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Is ROOT volume READY (pool already allocated)?: Yes
2012-07-22 09:49:25,471 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) This VM has last host_id specified, trying to choose the same host: 11
2012-07-22 09:49:25,474 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) The last host of this VM is in avoid set
2012-07-22 09:49:25,474 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Cannot choose the last host to deploy this VM
2012-07-22 09:49:25,474 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Searching resources only under specified Cluster: 1
2012-07-22 09:49:25,488 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Checking resources in Cluster: 1 under Pod: 1
2012-07-22 09:49:25,489 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Calling HostAllocators to find suitable hosts
2012-07-22 09:49:25,489 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-07-22 09:49:25,491 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-11-Routing]]
2012-07-22 09:49:25,494 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-11-Routing]]
2012-07-22 09:49:25,494 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Looking for speed=8000Mhz, Ram=8192
2012-07-22 09:49:25,494 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Host name: hv1.cloudusa.serveex.com, hostId: 11 is in avoid set, skipping this and trying other available hosts
2012-07-22 09:49:25,494 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-58:job-253 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2012-07-22 09:49:25,494 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) No suitable hosts found
2012-07-22 09:49:25,494 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) No suitable hosts found under this Cluster: 1
2012-07-22 09:49:25,494 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2012-07-22 09:49:25,495 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) DeploymentPlanner allocation algorithm: random
2012-07-22 09:49:25,495 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 8000, requested ram: 8589934592
2012-07-22 09:49:25,495 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Is ROOT volume READY (pool already allocated)?: No
2012-07-22 09:49:25,496 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) This VM has last host_id specified, trying to choose the same host: 11
2012-07-22 09:49:25,497 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) The last host of this VM is in avoid set
2012-07-22 09:49:25,497 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Cannot choose the last host to deploy this VM
2012-07-22 09:49:25,497 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Searching resources only under specified Pod: 1
2012-07-22 09:49:25,499 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2012-07-22 09:49:25,500 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) CPUOverprovisioningFactor considered: 2.0
2012-07-22 09:49:25,504 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) Removing from the clusterId list these clusters from avoid set: [1]
2012-07-22 09:49:25,506 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-58:job-253) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2012-07-22 09:49:25,546 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 11 new host id: null host id before state transition: 11
2012-07-22 09:49:25,553 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) Hosts's actual total CPU: 64008 and CPU after applying overprovisioning: 128016
2012-07-22 09:49:25,553 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) release cpu from host: 11, old used: 29349,reserved: 0, actual total: 64008, total with overprovisioning: 128016; new used: 21349,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-07-22 09:49:25,553 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-58:job-253) release mem from host: 11, old used: 30194794496,reserved: 0, total: 67546591232; new used: 21604859904,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-07-22 09:49:25,596 INFO [cloud.api.ApiDispatcher] (Job-Executor-58:job-253) Unable to create a deployment for VM[User|i-2-17-VM]
2012-07-22 09:49:25,597 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-58:job-253) Complete async job-253, jobStatus: 2, resultCode: 530, result: com.cloud.api.response.ExceptionResponse@2d730f15
2012-07-22 09:49:25,727 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-13:null) Async job-253 completed
2012-07-22 09:53:19,949 WARN [resource.computing.LibvirtComputingResource] (agentRequest-Handler-4:null) Failed to start domain: i-2-17-VM: Failed to add tap interface to bridge 'cloudVirBr306': No such device
2012-07-22 09:53:19,950 WARN [resource.computing.LibvirtComputingResource] (agentRequest-Handler-4:null) Exception
org.libvirt.LibvirtException: Failed to add tap interface to bridge 'cloudVirBr306': No such device
at org.libvirt.ErrorHandler.processError(Unknown Source)
at org.libvirt.Connect.processError(Unknown Source)
at org.libvirt.Domain.processError(Unknown Source)
at org.libvirt.Domain.create(Unknown Source)
at com.cloud.agent.resource.computing.LibvirtComputingResource.startDomain(LibvirtComputingResource.java:881)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2527)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1006)
at com.cloud.agent.Agent.processRequest(Agent.java:516)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:826)
at com.cloud.utils.nio.Task.run(Task.java:85)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
