search

cloudsoft / jclouds-vcloud-director

0 stars 9 forks source link

NPE creating VM in vCD private cloud (caused by ACCESS_TO_RESOURCE_IS_FORBIDDEN invoking VAppApi.get) #17

Closed aledsage closed 8 years ago

aledsage commented 9 years ago

In a customer's private cloud, using vCD 1.5 API, we hit this NPE when provisioning a VM:

Failed after 18m 22s: java.lang.NullPointerException

java.lang.NullPointerException
    at org.jclouds.vcloud.director.v1_5.compute.functions.VmToNodeMetadata.apply(VmToNodeMetadata.java:86)
    at org.jclouds.vcloud.director.v1_5.compute.functions.VmToNodeMetadata.apply(VmToNodeMetadata.java:53)
    at com.google.common.base.Functions$FunctionComposition.apply(Functions.java:211)
    at com.google.common.collect.Iterators$8.transform(Iterators.java:794)
    at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48)
    at com.google.common.collect.Iterators$7.computeNext(Iterators.java:646)
    at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
    at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
    at com.google.common.collect.Iterators.indexOf(Iterators.java:771)
    at com.google.common.collect.Iterators.any(Iterators.java:679)
    at com.google.common.collect.Iterables.any(Iterables.java:619)
    at org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet.getNextNames(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:197)
    at org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet.execute(CreateNodesWithGroupEncodedIntoNameThenAddToSet.java:121)
    at org.jclouds.compute.internal.BaseComputeService.createNodesInGroup(BaseComputeService.java:210)
    at brooklyn.location.jclouds.JcloudsLocation.obtainOnce(JcloudsLocation.java:709)
    at brooklyn.location.jclouds.JcloudsLocation.obtain(JcloudsLocation.java:604)
    at brooklyn.networking.portforwarding.subnet.JcloudsPortforwardingSubnetLocation.obtain(JcloudsPortforwardingSubnetLocation.java:119)
    at brooklyn.networking.portforwarding.subnet.JcloudsPortforwardingSubnetLocation.obtain(JcloudsPortforwardingSubnetLocation.java:57)
    at brooklyn.entity.software.MachineLifecycleEffectorTasks$5$1.call(MachineLifecycleEffectorTasks.java:291)
    at brooklyn.entity.software.MachineLifecycleEffectorTasks$5$1.call(MachineLifecycleEffectorTasks.java:289)
    at brooklyn.util.task.Tasks.withBlockingDetails(Tasks.java:99)
    at brooklyn.entity.software.MachineLifecycleEffectorTasks$5.call(MachineLifecycleEffectorTasks.java:289)
    at brooklyn.entity.software.MachineLifecycleEffectorTasks$5.call(MachineLifecycleEffectorTasks.java:279)
    at brooklyn.util.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:343)
    at brooklyn.util.task.BasicExecutionManager$SubmissionCallable.call(BasicExecutionManager.java:469)
    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)

Immediately before this, we got a 403 from vCD (custom's url changed to acme.com):

2015-07-30 20:59:56,965 DEBUG o.j.r.i.InvokeHttpMethod [brooklyn-execmanager-wLvf8HEQ-944]: >> invoking VAppApi.get
2015-07-30 20:59:56,965 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [brooklyn-execmanager-wLvf8HEQ-944]: Sending request 1247931680: GET https://acme.com/api/vApp/vapp-930e7003-7cbe-41a5-864a-8f1cb4a2567e HTTP/1.1
2015-07-30 20:59:56,966 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: >> GET https://acme.com/api/vApp/vapp-930e7003-7cbe-41a5-864a-8f1cb4a2567e HTTP/1.1
2015-07-30 20:59:56,966 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: >> x-vcloud-authorization: 7UYX4F8JIk+BEpaHwzs1B1WXj9yzko21qUdcUK0OYxE=
2015-07-30 20:59:56,966 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: >> Cookie: vcloud-token=7UYX4F8JIk+BEpaHwzs1B1WXj9yzko21qUdcUK0OYxE=
2015-07-30 20:59:56,966 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: >> Accept: application/*+xml;version=1.5
2015-07-30 20:59:57,078 DEBUG o.j.h.i.JavaUrlHttpCommandExecutorService [brooklyn-execmanager-wLvf8HEQ-944]: Receiving response 1247931680: HTTP/1.1 403 Forbidden
2015-07-30 20:59:57,078 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: << HTTP/1.1 403 Forbidden
2015-07-30 20:59:57,078 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: << Date: Thu, 30 Jul 2015 19:59:57 GMT
2015-07-30 20:59:57,078 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: << Date: Thu, 30 Jul 2015 19:59:57 GMT
2015-07-30 20:59:57,078 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: << Vary: Accept-Encoding
2015-07-30 20:59:57,078 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: << Content-Type: application/vnd.vmware.vcloud.error+xml;version=1.5
2015-07-30 20:59:57,078 DEBUG jclouds.headers [brooklyn-execmanager-wLvf8HEQ-944]: << Content-Length: 447
2015-07-30 20:59:57,119 DEBUG jclouds.wire [brooklyn-execmanager-wLvf8HEQ-944]: << "<?xml version="1.0" encoding="UTF-8"?>[\n]"
2015-07-30 20:59:57,119 DEBUG jclouds.wire [brooklyn-execmanager-wLvf8HEQ-944]: << "<Error xmlns="http://www.vmware.com/vcloud/v1.5" minorErrorCode="ACCESS_TO_RESOURCE_IS_FORBIDDEN" message="No access to entity &quot;com.vmware.vcloud.entity.vapp:930e7003-7cbe-41a5-
864a-8f1cb4a2567e&quot;." majorErrorCode="403" 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"></Error>[\n]"
2015-07-30 20:59:57,124 ERROR b.l.jclouds.JcloudsLocation [brooklyn-execmanager-wLvf8HEQ-944]: Failed to start VM for vcloud-director:https://acme.com/api@TomcatServerImpl{id=FFeuBTxV}: null

Another call to the API had worked a second earlier. It looks like a plausible VM id, based on this log snippet from earlier:

2015-07-30 20:56:16,616 DEBUG jclouds.wire [brooklyn-execmanager-wLvf8HEQ-877]: << "<Task xmlns="http://www.vmware.com/vcloud/v1.5" status="success" startTime="2015-07-30T21:56:10.287+02:00" operationName="vdcDeleteVapp" operation="Deleted Virtual Application brookl
yn-bpgp-amp-auto-qa-tomcat-gymv-tomcat-vgx8-2ba(930e7003-7cbe-41a5-864a-8f1cb4a2567e)" expiryTime="2015-10-28T21:56:10.287+01:00" endTime="2015-07-30T21:56:16.290+02:00" name="task" id="urn:vcloud:task:2a949e1d-e5eb-43a7-9f53-80f6d1da9e05" type="application/vnd.vmwa
re.vcloud.task+xml" href="https://acme.com/api/task/2a949e1d-e5eb-43a7-9f53-80f6d1da9e05" 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-07-30 20:56:16,616 DEBUG jclouds.wire [brooklyn-execmanager-wLvf8HEQ-877]: << "    <Owner type="application/vnd.vmware.vcloud.vApp+xml" name="brooklyn-bpgp-amp-auto-qa-tomcat-gymv-tomcat-vgx8-2ba" href="https://acme.com/api/vApp/vapp-930e7003-
7cbe-41a5-864a-8f1cb4a2567e"/>[\n]"
2015-07-30 20:56:16,616 DEBUG jclouds.wire [brooklyn-execmanager-wLvf8HEQ-877]: << "    <User type="application/vnd.vmware.admin.user+xml" name="martin" href="https://acme.com/api/admin/user/6c26165c-9ec1-4a6a-92c5-7e3e33af4c1d"/>[\n]"
2015-07-30 20:56:16,616 DEBUG jclouds.wire [brooklyn-execmanager-wLvf8HEQ-877]: << "    <Organization type="application/vnd.vmware.vcloud.org+xml" name="Canopy_compose-2_01" href="https://acme.com/api/org/e49fb225-454e-4ef0-8fb8-f89f5491a499"/>[\n]
"
2015-07-30 20:56:16,616 DEBUG jclouds.wire [brooklyn-execmanager-wLvf8HEQ-877]: << "</Task>[\n]"
aledsage commented 8 years ago

This looks like a similar problem to https://github.com/cloudsoft/jclouds-vcloud-director/issues/29 and https://github.com/cloudsoft/jclouds-vcloud-director/issues/35, which have both been fixed. I suspect that this is also fixed now. Closing now, and will re-open if we encountered it again.