cloudstack-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Suresh Sadhu <Suresh.Sa...@citrix.com>
Subject RE: Cannot create VM instance using template converted from snapshot
Date Mon, 21 Oct 2013 09:00:56 GMT
Your assumption is right and  it's a bug. An  issue exits for the same in open state .please
update your observation in below bug:

    CLOUDSTACK-4549 ceph:deployvm from template created from snapshot is failing

https://issues.apache.org/jira/browse/CLOUDSTACK-4549


regards
sadhu


-----Original Message-----
From: Indra Pramana [mailto:indra@sg.or.id] 
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 convert the snapshot
into a template. However, we are not able to create a new VM instance based on the template.Error
messages on both the management-server.log and agent.log shows that the problem happened during
the creation of the volume, specifically during the copying of the template from secondary
storage for volume creation.

Logs on management-server.log:

=====
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.Answer":{"result":false,"details":"
java.lang.NullPointerException\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2469)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingR
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) ===START===  103.25.200.2
-- GET command=queryAsyncJobResult&jobId=1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&response=json&sessionkey=PA1sQOGCDpcgv9KuxH6rulGrhhM%3D&
_=1381895842670
2013-10-16 11:57:23,594 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===END===  103.25.200.2
-- GET command=queryAsyncJobResult&jobId=1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&response=json&sessionkey=PA1sQOGCDpcgv9KuxH6rulGrhhM%3D&_=
1381895842670
2013-10-16 11:57:26,547 DEBUG [cloud.api.ApiServlet]
(catalina-exec-22:null) ===START===  103.25.200.2 -- GET command=queryAsyncJobResult&jobId=1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&response=json&sessionkey=PA1sQOGCDpcgv9KuxH6rulGrhhM%3D
&_=1381895845670
2013-10-16 11:57:26,602 DEBUG [cloud.api.ApiServlet]
(catalina-exec-22:null) ===END===  103.25.200.2 -- GET command=queryAsyncJobResult&jobId=1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a&response=json&sessionkey=PA1sQOGCDpcgv9KuxH6rulGrhhM%3D&_
=1381895845670
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.ConsoleProxyLoadReportComman
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.cloudstack.storage.command.CopyCmdAnswer":{
"result":false,"details":"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,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 = [ 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 = [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) releasing lock for VMTemplateStoragePool
122
2013-10-16 11:57:28,145 WARN  [utils.db.Merovingian2]
(Job-Executor-3:job-2437 = [ 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 = [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) Unable to create
Vol[2346|vm=2087|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-5a2d3f2728fe
2013-10-16 11:57:28,146 INFO  [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-2437 = [ 1a5ba5a7-5756-4bae-bf21-67fc4d1b5a5a ]) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:214] is unreachable:
Unable to create
Vol[2346|vm=2087|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-5a2d3f2728fe
=====

Logs on agent.log:

=====
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.storage.command.CopyCommand":{"srcTO":{"o
rg.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/203/310/61e60cb9-88ec-401a-b7f8-940a568c23c2.raw","uuid":"0cc44db5-ef14-4f43-b7ba-151990c8d5b0","id":310,"format":"RAW","accountId":203,"hvm":true,"displayText":"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.apache.cloud
stack.storage.to.TemplateObjectTO":{"uuid":"0cc44db5-ef14-4f43-b7ba-151990c8d5b0","id":310,"format":"RAW","accountId":203,"hvm":true,"displayText":"Root-2080-Template","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreT
O":{"uuid":"d433809b-01ea-3947-ba0f-48077244e4d6","id":214,"poolType":"RBD","host":"
xxxx.xxxx.xxxx.com <http://ceph-mon.simplercloud.com>
","path":"xxxxx-sg-01","port":6789}},"name":"205d49dd361-8fe6-3ab5-873f-fc5e17b60353","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=$(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=$(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 running pool: org.libvirt.LibvirtException:
Storage pool not found: no storage pool with matching uuid  ����a^W>~�h�Äp�,
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 duplicate 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) <pool type='netfs'> <name>91afb8e1-6117-3e7e-a068-f980c49570a4</name>
<uuid>91afb8e1-6117-3e7e-a068-f980c49570a4</uuid>
<source>
<host name='x.x.x.x'/>
<dir path='/mnt/vol1/sec-storage2/template/tmpl/203/310'/>
</source>
<target>
<path>/mnt/91afb8e1-6117-3e7e-a068-f980c49570a4</path>
</target>
</pool>

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 �r^\E^Lw3��@^_��e�M
        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(LibvirtStorageAdaptor.java:363)
        at
com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePool(KVMStoragePoolManager.java:104)
        at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2466)
        at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.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:1146)
        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(LibvirtComputingResource.java:2469)
        at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.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:1146)
        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(LibvirtComputingResource.java:2469)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.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 destination 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-f980c49570a4/61e60cb9-88ec-401a-b7f8-940a568c23c2.raw
to /tmp/b622fa54-aa6e-424d-a351-5a2d3f2728fe as  a temporary file for RBD conversion
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-940a568c23c2.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-940a568c23c2.raw':
Wrong medium typeqemu-img: Could not open '/ mnt/91afb8e1-6117-3e7e-a068-f980c49570a4/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/91afb8e1-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-940a568c23c2.raw':
Wrong medium typeqemu-img: Could not open '/mnt/91afb8e1-6117-3e7e-a068-f980c49570a4/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.storage.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.StopCommand":{"isProxy":false,"executeInSeq
uence":true,"vmName":"i-203-2087-VM","wait":0}}] } =====

It seems that the problem is because the template is being saved in .raw instead of .qcow2,
and for some reason, qemu-img is not able to do the conversion? Is it because we are using
Ceph RBD for primary storage?

Looking forward to your reply, thank you.

Cheers.

Mime
View raw message