Deleting VM failed due to OPERATION_LIMITS_EXCEEDED #40
Description
Running with jclouds-vcloud-director version 1.9.1-20151118.1705...
A customer stopped an entity with a VM running in vCD. After the entity was shut down, it was observed that the VM was still left behind (in a stopped state).
Digging into the log, the reason is that the delete failed because of OPERATION_LIMITS_EXCEEDED. This is similar to #28, where there was a failure during provisioning.
The long-term solution for this is to implement exponential-backoff, to retry the command if it fails with this error code.
2016-05-19 05:04:51,128 DEBUG o.j.r.i.InvokeHttpMethod [brooklyn-execmanager-MzvCwh86-7359]: >> invoking VAppApi.remove
2016-05-19 05:04:51,128 DEBUG o.j.h.o.OkHttpCommandExecutorService [brooklyn-execmanager-MzvCwh86-7359]: Sending request 851634426: DELETE https://emea01.acme.com/api/vApp/vapp-b39b4396-1ad3-4fec-93e1-2e48a636851e HTTP/1.1
2016-05-19 05:04:51,128 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: >> DELETE https://emea01.acme.com/api/vApp/vapp-b39b4396-1ad3-4fec-93e1-2e48a636851e HTTP/1.1
2016-05-19 05:04:51,128 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: >> x-vcloud-authorization: ZgZJxJO+GCSIs107SU4JShNqk0e4u18RJk+EtNvdUZM=
2016-05-19 05:04:51,128 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: >> Cookie: vcloud-token=ZgZJxJO+GCSIs107SU4JShNqk0e4u18RJk+EtNvdUZM=
2016-05-19 05:04:51,128 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: >> Accept: application/*+xml;version=1.5
2016-05-19 05:04:51,296 DEBUG o.j.h.o.OkHttpCommandExecutorService [brooklyn-execmanager-MzvCwh86-7359]: Receiving response 851634426: HTTP/1.1 400 Bad Request
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << HTTP/1.1 400 Bad Request
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << Date: Thu, 19 May 2016 05:04:53 GMT
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << Date: Thu, 19 May 2016 05:04:53 GMT
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << OkHttp-Received-Millis: 1463634291296
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << OkHttp-Selected-Protocol: http/1.1
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << OkHttp-Sent-Millis: 1463634291129
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << Set-Cookie: BIGipServer~cmbe_01_de-cpy0-dmz-maz~cmbe_01_vcd-portal-api-ext_443_pool=rd1o00000000000000000000ffffd973440bo443; path=/
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << Content-Type: application/vnd.vmware.vcloud.error+xml;version=1.5
2016-05-19 05:04:51,296 DEBUG jclouds.headers [brooklyn-execmanager-MzvCwh86-7359]: << Content-Length: 473
2016-05-19 05:04:51,296 DEBUG jclouds.wire [brooklyn-execmanager-MzvCwh86-7359]: << "<?xml version="1.0" encoding="UTF-8"?>[\n]"
2016-05-19 05:04:51,297 DEBUG jclouds.wire [brooklyn-execmanager-MzvCwh86-7359]: << "<Error xmlns="http://www.vmware.com/vcloud/v1.5" minorErrorCode="OPERATION_LIMITS_EXCEEDED" message="The maximum number of simultaneous operations for user "sanika-bda" on organization "bda-emea01" has been reached." majorErrorCode="400" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.vmware.com/vcloud/v1.5 http://emea01.acme.com/api/v1.5/schema/master.xsd"></Error>[\n]"
2016-05-19 05:04:51,301 ERROR o.a.b.l.j.JcloudsLocation [brooklyn-execmanager-MzvCwh86-7359]: Problem releasing machine SshMachineLocation[Acme TAI 2.0 BDA 005:[email protected]/1.2.3.4:11013(id=vH7wvdVi)] in JcloudsPortforwardingSubnetLocation[Acme TAI 2.0 BDA 005:sanika-bda@bda-emea01/vcloud-director:https://emea01.acme.com/api/vdc/cc9e3ba9-2be8-43a8-8fc1-247fbf11e8ff:https://emea01.acme.com/api@ReYl2vl9], instance id urn:vcloud:vm:6f924995-5cf1-4fa3-90be-dfb6531b0d9e; ignoring and continuing, will throw subsequently: org.jclouds.vcloud.director.v1_5.VCloudDirectorException: Operation Limits Exceeded (400) Error: The maximum number of simultaneous operations for user "sanika-bda" on organization "bda-emea01" has been reached.
org.jclouds.vcloud.director.v1_5.VCloudDirectorException: Operation Limits Exceeded (400) Error: The maximum number of simultaneous operations for user "sanika-bda" on organization "bda-emea01" has been reached.
at org.jclouds.vcloud.director.v1_5.handlers.VCloudDirectorErrorHandler.handleError(VCloudDirectorErrorHandler.java:58) ~[vcloud-director-1.9.1-20151118.1705.jar:1.9.1-20151118.1705]
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.$Proxy151.remove(Unknown Source) ~[na:na]
at org.jclouds.vcloud.director.v1_5.compute.strategy.VCloudDirectorComputeServiceAdapter.destroyNode(VCloudDirectorComputeServiceAdapter.java:550) ~[vcloud-director-1.9.1-20151118.1705.jar:1.9.1-20151118.1705]
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:2393) ~[brooklyn-locations-jclouds-0.9.0-20151120.1523.jar:0.9.0-20151120.1523]
at org.apache.brooklyn.location.jclouds.JcloudsLocation.release(JcloudsLocation.java:2343) ~[brooklyn-locations-jclouds-0.9.0-20151120.1523.jar:0.9.0-20151120.1523]
at org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks.stopAnyProvisionedMachines(MachineLifecycleEffectorTasks.java:912) [brooklyn-software-base-0.9.0-20151120.1523.jar:0.9.0-20151120.1523]
at org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks$StopAnyProvisionedMachinesTask.call(MachineLifecycleEffectorTasks.java:777) [brooklyn-software-base-0.9.0-20151120.1523.jar:0.9.0-20151120.1523]
at org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks$StopAnyProvisionedMachinesTask.call(MachineLifecycleEffectorTasks.java:775) [brooklyn-software-base-0.9.0-20151120.1523.jar:0.9.0-20151120.1523]
at org.apache.brooklyn.util.core.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:342) [brooklyn-core-0.9.0-20151120.1523.jar:0.9.0-20151120.1523]
at org.apache.brooklyn.util.core.task.BasicExecutionManager$SubmissionCallable.call(BasicExecutionManager.java:492) [patch-composec-1317-pr1043-1.0.jar:0.9.0-20151120.1523]
at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_75]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_75]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]