search

apache / cloudstack

Apache CloudStack is an opensource Infrastructure as a Service (IaaS) cloud computing platform
https://cloudstack.apache.org/
Apache License 2.0
1.98k stars 1.09k forks source link

Unable to find the target datastore in datacenter -ACS with VMware #6270

Closed ccycv closed 2 years ago

ccycv commented 2 years ago
ISSUE TYPE
COMPONENT NAME
Storage
CLOUDSTACK VERSION
4.15.x to 4.16.1
CONFIGURATION
ACS 4.16.x with VMware 6.5 - Advanced Networking - Local Storage
OS / ENVIRONMENT
CentOS 7.9, Ubuntu 20
SUMMARY

The migration for VMs with local storage is not working, tested in 3 different environment with similar setups. I verified the VMware for cloud.uuid, it is the same uuid as in the cloudstack.

STEPS TO REPRODUCE
- Stop Instance
- Migrate instance to another primary storage
EXPECTED RESULTS
Migrate the volume with success, in a older version was working
ACTUAL RESULTS
2022-04-15 06:18:52,030 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-309:ctx-515baff0 fra-de-001.domain.tld, job-2857/job-2858, cmd: MigrateVmToPoolCommand) (logid:e8851491) Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
2022-04-15 06:18:52,080 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-309:ctx-515baff0 fra-de-001.domain.tld, job-2857/job-2858, cmd: MigrateVmToPoolCommand) (logid:e8851491) Change data store for VM i-2-546-VM failed: Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
2022-04-15 06:18:52,086 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-309:ctx-515baff0) (logid:e8851491) Seq 1-3247939756264335318: Response Received:
2022-04-15 06:18:52,088 DEBUG [c.c.a.t.Request] (DirectAgent-309:ctx-515baff0) (logid:e8851491) Seq 1-3247939756264335318: Processing:  { Ans: , MgmtId: 39908814623087, via: 1(fra-de-001.domain.tld), Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":"false","details":"Exception: com.cloud.utils.exception.CloudRuntimeException
Message: Change data store for VM i-2-546-VM failed
Stack: com.cloud.utils.exception.CloudRuntimeException: Change data store for VM i-2-546-VM failed
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4550)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4507)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:501)
        at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
        at com.cloud.hypervisor.vmware.resource.VmwareResource.relocateVirtualMachine(VmwareResource.java:7588)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4545)
        ... 14 more
","wait":"0","bypassHostMaintenance":"false"}}] }
2022-04-15 06:18:52,088 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-309:ctx-515baff0) (logid:e8851491) Seq 1-3247939756264335318: No more commands found
2022-04-15 06:18:52,088 DEBUG [c.c.a.t.Request] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) Seq 1-3247939756264335318: Received:  { Ans: , MgmtId: 39908814623087, via: 1(fra-de-001.domain.tld), Ver: v1, Flags: 110, { Answer } }
2022-04-15 06:18:52,088 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) Cleaning up after hypervisor pool migration volumes for VM i-2-546-VM(143774cd-6cd7-4064-8383-45cf30c55afc)
2022-04-15 06:18:52,097 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) VM instance {id: "546", name: "i-2-546-VM", uuid: "143774cd-6cd7-4064-8383-45cf30c55afc", type="User"} state transited from [Migrating] to [Stopped] with event [AgentReportStopped]. VM's original host: Host {"id": "1", "name": "fra-de-001.domain.tld", "uuid": "d9b7391b-4ff6-4e0a-bcc2-697e472801c4", "type"="Routing"}, new host: null, host before state transition: null
2022-04-15 06:18:52,100 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) Hosts's actual total CPU: 76640 and CPU after applying overprovisioning: 229920
2022-04-15 06:18:52,100 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) Hosts's actual total RAM: (127.89 GB) 137320136704 and RAM after applying overprovisioning: (255.78 GB) 274640273408
2022-04-15 06:18:52,100 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) release cpu from host: 1, old used: 162600,reserved: 2000, actual total: 76640, total with overprovisioning: 229920; new used: 160600,reserved:2000; movedfromreserved: false,moveToReserveredfalse
2022-04-15 06:18:52,100 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) release mem from host: 1, old used: (170.75 GB) 183341416448,reserved: (2.00 GB) 2147483648, total: (255.78 GB) 274640273408; new used: (168.75 GB) 181193932800,reserved:(2.00 GB) 2147483648; movedfromreserved: false,moveToReserveredfalse
2022-04-15 06:18:52,107 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) Invocation exception, caused by: com.cloud.utils.exception.CloudRuntimeException: VM ID: 143774cd-6cd7-4064-8383-45cf30c55afc migration failed. Exception: com.cloud.utils.exception.CloudRuntimeException
Message: Change data store for VM i-2-546-VM failed
Stack: com.cloud.utils.exception.CloudRuntimeException: Change data store for VM i-2-546-VM failed
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4550)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4507)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:501)
        at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
        at com.cloud.hypervisor.vmware.resource.VmwareResource.relocateVirtualMachine(VmwareResource.java:7588)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4545)
        ... 14 more

2022-04-15 06:18:52,107 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858 ctx-8da49044) (logid:e8851491) Rethrow exception com.cloud.utils.exception.CloudRuntimeException: VM ID: 143774cd-6cd7-4064-8383-45cf30c55afc migration failed. Exception: com.cloud.utils.exception.CloudRuntimeException
Message: Change data store for VM i-2-546-VM failed
Stack: com.cloud.utils.exception.CloudRuntimeException: Change data store for VM i-2-546-VM failed
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4550)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4507)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:501)
        at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
        at com.cloud.hypervisor.vmware.resource.VmwareResource.relocateVirtualMachine(VmwareResource.java:7588)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4545)
        ... 14 more

2022-04-15 06:18:52,107 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Done with run of VM work job: com.cloud.vm.VmWorkStorageMigration for VM 546, job origin: 2857
2022-04-15 06:18:52,107 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Unable to complete AsyncJobVO: {id:2858, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStorageMigration, cmdInfo: rO0ABXNyACNjb20uY2xvdWQudm0uVm1Xb3JrU3RvcmFnZU1pZ3JhdGlvboeRn3LBtueeAgABTAAMdm9sdW1lVG9Qb29sdAAPTGphdmEvdXRpbC9NYXA7eHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAAIAAAAAAAAAAgAAAAAAAAIidAAZVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABc3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAAAAAAAInc3EAfgAIAAAAAAAAAAp4, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 39908814623087, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Apr 15 06:18:48 UTC 2022, removed: null}, job origin:2857
com.cloud.utils.exception.CloudRuntimeException: VM ID: 143774cd-6cd7-4064-8383-45cf30c55afc migration failed. Exception: com.cloud.utils.exception.CloudRuntimeException
Message: Change data store for VM i-2-546-VM failed
Stack: com.cloud.utils.exception.CloudRuntimeException: Change data store for VM i-2-546-VM failed
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4550)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4507)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:501)
        at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
        at com.cloud.hypervisor.vmware.resource.VmwareResource.relocateVirtualMachine(VmwareResource.java:7588)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4545)
        ... 14 more

        at com.cloud.vm.VirtualMachineManagerImpl.markVolumesInPool(VirtualMachineManagerImpl.java:2403)
        at com.cloud.vm.VirtualMachineManagerImpl.afterHypervisorMigrationCleanup(VirtualMachineManagerImpl.java:2395)
        at com.cloud.vm.VirtualMachineManagerImpl.migrateThroughHypervisorOrStorage(VirtualMachineManagerImpl.java:2459)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStorageMigration(VirtualMachineManagerImpl.java:2325)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStorageMigration(VirtualMachineManagerImpl.java:6011)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
        at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:6018)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
2022-04-15 06:18:52,116 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Complete async job-2858, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0CEJWTSBJRDogMTQzNzc0Y2QtNmNkNy00MDY0LTgzODMtNDVjZjMwYzU1YWZjIG1pZ3JhdGlvbiBmYWlsZWQuIEV4Y2VwdGlvbjogY29tLmNsb3VkLnV0aWxzLmV4Y2VwdGlvbi5DbG91ZFJ1bnRpbWVFeGNlcHRpb24KTWVzc2FnZTogQ2hhbmdlIGRhdGEgc3RvcmUgZm9yIFZNIGktMi01NDYtVk0gZmFpbGVkClN0YWNrOiBjb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbjogQ2hhbmdlIGRhdGEgc3RvcmUgZm9yIFZNIGktMi01NDYtVk0gZmFpbGVkCglhdCBjb20uY2xvdWQuaHlwZXJ2aXNvci52bXdhcmUucmVzb3VyY2UuVm13YXJlUmVzb3VyY2UubWlncmF0ZUFuZEFuc3dlcihWbXdhcmVSZXNvdXJjZS5qYXZhOjQ1NTApCglhdCBjb20uY2xvdWQuaHlwZXJ2aXNvci52bXdhcmUucmVzb3VyY2UuVm13YXJlUmVzb3VyY2UuZXhlY3V0ZShWbXdhcmVSZXNvdXJjZS5qYXZhOjQ1MDcpCglhdCBjb20uY2xvdWQuaHlwZXJ2aXNvci52bXdhcmUucmVzb3VyY2UuVm13YXJlUmVzb3VyY2UuZXhlY3V0ZVJlcXVlc3QoVm13YXJlUmVzb3VyY2UuamF2YTo1MDEpCglhdCBjb20uY2xvdWQuYWdlbnQubWFuYWdlci5EaXJlY3RBZ2VudEF0dGFjaGUkVGFzay5ydW5JbkNvbnRleHQoRGlyZWN0QWdlbnRBdHRhY2hlLmphdmE6MzE1KQoJYXQgb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDEucnVuKE1hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YTo0OCkKCWF0IG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMS5jYWxsKERlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhOjU1KQoJYXQgb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5jYWxsV2l0aENvbnRleHQoRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmE6MTAyKQoJYXQgb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5ydW5XaXRoQ29udGV4dChEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YTo1MikKCWF0IG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZS5ydW4oTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhOjQ1KQoJYXQgamF2YS5iYXNlL2phdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXIuY2FsbChFeGVjdXRvcnMuamF2YTo1MTUpCglhdCBqYXZhLmJhc2UvamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFzay5ydW4oRnV0dXJlVGFzay5qYXZhOjI2NCkKCWF0IGphdmEuYmFzZS9qYXZhLnV0aWwuY29uY3VycmVudC5TY2hlZHVsZWRUaHJlYWRQb29sRXhlY3V0b3IkU2NoZWR1bGVkRnV0dXJlVGFzay5ydW4oU2NoZWR1bGVkVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmE6MzA0KQoJYXQgamF2YS5iYXNlL2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvci5ydW5Xb3JrZXIoVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmE6MTEyOCkKCWF0IGphdmEuYmFzZS9qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VyLnJ1bihUaHJlYWRQb29sRXhlY3V0b3IuamF2YTo2MjgpCglhdCBqYXZhLmJhc2UvamF2YS5sYW5nLlRocmVhZC5ydW4oVGhyZWFkLmphdmE6ODI5KQpDYXVzZWQgYnk6IGNvbS5jbG91ZC51dGlscy5leGNlcHRpb24uQ2xvdWRSdW50aW1lRXhjZXB0aW9uOiBVbmFibGUgdG8gZmluZCB0aGUgdGFyZ2V0IGRhdGFzdG9yZTogNzBmNDg2YWMtZjk1Mi00NjNiLTkwYzctM2UzZGMyODQzYjYyIGluIGRhdGFjZW50ZXI6IEVNRUEtREUtMDEgdG8gZXhlY3V0ZSBtaWdyYXRpb24KCWF0IGNvbS5jbG91ZC5oeXBlcnZpc29yLnZtd2FyZS5yZXNvdXJjZS5WbXdhcmVSZXNvdXJjZS5yZWxvY2F0ZVZpcnR1YWxNYWNoaW5lKFZtd2FyZVJlc291cmNlLmphdmE6NzU4OCkKCWF0IGNvbS5jbG91ZC5oeXBlcnZpc29yLnZtd2FyZS5yZXNvdXJjZS5WbXdhcmVSZXNvdXJjZS5taWdyYXRlQW5kQW5zd2VyKFZtd2FyZVJlc291cmNlLmphdmE6NDU0NSkKCS4uLiAxNCBtb3JlCnVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAGHNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ABUwADmRlY2xhcmluZ0NsYXNzcQB-AAVMAAhmaWxlTmFtZXEAfgAFTAAKbWV0aG9kTmFtZXEAfgAFTAAKbW9kdWxlTmFtZXEAfgAFTAANbW9kdWxlVmVyc2lvbnEAfgAFeHABAAAJY3QAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAARbWFya1ZvbHVtZXNJblBvb2xwcHNxAH4ADAEAAAlbcQB-AA5xAH4AD3EAfgAQdAAfYWZ0ZXJIeXBlcnZpc29yTWlncmF0aW9uQ2xlYW51cHBwc3EAfgAMAQAACZtxAH4ADnEAfgAPcQB-ABB0ACFtaWdyYXRlVGhyb3VnaEh5cGVydmlzb3JPclN0b3JhZ2VwcHNxAH4ADAEAAAkVcQB-AA5xAH4AD3EAfgAQdAAbb3JjaGVzdHJhdGVTdG9yYWdlTWlncmF0aW9ucHBzcQB-AAwBAAAXe3EAfgAOcQB-AA9xAH4AEHEAfgAXcHBzcQB-AAwC_____nB0AC1qZGsuaW50ZXJuYWwucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTB0AAlqYXZhLmJhc2V0AAkxMS4wLjE0LjFzcQB-AAwCAAAAPnBxAH4AGnEAfgAbdAAGaW52b2tlcQB-AB1xAH4AHnNxAH4ADAIAAAArcHQAMWpkay5pbnRlcm5hbC5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AIHEAfgAdcQB-AB5zcQB-AAwCAAACNnB0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAgcQB-AB1xAH4AHnNxAH4ADAEAAABrcQB-AA50ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JwcHNxAH4ADAEAABeCcQB-AA5xAH4AD3EAfgAQcQB-ACpwcHNxAH4ADAEAAABmcQB-AA50ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnBwc3EAfgAMAQAAAmxxAH4ADnQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHBwc3EAfgAMAQAAADBxAH4ADnQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVucHBzcQB-AAwBAAAAN3EAfgAOdABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxscHBzcQB-AAwBAAAAZnEAfgAOdABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgA6dAAPY2FsbFdpdGhDb250ZXh0cHBzcQB-AAwBAAAANHEAfgAOcQB-AD1xAH4AOnQADnJ1bldpdGhDb250ZXh0cHBzcQB-AAwBAAAALXEAfgAOdAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADZxAH4AN3Bwc3EAfgAMAQAAAjhxAH4ADnEAfgAxcQB-ADJxAH4AN3Bwc3EAfgAMAgAAAgNwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADtxAH4AHXEAfgAec3EAfgAMAgAAAQhwdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgA3cQB-AB1xAH4AHnNxAH4ADAIAAARocHQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2VycQB-AB1xAH4AHnNxAH4ADAIAAAJ0cHQALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ATHEAfgA3cQB-AB1xAH4AHnNxAH4ADAIAAAM9cHQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgA3cQB-AB1xAH4AHnNyAB9qYXZhLnV0aWwuQ29sbGVjdGlvbnMkRW1wdHlMaXN0ergXtDynnt4CAAB4cHgAABCadwgAAAAAAAAAAHg
2022-04-15 06:18:52,117 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Publish async job-2858 complete on message bus
2022-04-15 06:18:52,117 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Wake up jobs related to job-2858
2022-04-15 06:18:52,117 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Update db status for job-2858
2022-04-15 06:18:52,117 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Wake up jobs joined with job-2858 and disjoin all subjobs created from job- 2858
2022-04-15 06:18:52,121 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Done executing com.cloud.vm.VmWorkStorageMigration for job-2858
2022-04-15 06:18:52,121 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-120:ctx-4c5f6d33 job-2857/job-2858) (logid:e8851491) Remove job-2858 from job monitoring
2022-04-15 06:18:52,125 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-101:ctx-26e9f7c1 job-2857) (logid:e8851491) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.MigrateVirtualMachineWithVolumeCmd
com.cloud.utils.exception.CloudRuntimeException: VM ID: 143774cd-6cd7-4064-8383-45cf30c55afc migration failed. Exception: com.cloud.utils.exception.CloudRuntimeException
Message: Change data store for VM i-2-546-VM failed
Stack: com.cloud.utils.exception.CloudRuntimeException: Change data store for VM i-2-546-VM failed
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4550)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4507)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:501)
        at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
        at com.cloud.hypervisor.vmware.resource.VmwareResource.relocateVirtualMachine(VmwareResource.java:7588)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4545)
        ... 14 more

        at com.cloud.vm.VirtualMachineManagerImpl.markVolumesInPool(VirtualMachineManagerImpl.java:2403)
        at com.cloud.vm.VirtualMachineManagerImpl.afterHypervisorMigrationCleanup(VirtualMachineManagerImpl.java:2395)
        at com.cloud.vm.VirtualMachineManagerImpl.migrateThroughHypervisorOrStorage(VirtualMachineManagerImpl.java:2459)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStorageMigration(VirtualMachineManagerImpl.java:2325)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStorageMigration(VirtualMachineManagerImpl.java:6011)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
        at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:6018)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
2022-04-15 06:18:52,127 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-26e9f7c1 job-2857) (logid:e8851491) Complete async job-2857, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"VM ID: 143774cd-6cd7-4064-8383-45cf30c55afc migration failed. Exception: com.cloud.utils.exception.CloudRuntimeException
Message: Change data store for VM i-2-546-VM failed
Stack: com.cloud.utils.exception.CloudRuntimeException: Change data store for VM i-2-546-VM failed
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4550)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4507)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:501)
        at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to find the target datastore: 70f486ac-f952-463b-90c7-3e3dc2843b62 in datacenter: EMEA-DE-01 to execute migration
        at com.cloud.hypervisor.vmware.resource.VmwareResource.relocateVirtualMachine(VmwareResource.java:7588)
        at com.cloud.hypervisor.vmware.resource.VmwareResource.migrateAndAnswer(VmwareResource.java:4545)
        ... 14 more
"}
2022-04-15 06:18:52,127 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-26e9f7c1 job-2857) (logid:e8851491) Publish async job-2857 complete on message bus
2022-04-15 06:18:52,127 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-26e9f7c1 job-2857) (logid:e8851491) Wake up jobs related to job-2857
2022-04-15 06:18:52,127 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-26e9f7c1 job-2857) (logid:e8851491) Update db status for job-2857
2022-04-15 06:18:52,128 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-26e9f7c1 job-2857) (logid:e8851491) Wake up jobs joined with job-2857 and disjoin all subjobs created from job- 2857
DaanHoogland commented 2 years ago

@ccycv from what I can see in your log this is expected behaviour, but I assume you tested this successfully in 4.15? Maybe you can add the logs relevant to the job starting with the line containing "===START===" that pertains to your migration request, up to the matching "===END===" that gave your error result.

ccycv commented 2 years ago

@ccycv from what I can see in your log this is expected behaviour, but I assume you tested this successfully in 4.15? Maybe you can add the logs relevant to the job starting with the line containing "===START===" that pertains to your migration request, up to the matching "===END===" that gave your error result.

@ccycv from what I can see in your log this is expected behaviour, but I assume you tested this successfully in 4.15? Maybe you can add the logs relevant to the job starting with the line containing "===START===" that pertains to your migration request, up to the matching "===END===" that gave your error result.

GET livemigrate=false&storageid=ce27d8fc-27cf-4754-8a82-e27497c390a7&volumeid=6a456713-a75e-48ba-a7aa-e4291aeb3472&command=migrateVolume&response=json 2022-04-25 05:47:09,405 DEBUG [c.c.a.ApiServer] (qtp515715487-873791:ctx-ee2a2ad0 ctx-a34c2a4a) (logid:87478f01) CIDRs from which account 'Acct[8a0f55f0-1f58-11ec-b6e8-244bfeb8116f-admin] -- Account {"id": 2, "name": "admin", "uuid": "8a0f55f0-1f58-11ec-b6e8-244bfeb8116f"}' is allowed to perform API calls: 0.0.0.0/0,::/0 2022-04-25 05:47:09,450 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-50:ctx-61f5af27 job-3035) (logid:7b804a24) Add job-3035 into job monitoring 2022-04-25 05:47:09,455 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp515715487-873791:ctx-ee2a2ad0 ctx-a34c2a4a) (logid:87478f01) submit async job-3035, details: AsyncJobVO: {id:3035, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","volumeid":"6a456713-a75e-48ba-a7aa-e4291aeb3472","httpmethod":"GET","ctxStartEventId":"9654","ctxDetails":"{\"interface com.cloud.storage.Volume\":\"6a456713-a75e-48ba-a7aa-e4291aeb3472\",\"interface com.cloud.storage.StoragePool\":\"ce27d8fc-27cf-4754-8a82-e27497c390a7\"}","ctxAccountId":"2","livemigrate":"false","cmdEventType":"VOLUME.MIGRATE","storageid":"ce27d8fc-27cf-4754-8a82-e27497c390a7"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 39908814623087, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2022-04-25 05:47:09,455 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035) (logid:42469f70) Executing AsyncJobVO: {id:3035, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","volumeid":"6a456713-a75e-48ba-a7aa-e4291aeb3472","httpmethod":"GET","ctxStartEventId":"9654","ctxDetails":"{\"interface com.cloud.storage.Volume\":\"6a456713-a75e-48ba-a7aa-e4291aeb3472\",\"interface com.cloud.storage.StoragePool\":\"ce27d8fc-27cf-4754-8a82-e27497c390a7\"}","ctxAccountId":"2","livemigrate":"false","cmdEventType":"VOLUME.MIGRATE","storageid":"ce27d8fc-27cf-4754-8a82-e27497c390a7"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 39908814623087, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2022-04-25 05:47:09,456 DEBUG [c.c.a.ApiServlet] (qtp515715487-873791:ctx-ee2a2ad0 ctx-a34c2a4a) (logid:87478f01) ===END=== 79.114.3.114 -- GET livemigrate=false&storageid=ce27d8fc-27cf-4754-8a82-e27497c390a7&volumeid=6a456713-a75e-48ba-a7aa-e4291aeb3472&command=migrateVolume&response=json 2022-04-25 05:47:09,463 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Checking pool 18 for storage, totalSize: 1912334188544, usedBytes: 99259252736, usedPct: 0.05190476294918585, disable threshold: 0.85 2022-04-25 05:47:09,463 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Destination pool id: 18 2022-04-25 05:47:09,465 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Pool ID for the volume with ID 591 is 8 2022-04-25 05:47:09,466 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Found storage pool ldnuk003 of type VMFS with over-provisioning factor 2 2022-04-25 05:47:09,466 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Total over-provisioned capacity calculated is 2 * (1.7393 TB) 1912334188544 2022-04-25 05:47:09,466 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Total capacity of the pool ldnuk003 with ID 18 is (3.4785 TB) 3824668377088 2022-04-25 05:47:09,467 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Checking pool: 18 for storage allocation , maxSize : (3.4785 TB) 3824668377088, totalAllocatedSize : (253.32 GB) 272004808704, askingSize : (30.00 GB) 32212254720, allocated disable threshold: 0.85 2022-04-25 05:47:09,471 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Sync job-3036 execution on object VmWorkJobQueue.583 2022-04-25 05:47:09,519 DEBUG [c.c.a.ApiServlet] (qtp515715487-1043626:ctx-1f70f026) (logid:f11fe8e1) ===START=== 79.114.3.114 -- GET jobId=42469f70-df52-4d24-a889-87b09b3f68ab&command=queryAsyncJobResult&response=json 2022-04-25 05:47:09,536 DEBUG [c.c.a.ApiServer] (qtp515715487-1043626:ctx-1f70f026 ctx-d0e32dbf) (logid:f11fe8e1) CIDRs from which account 'Acct[8a0f55f0-1f58-11ec-b6e8-244bfeb8116f-admin] -- Account {"id": 2, "name": "admin", "uuid": "8a0f55f0-1f58-11ec-b6e8-244bfeb8116f"}' is allowed to perform API calls: 0.0.0.0/0,::/0 2022-04-25 05:47:09,566 DEBUG [c.c.a.ApiServlet] (qtp515715487-1043626:ctx-1f70f026 ctx-d0e32dbf) (logid:f11fe8e1) ===END=== 79.114.3.114 -- GET jobId=42469f70-df52-4d24-a889-87b09b3f68ab&command=queryAsyncJobResult&response=json 2022-04-25 05:47:10,045 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) SeqA 27-972134: Processing Seq 27-972134: { Cmd , MgmtId: -1, via: 27, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"330","_loadInfo":"{ "connections": [] }","wait":"0","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,052 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) SeqA 27-972134: Sending Seq 27-972134: { Ans: , MgmtId: 39908814623087, via: 27, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,642 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-ad4d2842) (logid:fa8ab096) Execute sync-queue item: SyncQueueItemVO {id:1813, queueId: 1811, contentType: AsyncJob, contentId: 3036, lastProcessMsid: 39908814623087, lastprocessNumber: 3, lastProcessTime: Mon Apr 25 05:47:10 UTC 2022, created: Mon Apr 25 05:47:09 UTC 2022} 2022-04-25 05:47:10,644 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-ad4d2842) (logid:fa8ab096) Schedule queued job-3036 2022-04-25 05:47:10,653 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036) (logid:a8098653) Add job-3036 into job monitoring 2022-04-25 05:47:10,661 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036) (logid:42469f70) Executing AsyncJobVO: {id:3036, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkMigrateVolume, cmdInfo: rO0ABXNyACBjb20uY2xvdWQudm0uVm1Xb3JrTWlncmF0ZVZvbHVtZfgl82-871PmAgAESgAKZGVzdFBvb2xJZFoAC2xpdmVNaWdyYXRlSgAIdm9sdW1lSWRMABFuZXdEaXNrT2ZmZXJpbmdJZHQAEExqYXZhL2xhbmcvTG9uZzt4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAkd0ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbAAAAAAAAAASAQAAAAAAAAJPcA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 39908814623087, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 25 05:47:09 UTC 2022, removed: null} 2022-04-25 05:47:10,661 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036) (logid:42469f70) Run VM work job: com.cloud.vm.VmWorkMigrateVolume for VM 583, job origin: 3035 2022-04-25 05:47:10,667 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Execute VM work job: com.cloud.vm.VmWorkMigrateVolume{"volumeId":591,"destPoolId":18,"liveMigrate":true,"userId":2,"accountId":2,"vmId":583,"handlerName":"VolumeApiServiceImpl"} 2022-04-25 05:47:10,793 DEBUG [o.a.c.s.m.VmwareStorageMotionStrategy] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) class org.apache.cloudstack.storage.motion.VmwareStorageMotionStrategy can handle the request because 591(6a456713-a75e-48ba-a7aa-e4291aeb3472) and 591(6a456713-a75e-48ba-a7aa-e4291aeb3472) share the pod 2022-04-25 05:47:10,807 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) host id is null, using last host id 12 2022-04-25 05:47:10,879 DEBUG [c.c.a.t.Request] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Seq 12-5449355549118325210: Sending { Cmd , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.MigrateVolumeCommand":{"volumeId":"591","volumePath":"ROOT-583","chainInfo":"{"diskDeviceBusName":"scsi0:0","diskChain":["[ldnuk001] i-2-583-VM/ROOT-583.vmdk"]}","pool":{"id":"18","uuid":"ce27d8fc-27cf-4754-8a82-e27497c390a7","host":"VMFS datastore: datastore-7973","path":"datastore-7973","port":"0","type":"VMFS"},"sourcePool":{"id":"8","uuid":"7eb82b52-5e50-4db1-a4c1-5a6c2d5e2680","host":"VMFS datastore: datastore-7190","path":"datastore-7190","port":"0","type":"VMFS"},"attachedVmName":"i-2-583-VM","volumeType":"UNKNOWN","wait":"-1","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,880 DEBUG [c.c.a.t.Request] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Seq 12-5449355549118325210: Executing: { Cmd , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.MigrateVolumeCommand":{"volumeId":"591","volumePath":"ROOT-583","chainInfo":"{"diskDeviceBusName":"scsi0:0","diskChain":["[ldnuk001] i-2-583-VM/ROOT-583.vmdk"]}","pool":{"id":"18","uuid":"ce27d8fc-27cf-4754-8a82-e27497c390a7","host":"VMFS datastore: datastore-7973","path":"datastore-7973","port":"0","type":"VMFS"},"sourcePool":{"id":"8","uuid":"7eb82b52-5e50-4db1-a4c1-5a6c2d5e2680","host":"VMFS datastore: datastore-7190","path":"datastore-7190","port":"0","type":"VMFS"},"attachedVmName":"i-2-583-VM","volumeType":"UNKNOWN","wait":"-1","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,880 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-156:ctx-87c92daf) (logid:519241d4) Seq 12-5449355549118325210: Executing request 2022-04-25 05:47:10,880 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-156:ctx-87c92daf ldn-uk-001.domain.tld, job-3035/job-3036, cmd: MigrateVolumeCommand) (logid:42469f70) Executing resource MigrateVolumeCommand: {"volumeId":591,"volumePath":"ROOT-583","chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[ldnuk001] i-2-583-VM/ROOT-583.vmdk\"]}","pool":{"id":18,"uuid":"ce27d8fc-27cf-4754-8a82-e27497c390a7","host":"VMFS datastore: datastore-7973","path":"datastore-7973","port":0,"type":"VMFS"},"sourcePool":{"id":8,"uuid":"7eb82b52-5e50-4db1-a4c1-5a6c2d5e2680","host":"VMFS datastore: datastore-7190","path":"datastore-7190","port":0,"type":"VMFS"},"attachedVmName":"i-2-583-VM","volumeType":"UNKNOWN","wait":-1,"bypassHostMaintenance":false} 2022-04-25 05:47:11,977 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-156:ctx-87c92daf ldn-uk-001.domain.tld, job-3035/job-3036, cmd: MigrateVolumeCommand) (logid:42469f70) Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand 2022-04-25 05:47:11,977 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-156:ctx-87c92daf ldn-uk-001.domain.tld, job-3035/job-3036, cmd: MigrateVolumeCommand) (logid:42469f70) Catch Exception java.lang.Exception due to java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4896) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:505) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) 2022-04-25 05:47:11,978 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-156:ctx-87c92daf) (logid:42469f70) Seq 12-5449355549118325210: Response Received: 2022-04-25 05:47:11,978 DEBUG [c.c.a.t.Request] (DirectAgent-156:ctx-87c92daf) (logid:42469f70) Seq 12-5449355549118325210: Processing: { Ans: , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.MigrateVolumeAnswer":{"result":"false","details":"Catch Exception java.lang.Exception due to java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand","wait":"0","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:11,979 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-156:ctx-87c92daf) (logid:42469f70) Seq 12-5449355549118325210: No more commands found 2022-04-25 05:47:11,979 DEBUG [c.c.a.t.Request] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Seq 12-5449355549118325210: Received: { Ans: , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 110, { MigrateVolumeAnswer } } 2022-04-25 05:47:11,979 DEBUG [c.c.a.m.AgentManagerImpl] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Details from executing class com.cloud.agent.api.storage.MigrateVolumeCommand: Catch Exception java.lang.Exception due to java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand 2022-04-25 05:47:11,981 DEBUG [o.a.c.s.m.VmwareStorageMotionStrategy] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) retrieved 'null' as new path for volume(591)

This is how the event start when I start the volume migration.

Not sure why cloudstack is looking for destination storage on source host, in this part "Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand" this storage is the destination "ce27d8fc-27cf-4754-8a82-e27497c390a7" which is on host "ldn-uk-003.domain.tld" where I want to migrate.

This setup is only with local storage configured, the above behavior is for shared storage, both, when I execute volume migration and migrate to another primary storage.

ccycv commented 2 years ago

@ccycv from what I can see in your log this is expected behaviour, but I assume you tested this successfully in 4.15? Maybe you can add the logs relevant to the job starting with the line containing "===START===" that pertains to your migration request, up to the matching "===END===" that gave your error result.

@ccycv from what I can see in your log this is expected behaviour, but I assume you tested this successfully in 4.15? Maybe you can add the logs relevant to the job starting with the line containing "===START===" that pertains to your migration request, up to the matching "===END===" that gave your error result.

GET livemigrate=false&storageid=ce27d8fc-27cf-4754-8a82-e27497c390a7&volumeid=6a456713-a75e-48ba-a7aa-e4291aeb3472&command=migrateVolume&response=json 2022-04-25 05:47:09,405 DEBUG [c.c.a.ApiServer] (qtp515715487-873791:ctx-ee2a2ad0 ctx-a34c2a4a) (logid:87478f01) CIDRs from which account 'Acct[8a0f55f0-1f58-11ec-b6e8-244bfeb8116f-admin] -- Account {"id": 2, "name": "admin", "uuid": "8a0f55f0-1f58-11ec-b6e8-244bfeb8116f"}' is allowed to perform API calls: 0.0.0.0/0,::/0 2022-04-25 05:47:09,450 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-50:ctx-61f5af27 job-3035) (logid:7b804a24) Add job-3035 into job monitoring 2022-04-25 05:47:09,455 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp515715487-873791:ctx-ee2a2ad0 ctx-a34c2a4a) (logid:87478f01) submit async job-3035, details: AsyncJobVO: {id:3035, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","volumeid":"6a456713-a75e-48ba-a7aa-e4291aeb3472","httpmethod":"GET","ctxStartEventId":"9654","ctxDetails":"{\"interface com.cloud.storage.Volume\":\"6a456713-a75e-48ba-a7aa-e4291aeb3472\",\"interface com.cloud.storage.StoragePool\":\"ce27d8fc-27cf-4754-8a82-e27497c390a7\"}","ctxAccountId":"2","livemigrate":"false","cmdEventType":"VOLUME.MIGRATE","storageid":"ce27d8fc-27cf-4754-8a82-e27497c390a7"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 39908814623087, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2022-04-25 05:47:09,455 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035) (logid:42469f70) Executing AsyncJobVO: {id:3035, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","volumeid":"6a456713-a75e-48ba-a7aa-e4291aeb3472","httpmethod":"GET","ctxStartEventId":"9654","ctxDetails":"{\"interface com.cloud.storage.Volume\":\"6a456713-a75e-48ba-a7aa-e4291aeb3472\",\"interface com.cloud.storage.StoragePool\":\"ce27d8fc-27cf-4754-8a82-e27497c390a7\"}","ctxAccountId":"2","livemigrate":"false","cmdEventType":"VOLUME.MIGRATE","storageid":"ce27d8fc-27cf-4754-8a82-e27497c390a7"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 39908814623087, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2022-04-25 05:47:09,456 DEBUG [c.c.a.ApiServlet] (qtp515715487-873791:ctx-ee2a2ad0 ctx-a34c2a4a) (logid:87478f01) ===END=== 79.114.3.114 -- GET livemigrate=false&storageid=ce27d8fc-27cf-4754-8a82-e27497c390a7&volumeid=6a456713-a75e-48ba-a7aa-e4291aeb3472&command=migrateVolume&response=json 2022-04-25 05:47:09,463 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Checking pool 18 for storage, totalSize: 1912334188544, usedBytes: 99259252736, usedPct: 0.05190476294918585, disable threshold: 0.85 2022-04-25 05:47:09,463 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Destination pool id: 18 2022-04-25 05:47:09,465 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Pool ID for the volume with ID 591 is 8 2022-04-25 05:47:09,466 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Found storage pool ldnuk003 of type VMFS with over-provisioning factor 2 2022-04-25 05:47:09,466 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Total over-provisioned capacity calculated is 2 * (1.7393 TB) 1912334188544 2022-04-25 05:47:09,466 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Total capacity of the pool ldnuk003 with ID 18 is (3.4785 TB) 3824668377088 2022-04-25 05:47:09,467 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Checking pool: 18 for storage allocation , maxSize : (3.4785 TB) 3824668377088, totalAllocatedSize : (253.32 GB) 272004808704, askingSize : (30.00 GB) 32212254720, allocated disable threshold: 0.85 2022-04-25 05:47:09,471 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-50:ctx-61f5af27 job-3035 ctx-078119b5) (logid:42469f70) Sync job-3036 execution on object VmWorkJobQueue.583 2022-04-25 05:47:09,519 DEBUG [c.c.a.ApiServlet] (qtp515715487-1043626:ctx-1f70f026) (logid:f11fe8e1) ===START=== 79.114.3.114 -- GET jobId=42469f70-df52-4d24-a889-87b09b3f68ab&command=queryAsyncJobResult&response=json 2022-04-25 05:47:09,536 DEBUG [c.c.a.ApiServer] (qtp515715487-1043626:ctx-1f70f026 ctx-d0e32dbf) (logid:f11fe8e1) CIDRs from which account 'Acct[8a0f55f0-1f58-11ec-b6e8-244bfeb8116f-admin] -- Account {"id": 2, "name": "admin", "uuid": "8a0f55f0-1f58-11ec-b6e8-244bfeb8116f"}' is allowed to perform API calls: 0.0.0.0/0,::/0 2022-04-25 05:47:09,566 DEBUG [c.c.a.ApiServlet] (qtp515715487-1043626:ctx-1f70f026 ctx-d0e32dbf) (logid:f11fe8e1) ===END=== 79.114.3.114 -- GET jobId=42469f70-df52-4d24-a889-87b09b3f68ab&command=queryAsyncJobResult&response=json 2022-04-25 05:47:10,045 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) SeqA 27-972134: Processing Seq 27-972134: { Cmd , MgmtId: -1, via: 27, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"330","_loadInfo":"{ "connections": [] }","wait":"0","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,052 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) SeqA 27-972134: Sending Seq 27-972134: { Ans: , MgmtId: 39908814623087, via: 27, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,642 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-ad4d2842) (logid:fa8ab096) Execute sync-queue item: SyncQueueItemVO {id:1813, queueId: 1811, contentType: AsyncJob, contentId: 3036, lastProcessMsid: 39908814623087, lastprocessNumber: 3, lastProcessTime: Mon Apr 25 05:47:10 UTC 2022, created: Mon Apr 25 05:47:09 UTC 2022} 2022-04-25 05:47:10,644 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-ad4d2842) (logid:fa8ab096) Schedule queued job-3036 2022-04-25 05:47:10,653 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036) (logid:a8098653) Add job-3036 into job monitoring 2022-04-25 05:47:10,661 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036) (logid:42469f70) Executing AsyncJobVO: {id:3036, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkMigrateVolume, cmdInfo: rO0ABXNyACBjb20uY2xvdWQudm0uVm1Xb3JrTWlncmF0ZVZvbHVtZfgl82-871PmAgAESgAKZGVzdFBvb2xJZFoAC2xpdmVNaWdyYXRlSgAIdm9sdW1lSWRMABFuZXdEaXNrT2ZmZXJpbmdJZHQAEExqYXZhL2xhbmcvTG9uZzt4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAkd0ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbAAAAAAAAAASAQAAAAAAAAJPcA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 39908814623087, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 25 05:47:09 UTC 2022, removed: null} 2022-04-25 05:47:10,661 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036) (logid:42469f70) Run VM work job: com.cloud.vm.VmWorkMigrateVolume for VM 583, job origin: 3035 2022-04-25 05:47:10,667 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Execute VM work job: com.cloud.vm.VmWorkMigrateVolume{"volumeId":591,"destPoolId":18,"liveMigrate":true,"userId":2,"accountId":2,"vmId":583,"handlerName":"VolumeApiServiceImpl"} 2022-04-25 05:47:10,793 DEBUG [o.a.c.s.m.VmwareStorageMotionStrategy] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) class org.apache.cloudstack.storage.motion.VmwareStorageMotionStrategy can handle the request because 591(6a456713-a75e-48ba-a7aa-e4291aeb3472) and 591(6a456713-a75e-48ba-a7aa-e4291aeb3472) share the pod 2022-04-25 05:47:10,807 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) host id is null, using last host id 12 2022-04-25 05:47:10,879 DEBUG [c.c.a.t.Request] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Seq 12-5449355549118325210: Sending { Cmd , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.MigrateVolumeCommand":{"volumeId":"591","volumePath":"ROOT-583","chainInfo":"{"diskDeviceBusName":"scsi0:0","diskChain":["[ldnuk001] i-2-583-VM/ROOT-583.vmdk"]}","pool":{"id":"18","uuid":"ce27d8fc-27cf-4754-8a82-e27497c390a7","host":"VMFS datastore: datastore-7973","path":"datastore-7973","port":"0","type":"VMFS"},"sourcePool":{"id":"8","uuid":"7eb82b52-5e50-4db1-a4c1-5a6c2d5e2680","host":"VMFS datastore: datastore-7190","path":"datastore-7190","port":"0","type":"VMFS"},"attachedVmName":"i-2-583-VM","volumeType":"UNKNOWN","wait":"-1","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,880 DEBUG [c.c.a.t.Request] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Seq 12-5449355549118325210: Executing: { Cmd , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.MigrateVolumeCommand":{"volumeId":"591","volumePath":"ROOT-583","chainInfo":"{"diskDeviceBusName":"scsi0:0","diskChain":["[ldnuk001] i-2-583-VM/ROOT-583.vmdk"]}","pool":{"id":"18","uuid":"ce27d8fc-27cf-4754-8a82-e27497c390a7","host":"VMFS datastore: datastore-7973","path":"datastore-7973","port":"0","type":"VMFS"},"sourcePool":{"id":"8","uuid":"7eb82b52-5e50-4db1-a4c1-5a6c2d5e2680","host":"VMFS datastore: datastore-7190","path":"datastore-7190","port":"0","type":"VMFS"},"attachedVmName":"i-2-583-VM","volumeType":"UNKNOWN","wait":"-1","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:10,880 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-156:ctx-87c92daf) (logid:519241d4) Seq 12-5449355549118325210: Executing request 2022-04-25 05:47:10,880 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-156:ctx-87c92daf ldn-uk-001.domain.tld, job-3035/job-3036, cmd: MigrateVolumeCommand) (logid:42469f70) Executing resource MigrateVolumeCommand: {"volumeId":591,"volumePath":"ROOT-583","chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[ldnuk001] i-2-583-VM/ROOT-583.vmdk\"]}","pool":{"id":18,"uuid":"ce27d8fc-27cf-4754-8a82-e27497c390a7","host":"VMFS datastore: datastore-7973","path":"datastore-7973","port":0,"type":"VMFS"},"sourcePool":{"id":8,"uuid":"7eb82b52-5e50-4db1-a4c1-5a6c2d5e2680","host":"VMFS datastore: datastore-7190","path":"datastore-7190","port":0,"type":"VMFS"},"attachedVmName":"i-2-583-VM","volumeType":"UNKNOWN","wait":-1,"bypassHostMaintenance":false} 2022-04-25 05:47:11,977 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-156:ctx-87c92daf ldn-uk-001.domain.tld, job-3035/job-3036, cmd: MigrateVolumeCommand) (logid:42469f70) Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand 2022-04-25 05:47:11,977 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-156:ctx-87c92daf ldn-uk-001.domain.tld, job-3035/job-3036, cmd: MigrateVolumeCommand) (logid:42469f70) Catch Exception java.lang.Exception due to java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4896) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:505) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) 2022-04-25 05:47:11,978 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-156:ctx-87c92daf) (logid:42469f70) Seq 12-5449355549118325210: Response Received: 2022-04-25 05:47:11,978 DEBUG [c.c.a.t.Request] (DirectAgent-156:ctx-87c92daf) (logid:42469f70) Seq 12-5449355549118325210: Processing: { Ans: , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.MigrateVolumeAnswer":{"result":"false","details":"Catch Exception java.lang.Exception due to java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand","wait":"0","bypassHostMaintenance":"false"}}] } 2022-04-25 05:47:11,979 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-156:ctx-87c92daf) (logid:42469f70) Seq 12-5449355549118325210: No more commands found 2022-04-25 05:47:11,979 DEBUG [c.c.a.t.Request] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Seq 12-5449355549118325210: Received: { Ans: , MgmtId: 39908814623087, via: 12(ldn-uk-001.domain.tld), Ver: v1, Flags: 110, { MigrateVolumeAnswer } } 2022-04-25 05:47:11,979 DEBUG [c.c.a.m.AgentManagerImpl] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) Details from executing class com.cloud.agent.api.storage.MigrateVolumeCommand: Catch Exception java.lang.Exception due to java.lang.Exception: Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand 2022-04-25 05:47:11,981 DEBUG [o.a.c.s.m.VmwareStorageMotionStrategy] (Work-Job-Executor-50:ctx-59c546a2 job-3035/job-3036 ctx-0c4feac2) (logid:42469f70) retrieved 'null' as new path for volume(591)

This is how the event start when I start the volume migration.

Not sure why cloudstack is looking for destination storage on source host, in this part "Unable to find the mounted datastore with name: ce27d8fc-27cf-4754-8a82-e27497c390a7 on source host: ldn-uk-001.domain.tld to execute MigrateVolumeCommand" this storage is the destination "ce27d8fc-27cf-4754-8a82-e27497c390a7" which is on host "ldn-uk-003.domain.tld" where I want to migrate.

This setup is only with local storage configured, the above behavior is for shared storage, both, when I execute volume migration and migrate to another primary storage.

harikrishna-patnala commented 2 years ago

I could reproduce the issue with a similar local storage setup, I'll try to fix this.

rohityadavcloud commented 2 years ago

Fixed in https://github.com/apache/cloudstack/pull/6483