[GitHub] [cloudstack] GutoVeronezi commented on pull request #5282: Fix regression on create volume from snapshot

[GitBox <gi...@apache.org>]

GutoVeronezi commented on pull request #5282:
URL: https://github.com/apache/cloudstack/pull/5282#issuecomment-893661966


   @DaanHoogland this is the full log of the error:
   
   ```
   2021-08-05 00:16:12,138 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-2:ctx-1ec8a162 job-18853) (logid:ad059be6) Unexpected exception while executing org.apache.cloudstack.api.command.admin.volume.CreateVolumeCmdByAdmin
   com.cloud.utils.exception.CloudRuntimeException: Failed to create volume: 5786
           at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:901)
           at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:201)
           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.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
           at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
           at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
           at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
           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.createVolume(Unknown Source)
           at org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd.execute(CreateVolumeCmd.java:225)
           at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
           at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
           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)
   Caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to create volume from snapshot:com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt/e9ad8c2e-59f6-3886-aebd-a1c7da36028a/5769 to e5f21e96-9ee9-4f87-8b20-10b82d7dbcf6
           at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolumeFromSnapshot(VolumeOrchestrator.java:494)
           at com.cloud.storage.VolumeApiServiceImpl.createVolumeFromSnapshot(VolumeApiServiceImpl.java:923)
           at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:873)
           ... 31 more
   2021-08-05 00:16:12,150 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-2:ctx-1ec8a162 job-18853) (logid:ad059be6) Complete async job-18853, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Failed to create volume: 5786"}
   ```
   
   The NPE does not appear in the stack trace because it's being hidden; Therefore I mapped the hierarchy to facilitate the comprehension:
   
   - `VolumeApiServiceImpl::createVolume(CreateVolumeCmd)`, L873, `cmd.getVirtualMachineId()` is null, therefore it calls:
   - `VolumeApiServiceImpl::createVolumeFromSnapshot(VolumeVO, long, Long)` with a null `vmId`. As `vmId` is null, it will not instantiate `vm`. In L923, it calls: 
   - `VolumeOrchestrator::createVolumeFromSnapshot(Volume, Snapshot, UserVm)` with a null `vm`, then, in L434 it calls:
   - `VolumeOrchestrator::findStoragePool(DiskProfile, DataCenter, Pod, Long, Long, VirtualMachine, Set<StoragePool>)` with `vm` parameter null. It will instantiate a `VirtualMachineProfile` with null `vm` in L315 and in L324 it calls:
   - `AbstractStoragePoolAllocator::allocateToPool(DiskProfile, VirtualMachineProfile, DeploymentPlan, ExcludeList, int)`. In L97 it calls:
   - `AbstractStoragePoolAllocator::allocateToPool(DiskProfile, VirtualMachineProfile, DeploymentPlan, ExcludeList, int, boolean)` which, in L103, will call:
   - `AbstractStoragePoolAllocator::reorderPools(List<StoragePool>, VirtualMachineProfile, DeploymentPlan, DiskProfile)`. Here `vmProfile` is not null, but its property `_vm` is, therefore, when, in L193, it calls:
   - `VirtualMachineProfileImpl::getHypervisorType()`, it will throw a NPE due to the null `_vm`.
   
   Also, I added a commit to log the exception before throwing the `CloudRuntimeException`.
   
   ---
   About the remark, we choose to validate the `getVirtualMachine()` before the reorder block to add the log.


-- 
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: commits-unsubscribe@cloudstack.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org