10/3/2017 Debugging Failed Binding

Broker_ServiceCatalogLogs

From WebUI

The binding could not be created.

Error creating ServiceInstanceCredential "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321/jwm2" for ServiceInstance "jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr" of ServiceClass "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates" at ServiceBroker "ansible-service-broker", Status: 409; ErrorMessage: <nil>; Description: <nil>; ResponseError: <nil>






From Broker Logs:

[2017-10-03T17:20:28.917Z] [WARNING] [apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9] Retry attempt 8: Bind credentials not available yet
[2017-10-03T17:20:28.917Z] [WARNING] [apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9] Retry attempt 8: exec into apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9 failed
[2017-10-03T17:20:34.173Z] [INFO] Bind credentials not available.
command terminated with exit code 2

[2017-10-03T17:20:34.173Z] [WARNING] [apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9] Retry attempt 9: Bind credentials not available yet
[2017-10-03T17:20:34.173Z] [WARNING] [apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9] Retry attempt 9: exec into apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9 failed
[2017-10-03T17:20:39.441Z] [NOTICE] [apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9] Bind credentials found
[2017-10-03T17:20:39.441Z] [INFO] Destroying APB sandbox...
[2017-10-03T17:20:39.441Z] [DEBUG] Deleting serviceaccount apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9, namespace jwm2
[2017-10-03T17:20:39.634Z] [DEBUG] Successfully deleted serviceaccount apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9, namespace jwm2
[2017-10-03T17:20:39.634Z] [DEBUG] oc delete output:
[2017-10-03T17:20:39.634Z] [DEBUG] serviceaccount "apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9" deleted

[2017-10-03T17:20:39.634Z] [DEBUG] Deleting rolebinding apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9, namespace jwm2
[2017-10-03T17:20:39.826Z] [DEBUG] Successfully deleted rolebinding apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9, namespace jwm2
[2017-10-03T17:20:39.826Z] [DEBUG] oc delete output:
[2017-10-03T17:20:39.826Z] [DEBUG] rolebinding "apb-789b7558-261d-46a0-b0f2-b9cf67ae64b9" deleted

[2017-10-03T17:20:39.826Z] [DEBUG] Processed provision message from buffer
[2017-10-03T17:20:52.928Z] [DEBUG] service_id: e2df4f661cee76a13c7f5dc46be38fa9
[2017-10-03T17:20:52.928Z] [DEBUG] plan_id: dev
[2017-10-03T17:20:52.928Z] [DEBUG] operation:  ca0d4c38-8464-4aa6-9dfa-ea4b94942b65
172.17.0.6 - - [03/Oct/2017:17:20:52 +0000] "GET /ansible-service-broker/v2/service_instances/d2689a11-a9e1-4122-a02d-72af3c77c60a/last_operation?operation=ca0d4c38-8464-4aa6-9dfa-ea4b94942b65&plan_id=dev&service_id=e2df4f661cee76a13c7f5dc46be38fa9 HTTP/1.1" 200 27
[2017-10-03T17:21:15.248Z] [DEBUG] Injecting PlanID as parameter: { _apb_plan_id: dev }
[2017-10-03T17:21:15.25Z] [WARNING] Broker configured to *NOT* launch and run APB bind
172.17.0.6 - - [03/Oct/2017:17:21:15 +0000] "PUT /ansible-service-broker/v2/service_instances/d2689a11-a9e1-4122-a02d-72af3c77c60a/service_bindings/d3b094ad-ed6d-4000-ae78-3fa53338dc02 HTTP/1.1" 201 196
[2017-10-03T17:21:15.457Z] [DEBUG] Injecting PlanID as parameter: { _apb_plan_id: dev }
[2017-10-03T17:21:15.458Z] [INFO] duplicate binding instance diff params, returning 409 conflict
172.17.0.6 - - [03/Oct/2017:17:21:15 +0000] "PUT /ansible-service-broker/v2/service_instances/d2689a11-a9e1-4122-a02d-72af3c77c60a/service_bindings/d3b094ad-ed6d-4000-ae78-3fa53338dc02 HTTP/1.1" 409 3
[2017-10-03T17:22:51.398Z] [INFO] Broker configured to refresh specs every 10m0s seconds
[2017-10-03T17:22:51.399Z] [INFO] Attempting bootstrap at 2017-10-03 17:22:51.398568416 +0000 UTC
[2017-10-03T17:22:51.399Z] [INFO] AnsibleBroker::Bootstrap






From Service Catalog Logs:

I1003 17:21:15.195965       1 controller_binding.go:127] Processing ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.198102       1 controller.go:354] Creating client for ServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/
I1003 17:21:15.198295       1 controller_binding.go:200] Adding/Updating ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
W1003 17:21:15.199920       1 controller_binding.go:207] Failed to prepare ServiceInstanceCredential parameters
nil
 secrets "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-bind-parameters-iejzs" not found
I1003 17:21:15.199945       1 controller_binding.go:678] Setting ServiceInstanceCredential 'jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321' condition "Ready" to False
I1003 17:21:15.199961       1 controller_binding.go:689] Setting lastTransitionTime for ServiceInstanceCredential "jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321" condition "Ready" to 2017-10-03 17:21:15.19994021 +0000 UTC
I1003 17:21:15.199991       1 controller_binding.go:717] Updating status for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.205962       1 controller.go:200] Error syncing ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321: secrets "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-bind-parameters-iejzs" not found
I1003 17:21:15.206153       1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceInstanceCredential", Namespace:"jwm2", Name:"dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321", UID:"42a8ce29-a85f-11e7-a856-0242ac110005", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"306", FieldPath:""}): type: 'Warning' reason: 'ErrorWithParameters' Failed to prepare ServiceInstanceCredential parameters
nil
 secrets "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-bind-parameters-iejzs" not found
I1003 17:21:15.211191       1 controller_binding.go:127] Processing ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.213206       1 controller.go:354] Creating client for ServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/
I1003 17:21:15.213391       1 controller_binding.go:200] Adding/Updating ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
W1003 17:21:15.215214       1 controller_binding.go:207] Failed to prepare ServiceInstanceCredential parameters
nil
 secrets "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-bind-parameters-iejzs" not found
I1003 17:21:15.215235       1 controller_binding.go:678] Setting ServiceInstanceCredential 'jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321' condition "Ready" to False
I1003 17:21:15.215244       1 controller_binding.go:689] Setting lastTransitionTime for ServiceInstanceCredential "jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321" condition "Ready" to 2017-10-03 17:21:15.215232506 +0000 UTC
I1003 17:21:15.215255       1 controller_binding.go:717] Updating status for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
E1003 17:21:15.217925       1 controller_binding.go:720] Error updating status for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.217965       1 controller.go:200] Error syncing ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321: secrets "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-bind-parameters-iejzs" not found
I1003 17:21:15.218152       1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceInstanceCredential", Namespace:"jwm2", Name:"dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321", UID:"42a8ce29-a85f-11e7-a856-0242ac110005", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"306", FieldPath:""}): type: 'Warning' reason: 'ErrorWithParameters' Failed to prepare ServiceInstanceCredential parameters
nil
 secrets "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-bind-parameters-iejzs" not found
I1003 17:21:15.228211       1 controller_binding.go:127] Processing ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.230142       1 controller.go:354] Creating client for ServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/
I1003 17:21:15.230320       1 controller_binding.go:200] Adding/Updating ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.251497       1 controller_binding.go:570] Creating/updating Secret jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-credentials-m32co
I1003 17:21:15.256090       1 controller_binding.go:678] Setting ServiceInstanceCredential 'jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321' condition "Ready" to True
I1003 17:21:15.256111       1 controller_binding.go:689] Setting lastTransitionTime for ServiceInstanceCredential "jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321" condition "Ready" to 2017-10-03 17:21:15.256085706 +0000 UTC
I1003 17:21:15.256120       1 controller_binding.go:717] Updating status for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
E1003 17:21:15.258586       1 controller_binding.go:720] Error updating status for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.258659       1 controller_binding.go:409] Successfully bound to ServiceInstance jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr of ServiceClass dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates at ServiceBroker ansible-service-broker
I1003 17:21:15.258780       1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceInstanceCredential", Namespace:"jwm2", Name:"dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321", UID:"42a8ce29-a85f-11e7-a856-0242ac110005", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"306", FieldPath:""}): type: 'Normal' reason: 'InjectedBindResult' Injected bind result
I1003 17:21:15.395847       1 controller_binding.go:127] Processing ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.397813       1 controller.go:354] Creating client for ServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/
I1003 17:21:15.397967       1 controller_binding.go:200] Adding/Updating ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.458390       1 client.go:204] handling failure responses
W1003 17:21:15.458468       1 controller_binding.go:296] Error creating ServiceInstanceCredential "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321/jwm2" for ServiceInstance "jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr" of ServiceClass "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates" at ServiceBroker "ansible-service-broker", Status: 409; ErrorMessage: <nil>; Description: <nil>; ResponseError: <nil>
I1003 17:21:15.458482       1 controller_binding.go:678] Setting ServiceInstanceCredential 'jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321' condition "Failed" to True
I1003 17:21:15.458490       1 controller_binding.go:710] Setting lastTransitionTime for ServiceInstanceCredential 'jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321' condition "Failed" to 2017-10-03 17:21:15.458480228 +0000 UTC
I1003 17:21:15.458511       1 controller_binding.go:678] Setting ServiceInstanceCredential 'jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321' condition "Ready" to False
I1003 17:21:15.458516       1 controller_binding.go:717] Updating status for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321
I1003 17:21:15.462658       1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceInstanceCredential", Namespace:"jwm2", Name:"dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321", UID:"42a8ce29-a85f-11e7-a856-0242ac110005", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"307", FieldPath:""}): type: 'Warning' reason: 'BindCallFailed' Error creating ServiceInstanceCredential "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321/jwm2" for ServiceInstance "jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr" of ServiceClass "dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates" at ServiceBroker "ansible-service-broker", Status: 409; ErrorMessage: <nil>; Description: <nil>; ResponseError: <nil>
I1003 17:21:15.596034       1 controller_binding.go:100] Not processing event for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321 because status showed that it has failed
I1003 17:21:17.069487       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:19.075120       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:21.080224       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:22.979264       1 reflector.go:276] github.com/kubernetes-incubator/service-catalog/pkg/client/informers_generated/externalversions/factory.go:61: forcing resync
I1003 17:21:22.979418       1 controller_binding.go:100] Not processing event for ServiceInstanceCredential jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr-ml321 because status showed that it has failed
I1003 17:21:23.084537       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:25.091075       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:27.096227       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:29.101294       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:31.106382       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:33.135390       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:35.145105       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:37.150721       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:39.155665       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:41.160881       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:43.165142       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:44.172413       1 reflector.go:405] github.com/kubernetes-incubator/service-catalog/pkg/client/informers_generated/externalversions/factory.go:61: Watch close - *v1alpha1.ServiceInstance total 13 items received
I1003 17:21:45.173267       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:47.178217       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:49.183432       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:51.188147       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:53.193399       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:55.201382       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:57.206238       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:21:59.211073       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:01.216208       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:03.221400       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:05.230187       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:07.235367       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:09.240175       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:11.245118       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:13.249128       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:15.257929       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:17.934706       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:19.940070       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:21.945823       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:23.950721       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:25.962040       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:27.966194       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:29.971231       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:31.975993       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:33.981574       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:35.991267       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:37.995819       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:40.000292       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:42.004739       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I1003 17:22:43.162201       1 reflector.go:276] github.com/kubernetes-incubator/service-catalog/pkg/client/informers_generated/externalversions/factory.go:61: forcing resync
I1003 17:22:43.162283       1 controller_instance.go:471] Not processing event for ServiceInstance jwm2/dh-ansibleplaybookbundle-mediawiki123-apb-latest-fvcxv because reconciled generation showed there is no work to do
I1003 17:22:43.162306       1 controller_instance.go:471] Not processing event for ServiceInstance jwm2/dh-ansibleplaybookbundle-rhscl-postgresql-apb-lates-k5rrr because reconciled generation showed there is no work to do
I1003 17:22:44.008162       1 leaderelection.go:204] successfully renewed lease kube-service-catalog/service-catalog-controller-manager