search

cloudsoft / jclouds-vcloud-director

0 stars 9 forks source link

VM delete fails: could not be executed on vApp (undeploy not finished?) #23

Open aledsage opened 9 years ago

aledsage commented 9 years ago

Stopping a VM in a customer's vcloud-director environment failed (when in jclouds code).

It seems that the calls to undeploy and then delete were done in rapid succession, rather than waiting for the undeploy task to complete. The code looks fine, doing:

retryTaskSuccess.apply(undeployTask);

This was using vcloud-director-1.9.1-20150815.1541.jar

Some of the logging is shown below. Note the status="running" on the retrieved task. 

2015-09-23 14:18:45,021 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> GET https://acme.com/api/vApp/vm-4a227412-9e9e-4914-b414-be30c2e54363 HTTP/1.1
...
2015-09-23 14:18:46,183 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> GET https://acme.com/api/vApp/vapp-9ef20c19-5b70-4d23-b2cf-85f964107cb0 HTTP/1.1
...
2015-09-23 14:18:47,682 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> POST https://acme.com/api/vApp/vapp-9ef20c19-5b70-4d23-b2cf-85f964107cb0/action/undeploy HTTP/1.1

2015-09-23 14:18:49,911 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "<?xml version="1.0" encoding="UTF-8"?>[\n]"
2015-09-23 14:18:49,918 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "<Task xmlns="http://www.vmware.com/vcloud/v1.5" status="running" startTime="2015-09-23T15:18:47.903+02:00" operationName="vappUndeployPowerOff" operation="Stopping Virtual Application brooklyn-nv4p0s-amp-auto-qa-qnkh-mongodb-server-jcy6-1da(9ef20c19-5b70-4d23-b2cf-85f964107cb0)" expiryTime="2015-12-22T15:18:47.903+01:00" name="task" id="urn:vcloud:task:3664229c-1e7b-4da5-98a4-d76b3eb3e870" type="application/vnd.vmware.vcloud.task+xml" href="https://acme.com/api/task/3664229c-1e7b-4da5-98a4-d76b3eb3e870" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.vmware.com/vcloud/v1.5 http://acme.com/api/v1.5/schema/master.xsd">[\n]"
2015-09-23 14:18:49,918 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <Link rel="task:cancel" href="https://acme.com/api/task/3664229c-1e7b-4da5-98a4-d76b3eb3e870/action/cancel"/>[\n]"
2015-09-23 14:18:49,918 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <Owner type="application/vnd.vmware.vcloud.vApp+xml" name="brooklyn-nv4p0s-amp-auto-qa-qnkh-mongodb-server-jcy6-1da" href="https://acme.com/api/vApp/vapp-9ef20c19-5b70-4d23-b2cf-85f964107cb0"/>[\n]"
2015-09-23 14:18:49,918 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <User type="application/vnd.vmware.admin.user+xml" name="martin" href="https://acme.com/api/admin/user/6c26165c-9ec1-4a6a-92c5-7e3e33af4c1d"/>[\n]"
2015-09-23 14:18:49,918 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <Organization type="application/vnd.vmware.vcloud.org+xml" name="acme-2_01" href="https://acme.com/api/org/e49fb225-454e-4ef0-8fb8-f89f5491a499"/>[\n]"
2015-09-23 14:18:49,918 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "</Task>[\n]"
...
2015-09-23 14:18:49,926 DEBUG jclouds.compute [brooklyn-execmanager-dXFhr78G-9023]: >> awaiting vApp(urn:vcloud:vapp:9ef20c19-5b70-4d23-b2cf-85f964107cb0) undeploy completion
2015-09-23 14:18:49,927 DEBUG o.j.r.i.InvokeHttpMethod [brooklyn-execmanager-dXFhr78G-9023]: >> invoking TaskApi.get
2015-09-23 14:18:49,927 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [brooklyn-execmanager-dXFhr78G-9023]: Sending request -193659118: GET https://acme.com/api/task/3664229c-1e7b-4da5-98a4-d76b3eb3e870 HTTP/1.1
2015-09-23 14:18:49,927 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> GET https://acme.com/api/task/3664229c-1e7b-4da5-98a4-d76b3eb3e870 HTTP/1.1
2015-09-23 14:18:49,927 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> x-vcloud-authorization: ECtHZsZPop+tJwJ4bSLGMMJe5XWFgk8idkFd9d0bhJI=
2015-09-23 14:18:49,927 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> Cookie: vcloud-token=ECtHZsZPop+tJwJ4bSLGMMJe5XWFgk8idkFd9d0bhJI=
2015-09-23 14:18:49,927 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> Accept: application/*+xml;version=1.5

2015-09-23 14:18:50,176 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "<?xml version="1.0" encoding="UTF-8"?>[\n]"
2015-09-23 14:18:50,176 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "<Task xmlns="http://www.vmware.com/vcloud/v1.5" status="running" startTime="2015-09-23T15:18:47.903+02:00" operationName="vappUndeployPowerOff" operation="Stopping Virtual Application brooklyn-nv4p0s-amp-auto-qa-qnkh-mongodb-server-jcy6-1da(9ef20c19-5b70-4d23-b2cf-85f964107cb0)" expiryTime="2015-12-22T15:18:47.903+01:00" name="task" id="urn:vcloud:task:3664229c-1e7b-4da5-98a4-d76b3eb3e870" type="application/vnd.vmware.vcloud.task+xml" href="https://acme.com/api/task/3664229c-1e7b-4da5-98a4-d76b3eb3e870" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.vmware.com/vcloud/v1.5 http://acme.com/api/v1.5/schema/master.xsd">[\n]"
2015-09-23 14:18:50,176 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <Link rel="task:cancel" href="https://acme.com/api/task/3664229c-1e7b-4da5-98a4-d76b3eb3e870/action/cancel"/>[\n]"
2015-09-23 14:18:50,176 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <Owner type="application/vnd.vmware.vcloud.vApp+xml" name="brooklyn-nv4p0s-amp-auto-qa-qnkh-mongodb-server-jcy6-1da" href="https://acme.com/api/vApp/vapp-9ef20c19-5b70-4d23-b2cf-85f964107cb0"/>[\n]"
2015-09-23 14:18:50,176 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <User type="application/vnd.vmware.admin.user+xml" name="martin" href="https://acme.com/api/admin/user/6c26165c-9ec1-4a6a-92c5-7e3e33af4c1d"/>[\n]"
2015-09-23 14:18:50,176 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "    <Organization type="application/vnd.vmware.vcloud.org+xml" name="acme-2_01" href="https://acme.com/api/org/e49fb225-454e-4ef0-8fb8-f89f5491a499"/>[\n]"
2015-09-23 14:18:50,176 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "</Task>[\n]"
...
2015-09-23 14:18:50,209 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> DELETE https://acme.com/api/vApp/vapp-9ef20c19-5b70-4d23-b2cf-85f964107cb0 HTTP/1.1
2015-09-23 14:18:50,209 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> x-vcloud-authorization: ECtHZsZPop+tJwJ4bSLGMMJe5XWFgk8idkFd9d0bhJI=
2015-09-23 14:18:50,209 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> Cookie: vcloud-token=ECtHZsZPop+tJwJ4bSLGMMJe5XWFgk8idkFd9d0bhJI=
2015-09-23 14:18:50,209 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: >> Accept: application/*+xml;version=1.5

2015-09-23 14:18:50,840 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [brooklyn-execmanager-dXFhr78G-9023]: Receiving response 1102685733: HTTP/1.1 400 Bad Request
2015-09-23 14:18:50,840 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: << HTTP/1.1 400 Bad Request
2015-09-23 14:18:50,840 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: << Date: Wed, 23 Sep 2015 13:18:50 GMT
2015-09-23 14:18:50,840 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: << Date: Wed, 23 Sep 2015 13:18:50 GMT
2015-09-23 14:18:50,840 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: << Vary: Accept-Encoding
2015-09-23 14:18:50,840 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: << Content-Type: application/vnd.vmware.vcloud.error+xml;version=1.5
2015-09-23 14:18:50,840 DEBUG jclouds.headers [brooklyn-execmanager-dXFhr78G-9023]: << Content-Length: 480
2015-09-23 14:18:50,881 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "<?xml version="1.0" encoding="UTF-8"?>[\n]"
2015-09-23 14:18:50,881 DEBUG jclouds.wire [brooklyn-execmanager-dXFhr78G-9023]: << "<Error xmlns="http://www.vmware.com/vcloud/v1.5" minorErrorCode="BAD_REQUEST" message="The requested operation could not be executed on vApp &quot;brooklyn-nv

2015-09-23 14:18:50,894 ERROR o.a.b.l.j.JcloudsLocation [brooklyn-execmanager-dXFhr78G-9023]: Problem releasing machine SshMachineLocation[Acme (Test):217.115.71.201/217.115.71.201:11179@nztxMrj0] in JcloudsPortforwardingSubnetLocation[Acme (Test):martin@acme-2_01/vcloud-director:https://acme.com/api@rQ06iybE], instance id urn:vcloud:vm:4a227412-9e9e-4914-b414-be30c2e54363; ignoring and continuing, will throw subsequently: org.jclouds.vcloud.director.v1_5.VCloudDirectorException: Bad Request (400) Error: The requested operation could not be executed on vApp "brooklyn-nv4p0s-amp-auto-qa-qnkh-mongodb-server-jcy6-1da". Stop the vApp and try again.
org.jclouds.vcloud.director.v1_5.VCloudDirectorException: Bad Request (400) Error: The requested operation could not be executed on vApp "brooklyn-nv4p0s-amp-auto-qa-qnkh-mongodb-server-jcy6-1da". Stop the vApp and try again.
        at org.jclouds.vcloud.director.v1_5.handlers.VCloudDirectorErrorHandler.handleError(VCloudDirectorErrorHandler.java:58) ~[vcloud-director-1.9.1-20150815.1541.jar:1.9.1-20150815.1541]
        at org.jclouds.http.handlers.DelegatingErrorHandler.handleError(DelegatingErrorHandler.java:65) ~[jclouds-core-1.9.1.jar:1.9.1]
        at org.jclouds.http.internal.BaseHttpCommandExecutorService.shouldContinue(BaseHttpCommandExecutorService.java:136) ~[jclouds-core-1.9.1.jar:1.9.1]
        at org.jclouds.http.internal.BaseHttpCommandExecutorService.invoke(BaseHttpCommandExecutorService.java:105) ~[jclouds-core-1.9.1.jar:1.9.1]
        at org.jclouds.rest.internal.InvokeHttpMethod.invoke(InvokeHttpMethod.java:90) ~[jclouds-core-1.9.1.jar:1.9.1]
        at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:73) ~[jclouds-core-1.9.1.jar:1.9.1]
        at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:44) ~[jclouds-core-1.9.1.jar:1.9.1]
        at org.jclouds.reflect.FunctionalReflection$FunctionalInvocationHandler.handleInvocation(FunctionalReflection.java:117) ~[jclouds-core-1.9.1.jar:1.9.1]
        at com.google.common.reflect.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:87) ~[guava-16.0.1.jar:na]
        at com.sun.proxy.$Proxy210.remove(Unknown Source) ~[na:na]
        at org.jclouds.vcloud.director.v1_5.compute.strategy.VCloudDirectorComputeServiceAdapter.destroyNode(VCloudDirectorComputeServiceAdapter.java:504) ~[vcloud-director-1.9.1-20150815.1541.jar:1.9.1-20150815.1541]
        at org.jclouds.compute.strategy.impl.AdaptingComputeServiceStrategies.destroyNode(AdaptingComputeServiceStrategies.java:181) ~[jclouds-compute-1.9.1.jar:1.9.1]
        at org.jclouds.compute.internal.BaseComputeService$2.apply(BaseComputeService.java:291) ~[jclouds-compute-1.9.1.jar:1.9.1]
        at org.jclouds.compute.internal.BaseComputeService$2.apply(BaseComputeService.java:288) ~[jclouds-compute-1.9.1.jar:1.9.1]
        at org.jclouds.util.Predicates2$RetryablePredicate.apply(Predicates2.java:117) ~[jclouds-core-1.9.1.jar:1.9.1]
        at org.jclouds.compute.internal.BaseComputeService.doDestroyNode(BaseComputeService.java:302) ~[jclouds-compute-1.9.1.jar:1.9.1]
        at org.jclouds.compute.internal.BaseComputeService.destroyNode(BaseComputeService.java:243) ~[jclouds-compute-1.9.1.jar:1.9.1]
        at org.apache.brooklyn.location.jclouds.JcloudsLocation.releaseNode(JcloudsLocation.java:2365) ~[brooklyn-locations-jclouds-0.9.0-20150917.1636.jar:0.9.0-20150917.1636]
        at org.apache.brooklyn.location.jclouds.JcloudsLocation.release(JcloudsLocation.java:2315) ~[brooklyn-locations-jclouds-0.9.0-20150917.1636.jar:0.9.0-20150917.1636]
        at org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks.stopAnyProvisionedMachines(MachineLifecycleEffectorTasks.java:893) [brooklyn-software-base-0.9.0-20150917.1636.jar:0.9.0-20150917.1636]
        at org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks$StopAnyProvisionedMachinesTask.call(MachineLifecycleEffectorTasks.java:758) [brooklyn-software-base-0.9.0-20150917.1636.jar:0.9.0-20150917.1636]
        at org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks$StopAnyProvisionedMachinesTask.call(MachineLifecycleEffectorTasks.java:756) [brooklyn-software-base-0.9.0-20150917.1636.jar:0.9.0-20150917.1636]
        at org.apache.brooklyn.util.core.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:342) [brooklyn-core-0.9.0-20150917.1636.jar:0.9.0-20150917.1636]
        at org.apache.brooklyn.util.core.task.BasicExecutionManager$SubmissionCallable.call(BasicExecutionManager.java:468) [brooklyn-core-0.9.0-20150917.1636.jar:0.9.0-20150917.1636]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_71]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_71]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_71]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_71]
googlielmo commented 9 years ago

@aledsage I tried to reproduce this several times with no luck. My tests have succeeded in deleting the VM without errors. (Tried on both TAI and TAI2.0) -- Any ideas on how to reproduce?

aledsage commented 8 years ago

@googlielmo no idea how to reproduce it - I've also only seen it once.