[
https://issues.apache.org/jira/browse/CLOUDSTACK-8830?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Suresh Kumar Anaparti updated CLOUDSTACK-8830:
----------------------------------------------
Description:
ISSUE
============
[VMware] VM snapshot fails for 12 min after instance creation
Environment
==================
Product Name: Cloudstack
Hypervisor: VMWare VSphere 6
VM DETAILS
==================
i-84987-16119-VM
TROUBLESHOOTING
==================
I see that the following failure and immediate success result for the
CreateVMSnapshot call
{noformat}
2015-07-24 08:20:55,363 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Seq 80-6161487240196259878: Sending { Cmd , MgmtId:
345051581208, via: 80(ussfoldcsesx112.adslab.local), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CreateVMSnapshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-16119","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"target":{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}]
}
2015-07-24 08:20:55,373 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Seq 80-6161487240196259878: Executing: { Cmd , MgmtId:
345051581208, via: 80(ussfoldcsesx112.adslab.local), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CreateVMSnapshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-16119","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"target":{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}]
}
2015-07-24 08:20:55,374 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-66:ctx-5fbdccd8) (logid:710814a5) Seq 80-6161487240196259878:
Executing request
2015-07-24 08:20:55,523 ERROR [c.c.h.v.m.VmwareStorageManagerImpl]
(DirectAgent-66:ctx-5fbdccd8 ussfoldcsesx112.adslab.local, job-64835/job-64836,
cmd: CreateVMSnapshotCommand) (logid:8b87ab8a) failed to create snapshot for
vm:i-84987-16119-VM due to null
2015-07-24 08:20:55,524 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-66:ctx-5fbdccd8) (logid:8b87ab8a) Seq 80-6161487240196259878:
Response Received:
2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request] (DirectAgent-66:ctx-5fbdccd8)
(logid:8b87ab8a) Seq 80-6161487240196259878: Processing: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CreateVMSnapshotAnswer":{"result":false,"wait":0}}] }
2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Seq 80-6161487240196259878: Received: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10, { CreateVMSnapshotAnswer } }
2015-07-24 08:20:55,525 ERROR [o.a.c.s.v.DefaultVMSnapshotStrategy]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Creating VM snapshot: i-84987-16119-VM_VS_20150724152053 failed
2015-07-24 08:20:55,531 DEBUG [c.c.v.s.VMSnapshotManagerImpl]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Failed to create vm snapshot: 962
com.cloud.utils.exception.CloudRuntimeException: Creating VM snapshot:
i-84987-16119-VM_VS_20150724152053 failed
at
org.apache.cloudstack.storage.vmsnapshot.DefaultVMSnapshotStrategy.takeVMSnapshot(DefaultVMSnapshotStrategy.java:163)
at
com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapshot(VMSnapshotManagerImpl.java:438)
at
com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapshot(VMSnapshotManagerImpl.java:994)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.vm.snapshot.VMSnapshotManagerImpl.handleVmWorkJob(VMSnapshotManagerImpl.java:1021)
at sun.reflect.GeneratedMethodAccessor797.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy198.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:549)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:500)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
{noformat}
{noformat}
2015-07-24 08:23:01,359 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-137:ctx-bcdafb76) (logid:a20017dd) Seq 80-6161487240196259885:
Response Received:
2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request] (DirectAgent-137:ctx-bcdafb76)
(logid:a20017dd) Seq 80-6161487240196259885: Processing: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CreateVMSnapshotAnswer":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":33386,"path":"ROOT-16119-000001","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"vmSnapshotTo":{"id":964,"snapshotName":"i-84987-16119-VM_VS_20150724152253","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"result":true,"details":"","wait":0}}]
}
2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
(logid:a20017dd) Seq 80-6161487240196259885: Received: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10, { CreateVMSnapshotAnswer } }
2015-07-24 08:23:01,382 DEBUG [o.a.c.s.v.DefaultVMSnapshotStrategy]
(Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
(logid:a20017dd) Create vm snapshot i-84987-16119-VM_VS_20150724152253
succeeded for vm: i-84987-16119-VM
2015-07-24 08:23:01,396 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
(logid:a20017dd) Done executing VM work job:
com.cloud.vm.snapshot.VmWorkCreateVMSnapshot{"vmSnapshotId":964,"quiesceVm":false,"userId":1,"accountId":1,"vmId":16119,"handlerName":"VMSnapshotManagerImpl"}
{noformat}
It is not clear from this log what is causing this error "failed to create
snapshot for vm:i-84987-16119-VM due to null"
Interestingly, this VM has guest OS type set to None (138).
REPRO STEPS
==================
Try taking snapshot for 12 min after VM creation. VM snapshot fails for 12 mins
after VM creation.
EXPECTED BEHAVIOR
==================
VM snapshot should be successful from the moment the VM is ready.
ACTUAL BEHAVIOR
==================
VM snapshot is not successful for ~12 minutes
was:
ISSUE
============
[VMware] VM snapshot fails for 12 min after instance creation
Environment
==================
Product Name: Cloudstack
Hypervisor: VMWare VSphere 6
VM DETAILS
==================
i-84987-16119-VM
TROUBLESHOOTING
==================
I see that the following failure and immediate success result for the
CreateVMSnapshot call
{noformat}
2015-07-24 08:20:55,363 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Seq 80-6161487240196259878: Sending { Cmd , MgmtId:
345051581208, via: 80(ussfoldcsesx112.adslab.local), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CreateVMSnapshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-16119","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"target":{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}]
}
2015-07-24 08:20:55,373 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Seq 80-6161487240196259878: Executing: { Cmd , MgmtId:
345051581208, via: 80(ussfoldcsesx112.adslab.local), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CreateVMSnapshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-16119","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"target":{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}]
}
2015-07-24 08:20:55,374 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-66:ctx-5fbdccd8) (logid:710814a5) Seq 80-6161487240196259878:
Executing request
2015-07-24 08:20:55,523 ERROR [c.c.h.v.m.VmwareStorageManagerImpl]
(DirectAgent-66:ctx-5fbdccd8 ussfoldcsesx112.adslab.local, job-64835/job-64836,
cmd: CreateVMSnapshotCommand) (logid:8b87ab8a) failed to create snapshot for
vm:i-84987-16119-VM due to null
2015-07-24 08:20:55,524 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-66:ctx-5fbdccd8) (logid:8b87ab8a) Seq 80-6161487240196259878:
Response Received:
2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request] (DirectAgent-66:ctx-5fbdccd8)
(logid:8b87ab8a) Seq 80-6161487240196259878: Processing: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CreateVMSnapshotAnswer":{"result":false,"wait":0}}] }
2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Seq 80-6161487240196259878: Received: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10, { CreateVMSnapshotAnswer } }
2015-07-24 08:20:55,525 ERROR [o.a.c.s.v.DefaultVMSnapshotStrategy]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Creating VM snapshot: i-84987-16119-VM_VS_20150724152053 failed
2015-07-24 08:20:55,531 DEBUG [c.c.v.s.VMSnapshotManagerImpl]
(Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
(logid:8b87ab8a) Failed to create vm snapshot: 962
com.cloud.utils.exception.CloudRuntimeException: Creating VM snapshot:
i-84987-16119-VM_VS_20150724152053 failed
at
org.apache.cloudstack.storage.vmsnapshot.DefaultVMSnapshotStrategy.takeVMSnapshot(DefaultVMSnapshotStrategy.java:163)
at
com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapshot(VMSnapshotManagerImpl.java:438)
at
com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapshot(VMSnapshotManagerImpl.java:994)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.vm.snapshot.VMSnapshotManagerImpl.handleVmWorkJob(VMSnapshotManagerImpl.java:1021)
at sun.reflect.GeneratedMethodAccessor797.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy198.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:549)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:500)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
{noformat}
{noformat}
2015-07-24 08:23:01,359 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-137:ctx-bcdafb76) (logid:a20017dd) Seq 80-6161487240196259885:
Response Received:
2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request] (DirectAgent-137:ctx-bcdafb76)
(logid:a20017dd) Seq 80-6161487240196259885: Processing: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CreateVMSnapshotAnswer":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":33386,"path":"ROOT-16119-000001","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"vmSnapshotTo":{"id":964,"snapshotName":"i-84987-16119-VM_VS_20150724152253","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"result":true,"details":"","wait":0}}]
}
2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
(logid:a20017dd) Seq 80-6161487240196259885: Received: { Ans: , MgmtId:
345051581208, via: 80, Ver: v1, Flags: 10, { CreateVMSnapshotAnswer } }
2015-07-24 08:23:01,382 DEBUG [o.a.c.s.v.DefaultVMSnapshotStrategy]
(Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
(logid:a20017dd) Create vm snapshot i-84987-16119-VM_VS_20150724152253
succeeded for vm: i-84987-16119-VM
2015-07-24 08:23:01,396 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
(logid:a20017dd) Done executing VM work job:
com.cloud.vm.snapshot.VmWorkCreateVMSnapshot{"vmSnapshotId":964,"quiesceVm":false,"userId":1,"accountId":1,"vmId":16119,"handlerName":"VMSnapshotManagerImpl"}
{noformat}
It is not clear from this log what is causing this error "failed to create
snapshot for vm:i-84987-16119-VM due to null"
Interestingly, this VM has guest OS type set to None (138).
REPRO STEPS
==================
I tried couple of times with different options, could not repro this
EXPECTED BEHAVIOR
==================
VMSnapshot should be successful from the moment the VM is ready
ACTUAL BEHAVIOR
==================
VMSnapshot is not successful for ~12 minutes
> [VMware] VM snapshot fails for 12 min after instance creation
> -------------------------------------------------------------
>
> Key: CLOUDSTACK-8830
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8830
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Reporter: Maneesha
> Assignee: Maneesha
>
> ISSUE
> ============
> [VMware] VM snapshot fails for 12 min after instance creation
> Environment
> ==================
> Product Name: Cloudstack
> Hypervisor: VMWare VSphere 6
> VM DETAILS
> ==================
> i-84987-16119-VM
> TROUBLESHOOTING
> ==================
> I see that the following failure and immediate success result for the
> CreateVMSnapshot call
> {noformat}
> 2015-07-24 08:20:55,363 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
> (logid:8b87ab8a) Seq 80-6161487240196259878: Sending { Cmd , MgmtId:
> 345051581208, via: 80(ussfoldcsesx112.adslab.local), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.CreateVMSnapshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-16119","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
> i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
> 49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"target":{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}]
> }
> 2015-07-24 08:20:55,373 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
> (logid:8b87ab8a) Seq 80-6161487240196259878: Executing: { Cmd , MgmtId:
> 345051581208, via: 80(ussfoldcsesx112.adslab.local), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.CreateVMSnapshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-16119","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
> i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
> 49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"target":{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}]
> }
> 2015-07-24 08:20:55,374 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-66:ctx-5fbdccd8) (logid:710814a5) Seq 80-6161487240196259878:
> Executing request
> 2015-07-24 08:20:55,523 ERROR [c.c.h.v.m.VmwareStorageManagerImpl]
> (DirectAgent-66:ctx-5fbdccd8 ussfoldcsesx112.adslab.local,
> job-64835/job-64836, cmd: CreateVMSnapshotCommand) (logid:8b87ab8a) failed to
> create snapshot for vm:i-84987-16119-VM due to null
> 2015-07-24 08:20:55,524 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-66:ctx-5fbdccd8) (logid:8b87ab8a) Seq 80-6161487240196259878:
> Response Received:
> 2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request] (DirectAgent-66:ctx-5fbdccd8)
> (logid:8b87ab8a) Seq 80-6161487240196259878: Processing: { Ans: , MgmtId:
> 345051581208, via: 80, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.CreateVMSnapshotAnswer":{"result":false,"wait":0}}] }
> 2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
> (logid:8b87ab8a) Seq 80-6161487240196259878: Received: { Ans: , MgmtId:
> 345051581208, via: 80, Ver: v1, Flags: 10, { CreateVMSnapshotAnswer } }
> 2015-07-24 08:20:55,525 ERROR [o.a.c.s.v.DefaultVMSnapshotStrategy]
> (Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
> (logid:8b87ab8a) Creating VM snapshot: i-84987-16119-VM_VS_20150724152053
> failed
> 2015-07-24 08:20:55,531 DEBUG [c.c.v.s.VMSnapshotManagerImpl]
> (Work-Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965)
> (logid:8b87ab8a) Failed to create vm snapshot: 962
> com.cloud.utils.exception.CloudRuntimeException: Creating VM snapshot:
> i-84987-16119-VM_VS_20150724152053 failed
> at
> org.apache.cloudstack.storage.vmsnapshot.DefaultVMSnapshotStrategy.takeVMSnapshot(DefaultVMSnapshotStrategy.java:163)
> at
> com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapshot(VMSnapshotManagerImpl.java:438)
> at
> com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapshot(VMSnapshotManagerImpl.java:994)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
> com.cloud.vm.snapshot.VMSnapshotManagerImpl.handleVmWorkJob(VMSnapshotManagerImpl.java:1021)
> at sun.reflect.GeneratedMethodAccessor797.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> at com.sun.proxy.$Proxy198.handleVmWorkJob(Unknown Source)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:549)
> at
> org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at
> org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:500)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> {noformat}
> 2015-07-24 08:23:01,359 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-137:ctx-bcdafb76) (logid:a20017dd) Seq 80-6161487240196259885:
> Response Received:
> 2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request]
> (DirectAgent-137:ctx-bcdafb76) (logid:a20017dd) Seq 80-6161487240196259885:
> Processing: { Ans: , MgmtId: 345051581208, via: 80, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.CreateVMSnapshotAnswer":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.110/tintri/ECS-SR-CLD200/?ROLE=Primary&STOREUUID=346b381a-8543-3f7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":33386,"path":"ROOT-16119-000001","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[346b381a85433f7b9efffa909ad243c7]
> i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b381a85433f7b9efffa909ad243c7]
> 49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"vmSnapshotTo":{"id":964,"snapshotName":"i-84987-16119-VM_VS_20150724152253","type":"Disk","current":false,"description":"unit-test-instance-snapshot","quiescevm":false},"result":true,"details":"","wait":0}}]
> }
> 2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
> (logid:a20017dd) Seq 80-6161487240196259885: Received: { Ans: , MgmtId:
> 345051581208, via: 80, Ver: v1, Flags: 10, { CreateVMSnapshotAnswer } }
> 2015-07-24 08:23:01,382 DEBUG [o.a.c.s.v.DefaultVMSnapshotStrategy]
> (Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
> (logid:a20017dd) Create vm snapshot i-84987-16119-VM_VS_20150724152253
> succeeded for vm: i-84987-16119-VM
> 2015-07-24 08:23:01,396 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c)
> (logid:a20017dd) Done executing VM work job:
> com.cloud.vm.snapshot.VmWorkCreateVMSnapshot{"vmSnapshotId":964,"quiesceVm":false,"userId":1,"accountId":1,"vmId":16119,"handlerName":"VMSnapshotManagerImpl"}
> {noformat}
> It is not clear from this log what is causing this error "failed to create
> snapshot for vm:i-84987-16119-VM due to null"
> Interestingly, this VM has guest OS type set to None (138).
> REPRO STEPS
> ==================
> Try taking snapshot for 12 min after VM creation. VM snapshot fails for 12
> mins after VM creation.
> EXPECTED BEHAVIOR
> ==================
> VM snapshot should be successful from the moment the VM is ready.
> ACTUAL BEHAVIOR
> ==================
> VM snapshot is not successful for ~12 minutes
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
