Uploaded image for project: 'CloudStack'
  1. CloudStack
  2. CLOUDSTACK-9059

Snapshot on S3 fails when delta is zero

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Open
    • Priority: Critical
    • Resolution: Unresolved
    • Affects Version/s: 4.6.0
    • Fix Version/s: None
    • Component/s: Snapshot
    • Security Level: Public (Anyone can view this level - this is the default.)
    • Labels:
      None
    • Environment:
      XenServer and S3

      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 ]

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              remibergsma Remi Bergsma
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated: