Remi Bergsma created CLOUDSTACK-9059:
----------------------------------------
Summary: Snapshot on S3 fails when delta is zero
Key: CLOUDSTACK-9059
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-9059
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Snapshot
Affects Versions: 4.6.0
Environment: XenServer and S3
Reporter: Remi Bergsma
Priority: Critical
- 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 ####
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
