Return-Path: X-Original-To: apmail-cloudstack-dev-archive@www.apache.org Delivered-To: apmail-cloudstack-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 67B6D10877 for ; Mon, 21 Oct 2013 09:01:37 +0000 (UTC) Received: (qmail 49488 invoked by uid 500); 21 Oct 2013 09:01:31 -0000 Delivered-To: apmail-cloudstack-dev-archive@cloudstack.apache.org Received: (qmail 49426 invoked by uid 500); 21 Oct 2013 09:01:29 -0000 Mailing-List: contact dev-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 dev@cloudstack.apache.org Received: (qmail 49407 invoked by uid 99); 21 Oct 2013 09:01:28 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 21 Oct 2013 09:01:28 +0000 X-ASF-Spam-Status: No, hits=-5.0 required=5.0 tests=RCVD_IN_DNSWL_HI,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of Suresh.Sadhu@citrix.com designates 66.165.176.89 as permitted sender) Received: from [66.165.176.89] (HELO SMTP.CITRIX.COM) (66.165.176.89) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 21 Oct 2013 09:01:22 +0000 X-IronPort-AV: E=Sophos;i="4.93,537,1378857600"; d="scan'208";a="65514344" Received: from sinpex01cl01.citrite.net ([10.151.46.32]) by FTLPIPO01.CITRIX.COM with ESMTP/TLS/AES128-SHA; 21 Oct 2013 09:00:58 +0000 Received: from SINPEX01CL02.citrite.net ([169.254.2.76]) by SINPEX01CL01.citrite.net ([169.254.1.152]) with mapi id 14.02.0342.004; Mon, 21 Oct 2013 17:00:56 +0800 From: Suresh Sadhu To: "dev@cloudstack.apache.org" , "users@cloudstack.apache.org" Subject: RE: Cannot create VM instance using template converted from snapshot Thread-Topic: Cannot create VM instance using template converted from snapshot Thread-Index: AQHOziPc9HXuj+1x7E2kaELV3VOCAJn+2ohw Date: Mon, 21 Oct 2013 09:00:56 +0000 Message-ID: <5A4FE8EFA8C8584CBEFEEACD9AA077EE141FE438@SINPEX01CL02.citrite.net> References: In-Reply-To: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-originating-ip: [10.252.192.97] Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 X-Virus-Checked: Checked by ClamAV on apache.org Your assumption is right and it's a bug. An issue exits for the same in o= pen state .please update your observation in below bug: CLOUDSTACK-4549 ceph:deployvm from template created from snapshot is fa= iling https://issues.apache.org/jira/browse/CLOUDSTACK-4549 regards sadhu -----Original Message----- From: Indra Pramana [mailto:indra@sg.or.id]=20 Sent: 21 October 2013 11:29 To: users@cloudstack.apache.org; dev@cloudstack.apache.org Subject: Cannot create VM instance using template converted from snapshot Dear all, We are using CloudStack 4.2.0, KVM hypervisors and Ceph RBD primary storage= . We are able to create a volume snapshot of a VM instance's root-disk, and c= onvert the snapshot into a template. However, we are not able to create a n= ew VM instance based on the template.Error messages on both the management-= server.log and agent.log shows that the problem happened during the creatio= n of the volume, specifically during the copying of the template from secon= dary storage for volume creation. Logs on management-server.log: =3D=3D=3D=3D=3D 2013-10-16 11:57:23,118 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 34-1629225029: Processing: { Ans: , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 10, [{"com.cloud.agent.api.A= nswer":{"result":false,"details":" java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtC= omputingResource.java:2469)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(L= ibvirtComputingR esource.java:1230)\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.ThreadPoolEx ecutor.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-10-16 11:57:23,119 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 34-1629225029: Received: { Ans: , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 10, { Answer } } 2013-10-16 11:57:23,549 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)= =3D=3D=3DSTART=3D=3D=3D 103.25.200.2 -- GET command=3DqueryAsyncJobResult= &jobId=3D1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&response=3Djson&sessionkey=3D= PA1sQOGCDpcgv9KuxH6rulGrhhM%3D& _=3D1381895842670 2013-10-16 11:57:23,594 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)= =3D=3D=3DEND=3D=3D=3D 103.25.200.2 -- GET command=3DqueryAsyncJobResult&j= obId=3D1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&response=3Djson&sessionkey=3DPA= 1sQOGCDpcgv9KuxH6rulGrhhM%3D&_=3D 1381895842670 2013-10-16 11:57:26,547 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) =3D=3D=3DSTART=3D=3D=3D 103.25.200.2 -- GET comman= d=3DqueryAsyncJobResult&jobId=3D1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&respon= se=3Djson&sessionkey=3DPA1sQOGCDpcgv9KuxH6rulGrhhM%3D &_=3D1381895845670 2013-10-16 11:57:26,602 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) =3D=3D=3DEND=3D=3D=3D 103.25.200.2 -- GET command= =3DqueryAsyncJobResult&jobId=3D1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&respons= e=3Djson&sessionkey=3DPA1sQOGCDpcgv9KuxH6rulGrhhM%3D&_ =3D1381895845670 2013-10-16 11:57:27,255 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 61-109650: Processing Seq 61-109650: {= Cmd , MgmtId: -1, via: 61, Ver: v1, Flags: 11, [{"com.cloud.agent.api.Cons= oleProxyLoadReportComman d":{"_proxyVmId":2039,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}]= } 2013-10-16 11:57:27,278 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 61-109650: Sending Seq 61-109650: { Ans: , MgmtId: 161342671900, via: 61, Ver: v1, Flags: 100010, [{"com.cloud.= agent.api.AgentControlAnsw er":{"result":true,"wait":0}}] } 2013-10-16 11:57:28,060 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 34-1629225027: Processing: { Ans: , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 110, [{"org.apache.cloudstac= k.storage.command.CopyCmdAnswer":{ "result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt/91afb8e1-6117-3e7e-a068-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c2= 3c2.raw to b622fa54-aa6e-424d-a351-5a2d3f2728fe","wait":0}}] } 2013-10-16 11:57:28,060 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-15:null) Seq 34-1629225027: No more commands found 2013-10-16 11:57:28,060 DEBUG [agent.transport.Request] (Job-Executor-3:job-2437 =3D [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) Seq 34-1629225027: Received: { Ans: , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 110, { CopyCmdAnswer } } 2013-10-16 11:57:28,144 INFO [storage.volume.VolumeServiceImpl] (Job-Executor-3:job-2437 =3D [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) rele= asing lock for VMTemplateStoragePool 122 2013-10-16 11:57:28,145 WARN [utils.db.Merovingian2] (Job-Executor-3:job-2437 =3D [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) Was = unable to find lock for the key template_spool_ref122 and thread id 7779986 2013-10-16 11:57:28,146 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-3:job-2437 =3D [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) Unab= le to create Vol[2346|vm=3D2087|ROOT]:com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt/91afb8e1-6117-3e7e-a068-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c2= 3c2.raw to b622fa54-aa6e-424d-a351-5a2d3f2728fe 2013-10-16 11:57:28,146 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-3:job-2437 =3D [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) Unab= le to contact resource. com.cloud.exception.StorageUnavailableException: Resource [StoragePool:214]= is unreachable: Unable to create Vol[2346|vm=3D2087|ROOT]:com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt/91afb8e1-6117-3e7e-a068-f980c49570a4 /61e60cb9-88ec-401a-b7f8-940a568c23c2.raw to b622fa54-aa6e-424d-a351-5a2d3f= 2728fe =3D=3D=3D=3D=3D Logs on agent.log: =3D=3D=3D=3D=3D 2013-10-16 11:57:19,480 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) Request:Seq 34-1629225027: { Cmd , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.sto= rage.command.CopyCommand":{"srcTO":{"o rg.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/20= 3/310/61e60cb9-88ec-401a-b7f8-940a568c23c2.raw","uuid":"0cc44db5-ef14-4f43-= b7ba-151990c8d5b0","id":310,"format":"RAW","accountId":203,"hvm":true,"disp= layText":"Ro ot-2080-Template","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":= "nfs://x.x.x.x/mnt/vol1/sec-storage2","_role":"Image"}},"name":"205d49dd361= -8fe6-3ab5-873f-fc5e17b60353","hypervisorType":"KVM"}},"destTO":{"org.apach= e.cloud stack.storage.to.TemplateObjectTO":{"uuid":"0cc44db5-ef14-4f43-b7ba-151990c= 8d5b0","id":310,"format":"RAW","accountId":203,"hvm":true,"displayText":"Ro= ot-2080-Template","imageDataStore":{"org.apache.cloudstack.storage.to.Prima= ryDataStoreT O":{"uuid":"d433809b-01ea-3947-ba0f-48077244e4d6","id":214,"poolType":"RBD"= ,"host":" xxxx.xxxx.xxxx.com ","path":"xxxxx-sg-01","port":6789}},"name":"205d49dd361-8fe6-3ab5-873f-fc5= e17b60353","hypervisorType":"KVM"}},"executeIn Sequence":true,"wait":10800}}] } 2013-10-16 11:57:19,481 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) Processing command: org.apache.cloudstack.storage.command.CopyCommand 2013-10-16 11:57:20,266 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) Processing command: com.cloud.agent.api.GetHostStatsCommand 2013-10-16 11:57:20,267 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) Executing: /bin/bash -c idle=3D$(top -b -n 1|grep Cpu\(s\):|cut -d% -f4|cut -d, -f2);echo $idle 2013-10-16 11:57:20,830 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) Execution is successful. 2013-10-16 11:57:20,831 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) Executing: /bin/bash -c freeMem=3D$(free|grep= cache:|awk '{print $4}');echo $freeMem 2013-10-16 11:57:20,878 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) Execution is successful. 2013-10-16 11:57:20,879 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) Executing: /bin/bash -c free|grep Mem:|awk '{= print $2}' 2013-10-16 11:57:20,926 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) Execution is successful. 2013-10-16 11:57:23,058 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) createStoragePool didn't find existing runnin= g pool: org.libvirt.LibvirtException: Storage pool not found: no storage po= ol with matching uuid =EF=BF=BD=EF=BF=BD=EF=BF=BD=EF=BF=BDa^W>~=EF=BF=BDh= =EF=BF=BD=C4p=EF=BF=BD, need to create it 2013-10-16 11:57:23,058 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) Didn't find an existing storage pool 91afb8e1-6117-3e7e-a068-f980c49570a4 by UUID, checking for pools with dupli= cate paths 2013-10-16 11:57:23,061 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) Checking path of existing pool 22b0d26c-d8fa-= 490e-9382-9b4685e2b08e against pool we want to create 2013-10-16 11:57:23,067 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) Checking path of existing pool d433809b-01ea-3947-ba0f-48077244e4d6 against pool we want to create 2013-10-16 11:57:23,071 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) Checking path of existing pool 6139b132-49ee-= 36d1-8ecb-49588b54913f against pool we want to create 2013-10-16 11:57:23,074 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) Processing command: com.cloud.agent.api.GetStorageStatsCommand 2013-10-16 11:57:23,076 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) Attempting to create storage pool 91afb8e1-6117-3e7e-a068-f980c49570a4 2013-10-16 11:57:23,076 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) 91afb8e1-6117-3e7= e-a068-f980c49570a4 91afb8e1-6117-3e7e-a068-f980c49570a4 /mnt/91afb8e1-6117-3e7e-a068-f980c49570a4 2013-10-16 11:57:23,077 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) can't get storage pool org.libvirt.LibvirtException: Storage pool not found: no storage pool with = matching uuid =EF=BF=BDr^\E^Lw3=EF=BF=BD=EF=BF=BD@^_=EF=BF=BD=EF=BF=BDe=EF= =BF=BDM at org.libvirt.ErrorHandler.processError(Unknown Source) at org.libvirt.Connect.processError(Unknown Source) at org.libvirt.Connect.storagePoolLookupByUUIDString(Unknown Source= ) at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getStoragePool(Libvi= rtStorageAdaptor.java:363) at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePool(KVMSt= oragePoolManager.java:104) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtC= omputingResource.java:2466) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(L= ibvirtComputingResource.java:1230) 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:1= 146) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:= 615) at java.lang.Thread.run(Thread.java:679) 2013-10-16 11:57:23,078 WARN [cloud.agent.Agent] (agentRequest-Handler-2:null) Caught: java.lang.NullPointerException at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtC= omputingResource.java:2469) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(L= ibvirtComputingResource.java:1230) 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:1= 146) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:= 615) at java.lang.Thread.run(Thread.java:679) 2013-10-16 11:57:23,079 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) Seq 34-1629225029: { Ans: , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{= "result":false,"details":"java.lang.NullPoint erException\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtC= omputingResource.java:2469)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(L= ibvirtComputingResource.java:1230)\ 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(Th readPoolExecutor.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-10-16 11:57:27,964 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) The source image is not RBD, but the destinat= ion is. We will convert into RBD format 2 2013-10-16 11:57:27,965 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) Converting /mnt/91afb8e1-6117-3e7e-a068-f980c= 49570a4/61e60cb9-88ec-401a-b7f8-940a568c23c2.raw to /tmp/b622fa54-aa6e-424d-a351-5a2d3f2728fe as a temporary file for RBD c= onversion 2013-10-16 11:57:27,965 DEBUG [utils.script.Script] (agentRequest-Handler-5:null) Executing: qemu-img convert -f qcow2 -O raw /= mnt/91afb8e1-6117-3e7e-a068-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c23= c2.raw /tmp/b622fa54-aa6e-424d-a351 -5a2d3f2728fe 2013-10-16 11:57:28,014 DEBUG [utils.script.Script] (agentRequest-Handler-5:null) Exit value is 1 2013-10-16 11:57:28,016 DEBUG [utils.script.Script] (agentRequest-Handler-5:null) qemu-img: Could not open '/mnt/91afb8e1-6117-3e7e-a068-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c= 23c2.raw': Wrong medium typeqemu-img: Could not open '/ mnt/91afb8e1-6117-3e7e-a068-f9= 80c49570a4/61e60cb9-88ec-401a-b7f8-940a568c23c2.raw' 2013-10-16 11:57:28,016 ERROR [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) Failed to do a temp convert from /mnt/91afb8e= 1-6117-3e7e-a068-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c23c2.raw to /tmp/b622fa54-aa6e-424 d-a351-5a2d3f2728fe the error was: qemu-img: Could not open '/mnt/91afb8e1-6117-3e7e-a068-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c= 23c2.raw': Wrong medium typeqemu-img: Could not open '/mnt/91afb8e1-6117-3e7e-a068-f98= 0c49570a4/61e60c b9-88ec-401a-b7f8-940a568c23c2.raw' 2013-10-16 11:57:28,057 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) Seq 34-1629225027: { Ans: , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storag= e.command.CopyCmdAnswer":{"result":false,"det ails":"com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt= /91afb8e1-6117-3e7e-a068-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c23c2.= raw to b622fa54-aa6e-424d-a351-5a2d3f2728fe","wait":0}}] } 2013-10-16 11:57:28,220 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) Request:Seq 34-1629225030: { Cmd , MgmtId: 161342671900, via: 34, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopC= ommand":{"isProxy":false,"executeInSeq uence":true,"vmName":"i-203-2087-VM","wait":0}}] } =3D=3D=3D=3D=3D It seems that the problem is because the template is being saved in .raw in= stead of .qcow2, and for some reason, qemu-img is not able to do the conver= sion? Is it because we are using Ceph RBD for primary storage? Looking forward to your reply, thank you. Cheers.