[CLOUDSTACK-9059] Snapshot on S3 fails when delta is zero

• Type: Bug
• Status: Open
• Priority: Critical
• Resolution: Unresolved
• Affects Version/s: 4.6.0
• Component/s: Snapshot
• Security Level: Public (Anyone can view this level - this is the default.)
• Environment: XenServer and S3
• Assignee: Unassigned
• Reporter: Remi Bergsma
• Created: 12/Nov/15 15:40
• Updated: 12/Nov/15 18:40

Description

• Create a vm
• make snapshot
  Verify it works and makes it to S3. This should work.
• make another snapshot
  It fails: Failed to create snapshot due to an internal error creating snapshot for volume 220

Logs from management:
2015-11-12 16:26:15,103 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Add job-1669 into job monitoring
2015-11-12 16:26:15,107 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Executing AsyncJobVO {id:1669, userId: 4, accountId: 2, instanceType: Snapshot, instanceId: 12, cmd: org.apa
che.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo: {"quiescevm":"false","httpmethod":"GET","ctxAccountId":"2","uuid":"2a2b67ce-e6a5-4dd3-85f5-823f14d9fbbe","cmdEventType":"SNAPSHOT.CREATE","respons
e":"json","ctxUserId":"4","volumeId":"0137c81d-aedb-469a-bcbb-cf7df2985c82","name":"nog een","ctxStartEventId":"2906","id":"12","ctxDetails":"

{\"interface com.cloud.storage.Snapshot\":\"2a2b67ce-e6a5-4dd3-85f5-823f1 4d9fbbe\",\"interface com.cloud.storage.Volume\":\"0137c81d-aedb-469a-bcbb-cf7df2985c82\"}

","_":"1447341974884"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 28867301
26, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2015-11-12 16:26:15,109 DEBUG [c.c.a.ApiServlet] (http-bio-8080-exec-26:ctx-f0fd7270 ctx-2f203261) ===END=== 10.200.22.3 – GET command=createSnapshot&response=json&volumeId=0137c81d-aedb-469a-bcbb-cf7df2985c82&qu
iescevm=false&name=nog+een&_=1447341974884
2015-11-12 16:26:15,181 INFO [o.a.c.a.c.u.s.CreateSnapshotCmd] (API-Job-Executor-3:ctx-a1e712e2 job-1669 ctx-2f94ce7b) VOLSS: createSnapshotCmd starts:1447341975181
2015-11-12 16:26:15,231 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669 ctx-2f94ce7b) Sync job-1670 execution on object VmWorkJobQueue.220
2015-11-12 16:26:18,143 DEBUG [c.c.a.ApiServlet] (http-bio-8080-exec-17:ctx-0304676c) ===START=== 10.200.22.3 – GET command=queryAsyncJobResult&jobId=5a6748af-cb5f-41b6-82c6-a17971c63d09&response=json&_=144734197
8124
2015-11-12 16:26:18,178 DEBUG [c.c.a.ApiServlet] (http-bio-8080-exec-17:ctx-0304676c ctx-321af332) ===END=== 10.200.22.3 – GET command=queryAsyncJobResult&jobId=5a6748af-cb5f-41b6-82c6-a17971c63d09&response=json&
_=1447341978124
2015-11-12 16:26:19,497 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-4fd0fb68) AutoScaling Monitor is running...
2015-11-12 16:26:21,180 DEBUG [c.c.a.ApiServlet] (http-bio-8080-exec-14:ctx-7690a426) ===START=== 10.200.22.3 – GET command=queryAsyncJobResult&jobId=5a6748af-cb5f-41b6-82c6-a17971c63d09&response=json&_=144734198
1124
2015-11-12 16:26:21,216 DEBUG [c.c.a.ApiServlet] (http-bio-8080-exec-14:ctx-7690a426 ctx-61c72bab) ===END=== 10.200.22.3 – GET command=queryAsyncJobResult&jobId=5a6748af-cb5f-41b6-82c6-a17971c63d09&response=json&
_=1447341981124
2015-11-12 16:26:21,316 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Complete async job-1669, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.Exce
ptionResponse/null/

{"uuidList":[],"errorcode":530,"errortext":"Failed to create snapshot due to an internal error creating snapshot for volume 220"}

2015-11-12 16:26:21,318 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Publish async job-1669 complete on message bus
2015-11-12 16:26:21,318 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Wake up jobs related to job-1669
2015-11-12 16:26:21,318 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Update db status for job-1669
2015-11-12 16:26:21,321 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Wake up jobs joined with job-1669 and disjoin all subjobs created from job- 1669
2015-11-12 16:26:21,326 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Done executing org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-1669
2015-11-12 16:26:21,326 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-3:ctx-a1e712e2 job-1669) Remove job-1669 from job monitoring

2015-11-12 16:26:18,280 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-3:ctx-fbda09ad job-1669/job-1670) Unable to complete AsyncJobVO

{id:1670, userId: 4, accountId: 2, instanceType: null, instanceId: null, c md: com.cloud.vm.VmWorkTakeVolumeSnapshot, cmdInfo: rO0ABXNyACVjb20uY2xvdWQudm0uVm1Xb3JrVGFrZVZvbHVtZVNuYXBzaG90BL5gG4Li1c8CAARaAAlxdWllc2NlVm1MAAhwb2xpY3lJZHQAEExqYXZhL2xhbmcvTG9uZztMAApzbmFwc2hvdElkcQB-AAFMAAh2b2x 1bWVJZHEAfgABeHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAAUAAAAAAAAABAAAAAAAAADcdAAUVm9sdW1lQXBpU2VydmljZUltcGwAc3IADm phdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAAAAAAAAAc3EAfgAGAAAAAAAAAAxzcQB-AAYAAAAAAAAA3A, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2886730126, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Nov 12 16:26:15 CET 2015}

, job origin:1669
com.cloud.utils.exception.CloudRuntimeException: Failed to take snapshot
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1594)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2078)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2865)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2873)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
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.$Proxy197.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:537)
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:494)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to create snapshot
at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1025)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
... 42 more
Caused by: com.cloud.utils.exception.CloudRuntimeException: BackupSnapshot Failed due to S3 upload of snapshots null failed
at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:285)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:155)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:322)
... 45 more

2015-11-12 16:26:18,155 WARN [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-109:ctx-23c1fe16) BackupSnapshot Failed due to S3 upload of snapshots null failed
com.cloud.utils.exception.CloudRuntimeException: S3 upload of snapshots null failed
at com.cloud.hypervisor.xenserver.resource.Xenserver625StorageProcessor.backupSnapshot(Xenserver625StorageProcessor.java:525)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:99)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:54)
at com.cloud.hypervisor.xenserver.resource.wrapper.xenbase.CitrixStorageSubSystemCommandWrapper.execute(CitrixStorageSubSystemCommandWrapper.java:36)
at com.cloud.hypervisor.xenserver.resource.wrapper.xenbase.CitrixStorageSubSystemCommandWrapper.execute(CitrixStorageSubSystemCommandWrapper.java:30)
at com.cloud.hypervisor.xenserver.resource.wrapper.xenbase.CitrixRequestWrapper.execute(CitrixRequestWrapper.java:122)
at com.cloud.hypervisor.xenserver.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:1676)
at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:302)
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:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2015-11-12 16:26:18,156 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-109:ctx-23c1fe16) Seq 8-8143352551215989060: Response Received:
2015-11-12 16:26:18,156 DEBUG [c.c.a.t.Request] (DirectAgent-109:ctx-23c1fe16) Seq 8-8143352551215989060: Processing: { Ans: , MgmtId: 90520741485751, via: 8(mccxpod01-hv07), Ver: v1, Flags: 110, [{"org.apache.clou
dstack.storage.command.CopyCmdAnswer":{"result":false,"details":"BackupSnapshot Failed due to S3 upload of snapshots null failed","wait":0}}] }
2015-11-12 16:26:18,156 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-109:ctx-23c1fe16) Seq 8-8143352551215989060: No more commands found
2015-11-12 16:26:18,156 DEBUG [c.c.a.t.Request] (Work-Job-Executor-3:ctx-fbda09ad job-1669/job-1670 ctx-d2d8b8ab) Seq 8-8143352551215989060: Received: { Ans: , MgmtId: 90520741485751, via: 8(mccxpod01-hv07), Ver: v
1, Flags: 110,

{ CopyCmdAnswer }

}
2015-11-12 16:26:18,177 ERROR [o.a.c.s.i.BaseImageStoreDriverImpl] (Work-Job-Executor-3:ctx-fbda09ad job-1669/job-1670 ctx-d2d8b8ab) No remote endpoint to send command, check if host or ssvm is down?

Logs from XenServer /var/log/cloud/s3xen.log:
2015-11-12 16:26:17 DEBUG [root] #### VMOPS enter s3 #### ####
2015-11-12 16:26:17 DEBUG [root] #### VMOPS Operation put on file /var/run/sr-mount/2dcb90fe-1068-2e9f-6963-7de833f109f0/null.vhd from/in bucket mccx-nl2 key snapshots/5/220/null.vhd ####
2015-11-12 16:26:17 DEBUG [root] #### VMOPS Traceback (most recent call last):
File "/etc/xapi.d/plugins/s3xenserver", line 414, in s3
client.put(bucket, key, filename, maxSingleUploadBytes)
File "/etc/xapi.d/plugins/s3xenserver", line 325, in put
raise Exception(
Exception: Attempt to put /var/run/sr-mount/2dcb90fe-1068-2e9f-6963-7de833f109f0/null.vhd that does not exist.
####
2015-11-12 16:26:17 DEBUG [root] #### VMOPS exit s3 with result false ####

In xensource.log you see it call the s3xenserver plugin:
Nov 12 19:22:16 mccxpod01-hv08 xapi: [debug|mccxpod01-hv08|2166532|Async.host.call_plugin R:36173a97bfdc|audit] Host.call_plugin host = '5d4cc523-ced7-4324-9dfb-fb81cb225899 (mccxpod01-hv07)'; plugin = 's3xenserver'; fn = 's3'; args = [ maxErrorRetry: 10; secretKey: x; connectionTtl: null; iSCSIFlag: false; maxSingleUploadSizeInBytes: 5368709120; bucket: mccx-nl2; endPoint: s3.x.schubergphilis.com; filename: /var/run/sr-mount/e914d2c5-f74f-4818-9dc5-c2f2f6f909f1/4b9295bd-779c-4212-84b7-9b79520cf42e.vhd; accessKey: x; socketTimeout: null; https: false; connectionTimeout: 300000; operation: put; key: snapshots/5/215/4b9295bd-779c-4212-84b7-9b79520cf42e.vhd; useTCPKeepAlive: null ]
Nov 12 19:29:29 mccxpod01-hv08 xapi: [debug|mccxpod01-hv08|2168571|Async.host.call_plugin R:988800b3c267|audit] Host.call_plugin host = '552570ac-1a04-4576-8615-2af7767803b6 (mccxpod01-hv08)'; plugin = 's3xenserver'; fn = 's3'; args = [ maxErrorRetry: 10; secretKey: +x; connectionTtl: null; iSCSIFlag: false; maxSingleUploadSizeInBytes: 5368709120; bucket: mccx-nl2; endPoint:

This one doesn't work because it doesn't exist:
s3.x.schubergphilis.com; filename: /var/run/sr-mount/2dcb90fe-1068-2e9f-6963-7de833f109f0/null.vhd; accessKey: x; socketTimeout: null; https: false; connectionTimeout: 300000; operation: put; key: snapshots/5/215/null.vhd; useTCPKeepAlive: null ]