[CLOUDSTACK-5482] Vmware - When nfs was down for about 1 hour , when snapshots were in progress , snapshot job failed when nfs was brought up leaving behind snaphots in "CreatedOnPrimary" state.

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Duplicate
• Affects Version/s: 4.3.0
• Fix Version/s: 4.4.0, 4.5.0
• Component/s: Management Server
• Security Level: Public (Anyone can view this level - this is the default.)
• Environment: Build from 4.3
• Assignee: Disheng Su
• Reporter: Sangeetha Hariharan
• Created: 13/Dec/13 01:50
• Updated: 17/Nov/14 23:44
• Resolved: 17/Nov/14 23:44

Description

Set up :
Advanced Zone with 2 5.1 ESXI hosts.

Steps to reproduce the problem:

1. Deploy 5 Vms in each of the hosts , so we start with 11 Vms.
2. Start concurrent snapshots for ROOT volumes of all the Vms.
3. Shutdown the Secondary storage server when the snapshots are in the progress.
4. Bring the Secondary storage server up after 1 hour.

When the secondary storage was down , 2 of the snapshots were already completed. 5 of them were in progress and the other 4 had not started yet.

Once the secondary store was brought up , I see the snapshots that were in progress actually continue to download to secondary and succeed. But the other 4 snapshots error out.

mysql> select volume_id,status,created from snapshots;
----------------------------------------------

volume_id

status

created

----------------------------------------------

22	BackedUp	2013-12-12 23:24:13
21	Destroyed	2013-12-12 23:24:13
20	BackedUp	2013-12-12 23:24:14
19	Destroyed	2013-12-12 23:24:14
18	BackedUp	2013-12-12 23:24:14
17	BackedUp	2013-12-12 23:24:14
16	BackedUp	2013-12-12 23:24:14
14	BackedUp	2013-12-12 23:24:15
25	BackedUp	2013-12-12 23:24:15
24	BackedUp	2013-12-12 23:24:15
23	BackedUp	2013-12-12 23:24:15
22	CreatedOnPrimary	2013-12-12 23:53:38
21	BackedUp	2013-12-12 23:53:38
20	BackedUp	2013-12-12 23:53:38
19	BackedUp	2013-12-12 23:53:39
18	CreatedOnPrimary	2013-12-12 23:53:39
17	CreatedOnPrimary	2013-12-12 23:53:40
16	CreatedOnPrimary	2013-12-12 23:53:40
14	BackedUp	2013-12-12 23:53:40
25	BackedUp	2013-12-12 23:53:41
24	BackedUp	2013-12-12 23:53:41
23	BackedUp	2013-12-12 23:53:42
21	BackedUp	2013-12-13 00:53:37
19	BackedUp	2013-12-13 00:53:38

----------------------------------------------
24 rows in set (0.00 sec)

This leaves behind incomplete snapshots. The directory does not have a ovf file and has incomplete vmdk file.

[root@Rack3Host8 18]# ls -ltR
.:
total 12
drwxr-xr-x. 2 root root 4096 Dec 12 22:56 36d7964c-e545-41d7-b303-96359a88dcef
drwxr-xr-x. 2 root root 4096 Dec 12 22:30 68802f5f-84b1-42ad-8dca-4de7e83324e2

./36d7964c-e545-41d7-b303-96359a88dcef:
total 403256
rw-rr-. 1 root root 412524288 Dec 13 00:20 36d7964c-e545-41d7-b303-96359a88dcef-disk0.vmdk

./68802f5f-84b1-42ad-8dca-4de7e83324e2:
total 448860
rw-rr-. 1 root root 459168256 Dec 12 22:30 68802f5f-84b1-42ad-8dca-4de7e83324e2-disk0.vmdk
rw-rr-. 1 root root 6454 Dec 12 22:30 68802f5f-84b1-42ad-8dca-4de7e83324e2.ovf
[root@Rack3Host8 18]#

Following exception seen in the management server logs:

2013-12-12 20:23:13,021 DEBUG [c.c.a.t.Request] (AgentManager-Handler-2:null) Seq 5-813367309: Processing: { Ans: , MgmtId: 95307354844397, via: 5, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"backup snapshot exception: Exception: java.lang.Exception\nMessage: Unable to finish the whole process to package as a OVA file\n","wait":0}}] }
2013-12-12 20:23:13,022 DEBUG [c.c.a.t.Request] (Job-Executor-1:ctx-83fb69a5 ctx-51e56052) Seq 5-813367309: Received: { Ans: , MgmtId: 95307354844397, via: 5, Ver: v1, Flags: 10,

{ CopyCmdAnswer }

}
2013-12-12 20:23:13,041 DEBUG [c.c.s.s.SnapshotManagerImpl] (Job-Executor-1:ctx-83fb69a5 ctx-51e56052) Failed to create snapshot
com.cloud.utils.exception.CloudRuntimeException: backup snapshot exception: Exception: java.lang.Exception
Message: Unable to finish the whole process to package as a OVA file

at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:275)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:135)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:294)
at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:951)
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:601)
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 $Proxy161.takeSnapshot(Unknown Source)
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1341)
at com.cloud.storage.VolumeApiServiceImpl.takeSnapshot(VolumeApiServiceImpl.java:1486)
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:601)
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 $Proxy233.takeSnapshot(Unknown Source)
at org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd.execute(CreateSnapshotCmd.java:181)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
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 com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:520)
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 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)

Issue Links

• duplicates: CLOUDSTACK-5356 Xenserver - Failed to create snapshot when secondary store was made unavaibale for about 1.5 hour leaving behind snapshot in " CreatedOnPrimary" state. The subsequent scheduled snapshot also failed