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:in...@sg.or.id]
Sent: 21 October 2013 11:29
To: us...@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.
