Bug 1535171 - Project stuck in terminating state
Summary: Project stuck in terminating state
Keywords:
Status: CLOSED DUPLICATE of bug 1540819
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Service Broker
Version: 3.9.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: 3.9.0
Assignee: Ben Parees
QA Contact: Vikas Laad
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-01-16 18:47 UTC by Vikas Laad
Modified: 2021-03-11 16:55 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-02-06 21:22:52 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
master and node logs (1006.10 KB, application/zip)
2018-01-16 18:50 UTC, Vikas Laad
no flags Details
Service Catalog Controller log file (309.89 KB, application/x-gzip)
2018-02-06 21:25 UTC, Jay Boyd
no flags Details

Description Vikas Laad 2018-01-16 18:47:13 UTC
Description of problem:
I have a cluster oc OCP 3.9 (1 master 1 infra 2 compute nodes) where a project is stuck in terminating state. I was trying to create eap quickstart app, something did not work and I had to delete project.

oc get project
vlaad1                                             Terminating

Here are few errors from etcd

root@ip-172-31-9-130: ~ # ETCDCTL_API=3 /usr/bin/etcdctl --cert /etc/etcd/peer.crt --key /etc/etcd/peer.key --cacert /etc/etcd/ca.crt --endpoints https://172.31.9.130:2379 get /registry/servicecatalog.k8s.io/servicebindings/vlaad1/eap64-mysql-persistent-s2i-bh7d8-ftn5s

/registry/servicecatalog.k8s.io/servicebindings/vlaad1/eap64-mysql-persistent-s2i-bh7d8-ftn5s
{"kind":"ServiceBinding","apiVersion":"servicecatalog.k8s.io/v1beta1","metadata":{"name":"eap64-mysql-persistent-s2i-bh7d8-ftn5s","generateName":"eap64-mysql-persistent-s2i-bh7d8-","namespace":"vlaad1","uid":"52269d94-fad5-11e7-ac61-0a58ac150002","generation":2,"creationTimestamp":"2018-01-16T15:52:57Z","deletionTimestamp":"2018-01-16T18:37:07Z","deletionGracePeriodSeconds":0,"finalizers":["kubernetes-incubator/service-catalog"]},"spec":{"instanceRef":{"name":"eap64-mysql-persistent-s2i-bh7d8"},"secretName":"eap64-mysql-persistent-s2i-bh7d8-credentials-ik9m3","externalID":"ab38884e-1557-4a39-a267-3d9ee7250684","userInfo":{"username":"system:serviceaccount:kube-system:namespace-controller","uid":"","groups":["system:serviceaccounts","system:serviceaccounts:kube-system","system:authenticated"]}},"status":{"conditions":[{"type":"Ready","status":"Unknown","lastTransitionTime":"2018-01-16T16:00:23Z","reason":"UnbindCallFailed","message":"Unbind call failed. Error unbinding from ServiceInstance \"vlaad1/eap64-mysql-persistent-s2i-bh7d8\" of ClusterServiceClass (K8S: \"a0475f42-face-11e7-a2a1-020813ce4ab6\" ExternalName: \"eap64-mysql-persistent-s2i\") at ClusterServiceBroker \"template-service-broker\": Status: 500; ErrorMessage: \u003cnil\u003e; Description: templateinstances.template.openshift.io \"bacee5e5-fc1c-4464-8ebf-1daf99236464\" not found; ResponseError: \u003cnil\u003e"},{"type":"Failed","status":"True","lastTransitionTime":"2018-01-16T15:56:15Z","reason":"UnbindCallFailed","message":"Unbind call failed. Error unbinding from ServiceInstance \"vlaad1/eap64-mysql-persistent-s2i-bh7d8\" of ClusterServiceClass (K8S: \"a0475f42-face-11e7-a2a1-020813ce4ab6\" ExternalName: \"eap64-mysql-persistent-s2i\") at ClusterServiceBroker \"template-service-broker\": Status: 500; ErrorMessage: \u003cnil\u003e; Description: templateinstances.template.openshift.io \"bacee5e5-fc1c-4464-8ebf-1daf99236464\" not found; ResponseError: \u003cnil\u003e"}],"reconciledGeneration":2,"orphanMitigationInProgress":false}}

root@ip-172-31-9-130: ~ # ETCDCTL_API=3 /usr/bin/etcdctl --cert /etc/etcd/peer.crt --key /etc/etcd/peer.key --cacert /etc/etcd/ca.crt --endpoints https://172.31.9.130:2379 get /registry/servicecatalog.k8s.io/serviceinstances/vlaad1/eap64-mysql-persistent-s2i-bh7d8
/registry/servicecatalog.k8s.io/serviceinstances/vlaad1/eap64-mysql-persistent-s2i-bh7d8

{"kind":"ServiceInstance","apiVersion":"servicecatalog.k8s.io/v1beta1","metadata":{"name":"eap64-mysql-persistent-s2i-bh7d8","generateName":"eap64-mysql-persistent-s2i-","namespace":"vlaad1","uid":"521390c4-fad5-11e7-ac61-0a58ac150002","generation":2,"creationTimestamp":"2018-01-16T15:52:57Z","deletionTimestamp":"2018-01-16T18:38:51Z","deletionGracePeriodSeconds":0,"finalizers":["kubernetes-incubator/service-catalog"]},"spec":{"clusterServiceClassExternalName":"eap64-mysql-persistent-s2i","clusterServicePlanExternalName":"default","clusterServiceClassRef":{"name":"a0475f42-face-11e7-a2a1-020813ce4ab6"},"clusterServicePlanRef":{"name":"a0475f42-face-11e7-a2a1-020813ce4ab6"},"parametersFrom":[{"secretKeyRef":{"name":"eap64-mysql-persistent-s2i-parametersr8ivv","key":"parameters"}}],"externalID":"bacee5e5-fc1c-4464-8ebf-1daf99236464","userInfo":{"username":"system:serviceaccount:kube-system:namespace-controller","uid":"","groups":["system:serviceaccounts","system:serviceaccounts:kube-system","system:authenticated"]},"updateRequests":0},"status":{"conditions":[{"type":"Ready","status":"False","lastTransitionTime":"2018-01-16T16:00:23Z","reason":"DeprovisionBlockedByExistingCredentials","message":"Delete instance failed. Delete instance blocked by existing ServiceBindings associated with this instance.  All credentials must be removed first"}],"asyncOpInProgress":false,"orphanMitigationInProgress":false,"reconciledGeneration":1,"externalProperties":{"clusterServicePlanExternalName":"default","clusterServicePlanExternalID":"a0475f42-face-11e7-a2a1-020813ce4ab6","parameters":{"APPLICATION_NAME":"\u003credacted\u003e","AUTO_DEPLOY_EXPLODED":"\u003credacted\u003e","CONTEXT_DIR":"\u003credacted\u003e","DB_DATABASE":"\u003credacted\u003e","DB_JNDI":"\u003credacted\u003e","HTTPS_KEYSTORE":"\u003credacted\u003e","HTTPS_SECRET":"\u003credacted\u003e","IMAGE_STREAM_NAMESPACE":"\u003credacted\u003e","JGROUPS_ENCRYPT_KEYSTORE":"\u003credacted\u003e","JGROUPS_ENCRYPT_SECRET":"\u003credacted\u003e","MYSQL_IMAGE_STREAM_TAG":"\u003credacted\u003e","SERVICE_ACCOUNT_NAME":"\u003credacted\u003e","SOURCE_REPOSITORY_REF":"\u003credacted\u003e","SOURCE_REPOSITORY_URL":"\u003credacted\u003e","VOLUME_CAPACITY":"\u003credacted\u003e"},"parameterChecksum":"781cd60307b9dba6c8a828d9c74849caa13f6cd472625be335f8ac729453c008","userInfo":{"username":"test","uid":"","groups":["system:authenticated:oauth","system:authenticated"],"extra":{"scopes.authorization.openshift.io":["user:full"]}}},"deprovisionStatus":"Required"}}
Version-Release number of selected component (if applicable):
openshift v3.9.0-0.20.0
kubernetes v1.9.1+a0ce1bc657
etcd 3.2.8

How reproducible:
Not happening for all the projects.

Steps to Reproduce:
1. oc new-project vlaad1
2. oc new-app --template=eap64-mysql-s2i
3. oc delete project vlaad1

Actual results:
Project stuck in terminating state

Expected results:
Project should be deleted.

Additional info:
Attaching master and compute node logs, bouncing master api and controller services also did not help.

Comment 1 Vikas Laad 2018-01-16 18:50:43 UTC
Created attachment 1382130 [details]
master and node logs

Comment 2 Mike Fiedler 2018-01-16 18:55:33 UTC
Looking at etcd after project deletion there are a couple of servicecatalog keys still hanging around.   One entry points to the error message:

Delete instance failed. Delete instance blocked by existing ServiceBindings associated with this instance.  All credentials must be removed first

The project has no secrets or serviceaccounts left.   The only entries in etcd are:

/kubernetes.io/namespaces/vlaad1
/openshift.io/registry/sdnnetnamespaces/vlaad1
/registry/servicecatalog.k8s.io/servicebindings/vlaad1/eap64-mysql-persistent-s2i-bh7d8-ftn5s
/registry/servicecatalog.k8s.io/serviceinstances/vlaad1/eap64-mysql-persistent-s2i-bh7d8


Not sure if this is the cause, but can't see anything else on the master or nodes that would be keeping the project in Terminating.

Comment 3 Jay Boyd 2018-01-25 15:25:23 UTC
Service Catalog attempts to deprovision servicebinding but gets an error 500 from templateservicebroker:

0125 15:10:45.029577       1 controller_binding.go:615] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Processing Delete
I0125 15:10:45.029610       1 controller_binding.go:1013] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Deleting Secret "jay/mysql-persistent-7mkb4-credentials-563od"
I0125 15:10:45.032910       1 controller_binding.go:1050] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Setting condition "Ready" to False
I0125 15:10:45.032970       1 controller_binding.go:1074] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Found status change for condition "Ready": "True" -> "False"; setting lastTransitionTime to 2018-01-2
5 15:10:45.032890658 +0000 UTC m=+149112.881601734
I0125 15:10:45.032981       1 controller_binding.go:1099] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Updating status
I0125 15:10:45.044388       1 controller_binding.go:729] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Going to make request to unbind
I0125 15:10:45.046616       1 controller.go:414] Creating client for ClusterServiceBroker template-service-broker, URL: https://apiserver.openshift-template-service-broker.svc:443/brokers/template.openshift.io
I0125 15:10:45.074996       1 leaderelection.go:199] successfully renewed lease kube-service-catalog/service-catalog-controller-manager
I0125 15:10:45.082844       1 client.go:206] handling failure responses
W0125 15:10:45.083277       1 controller_binding.go:830] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Error unbinding from ServiceInstance "jay/mysql-persistent-7mkb4" of ClusterServiceClass (K8S: "a62c59d0-0086-11e8-a43f-c85b76aab8ec" ExternalName: "mysql-persistent") at ClusterServiceBroker "template-service-broker": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io "913f5dab-2dae-425b-b510-ae50f40348d2" not found; ResponseError: <nil>
I0125 15:10:45.083410       1 controller_binding.go:1050] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Setting condition "Ready" to Unknown
I0125 15:10:45.083474       1 controller_binding.go:1074] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Found status change for condition "Ready": "False" -> "Unknown"; setting lastTransitionTime to 2018-01-25 15:10:45.083378298 +0000 UTC m=+149112.932089339
I0125 15:10:45.083505       1 controller_binding.go:1050] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Setting condition "Failed" to True
I0125 15:10:45.083528       1 controller_binding.go:1088] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Setting lastTransitionTime for condition "Failed" to 2018-01-25 15:10:45.08348937 +0000 UTC m=+149112.932200415
I0125 15:10:45.083541       1 controller_binding.go:1099] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Updating status
I0125 15:10:45.084000       1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceBinding", Namespace:"jay", Name:"mysql-persistent-7mkb4-88s7h", UID:"160d1070-01e1-11e8-a158-0242ac110004", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"785", FieldPath:""}): type: 'Warning' reason: 'UnbindCallFailed' Error unbinding from ServiceInstance "jay/mysql-persistent-7mkb4" of ClusterServiceClass (K8S: "a62c59d0-0086-11e8-a43f-c85b76aab8ec" ExternalName: "mysql-persistent") at ClusterServiceBroker "template-service-broker": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io "913f5dab-2dae-425b-b510-ae50f40348d2" not found; ResponseError: <nil>
E0125 15:10:45.086703       1 event.go:200] Server rejected event '&v1.Event{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"mysql-persistent-7mkb4-88s7h.150d16300a74307e", GenerateName:"", Namespace:"jay", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Initializers:(*v1.Initializers)(nil), Finalizers:[]string(nil), ClusterName:""}, InvolvedObject:v1.ObjectReference{Kind:"ServiceBinding", Namespace:"jay", Name:"mysql-persistent-7mkb4-88s7h", UID:"160d1070-01e1-11e8-a158-0242ac110004", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"785", FieldPath:""}, Reason:"UnbindCallFailed", Message:"Error unbinding from ServiceInstance \"jay/mysql-persistent-7mkb4\" of ClusterServiceClass (K8S: \"a62c59d0-0086-11e8-a43f-c85b76aab8ec\" ExternalName: \"mysql-persistent\") at ClusterServiceBroker \"template-service-broker\": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io \"913f5dab-2dae-425b-b510-ae50f40348d2\" not found; ResponseError: <nil>", Source:v1.EventSource{Component:"service-catalog-controller-manager", Host:""}, FirstTimestamp:v1.Time{Time:time.Time{wall:0xbe929abd44f7de7e, ext:149112932064258, loc:(*time.Location)(0x25da700)}}, LastTimestamp:v1.Time{Time:time.Time{wall:0xbe929abd44f7de7e, ext:149112932064258, loc:(*time.Location)(0x25da700)}}, Count:1, Type:"Warning"}': 'events "mysql-persistent-7mkb4-88s7h.150d16300a74307e" is forbidden: unable to create new content in namespace jay because it is being terminated.' (will not retry!)
I0125 15:10:45.110396       1 controller_instance.go:237] ServiceInstance "jay/mysql-persistent-7mkb4": Processing deleting event
W0125 15:10:45.110458       1 controller_instance.go:259] ServiceInstance "jay/mysql-persistent-7mkb4": Delete instance blocked by existing ServiceBindings associated with this instance.  All credentials must be removed first
I0125 15:10:45.110554       1 controller_instance.go:1778] ServiceInstance "jay/mysql-persistent-7mkb4": Setting condition "Ready" to False
I0125 15:10:45.110579       1 controller_instance.go:1803] ServiceInstance "jay/mysql-persistent-7mkb4": Found status change, condition "Ready": "True" -> "False"; setting lastTransitionTime to 2018-01-25 15:10:45.110492167 +0000 UTC m=+149112.959203217
I0125 15:10:45.110589       1 controller_instance.go:1841] ServiceInstance "jay/mysql-persistent-7mkb4": Updating status
I0125 15:10:45.111080       1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceInstance", Namespace:"jay", Name:"mysql-persistent-7mkb4", UID:"1609e6cc-01e1-11e8-a158-0242ac110004", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"784", FieldPath:""}): type: 'Warning' reason: 'DeprovisionBlockedByExistingCredentials' Delete instance blocked by existing ServiceBindings associated with this instance.  All credentials must be removed first
E0125 15:10:45.116388       1 event.go:200] Server rejected event '&v1.Event{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"mysql-persistent-7mkb4.150d16300c122800", GenerateName:"", Namespace:"jay", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Initializers:(*v1.Initializers)(nil), Finalizers:[]string(nil), ClusterName:""}, InvolvedObject:v1.ObjectReference{Kind:"ServiceInstance", Namespace:"jay", Name:"mysql-persistent-7mkb4", UID:"1609e6cc-01e1-11e8-a158-0242ac110004", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"784", FieldPath:""}, Reason:"DeprovisionBlockedByExistingCredentials", Message:"Delete instance blocked by existing ServiceBindings associated with this instance.  All credentials must be removed first", Source:v1.EventSource{Component:"service-catalog-controller-manager", Host:""}, FirstTimestamp:v1.Time{Time:time.Time{wall:0xbe929abd4695d600, ext:149112959193988, loc:(*time.Location)(0x25da700)}}, LastTimestamp:v1.Time{Time:time.Time{wall:0xbe929abd4695d600, ext:149112959193988, loc:(*time.Location)(0x25da700)}}, Count:1, Type:"Warning"}': 'events "mysql-persistent-7mkb4.150d16300c122800" is forbidden: unable to create new content in namespace jay because it is being terminated.' (will not retry!)
I0125 15:10:45.229420       1 controller_binding.go:615] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Processing Delete
I0125 15:10:45.229478       1 controller_binding.go:1013] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Deleting Secret "jay/mysql-persistent-7mkb4-credentials-563od"
I0125 15:10:45.231582       1 controller_binding.go:729] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Going to make request to unbind
0125 15:10:45.233608       1 controller.go:414] Creating client for ClusterServiceBroker template-service-broker, URL: https://apiserver.openshift-template-service-broker.svc:443/brokers/template.openshift.io
I0125 15:10:45.253700       1 client.go:206] handling failure responses
W0125 15:10:45.253787       1 controller_binding.go:830] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Error unbinding from ServiceInstance "jay/mysql-persistent-7mkb4" of ClusterServiceClass (K8S: "a62c59d0-0086-11e8-a43f-c85b76aab8ec" ExternalName: "mysql-persistent") at ClusterServiceBroker "template-service-broker": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io "913f5dab-2dae-425b-b510-ae50f40348d2" not found; ResponseError: <nil>
I0125 15:10:45.253827       1 controller_binding.go:1050] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Setting condition "Ready" to Unknown
I0125 15:10:45.253847       1 controller_binding.go:1074] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Found status change for condition "Ready": "False" -> "Unknown"; setting lastTransitionTime to 2018-01-25 15:10:45.253816582 +0000 UTC m=+149113.102527624
I0125 15:10:45.253860       1 controller_binding.go:1050] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Setting condition "Failed" to True
I0125 15:10:45.253878       1 controller_binding.go:1088] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Setting lastTransitionTime for condition "Failed" to 2018-01-25 15:10:45.25385391 +0000 UTC m=+149113.102564954
I0125 15:10:45.253901       1 controller_binding.go:1099] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Updating status
I0125 15:10:45.254025       1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceBinding", Namespace:"jay", Name:"mysql-persistent-7mkb4-88s7h", UID:"160d1070-01e1-11e8-a158-0242ac110004", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"786", FieldPath:""}): type: 'Warning' reason: 'UnbindCallFailed' Error unbinding from ServiceInstance "jay/mysql-persistent-7mkb4" of ClusterServiceClass (K8S: "a62c59d0-0086-11e8-a43f-c85b76aab8ec" ExternalName: "mysql-persistent") at ClusterServiceBroker "template-service-broker": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io "913f5dab-2dae-425b-b510-ae50f40348d2" not found; ResponseError: <nil>
E0125 15:10:45.260882       1 controller_binding.go:1102] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Error updating status: Operation cannot be fulfilled on servicebindings.servicecatalog.k8s.io "mysql-persistent-7mkb4-88s7h": the object has been modified; please apply your changes to the latest version and try again
I0125 15:10:45.260901       1 controller.go:237] Error syncing ServiceBinding jay/mysql-persistent-7mkb4-88s7h: Operation cannot be fulfilled on servicebindings.servicecatalog.k8s.io "mysql-persistent-7mkb4-88s7h": the object has been modified; please apply your changes to the latest version and try again
I0125 15:10:45.260931       1 controller_binding.go:615] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Processing Delete
I0125 15:10:45.260947       1 controller_binding.go:625] ServiceBinding "jay/mysql-persistent-7mkb4-88s7h": Not processing delete event because unbinding has failed


The first unbind attempt gets an error 500 from the template service broker and does not re-attempt to unbind.  This upstream PR https://github.com/kubernetes-incubator/service-catalog/pull/1653  will make Service Catalog re-attempt, this may fix the issue.  Need new Service Catalog vendoring into OpenShift.

Comment 4 Jay Boyd 2018-02-06 14:20:58 UTC
Still an issue even when testing with Service Catalog v0.1.5 revendoring.   After project is deleted, we see this in controller logs:

Template Service Broker returning an error 500 saying that the binding isn't found:
I0206 13:56:22.318447       1 controller_binding.go:579] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Updating status
I0206 13:56:22.390935       1 controller_binding.go:183] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Not processing event; reconciled generation showed there is no work to do



I0206 13:59:36.592234       1 controller_binding.go:315] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Processing Delete
I0206 13:59:36.592270       1 controller_binding.go:492] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Deleting Secret "jaysproject/mysql-persistent-xn76t-credentials-g9jxv"
I0206 13:59:36.679626       1 controller_binding.go:529] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Unbind request for ServiceBinding in-flight to Broker
I0206 13:59:36.679643       1 controller_binding.go:530] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Setting condition "Ready" to False
I0206 13:59:36.679659       1 controller_binding.go:554] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Found status change for condition "Ready": "True" -> "False"; setting lastTransitionTime to 2018-02-06 13:59:36.67961451 +0000 UTC m=+57429.464524092
I0206 13:59:36.679668       1 controller_binding.go:579] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Updating status


I0206 13:59:37.025270       1 controller_binding.go:529] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Error unbinding from ServiceInstance "jaysproject/mysql-persistent-xn76t" of ClusterServiceClass (K8S: "314d11a2-0ac0-11e8-b588-c85b76aab8ec" ExternalName: "mysql-persistent") at ClusterServiceBroker "template-service-broker": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io "20d38435-2514-4b8e-ba71-b9081d7cf5c0" not found; ResponseError: <nil>


I0206 13:59:37.025293       1 controller_binding.go:530] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Setting condition "Ready" to Unknown
I0206 13:59:37.025313       1 controller_binding.go:554] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Found status change for condition "Ready": "False" -> "Unknown"; setting lastTransitionTime to 2018-02-06 13:59:37.025255622 +0000 UTC m=+57429.810165211
I0206 13:59:37.025323       1 controller_binding.go:579] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Updating status
I0206 13:59:37.037200       1 controller_binding.go:315] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Processing Delete
I0206 13:59:37.037236       1 controller_binding.go:492] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Deleting Secret "jaysproject/mysql-persistent-xn76t-credentials-g9jxv"
I0206 13:59:37.059678       1 controller_binding.go:529] ServiceBinding "jaysproject/mysql-persistent-xn76t-4rlrz": Error unbinding from ServiceInstance "jaysproject/mysql-persistent-xn76t" of ClusterServiceClass (K8S: "314d11a2-0ac0-11e8-b588-c85b76aab8ec" ExternalName: "mysql-persistent") at ClusterServiceBroker "template-service-broker": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io "20d38435-2514-4b8e-ba71-b9081d7cf5c0" not found; ResponseError: <nil>


Looks like an issue with TSB, still investigating.

Comment 5 Jay Boyd 2018-02-06 21:20:30 UTC
Re-assigning to Template Service Broker team.

Quick reproduce details:  create a MySql app from the Template Service Broker and check the box to have a binding created for you.   Once successfully created, delete the project.

Service Catalog will send requests to delete the binding.  TSB responds with an error 500:

I0206 21:01:14.767916       1 controller.go:401] Creating client for ClusterServiceBroker template-service-broker, URL: https://apiserver.openshift-template-service-broker.svc:443/brokers/template.openshift.io
I0206 21:01:14.800161       1 client.go:206] handling failure responses
I0206 21:01:14.800312       1 controller_binding.go:529] ServiceBinding "my-project/mysql-persistent-knt8v-cvdqp": Error unbinding from ServiceInstance "my-project/mysql-persistent-knt8v" of ClusterServiceClass (K8S: "2590e643-0b80-11e8-ae6f-c85b76aab8ec" ExternalName: "mysql-persistent") at ClusterServiceBroker "template-service-broker": Status: 500; ErrorMessage: <nil>; Description: templateinstances.template.openshift.io "5e00907c-cd39-4de6-a878-c417ded8c1e9" not found; ResponseError: <nil>


According to the spec brokers should return a 200, 400 or 410 (I'd expect a 410 given the text returned from TSB).


Catalog believes the delete request failed at the broker and will keep retrying.

Comment 6 Ben Parees 2018-02-06 21:22:52 UTC
effectively a dupe of 1540819, will be resolved by https://github.com/openshift/origin/pull/18416

*** This bug has been marked as a duplicate of bug 1540819 ***

Comment 7 Jay Boyd 2018-02-06 21:25:41 UTC
Created attachment 1392371 [details]
Service Catalog Controller log file

attached logs are from Service Catalog Controller and Template Service Broker.  Failure to delete first occurs at 21:01:14 (in controller log search for "unbind")


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