Aled Sage created BROOKLYN-411:
----------------------------------
Summary: Softlayer VM deletion failed: 500 Internal Server Error
from Softlayer API
Key: BROOKLYN-411
URL: https://issues.apache.org/jira/browse/BROOKLYN-411
Project: Brooklyn
Issue Type: Bug
Reporter: Aled Sage
Using Brooklyn 0.11.0-SNAPSHOT with jclouds 2.0.0, when deploying to Softlayer
(in a brooklyn live test), it failed to provision (non-deterministic: the other
tests worked). There were two separate problems (shown in the log snippets
below):
1. failed to login to the VM: {{doesn't have login details within 3600000ms}}
2. failed to delete the VM, when discarding it: softlayer sent back a 500
Internal Server Error {{This cancellation could not be processed please contact
support.This cancellation could not be processed. Please contact support. There
is currently an active transaction.}}
{noformat}
2016-12-13 12:45:23,293 INFO Creating VM null in
JcloudsLocation[softlayer:software-development@pl9nu7srsh]
2016-12-13 12:45:32,963 INFO ignoring auto-generate-keypairs(false) in VM
creation because not supported for cloud/type ({})
...
2016-12-13 13:45:42,538 WARN VirtualGuest(VirtualGuest{accountId=278918,
createDate=Tue Dec 13 12:45:38 GMT 2016, domain=local.brooklyncentral.org,
fullyQualifiedDomainName=brooklyn-oi4jfn-aled-366.local.brooklyncentral.org,
hostname=brooklyn-oi4jfn-aled-366, id=26769559, lastVerifiedDate=null,
maxCpu=1, maxCpuUnits=CORE, maxMemory=1024, metricPollDate=null,
modifyDate=null, notes=null, startCpus=1, statusId=1001,
uuid=4581fc07-2752-4ae5-9cde-22e6177b62bf, primaryBackendIpAddress=null,
primaryIpAddress=null, billingItemId=0, operatingSystem=null,
operatingSystemReferenceCode=null, datacenter=null, powerState=null,
softwareLicense=null, activeTransactionCount=0, blockDevices=null,
hourlyBillingFlag=false, localDiskFlag=false,
dedicatedAccountHostOnlyFlag=false, privateNetworkOnlyFlag=false,
blockDeviceTemplateGroup=null, networkComponents=null, tagReferences=null,
primaryNetworkComponent=null, primaryBackendNetworkComponent=null,
postInstallScriptUri=null, virtualGuestAttribute=null, sshKeys=null}) doesn't
have login details within 3600000ms so it will be destroyed.
2016-12-13 13:46:17,673 ERROR Cannot retry after server error, command has
exceeded retry limit 6:
[method=org.jclouds.softlayer.features.VirtualGuestApi.public abstract boolean
org.jclouds.softlayer.features.VirtualGuestApi.deleteVirtualGuest(long)[26769559],
request=GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26769559/deleteObject
HTTP/1.1]
2016-12-13 13:46:17,678 ERROR createNodesInGroup(brooklyn-oi4jfn-aled),
completed: 0/1, errors: 1, rate: 3642580ms/op
java.util.concurrent.ExecutionException: java.lang.IllegalStateException:
{"error":"This cancellation could not be processed please contact support.This
cancellation could not be processed. Please contact support. There is currently
an active transaction.","code":"SoftLayer_Exception_Public"}
at
com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:299)
~[guava-18.0.jar:na]
java.lang.IllegalStateException: {"error":"This cancellation could not be
processed please contact support.This cancellation could not be processed.
Please contact support. There is currently an active
transaction.","code":"SoftLayer_Exception_Public"}
at
org.jclouds.softlayer.handlers.SoftLayerErrorHandler.handleError(SoftLayerErrorHandler.java:63)
~[softlayer-2.0.0.jar:2.0.0]
org.jclouds.http.HttpResponseException: command: GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26769559/deleteObject
HTTP/1.1 failed with response: HTTP/1.1 500 Internal Server Error; content:
[{"error":"This cancellation could not be processed please contact support.This
cancellation could not be processed. Please contact support. There is currently
an active transaction.","code":"SoftLayer_Exception_Public"}]
at
org.jclouds.softlayer.handlers.SoftLayerErrorHandler.handleError(SoftLayerErrorHandler.java:43)
~[softlayer-2.0.0.jar:2.0.0]
2016-12-13 13:46:17,679 ERROR createNodesInGroup(brooklyn-oi4jfn-aled),
completed: 0/1, errors: 1, rate: 3642582ms/op
java.lang.RuntimeException: createNodesInGroup(brooklyn-oi4jfn-aled),
completed: 0/1, errors: 1, rate: 3642582ms/op
at
org.jclouds.concurrent.FutureIterables.awaitCompletion(FutureIterables.java:153)
~[jclouds-core-2.0.0.jar:2.0.0]
2016-12-13 13:46:17,681 ERROR Failed to start VM for null after 1h 54s
(semaphore obtained in 0ms; template built in 9.68s;): error running 1 node
group(brooklyn-oi4jfn-aled) location(dal09) image(CENTOS_6_64)
size(cpu=1,memory=1024,disk=25,type=LOCAL) options({scriptPresent=true,
tags=[Name:brooklyn-oi4jfn-aled-yoqq, brooklyn-user:aled],
userMetadata={Name=brooklyn-oi4jfn-aled-yoqq, brooklyn-user=aled, notes=User
Metadata
=============
* Name: brooklyn-oi4jfn-aled-yoqq
* brooklyn-user: aled}})
Execution failures:
1) ExecutionException on brooklyn-oi4jfn-aled-366:
java.util.concurrent.ExecutionException: java.lang.IllegalStateException:
{"error":"This cancellation could not be processed please contact support.This
cancellation could not be processed. Please contact support. There is currently
an active transaction.","code":"SoftLayer_Exception_Public"}
at
com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:299)
at
com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:286)
at
com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
at
org.jclouds.concurrent.FutureIterables$1.run(FutureIterables.java:123)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: {"error":"This cancellation could
not be processed please contact support.This cancellation could not be
processed. Please contact support. There is currently an active
transaction.","code":"SoftLayer_Exception_Public"}
at
org.jclouds.softlayer.handlers.SoftLayerErrorHandler.handleError(SoftLayerErrorHandler.java:63)
at
org.jclouds.http.handlers.DelegatingErrorHandler.handleError(DelegatingErrorHandler.java:67)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService.shouldContinue(BaseHttpCommandExecutorService.java:140)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService.invoke(BaseHttpCommandExecutorService.java:109)
at
org.jclouds.rest.internal.InvokeHttpMethod.invoke(InvokeHttpMethod.java:90)
at
org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:73)
at
org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:44)
at
org.jclouds.reflect.FunctionalReflection$FunctionalInvocationHandler.handleInvocation(FunctionalReflection.java:117)
at
com.google.common.reflect.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:87)
at com.sun.proxy.$Proxy68.deleteVirtualGuest(Unknown Source)
at
org.jclouds.softlayer.compute.strategy.SoftLayerComputeServiceAdapter.createNodeWithGroupEncodedIntoName(SoftLayerComputeServiceAdapter.java:238)
at
org.jclouds.compute.strategy.impl.AdaptingComputeServiceStrategies.createNodeWithGroupEncodedIntoName(AdaptingComputeServiceStrategies.java:196)
at
org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet$AddNode.call(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:81)
at
org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet$AddNode.call(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:64)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
at java.lang.Thread.getStackTrace(Thread.java:1589)
at
org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet.createNodeInGroupWithNameAndTemplate(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:169)
at
org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet.execute(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:124)
at
org.jclouds.compute.internal.BaseComputeService.createNodesInGroup(BaseComputeService.java:217)
at
org.apache.brooklyn.location.jclouds.JcloudsLocation.obtainOnce(JcloudsLocation.java:740)
at
org.apache.brooklyn.location.jclouds.JcloudsLocation.obtain(JcloudsLocation.java:628)
at
org.apache.brooklyn.location.jclouds.provider.AbstractJcloudsLocationTest.obtainMachine(AbstractJcloudsLocationTest.java:188)
at
org.apache.brooklyn.location.jclouds.provider.AbstractJcloudsLocationTest.testProvisionVmUsingImageId(AbstractJcloudsLocationTest.java:161)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:86)
at org.testng.internal.Invoker.invokeMethod(Invoker.java:643)
at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:820)
at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1128)
at
org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:129)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:112)
at org.testng.TestRunner.privateRun(TestRunner.java:782)
at org.testng.TestRunner.run(TestRunner.java:632)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:366)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:361)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:319)
at org.testng.SuiteRunner.run(SuiteRunner.java:268)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1244)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1169)
at org.testng.TestNG.run(TestNG.java:1064)
at
org.testng.remote.AbstractRemoteTestNG.run(AbstractRemoteTestNG.java:132)
at org.testng.remote.RemoteTestNG.initAndRun(RemoteTestNG.java:236)
at org.testng.remote.RemoteTestNG.main(RemoteTestNG.java:81)
Caused by: org.jclouds.http.HttpResponseException: command: GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26769559/deleteObject
HTTP/1.1 failed with response: HTTP/1.1 500 Internal Server Error; content:
[{"error":"This cancellation could not be processed please contact support.This
cancellation could not be processed. Please contact support. There is currently
an active transaction.","code":"SoftLayer_Exception_Public"}]
at
org.jclouds.softlayer.handlers.SoftLayerErrorHandler.handleError(SoftLayerErrorHandler.java:43)
at
org.jclouds.http.handlers.DelegatingErrorHandler.handleError(DelegatingErrorHandler.java:67)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService.shouldContinue(BaseHttpCommandExecutorService.java:140)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService.invoke(BaseHttpCommandExecutorService.java:109)
at
org.jclouds.rest.internal.InvokeHttpMethod.invoke(InvokeHttpMethod.java:90)
at
org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:73)
at
org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:44)
at
org.jclouds.reflect.FunctionalReflection$FunctionalInvocationHandler.handleInvocation(FunctionalReflection.java:117)
at
com.google.common.reflect.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:87)
at com.sun.proxy.$Proxy68.deleteVirtualGuest(Unknown Source)
at
org.jclouds.softlayer.compute.strategy.SoftLayerComputeServiceAdapter.createNodeWithGroupEncodedIntoName(SoftLayerComputeServiceAdapter.java:238)
at
org.jclouds.compute.strategy.impl.AdaptingComputeServiceStrategies.createNodeWithGroupEncodedIntoName(AdaptingComputeServiceStrategies.java:196)
at
org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet$AddNode.call(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:81)
at
org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet$AddNode.call(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:64)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
1 error[s]
Node failures:
0 error[s]
2016-12-13 13:46:17,684 WARN Attempt #1/2 to obtain machine threw error:
org.apache.brooklyn.util.exceptions.PropagatedRuntimeException:
RunNodesException: error running 1 node group(brooklyn-oi4jfn-aled)
location(dal09) image(CENTOS_6_64) size(cpu=1,memory=1024,disk=25,type=LOCAL)
options({scriptPresent=true, tags=[Name:brooklyn-oi4jfn-aled-yoqq,
brooklyn-user:aled], userMetadata={Name=brooklyn-oi4jfn-aled-yoqq,
brooklyn-user=aled, notes=User Metadata
{noformat}
Looking in the debug log, below is the response details. This was retried 6
times:
{noformat}
2016-12-13 13:45:42,539 DEBUG o.j.r.i.InvokeHttpMethod [user thread 1]: >>
invoking VirtualGuests:delete
2016-12-13 13:45:42,539 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [user
thread 1]: Sending request -1185878952: GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26769559/deleteObject
HTTP/1.1
2016-12-13 13:45:42,539 DEBUG jclouds.headers [user thread 1]: >> GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26769559/deleteObject
HTTP/1.1
2016-12-13 13:45:42,539 DEBUG jclouds.headers [user thread 1]: >> Accept:
application/json
2016-12-13 13:45:42,540 DEBUG jclouds.headers [user thread 1]: >>
Authorization: Basic
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
2016-12-13 13:45:44,362 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [user
thread 1]: Receiving response -1185878952: HTTP/1.1 500 Internal Server Error
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: << HTTP/1.1 500
Internal Server Error
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: <<
X-Frame-Options: SAMEORIGIN
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: << Vary:
Accept-Encoding
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: << Date: Tue, 13
Dec 2016 13:45:43 GMT
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: << Connection:
close
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: << Server: Apache
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: << Content-Type:
application/json
2016-12-13 13:45:44,363 DEBUG jclouds.headers [user thread 1]: <<
Content-Length: 219
...
2016-12-13 13:46:17,673 ERROR o.j.h.h.BackoffLimitedRetryHandler [user thread
1]: Cannot retry after server error, command has exceeded retry limit 6:
[method=org.jclouds.softlayer.features.VirtualGuestApi.public abstract boolean
org.jclouds.softlayer.features.VirtualGuestApi.deleteVirtualGuest(long)[26769559],
request=GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26769559/deleteObject
HTTP/1.1]
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
