You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Asai <as...@globalchangemusic.org> on 2019/06/10 21:07:55 UTC
Failed to copy the volume from the source primary storage pool to
secondary storage
Greetings,
I am trying to figure out the steps in migrating a KVM based guest to a
Xen based guest.
I have attempted to download the KVM volume so that I can attempt to
attach the volume to a Xen based VM, however I get the following error
when trying to download the volume:
"Failed to copy the volume from the source primary storage pool to
secondary storage"
My secondary storage is 90% full, but it's actually got over 500 GB in
it and this VM is under 60 GB, so there is plenty of room for the VM on
secondary.
Any advice or direction would be appreciated.
Asai
Re: Failed to copy the volume from the source primary
storage pool to secondary storage
Posted by Nicolas Vazquez <Ni...@shapeblue.com>.
That is a known error on version 4.11.1 which has been fixed on 4.11.2 by this PR: https://github.com/apache/cloudstack/pull/2776.
You can consider upgrading to version 4.11.2 to get the fix.
Regards,
Nicolas Vazquez
________________________________
From: Asai <as...@globalchangemusic.org>
Sent: Monday, June 10, 2019 8:18:03 PM
To: users@cloudstack.apache.org
Subject: Re: Failed to copy the volume from the source primary storage pool to secondary storage
Thanks for the response, Nicolas.
Here are the log entries from management-server.log corresponding to the
specific time period of running the download volume command:
2019-06-10 14:00:35,893 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Executing AsyncJobVO {id:2512, userId: 2, accountId: 2, instanceType: Volume, instanceId: 26, cmd: org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd, cmdInfo: {"mode":"HTTP_DOWNLOAD","response":"json","ctxUserId":"2","zoneid":"74a2a355-725a-4389-abe5-a24d52b5b7de","httpmethod":"GET","ctxStartEventId":"8780","id":"3a552f54-8d82-452a-ac5c-5144495d38c0","ctxDetails":"{\"interface com.cloud.dc.DataCenter\":\"74a2a355-725a-4389-abe5-a24d52b5b7de\",\"interface com.cloud.storage.Volume\":\"3a552f54-8d82-452a-ac5c-5144495d38c0\"}","ctxAccountId":"2","uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","cmdEventType":"VOLUME.EXTRACT","_":"1560200437111"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:00:35,933 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512 ctx-addef465) (logid:3ba6ac78) Sync job-2513 execution on object VmWorkJobQueue.13
2019-06-10 14:00:36,307 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6b017172) (logid:e6da8580) Execute sync-queue item: SyncQueueItemVO {id:327, queueId: 223, contentType: AsyncJob, contentId: 2513, lastProcessMsid: 14038012851765, lastprocessNumber: 114, lastProcessTime: Mon Jun 10 14:00:36 MST 2019, created: Mon Jun 10 14:00:35 MST 2019}
2019-06-10 14:00:36,308 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6b017172) (logid:e6da8580) Schedule queued job-2513
2019-06-10 14:00:36,331 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:426ea95f) Add job-2513 into job monitoring
2019-06-10 14:00:36,337 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Executing AsyncJobVO {id:2513, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkExtractVolume, cmdInfo: rO0ABXNyACBjb20uY2xvdWQudm0uVm1Xb3JrRXh0cmFjdFZvbHVtZfgl82-871PmAgACSgAIdm9sdW1lSWRKAAZ6b25lSWR4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAA10ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbAAAAAAAAAAaAAAAAAAAAAE, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Jun 10 14:00:35 MST 2019}
2019-06-10 14:00:36,337 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Run VM work job: com.cloud.vm.VmWorkExtractVolume for VM 13, job origin: 2512
2019-06-10 14:00:36,339 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Execute VM work job: com.cloud.vm.VmWorkExtractVolume{"volumeId":26,"zoneId":1,"userId":2,"accountId":2,"vmId":13,"handlerName":"VolumeApiServiceImpl"}
2019-06-10 14:00:36,380 ERROR [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) failed to copy volume to image store
java.lang.NullPointerException
at org.apache.cloudstack.storage.motion.StorageSystemDataMotionStrategy.isVolumeOnManagedStorage(StorageSystemDataMotionStrategy.java:202)
at org.apache.cloudstack.storage.motion.StorageSystemDataMotionStrategy.canHandle(StorageSystemDataMotionStrategy.java:182)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$1.canHandle(StorageStrategyFactoryImpl.java:52)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$1.canHandle(StorageStrategyFactoryImpl.java:49)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getDataMotionStrategy(StorageStrategyFactoryImpl.java:49)
at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:62)
at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:73)
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolumeFromPrimaryToImage(VolumeServiceImpl.java:1371)
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:1417)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:2515)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:3139)
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:498)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3178)
at sun.reflect.GeneratedMethodAccessor295.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy196.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-06-10 14:00:36,393 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2019-06-10 14:00:36,393 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:36,394 DEBUG [c.c.a.t.Request] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Seq 6-5229523592307647624: Sending { Cmd , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.210/mnt/export/secondary","_role":"Image"}},"name":"ROOT-13","size":42949672960,"path":"volumes/2/26","volumeId":26,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":26,"deviceId":0,"hypervisorType":"KVM"}},"wait":0}}] }
2019-06-10 14:00:36,460 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null) (logid:) Seq 6-5229523592307647624: Processing: { Ans: , MgmtId: 14038012851765, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"volume parent directory 2 doesn't exist","wait":0}}] }
2019-06-10 14:00:36,461 DEBUG [c.c.a.t.Request] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Seq 6-5229523592307647624: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { Answer } }
2019-06-10 14:00:36,494 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@40c3d5da), no need to delete from object in store ref table
2019-06-10 14:00:36,494 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Invocation exception, caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
2019-06-10 14:00:36,494 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Rethrow exception com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
2019-06-10 14:00:36,494 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Done with run of VM work job: com.cloud.vm.VmWorkExtractVolume for VM 13, job origin: 2512
2019-06-10 14:00:36,494 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Unable to complete AsyncJobVO {id:2513, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkExtractVolume, cmdInfo: rO0ABXNyACBjb20uY2xvdWQudm0uVm1Xb3JrRXh0cmFjdFZvbHVtZfgl82-871PmAgACSgAIdm9sdW1lSWRKAAZ6b25lSWR4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAA10ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbAAAAAAAAAAaAAAAAAAAAAE, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Jun 10 14:00:35 MST 2019}, job origin:2512
com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:2529)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:3139)
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:498)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3178)
at sun.reflect.GeneratedMethodAccessor295.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy196.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-06-10 14:00:36,496 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Complete async job-2513, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0AFRGYWlsZWQgdG8gY29weSB0aGUgdm9sdW1lIGZyb20gdGhlIHNvdXJjZSBwcmltYXJ5IHN0b3JhZ2UgcG9vbCB0byBzZWNvbmRhcnkgc3RvcmFnZS51cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAB9zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABUwACGZpbGVOYW1lcQB-AAVMAAptZXRob2ROYW1lcQB-AAV4cAAACeF0ACZjb20uY2xvdWQuc3RvcmFnZS5Wb2x1bWVBcGlTZXJ2aWNlSW1wbHQAGVZvbHVtZUFwaVNlcnZpY2VJbXBsLmphdmF0ABhvcmNoZXN0cmF0ZUV4dHJhY3RWb2x1bWVzcQB-AAwAAAxDcQB-AA5xAH4AD3EAfgAQc3EAfgAM_____nQAJHN1bi5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHNxAH4ADAAAAD5xAH4AE3EAfgAUdAAGaW52b2tlc3EAfgAMAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AF3NxAH4ADAAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAXc3EAfgAMAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4ADAAADGpxAH4ADnEAfgAPcQB-ACFzcQB-AAz_____dAAmc3VuLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3IyOTVwcQB-ABdzcQB-AAwAAAArcQB-ABlxAH4AGnEAfgAXc3EAfgAMAAAB8nEAfgAccQB-AB1xAH4AF3NxAH4ADAAAAVJ0AChvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5zdXBwb3J0LkFvcFV0aWxzdAANQW9wVXRpbHMuamF2YXQAHmludm9rZUpvaW5wb2ludFVzaW5nUmVmbGVjdGlvbnNxAH4ADAAAAMV0ADxvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5mcmFtZXdvcmsuUmVmbGVjdGl2ZU1ldGhvZEludm9jYXRpb250AB9SZWZsZWN0aXZlTWV0aG9kSW52b2NhdGlvbi5qYXZhdAAPaW52b2tlSm9pbnBvaW50c3EAfgAMAAAAo3EAfgAscQB-AC10AAdwcm9jZWVkc3EAfgAMAAAAXHQAP29yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmludGVyY2VwdG9yLkV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvcnQAIEV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvci5qYXZhcQB-ABdzcQB-AAwAAAC5cQB-ACxxAH4ALXEAfgAwc3EAfgAMAAAA1HQANG9yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmZyYW1ld29yay5KZGtEeW5hbWljQW9wUHJveHl0ABdKZGtEeW5hbWljQW9wUHJveHkuamF2YXEAfgAXc3EAfgAM_____3QAF2NvbS5zdW4ucHJveHkuJFByb3h5MTk2cHEAfgAhc3EAfgAMAAAAZnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgAMAAACRXQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4ADAAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4ADAAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-AAwAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgBIdAAPY2FsbFdpdGhDb250ZXh0c3EAfgAMAAAANXEAfgBLcQB-AEh0AA5ydW5XaXRoQ29udGV4dHNxAH4ADAAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4ARHEAfgBFc3EAfgAMAAACEXEAfgA_cQB-AEBxAH4ARXNxAH4ADAAAAf90AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4ASXNxAH4ADAAAAQp0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-AEVzcQB-AAwAAAR2dAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJzcQB-AAwAAAJpdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBacQB-AEVzcQB-AAwAAALpdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-AEVzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUxteyOEAIAAUwABGxpc3RxAH4AB3hyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlQ29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgBmeAAAEJp3CAAAAAAAAAAAeA
2019-06-10 14:00:36,497 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Publish async job-2513 complete on message bus
2019-06-10 14:00:36,497 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Wake up jobs related to job-2513
2019-06-10 14:00:36,497 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Update db status for job-2513
2019-06-10 14:00:36,498 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Wake up jobs joined with job-2513 and disjoin all subjobs created from job- 2513
2019-06-10 14:00:36,508 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Done executing com.cloud.vm.VmWorkExtractVolume for job-2513
2019-06-10 14:00:36,510 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Remove job-2513 from job monitoring
2019-06-10 14:00:36,532 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Unexpected exception while executing org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd
com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:2529)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:3139)
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:498)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3178)
at sun.reflect.GeneratedMethodAccessor295.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy196.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-06-10 14:00:36,533 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Complete async job-2512, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to copy the volume from the source primary storage pool to secondary storage."}
2019-06-10 14:00:36,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Publish async job-2512 complete on message bus
2019-06-10 14:00:36,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Wake up jobs related to job-2512
2019-06-10 14:00:36,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Update db status for job-2512
2019-06-10 14:00:36,538 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Wake up jobs joined with job-2512 and disjoin all subjobs created from job- 2512
2019-06-10 14:00:36,546 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Done executing org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd for job-2512
2019-06-10 14:00:36,546 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Remove job-2512 from job monitoring
2019-06-10 14:00:38,901 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-69281f08) (logid:033aa8e9) ===START=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=3ba6ac78-2111-4fa2-92d4-bfb04db2b7e3&response=json&_=1560200440168
2019-06-10 14:00:38,904 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-69281f08 ctx-7836867d) (logid:033aa8e9) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:00:38,926 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-69281f08 ctx-7836867d) (logid:033aa8e9) ===END=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=3ba6ac78-2111-4fa2-92d4-bfb04db2b7e3&response=json&_=1560200440168
2019-06-10 14:00:43,930 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857300: Processing Seq 2-1857300: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:00:43,941 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857300: Sending Seq 2-1857300: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:00:44,296 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-c6317c11) (logid:2703bdbf) Begin cleanup expired async-jobs
2019-06-10 14:00:44,301 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-c6317c11) (logid:2703bdbf) End cleanup expired async-jobs
2019-06-10 14:00:44,621 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0607e04a) (logid:57df045a) Found 2 routers to update status.
2019-06-10 14:00:44,622 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0607e04a) (logid:57df045a) Found 0 VPC networks to update Redundant State.
2019-06-10 14:00:44,624 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0607e04a) (logid:57df045a) Found 0 networks to update RvR status.
2019-06-10 14:00:51,612 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-f8169009) (logid:407c8b82) Seq 1-2212674791923289268: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2019-06-10 14:00:53,932 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857301: Processing Seq 2-1857301: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:00:53,941 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857301: Sending Seq 2-1857301: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:00:54,296 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-79a6dcbe) (logid:f73e4c31) Begin cleanup expired async-jobs
2019-06-10 14:00:54,300 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-79a6dcbe) (logid:f73e4c31) End cleanup expired async-jobs
2019-06-10 14:00:54,679 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-6ef02f9d) (logid:13f535b4) AutoScaling Monitor is running...
2019-06-10 14:00:55,915 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) StorageCollector is running...
2019-06-10 14:00:55,922 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:55,922 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:55,983 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 6-5229523592307647625: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:55,986 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:55,986 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:56,079 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 6-5229523592307647626: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:56,081 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:56,081 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:56,105 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 1-2212674791923289269: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:56,107 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:56,107 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:56,259 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 1-2212674791923289270: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:56,759 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-f0ec945d) (logid:0cde1d85) HostStatsCollector is running...
2019-06-10 14:00:56,768 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-f0ec945d) (logid:0cde1d85) Seq 1-2212674791923289271: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2019-06-10 14:00:58,934 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-1857302: Processing Seq 2-1857302: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:00:58,944 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-1857302: Sending Seq 2-1857302: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:00:59,936 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-5887b752) (logid:7ad48ac5) Zone 1 is ready to launch console proxy
2019-06-10 14:01:00,052 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-5a269b40) (logid:d9687cad) Zone 1 is ready to launch secondary storage VM
2019-06-10 14:01:04,297 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9470bc78) (logid:ec23a634) Begin cleanup expired async-jobs
2019-06-10 14:01:04,301 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9470bc78) (logid:ec23a634) End cleanup expired async-jobs
2019-06-10 14:01:07,023 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) Ping from 1(monota.globalchange.media)
2019-06-10 14:01:07,024 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process host VM state report from ping process. host: 1
2019-06-10 14:01:07,039 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process VM state report. host: 1, number of records in report: 12
2019-06-10 14:01:07,039 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 1, power state: PowerOn
2019-06-10 14:01:07,041 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 1
2019-06-10 14:01:07,041 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 2, power state: PowerOn
2019-06-10 14:01:07,042 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 2
2019-06-10 14:01:07,042 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 35, power state: PowerOn
2019-06-10 14:01:07,043 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 35
2019-06-10 14:01:07,043 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 4, power state: PowerOn
2019-06-10 14:01:07,045 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 4
2019-06-10 14:01:07,045 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 20, power state: PowerOn
2019-06-10 14:01:07,046 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 20
2019-06-10 14:01:07,046 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 5, power state: PowerOn
2019-06-10 14:01:07,047 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 5
2019-06-10 14:01:07,047 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 21, power state: PowerOn
2019-06-10 14:01:07,049 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 21
2019-06-10 14:01:07,049 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 22, power state: PowerOn
2019-06-10 14:01:07,050 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 22
2019-06-10 14:01:07,050 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 25, power state: PowerOn
2019-06-10 14:01:07,052 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 25
2019-06-10 14:01:07,052 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 9, power state: PowerOn
2019-06-10 14:01:07,053 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 9
2019-06-10 14:01:07,053 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 10, power state: PowerOn
2019-06-10 14:01:07,054 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 10
2019-06-10 14:01:07,055 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 12, power state: PowerOn
2019-06-10 14:01:07,056 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 12
2019-06-10 14:01:07,063 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Done with process of VM state report. host: 1
2019-06-10 14:01:08,936 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857303: Processing Seq 2-1857303: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:08,947 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857303: Sending Seq 2-1857303: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:09,387 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Resetting hosts suitable for reconnect
2019-06-10 14:01:09,388 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Completed resetting hosts suitable for reconnect
2019-06-10 14:01:09,388 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Acquiring hosts for clusters already owned by this management server
2019-06-10 14:01:09,389 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Completed acquiring hosts for clusters already owned by this management server
2019-06-10 14:01:09,389 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Acquiring hosts for clusters not owned by any management server
2019-06-10 14:01:09,389 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Completed acquiring hosts for clusters not owned by any management server
2019-06-10 14:01:14,299 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-62657402) (logid:9649aed8) Begin cleanup expired async-jobs
2019-06-10 14:01:14,304 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-62657402) (logid:9649aed8) End cleanup expired async-jobs
2019-06-10 14:01:14,621 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7afba768) (logid:372726e3) Found 2 routers to update status.
2019-06-10 14:01:14,623 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7afba768) (logid:372726e3) Found 0 VPC networks to update Redundant State.
2019-06-10 14:01:14,624 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7afba768) (logid:372726e3) Found 0 networks to update RvR status.
2019-06-10 14:01:18,937 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 2-1857304: Processing Seq 2-1857304: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:18,952 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 2-1857304: Sending Seq 2-1857304: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:24,297 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9e74ead5) (logid:e3e07d2a) Begin cleanup expired async-jobs
2019-06-10 14:01:24,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9e74ead5) (logid:e3e07d2a) End cleanup expired async-jobs
2019-06-10 14:01:28,902 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-7f2ae184) (logid:b45ca26f) ===START=== 192.168.55.58 -- GET command=listSnapshots&response=json&listAll=true&page=1&pagesize=20&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200490168
2019-06-10 14:01:28,907 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-7f2ae184 ctx-52ada595) (logid:b45ca26f) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:28,937 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) SeqA 2-1857305: Processing Seq 2-1857305: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:28,954 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) SeqA 2-1857305: Sending Seq 2-1857305: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:28,955 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-7f2ae184 ctx-52ada595) (logid:b45ca26f) ===END=== 192.168.55.58 -- GET command=listSnapshots&response=json&listAll=true&page=1&pagesize=20&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200490168
2019-06-10 14:01:29,211 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-efd528b8) (logid:aa54274c) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=c2b7a1aa-b410-47d5-b552-025ec4a0650b&response=json&_=1560200490479
2019-06-10 14:01:29,216 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-efd528b8 ctx-02b5c208) (logid:aa54274c) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:29,242 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-efd528b8 ctx-02b5c208) (logid:aa54274c) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=c2b7a1aa-b410-47d5-b552-025ec4a0650b&response=json&_=1560200490479
2019-06-10 14:01:29,939 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-02e95550) (logid:d13dc3d8) Zone 1 is ready to launch console proxy
2019-06-10 14:01:30,058 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-0126d0fd) (logid:0ea22536) Zone 1 is ready to launch secondary storage VM
2019-06-10 14:01:31,064 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) Ping from 2(v-2-VM)
2019-06-10 14:01:33,969 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) (logid:) Ping from 6(s-1-VM)
2019-06-10 14:01:34,298 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-92ea9ab4) (logid:059cd292) Begin cleanup expired async-jobs
2019-06-10 14:01:34,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-92ea9ab4) (logid:059cd292) End cleanup expired async-jobs
2019-06-10 14:01:38,609 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-89132598) (logid:ed0da0ba) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200499879
2019-06-10 14:01:38,614 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-89132598 ctx-d2f260bf) (logid:ed0da0ba) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:38,634 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-89132598 ctx-d2f260bf) (logid:ed0da0ba) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200499879
2019-06-10 14:01:38,939 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857307: Processing Seq 2-1857307: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:38,950 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857307: Sending Seq 2-1857307: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:39,213 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-1df0c4be) (logid:5cd3fb69) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200500482
2019-06-10 14:01:39,217 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-1df0c4be ctx-86dc0b4e) (logid:5cd3fb69) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:39,237 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-1df0c4be ctx-86dc0b4e) (logid:5cd3fb69) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200500482
2019-06-10 14:01:43,519 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-60ef5bab) (logid:c102571b) ===START=== 192.168.55.58 -- GET command=deleteSnapshot&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200504789
2019-06-10 14:01:43,525 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-60ef5bab ctx-3d0b2beb) (logid:c102571b) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:43,559 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:e483ef83) Add job-2514 into job monitoring
2019-06-10 14:01:43,563 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp66233253-180790:ctx-60ef5bab ctx-3d0b2beb) (logid:c102571b) submit async job-2514, details: AsyncJobVO {id:2514, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 696, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8783","id":"bf492ec5-880b-47a9-bbb2-3be13f67c734","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"bf492ec5-880b-47a9-bbb2-3be13f67c734\"}","ctxAccountId":"2","uuid":"bf492ec5-880b-47a9-bbb2-3be13f67c734","cmdEventType":"SNAPSHOT.DELETE","_":"1560200504789"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:43,563 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:b5259bd3) Executing AsyncJobVO {id:2514, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 696, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8783","id":"bf492ec5-880b-47a9-bbb2-3be13f67c734","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"bf492ec5-880b-47a9-bbb2-3be13f67c734\"}","ctxAccountId":"2","uuid":"bf492ec5-880b-47a9-bbb2-3be13f67c734","cmdEventType":"SNAPSHOT.DELETE","_":"1560200504789"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:43,564 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-60ef5bab ctx-3d0b2beb) (logid:c102571b) ===END=== 192.168.55.58 -- GET command=deleteSnapshot&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200504789
2019-06-10 14:01:43,605 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) delete snapshot chain for snapshot: 696
2019-06-10 14:01:43,606 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Snapshot: 696 doesn't have children, so it's ok to delete it and its parents
2019-06-10 14:01:43,628 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2019-06-10 14:01:43,628 DEBUG [c.c.h.XenServerGuru] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:43,630 DEBUG [c.c.a.t.Request] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Seq 6-5229523592307647627: Sending { Cmd , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/26/6894b376-722d-45ad-abe2-03fc3a0f64ad","volume":{"uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"04a00bdb-0463-3279-bd38-bbe619e04881","id":1,"poolType":"NetworkFilesystem","host":"192.168.200.232","path":"/home/export/primary","port":2049,"url":"NetworkFilesystem://192.168.200.232/home/export/primary/?ROLE=Primary&STOREUUID=04a00bdb-0463-3279-bd38-bbe619e04881","isManaged":false}},"name":"ROOT-13","size":42949672960,"path":"645500be-9376-4cd4-821d-d5ed788e0de1","volumeId":26,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":26,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.210/mnt/export/secondary","_role":"Image"}},"vmName":"i-2-13-VM","name":"meteor_ROOT-13_20190609080249","hypervisorType":"KVM","id":696,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2019-06-10 14:01:44,298 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0720dc96) (logid:546ec0c3) Begin cleanup expired async-jobs
2019-06-10 14:01:44,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0720dc96) (logid:546ec0c3) End cleanup expired async-jobs
2019-06-10 14:01:44,342 DEBUG [c.c.a.t.Request] (AgentManager-Handler-9:null) (logid:) Seq 6-5229523592307647627: Processing: { Ans: , MgmtId: 14038012851765, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2019-06-10 14:01:44,342 DEBUG [c.c.a.t.Request] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Seq 6-5229523592307647627: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { Answer } }
2019-06-10 14:01:44,387 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Updating resource Type = snapshot count for Account = 2 Operation = decreasing Amount = 1
2019-06-10 14:01:44,398 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Updating resource Type = secondary_storage count for Account = 2 Operation = decreasing Amount = 12402425856
2019-06-10 14:01:44,420 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Complete async job-2514, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.SuccessResponse/null/{"success":true}
2019-06-10 14:01:44,421 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Publish async job-2514 complete on message bus
2019-06-10 14:01:44,421 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Wake up jobs related to job-2514
2019-06-10 14:01:44,421 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Update db status for job-2514
2019-06-10 14:01:44,422 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Wake up jobs joined with job-2514 and disjoin all subjobs created from job- 2514
2019-06-10 14:01:44,430 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:b5259bd3) Done executing org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd for job-2514
2019-06-10 14:01:44,430 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:b5259bd3) Remove job-2514 from job monitoring
2019-06-10 14:01:44,621 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bcd8a75a) (logid:b0857b64) Found 2 routers to update status.
2019-06-10 14:01:44,622 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bcd8a75a) (logid:b0857b64) Found 0 VPC networks to update Redundant State.
2019-06-10 14:01:44,623 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bcd8a75a) (logid:b0857b64) Found 0 networks to update RvR status.
2019-06-10 14:01:45,961 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-cf56e888) (logid:730f7064) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200507231
2019-06-10 14:01:45,965 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-cf56e888 ctx-7359a813) (logid:730f7064) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:45,985 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-cf56e888 ctx-7359a813) (logid:730f7064) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200507231
2019-06-10 14:01:46,575 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-5388c6a0) (logid:7e273a2e) ===START=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b5259bd3-c108-4f89-a91a-077831d8dfca&response=json&_=1560200507844
2019-06-10 14:01:46,579 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-5388c6a0 ctx-4251a1bb) (logid:7e273a2e) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:46,600 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-5388c6a0 ctx-4251a1bb) (logid:7e273a2e) ===END=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b5259bd3-c108-4f89-a91a-077831d8dfca&response=json&_=1560200507844
2019-06-10 14:01:48,940 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857308: Processing Seq 2-1857308: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:48,951 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857308: Sending Seq 2-1857308: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:49,846 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-a54e1563) (logid:a10f9ca2) ===START=== 192.168.55.58 -- GET command=deleteSnapshot&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200511116
2019-06-10 14:01:49,851 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-a54e1563 ctx-0780498f) (logid:a10f9ca2) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:49,881 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:2cf85af7) Add job-2515 into job monitoring
2019-06-10 14:01:49,884 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp66233253-186590:ctx-a54e1563 ctx-0780498f) (logid:a10f9ca2) submit async job-2515, details: AsyncJobVO {id:2515, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 622, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8786","id":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"55df53d5-8d8b-426d-ba6d-3180474ffaa4\"}","ctxAccountId":"2","uuid":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","cmdEventType":"SNAPSHOT.DELETE","_":"1560200511116"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:49,885 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:b6ecd189) Executing AsyncJobVO {id:2515, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 622, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8786","id":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"55df53d5-8d8b-426d-ba6d-3180474ffaa4\"}","ctxAccountId":"2","uuid":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","cmdEventType":"SNAPSHOT.DELETE","_":"1560200511116"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:49,885 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-a54e1563 ctx-0780498f) (logid:a10f9ca2) ===END=== 192.168.55.58 -- GET command=deleteSnapshot&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200511116
2019-06-10 14:01:49,925 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) delete snapshot chain for snapshot: 622
2019-06-10 14:01:49,926 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Snapshot: 622 doesn't have children, so it's ok to delete it and its parents
2019-06-10 14:01:49,948 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2019-06-10 14:01:49,948 DEBUG [c.c.h.XenServerGuru] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:49,950 DEBUG [c.c.a.t.Request] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Seq 6-5229523592307647628: Sending { Cmd , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/26/0e20a916-ae5f-448b-a9ee-15ac2f36273e","volume":{"uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"04a00bdb-0463-3279-bd38-bbe619e04881","id":1,"poolType":"NetworkFilesystem","host":"192.168.200.232","path":"/home/export/primary","port":2049,"url":"NetworkFilesystem://192.168.200.232/home/export/primary/?ROLE=Primary&STOREUUID=04a00bdb-0463-3279-bd38-bbe619e04881","isManaged":false}},"name":"ROOT-13","size":42949672960,"path":"645500be-9376-4cd4-821d-d5ed788e0de1","volumeId":26,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":26,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.210/mnt/export/secondary","_role":"Image"}},"vmName":"i-2-13-VM","name":"meteor_ROOT-13_20190519080248","hypervisorType":"KVM","id":622,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2019-06-10 14:01:50,305 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null) (logid:) Seq 6-5229523592307647628: Processing: { Ans: , MgmtId: 14038012851765, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2019-06-10 14:01:50,305 DEBUG [c.c.a.t.Request] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Seq 6-5229523592307647628: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { Answer } }
2019-06-10 14:01:50,356 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Updating resource Type = snapshot count for Account = 2 Operation = decreasing Amount = 1
2019-06-10 14:01:50,367 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Updating resource Type = secondary_storage count for Account = 2 Operation = decreasing Amount = 12402425856
2019-06-10 14:01:50,388 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Complete async job-2515, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.SuccessResponse/null/{"success":true}
2019-06-10 14:01:50,389 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Publish async job-2515 complete on message bus
2019-06-10 14:01:50,389 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Wake up jobs related to job-2515
2019-06-10 14:01:50,389 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Update db status for job-2515
2019-06-10 14:01:50,391 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Wake up jobs joined with job-2515 and disjoin all subjobs created from job- 2515
2019-06-10 14:01:50,399 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:b6ecd189) Done executing org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd for job-2515
2019-06-10 14:01:50,399 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:b6ecd189) Remove job-2515 from job monitoring
2019-06-10 14:01:51,744 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0c21de49) (logid:de81a7b0) Seq 1-2212674791923289272: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2019-06-10 14:01:52,892 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-15c74113) (logid:57de8195) ===START=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b6ecd189-50a0-4bbb-a378-5e68c63a9193&response=json&_=1560200514162
2019-06-10 14:01:52,897 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-15c74113 ctx-1e2a1b04) (logid:57de8195) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:52,919 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-15c74113 ctx-1e2a1b04) (logid:57de8195) ===END=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b6ecd189-50a0-4bbb-a378-5e68c63a9193&response=json&_=1560200514162
2019-06-10 14:01:54,297 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-1a5d70c0) (logid:bad055c1) Begin cleanup expired async-jobs
2019-06-10 14:01:54,301 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-1a5d70c0) (logid:bad055c1) End cleanup expired async-jobs
2019-06-10 14:01:54,680 DEBUG [c.c.s.StatsCollector] (StatsCollector-6:ctx-b9e7f67b) (logid:911d3277) AutoScaling Monitor is running...
2019-06-10 14:01:56,259 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) StorageCollector is running...
2019-06-10 14:01:56,268 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,269 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,287 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 6-5229523592307647629: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,291 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,291 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,385 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 6-5229523592307647630: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,388 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,388 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,410 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 1-2212674791923289273: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,411 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,411 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,558 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 1-2212674791923289274: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,769 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-14824342) (logid:e721160c) HostStatsCollector is running...
2019-06-10 14:01:56,781 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-14824342) (logid:e721160c) Seq 1-2212674791923289275: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2019-06-10 14:01:58,540 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-8e373768) (logid:6f391e1e) ===START=== 192.168.55.58 -- GET command=listSnapshotPolicies&response=json&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200519810
2019-06-10 14:01:58,545 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-8e373768 ctx-2fdd1d7f) (logid:6f391e1e) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:58,556 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-8e373768 ctx-2fdd1d7f) (logid:6f391e1e) ===END=== 192.168.55.58 -- GET command=listSnapshotPolicies&response=json&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200519810
2019-06-10 14:01:58,940 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857309: Processing Seq 2-1857309: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:58,951 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857309: Sending Seq 2-1857309: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:59,941 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-232b1184) (logid:5a39d2be) Zone 1 is ready to launch console proxy
2019-06-10 14:02:00,057 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-ee9fa345) (logid:5c7b94e3) Zone 1 is ready to launch secondary storage VM
2019-06-10 14:02:02,629 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-947c9745) (logid:a60a67a6) ===START=== 192.168.55.58 -- GET command=deleteSnapshotPolicies&response=json&id=855eff6b-6c61-48af-8c4c-d8ddb153e32d&_=1560200523899
2019-06-10 14:02:02,634 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-947c9745 ctx-8e3f91a4) (logid:a60a67a6) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:02:02,666 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-947c9745 ctx-8e3f91a4) (logid:a60a67a6) ===END=== 192.168.55.58 -- GET command=deleteSnapshotPolicies&response=json&id=855eff6b-6c61-48af-8c4c-d8ddb153e32d&_=1560200523899
2019-06-10 14:02:04,296 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-61feccca) (logid:e09a9e07) Begin cleanup expired async-jobs
2019-06-10 14:02:04,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-61feccca) (logid:e09a9e07) End cleanup expired async-jobs
2019-06-10 14:02:06,793 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-b95461c5) (logid:13f24e31) ===START=== 192.168.55.58 -- GET command=listSnapshots&response=json&listAll=true&page=1&pagesize=20&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200528064
2019-06-10 14:02:06,798 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-b95461c5 ctx-ed6cb83d) (logid:13f24e31) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
Nicolas.Vazquez@shapeblue.com
www.shapeblue.com
Amadeus House, Floral Street, London WC2E 9DPUK
@shapeblue
Re: Failed to copy the volume from the source primary storage pool to
secondary storage
Posted by Asai <as...@globalchangemusic.org>.
Thanks for the response, Nicolas.
Here are the log entries from management-server.log corresponding to the
specific time period of running the download volume command:
2019-06-10 14:00:35,893 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Executing AsyncJobVO {id:2512, userId: 2, accountId: 2, instanceType: Volume, instanceId: 26, cmd: org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd, cmdInfo: {"mode":"HTTP_DOWNLOAD","response":"json","ctxUserId":"2","zoneid":"74a2a355-725a-4389-abe5-a24d52b5b7de","httpmethod":"GET","ctxStartEventId":"8780","id":"3a552f54-8d82-452a-ac5c-5144495d38c0","ctxDetails":"{\"interface com.cloud.dc.DataCenter\":\"74a2a355-725a-4389-abe5-a24d52b5b7de\",\"interface com.cloud.storage.Volume\":\"3a552f54-8d82-452a-ac5c-5144495d38c0\"}","ctxAccountId":"2","uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","cmdEventType":"VOLUME.EXTRACT","_":"1560200437111"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:00:35,933 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512 ctx-addef465) (logid:3ba6ac78) Sync job-2513 execution on object VmWorkJobQueue.13
2019-06-10 14:00:36,307 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6b017172) (logid:e6da8580) Execute sync-queue item: SyncQueueItemVO {id:327, queueId: 223, contentType: AsyncJob, contentId: 2513, lastProcessMsid: 14038012851765, lastprocessNumber: 114, lastProcessTime: Mon Jun 10 14:00:36 MST 2019, created: Mon Jun 10 14:00:35 MST 2019}
2019-06-10 14:00:36,308 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6b017172) (logid:e6da8580) Schedule queued job-2513
2019-06-10 14:00:36,331 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:426ea95f) Add job-2513 into job monitoring
2019-06-10 14:00:36,337 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Executing AsyncJobVO {id:2513, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkExtractVolume, cmdInfo: rO0ABXNyACBjb20uY2xvdWQudm0uVm1Xb3JrRXh0cmFjdFZvbHVtZfgl82-871PmAgACSgAIdm9sdW1lSWRKAAZ6b25lSWR4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAA10ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbAAAAAAAAAAaAAAAAAAAAAE, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Jun 10 14:00:35 MST 2019}
2019-06-10 14:00:36,337 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Run VM work job: com.cloud.vm.VmWorkExtractVolume for VM 13, job origin: 2512
2019-06-10 14:00:36,339 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Execute VM work job: com.cloud.vm.VmWorkExtractVolume{"volumeId":26,"zoneId":1,"userId":2,"accountId":2,"vmId":13,"handlerName":"VolumeApiServiceImpl"}
2019-06-10 14:00:36,380 ERROR [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) failed to copy volume to image store
java.lang.NullPointerException
at org.apache.cloudstack.storage.motion.StorageSystemDataMotionStrategy.isVolumeOnManagedStorage(StorageSystemDataMotionStrategy.java:202)
at org.apache.cloudstack.storage.motion.StorageSystemDataMotionStrategy.canHandle(StorageSystemDataMotionStrategy.java:182)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$1.canHandle(StorageStrategyFactoryImpl.java:52)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$1.canHandle(StorageStrategyFactoryImpl.java:49)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
at org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getDataMotionStrategy(StorageStrategyFactoryImpl.java:49)
at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:62)
at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:73)
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolumeFromPrimaryToImage(VolumeServiceImpl.java:1371)
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:1417)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:2515)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:3139)
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:498)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3178)
at sun.reflect.GeneratedMethodAccessor295.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy196.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-06-10 14:00:36,393 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2019-06-10 14:00:36,393 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:36,394 DEBUG [c.c.a.t.Request] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Seq 6-5229523592307647624: Sending { Cmd , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.210/mnt/export/secondary","_role":"Image"}},"name":"ROOT-13","size":42949672960,"path":"volumes/2/26","volumeId":26,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":26,"deviceId":0,"hypervisorType":"KVM"}},"wait":0}}] }
2019-06-10 14:00:36,460 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null) (logid:) Seq 6-5229523592307647624: Processing: { Ans: , MgmtId: 14038012851765, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"volume parent directory 2 doesn't exist","wait":0}}] }
2019-06-10 14:00:36,461 DEBUG [c.c.a.t.Request] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Seq 6-5229523592307647624: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { Answer } }
2019-06-10 14:00:36,494 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@40c3d5da), no need to delete from object in store ref table
2019-06-10 14:00:36,494 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Invocation exception, caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
2019-06-10 14:00:36,494 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513 ctx-2a57f8fd) (logid:3ba6ac78) Rethrow exception com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
2019-06-10 14:00:36,494 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Done with run of VM work job: com.cloud.vm.VmWorkExtractVolume for VM 13, job origin: 2512
2019-06-10 14:00:36,494 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Unable to complete AsyncJobVO {id:2513, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkExtractVolume, cmdInfo: rO0ABXNyACBjb20uY2xvdWQudm0uVm1Xb3JrRXh0cmFjdFZvbHVtZfgl82-871PmAgACSgAIdm9sdW1lSWRKAAZ6b25lSWR4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAA10ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbAAAAAAAAAAaAAAAAAAAAAE, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Jun 10 14:00:35 MST 2019}, job origin:2512
com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:2529)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:3139)
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:498)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3178)
at sun.reflect.GeneratedMethodAccessor295.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy196.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-06-10 14:00:36,496 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Complete async job-2513, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0AFRGYWlsZWQgdG8gY29weSB0aGUgdm9sdW1lIGZyb20gdGhlIHNvdXJjZSBwcmltYXJ5IHN0b3JhZ2UgcG9vbCB0byBzZWNvbmRhcnkgc3RvcmFnZS51cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAB9zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABUwACGZpbGVOYW1lcQB-AAVMAAptZXRob2ROYW1lcQB-AAV4cAAACeF0ACZjb20uY2xvdWQuc3RvcmFnZS5Wb2x1bWVBcGlTZXJ2aWNlSW1wbHQAGVZvbHVtZUFwaVNlcnZpY2VJbXBsLmphdmF0ABhvcmNoZXN0cmF0ZUV4dHJhY3RWb2x1bWVzcQB-AAwAAAxDcQB-AA5xAH4AD3EAfgAQc3EAfgAM_____nQAJHN1bi5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHNxAH4ADAAAAD5xAH4AE3EAfgAUdAAGaW52b2tlc3EAfgAMAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AF3NxAH4ADAAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAXc3EAfgAMAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4ADAAADGpxAH4ADnEAfgAPcQB-ACFzcQB-AAz_____dAAmc3VuLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3IyOTVwcQB-ABdzcQB-AAwAAAArcQB-ABlxAH4AGnEAfgAXc3EAfgAMAAAB8nEAfgAccQB-AB1xAH4AF3NxAH4ADAAAAVJ0AChvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5zdXBwb3J0LkFvcFV0aWxzdAANQW9wVXRpbHMuamF2YXQAHmludm9rZUpvaW5wb2ludFVzaW5nUmVmbGVjdGlvbnNxAH4ADAAAAMV0ADxvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5mcmFtZXdvcmsuUmVmbGVjdGl2ZU1ldGhvZEludm9jYXRpb250AB9SZWZsZWN0aXZlTWV0aG9kSW52b2NhdGlvbi5qYXZhdAAPaW52b2tlSm9pbnBvaW50c3EAfgAMAAAAo3EAfgAscQB-AC10AAdwcm9jZWVkc3EAfgAMAAAAXHQAP29yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmludGVyY2VwdG9yLkV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvcnQAIEV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvci5qYXZhcQB-ABdzcQB-AAwAAAC5cQB-ACxxAH4ALXEAfgAwc3EAfgAMAAAA1HQANG9yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmZyYW1ld29yay5KZGtEeW5hbWljQW9wUHJveHl0ABdKZGtEeW5hbWljQW9wUHJveHkuamF2YXEAfgAXc3EAfgAM_____3QAF2NvbS5zdW4ucHJveHkuJFByb3h5MTk2cHEAfgAhc3EAfgAMAAAAZnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgAMAAACRXQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4ADAAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4ADAAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-AAwAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgBIdAAPY2FsbFdpdGhDb250ZXh0c3EAfgAMAAAANXEAfgBLcQB-AEh0AA5ydW5XaXRoQ29udGV4dHNxAH4ADAAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4ARHEAfgBFc3EAfgAMAAACEXEAfgA_cQB-AEBxAH4ARXNxAH4ADAAAAf90AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4ASXNxAH4ADAAAAQp0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-AEVzcQB-AAwAAAR2dAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJzcQB-AAwAAAJpdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBacQB-AEVzcQB-AAwAAALpdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-AEVzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUxteyOEAIAAUwABGxpc3RxAH4AB3hyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlQ29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgBmeAAAEJp3CAAAAAAAAAAAeA
2019-06-10 14:00:36,497 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Publish async job-2513 complete on message bus
2019-06-10 14:00:36,497 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Wake up jobs related to job-2513
2019-06-10 14:00:36,497 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Update db status for job-2513
2019-06-10 14:00:36,498 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Wake up jobs joined with job-2513 and disjoin all subjobs created from job- 2513
2019-06-10 14:00:36,508 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Done executing com.cloud.vm.VmWorkExtractVolume for job-2513
2019-06-10 14:00:36,510 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-42:ctx-a1e70224 job-2512/job-2513) (logid:3ba6ac78) Remove job-2513 from job monitoring
2019-06-10 14:00:36,532 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Unexpected exception while executing org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd
com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from the source primary storage pool to secondary storage.
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:2529)
at com.cloud.storage.VolumeApiServiceImpl.orchestrateExtractVolume(VolumeApiServiceImpl.java:3139)
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:498)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3178)
at sun.reflect.GeneratedMethodAccessor295.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy196.handleVmWorkJob(Unknown Source)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-06-10 14:00:36,533 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Complete async job-2512, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to copy the volume from the source primary storage pool to secondary storage."}
2019-06-10 14:00:36,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Publish async job-2512 complete on message bus
2019-06-10 14:00:36,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Wake up jobs related to job-2512
2019-06-10 14:00:36,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Update db status for job-2512
2019-06-10 14:00:36,538 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Wake up jobs joined with job-2512 and disjoin all subjobs created from job- 2512
2019-06-10 14:00:36,546 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Done executing org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd for job-2512
2019-06-10 14:00:36,546 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-86:ctx-68e69b5d job-2512) (logid:3ba6ac78) Remove job-2512 from job monitoring
2019-06-10 14:00:38,901 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-69281f08) (logid:033aa8e9) ===START=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=3ba6ac78-2111-4fa2-92d4-bfb04db2b7e3&response=json&_=1560200440168
2019-06-10 14:00:38,904 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-69281f08 ctx-7836867d) (logid:033aa8e9) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:00:38,926 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-69281f08 ctx-7836867d) (logid:033aa8e9) ===END=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=3ba6ac78-2111-4fa2-92d4-bfb04db2b7e3&response=json&_=1560200440168
2019-06-10 14:00:43,930 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857300: Processing Seq 2-1857300: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:00:43,941 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857300: Sending Seq 2-1857300: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:00:44,296 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-c6317c11) (logid:2703bdbf) Begin cleanup expired async-jobs
2019-06-10 14:00:44,301 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-c6317c11) (logid:2703bdbf) End cleanup expired async-jobs
2019-06-10 14:00:44,621 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0607e04a) (logid:57df045a) Found 2 routers to update status.
2019-06-10 14:00:44,622 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0607e04a) (logid:57df045a) Found 0 VPC networks to update Redundant State.
2019-06-10 14:00:44,624 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0607e04a) (logid:57df045a) Found 0 networks to update RvR status.
2019-06-10 14:00:51,612 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-f8169009) (logid:407c8b82) Seq 1-2212674791923289268: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2019-06-10 14:00:53,932 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857301: Processing Seq 2-1857301: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:00:53,941 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857301: Sending Seq 2-1857301: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:00:54,296 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-79a6dcbe) (logid:f73e4c31) Begin cleanup expired async-jobs
2019-06-10 14:00:54,300 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-79a6dcbe) (logid:f73e4c31) End cleanup expired async-jobs
2019-06-10 14:00:54,679 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-6ef02f9d) (logid:13f535b4) AutoScaling Monitor is running...
2019-06-10 14:00:55,915 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) StorageCollector is running...
2019-06-10 14:00:55,922 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:55,922 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:55,983 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 6-5229523592307647625: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:55,986 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:55,986 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:56,079 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 6-5229523592307647626: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:56,081 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:56,081 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:56,105 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 1-2212674791923289269: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:56,107 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:00:56,107 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:00:56,259 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-fa64572d) (logid:0bd0a0cf) Seq 1-2212674791923289270: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:00:56,759 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-f0ec945d) (logid:0cde1d85) HostStatsCollector is running...
2019-06-10 14:00:56,768 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-f0ec945d) (logid:0cde1d85) Seq 1-2212674791923289271: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2019-06-10 14:00:58,934 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-1857302: Processing Seq 2-1857302: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:00:58,944 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-1857302: Sending Seq 2-1857302: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:00:59,936 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-5887b752) (logid:7ad48ac5) Zone 1 is ready to launch console proxy
2019-06-10 14:01:00,052 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-5a269b40) (logid:d9687cad) Zone 1 is ready to launch secondary storage VM
2019-06-10 14:01:04,297 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9470bc78) (logid:ec23a634) Begin cleanup expired async-jobs
2019-06-10 14:01:04,301 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9470bc78) (logid:ec23a634) End cleanup expired async-jobs
2019-06-10 14:01:07,023 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) Ping from 1(monota.globalchange.media)
2019-06-10 14:01:07,024 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process host VM state report from ping process. host: 1
2019-06-10 14:01:07,039 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process VM state report. host: 1, number of records in report: 12
2019-06-10 14:01:07,039 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 1, power state: PowerOn
2019-06-10 14:01:07,041 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 1
2019-06-10 14:01:07,041 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 2, power state: PowerOn
2019-06-10 14:01:07,042 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 2
2019-06-10 14:01:07,042 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 35, power state: PowerOn
2019-06-10 14:01:07,043 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 35
2019-06-10 14:01:07,043 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 4, power state: PowerOn
2019-06-10 14:01:07,045 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 4
2019-06-10 14:01:07,045 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 20, power state: PowerOn
2019-06-10 14:01:07,046 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 20
2019-06-10 14:01:07,046 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 5, power state: PowerOn
2019-06-10 14:01:07,047 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 5
2019-06-10 14:01:07,047 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 21, power state: PowerOn
2019-06-10 14:01:07,049 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 21
2019-06-10 14:01:07,049 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 22, power state: PowerOn
2019-06-10 14:01:07,050 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 22
2019-06-10 14:01:07,050 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 25, power state: PowerOn
2019-06-10 14:01:07,052 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 25
2019-06-10 14:01:07,052 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 9, power state: PowerOn
2019-06-10 14:01:07,053 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 9
2019-06-10 14:01:07,053 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 10, power state: PowerOn
2019-06-10 14:01:07,054 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 10
2019-06-10 14:01:07,055 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 1, vm id: 12, power state: PowerOn
2019-06-10 14:01:07,056 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 12
2019-06-10 14:01:07,063 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Done with process of VM state report. host: 1
2019-06-10 14:01:08,936 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857303: Processing Seq 2-1857303: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:08,947 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857303: Sending Seq 2-1857303: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:09,387 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Resetting hosts suitable for reconnect
2019-06-10 14:01:09,388 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Completed resetting hosts suitable for reconnect
2019-06-10 14:01:09,388 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Acquiring hosts for clusters already owned by this management server
2019-06-10 14:01:09,389 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Completed acquiring hosts for clusters already owned by this management server
2019-06-10 14:01:09,389 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Acquiring hosts for clusters not owned by any management server
2019-06-10 14:01:09,389 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-da5e2f27) (logid:ce31af42) Completed acquiring hosts for clusters not owned by any management server
2019-06-10 14:01:14,299 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-62657402) (logid:9649aed8) Begin cleanup expired async-jobs
2019-06-10 14:01:14,304 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-62657402) (logid:9649aed8) End cleanup expired async-jobs
2019-06-10 14:01:14,621 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7afba768) (logid:372726e3) Found 2 routers to update status.
2019-06-10 14:01:14,623 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7afba768) (logid:372726e3) Found 0 VPC networks to update Redundant State.
2019-06-10 14:01:14,624 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7afba768) (logid:372726e3) Found 0 networks to update RvR status.
2019-06-10 14:01:18,937 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 2-1857304: Processing Seq 2-1857304: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:18,952 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 2-1857304: Sending Seq 2-1857304: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:24,297 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9e74ead5) (logid:e3e07d2a) Begin cleanup expired async-jobs
2019-06-10 14:01:24,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9e74ead5) (logid:e3e07d2a) End cleanup expired async-jobs
2019-06-10 14:01:28,902 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-7f2ae184) (logid:b45ca26f) ===START=== 192.168.55.58 -- GET command=listSnapshots&response=json&listAll=true&page=1&pagesize=20&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200490168
2019-06-10 14:01:28,907 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-7f2ae184 ctx-52ada595) (logid:b45ca26f) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:28,937 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) SeqA 2-1857305: Processing Seq 2-1857305: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:28,954 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) SeqA 2-1857305: Sending Seq 2-1857305: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:28,955 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-7f2ae184 ctx-52ada595) (logid:b45ca26f) ===END=== 192.168.55.58 -- GET command=listSnapshots&response=json&listAll=true&page=1&pagesize=20&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200490168
2019-06-10 14:01:29,211 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-efd528b8) (logid:aa54274c) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=c2b7a1aa-b410-47d5-b552-025ec4a0650b&response=json&_=1560200490479
2019-06-10 14:01:29,216 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-efd528b8 ctx-02b5c208) (logid:aa54274c) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:29,242 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-efd528b8 ctx-02b5c208) (logid:aa54274c) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=c2b7a1aa-b410-47d5-b552-025ec4a0650b&response=json&_=1560200490479
2019-06-10 14:01:29,939 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-02e95550) (logid:d13dc3d8) Zone 1 is ready to launch console proxy
2019-06-10 14:01:30,058 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-0126d0fd) (logid:0ea22536) Zone 1 is ready to launch secondary storage VM
2019-06-10 14:01:31,064 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) Ping from 2(v-2-VM)
2019-06-10 14:01:33,969 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) (logid:) Ping from 6(s-1-VM)
2019-06-10 14:01:34,298 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-92ea9ab4) (logid:059cd292) Begin cleanup expired async-jobs
2019-06-10 14:01:34,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-92ea9ab4) (logid:059cd292) End cleanup expired async-jobs
2019-06-10 14:01:38,609 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-89132598) (logid:ed0da0ba) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200499879
2019-06-10 14:01:38,614 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-89132598 ctx-d2f260bf) (logid:ed0da0ba) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:38,634 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-89132598 ctx-d2f260bf) (logid:ed0da0ba) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200499879
2019-06-10 14:01:38,939 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857307: Processing Seq 2-1857307: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:38,950 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 2-1857307: Sending Seq 2-1857307: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:39,213 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-1df0c4be) (logid:5cd3fb69) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200500482
2019-06-10 14:01:39,217 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-1df0c4be ctx-86dc0b4e) (logid:5cd3fb69) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:39,237 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-1df0c4be ctx-86dc0b4e) (logid:5cd3fb69) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200500482
2019-06-10 14:01:43,519 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-60ef5bab) (logid:c102571b) ===START=== 192.168.55.58 -- GET command=deleteSnapshot&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200504789
2019-06-10 14:01:43,525 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-60ef5bab ctx-3d0b2beb) (logid:c102571b) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:43,559 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:e483ef83) Add job-2514 into job monitoring
2019-06-10 14:01:43,563 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp66233253-180790:ctx-60ef5bab ctx-3d0b2beb) (logid:c102571b) submit async job-2514, details: AsyncJobVO {id:2514, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 696, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8783","id":"bf492ec5-880b-47a9-bbb2-3be13f67c734","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"bf492ec5-880b-47a9-bbb2-3be13f67c734\"}","ctxAccountId":"2","uuid":"bf492ec5-880b-47a9-bbb2-3be13f67c734","cmdEventType":"SNAPSHOT.DELETE","_":"1560200504789"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:43,563 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:b5259bd3) Executing AsyncJobVO {id:2514, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 696, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8783","id":"bf492ec5-880b-47a9-bbb2-3be13f67c734","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"bf492ec5-880b-47a9-bbb2-3be13f67c734\"}","ctxAccountId":"2","uuid":"bf492ec5-880b-47a9-bbb2-3be13f67c734","cmdEventType":"SNAPSHOT.DELETE","_":"1560200504789"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:43,564 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-60ef5bab ctx-3d0b2beb) (logid:c102571b) ===END=== 192.168.55.58 -- GET command=deleteSnapshot&id=bf492ec5-880b-47a9-bbb2-3be13f67c734&response=json&_=1560200504789
2019-06-10 14:01:43,605 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) delete snapshot chain for snapshot: 696
2019-06-10 14:01:43,606 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Snapshot: 696 doesn't have children, so it's ok to delete it and its parents
2019-06-10 14:01:43,628 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2019-06-10 14:01:43,628 DEBUG [c.c.h.XenServerGuru] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:43,630 DEBUG [c.c.a.t.Request] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Seq 6-5229523592307647627: Sending { Cmd , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/26/6894b376-722d-45ad-abe2-03fc3a0f64ad","volume":{"uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"04a00bdb-0463-3279-bd38-bbe619e04881","id":1,"poolType":"NetworkFilesystem","host":"192.168.200.232","path":"/home/export/primary","port":2049,"url":"NetworkFilesystem://192.168.200.232/home/export/primary/?ROLE=Primary&STOREUUID=04a00bdb-0463-3279-bd38-bbe619e04881","isManaged":false}},"name":"ROOT-13","size":42949672960,"path":"645500be-9376-4cd4-821d-d5ed788e0de1","volumeId":26,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":26,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.210/mnt/export/secondary","_role":"Image"}},"vmName":"i-2-13-VM","name":"meteor_ROOT-13_20190609080249","hypervisorType":"KVM","id":696,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2019-06-10 14:01:44,298 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0720dc96) (logid:546ec0c3) Begin cleanup expired async-jobs
2019-06-10 14:01:44,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0720dc96) (logid:546ec0c3) End cleanup expired async-jobs
2019-06-10 14:01:44,342 DEBUG [c.c.a.t.Request] (AgentManager-Handler-9:null) (logid:) Seq 6-5229523592307647627: Processing: { Ans: , MgmtId: 14038012851765, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2019-06-10 14:01:44,342 DEBUG [c.c.a.t.Request] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Seq 6-5229523592307647627: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { Answer } }
2019-06-10 14:01:44,387 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Updating resource Type = snapshot count for Account = 2 Operation = decreasing Amount = 1
2019-06-10 14:01:44,398 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Updating resource Type = secondary_storage count for Account = 2 Operation = decreasing Amount = 12402425856
2019-06-10 14:01:44,420 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Complete async job-2514, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.SuccessResponse/null/{"success":true}
2019-06-10 14:01:44,421 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Publish async job-2514 complete on message bus
2019-06-10 14:01:44,421 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Wake up jobs related to job-2514
2019-06-10 14:01:44,421 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Update db status for job-2514
2019-06-10 14:01:44,422 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514 ctx-2300227f) (logid:b5259bd3) Wake up jobs joined with job-2514 and disjoin all subjobs created from job- 2514
2019-06-10 14:01:44,430 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:b5259bd3) Done executing org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd for job-2514
2019-06-10 14:01:44,430 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-88:ctx-0f674010 job-2514) (logid:b5259bd3) Remove job-2514 from job monitoring
2019-06-10 14:01:44,621 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bcd8a75a) (logid:b0857b64) Found 2 routers to update status.
2019-06-10 14:01:44,622 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bcd8a75a) (logid:b0857b64) Found 0 VPC networks to update Redundant State.
2019-06-10 14:01:44,623 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bcd8a75a) (logid:b0857b64) Found 0 networks to update RvR status.
2019-06-10 14:01:45,961 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-cf56e888) (logid:730f7064) ===START=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200507231
2019-06-10 14:01:45,965 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-cf56e888 ctx-7359a813) (logid:730f7064) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:45,985 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-cf56e888 ctx-7359a813) (logid:730f7064) ===END=== 192.168.55.58 -- GET command=listSnapshots&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200507231
2019-06-10 14:01:46,575 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-5388c6a0) (logid:7e273a2e) ===START=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b5259bd3-c108-4f89-a91a-077831d8dfca&response=json&_=1560200507844
2019-06-10 14:01:46,579 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-5388c6a0 ctx-4251a1bb) (logid:7e273a2e) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:46,600 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-5388c6a0 ctx-4251a1bb) (logid:7e273a2e) ===END=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b5259bd3-c108-4f89-a91a-077831d8dfca&response=json&_=1560200507844
2019-06-10 14:01:48,940 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857308: Processing Seq 2-1857308: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:48,951 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 2-1857308: Sending Seq 2-1857308: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:49,846 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-a54e1563) (logid:a10f9ca2) ===START=== 192.168.55.58 -- GET command=deleteSnapshot&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200511116
2019-06-10 14:01:49,851 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-a54e1563 ctx-0780498f) (logid:a10f9ca2) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:49,881 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:2cf85af7) Add job-2515 into job monitoring
2019-06-10 14:01:49,884 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp66233253-186590:ctx-a54e1563 ctx-0780498f) (logid:a10f9ca2) submit async job-2515, details: AsyncJobVO {id:2515, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 622, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8786","id":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"55df53d5-8d8b-426d-ba6d-3180474ffaa4\"}","ctxAccountId":"2","uuid":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","cmdEventType":"SNAPSHOT.DELETE","_":"1560200511116"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:49,885 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:b6ecd189) Executing AsyncJobVO {id:2515, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 622, cmd: org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"8786","id":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"55df53d5-8d8b-426d-ba6d-3180474ffaa4\"}","ctxAccountId":"2","uuid":"55df53d5-8d8b-426d-ba6d-3180474ffaa4","cmdEventType":"SNAPSHOT.DELETE","_":"1560200511116"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038012851765, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-06-10 14:01:49,885 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-a54e1563 ctx-0780498f) (logid:a10f9ca2) ===END=== 192.168.55.58 -- GET command=deleteSnapshot&id=55df53d5-8d8b-426d-ba6d-3180474ffaa4&response=json&_=1560200511116
2019-06-10 14:01:49,925 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) delete snapshot chain for snapshot: 622
2019-06-10 14:01:49,926 DEBUG [o.a.c.s.s.XenserverSnapshotStrategy] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Snapshot: 622 doesn't have children, so it's ok to delete it and its parents
2019-06-10 14:01:49,948 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2019-06-10 14:01:49,948 DEBUG [c.c.h.XenServerGuru] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:49,950 DEBUG [c.c.a.t.Request] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Seq 6-5229523592307647628: Sending { Cmd , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/26/0e20a916-ae5f-448b-a9ee-15ac2f36273e","volume":{"uuid":"3a552f54-8d82-452a-ac5c-5144495d38c0","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"04a00bdb-0463-3279-bd38-bbe619e04881","id":1,"poolType":"NetworkFilesystem","host":"192.168.200.232","path":"/home/export/primary","port":2049,"url":"NetworkFilesystem://192.168.200.232/home/export/primary/?ROLE=Primary&STOREUUID=04a00bdb-0463-3279-bd38-bbe619e04881","isManaged":false}},"name":"ROOT-13","size":42949672960,"path":"645500be-9376-4cd4-821d-d5ed788e0de1","volumeId":26,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":26,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.210/mnt/export/secondary","_role":"Image"}},"vmName":"i-2-13-VM","name":"meteor_ROOT-13_20190519080248","hypervisorType":"KVM","id":622,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2019-06-10 14:01:50,305 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null) (logid:) Seq 6-5229523592307647628: Processing: { Ans: , MgmtId: 14038012851765, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2019-06-10 14:01:50,305 DEBUG [c.c.a.t.Request] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Seq 6-5229523592307647628: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { Answer } }
2019-06-10 14:01:50,356 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Updating resource Type = snapshot count for Account = 2 Operation = decreasing Amount = 1
2019-06-10 14:01:50,367 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Updating resource Type = secondary_storage count for Account = 2 Operation = decreasing Amount = 12402425856
2019-06-10 14:01:50,388 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Complete async job-2515, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.SuccessResponse/null/{"success":true}
2019-06-10 14:01:50,389 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Publish async job-2515 complete on message bus
2019-06-10 14:01:50,389 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Wake up jobs related to job-2515
2019-06-10 14:01:50,389 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Update db status for job-2515
2019-06-10 14:01:50,391 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515 ctx-ca333dba) (logid:b6ecd189) Wake up jobs joined with job-2515 and disjoin all subjobs created from job- 2515
2019-06-10 14:01:50,399 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:b6ecd189) Done executing org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd for job-2515
2019-06-10 14:01:50,399 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-89:ctx-3b90c240 job-2515) (logid:b6ecd189) Remove job-2515 from job monitoring
2019-06-10 14:01:51,744 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0c21de49) (logid:de81a7b0) Seq 1-2212674791923289272: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2019-06-10 14:01:52,892 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-15c74113) (logid:57de8195) ===START=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b6ecd189-50a0-4bbb-a378-5e68c63a9193&response=json&_=1560200514162
2019-06-10 14:01:52,897 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-15c74113 ctx-1e2a1b04) (logid:57de8195) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:52,919 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-15c74113 ctx-1e2a1b04) (logid:57de8195) ===END=== 192.168.55.58 -- GET command=queryAsyncJobResult&jobId=b6ecd189-50a0-4bbb-a378-5e68c63a9193&response=json&_=1560200514162
2019-06-10 14:01:54,297 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-1a5d70c0) (logid:bad055c1) Begin cleanup expired async-jobs
2019-06-10 14:01:54,301 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-1a5d70c0) (logid:bad055c1) End cleanup expired async-jobs
2019-06-10 14:01:54,680 DEBUG [c.c.s.StatsCollector] (StatsCollector-6:ctx-b9e7f67b) (logid:911d3277) AutoScaling Monitor is running...
2019-06-10 14:01:56,259 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) StorageCollector is running...
2019-06-10 14:01:56,268 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,269 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,287 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 6-5229523592307647629: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,291 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,291 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,385 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 6-5229523592307647630: Received: { Ans: , MgmtId: 14038012851765, via: 6(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,388 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,388 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,410 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 1-2212674791923289273: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,411 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2019-06-10 14:01:56,411 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) We are returning the default host to execute commands because the command is not of Copy type.
2019-06-10 14:01:56,558 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-af6f7b52) (logid:989135a5) Seq 1-2212674791923289274: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-06-10 14:01:56,769 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-14824342) (logid:e721160c) HostStatsCollector is running...
2019-06-10 14:01:56,781 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-14824342) (logid:e721160c) Seq 1-2212674791923289275: Received: { Ans: , MgmtId: 14038012851765, via: 1(monota.globalchange.media), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2019-06-10 14:01:58,540 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-8e373768) (logid:6f391e1e) ===START=== 192.168.55.58 -- GET command=listSnapshotPolicies&response=json&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200519810
2019-06-10 14:01:58,545 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-8e373768 ctx-2fdd1d7f) (logid:6f391e1e) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:01:58,556 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-8e373768 ctx-2fdd1d7f) (logid:6f391e1e) ===END=== 192.168.55.58 -- GET command=listSnapshotPolicies&response=json&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200519810
2019-06-10 14:01:58,940 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857309: Processing Seq 2-1857309: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2019-06-10 14:01:58,951 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) SeqA 2-1857309: Sending Seq 2-1857309: { Ans: , MgmtId: 14038012851765, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-06-10 14:01:59,941 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-232b1184) (logid:5a39d2be) Zone 1 is ready to launch console proxy
2019-06-10 14:02:00,057 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-ee9fa345) (logid:5c7b94e3) Zone 1 is ready to launch secondary storage VM
2019-06-10 14:02:02,629 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-947c9745) (logid:a60a67a6) ===START=== 192.168.55.58 -- GET command=deleteSnapshotPolicies&response=json&id=855eff6b-6c61-48af-8c4c-d8ddb153e32d&_=1560200523899
2019-06-10 14:02:02,634 DEBUG [c.c.a.ApiServer] (qtp66233253-180790:ctx-947c9745 ctx-8e3f91a4) (logid:a60a67a6) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-06-10 14:02:02,666 DEBUG [c.c.a.ApiServlet] (qtp66233253-180790:ctx-947c9745 ctx-8e3f91a4) (logid:a60a67a6) ===END=== 192.168.55.58 -- GET command=deleteSnapshotPolicies&response=json&id=855eff6b-6c61-48af-8c4c-d8ddb153e32d&_=1560200523899
2019-06-10 14:02:04,296 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-61feccca) (logid:e09a9e07) Begin cleanup expired async-jobs
2019-06-10 14:02:04,302 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-61feccca) (logid:e09a9e07) End cleanup expired async-jobs
2019-06-10 14:02:06,793 DEBUG [c.c.a.ApiServlet] (qtp66233253-186590:ctx-b95461c5) (logid:13f24e31) ===START=== 192.168.55.58 -- GET command=listSnapshots&response=json&listAll=true&page=1&pagesize=20&volumeid=3a552f54-8d82-452a-ac5c-5144495d38c0&_=1560200528064
2019-06-10 14:02:06,798 DEBUG [c.c.a.ApiServer] (qtp66233253-186590:ctx-b95461c5 ctx-ed6cb83d) (logid:13f24e31) CIDRs from which account 'Acct[4d250460-b28e-11e6-9ea0-0cc47ac4f634-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
Re: Failed to copy the volume from the source primary
storage pool to secondary storage
Posted by Nicolas Vazquez <Ni...@shapeblue.com>.
Hi Asai,
The error itself is not very descriptive but you can find more information on the logs around the failure. If you need help with it please upload it
Regards,
Nicolas Vazquez
De: Asai
Enviado: lunes, 10 de junio 18:08
Asunto: Failed to copy the volume from the source primary storage pool to secondary storage
Para: users@cloudstack.apache.org
Greetings,
I am trying to figure out the steps in migrating a KVM based guest to a
Xen based guest.
I have attempted to download the KVM volume so that I can attempt to
attach the volume to a Xen based VM, however I get the following error
when trying to download the volume:
"Failed to copy the volume from the source primary storage pool to
secondary storage"
My secondary storage is 90% full, but it's actually got over 500 GB in
it and this VM is under 60 GB, so there is plenty of room for the VM on
secondary.
Any advice or direction would be appreciated.
Asai
Nicolas.Vazquez@shapeblue.com
www.shapeblue.com
Amadeus House, Floral Street, London WC2E 9DPUK
@shapeblue