System VM's not starting.. Any thoughts are appreciated... Log Attached
2012-02-02 08:17:45,865 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 4
2012-02-02 08:17:52,965 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2012-02-02 08:17:53,047 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2012-02-02 08:17:53,724 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-6:null) Cleanup succeeded. Details null
2012-02-02 08:17:53,724 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1582437956: Received: { Ans: , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-02-02 08:17:53,724 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null

2012-02-02 08:17:58,341 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-02-02 08:17:58,350 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) No running secondary storage vms found in datacenter id=1, starting one
2012-02-02 08:17:58,364 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Found a stopped secondary storage vm, bring it up to running pool. secStorageVm vm id : 982
2012-02-02 08:17:58,379 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-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
2012-02-02 08:17:58,379 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully transitioned to start state for VM[SecondaryStorageVm|s-982-VM] reservation id = e3cec7aa-c9a6-4a39-893a-1d814df82980
2012-02-02 08:17:58,477 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1
2012-02-02 08:17:58,477 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2012-02-02 08:17:58,484 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Root volume is ready, need to place VM in volume's cluster
2012-02-02 08:17:58,484 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Vol[982|vm=982|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2012-02-02 08:17:58,488 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) In FirstFitPlanner:: plan
2012-02-02 08:17:58,488 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 268435456
2012-02-02 08:17:58,488 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2012-02-02 08:17:58,488 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching resources only under specified Cluster: 1
2012-02-02 08:17:58,493 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Checking resources in Cluster: 1 under Pod: 1
2012-02-02 08:17:58,494 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Calling HostAllocators to find suitable hosts
2012-02-02 08:17:58,494 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-02-02 08:17:58,498 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-4-Routing]]
2012-02-02 08:17:58,505 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-4-Routing]]
2012-02-02 08:17:58,505 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=256
2012-02-02 08:17:58,505 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Checking if host: 4 has enough capacity for requested CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 1.0
2012-02-02 08:17:58,511 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 7200 and CPU after applying overprovisioning: 7200
2012-02-02 08:17:58,511 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Free CPU: 7200 , Requested CPU: 500
2012-02-02 08:17:58,511 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Free RAM: 7704236032 , Requested RAM: 268435456
2012-02-02 08:17:58,511 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2012-02-02 08:17:58,511 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 4, used: 0, reserved: 0, actual total: 7200, total with overprovisioning: 7200; requested cpu:500,alloc_from_last_host?:false
2012-02-02 08:17:58,511 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 4, used: 0, reserved: 0, total: 7704236032; requested mem: 268435456,alloc_from_last_host?:false
2012-02-02 08:17:58,511 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 4
2012-02-02 08:17:58,511 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2012-02-02 08:17:58,514 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Checking suitable pools for volume (Id, Type): (982,ROOT)
2012-02-02 08:17:58,514 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 200
2012-02-02 08:17:58,517 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Planner need not allocate a pool for this volume since its READY
2012-02-02 08:17:58,517 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2012-02-02 08:17:58,517 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Checking if host: 4 can access any suitable storage pool for volume: ROOT
2012-02-02 08:17:58,520 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Host: 4 can access pool: 200
2012-02-02 08:17:58,520 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Found a potential host id: 4 name: host1.comcloud.co and associated storage pools for this VM
2012-02-02 08:17:58,524 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-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(4)-Storage()]
2012-02-02 08:17:58,525 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Deployment found - P0=VM[SecondaryStorageVm|s-982-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(4)-Storage()]
2012-02-02 08:17:58,633 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 4 host id before state transition: null
2012-02-02 08:17:58,649 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 7200 and CPU after applying overprovisioning: 7200
2012-02-02 08:17:58,649 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) We are allocating VM, increasing the used capacity of this host:4
2012-02-02 08:17:58,649 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Current Used CPU: 0 , Free CPU:7200 ,Requested CPU: 500
2012-02-02 08:17:58,649 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Current Used RAM: 0 , Free RAM:7704236032 ,Requested RAM: 268435456
2012-02-02 08:17:58,649 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) CPU STATS after allocation: for host: 4, old used: 0, old reserved: 0, actual total: 7200, total with overprovisioning: 7200; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2012-02-02 08:17:58,649 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) RAM STATS after allocation: for host: 4, old used: 0, old reserved: 0, total: 7704236032; new used: 268435456, reserved: 0; requested mem: 268435456,alloc_from_last:false
2012-02-02 08:17:58,722 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) VM is being started in podId: 1
2012-02-02 08:17:58,741 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=204 is already implemented
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalFirewall to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalLoadBalancer to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking DomainRouter to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Dhcp to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalDhcp to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking BareMetal to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,903 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ElasticLoadBalancer to prepare for Nic[2944-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.66]
2012-02-02 08:17:58,909 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=202 is already implemented
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalFirewall to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalLoadBalancer to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking DomainRouter to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Dhcp to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalDhcp to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking BareMetal to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,204 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ElasticLoadBalancer to prepare for Nic[2945-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-169.254.2.98]
2012-02-02 08:17:59,209 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=201 is already implemented

2012-02-02 08:17:59,210 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-02-02 08:17:59,210 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Expand console proxy standby capacity for zone RaleighZone
2012-02-02 08:17:59,219 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, bring it up to running pool. proxy vm id : 2
2012-02-02 08:17:59,243 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
2012-02-02 08:17:59,243 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state for VM[ConsoleProxy|v-2-VM] reservation id = 7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88
2012-02-02 08:17:59,395 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1
2012-02-02 08:17:59,395 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2012-02-02 08:17:59,401 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
2012-02-02 08:17:59,401 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
2012-02-02 08:17:59,404 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) In FirstFitPlanner:: plan
2012-02-02 08:17:59,404 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
2012-02-02 08:17:59,404 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2012-02-02 08:17:59,404 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
2012-02-02 08:17:59,409 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1
2012-02-02 08:17:59,409 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Calling HostAllocators to find suitable hosts
2012-02-02 08:17:59,410 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-02-02 08:17:59,413 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-4-Routing]]
2012-02-02 08:17:59,418 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-4-Routing]]
2012-02-02 08:17:59,418 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2012-02-02 08:17:59,418 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 4 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2012-02-02 08:17:59,424 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 7200 and CPU after applying overprovisioning: 7200
2012-02-02 08:17:59,424 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 6700 , Requested CPU: 500
2012-02-02 08:17:59,424 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 7435800576 , Requested RAM: 1073741824
2012-02-02 08:17:59,424 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2012-02-02 08:17:59,424 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 4, used: 500, reserved: 0, actual total: 7200, total with overprovisioning: 7200; requested cpu:500,alloc_from_last_host?:false
2012-02-02 08:17:59,424 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 4, used: 268435456, reserved: 0, total: 7704236032; requested mem: 1073741824,alloc_from_last_host?:false
2012-02-02 08:17:59,424 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 4
2012-02-02 08:17:59,424 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2012-02-02 08:17:59,427 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (2,ROOT)
2012-02-02 08:17:59,427 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 200
2012-02-02 08:17:59,430 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Planner need not allocate a pool for this volume since its READY
2012-02-02 08:17:59,430 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
2012-02-02 08:17:59,430 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking if host: 4 can access any suitable storage pool for volume: ROOT
2012-02-02 08:17:59,433 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Host: 4 can access pool: 200
2012-02-02 08:17:59,433 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Found a potential host id: 4 name: host1.comcloud.co and associated storage pools for this VM
2012-02-02 08:17:59,436 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(4)-Storage()]
2012-02-02 08:17:59,437 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(4)-Storage()]
2012-02-02 08:17:59,484 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Allocated a nic NicProfile[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980 for VM[SecondaryStorageVm|s-982-VM]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalFirewall to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalLoadBalancer to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking DomainRouter to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Dhcp to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalDhcp to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking BareMetal to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,618 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ElasticLoadBalancer to prepare for Nic[2946-982-e3cec7aa-c9a6-4a39-893a-1d814df82980-10.5.1.49]
2012-02-02 08:17:59,621 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Checking if we need to prepare 1 volumes for VM[SecondaryStorageVm|s-982-VM]
2012-02-02 08:17:59,621 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) No need to recreate the volume: Vol[982|vm=982|ROOT], since it already has a pool assigned: 200, adding disk to VM
2012-02-02 08:17:59,629 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Boot Args for VM[SecondaryStorageVm|s-982-VM]: template=domP type=secstorage host=10.5.1.11 port=8250 name=s-982-VM zone=1 pod=1 guid=s-982-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=true role=templateProcessor eth2ip=10.5.1.66 eth2mask=255.255.255.0 eth2mask=255.255.255.0 gateway=10.5.1.1 eth0ip=169.254.2.98 eth0mask=255.255.0.0 eth0mask=255.255.0.0 eth1ip=10.5.1.49 eth1mask=255.255.255.0 eth1mask=255.255.255.0 mgmtcidr=10.5.1.0/24 localgw=10.5.1.1 private.network.device=eth1 internaldns1=8.8.8.8 internaldns2=8.8.4.4 dns1=8.8.8.8 dns2=8.8.4.4
2012-02-02 08:17:59,706 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: 4 host id before state transition: null
2012-02-02 08:17:59,724 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 7200 and CPU after applying overprovisioning: 7200
2012-02-02 08:17:59,724 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM, increasing the used capacity of this host:4
2012-02-02 08:17:59,724 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used CPU: 500 , Free CPU:6700 ,Requested CPU: 500
2012-02-02 08:17:59,724 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used RAM: 268435456 , Free RAM:7435800576 ,Requested RAM: 1073741824
2012-02-02 08:17:59,724 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) CPU STATS after allocation: for host: 4, old used: 500, old reserved: 0, actual total: 7200, total with overprovisioning: 7200; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false
2012-02-02 08:17:59,724 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) RAM STATS after allocation: for host: 4, old used: 268435456, old reserved: 0, total: 7704236032; new used: 1342177280, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2012-02-02 08:17:59,885 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is being started in podId: 1
2012-02-02 08:17:59,910 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=204 is already implemented


2012-02-02 08:17:59,979 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 4-1582437957: Sending { Cmd , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":982,"name":"s-982-VM","type":"SecondaryStorageVm","cpus":1,"speed":500,"minRam":268435456,"maxRam":268435456,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=secstorage host=10.5.1.11 port=8250 name=s-982-VM zone=1 pod=1 guid=s-982-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=true role=templateProcessor eth2ip=10.5.1.66 eth2mask=255.255.255.0 eth2mask=255.255.255.0 gateway=10.5.1.1 eth0ip=169.254.2.98 eth0mask=255.255.0.0 eth0mask=255.255.0.0 eth1ip=10.5.1.49 eth1mask=255.255.255.0 eth1mask=255.255.255.0 mgmtcidr=10.5.1.0/24 localgw=10.5.1.1 private.network.device=eth1 internaldns1=8.8.8.8 internaldns2=8.8.4.4 dns1=8.8.8.8 dns2=8.8.4.4","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7c7704871cc53f8c","params":{},"disks":[{"id":982,"name":"ROOT-982","mountPoint":"/primary","path":"/mnt/90771691-15c6-3460-a160-caae264dd80e/3ff689d2-14d9-421c-bea1-f530ffc42223","size":2097152000,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"90771691-15c6-3460-a160-caae264dd80e","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"ip":"10.5.1.66","netmask":"255.255.255.0","gateway":"10.5.1.1","mac":"06:d5:5e:00:00:1b","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true,"tags":[]},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"ip":"169.254.2.98","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:62","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false,"tags":[]},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"ip":"10.5.1.49","netmask":"255.255.255.0","gateway":"10.5.1.1","mac":"06:e7:6e:00:00:0a","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"tags":[]}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.2.98","port":3922,"interval":5,"retries":20,"name":"s-982-VM","wait":0}}] }

2012-02-02 08:18:00,009 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 4-1582437957: Processing: { Ans: , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:499)\n\tat com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)\n\tat com.cloud.utils.nio.Task.run(Task.java:85)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }

2012-02-02 08:18:00,009 WARN [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-11:null) Cleanup failed due to java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
for com.cloud.agent.api.Answer
2012-02-02 08:18:00,009 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 4-1582437957: Received: { Ans: , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 110, { Answer, Answer } }
2012-02-02 08:18:00,010 WARN [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-11:null) Cleanup failed due to Stopped by previous failure for com.cloud.agent.api.Answer
2012-02-02 08:18:00,010 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-11:null) Seq 4-1582437957: No more commands found
2012-02-02 08:18:00,010 WARN [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleanup failed due to java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
for com.cloud.agent.api.Answer
2012-02-02 08:18:00,010 WARN [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleanup failed due to Stopped by previous failure for com.cloud.agent.api.Answer

2012-02-02 08:18:00,131 ERROR [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Failed to start instance VM[SecondaryStorageVm|s-982-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:81)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:757)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:457)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:452)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:215)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:633)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1172)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:106)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:37)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:108)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:36)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:85)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:75)
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:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2012-02-02 08:18:00,198 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalFirewall to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,198 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalLoadBalancer to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,198 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking DomainRouter to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,198 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Dhcp to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,199 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,199 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcp to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,199 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,199 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ElasticLoadBalancer to prepare for Nic[4-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.89]
2012-02-02 08:18:00,204 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=202 is already implemented
2012-02-02 08:18:00,265 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up resources for the vm VM[SecondaryStorageVm|s-982-VM] in Starting state
2012-02-02 08:18:00,366 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-02-02 08:18:00,667 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalFirewall to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,667 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalLoadBalancer to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,668 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking DomainRouter to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,668 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Dhcp to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,668 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,668 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcp to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,668 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,668 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ElasticLoadBalancer to prepare for Nic[5-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-169.254.1.98]
2012-02-02 08:18:00,673 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=201 is already implemented
2012-02-02 08:18:00,935 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Allocated a nic NicProfile[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88 for VM[ConsoleProxy|v-2-VM]
2012-02-02 08:18:01,069 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalFirewall to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,070 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalLoadBalancer to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,070 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking DomainRouter to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,070 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Dhcp to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,070 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,070 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcp to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,070 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,070 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ElasticLoadBalancer to prepare for Nic[6-2-7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88-10.5.1.51]
2012-02-02 08:18:01,073 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-2-VM]
2012-02-02 08:18:01,073 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: 200, adding disk to VM
2012-02-02 08:18:01,082 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Boot Args for VM[ConsoleProxy|v-2-VM]: template=domP type=consoleproxy host=10.5.1.11 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=10.5.1.89 eth2mask=255.255.255.0 gateway=10.5.1.1 eth0ip=169.254.1.98 eth0mask=255.255.0.0 eth1ip=10.5.1.51 eth1mask=255.255.255.0 mgmtcidr=10.5.1.0/24 localgw=10.5.1.1 internaldns1=8.8.8.8 internaldns2=8.8.4.4 dns1=8.8.8.8 dns2=8.8.4.4
2012-02-02 08:18:01,138 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (secstorage-1:null) Releasing ip address for reservationId=e3cec7aa-c9a6-4a39-893a-1d814df82980, instance=2946
2012-02-02 08:18:01,377 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 4-1582437958: Sending { Cmd , MgmtId: 48658629866193, via: 4, 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=10.5.1.11 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=10.5.1.89 eth2mask=255.255.255.0 gateway=10.5.1.1 eth0ip=169.254.1.98 eth0mask=255.255.0.0 eth1ip=10.5.1.51 eth1mask=255.255.255.0 mgmtcidr=10.5.1.0/24 localgw=10.5.1.1 internaldns1=8.8.8.8 internaldns2=8.8.4.4 dns1=8.8.8.8 dns2=8.8.4.4","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"68016cc6379183d8","params":{},"disks":[{"id":2,"name":"ROOT-2","mountPoint":"/primary","path":"/mnt/90771691-15c6-3460-a160-caae264dd80e/3854daff-e016-4407-bb9e-065462a2f602","size":2097152000,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"90771691-15c6-3460-a160-caae264dd80e","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"ip":"10.5.1.89","netmask":"255.255.255.0","gateway":"10.5.1.1","mac":"06:4b:8e:00:00:32","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true,"tags":[]},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"ip":"169.254.1.98","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:01:62","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false,"tags":[]},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"ip":"10.5.1.51","netmask":"255.255.255.0","gateway":"10.5.1.1","mac":"06:37:68:00:00:0c","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"tags":[]}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.1.98","port":3922,"interval":5,"retries":20,"name":"v-2-VM","wait":0}}] }
2012-02-02 08:18:01,407 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null) Seq 4-1582437958: Processing: { Ans: , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)\n\tat com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:499)\n\tat com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)\n\tat com.cloud.utils.nio.Task.run(Task.java:85)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
2012-02-02 08:18:01,407 WARN [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-12:null) Cleanup failed due to java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
for com.cloud.agent.api.Answer
2012-02-02 08:18:01,407 WARN [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-12:null) Cleanup failed due to Stopped by previous failure for com.cloud.agent.api.Answer
2012-02-02 08:18:01,407 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 4-1582437958: Received: { Ans: , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 110, { Answer, Answer } }
2012-02-02 08:18:01,408 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-12:null) Seq 4-1582437958: No more commands found
2012-02-02 08:18:01,408 WARN [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleanup failed due to java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
for com.cloud.agent.api.Answer
2012-02-02 08:18:01,408 WARN [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleanup failed due to Stopped by previous failure for com.cloud.agent.api.Answer
2012-02-02 08:18:01,462 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-982-VM] in Starting state

2012-02-02 08:18:01,551 ERROR [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Failed to start instance VM[ConsoleProxy|v-2-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:81)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:757)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:457)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:452)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:430)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:916)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1647)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:151)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:115)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:36)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:85)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:75)
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:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2012-02-02 08:18:01,729 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2012-02-02 08:18:01,819 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 4
2012-02-02 08:18:01,835 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 7200 and CPU after applying overprovisioning: 7200
2012-02-02 08:18:01,835 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release cpu from host: 4, old used: 1000,reserved: 0, actual total: 7200, total with overprovisioning: 7200; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-02-02 08:18:01,836 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release mem from host: 4, old used: 1342177280,reserved: 0, total: 7704236032; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-02-02 08:18:01,953 WARN [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.AgentUnavailableException: Resource [Host:4] is unreachable: Host 4: Unable to start instance
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:819)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:457)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:452)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:215)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:633)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1172)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:106)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:37)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:108)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:36)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:85)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:75)
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:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
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:81)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:757)
... 19 more
2012-02-02 08:18:01,956 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 982, will recycle it and start a new one
2012-02-02 08:18:01,960 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) VM is already stopped: VM[SecondaryStorageVm|s-982-VM]
2012-02-02 08:18:02,154 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Stopped to Expunging with event: ExpungeOperationvm's original host id: null new host id: null host id before state transition: null
2012-02-02 08:18:02,154 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Destroying vm VM[SecondaryStorageVm|s-982-VM]
2012-02-02 08:18:02,154 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Cleaning network for vm: 982
2012-02-02 08:18:02,293 DEBUG [network.guru.DirectNetworkGuru] (secstorage-1:null) direct network deallocate network: networkId: 204, ip: 10.5.1.66
2012-02-02 08:18:02,678 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=7b1b62bc-a2c1-4585-b8c7-ef0c35aeca88, instance=6
2012-02-02 08:18:02,946 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2012-02-02 08:18:03,147 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Cleaning storage for vm: 982
2012-02-02 08:18:03,215 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 4
2012-02-02 08:18:03,224 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 7200 and CPU after applying overprovisioning: 7200
2012-02-02 08:18:03,225 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 4, old used: 500,reserved: 0, actual total: 7200, total with overprovisioning: 7200; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-02-02 08:18:03,225 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 4, old used: 1073741824,reserved: 0, total: 7704236032; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-02-02 08:18:03,282 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Expunging Vol[982|vm=982|ROOT]
2012-02-02 08:18:03,297 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 4-1582437959: Sending { Cmd , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 100111, [{"storage.DestroyCommand":{"vmName":"s-982-VM","volume":{"id":982,"name":"ROOT-982","mountPoint":"/primary","path":"/mnt/90771691-15c6-3460-a160-caae264dd80e/3ff689d2-14d9-421c-bea1-f530ffc42223","size":2097152000,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"90771691-15c6-3460-a160-caae264dd80e","deviceId":0},"wait":0}}] }
2012-02-02 08:18:03,349 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.AgentUnavailableException: Resource [Host:4] is unreachable: Host 4: Unable to start instance
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:819)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:457)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:452)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:430)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:916)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1647)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:151)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:115)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:36)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:85)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:75)
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:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
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:81)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:757)
... 18 more
2012-02-02 08:18:03,357 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 4-1582437959: Processing: { Ans: , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 110, [{"Answer":{"result":true,"details":"Success","wait":0}}] }
2012-02-02 08:18:03,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) Cleanup succeeded. Details Success
2012-02-02 08:18:03,357 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-13:null) Seq 4-1582437959: No more commands found
2012-02-02 08:18:03,357 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 4-1582437959: Received: { Ans: , MgmtId: 48658629866193, via: 4, Ver: v1, Flags: 110, { Answer } }
2012-02-02 08:18:03,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleanup succeeded. Details Success
2012-02-02 08:18:03,440 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Volume successfully expunged from 200
2012-02-02 08:18:03,529 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Expunged VM[SecondaryStorageVm|s-982-VM]
2012-02-02 08:18:03,976 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn

I don't see any logs attached

just added the log text

can we see agent log too?

2012-02-02 14:02:47,289 WARN [resource.computing.LibvirtComputingResource] (Agent-Handler-5:null) Exception
org.libvirt.LibvirtException: cannot create path '/mnt/90771691-15c6-3460-a160-caae264dd80e/153fff60-8bd8-4b13-9766-1e1c46ec24ca': Invalid argument
at org.libvirt.ErrorHandler.processError(Unknown Source)
at org.libvirt.Connect.processError(Unknown Source)
at org.libvirt.StoragePool.processError(Unknown Source)
at org.libvirt.StoragePool.storageVolCreateXML(Unknown Source)
at com.cloud.agent.resource.computing.LibvirtStorageResource.createTmplDataDisk(LibvirtStorageResource.java:177)
at com.cloud.agent.resource.computing.LibvirtComputingResource.createPatchVbd(LibvirtComputingResource.java:2394)
at com.cloud.agent.resource.computing.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2374)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2284)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
2012-02-02 14:02:47,290{GMT} WARN [cloud.agent.Agent] (Agent-Handler-5:) Caught:
java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
2012-02-02 14:02:47,290 WARN [cloud.agent.Agent] (Agent-Handler-5:null) Caught:
java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
libvir: Storage error : cannot create path '/mnt/90771691-15c6-3460-a160-caae264dd80e/89482cb1-47ed-41d5-8d41-c2d7fdf0c0f2': Invalid argument
2012-02-02 14:02:48,279{GMT} WARN [resource.computing.LibvirtComputingResource] (Agent-Handler-2:) Exception
org.libvirt.LibvirtException: cannot create path '/mnt/90771691-15c6-3460-a160-caae264dd80e/89482cb1-47ed-41d5-8d41-c2d7fdf0c0f2': Invalid argument
at org.libvirt.ErrorHandler.processError(Unknown Source)
at org.libvirt.Connect.processError(Unknown Source)
at org.libvirt.StoragePool.processError(Unknown Source)
at org.libvirt.StoragePool.storageVolCreateXML(Unknown Source)
at com.cloud.agent.resource.computing.LibvirtStorageResource.createTmplDataDisk(LibvirtStorageResource.java:177)
at com.cloud.agent.resource.computing.LibvirtComputingResource.createPatchVbd(LibvirtComputingResource.java:2394)
at com.cloud.agent.resource.computing.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2374)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2284)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
2012-02-02 14:02:48,279 WARN [resource.computing.LibvirtComputingResource] (Agent-Handler-2:null) Exception
org.libvirt.LibvirtException: cannot create path '/mnt/90771691-15c6-3460-a160-caae264dd80e/89482cb1-47ed-41d5-8d41-c2d7fdf0c0f2': Invalid argument
at org.libvirt.ErrorHandler.processError(Unknown Source)
at org.libvirt.Connect.processError(Unknown Source)
at org.libvirt.StoragePool.processError(Unknown Source)
at org.libvirt.StoragePool.storageVolCreateXML(Unknown Source)
at com.cloud.agent.resource.computing.LibvirtStorageResource.createTmplDataDisk(LibvirtStorageResource.java:177)
at com.cloud.agent.resource.computing.LibvirtComputingResource.createPatchVbd(LibvirtComputingResource.java:2394)
at com.cloud.agent.resource.computing.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2374)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2284)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
2012-02-02 14:02:48,279{GMT} WARN [cloud.agent.Agent] (Agent-Handler-2:) Caught:
java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)
2012-02-02 14:02:48,279 WARN [cloud.agent.Agent] (Agent-Handler-2:null) Caught:
java.lang.NullPointerException
at com.cloud.agent.resource.computing.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3259)
at com.cloud.agent.resource.computing.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2199)
at com.cloud.agent.resource.computing.LibvirtComputingResource.execute(LibvirtComputingResource.java:2315)
at com.cloud.agent.resource.computing.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:919)
at com.cloud.agent.Agent.processRequest(Agent.java:499)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:818)
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)

Just a quick note on my setup.

I have two systems. 1) management serer & 1) host
The primary and secondary storage are both on the Management server under /primary & /secondary