I’m running into an issue that appears to be easily reproduced (on our current
setup at least) following these steps on a vm:
Create snapshot (succeeds)
Create 2nd snapshot (also succeeds)
Delete 2nd snapshot (succeeds)
Create another snapshot (fails)
Delete ALL snapshots incl first
Create another snapshot (fails)
This is using the take snapshot button in the cloudstack ui when you go to the
vm and then volumes and click on the root disk volume.
The first snapshot seems to work fine, but any snapshots after that fail. We
are using local storage for the root volumes if it matters.
I watched the logs on the secondary storage and also the hypervisor, and did
not see anything hit any of these logs:
ss-vm: /var/log/cloud/api-server.log /var/log/cloud/cloud.out hv:
/var/log/cloud/* /var/log/SMLOG
From the management server logs, I’m assuming it failed before it ever tried to
contact the hv/ssvm?
These are the management-server logs for the job. Sidenote: even though it
failed, it still returned success for the async job:
[root@mgmt-1 ~]# egrep 'ctx-9da8fde3|job-183808|job-183809'
/var/log/cloudstack/management/management-server.log
2014-09-16 12:15:05,751 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-89d7d82c) Schedule queued job-183809
2014-09-16 12:15:05,760 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809) Add job-183809 into
job monitoring
2014-09-16 12:15:05,760 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809) Executing AsyncJobVO
{id:183809, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.storage.VmWorkTakeVolumeSnapshot, cmdInfo:
rO0ABXNyACpjb20uY2xvdWQuc3RvcmFnZS5WbVdvcmtUYWtlVm9sdW1lU25hcHNob3QEvmAbguLVzwIABFoACXF1aWVzY2VWbUwACHBvbGljeUlkdAAQTGphdmEvbGFuZy9Mb25nO0wACnNuYXBzaG90SWRxAH4AAUwACHZvbHVtZUlkcQB-AAF4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAILwAAAAAAAAACAAAAAAAAFSN0ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbABzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAABzcQB-AAYAAAAAAAACgXNxAH4ABgAAAAAAABUl,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 33862771676063, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Tue Sep 16 12:15:05 MST 2014}
2014-09-16 12:15:05,762 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809) Run VM work job:
com.cloud.storage.VmWorkTakeVolumeSnapshot for VM 5411, job origin: 183808
2014-09-16 12:15:05,770 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) Execute
VM work job:
com.cloud.storage.VmWorkTakeVolumeSnapshot{"volumeId":5413,"policyId":0,"snapshotId":641,"quiesceVm":false,"userId":2,"accountId":2095,"vmId":5411,"handlerName":"VolumeApiServiceImpl"}
2014-09-16 12:15:05,989 DEBUG
[o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) Failed
to take snapshot: 641
2014-09-16 12:15:05,991 DEBUG [o.a.c.s.s.SnapshotServiceImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) create
snapshot mytestvmdb_ROOT-5411_20140916191505 failed:
java.lang.NullPointerException
java.lang.NullPointerException
at
org.apache.cloudstack.storage.snapshot.SnapshotObject.getId(SnapshotObject.java:148)
at
org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.findObject(ObjectInDataStoreManagerImpl.java:330)
at
org.apache.cloudstack.storage.snapshot.SnapshotObject.getPath(SnapshotObject.java:205)
at
org.apache.cloudstack.storage.to.SnapshotObjectTO.<init>(SnapshotObjectTO.java:60)
at
org.apache.cloudstack.storage.snapshot.SnapshotObject.getTO(SnapshotObject.java:273)
at
org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.takeSnapshot(CloudStackPrimaryDataStoreDriverImpl.java:277)
at
org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.takeSnapshot(SnapshotServiceImpl.java:198)
at
org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:284)
at
com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:922)
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
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.$Proxy196.takeSnapshot(Unknown Source)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1503)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:1738)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2475)
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.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2483)
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
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.$Proxy200.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
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:460)
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)
2014-09-16 12:15:06,027 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) Failed
to take snapshot: java.lang.NullPointerException
com.cloud.utils.exception.CloudRuntimeException: java.lang.NullPointerException
at
org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:287)
at
com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:922)
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
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.$Proxy196.takeSnapshot(Unknown Source)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1503)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:1738)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2475)
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.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2483)
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
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.$Proxy200.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
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:460)
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)
com.cloud.utils.exception.CloudRuntimeException: Failed to create snapshot
at
com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:939)
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
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.$Proxy196.takeSnapshot(Unknown Source)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1503)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:1738)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2475)
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.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2483)
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
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.$Proxy200.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
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:460)
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)
Caused by: com.cloud.utils.exception.CloudRuntimeException:
java.lang.NullPointerException
at
org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:287)
at
com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:922)
... 44 more
2014-09-16 12:15:06,059 DEBUG [c.c.s.s.SnapshotManagerImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) Failed
to create snapshot
2014-09-16 12:15:06,097 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) Take
snapshot: 5413 failed
2014-09-16 12:15:06,098 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) Done
executing VM work job:
com.cloud.storage.VmWorkTakeVolumeSnapshot{"volumeId":5413,"policyId":0,"snapshotId":641,"quiesceVm":false,"userId":2,"accountId":2095,"vmId":5411,"handlerName":"VolumeApiServiceImpl"}
2014-09-16 12:15:06,098 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809 ctx-34d1b2eb) Complete
async job-183809, jobStatus: SUCCEEDED, resultCode: 0, result:
rO0ABXNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAAAAAAAACgQ
2014-09-16 12:15:06,116 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809) Done with run of VM
work job: com.cloud.storage.VmWorkTakeVolumeSnapshot for VM 5411, job origin:
183808
2014-09-16 12:15:06,116 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809) Done executing
com.cloud.storage.VmWorkTakeVolumeSnapshot for job-183809
2014-09-16 12:15:06,146 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809) Sync queue (54298) is
currently empty
2014-09-16 12:15:06,147 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-34:ctx-9da8fde3 job-183808/job-183809) Remove job-183809
from job monitoring
Anyone have any ideas on how to fix this or what else to check from here? I did
see a few snapshot related issues open on
http://cloudstack-release-notes.readthedocs.org/en/latest/known_issues.html but
didn’t see any that looked exactly like this.
Thanks,
--
Justyn Shull
DevOps
