You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "edison su (JIRA)" <ji...@apache.org> on 2013/07/08 20:25:48 UTC
[jira] [Closed] (CLOUDSTACK-3329) [Automation] Failed to deploy VM with "NullPointer Exception” , and observed LibvirtException: name in virStorageVolLookupByName must not be NULL in agent log
[ https://issues.apache.org/jira/browse/CLOUDSTACK-3329?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
edison su closed CLOUDSTACK-3329.
---------------------------------
Resolution: Fixed
It's the same bug, as reported long time ago, that the storage pool is missing on kvm host, then createcommand failed, but mgt server didn't catch this error, sending out startcommand to kvm host regardless the failure of createcommand. Add a fix, mgt server needs to honor the result of createcommand.
> [Automation] Failed to deploy VM with "NullPointer Exception” , and observed LibvirtException: name in virStorageVolLookupByName must not be NULL in agent log
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-3329
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3329
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Automation, Volumes
> Affects Versions: 4.2.0
> Environment: KVM
> master-6-17-stable
> Reporter: Rayees Namathponnan
> Assignee: edison su
> Priority: Blocker
> Fix For: 4.2.0
>
> Attachments: CLOUDSTACK-3329.rar
>
>
> This issue observed during automation run in KVM
> Here taking Job : 151 for reference
> 1) VR created successfully
> 2013-07-02 04:54:18,306 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-4:job-151) Start completed for VM VM[DomainRouter|r-37-QA]
> 2013-07-02 04:54:18,308 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-4:job-151) Reprogramming network Ntwk[222|Guest|8] as a part of network implement
> 2013-07-02 04:54:18,317 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-4:job-151) Applying ip association in network Ntwk[222|Guest|8]
> 2) Create volume completed successfully
> 2013-07-02 04:55:48,634 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-4:job-151) Checking if we need to prepare 1 volumes for VM[User|2c6aada6-d82e-4edc-bed1-01f21726e43f]
> 2013-07-02 04:55:48,639 DEBUG [storage.image.ImageDataFactoryImpl] (Job-Executor-4:job-151) template 4 is not in store:1, type:Image
> 2013-07-02 04:55:48,655 DEBUG [agent.transport.Request] (Job-Executor-4:job-151) Seq 5-1791689215: Waiting for Seq 1791689211 Scheduling: { Cmd , MgmtId: 29066118877352, via: 5, Ver: v1, Flags: 100111, [{"storage.CreateCommand":{"volId":41,"pool":{"id":1,"uuid":"fff90cb5-06dd-33b3-8815-d78c08ca01d9","host":"10.223.110.232","path":"/export/home/rayees/SC_QA_AUTO4/primary","port":2049,"type":"NetworkFilesystem"},"diskCharacteristics":{"size":8589934592,"tags":[],"type":"ROOT","name":"ROOT-36","useLocalStorage":false,"recreatable":true,"diskOfferingId":39,"volumeId":41},"templateUrl":"3fd1c1cd-6583-46eb-b2e6-e7ac7e933ecc","wait":0}}] }
> 2013-07-02 04:55:48,766 DEBUG [agent.transport.Request] (AgentManager-Handler-7:null) Seq 5-1791689211: Processing: { Ans: , MgmtId: 29066118877352, via: 5, Ver: v1, Flags: 110, [{"storage.CreateAnswer":{"volume":{"id":45,"name":"/export/home/rayees/SC_QA_AUTO4/primary2","mountPoint":"5a1b1c5a-5d60-451e-b74b-aea295be9ba6","path":"5a1b1c5a-5d60-451e-b74b-aea295be9ba6","size":276572672,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"41b632b5-40b3-3024-a38b-ea259c72579f","deviceId":0},"requestTemplateReload":false,"result":true,"wait":0}}] }
> 3) Observed below error in MS log
> 2013-07-02 04:55:49,255 DEBUG [agent.transport.Request] (AgentManager-Handler-10:null) Seq 4-829227230: Processing: { Ans: , MgmtId: 29066118877352, via: 4, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: name in virStorageVolLookupByName must not be NULL\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:106)\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:401)\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:123)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:3455)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:3346)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1211)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}}] }
> 2013-07-02 04:55:49,256 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-10:null) Seq 4-829227230: No more commands found
> 2013-07-02 04:55:49,256 DEBUG [agent.transport.Request] (Job-Executor-4:job-151) Seq 4-829227230: Received: { Ans: , MgmtId: 29066118877352, via: 4, Ver: v1, Flags: 110, { Answer } }
> 2013-07-02 04:55:49,259 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-4:job-151) Failed to start instance VM[User|2c6aada6-d82e-4edc-bed1-01f21726e43f]
> 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:878)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:554)
> at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:239)
> at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3326)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2864)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2850)
> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
> at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-07-02 04:55:49,263 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-4:job-151) Cleaning up resources for the vm VM[User|2c6aada6-d82e-4edc-bed1-01f21726e43f] in Starting state
> 2013-07-02 04:55:49,264 DEBUG [agent.transport.Request] (Job-Executor-4:job-151) Seq 4-829227231: Sending { Cmd , MgmtId: 29066118877352, via: 4, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-20-36-QA","wait":0}}] }
> Followed by null pointer exception
> 2013-07-02 04:55:49,597 WARN [apache.cloudstack.alerts] (Job-Executor-4:job-151) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 36, on Host with Id: null
> 2013-07-02 04:55:49,641 ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-4:job-151) Unexpected exception while executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd
> java.lang.NullPointerException
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:764)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:554)
> at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:243)
> at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3326)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2864)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2850)
> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
> at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-07-02 04:55:49,642 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-4:job-151) Complete async job-151, jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: null
> Observed below error in agent log
> 2013-07-02 09:03:27,900 WARN [cloud.agent.Agent] (agentRequest-Handler-3:null) Caught:
> com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: name in virStorageVolLookupByName must not be NULL
> at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:106)
> at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.java:401)
> at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysicalDisk(LibvirtStoragePool.java:123)
> at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:3455)
> at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:3346)
> at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1211)
> at com.cloud.agent.Agent.processRequest(Agent.java:525)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)
> 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:679)
> 2013-07-02 09:04:38,577 WARN [cloud.agent.Agent] (agentRequest-Handler-5:null) Caught:
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira