shwstppr commented on issue #8034:
URL: https://github.com/apache/cloudstack/issues/8034#issuecomment-1746346516
I'm able to reproduce this behviour and problem with snapshots having
backing_files.
- Deployed a test VM. Stopped it. Took ROOT volume snapshot
- Deleted the VM. This deleted cached template files on the primary store
when storage GC ran.
- Created a new template from the snapshot <- This got created successfully
- Tried deploying a VM with the new template <- This failed
```
2023-10-04 07:57:28,675 ERROR [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-19:ctx-9609c044 job-129/job-131 ctx-a74d034e)
(logid:84378832) Unable to create volume
[{"name":"ROOT-11","uuid":"62662375-984a-4ad2-be79-49e4a156133d"}] due to
[com.cloud.utils.exception.CloudRuntimeException: Failed to copy
/mnt/99ceb614-2662-38a9-843c-53b0d26b3515/f7f32a7d-5170-472a-9ca4-51556ff7d0f5.qcow2
to c57053ea-ea69-4c2c-846b-39e7a8dc2248].
2023-10-04 07:57:28,675 WARN [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-19:ctx-9609c044 job-129/job-131 ctx-a74d034e)
(logid:84378832) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is
unreachable: Unable to create volume
[{"name":"ROOT-11","uuid":"62662375-984a-4ad2-be79-49e4a156133d"}] due to
[com.cloud.utils.exception.CloudRuntimeException: Failed to copy
/mnt/99ceb614-2662-38a9-843c-53b0d26b3515/f7f32a7d-5170-472a-9ca4-51556ff7d0f5.qcow2
to c57053ea-ea69-4c2c-846b-39e7a8dc2248].
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume(VolumeOrchestrator.java:1814)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1923)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy227.prepare(Unknown Source)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1266)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5412)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5536)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
```
Agent logs from host
```
2023-10-04 07:57:28,560 DEBUG [kvm.storage.KVMStorageProcessor]
(agentRequest-Handler-1:null) (logid:84378832) Copying template to primary
storage, template format is qcow2
2023-10-04 07:57:28,560 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:84378832) Trying to fetch storage pool
74659b4e-12be-388d-9877-2c992e20b732 from libvirt
2023-10-04 07:57:28,560 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-1:null) (logid:84378832) Looking for libvirtd connection
at: qemu:///system
2023-10-04 07:57:28,562 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:84378832) Successfully refreshed pool
74659b4e-12be-388d-9877-2c992e20b732 Capacity: (1.9685 TB) 2164372013056 Used:
(253.98 GB) 272709451776 Available: (1.7205 TB) 1891662561280
2023-10-04 07:57:28,562 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:84378832) Trying to fetch storage pool
74659b4e-12be-388d-9877-2c992e20b732 from libvirt
2023-10-04 07:57:28,562 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-1:null) (logid:84378832) Looking for libvirtd connection
at: qemu:///system
2023-10-04 07:57:28,564 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:84378832) Successfully refreshed pool
74659b4e-12be-388d-9877-2c992e20b732 Capacity: (1.9685 TB) 2164372013056 Used:
(253.98 GB) 272709451776 Available: (1.7205 TB) 1891662561280
2023-10-04 07:57:28,564 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:84378832) copyPhysicalDisk: disk
size:(1.00 MB) 1048576, virtualsize:(50.00 MB) 52428800 format:qcow2
2023-10-04 07:57:28,564 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) (logid:84378832) Attempting to create volume
c57053ea-ea69-4c2c-846b-39e7a8dc2248 (NetworkFilesystem) in pool
74659b4e-12be-388d-9877-2c992e20b732 with size (50.00 MB) 52428800
2023-10-04 07:57:28,564 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-1:null) (logid:84378832) Looking for libvirtd connection
at: qemu:///system
2023-10-04 07:57:28,565 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing: qemu-img create -o
preallocation=off -f qcow2
/mnt/74659b4e-12be-388d-9877-2c992e20b732/c57053ea-ea69-4c2c-846b-39e7a8dc2248
52428800
2023-10-04 07:57:28,566 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing while with timeout :
3600000
2023-10-04 07:57:28,590 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Execution is successful.
2023-10-04 07:57:28,590 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Formatting
'/mnt/74659b4e-12be-388d-9877-2c992e20b732/c57053ea-ea69-4c2c-846b-39e7a8dc2248',
fmt=qcow2 size=52428800 encryption=off cluster_size=65536 preallocation='off'
lazy_refcounts=off
2023-10-04 07:57:28,590 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing: qemu-img info
/mnt/74659b4e-12be-388d-9877-2c992e20b732/c57053ea-ea69-4c2c-846b-39e7a8dc2248
2023-10-04 07:57:28,591 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing while with timeout :
3600000
2023-10-04 07:57:28,604 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Execution is successful.
2023-10-04 07:57:28,604 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-1:null) (logid:84378832) Looking for libvirtd connection
at: qemu:///system
2023-10-04 07:57:28,605 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing: qemu-img info
/mnt/99ceb614-2662-38a9-843c-53b0d26b3515/f7f32a7d-5170-472a-9ca4-51556ff7d0f5.qcow2
2023-10-04 07:57:28,607 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing while with timeout :
3600000
2023-10-04 07:57:28,624 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Execution is successful.
2023-10-04 07:57:28,625 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing: qemu-img convert -O
qcow2
/mnt/99ceb614-2662-38a9-843c-53b0d26b3515/f7f32a7d-5170-472a-9ca4-51556ff7d0f5.qcow2
/mnt/74659b4e-12be-388d-9877-2c992e20b732/c57053ea-ea69-4c2c-846b-39e7a8dc2248
2023-10-04 07:57:28,626 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Executing while with timeout :
10800000
2023-10-04 07:57:28,644 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) Exit value is 1
2023-10-04 07:57:28,644 DEBUG [utils.script.Script]
(agentRequest-Handler-1:null) (logid:84378832) qemu-img: Could not open
'/mnt/99ceb614-2662-38a9-843c-53b0d26b3515/f7f32a7d-5170-472a-9ca4-51556ff7d0f5.qcow2':
Could not open backing file: Could not open
'/mnt/760626fb-2450-3276-ad82-8a4cc91110b5/a9388628-b90d-41ec-917a-6008011e779c':
No such file or directoryqemu-img: Could not open
'/mnt/99ceb614-2662-38a9-843c-53b0d26b3515/f7f32a7d-5170-472a-9ca4-51556ff7d0f5.qcow2'
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
