You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users-cn@cloudstack.apache.org by "houqd2012@163.com" <ho...@163.com> on 2013/11/30 16:03:27 UTC
系统虚拟机无法创建成功
各位：
我的环境是CS4.0.1+kvm，区域可以创建成功，可是系统虚拟机一直无法创建成功，一直创建删除、创建删除。
agent.log的日志为：
2013-11-30 23:01:08,723 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-11-30 23:01:08,724 WARN [cloud.agent.Agent] (agentRequest-Handler-1:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
libvirtd.log 中的错误日志：
2013-11-30 14:45:28.379+0000: 22402: error : virFileOpenForceOwnerMode:807 : cannot chown '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk' to (0, 0): Invalid argument
2013-11-30 14:45:28.379+0000: 22402: error : virStorageBackendCreateRaw:412 : cannot create path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk': Invalid argument
2013-11-30 14:45:28.494+0000: 22400: error : virStorageBackendVolOpenCheckMode:1049 : cannot open volume '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/45052b17-61e9-4387-af47-9c4a756755a5': No such file or directory
2013-11-30 14:50:01.984+0000: 22403: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.322+0000: 22400: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.322+0000: 22400: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.400+0000: 22402: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.400+0000: 22402: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
houqd2012@163.com
回复: 回复: 系统虚拟机无法创建成功
Posted by evanitsharp <ev...@gmail.com>.
很可能是Agent没有正常启动，你试试登录管理端修改Agent的配置，实在不行就重装吧
evanitsharp
发件人： houqd2012@163.com
发送时间： 2013-12-02 11:10
收件人： users-cn
主题： 回复: Re: 系统虚拟机无法创建成功
各位：
之前的确是因为nfs存储共享的权限问题，修改之后在kvm宿主机端可以正常挂载，而且目录权限也是正确的，但是现在系统虚拟机仍然是创建、删除、创建、删除。。。恳请各位帮忙分析替下。
kvm宿主机上/var/log/cloud/agent/agent.log中的日志为：
2013-12-02 11:05:13,313 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-12-02 11:05:13,314 WARN [cloud.agent.Agent] (agentRequest-Handler-5:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
一直是这两段交互。
管理端/var/log/cloud/management/management-server.log中的日志为：
2013-12-02 11:07:43,007 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up NICS
2013-12-02 11:07:43,008 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Cleaning network for vm: 2206
2013-12-02 11:07:43,012 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, bring it up to running pool. proxy vm id : 2
2013-12-02 11:07:43,025 DEBUG [network.guru.DirectNetworkGuru] (secstorage-1:null) Deallocate network: networkId: 204, ip: null
2013-12-02 11:07:43,026 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2013-12-02 11:07:43,026 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state for VM[ConsoleProxy|v-2-VM] reservation id = 8c7b1a03-842a-46c7-bedc-63f275cdd83a
2013-12-02 11:07:43,033 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8820
2013-12-02 11:07:43,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-12-02 11:07:43,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-02 11:07:43,038 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
2013-12-02 11:07:43,039 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Vol[2|vm=2|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2013-12-02 11:07:43,047 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: random
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 1073741824
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
2013-12-02 11:07:43,049 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8821
2013-12-02 11:07:43,063 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1
2013-12-02 11:07:43,063 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Calling HostAllocators to find suitable hosts
2013-12-02 11:07:43,063 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-12-02 11:07:43,065 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8822
2013-12-02 11:07:43,067 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2013-12-02 11:07:43,074 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2013-12-02 11:07:43,075 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2013-12-02 11:07:43,078 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-12-02 11:07:43,081 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8823
2013-12-02 11:07:43,081 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Cleaning storage for vm: 2206
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 64000 , Requested CPU: 500
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 270832836608 , Requested RAM: 1073741824
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 64000, total with overprovisioning: 64000; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 270832836608; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-02 11:07:43,083 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-12-02 11:07:43,083 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-12-02 11:07:43,085 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (2,ROOT)
2013-12-02 11:07:43,085 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
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Planner need not allocate a pool for this volume since its READY
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-12-02 11:07:43,089 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Host: 1 can access pool: 200
2013-12-02 11:07:43,089 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Found a potential host id: 1 name: kvmhost.vsdevel.corp.landhightech.com and associated storage pools for this VM
2013-12-02 11:07:43,091 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Expunging Vol[2206|vm=2206|ROOT]
2013-12-02 11:07:43,091 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(1)-Storage()]
2013-12-02 11:07:43,091 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(1)-Storage()]
2013-12-02 11:07:43,097 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: 1 host id before state transition: null
2013-12-02 11:07:43,097 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Marking volume that was never created as destroyed: Vol[2206|vm=2206|ROOT]
2013-12-02 11:07:43,107 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Expunged VM[SecondaryStorageVm|s-2206-VM]
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM, increasing the used capacity of this host:1
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used CPU: 0 , Free CPU:64000 ,Requested CPU: 500
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used RAM: 0 , Free RAM:270832836608 ,Requested RAM: 1073741824
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 0, total: 270832836608; new used: 1073741824, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2013-12-02 11:07:43,114 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn
2013-12-02 11:07:43,117 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is being created in podId: 1
2013-12-02 11:07:43,122 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 204 as a part of network implement
2013-12-02 11:07:43,122 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=204 is already implemented
2013-12-02 11:07:43,123 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 204 as a part of network implement
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[204|Guest|6] is not associated with any VPC
2013-12-02 11:07:43,156 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,166 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 202 as a part of network implement
2013-12-02 11:07:43,166 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=202 is already implemented
2013-12-02 11:07:43,167 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 202 as a part of network implement
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[202|Control|3] is not associated with any VPC
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,205 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 201 as a part of network implement
2013-12-02 11:07:43,205 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=201 is already implemented
2013-12-02 11:07:43,206 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 201 as a part of network implement
2013-12-02 11:07:43,233 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Allocated a nic NicProfile[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175-null for VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[201|Management|2] is not associated with any VPC
2013-12-02 11:07:43,244 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,246 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,246 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
2013-12-02 11:07:43,254 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Boot Args for VM[ConsoleProxy|v-2-VM]: template=domP type=consoleproxy host=192.168.1.165 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.193 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.79 eth0mask=255.255.0.0 eth1ip=192.168.1.175 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.92 dns1=61.177.7.1
2013-12-02 11:07:43,277 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210010: Sending { Cmd , MgmtId: 52234685305, via: 1, 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=192.168.1.165 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.193 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.79 eth0mask=255.255.0.0 eth1ip=192.168.1.175 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.92 dns1=61.177.7.1","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"db880981011a6b2d","params":{},"uuid":"0f51eaf6-1269-449d-bf55-87038851c236","disks":[{"id":2,"name":"ROOT-2","mountPoint":"/primary","path":"dd324d10-c822-4c1b-a3d5-bfb0b84e323c","size":0,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"3c812bf5-0e22-3263-b902-4a65532af2e3","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"badb94d8-94e6-471c-a59d-687cad6fe277","ip":"192.168.1.193","netmask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:ae:3a:00:00:0d","dns1":"61.177.7.1","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"3b89dfe3-a5d4-4acf-98ce-13cc30d51a20","ip":"169.254.2.79","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:4f","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"a76f71f0-9895-4e8b-856f-ad87e62b8df4","ip":"192.168.1.175","netmask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:57:24:00:00:09","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.2.79","port":3922,"interval":6,"retries":100,"name":"v-2-VM","wait":0}}] }
2013-12-02 11:07:43,321 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2013-12-02 11:07:43,384 DEBUG [agent.transport.Request] (AgentManager-Handler-8:null) Seq 1-432210010: Processing: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:701)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
2013-12-02 11:07:43,384 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-8:null) Seq 1-432210010: No more commands found
2013-12-02 11:07:43,384 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210010: Received: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, { Answer, Answer } }
2013-12-02 11:07:43,388 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:80)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-12-02 11:07:43,392 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2013-12-02 11:07:43,395 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210011: Sending { Cmd , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"v-2-VM","wait":0}}] }
2013-12-02 11:07:43,636 DEBUG [agent.transport.Request] (AgentManager-Handler-2:null) Seq 1-432210011: Processing: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-02 11:07:43,636 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-2:null) Seq 1-432210011: No more commands found
2013-12-02 11:07:43,636 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210011: Received: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,658 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,658 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,671 DEBUG [network.guru.ControlNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[6-2-null-null-null
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,684 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=8c7b1a03-842a-46c7-bedc-63f275cdd83a, instance=7
2013-12-02 11:07:43,686 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[7-2-null-null-null
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully released network resources for the vm VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,690 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2013-12-02 11:07:43,699 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: 1
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 1, old used: 500,reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 1, old used: 1073741824,reserved: 0, total: 270832836608; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-02 11:07:43,708 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to get answer that is of class com.cloud.agent.api.StartAnswer
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is of class com.cloud.agent.api.StartAnswer
at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
... 19 more
2013-12-02 11:07:57,947 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
houqd2012@163.com
发件人： tanthalas
发送时间： 2013-12-01 21:26
收件人： users-cn
主题： Re: 系统虚拟机无法创建成功
从libvirtd的log来看，有可能是存储有问题，比如权限之类的，建不了目录。
CloudStack的log，你要在exception这个关键字前面再看看有没有报错原因。
刘宇超 Richard Liu
发件人： houqd2012@163.com
发送时间： 2013-11-30 23:04:12
收件人： users-cn
抄送：
主题： 系统虚拟机无法创建成功
各位：
我的环境是CS4.0.1+kvm，区域可以创建成功，可是系统虚拟机一直无法创建成功，一直创建删除、创建删除。
agent.log的日志为：
2013-11-30 23:01:08,723 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-11-30 23:01:08,724 WARN [cloud.agent.Agent] (agentRequest-Handler-1:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
libvirtd.log 中的错误日志：
2013-11-30 14:45:28.379+0000: 22402: error : virFileOpenForceOwnerMode:807 : cannot chown '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk' to (0, 0): Invalid argument
2013-11-30 14:45:28.379+0000: 22402: error : virStorageBackendCreateRaw:412 : cannot create path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk': Invalid argument
2013-11-30 14:45:28.494+0000: 22400: error : virStorageBackendVolOpenCheckMode:1049 : cannot open volume '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/45052b17-61e9-4387-af47-9c4a756755a5': No such file or directory
2013-11-30 14:50:01.984+0000: 22403: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.322+0000: 22400: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.322+0000: 22400: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.400+0000: 22402: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.400+0000: 22402: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
houqd2012@163.com
回复: Re: 系统虚拟机无法创建成功
Posted by "houqd2012@163.com" <ho...@163.com>.
各位：
之前的确是因为nfs存储共享的权限问题，修改之后在kvm宿主机端可以正常挂载，而且目录权限也是正确的，但是现在系统虚拟机仍然是创建、删除、创建、删除。。。恳请各位帮忙分析替下。
kvm宿主机上/var/log/cloud/agent/agent.log中的日志为：
2013-12-02 11:05:13,313 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-12-02 11:05:13,314 WARN [cloud.agent.Agent] (agentRequest-Handler-5:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
一直是这两段交互。
管理端/var/log/cloud/management/management-server.log中的日志为：
2013-12-02 11:07:43,007 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up NICS
2013-12-02 11:07:43,008 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Cleaning network for vm: 2206
2013-12-02 11:07:43,012 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, bring it up to running pool. proxy vm id : 2
2013-12-02 11:07:43,025 DEBUG [network.guru.DirectNetworkGuru] (secstorage-1:null) Deallocate network: networkId: 204, ip: null
2013-12-02 11:07:43,026 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2013-12-02 11:07:43,026 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state for VM[ConsoleProxy|v-2-VM] reservation id = 8c7b1a03-842a-46c7-bedc-63f275cdd83a
2013-12-02 11:07:43,033 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8820
2013-12-02 11:07:43,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-12-02 11:07:43,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-02 11:07:43,038 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
2013-12-02 11:07:43,039 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Vol[2|vm=2|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2013-12-02 11:07:43,047 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: random
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 1073741824
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
2013-12-02 11:07:43,049 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8821
2013-12-02 11:07:43,063 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1
2013-12-02 11:07:43,063 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Calling HostAllocators to find suitable hosts
2013-12-02 11:07:43,063 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-12-02 11:07:43,065 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8822
2013-12-02 11:07:43,067 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2013-12-02 11:07:43,074 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2013-12-02 11:07:43,075 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2013-12-02 11:07:43,078 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-12-02 11:07:43,081 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8823
2013-12-02 11:07:43,081 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Cleaning storage for vm: 2206
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 64000 , Requested CPU: 500
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 270832836608 , Requested RAM: 1073741824
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 64000, total with overprovisioning: 64000; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 270832836608; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-02 11:07:43,083 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-12-02 11:07:43,083 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-12-02 11:07:43,085 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (2,ROOT)
2013-12-02 11:07:43,085 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
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Planner need not allocate a pool for this volume since its READY
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-12-02 11:07:43,089 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Host: 1 can access pool: 200
2013-12-02 11:07:43,089 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Found a potential host id: 1 name: kvmhost.vsdevel.corp.landhightech.com and associated storage pools for this VM
2013-12-02 11:07:43,091 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Expunging Vol[2206|vm=2206|ROOT]
2013-12-02 11:07:43,091 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(1)-Storage()]
2013-12-02 11:07:43,091 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(1)-Storage()]
2013-12-02 11:07:43,097 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: 1 host id before state transition: null
2013-12-02 11:07:43,097 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Marking volume that was never created as destroyed: Vol[2206|vm=2206|ROOT]
2013-12-02 11:07:43,107 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Expunged VM[SecondaryStorageVm|s-2206-VM]
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM, increasing the used capacity of this host:1
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used CPU: 0 , Free CPU:64000 ,Requested CPU: 500
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used RAM: 0 , Free RAM:270832836608 ,Requested RAM: 1073741824
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 0, total: 270832836608; new used: 1073741824, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2013-12-02 11:07:43,114 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn
2013-12-02 11:07:43,117 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is being created in podId: 1
2013-12-02 11:07:43,122 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 204 as a part of network implement
2013-12-02 11:07:43,122 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=204 is already implemented
2013-12-02 11:07:43,123 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 204 as a part of network implement
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[204|Guest|6] is not associated with any VPC
2013-12-02 11:07:43,156 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,166 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 202 as a part of network implement
2013-12-02 11:07:43,166 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=202 is already implemented
2013-12-02 11:07:43,167 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 202 as a part of network implement
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[202|Control|3] is not associated with any VPC
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,205 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 201 as a part of network implement
2013-12-02 11:07:43,205 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=201 is already implemented
2013-12-02 11:07:43,206 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 201 as a part of network implement
2013-12-02 11:07:43,233 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Allocated a nic NicProfile[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175-null for VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[201|Management|2] is not associated with any VPC
2013-12-02 11:07:43,244 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,246 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,246 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
2013-12-02 11:07:43,254 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Boot Args for VM[ConsoleProxy|v-2-VM]: template=domP type=consoleproxy host=192.168.1.165 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.193 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.79 eth0mask=255.255.0.0 eth1ip=192.168.1.175 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.92 dns1=61.177.7.1
2013-12-02 11:07:43,277 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210010: Sending { Cmd , MgmtId: 52234685305, via: 1, 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=192.168.1.165 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.193 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.79 eth0mask=255.255.0.0 eth1ip=192.168.1.175 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.92 dns1=61.177.7.1","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"db880981011a6b2d","params":{},"uuid":"0f51eaf6-1269-449d-bf55-87038851c236","disks":[{"id":2,"name":"ROOT-2","mountPoint":"/primary","path":"dd324d10-c822-4c1b-a3d5-bfb0b84e323c","size":0,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"3c812bf5-0e22-3263-b902-4a65532af2e3","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"badb94d8-94e6-471c-a59d-687cad6fe277","ip":"192.168.1.193","netmask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:ae:3a:00:00:0d","dns1":"61.177.7.1","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"3b89dfe3-a5d4-4acf-98ce-13cc30d51a20","ip":"169.254.2.79","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:4f","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"a76f71f0-9895-4e8b-856f-ad87e62b8df4","ip":"192.168.1.175","netmask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:57:24:00:00:09","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.2.79","port":3922,"interval":6,"retries":100,"name":"v-2-VM","wait":0}}] }
2013-12-02 11:07:43,321 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2013-12-02 11:07:43,384 DEBUG [agent.transport.Request] (AgentManager-Handler-8:null) Seq 1-432210010: Processing: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:701)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
2013-12-02 11:07:43,384 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-8:null) Seq 1-432210010: No more commands found
2013-12-02 11:07:43,384 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210010: Received: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, { Answer, Answer } }
2013-12-02 11:07:43,388 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:80)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-12-02 11:07:43,392 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2013-12-02 11:07:43,395 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210011: Sending { Cmd , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"v-2-VM","wait":0}}] }
2013-12-02 11:07:43,636 DEBUG [agent.transport.Request] (AgentManager-Handler-2:null) Seq 1-432210011: Processing: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-02 11:07:43,636 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-2:null) Seq 1-432210011: No more commands found
2013-12-02 11:07:43,636 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210011: Received: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,658 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,658 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,671 DEBUG [network.guru.ControlNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[6-2-null-null-null
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,684 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=8c7b1a03-842a-46c7-bedc-63f275cdd83a, instance=7
2013-12-02 11:07:43,686 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[7-2-null-null-null
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully released network resources for the vm VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,690 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2013-12-02 11:07:43,699 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: 1
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 1, old used: 500,reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 1, old used: 1073741824,reserved: 0, total: 270832836608; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-02 11:07:43,708 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to get answer that is of class com.cloud.agent.api.StartAnswer
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is of class com.cloud.agent.api.StartAnswer
at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
... 19 more
2013-12-02 11:07:57,947 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
houqd2012@163.com
发件人： tanthalas
发送时间： 2013-12-01 21:26
收件人： users-cn
主题： Re: 系统虚拟机无法创建成功
从libvirtd的log来看，有可能是存储有问题，比如权限之类的，建不了目录。
CloudStack的log，你要在exception这个关键字前面再看看有没有报错原因。
刘宇超 Richard Liu
发件人： houqd2012@163.com
发送时间： 2013-11-30 23:04:12
收件人： users-cn
抄送：
主题： 系统虚拟机无法创建成功
各位：
我的环境是CS4.0.1+kvm，区域可以创建成功，可是系统虚拟机一直无法创建成功，一直创建删除、创建删除。
agent.log的日志为：
2013-11-30 23:01:08,723 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-11-30 23:01:08,724 WARN [cloud.agent.Agent] (agentRequest-Handler-1:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
libvirtd.log 中的错误日志：
2013-11-30 14:45:28.379+0000: 22402: error : virFileOpenForceOwnerMode:807 : cannot chown '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk' to (0, 0): Invalid argument
2013-11-30 14:45:28.379+0000: 22402: error : virStorageBackendCreateRaw:412 : cannot create path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk': Invalid argument
2013-11-30 14:45:28.494+0000: 22400: error : virStorageBackendVolOpenCheckMode:1049 : cannot open volume '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/45052b17-61e9-4387-af47-9c4a756755a5': No such file or directory
2013-11-30 14:50:01.984+0000: 22403: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.322+0000: 22400: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.322+0000: 22400: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.400+0000: 22402: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.400+0000: 22402: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
houqd2012@163.com
Re: 回复: Re: 系统虚拟机无法创建成功
Posted by tanthalas <ta...@hotmail.com>.
这log，看着太费劲了，没有找到确切的原因，分析大概是你在安装配置过程中还有些错误。
建议把KVM节点重装一下，重新加入吧。
刘宇超 Richard Liu
发件人： houqd2012@163.com
发送时间： 2013-12-02 11:11:09
收件人： users-cn
抄送：
主题： 回复: Re: 系统虚拟机无法创建成功
各位：
之前的确是因为nfs存储共享的权限问题，修改之后在kvm宿主机端可以正常挂载，而且目录权限也是正确的，但是现在系统虚拟机仍然是创建、删除、创建、删除。。。恳请各位帮忙分析替下。
kvm宿主机上/var/log/cloud/agent/agent.log中的日志为：
2013-12-02 11:05:13,313 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-12-02 11:05:13,314 WARN [cloud.agent.Agent] (agentRequest-Handler-5:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
一直是这两段交互。
管理端/var/log/cloud/management/management-server.log中的日志为：
2013-12-02 11:07:43,007 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up NICS
2013-12-02 11:07:43,008 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Cleaning network for vm: 2206
2013-12-02 11:07:43,012 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, bring it up to running pool. proxy vm id : 2
2013-12-02 11:07:43,025 DEBUG [network.guru.DirectNetworkGuru] (secstorage-1:null) Deallocate network: networkId: 204, ip: null
2013-12-02 11:07:43,026 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2013-12-02 11:07:43,026 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state for VM[ConsoleProxy|v-2-VM] reservation id = 8c7b1a03-842a-46c7-bedc-63f275cdd83a
2013-12-02 11:07:43,033 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8820
2013-12-02 11:07:43,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-12-02 11:07:43,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-02 11:07:43,038 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
2013-12-02 11:07:43,039 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Vol[2|vm=2|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2013-12-02 11:07:43,047 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: random
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 1073741824
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2013-12-02 11:07:43,048 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
2013-12-02 11:07:43,049 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8821
2013-12-02 11:07:43,063 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1
2013-12-02 11:07:43,063 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Calling HostAllocators to find suitable hosts
2013-12-02 11:07:43,063 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-12-02 11:07:43,065 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8822
2013-12-02 11:07:43,067 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2013-12-02 11:07:43,074 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2013-12-02 11:07:43,075 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2013-12-02 11:07:43,078 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-12-02 11:07:43,081 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=8823
2013-12-02 11:07:43,081 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Cleaning storage for vm: 2206
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 64000 , Requested CPU: 500
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 270832836608 , Requested RAM: 1073741824
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 64000, total with overprovisioning: 64000; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-02 11:07:43,083 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 270832836608; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-02 11:07:43,083 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-12-02 11:07:43,083 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-12-02 11:07:43,085 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (2,ROOT)
2013-12-02 11:07:43,085 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
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Planner need not allocate a pool for this volume since its READY
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-12-02 11:07:43,087 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-12-02 11:07:43,089 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Host: 1 can access pool: 200
2013-12-02 11:07:43,089 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Found a potential host id: 1 name: kvmhost.vsdevel.corp.landhightech.com and associated storage pools for this VM
2013-12-02 11:07:43,091 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Expunging Vol[2206|vm=2206|ROOT]
2013-12-02 11:07:43,091 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(1)-Storage()]
2013-12-02 11:07:43,091 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(1)-Storage()]
2013-12-02 11:07:43,097 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: 1 host id before state transition: null
2013-12-02 11:07:43,097 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Marking volume that was never created as destroyed: Vol[2206|vm=2206|ROOT]
2013-12-02 11:07:43,107 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Expunged VM[SecondaryStorageVm|s-2206-VM]
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM, increasing the used capacity of this host:1
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used CPU: 0 , Free CPU:64000 ,Requested CPU: 500
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used RAM: 0 , Free RAM:270832836608 ,Requested RAM: 1073741824
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2013-12-02 11:07:43,111 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 0, total: 270832836608; new used: 1073741824, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2013-12-02 11:07:43,114 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn
2013-12-02 11:07:43,117 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is being created in podId: 1
2013-12-02 11:07:43,122 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 204 as a part of network implement
2013-12-02 11:07:43,122 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=204 is already implemented
2013-12-02 11:07:43,123 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 204 as a part of network implement
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,155 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[204|Guest|6] is not associated with any VPC
2013-12-02 11:07:43,156 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,166 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 202 as a part of network implement
2013-12-02 11:07:43,166 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=202 is already implemented
2013-12-02 11:07:43,167 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 202 as a part of network implement
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,201 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,202 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[202|Control|3] is not associated with any VPC
2013-12-02 11:07:43,202 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-169.254.2.79]
2013-12-02 11:07:43,205 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 201 as a part of network implement
2013-12-02 11:07:43,205 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=201 is already implemented
2013-12-02 11:07:43,206 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 201 as a part of network implement
2013-12-02 11:07:43,233 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Allocated a nic NicProfile[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175-null for VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,243 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[201|Management|2] is not associated with any VPC
2013-12-02 11:07:43,244 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.175]
2013-12-02 11:07:43,246 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,246 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
2013-12-02 11:07:43,254 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Boot Args for VM[ConsoleProxy|v-2-VM]: template=domP type=consoleproxy host=192.168.1.165 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.193 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.79 eth0mask=255.255.0.0 eth1ip=192.168.1.175 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.92 dns1=61.177.7.1
2013-12-02 11:07:43,277 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210010: Sending { Cmd , MgmtId: 52234685305, via: 1, 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=192.168.1.165 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.193 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.79 eth0mask=255.255.0.0 eth1ip=192.168.1.175 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.92 dns1=61.177.7.1","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"db880981011a6b2d","params":{},"uuid":"0f51eaf6-1269-449d-bf55-87038851c236","disks":[{"id":2,"name":"ROOT-2","mountPoint":"/primary","path":"dd324d10-c822-4c1b-a3d5-bfb0b84e323c","size":0,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"3c812bf5-0e22-3263-b902-4a65532af2e3","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"badb94d8-94e6-471c-a59d-687cad6fe277","ip":"192.168.1.193","netmask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:ae:3a:00:00:0d","dns1":"61.177.7.1","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"3b89dfe3-a5d4-4acf-98ce-13cc30d51a20","ip":"169.254.2.79","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:4f","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"a76f71f0-9895-4e8b-856f-ad87e62b8df4","ip":"192.168.1.175","netmask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:57:24:00:00:09","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.2.79","port":3922,"interval":6,"retries":100,"name":"v-2-VM","wait":0}}] }
2013-12-02 11:07:43,321 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2013-12-02 11:07:43,384 DEBUG [agent.transport.Request] (AgentManager-Handler-8:null) Seq 1-432210010: Processing: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:701)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
2013-12-02 11:07:43,384 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-8:null) Seq 1-432210010: No more commands found
2013-12-02 11:07:43,384 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210010: Received: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, { Answer, Answer } }
2013-12-02 11:07:43,388 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:80)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-12-02 11:07:43,392 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2013-12-02 11:07:43,395 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210011: Sending { Cmd , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"v-2-VM","wait":0}}] }
2013-12-02 11:07:43,636 DEBUG [agent.transport.Request] (AgentManager-Handler-2:null) Seq 1-432210011: Processing: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-02 11:07:43,636 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-2:null) Seq 1-432210011: No more commands found
2013-12-02 11:07:43,636 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-432210011: Received: { Ans: , MgmtId: 52234685305, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,657 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,658 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,658 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[5-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-192.168.1.193]
2013-12-02 11:07:43,671 DEBUG [network.guru.ControlNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[6-2-null-null-null
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,675 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[6-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,684 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=8c7b1a03-842a-46c7-bedc-63f275cdd83a, instance=7
2013-12-02 11:07:43,686 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[7-2-null-null-null
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,689 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[7-2-8c7b1a03-842a-46c7-bedc-63f275cdd83a-null]
2013-12-02 11:07:43,690 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully released network resources for the vm VM[ConsoleProxy|v-2-VM]
2013-12-02 11:07:43,690 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2013-12-02 11:07:43,699 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: 1
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 1, old used: 500,reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-02 11:07:43,705 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 1, old used: 1073741824,reserved: 0, total: 270832836608; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-02 11:07:43,708 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to get answer that is of class com.cloud.agent.api.StartAnswer
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is of class com.cloud.agent.api.StartAnswer
at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
... 19 more
2013-12-02 11:07:57,947 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
houqd2012@163.com
发件人： tanthalas
发送时间： 2013-12-01 21:26
收件人： users-cn
主题： Re: 系统虚拟机无法创建成功
从libvirtd的log来看，有可能是存储有问题，比如权限之类的，建不了目录。
CloudStack的log，你要在exception这个关键字前面再看看有没有报错原因。
刘宇超 Richard Liu
发件人： houqd2012@163.com
发送时间： 2013-11-30 23:04:12
收件人： users-cn
抄送：
主题： 系统虚拟机无法创建成功
各位：
我的环境是CS4.0.1+kvm，区域可以创建成功，可是系统虚拟机一直无法创建成功，一直创建删除、创建删除。
agent.log的日志为：
2013-11-30 23:01:08,723 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-11-30 23:01:08,724 WARN [cloud.agent.Agent] (agentRequest-Handler-1:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
libvirtd.log 中的错误日志：
2013-11-30 14:45:28.379+0000: 22402: error : virFileOpenForceOwnerMode:807 : cannot chown '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk' to (0, 0): Invalid argument
2013-11-30 14:45:28.379+0000: 22402: error : virStorageBackendCreateRaw:412 : cannot create path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk': Invalid argument
2013-11-30 14:45:28.494+0000: 22400: error : virStorageBackendVolOpenCheckMode:1049 : cannot open volume '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/45052b17-61e9-4387-af47-9c4a756755a5': No such file or directory
2013-11-30 14:50:01.984+0000: 22403: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.322+0000: 22400: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.322+0000: 22400: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.400+0000: 22402: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.400+0000: 22402: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
houqd2012@163.com
Re: 系统虚拟机无法创建成功
Posted by tanthalas <ta...@hotmail.com>.
从libvirtd的log来看，有可能是存储有问题，比如权限之类的，建不了目录。
CloudStack的log，你要在exception这个关键字前面再看看有没有报错原因。
刘宇超 Richard Liu
发件人： houqd2012@163.com
发送时间： 2013-11-30 23:04:12
收件人： users-cn
抄送：
主题： 系统虚拟机无法创建成功
各位：
我的环境是CS4.0.1+kvm，区域可以创建成功，可是系统虚拟机一直无法创建成功，一直创建删除、创建删除。
agent.log的日志为：
2013-11-30 23:01:08,723 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) Exception
com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'dd324d10-c822-4c1b-a3d5-bfb0b84e323c'
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:90)
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:404)
at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:113)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2888)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-11-30 23:01:08,724 WARN [cloud.agent.Agent] (agentRequest-Handler-1:null) Caught:
java.lang.NullPointerException
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
at com.cloud.agent.Agent.processRequest(Agent.java:518)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
libvirtd.log 中的错误日志：
2013-11-30 14:45:28.379+0000: 22402: error : virFileOpenForceOwnerMode:807 : cannot chown '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk' to (0, 0): Invalid argument
2013-11-30 14:45:28.379+0000: 22402: error : virStorageBackendCreateRaw:412 : cannot create path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/s-28-VM-patchdisk': Invalid argument
2013-11-30 14:45:28.494+0000: 22400: error : virStorageBackendVolOpenCheckMode:1049 : cannot open volume '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3/45052b17-61e9-4387-af47-9c4a756755a5': No such file or directory
2013-11-30 14:50:01.984+0000: 22403: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.322+0000: 22400: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.322+0000: 22400: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
2013-11-30 14:50:48.400+0000: 22402: error : virCommandWait:2272 : internal error Child process (/bin/mount 192.168.1.165:/primary /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3) unexpected exit status 1: mount.nfs: mount point /mnt/3c812bf5-0e22-3263-b902-4a65532af2e3 does not exist
2013-11-30 14:50:48.400+0000: 22402: error : virStorageBackendFileSystemRefresh:823 : cannot open path '/mnt/3c812bf5-0e22-3263-b902-4a65532af2e3': No such file or directory
houqd2012@163.com