1501523 – [ASB] APB provisioning fails to start when attempted directly after "apb push"ing a new APB.

Bug 1501523 - [ASB] APB provisioning fails to start when attempted directly after "apb push"ing a new APB.

Summary: [ASB] APB provisioning fails to start when attempted directly after "apb push...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	OpenShift Container Platform
Classification:	Red Hat
Component:	Service Broker
Sub Component:
Version:	3.7.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Target Release:	3.7.0
Assignee:	Dylan Murray
QA Contact:	Jian Zhang
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-10-12 18:09 UTC by Derek Whatley
Modified:	2017-11-28 22:16 UTC (History)
CC List:	5 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2017-11-28 22:16:57 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHSA-2017:3188	0	normal	SHIPPED_LIVE	Moderate: Red Hat OpenShift Container Platform 3.7 security, bug, and enhancement update	2017-11-29 02:34:54 UTC

Description Derek Whatley 2017-10-12 18:09:58 UTC

Description of problem
=======================
After using "apb push" to push an APB which hasn't previously been pushed to ASB, ASB will fail to carry out a provision requested from the Web UI for that particular APB until some amount of time has passed. After a period of time has passed, provision attempts will start working.

The error message shown in the Web UI look like this:

ServiceInstance "emr/apb-push-emr-apb-7vjqk": Error provisioning ServiceInstance of ClusterServiceClass (K8S: "053d4c56a86eda1d126fadcccf96804a" ExternalName: "apb-push-emr-apb") at ClusterServiceBroker "ansible-service-broker": Status: 400; ErrorMessage: <nil>; Description: not found; ResponseError: <nil>

How reproducible
=================
Has happened every time I try to replicate it today

Steps to Reproduce
===================
1. Find a local APB that hasn't been added to ASB / service-catalog yet
2. Run "apb push" to push that APB 
3. Immediately attempt to provision that APB, you should see an error appear.

Actual results
===============
Attempted provision from Web UI errors out unless I wait a few minutes after running after APB.


Expected results
=================
Attempted provision will run successfully if the APB is visible in the service catalog Web UI.


***************************
controller-manager LOGS
***************************
***************************

I1012 17:36:05.398115       1 request.go:462] Throttling request took 190.638559ms, request: POST:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceclasses 
I1012 17:36:05.406855       1 controller_broker.go:427] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServiceClass (K8S: "053d4c56a86eda1d126fadcccf96804a" ExternalName: "apb-push-emr-apb")
I1012 17:36:05.406911       1 controller_broker.go:724] ClusterServiceBroker "ansible-service-broker": Updating ready condition to True
I1012 17:36:05.598168       1 request.go:462] Throttling request took 191.070789ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterservicebrokers/ansible-service-broker/status 
I1012 17:36:05.637780       1 controller_broker.go:729] ClusterServiceBroker "ansible-service-broker": Updated ready condition to True
I1012 17:36:05.637921       1 event.go:218] Event(v1.ObjectReference{Kind:"ClusterServiceBroker", Namespace:"", Name:"ansible-service-broker", UID:"ab7f1c5a-af55-11e7-b6af-0242ac110005", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"185", FieldPath:""}): type: 'Normal' reason: 'FetchedCatalog' Successfully fetched catalog entries from broker.
I1012 17:36:05.793689       1 controller_broker.go:224] ClusterServiceBroker "ansible-service-broker": processing
I1012 17:36:05.798540       1 controller_broker.go:248] ClusterServiceBroker "ansible-service-broker": creating client, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ 
I1012 17:36:05.798915       1 controller_broker.go:260] ClusterServiceBroker "ansible-service-broker": processing adding/update event
I1012 17:36:05.824574       1 controller_broker.go:303] ClusterServiceBroker "ansible-service-broker": successfully fetched 4 catalog entries
I1012 17:36:05.824631       1 controller_broker.go:320] ClusterServiceBroker "ansible-service-broker": converting catalog response into service-catalog API
I1012 17:36:05.826122       1 controller_broker.go:331] ClusterServiceBroker "ansible-service-broker": successfully converted catalog payload from to service-catalog API
I1012 17:36:05.998147       1 request.go:462] Throttling request took 164.739269ms, request: GET:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans?fieldSelector=spec.clusterServiceBrokerName%3Dansible-service-broker 
I1012 17:36:06.011521       1 leaderelection.go:199] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1012 17:36:06.012045       1 controller_broker.go:360] ClusterServiceBroker "ansible-service-broker": reconciling ClusterServicePlan (K8S: "bcf4d6886d81716942e33f09ee45f09a" ExternalName: "standard")
I1012 17:36:06.012079       1 controller_broker.go:656] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServicePlan "bcf4d6886d81716942e33f09ee45f09a"; updating
I1012 17:36:06.198158       1 request.go:462] Throttling request took 185.825026ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans/bcf4d6886d81716942e33f09ee45f09a 
I1012 17:36:06.203041       1 controller_broker.go:375] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServicePlan (K8S: "bcf4d6886d81716942e33f09ee45f09a" ExternalName: "standard")
I1012 17:36:06.203086       1 controller_broker.go:360] ClusterServiceBroker "ansible-service-broker": reconciling ClusterServicePlan (K8S: "95a58462c77c207e446d51c9f4749b26" ExternalName: "fifo")
I1012 17:36:06.203095       1 controller_broker.go:656] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServicePlan "95a58462c77c207e446d51c9f4749b26"; updating
I1012 17:36:06.398096       1 request.go:462] Throttling request took 194.804584ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans/95a58462c77c207e446d51c9f4749b26 
I1012 17:36:06.403394       1 controller_broker.go:375] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServicePlan (K8S: "95a58462c77c207e446d51c9f4749b26" ExternalName: "fifo")
I1012 17:36:06.403427       1 controller_broker.go:360] ClusterServiceBroker "ansible-service-broker": reconciling ClusterServicePlan (K8S: "f2546f24cd54e76154f86481296adc9d" ExternalName: "default")
I1012 17:36:06.403435       1 controller_broker.go:656] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServicePlan "f2546f24cd54e76154f86481296adc9d"; updating
I1012 17:36:06.598149       1 request.go:462] Throttling request took 194.348921ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans/f2546f24cd54e76154f86481296adc9d 
I1012 17:36:06.605959       1 controller_broker.go:375] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServicePlan (K8S: "f2546f24cd54e76154f86481296adc9d" ExternalName: "default")
I1012 17:36:06.606009       1 controller_broker.go:360] ClusterServiceBroker "ansible-service-broker": reconciling ClusterServicePlan (K8S: "65e9e7125c15e3c10373075dac4c0b61" ExternalName: "default")
I1012 17:36:06.606027       1 controller_broker.go:656] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServicePlan "65e9e7125c15e3c10373075dac4c0b61"; updating
I1012 17:36:06.798124       1 request.go:462] Throttling request took 191.852575ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans/65e9e7125c15e3c10373075dac4c0b61 
I1012 17:36:06.807946       1 controller_broker.go:375] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServicePlan (K8S: "65e9e7125c15e3c10373075dac4c0b61" ExternalName: "default")
I1012 17:36:06.807998       1 controller_broker.go:360] ClusterServiceBroker "ansible-service-broker": reconciling ClusterServicePlan (K8S: "9e26f4df92dee2f528d03e0f6a6b0bba" ExternalName: "topicwithsub")
I1012 17:36:06.808012       1 controller_broker.go:656] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServicePlan "9e26f4df92dee2f528d03e0f6a6b0bba"; updating
I1012 17:36:06.998134       1 request.go:462] Throttling request took 189.926054ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans/9e26f4df92dee2f528d03e0f6a6b0bba 
I1012 17:36:07.005652       1 controller_broker.go:375] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServicePlan (K8S: "9e26f4df92dee2f528d03e0f6a6b0bba" ExternalName: "topicwithsub")
I1012 17:36:07.005730       1 controller_broker.go:360] ClusterServiceBroker "ansible-service-broker": reconciling ClusterServicePlan (K8S: "d95ac0ba90e194af69a691ea70a5fd41" ExternalName: "topic")
I1012 17:36:07.005793       1 controller_broker.go:656] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServicePlan "d95ac0ba90e194af69a691ea70a5fd41"; updating
I1012 17:36:07.198128       1 request.go:462] Throttling request took 192.064204ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans/d95ac0ba90e194af69a691ea70a5fd41 
I1012 17:36:07.203960       1 controller_broker.go:375] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServicePlan (K8S: "d95ac0ba90e194af69a691ea70a5fd41" ExternalName: "topic")
I1012 17:36:07.204009       1 controller_broker.go:360] ClusterServiceBroker "ansible-service-broker": reconciling ClusterServicePlan (K8S: "44d13ba6a428cff63d6945eaad6d1acd" ExternalName: "subscription")
I1012 17:36:07.204023       1 controller_broker.go:656] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServicePlan "44d13ba6a428cff63d6945eaad6d1acd"; updating
I1012 17:36:07.398157       1 request.go:462] Throttling request took 193.9136ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceplans/44d13ba6a428cff63d6945eaad6d1acd 
I1012 17:36:07.404675       1 controller_broker.go:375] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServicePlan (K8S: "44d13ba6a428cff63d6945eaad6d1acd" ExternalName: "subscription")
I1012 17:36:07.404732       1 controller_broker.go:410] ClusterServiceBroker "ansible-service-broker": Reconciling ClusterServiceClass (K8S: "8b7a3edb3e5ed6446bf8a03a6bb11459" ExternalName: "apb-push-sqs-apb")
I1012 17:36:07.404748       1 controller_broker.go:592] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServiceClass (K8S: "8b7a3edb3e5ed6446bf8a03a6bb11459" ExternalName: "apb-push-sqs-apb"); updating
I1012 17:36:07.598126       1 request.go:462] Throttling request took 193.166467ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceclasses/8b7a3edb3e5ed6446bf8a03a6bb11459 
I1012 17:36:07.603786       1 controller_broker.go:427] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServiceClass (K8S: "8b7a3edb3e5ed6446bf8a03a6bb11459" ExternalName: "apb-push-sqs-apb")
I1012 17:36:07.603837       1 controller_broker.go:410] ClusterServiceBroker "ansible-service-broker": Reconciling ClusterServiceClass (K8S: "bdf67db17594d5f2d37c69c16f97cce6" ExternalName: "apb-push-rds-mysql-apb")
I1012 17:36:07.603854       1 controller_broker.go:592] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServiceClass (K8S: "bdf67db17594d5f2d37c69c16f97cce6" ExternalName: "apb-push-rds-mysql-apb"); updating
I1012 17:36:07.798143       1 request.go:462] Throttling request took 194.114986ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceclasses/bdf67db17594d5f2d37c69c16f97cce6 
I1012 17:36:07.804257       1 controller_broker.go:427] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServiceClass (K8S: "bdf67db17594d5f2d37c69c16f97cce6" ExternalName: "apb-push-rds-mysql-apb")
I1012 17:36:07.804466       1 controller_broker.go:410] ClusterServiceBroker "ansible-service-broker": Reconciling ClusterServiceClass (K8S: "053d4c56a86eda1d126fadcccf96804a" ExternalName: "apb-push-emr-apb")
I1012 17:36:07.804494       1 controller_broker.go:592] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServiceClass (K8S: "053d4c56a86eda1d126fadcccf96804a" ExternalName: "apb-push-emr-apb"); updating
I1012 17:36:07.998113       1 request.go:462] Throttling request took 193.440048ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceclasses/053d4c56a86eda1d126fadcccf96804a 
I1012 17:36:08.006846       1 controller_broker.go:427] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServiceClass (K8S: "053d4c56a86eda1d126fadcccf96804a" ExternalName: "apb-push-emr-apb")
I1012 17:36:08.006898       1 controller_broker.go:410] ClusterServiceBroker "ansible-service-broker": Reconciling ClusterServiceClass (K8S: "ab883cebb0a87311150230384078477c" ExternalName: "apb-push-sns-apb")
I1012 17:36:08.006911       1 controller_broker.go:592] ClusterServiceBroker "ansible-service-broker": Found existing ClusterServiceClass (K8S: "ab883cebb0a87311150230384078477c" ExternalName: "apb-push-sns-apb"); updating
I1012 17:36:08.019137       1 leaderelection.go:199] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1012 17:36:08.198150       1 request.go:462] Throttling request took 191.05394ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterserviceclasses/ab883cebb0a87311150230384078477c 
I1012 17:36:08.203151       1 controller_broker.go:427] ClusterServiceBroker "ansible-service-broker": Reconciled ClusterServiceClass (K8S: "ab883cebb0a87311150230384078477c" ExternalName: "apb-push-sns-apb")
I1012 17:36:08.203214       1 controller_broker.go:724] ClusterServiceBroker "ansible-service-broker": Updating ready condition to True
I1012 17:36:08.398109       1 request.go:462] Throttling request took 194.668674ms, request: PUT:https://172.30.0.1:443/apis/servicecatalog.k8s.io/v1beta1/clusterservicebrokers/ansible-service-broker/status 
I1012 17:36:08.411697       1 controller_broker.go:729] ClusterServiceBroker "ansible-service-broker": Updated ready condition to True
I1012 17:36:08.411885       1 event.go:218] Event(v1.ObjectReference{Kind:"ClusterServiceBroker", Namespace:"", Name:"ansible-service-broker", UID:"ab7f1c5a-af55-11e7-b6af-0242ac110005", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"188", FieldPath:""}): type: 'Normal' reason: 'FetchedCatalog' Successfully fetched catalog entries from broker.
I1012 17:36:10.024861       1 leaderelection.go:199] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1012 17:36:12.032178       1 leaderelection.go:199] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1012 17:36:13.922341       1 controller.go:312] Creating client for ClusterServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ 
I1012 17:36:13.922668       1 controller_instance.go:1471] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Setting condition "Ready" to False
I1012 17:36:13.922692       1 controller_instance.go:1490] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Found status change, condition "Ready": "True" -> "False"; setting lastTransitionTime to 2017-10-12 17:36:13.922663641 +0000 UTC
I1012 17:36:13.922713       1 controller_instance.go:1521] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Updating status
E1012 17:36:13.937946       1 controller_instance.go:1524] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Failed to update status: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal
I1012 17:36:13.938003       1 controller.go:232] Error syncing ServiceInstance sns-topic-only/apb-push-sns-apb-h4jf4: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal
I1012 17:36:14.042128       1 leaderelection.go:199] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1012 17:36:34.422153       1 controller.go:312] Creating client for ClusterServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ 
I1012 17:36:34.422578       1 controller_instance.go:1471] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Setting condition "Ready" to False
I1012 17:36:34.422607       1 controller_instance.go:1490] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Found status change, condition "Ready": "True" -> "False"; setting lastTransitionTime to 2017-10-12 17:36:34.422572758 +0000 UTC
I1012 17:36:34.422627       1 controller_instance.go:1521] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Updating status
E1012 17:36:34.430767       1 controller_instance.go:1524] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Failed to update status: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal
I1012 17:36:34.430800       1 controller.go:232] Error syncing ServiceInstance sns-topic-only/apb-push-sns-apb-h4jf4: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal
I1012 17:37:15.395794       1 controller.go:312] Creating client for ClusterServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ 
I1012 17:37:15.396273       1 controller_instance.go:1471] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Setting condition "Ready" to False
I1012 17:37:15.396397       1 controller_instance.go:1490] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Found status change, condition "Ready": "True" -> "False"; setting lastTransitionTime to 2017-10-12 17:37:15.39626593 +0000 UTC
I1012 17:37:15.396423       1 controller_instance.go:1521] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Updating status
E1012 17:37:15.417279       1 controller_instance.go:1524] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Failed to update status: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal
I1012 17:37:15.417331       1 controller.go:232] Error syncing ServiceInstance sns-topic-only/apb-push-sns-apb-h4jf4: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal

I1012 17:37:24.821238       1 reflector.go:286] github.com/kubernetes-incubator/service-catalog/pkg/client/informers_generated/externalversions/factory.go:61: forcing resync
I1012 17:38:37.342666       1 controller.go:312] Creating client for ClusterServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ 
I1012 17:38:37.343215       1 controller_instance.go:1471] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Setting condition "Ready" to False
I1012 17:38:37.343249       1 controller_instance.go:1490] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Found status change, condition "Ready": "True" -> "False"; setting lastTransitionTime to 2017-10-12 17:38:37.343204249 +0000 UTC
I1012 17:38:37.343272       1 controller_instance.go:1521] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Updating status
E1012 17:38:37.358687       1 controller_instance.go:1524] ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4": Failed to update status: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal
I1012 17:38:37.358728       1 controller.go:237] Dropping ServiceInstance "sns-topic-only/apb-push-sns-apb-h4jf4" out of the queue: ServiceInstance.servicecatalog.k8s.io "apb-push-sns-apb-h4jf4" is invalid: status.currentOperation: Forbidden: currentOperation must not be present when reconciledGeneration and generation are equal
I1012 17:38:37.650011       1 reflector.go:421] github.com/kubernetes-incubator/service-catalog/pkg/client/informers_generated/externalversions/factory.go:61: Watch close - *v1beta1.ServiceBinding total 0 items received

I1012 17:38:54.488860       1 controller_instance.go:1374] ServiceInstance "emr/apb-push-emr-apb-7vjqk": looking up a ClusterServiceClass from externalName: "apb-push-emr-apb"
I1012 17:38:54.495622       1 controller_instance.go:1386] ServiceInstance "emr/apb-push-emr-apb-7vjqk": resolved ClusterServiceClass with externalName "apb-push-emr-apb" to K8S ClusterServiceClass "053d4c56a86eda1d126fadcccf96804a"
I1012 17:38:54.502609       1 controller_instance.go:1428] ServiceInstance "emr/apb-push-emr-apb-7vjqk": resolved ClusterServicePlan with externalName "default" to K8S ClusterServicePlan "65e9e7125c15e3c10373075dac4c0b61"
I1012 17:38:54.502626       1 controller_instance.go:1508] ServiceInstance "emr/apb-push-emr-apb-7vjqk": Updating references
I1012 17:38:54.529392       1 controller_instance.go:509] ServiceInstance "emr/apb-push-emr-apb-7vjqk": Processing adding/updating event
I1012 17:38:54.565912       1 controller.go:312] Creating client for ClusterServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ 
I1012 17:38:54.640637       1 controller_instance.go:1471] ServiceInstance "emr/apb-push-emr-apb-7vjqk": Setting condition "Ready" to False
I1012 17:38:54.640674       1 controller_instance.go:1481] ServiceInstance "emr/apb-push-emr-apb-7vjqk": Setting lastTransitionTime, condition "Ready" to 2017-10-12 17:38:54.64062228 +0000 UTC
I1012 17:38:54.640697       1 controller_instance.go:1521] ServiceInstance "emr/apb-push-emr-apb-7vjqk": Updating status
I1012 17:38:54.648781       1 controller_instance.go:701] ServiceInstance "emr/apb-push-emr-apb-7vjqk": Provisioning a new ServiceInstance of ClusterServiceClass (K8S: "053d4c56a86eda1d126fadcccf96804a" ExternalName: "apb-push-emr-apb") at ClusterServiceBroker "ansible-service-broker"
I1012 17:38:54.688098       1 client.go:204] handling failure responses
W1012 17:38:54.688224       1 controller_instance.go:719] ServiceInstance "emr/apb-push-emr-apb-7vjqk": Error provisioning ServiceInstance of ClusterServiceClass (K8S: "053d4c56a86eda1d126fadcccf96804a" ExternalName: "apb-push-emr-apb") at ClusterServiceBroker "ansible-service-broker": Status: 400; ErrorMessage: <nil>; Description: not found; ResponseError: <nil>



*****************************
ansible-service-broker LOGS
*****************************
*****************************

Comment 1 Dylan Murray 2017-10-16 15:44:01 UTC

The error seems to be related to this function call reporting a 400: https://github.com/openshift/ansible-service-broker/blob/3568cfe733824deff6379331ae862df7ac829760/pkg/broker/broker.go#L638. This error goes away as soon as the broker auto bootstraps.

Comment 2 Dylan Murray 2017-10-16 15:44:01 UTC

The error seems to be related to this function call reporting a 400: https://github.com/openshift/ansible-service-broker/blob/3568cfe733824deff6379331ae862df7ac829760/pkg/broker/broker.go#L638. This error goes away as soon as the broker auto bootstraps.

Comment 3 Dylan Murray 2017-10-16 16:40:10 UTC

https://github.com/openshift/ansible-service-broker/pull/495

Comment 5 Jian Zhang 2017-10-27 08:58:25 UTC

1, Init a new local APB and then push it to the ASB by "apb push".

2, Provision this new APB in Web UI, but got the below error:

[root@preserve-jiazha-1027master-etcd-1 ~]# oc get pods -n apb-push-hello-apb-prov-95xp8
NAME                                       READY     STATUS             RESTARTS   AGE
apb-4884e0d1-6d1c-4417-ac10-50455c073265   0/1       ImagePullBackOff   0          38m

And, as described in this bug: https://bugzilla.redhat.com/show_bug.cgi?id=1504712, there are two workarounds, if I use one of them, will it affect the test results?

I test this bug used two workarounds above, did not get errors that described in above. Or could you provide me your example APB? I will double check this issue.

Comment 6 Dylan Murray 2017-10-27 14:34:23 UTC

Jian,

Using the workaround will not affect the test results. Since using the workaround fixed the problem for you it tells me the patch worked as expected. The workaround was the best way for you to test this so the test passed.

We need to add the capability for the tool to work with remote hosts... but that is out of the scope of this bug.

Dylan

Comment 8 Dylan Murray 2017-11-02 20:48:42 UTC

Jian,

It looks like this fix was accidentally removed from the master branch here:
https://github.com/openshift/ansible-service-broker/commit/439ce3e217aa48d9a9fc097bf26760f9b55898bd#diff-55aca6fb74ac953881309c295ee9441eL1034

I am working to figure out if that was intentional and I will get it resolved. Thanks for bringing it to my attention.

Comment 9 Dylan Murray 2017-11-02 21:06:15 UTC

https://github.com/openshift/ansible-service-broker/pull/533

Comment 14 errata-xmlrpc 2017-11-28 22:16:57 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2017:3188

Note You need to log in before you can comment on or make changes to this bug.