Aled Sage created BROOKLYN-413:
----------------------------------
Summary: Softlayer provisioning failed: "doesn't have login
details" after one hour
Key: BROOKLYN-413
URL: https://issues.apache.org/jira/browse/BROOKLYN-413
Project: Brooklyn
Issue Type: Bug
Reporter: Aled Sage
With brooklyn 0.11.0-SNAPSHOT (with jclouds 2.0.0)...
When attempting to provision a Windows VM in Softlayer, the provisioning timed
out after one hour.
This was when running a live test in brooklyn, which I was working on. The yaml
equivalent would be (approximately!):
{noformat}
location:
jclouds:softlayer:
imageId: WIN_2012-STD-R2_64
vmNameMaxLength: 15
useJcloudsSshInit: false
osFamilyOverride: windows
services:
- type: org.apache.brooklyn.entity.software.base.VanillaWindowsProcess
brooklyn.config:
...
{noformat}
When provisioning, it chose this template:
{noformat}
2016-12-16 17:41:56,354 DEBUG o.a.b.l.j.JcloudsLocation [main]: jclouds using
template {image={id=WIN_2012-STD-R2_64, providerId=WIN_2012-STD-R2_64,
os={family=windows, version=2012, description=Microsoft Windows 2012 R2 FULL
STD 64 bit 2012 R2 FULL STD x64, is64Bit=true}, description=WIN_2012-STD
-R2_64, status=AVAILABLE, loginUser=Administrator},
hardware={id=cpu=1,memory=1024,disk=25,type=LOCAL,
providerId=cpu=1,memory=1024,disk=25,type=LOCAL, processors=[{cores=1.0,
speed=2.0}], ram=1024, volumes=[{id=0, type=LOCAL, size=25.0, device=0,
bootDevice=false, durable=true}], hypervisor=XenSe
rver, supportsImage=Predicates.alwaysTrue()}, location={scope=ZONE, id=dal09,
description=Dallas 9, parent=softlayer, iso3166Codes=[US-TX],
metadata={name=dal09}}, options={inboundPorts=[5986, 5985, 3389],
tags=[Name:br-oiah5l-u8i4, brooklyn-user:aled],
userMetadata={Name=br-oiah5l-u8i4, brooklyn-
user=aled, notes=User Metadata
=============
* Name: br-oiah5l-u8i4
* brooklyn-user: aled}}} / options {inboundPorts=[5986, 5985, 3389],
tags=[Name:br-oiah5l-u8i4, brooklyn-user:aled],
userMetadata={Name=br-oiah5l-u8i4, brooklyn-user=aled, notes=User Metadata
=============
* Name: br-oiah5l-u8i4
* brooklyn-user: aled}} to provision machine in null
2016-12-16 17:41:56,355 DEBUG jclouds.compute [main]: >> running 1 node
group(br-oiah5l) location(dal09) image(WIN_2012-STD-R2_64)
hardwareProfile(cpu=1,memory=1024,disk=25,type=LOCAL)
options({inboundPorts=[5986, 5985, 3389], tags=[Name:br-oiah5l-u8i4,
brooklyn-user:aled], userMetadata={Name=br-o
iah5l-u8i4, brooklyn-user=aled, notes=User Metadata
=============
* Name: br-oiah5l-u8i4
* brooklyn-user: aled}})
{noformat}
It seems to successfully create the VM, and then repeatedly polls
{{VirtualGuests:get}} for the rest of the hour:
{noformat}
...
2016-12-16 18:42:09,602 DEBUG o.j.r.i.InvokeHttpMethod [user thread 0]: >>
invoking VirtualGuests:get
2016-12-16 18:42:09,602 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [user
thread 0]: Sending request 1685001926: GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26864303/getObject?objectMask=id%3Bhostname%3Bdomain%3BfullyQualifiedDomainName%3BpowerState%3BmaxCpu%3BmaxMemory%3Bsta
tusId%3BoperatingSystem.passwords%3BprimaryBackendIpAddress%3BprimaryIpAddress%3BactiveTransactionCount%3BblockDevices.diskImage%3Bdatacenter%3BtagReferences%3BprivateNetworkOnlyFlag%3BsshKeys
HTTP/1.1
2016-12-16 18:42:09,602 DEBUG jclouds.headers [user thread 0]: >> GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26864303/getObject?objectMask=id%3Bhostname%3Bdomain%3BfullyQualifiedDomainName%3BpowerState%3BmaxCpu%3BmaxMemory%3BstatusId%3BoperatingSystem.passwords%3BprimaryBackendI
pAddress%3BprimaryIpAddress%3BactiveTransactionCount%3BblockDevices.diskImage%3Bdatacenter%3BtagReferences%3BprivateNetworkOnlyFlag%3BsshKeys
HTTP/1.1
2016-12-16 18:42:09,602 DEBUG jclouds.headers [user thread 0]: >> Accept:
application/json
2016-12-16 18:42:09,602 DEBUG jclouds.headers [user thread 0]: >>
Authorization: Basic
c29mdHdhcmUtZGV2ZWxvcG1lbnQ6NThkYjZkY2QyNGI3N2RiOTFjYmVjZjQ4ZDlkYzg4MzU3MzMyMDEyOTcxMTQ3NjU5NzYwNWYwZTEyMmExZGIzMA==
2016-12-16 18:42:10,392 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [user
thread 0]: Receiving response 1685001926: HTTP/1.1 200 OK
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: << HTTP/1.1 200
OK
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: <<
X-Frame-Options: SAMEORIGIN
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: << Vary:
Accept-Encoding
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: << Date: Fri, 16
Dec 2016 18:42:10 GMT
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: << Connection:
close
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: << Server: Apache
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: << Content-Type:
application/json
2016-12-16 18:42:10,393 DEBUG jclouds.headers [user thread 0]: <<
Content-Length: 35385
2016-12-16 18:42:10,607 WARN jclouds.compute [user thread 0]:
VirtualGuest(VirtualGuest{accountId=278918, createDate=Fri Dec 16 17:42:05 GMT
2016, domain=local.brooklyncentral.org,
fullyQualifiedDomainName=br-oiah5l-1d0.local.brooklyncentral.org,
hostname=br-oiah5l-1d0, id=26864303, lastVerifiedD
ate=null, maxCpu=1, maxCpuUnits=CORE, maxMemory=1024, metricPollDate=null,
modifyDate=null, notes=null, startCpus=1, statusId=1001,
uuid=f31e547d-ce95-4fb5-a603-4277ea96a3cc, primaryBackendIpAddress=null,
primaryIpAddress=null, billingItemId=0, operatingSystem=null,
operatingSystemReferenceCode=nu
ll, datacenter=null, powerState=null, softwareLicense=null,
activeTransactionCount=0, blockDevices=null, hourlyBillingFlag=false,
localDiskFlag=false, dedicatedAccountHostOnlyFlag=false,
privateNetworkOnlyFlag=false, blockDeviceTemplateGroup=null,
networkComponents=null, tagReferences=null, primar
yNetworkComponent=null, primaryBackendNetworkComponent=null,
postInstallScriptUri=null, virtualGuestAttribute=null, sshKeys=null}) doesn't
have login details within 3600000ms so it will be destroyed.
{noformat}
---
The VM deletion ({{VirtualGuests:delete}}) subsequently failed, including for 6
retry attempts, with "500 Internal Server Error" response (see
https://issues.apache.org/jira/browse/BROOKLYN-411).
Only the final retry attempt's details were logged in full. This showed:
{noformat}
2016-12-16 18:42:38,664 ERROR jclouds.compute [user thread 1]:
createNodesInGroup(br-oiah5l), completed: 0/1, errors: 1, rate: 3641567ms/op
java.util.concurrent.ExecutionException:
org.jclouds.http.HttpResponseException: command: GET
https://api.softlayer.com/rest/v3/SoftLayer_Virtual_Guest/26864303/deleteObject
HTTP/1.1 failed with response: HTTP/1.1 500 Internal Server Error; content:
[{"error":"A billing item is required to process
a cancellation.","code":"SoftLayer_Exception_NotFound"}]
{noformat}
This could indicate that the VM in Softlayer was in a very bad way (which might
explain the first error). Or alternatively it could be that the first
{{VirtualGuests:delete}} partially deleted it, causing the subsequent retries
to fail in a different way.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
