Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 114AE101A6 for ; Sun, 25 Aug 2013 04:12:54 +0000 (UTC) Received: (qmail 5294 invoked by uid 500); 25 Aug 2013 04:12:53 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 5149 invoked by uid 500); 25 Aug 2013 04:12:53 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 5140 invoked by uid 500); 25 Aug 2013 04:12:52 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 5133 invoked by uid 99); 25 Aug 2013 04:12:51 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 25 Aug 2013 04:12:51 +0000 Date: Sun, 25 Aug 2013 04:12:51 +0000 (UTC) From: "edison su (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (CLOUDSTACK-4459) [Automation] Vm deployment failed in KVM with missing storage pool error MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-4459?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId= =3D13749522#comment-13749522 ]=20 edison su commented on CLOUDSTACK-4459: --------------------------------------- Rayees, could you tell which version of libvirt you are using on kvm host? You can use "yum info libvirt" or something like that to get detailed packa= ge information. "The storage pool not found issue" won't happened in the last week, after I= fixed cloudstack-2729. =20 > [Automation] Vm deployment failed in KVM with missing storage pool error= =20 > ------------------------------------------------------------------------- > > Key: CLOUDSTACK-4459 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-445= 9 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Components: Automation, KVM > Affects Versions: 4.2.0 > Environment: Automation > KVM > Reporter: Rayees Namathponnan > Assignee: edison su > Priority: Critical > Fix For: 4.2.0, 4.2.1 > > Attachments: CLOUDSTACK-4457_Agent.rar, CLOUDSTACK-4457_MS.rar, K= VM_Regression_24_Aug_Agent.rar, KVM_Regression_24_Aug_MS.rar > > > This is observed during automation; few VM deployment failed due to miss= ing storage pool;=20 > See the error from MS > 2013-08-21 19:55:29,239 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-23:job-40 =3D [ 5244a122-13cb-4480-976f-d464c1e461fb ]) Start compl= eted for VM VM[User|1ce406e5-67c5-43fc-8284-8190bf29c42c] > 2013-08-21 19:55:29,285 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-23:job-40 =3D [ 5244a122-13cb-4480-976f-d464c1e461fb ]) Complete async= job-40 =3D [ 5244a122-13cb-4480-976f-d464c1e461fb ], jobStatus: 1, resultC= ode: 0, result: org.apache.cloudstack.api.response.UserVmResponse@d912e1d > 2013-08-21 19:55:29,289 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-23:job-40 =3D [ 5244a122-13cb-4480-976f-d464c1e461fb ]) Done executing= org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-40 =3D [ 524= 4a122-13cb-4480-976f-d464c1e461fb ] > 2013-08-21 19:55:29,400 DEBUG [agent.transport.Request] (AgentManager-Han= dler-6:null) Seq 2-861536310: Processing: { Ans: , MgmtId: 29066118877352,= via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false= ,"details":"com.cloud.utils.exception.CloudRuntimeException: org.libvirt.Li= bvirtException: Storage volume not found: no storage vol with matching name= '8acfcc0f-5389-4d9a-8072-3494b8eb0197'\n\tat com.cloud.hypervisor.kvm.stor= age.LibvirtStorageAdaptor.getVolume(LibvirtStorageAdaptor.java:111)\n\tat c= om.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(Libvi= rtStorageAdaptor.java:411)\n\tat com.cloud.hypervisor.kvm.storage.LibvirtSt= oragePool.getPhysicalDisk(LibvirtStoragePool.java:123)\n\tat com.cloud.hype= rvisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingReso= urce.java:3650)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingRes= ource.execute(LibvirtComputingResource.java:3519)\n\tat com.cloud.hyperviso= r.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingReso= urce.java:1252)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\= n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\ta= t com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.Thr= eadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.con= current.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat ja= va.lang.Thread.run(Thread.java:679)\n","wait":0}}] } > 2013-08-21 19:55:29,401 DEBUG [agent.transport.Request] (Job-Executor-24:= job-41 =3D [ 30ed2109-5ffd-455f-8ad7-3eeff366d9f5 ]) Seq 2-861536310: Recei= ved: { Ans: , MgmtId: 29066118877352, via: 2, Ver: v1, Flags: 10, { Answer= } } > 2013-08-21 19:55:29,404 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-41 =3D [ 30ed2109-5ffd-455f-8ad7-3eeff366d9f5 ]) Failed to s= tart instance VM[User|76e3d7a7-825e-49d2-b663-783b65081d43] > com.cloud.utils.exception.CloudRuntimeException: Unable to get answer tha= t is of class com.cloud.agent.api.StartAnswer > at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80) > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMac= hineManagerImpl.java:917) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineMan= agerImpl.java:575) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerI= mpl.deployVirtualMachine(VMEntityManagerImpl.java:227) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEn= tityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3406) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:2966) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:2952) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(= DeployVMCmd.java:420) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.= java:531) > 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(ThreadPoolEx= ecutor.java:1110) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:603) > at java.lang.Thread.run(Thread.java:679) > 2013-08-21 19:55:29,423 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-41 =3D [ 30ed2109-5ffd-455f-8ad7-3eeff366d9f5 ]) Cleaning up= resources for the vm VM[User|76e3d7a7-825e-49d2-b663-783b65081d43] in Star= ting state > 2013-08-21 19:55:29,424 DEBUG [agent.transport.Request] (Job-Executor-24:= job-41 =3D [ 30ed2109-5ffd-455f-8ad7-3eeff366d9f5 ]) Seq 2-861536311: Sendi= ng { Cmd , MgmtId: 29066118877352, via: 2, Ver: v1, Flags: 100011, [{"com.= cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vm= Name":"i-15-11-QA","wait":0}}] } > 2013-08-21 19:55:29,452 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.223.240.194 -- GET signature=3De4Hny9U69Fy= tbQJvEGXyOINqAnE%3D&apiKey=3DTy4Px5VTEEtyO3iOqLGHgQybcOQSbJSbvjy6EJCorms5oJ= PfsjEHzzrMVuBXvDnBfeURYj25CTJxY6AH7bmTOA&command=3DqueryAsyncJobResult&resp= onse=3Djson&jobid=3D2544e998-5f88-4ed9-92cb-cfc5816196e2 > 2013-08-21 19:55:29,469 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.223.240.194 -- GET signature=3De4Hny9U69Fytb= QJvEGXyOINqAnE%3D&apiKey=3DTy4Px5VTEEtyO3iOqLGHgQybcOQSbJSbvjy6EJCorms5oJPf= sjEHzzrMVuBXvDnBfeURYj25CTJxY6AH7bmTOA&command=3DqueryAsyncJobResult&respon= se=3Djson&jobid=3D2544e998-5f88-4ed9-92cb-cfc5816196e2 > Error from Agent log > 2013-08-21 19:55:48,406 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2= :null) Seq 2-861536309: { Ans: , MgmtId: 29066118877352, via: 2, Ver: v1, = Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":9,"name":"i-13-9= -QA","t > ype":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":268435456,"ma= xRam":268435456,"arch":"x86_64","os":"CentOS 5.5 (64-bit)","bootArgs":"","r= ebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamically= ScaleVm > ":false,"vncPassword":"a60225fa04019d4b","vncAddr":"10.223.50.66","params= ":{},"uuid":"1ce406e5-67c5-43fc-8284-8190bf29c42c","disks":[{"data":{"org.a= pache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"394f3f2b-0fa5-4ec1-898= 6-b41b5 > 8f7ee41","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.= to.PrimaryDataStoreTO":{"uuid":"fff90cb5-06dd-33b3-8815-d78c08ca01d9","id":= 1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/ho= me/raye > es/SC_QA_AUTO4/primary","port":2049}},"name":"ROOT-9","size":8589934592,"= path":"3d447769-65f0-433e-b13a-e168948c6c20","volumeId":10,"vmName":"i-13-9= -QA","accountId":13,"format":"QCOW2","id":10,"hypervisorType":"KVM"}},"disk= Seq":0, > "type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectT= O":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"I= SO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":= "523d8e > 8f-bbac-4da4-946d-a6b27a6b9b63","ip":"10.1.1.217","netmask":"255.255.255.= 0","gateway":"10.1.1.1","mac":"02:00:37:4e:00:01","dns1":"8.8.8.8","broadca= stType":"Vlan","type":"Guest","broadcastUri":"vlan://2306","isolationUri":"= vlan:// > 2306","isSecurityGroupEnabled":false}]},"result":true,"wait":0}}] } > 2013-08-21 19:55:48,445 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5= :null) Request:Seq 2-861536310: { Cmd , MgmtId: 29066118877352, via: 2, Ve= r: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":11,"= name":"i-15-11-QA","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"mi= nRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS 5.5 (64-bit= )","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false= ,"enableDynamicallyScaleVm":false,"vncPassword":"88cb5c1b394aa3fe","params"= :{},"uuid":"76e3d7a7-825e-49d2-b663-783b65081d43","disks":[{"data":{"org.ap= ache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"026f0b34-550f-4888-965e= -83be2728b411","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.stor= age.to.PrimaryDataStoreTO":{"uuid":"fff90cb5-06dd-33b3-8815-d78c08ca01d9","= id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/expor= t/home/rayees/SC_QA_AUTO4/primary","port":2049}},"name":"ROOT-11","size":85= 89934592,"path":"8acfcc0f-5389-4d9a-8072-3494b8eb0197","volumeId":12,"vmNam= e":"i-15-11-QA","accountId":15,"format":"QCOW2","id":12,"hypervisorType":"K= VM"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to= .TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"disk= Seq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultN= ic":true,"uuid":"ae40fb43-0763-42e6-89ea-f48dc6de7316","ip":"10.1.1.28","ne= tmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:21:39:00:01","dns1= ":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://23= 55","isolationUri":"vlan://2355","isSecurityGroupEnabled":false}]},"hostIp"= :"10.223.50.66","executeInSequence":false,"wait":0}}] } > 2013-08-21 19:55:48,446 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5= :null) Processing command: com.cloud.agent.api.StartCommand > 2013-08-21 19:55:48,587 WARN [cloud.agent.Agent] (agentRequest-Handler-5= :null) Caught: > com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtExcep= tion: Storage volume not found: no storage vol with matching name '8acfcc0f= -5389-4d9a-8072-3494b8eb0197' > at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getVolu= me(LibvirtStorageAdaptor.java:111) > at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getPhys= icalDisk(LibvirtStorageAdaptor.java:411) > at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysica= lDisk(LibvirtStoragePool.java:123) > at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cre= ateVbd(LibvirtComputingResource.java:3650) > at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.exe= cute(LibvirtComputingResource.java:3519) > at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.exe= cuteRequest(LibvirtComputingResource.java:1252) > at com.cloud.agent.Agent.processRequest(Agent.java:525) > at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:85= 2) > at com.cloud.utils.nio.Task.run(Task.java:83) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx= ecutor.java:1146) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:615) > at java.lang.Thread.run(Thread.java:679) > 2013-08-21 19:55:48,589 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5= :null) Seq 2-861536310: { Ans: , MgmtId: 29066118877352, via: 2, Ver: v1, = Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cl= oud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: St= orage volume not found: no storage vol with matching name '8acfcc0f-5389-4d= 9a-8072-3494b8eb0197'\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorage= Adaptor.getVolume(LibvirtStorageAdaptor.java:111)\n\tat com.cloud.hyperviso= r.kvm.storage.LibvirtStorageAdaptor.getPhysicalDisk(LibvirtStorageAdaptor.j= ava:411)\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.getPhysi= calDisk(LibvirtStoragePool.java:123)\n\tat com.cloud.hypervisor.kvm.resourc= e.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:3650)\n\= tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(Libv= irtComputingResource.java:3519)\n\tat com.cloud.hypervisor.kvm.resource.Lib= virtComputingResource.executeRequest(LibvirtComputingResource.java:1252)\n\= tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.ag= ent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.= nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.ru= nWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPool= Executor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run= (Thread.java:679)\n","wait":0}}] } > 2013-08-21 19:55:48,658 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3= :null) Request:Seq 2-861536311: { Cmd , MgmtId: 29066118877352, via: 2, Ve= r: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,= "executeInSequence":false,"vmName":"i-15-11-QA","wait":0}}] } > 2013-08-21 19:55:48,659 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3= :null) Processing command: com.cloud.agent.api.StopCommand > 2013-08-21 19:55:48,661 DEBUG [kvm.resource.LibvirtConnection] (agentRequ= est-Handler-3:null) can't find connection: KVM, for vm: i-15-11-QA, continu= e > 2013-08-21 19:55:48,676 DEBUG [kvm.resource.LibvirtConnection] (agentRequ= est-Handler-3:null) can't find connection: LXC, for vm: i-15-11-QA, continu= e > 2013-08-21 19:55:48,676 DEBUG [kvm.resource.LibvirtConnection] (agentRequ= est-Handler-3:null) can't find which hypervisor the vm used , then use the = default hypervisor -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrato= rs For more information on JIRA, see: http://www.atlassian.com/software/jira