cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remi Bergsma (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CLOUDSTACK-9059) Snapshot on S3 fails when delta is zero
Date Thu, 12 Nov 2015 18:41:10 GMT

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-9059?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Remi Bergsma updated CLOUDSTACK-9059:
-------------------------------------
    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 ]


  was:
- 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 ####




> 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 ####
> 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 ]



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message