Bug 1500930
| Summary: | Deleting 1 APB service instance triggers 4 deprovision pods inside of 4 temporary namespaces | ||
|---|---|---|---|
| Product: | OpenShift Container Platform | Reporter: | Derek Whatley <dwhatley> |
| Component: | Service Broker | Assignee: | Erik Nelson <ernelson> |
| Status: | CLOSED ERRATA | QA Contact: | Qixuan Wang <qixuan.wang> |
| Severity: | high | Docs Contact: | |
| Priority: | medium | ||
| Version: | 3.7.0 | CC: | aos-bugs, chezhang, dymurray, jmatthew, qixuan.wang, wmeng |
| Target Milestone: | --- | ||
| Target Release: | 3.7.0 | ||
| Hardware: | x86_64 | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2017-11-28 22:16:24 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
Just did another test with this and saw 3 deprovision pods spin up instead of 4. Makes me think it could be a timing-specific bug. Can confirm I'm seeing the same thing deprovisioning Mediawiki. Tested on OCP (openshift v3.7.0-0.158.0, kubernetes v1.7.6+a08f5eeb62, etcd 3.2.8), now when deprovision a ServiceInstance, only one temporary namespace generates, so the bug has been fixed, thanks. Here is the result: [root@preserve-qw-master-etcd-1 ~]# oc delete serviceinstance dh-mediawiki123-apb-kqrf7 -n qwang2; oc get project -w serviceinstance "dh-mediawiki123-apb-kqrf7" deleted NAME DISPLAY NAME STATUS ansible-service-broker Active default Active dh-mediawiki123-apb-depr-rs0f5 Active kube-public Active kube-service-catalog Active kube-system Active logging Active openshift Active openshift-infra Active openshift-node Active qwang1 Active qwang2 Active dh-mediawiki123-apb-depr-rs0f5 Active dh-mediawiki123-apb-depr-rs0f5 Terminating dh-mediawiki123-apb-depr-rs0f5 [root@preserve-qw-master-etcd-1 ~]# oc logs po/asb-1-m3vc7 -c asb -n ansible-service-broker [2017-10-23T03:27:48.09Z] [INFO] ASYNC deprovision in progress [2017-10-23T03:27:48.09Z] [NOTICE] ============================================================ [2017-10-23T03:27:48.09Z] [NOTICE] DEPROVISIONING [2017-10-23T03:27:48.09Z] [NOTICE] ============================================================ [2017-10-23T03:27:48.09Z] [NOTICE] ServiceInstance.Id: 268dbc13f56297fdd3737b7d30104eb4 [2017-10-23T03:27:48.09Z] [NOTICE] ServiceInstance.Name: dh-mediawiki123-apb [2017-10-23T03:27:48.09Z] [NOTICE] ServiceInstance.Image: docker.io/ansibleplaybookbundle/mediawiki123-apb:latest [2017-10-23T03:27:48.09Z] [NOTICE] ServiceInstance.Description: Mediawiki123 apb implementation [2017-10-23T03:27:48.09Z] [NOTICE] ============================================================ [2017-10-23T03:27:48.091Z] [DEBUG] ExecutingApb: [2017-10-23T03:27:48.091Z] [DEBUG] name:[ dh-mediawiki123-apb ] [2017-10-23T03:27:48.091Z] [DEBUG] image:[ docker.io/ansibleplaybookbundle/mediawiki123-apb:latest ] [2017-10-23T03:27:48.091Z] [DEBUG] action:[ deprovision ] [2017-10-23T03:27:48.091Z] [DEBUG] pullPolciy:[ IfNotPresent ] [2017-10-23T03:27:48.091Z] [DEBUG] role:[ edit ] 10.128.0.1 - - [23/Oct/2017:03:27:48 +0000] "DELETE /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9?accepts_incomplete=true&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 202 58 [2017-10-23T03:27:48.133Z] [DEBUG] Creating resource file dir: /tmp/asb-resource-files [2017-10-23T03:27:48.223Z] [DEBUG] Creating resource file /tmp/asb-resource-files/apb-ba6a4637-d37a-448e-8bd2-c74445154828.yaml [2017-10-23T03:27:48.224Z] [INFO] Successfully wrote resources to /tmp/asb-resource-files/apb-ba6a4637-d37a-448e-8bd2-c74445154828.yaml [2017-10-23T03:27:48.224Z] [DEBUG] Trying to create apb sandbox: [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ], with edit permissions in namespace dh-mediawiki123-apb-depr-rs0f5 [2017-10-23T03:27:48.224Z] [DEBUG] Creating resources from file at path: /tmp/asb-resource-files/apb-ba6a4637-d37a-448e-8bd2-c74445154828.yaml [2017-10-23T03:27:48.306Z] [DEBUG] Unable to find originating origin header [2017-10-23T03:27:48.306Z] [INFO] Request: "DELETE /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9?accepts_incomplete=true&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1\r\nHost: asb.ansible-service-broker.svc:1338\r\nAccept-Encoding: gzip\r\nUser-Agent: Go-http-client/1.1\r\nX-Broker-Api-Version: 2.12\r\n\r\n" [2017-10-23T03:27:48.309Z] [DEBUG] Auto Escalate has been set to true, we are escalating permissions [2017-10-23T03:27:48.309Z] [DEBUG] Dao::GetSvcInstJobsByState [2017-10-23T03:27:48.309Z] [DEBUG] Dao::getJobsForSvcInst [2017-10-23T03:27:48.314Z] [DEBUG] Successfully loaded [ 2 ] jobs objects from [ /state/eca5a2b3-de5b-44d2-a997-330cdd3987e9/job ] [2017-10-23T03:27:48.314Z] [DEBUG] Filtered on state: [ %!s(int=1) ], returning %!d(MISSING) jobs [2017-10-23T03:27:48.314Z] [INFO] Deprovision requested for instance eca5a2b3-de5b-44d2-a997-330cdd3987e9, but job is already in progress 10.128.0.1 - - [23/Oct/2017:03:27:48 +0000] "DELETE /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9?accepts_incomplete=true&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 202 3 [2017-10-23T03:27:48.563Z] [DEBUG] Unable to find originating origin header [2017-10-23T03:27:48.564Z] [INFO] Request: "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1\r\nHost: asb.ansible-service-broker.svc:1338\r\nAccept-Encoding: gzip\r\nUser-Agent: Go-http-client/1.1\r\nX-Broker-Api-Version: 2.12\r\n\r\n" [2017-10-23T03:27:48.564Z] [DEBUG] service_id: 268dbc13f56297fdd3737b7d30104eb4 [2017-10-23T03:27:48.564Z] [DEBUG] plan_id: c54bf88ce67b96a39e639d2bdf6caf1a [2017-10-23T03:27:48.564Z] [DEBUG] operation: eb5ce158-b3fd-4c79-8264-15fb7ee62d06 10.128.0.1 - - [23/Oct/2017:03:27:48 +0000] "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 200 29 [2017-10-23T03:27:49.081Z] [DEBUG] Successfully created resources, oc create -f output: [2017-10-23T03:27:49.081Z] [DEBUG] serviceaccount "apb-ba6a4637-d37a-448e-8bd2-c74445154828" created rolebinding "apb-ba6a4637-d37a-448e-8bd2-c74445154828" created rolebinding "apb-ba6a4637-d37a-448e-8bd2-c74445154828" created [2017-10-23T03:27:49.081Z] [INFO] Successfully created apb sandbox: [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ], with edit permissions in namespace dh-mediawiki123-apb-depr-rs0f5 [2017-10-23T03:27:49.081Z] [NOTICE] Creating pod "apb-ba6a4637-d37a-448e-8bd2-c74445154828" in the dh-mediawiki123-apb-depr-rs0f5 namespace [2017-10-23T03:27:49.092Z] [DEBUG] Watching pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] in namespace [ dh-mediawiki123-apb-depr-rs0f5 ] for completion [2017-10-23T03:27:49.092Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 1 [2017-10-23T03:27:49.187Z] [DEBUG] Unable to find originating origin header [2017-10-23T03:27:49.187Z] [INFO] Request: "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1\r\nHost: asb.ansible-service-broker.svc:1338\r\nAccept-Encoding: gzip\r\nUser-Agent: Go-http-client/1.1\r\nX-Broker-Api-Version: 2.12\r\n\r\n" [2017-10-23T03:27:49.187Z] [DEBUG] service_id: 268dbc13f56297fdd3737b7d30104eb4 [2017-10-23T03:27:49.187Z] [DEBUG] plan_id: c54bf88ce67b96a39e639d2bdf6caf1a [2017-10-23T03:27:49.187Z] [DEBUG] operation: eb5ce158-b3fd-4c79-8264-15fb7ee62d06 10.128.0.1 - - [23/Oct/2017:03:27:49 +0000] "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 200 29 [2017-10-23T03:27:49.341Z] [INFO] Pod completion not found, continuing to watch [2017-10-23T03:27:49.341Z] [INFO] apb-ba6a4637-d37a-448e-8bd2-c74445154828 0/1 ContainerCreating 0 0s [2017-10-23T03:27:53.235Z] [DEBUG] Unable to find originating origin header [2017-10-23T03:27:53.235Z] [INFO] Request: "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1\r\nHost: asb.ansible-service-broker.svc:1338\r\nAccept-Encoding: gzip\r\nUser-Agent: Go-http-client/1.1\r\nX-Broker-Api-Version: 2.12\r\n\r\n" [2017-10-23T03:27:53.235Z] [DEBUG] service_id: 268dbc13f56297fdd3737b7d30104eb4 [2017-10-23T03:27:53.235Z] [DEBUG] plan_id: c54bf88ce67b96a39e639d2bdf6caf1a [2017-10-23T03:27:53.235Z] [DEBUG] operation: eb5ce158-b3fd-4c79-8264-15fb7ee62d06 10.128.0.1 - - [23/Oct/2017:03:27:53 +0000] "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 200 29 [2017-10-23T03:27:54.341Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 2 [2017-10-23T03:27:54.588Z] [INFO] Pod apb-ba6a4637-d37a-448e-8bd2-c74445154828 still running, continuing to watch [2017-10-23T03:27:59.59Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 3 [2017-10-23T03:27:59.904Z] [INFO] Pod apb-ba6a4637-d37a-448e-8bd2-c74445154828 still running, continuing to watch [2017-10-23T03:28:01.265Z] [DEBUG] Unable to find originating origin header [2017-10-23T03:28:01.265Z] [INFO] Request: "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1\r\nHost: asb.ansible-service-broker.svc:1338\r\nAccept-Encoding: gzip\r\nUser-Agent: Go-http-client/1.1\r\nX-Broker-Api-Version: 2.12\r\n\r\n" [2017-10-23T03:28:01.265Z] [DEBUG] service_id: 268dbc13f56297fdd3737b7d30104eb4 [2017-10-23T03:28:01.265Z] [DEBUG] plan_id: c54bf88ce67b96a39e639d2bdf6caf1a [2017-10-23T03:28:01.265Z] [DEBUG] operation: eb5ce158-b3fd-4c79-8264-15fb7ee62d06 10.128.0.1 - - [23/Oct/2017:03:28:01 +0000] "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 200 29 [2017-10-23T03:28:04.904Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 4 [2017-10-23T03:28:05.355Z] [INFO] Pod apb-ba6a4637-d37a-448e-8bd2-c74445154828 still running, continuing to watch [2017-10-23T03:28:10.356Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 5 [2017-10-23T03:28:10.609Z] [INFO] Pod apb-ba6a4637-d37a-448e-8bd2-c74445154828 still running, continuing to watch [2017-10-23T03:28:15.609Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 6 [2017-10-23T03:28:15.828Z] [INFO] Pod apb-ba6a4637-d37a-448e-8bd2-c74445154828 still running, continuing to watch [2017-10-23T03:28:17.285Z] [DEBUG] Unable to find originating origin header [2017-10-23T03:28:17.285Z] [INFO] Request: "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1\r\nHost: asb.ansible-service-broker.svc:1338\r\nAccept-Encoding: gzip\r\nUser-Agent: Go-http-client/1.1\r\nX-Broker-Api-Version: 2.12\r\n\r\n" [2017-10-23T03:28:17.285Z] [DEBUG] service_id: 268dbc13f56297fdd3737b7d30104eb4 [2017-10-23T03:28:17.285Z] [DEBUG] plan_id: c54bf88ce67b96a39e639d2bdf6caf1a [2017-10-23T03:28:17.285Z] [DEBUG] operation: eb5ce158-b3fd-4c79-8264-15fb7ee62d06 10.128.0.1 - - [23/Oct/2017:03:28:17 +0000] "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 200 29 [2017-10-23T03:28:20.843Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 7 [2017-10-23T03:28:21.068Z] [INFO] Pod apb-ba6a4637-d37a-448e-8bd2-c74445154828 still running, continuing to watch [2017-10-23T03:28:26.069Z] [INFO] Watch pod [ apb-ba6a4637-d37a-448e-8bd2-c74445154828 ] tick 8 [2017-10-23T03:28:26.286Z] [INFO] Destroying APB sandbox... [2017-10-23T03:28:26.288Z] [DEBUG] Deleting namespace dh-mediawiki123-apb-depr-rs0f5 [2017-10-23T03:28:26.292Z] [DEBUG] Deleting rolebinding apb-ba6a4637-d37a-448e-8bd2-c74445154828, namespace dh-mediawiki123-apb-depr-rs0f5 [2017-10-23T03:28:26.551Z] [DEBUG] Successfully deleted rolebinding apb-ba6a4637-d37a-448e-8bd2-c74445154828, namespace dh-mediawiki123-apb-depr-rs0f5 [2017-10-23T03:28:26.551Z] [DEBUG] oc delete output: [2017-10-23T03:28:26.551Z] [DEBUG] rolebinding "apb-ba6a4637-d37a-448e-8bd2-c74445154828" deleted [2017-10-23T03:28:26.551Z] [DEBUG] Deleting rolebinding apb-ba6a4637-d37a-448e-8bd2-c74445154828, namespace qwang2 [2017-10-23T03:28:26.811Z] [DEBUG] Successfully deleted rolebinding apb-ba6a4637-d37a-448e-8bd2-c74445154828, namespace qwang2 [2017-10-23T03:28:26.812Z] [DEBUG] oc delete output: [2017-10-23T03:28:26.812Z] [DEBUG] rolebinding "apb-ba6a4637-d37a-448e-8bd2-c74445154828" deleted [2017-10-23T03:28:26.826Z] [DEBUG] sending deprovision complete msg to channel [2017-10-23T03:28:26.826Z] [DEBUG] Processed deprovision message from buffer [2017-10-23T03:28:26.841Z] [DEBUG] Dao::DeleteServiceInstance -> [ eca5a2b3-de5b-44d2-a997-330cdd3987e9 ] [2017-10-23T03:28:49.309Z] [DEBUG] Unable to find originating origin header [2017-10-23T03:28:49.309Z] [INFO] Request: "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1\r\nHost: asb.ansible-service-broker.svc:1338\r\nAccept-Encoding: gzip\r\nUser-Agent: Go-http-client/1.1\r\nX-Broker-Api-Version: 2.12\r\n\r\n" [2017-10-23T03:28:49.309Z] [DEBUG] service_id: 268dbc13f56297fdd3737b7d30104eb4 [2017-10-23T03:28:49.309Z] [DEBUG] plan_id: c54bf88ce67b96a39e639d2bdf6caf1a [2017-10-23T03:28:49.31Z] [DEBUG] operation: eb5ce158-b3fd-4c79-8264-15fb7ee62d06 10.128.0.1 - - [23/Oct/2017:03:28:49 +0000] "GET /ansible-service-broker/v2/service_instances/eca5a2b3-de5b-44d2-a997-330cdd3987e9/last_operation?operation=eb5ce158-b3fd-4c79-8264-15fb7ee62d06&plan_id=c54bf88ce67b96a39e639d2bdf6caf1a&service_id=268dbc13f56297fdd3737b7d30104eb4 HTTP/1.1" 200 27 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 |
============================================================= Description of problem ============================================================= After successfully provisioning an SNS APB, I clicked "Delete" on the SNS APB service instance from the OpenShift Web UI and noticed that 4 temporary namespaces had been created, each containing an SNS APB deprovision pod. In my testing, deleting a service instance always resulted in exactly 4 deprovision pods being spawned. If you look closely at the logs below, you'll notice that ASB receives 4 separate "delete" calls from the service-catalog, all with the same "service_id". Instead of acting upon one call and disregarding the rest, all calls are acted upon. 172.17.0.5 - - [11/Oct/2017:18:25:16 +0000] "DELETE /ansible-service-broker/v2/service_instances/9b5908cf-dcd3-405d-87fc-3ae63bbe5e5d?accepts_incomplete=true&plan_id=topicwithsub&service_id=ab883cebb0a87311150230384078477c HTTP/1.1" 200 58 (Additional logs included at bottom of BZ) ============================================================= How reproducible ============================================================= Has happened every time I delete an SNS service instance on the asb:canary and openshift:latest. Clicking delete on a single service instance consistently results in 4 pods / 4 namespaces. Doesn't matter how many APBs have been deployed, or how many service instances currently exist. ============================================================= Steps to Reproduce ============================================================= 1. Run catasb with canary broker, latest openshift 2. Provision an APB (used SNS in this example) 3. Wait for APB provision to complete and for service to be marked as "Ready" 4. Delete service instance 5. Watch how many new namespaces appear 6. Observe how many messages service-catalog sends to ansible-service-broker in while reconciling desired state. ============================================================= Actual results ============================================================= When I click delete on a single service instance, 4 deprovision pods spin up to complete the action on behalf of the controller-manager. ============================================================= Expected results ============================================================= When I click delete on a single service instance, 1 deprovision pod spins up to complete the action despite the controller-manager sending messages requesting the action multiple times. ******************************************************** ******************************************************** ansible-service-broker - relevant logs ******************************************************** ******************************************************** ===================== 172.17.0.5 - - [11/Oct/2017:18:25:03 +0000] "GET /ansible-service-broker/v2/catalog HTTP/1.1" 200 13732 [2017-10-11T18:25:16.885Z] [DEBUG] Auto Escalate has been set to true, we are escalating permissions [2017-10-11T18:25:16.885Z] [INFO] ASYNC deprovision in progress [2017-10-11T18:25:16.885Z] [NOTICE] ============================================================ [2017-10-11T18:25:16.885Z] [NOTICE] DEPROVISIONING [2017-10-11T18:25:16.885Z] [NOTICE] ============================================================ [2017-10-11T18:25:16.885Z] [NOTICE] ServiceInstance.Id: ab883cebb0a87311150230384078477c [2017-10-11T18:25:16.885Z] [NOTICE] ServiceInstance.Name: apb-push-sns-apb [2017-10-11T18:25:16.885Z] [NOTICE] ServiceInstance.Image: sns-apb [2017-10-11T18:25:16.886Z] [NOTICE] ServiceInstance.Description: Managed sns topic [2017-10-11T18:25:16.886Z] [NOTICE] ============================================================ [2017-10-11T18:25:16.886Z] [DEBUG] ExecutingApb: [2017-10-11T18:25:16.886Z] [DEBUG] name:[ apb-push-sns-apb ] [2017-10-11T18:25:16.886Z] [DEBUG] image:[ sns-apb ] [2017-10-11T18:25:16.886Z] [DEBUG] action:[ deprovision ] [2017-10-11T18:25:16.886Z] [DEBUG] pullPolciy:[ IfNotPresent ] [2017-10-11T18:25:16.886Z] [DEBUG] role:[ edit ] 172.17.0.5 - - [11/Oct/2017:18:25:16 +0000] "DELETE /ansible-service-broker/v2/service_instances/9b5908cf-dcd3-405d-87fc-3ae63bbe5e5d?accepts_incomplete=true&plan_id=topicwithsub&service_id=ab883cebb0a87311150230384078477c HTTP/1.1" 200 58 [2017-10-11T18:25:16.936Z] [DEBUG] Creating resource file dir: /tmp/asb-resource-files [2017-10-11T18:25:16.937Z] [DEBUG] Creating resource file /tmp/asb-resource-files/apb-8f0e2b93-d3fc-4c2d-8d69-030be8c67c25.yaml [2017-10-11T18:25:16.937Z] [INFO] Successfully wrote resources to /tmp/asb-resource-files/apb-8f0e2b93-d3fc-4c2d-8d69-030be8c67c25.yaml [2017-10-11T18:25:16.937Z] [DEBUG] Trying to create apb sandbox: [ apb-8f0e2b93-d3fc-4c2d-8d69-030be8c67c25 ], with edit permissions in namespace c25d31df-d14e-4029-a984-4a58b502b06f [2017-10-11T18:25:16.937Z] [DEBUG] Creating resources from file at path: /tmp/asb-resource-files/apb-8f0e2b93-d3fc-4c2d-8d69-030be8c67c25.yaml [2017-10-11T18:25:16.95Z] [DEBUG] Auto Escalate has been set to true, we are escalating permissions [2017-10-11T18:25:16.951Z] [INFO] ASYNC deprovision in progress [2017-10-11T18:25:16.951Z] [NOTICE] ============================================================ [2017-10-11T18:25:16.951Z] [NOTICE] DEPROVISIONING [2017-10-11T18:25:16.951Z] [NOTICE] ============================================================ [2017-10-11T18:25:16.951Z] [NOTICE] ServiceInstance.Id: ab883cebb0a87311150230384078477c [2017-10-11T18:25:16.951Z] [NOTICE] ServiceInstance.Name: apb-push-sns-apb [2017-10-11T18:25:16.951Z] [NOTICE] ServiceInstance.Image: sns-apb [2017-10-11T18:25:16.951Z] [NOTICE] ServiceInstance.Description: Managed sns topic [2017-10-11T18:25:16.951Z] [NOTICE] ============================================================ [2017-10-11T18:25:16.951Z] [DEBUG] ExecutingApb: [2017-10-11T18:25:16.951Z] [DEBUG] name:[ apb-push-sns-apb ] [2017-10-11T18:25:16.951Z] [DEBUG] image:[ sns-apb ] [2017-10-11T18:25:16.951Z] [DEBUG] action:[ deprovision ] [2017-10-11T18:25:16.951Z] [DEBUG] pullPolciy:[ IfNotPresent ] [2017-10-11T18:25:16.951Z] [DEBUG] role:[ edit ] 172.17.0.5 - - [11/Oct/2017:18:25:16 +0000] "DELETE /ansible-service-broker/v2/service_instances/9b5908cf-dcd3-405d-87fc-3ae63bbe5e5d?accepts_incomplete=true&plan_id=topicwithsub&service_id=ab883cebb0a87311150230384078477c HTTP/1.1" 200 58 [2017-10-11T18:25:16.983Z] [DEBUG] Creating resource file dir: /tmp/asb-resource-files [2017-10-11T18:25:16.983Z] [DEBUG] Creating resource file /tmp/asb-resource-files/apb-63f749ed-c4a2-4c03-83dc-915e9131977a.yaml [2017-10-11T18:25:16.984Z] [INFO] Successfully wrote resources to /tmp/asb-resource-files/apb-63f749ed-c4a2-4c03-83dc-915e9131977a.yaml [2017-10-11T18:25:16.984Z] [DEBUG] Trying to create apb sandbox: [ apb-63f749ed-c4a2-4c03-83dc-915e9131977a ], with edit permissions in namespace fdad61d5-e936-453e-9f37-af76b94e5327 [2017-10-11T18:25:16.984Z] [DEBUG] Creating resources from file at path: /tmp/asb-resource-files/apb-63f749ed-c4a2-4c03-83dc-915e9131977a.yaml [2017-10-11T18:25:17.011Z] [DEBUG] Auto Escalate has been set to true, we are escalating permissions [2017-10-11T18:25:17.011Z] [INFO] ASYNC deprovision in progress [2017-10-11T18:25:17.011Z] [NOTICE] ============================================================ [2017-10-11T18:25:17.011Z] [NOTICE] DEPROVISIONING [2017-10-11T18:25:17.011Z] [NOTICE] ============================================================ [2017-10-11T18:25:17.011Z] [NOTICE] ServiceInstance.Id: ab883cebb0a87311150230384078477c [2017-10-11T18:25:17.011Z] [NOTICE] ServiceInstance.Name: apb-push-sns-apb [2017-10-11T18:25:17.011Z] [NOTICE] ServiceInstance.Image: sns-apb [2017-10-11T18:25:17.011Z] [NOTICE] ServiceInstance.Description: Managed sns topic [2017-10-11T18:25:17.011Z] [NOTICE] ============================================================ [2017-10-11T18:25:17.011Z] [DEBUG] ExecutingApb: [2017-10-11T18:25:17.011Z] [DEBUG] name:[ apb-push-sns-apb ] [2017-10-11T18:25:17.012Z] [DEBUG] image:[ sns-apb ] [2017-10-11T18:25:17.012Z] [DEBUG] action:[ deprovision ] [2017-10-11T18:25:17.012Z] [DEBUG] pullPolciy:[ IfNotPresent ] [2017-10-11T18:25:17.012Z] [DEBUG] role:[ edit ] 172.17.0.5 - - [11/Oct/2017:18:25:17 +0000] "DELETE /ansible-service-broker/v2/service_instances/9b5908cf-dcd3-405d-87fc-3ae63bbe5e5d?accepts_incomplete=true&plan_id=topicwithsub&service_id=ab883cebb0a87311150230384078477c HTTP/1.1" 200 58 [2017-10-11T18:25:17.029Z] [DEBUG] Creating resource file dir: /tmp/asb-resource-files [2017-10-11T18:25:17.029Z] [DEBUG] Creating resource file /tmp/asb-resource-files/apb-c6c26f46-5840-4e90-a82f-351063b80ec9.yaml [2017-10-11T18:25:17.029Z] [INFO] Successfully wrote resources to /tmp/asb-resource-files/apb-c6c26f46-5840-4e90-a82f-351063b80ec9.yaml [2017-10-11T18:25:17.029Z] [DEBUG] Trying to create apb sandbox: [ apb-c6c26f46-5840-4e90-a82f-351063b80ec9 ], with edit permissions in namespace cdfc5e23-d3a1-42e5-a47e-0f060e89b7bf [2017-10-11T18:25:17.029Z] [DEBUG] Creating resources from file at path: /tmp/asb-resource-files/apb-c6c26f46-5840-4e90-a82f-351063b80ec9.yaml [2017-10-11T18:25:17.103Z] [DEBUG] Auto Escalate has been set to true, we are escalating permissions [2017-10-11T18:25:17.103Z] [INFO] ASYNC deprovision in progress [2017-10-11T18:25:17.103Z] [NOTICE] ============================================================ [2017-10-11T18:25:17.103Z] [NOTICE] DEPROVISIONING [2017-10-11T18:25:17.103Z] [NOTICE] ============================================================ [2017-10-11T18:25:17.103Z] [NOTICE] ServiceInstance.Id: ab883cebb0a87311150230384078477c [2017-10-11T18:25:17.103Z] [NOTICE] ServiceInstance.Name: apb-push-sns-apb [2017-10-11T18:25:17.103Z] [NOTICE] ServiceInstance.Image: sns-apb [2017-10-11T18:25:17.103Z] [NOTICE] ServiceInstance.Description: Managed sns topic [2017-10-11T18:25:17.103Z] [NOTICE] ============================================================ [2017-10-11T18:25:17.103Z] [DEBUG] ExecutingApb: [2017-10-11T18:25:17.104Z] [DEBUG] name:[ apb-push-sns-apb ] [2017-10-11T18:25:17.104Z] [DEBUG] image:[ sns-apb ] [2017-10-11T18:25:17.104Z] [DEBUG] action:[ deprovision ] [2017-10-11T18:25:17.104Z] [DEBUG] pullPolciy:[ IfNotPresent ] [2017-10-11T18:25:17.104Z] [DEBUG] role:[ edit ] 172.17.0.5 - - [11/Oct/2017:18:25:17 +0000] "DELETE /ansible-service-broker/v2/service_instances/9b5908cf-dcd3-405d-87fc-3ae63bbe5e5d?accepts_incomplete=true&plan_id=topicwithsub&service_id=ab883cebb0a87311150230384078477c HTTP/1.1" 200 58 ******************************************************** ******************************************************** controller-manager - relevant logs ******************************************************** ******************************************************** I1011 18:27:19.842516 1 controller_instance.go:1347] Setting ServiceInstance "sns7/apb-push-sns-apb-q316z" condition "Ready" to False I1011 18:27:19.842550 1 controller_instance.go:1366] Found status change for ServiceInstance "sns7/apb-push-sns-apb-q316z" condition "Ready": "True" -> "False"; setting lastTransitionTime to 2017-10-11 18:27:19.842509226 +0000 UTC I1011 18:27:19.842716 1 controller_instance.go:1397] Updating status for ServiceInstance sns7/apb-push-sns-apb-q316z I1011 18:27:19.860277 1 controller_instance.go:293] Deprovisioning ServiceInstance sns7/apb-push-sns-apb-q316z of ServiceClass ab883cebb0a87311150230384078477c at ServiceBroker ansible-service-broker I1011 18:27:19.877416 1 controller_instance.go:414] Deprovision call to broker succeeded for ServiceInstance sns7/apb-push-sns-apb-q316z, finalizing I1011 18:27:19.877461 1 controller_instance.go:1347] Setting ServiceInstance "sns7/apb-push-sns-apb-q316z" condition "Ready" to False I1011 18:27:19.877488 1 controller_instance.go:1397] Updating status for ServiceInstance sns7/apb-push-sns-apb-q316z I1011 18:27:19.885033 1 controller_instance.go:438] Successfully deprovisioned ServiceInstance sns7/apb-push-sns-apb-q316z of ServiceClass ab883cebb0a87311150230384078477c at ServiceBroker ansible-service-broker I1011 18:27:19.885108 1 event.go:218] Event(v1.ObjectReference{Kind:"ServiceInstance", Namespace:"sns7", Name:"apb-push-sns-apb-q316z", UID:"a897acd5-aeb1-11e7-8d64-0242ac110006", APIVersion:"servicecatalog.k8s.io", ResourceVersion:"151", FieldPath:""}): type: 'Normal' reason: 'DeprovisionedSuccessfully' The instance was deprovisioned successfully I1011 18:27:19.903429 1 controller.go:312] Creating client for ServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ I1011 18:27:19.903950 1 controller_instance.go:293] Deprovisioning ServiceInstance sns7/apb-push-sns-apb-q316z of ServiceClass ab883cebb0a87311150230384078477c at ServiceBroker ansible-service-broker I1011 18:27:19.915965 1 controller_instance.go:414] Deprovision call to broker succeeded for ServiceInstance sns7/apb-push-sns-apb-q316z, finalizing I1011 18:27:19.915992 1 controller_instance.go:1347] Setting ServiceInstance "sns7/apb-push-sns-apb-q316z" condition "Ready" to False I1011 18:27:19.916011 1 controller_instance.go:1397] Updating status for ServiceInstance sns7/apb-push-sns-apb-q316z E1011 18:27:19.920567 1 controller_instance.go:1400] Failed to update status for ServiceInstance sns7/apb-push-sns-apb-q316z: Operation cannot be fulfilled on serviceinstances "apb-push-sns-apb-q316z": StorageError: invalid object, Code: 4, Key: /k8s.io/service-catalog/serviceinstances/sns7/apb-push-sns-apb-q316z, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: a897acd5-aeb1-11e7-8d64-0242ac110006, UID in object meta: I1011 18:27:19.920596 1 controller.go:232] Error syncing ServiceInstance sns7/apb-push-sns-apb-q316z: Operation cannot be fulfilled on serviceinstances "apb-push-sns-apb-q316z": StorageError: invalid object, Code: 4, Key: /k8s.io/service-catalog/serviceinstances/sns7/apb-push-sns-apb-q316z, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: a897acd5-aeb1-11e7-8d64-0242ac110006, UID in object meta: I1011 18:27:19.959789 1 controller.go:312] Creating client for ServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ I1011 18:27:19.961412 1 controller_instance.go:293] Deprovisioning ServiceInstance sns7/apb-push-sns-apb-q316z of ServiceClass ab883cebb0a87311150230384078477c at ServiceBroker ansible-service-broker I1011 18:27:19.971830 1 controller_instance.go:414] Deprovision call to broker succeeded for ServiceInstance sns7/apb-push-sns-apb-q316z, finalizing I1011 18:27:19.971864 1 controller_instance.go:1347] Setting ServiceInstance "sns7/apb-push-sns-apb-q316z" condition "Ready" to False I1011 18:27:19.971887 1 controller_instance.go:1397] Updating status for ServiceInstance sns7/apb-push-sns-apb-q316z E1011 18:27:19.975918 1 controller_instance.go:1400] Failed to update status for ServiceInstance sns7/apb-push-sns-apb-q316z: Operation cannot be fulfilled on serviceinstances "apb-push-sns-apb-q316z": StorageError: invalid object, Code: 4, Key: /k8s.io/service-catalog/serviceinstances/sns7/apb-push-sns-apb-q316z, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: a897acd5-aeb1-11e7-8d64-0242ac110006, UID in object meta: I1011 18:27:19.975952 1 controller.go:232] Error syncing ServiceInstance sns7/apb-push-sns-apb-q316z: Operation cannot be fulfilled on serviceinstances "apb-push-sns-apb-q316z": StorageError: invalid object, Code: 4, Key: /k8s.io/service-catalog/serviceinstances/sns7/apb-push-sns-apb-q316z, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: a897acd5-aeb1-11e7-8d64-0242ac110006, UID in object meta: I1011 18:27:20.037076 1 controller_instance.go:70] Received delete event for ServiceInstance sns7/apb-push-sns-apb-q316z; no further processing will occur I1011 18:27:20.039080 1 controller.go:312] Creating client for ServiceBroker ansible-service-broker, URL: https://asb.ansible-service-broker.svc:1338/ansible-service-broker/ I1011 18:27:20.040660 1 controller_instance.go:293] Deprovisioning ServiceInstance sns7/apb-push-sns-apb-q316z of ServiceClass ab883cebb0a87311150230384078477c at ServiceBroker ansible-service-broker I1011 18:27:20.054124 1 controller_instance.go:414] Deprovision call to broker succeeded for ServiceInstance sns7/apb-push-sns-apb-q316z, finalizing I1011 18:27:20.054157 1 controller_instance.go:1347] Setting ServiceInstance "sns7/apb-push-sns-apb-q316z" condition "Ready" to False I1011 18:27:20.054180 1 controller_instance.go:1397] Updating status for ServiceInstance sns7/apb-push-sns-apb-q316z E1011 18:27:20.057290 1 controller_instance.go:1400] Failed to update status for ServiceInstance sns7/apb-push-sns-apb-q316z: Operation cannot be fulfilled on serviceinstances "apb-push-sns-apb-q316z": StorageError: invalid object, Code: 4, Key: /k8s.io/service-catalog/serviceinstances/sns7/apb-push-sns-apb-q316z, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: a897acd5-aeb1-11e7-8d64-0242ac110006, UID in object meta: I1011 18:27:20.057371 1 controller.go:232] Error syncing ServiceInstance sns7/apb-push-sns-apb-q316z: Operation cannot be fulfilled on serviceinstances "apb-push-sns-apb-q316z": StorageError: invalid object, Code: 4, Key: /k8s.io/service-catalog/serviceinstances/sns7/apb-push-sns-apb-q316z, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: a897acd5-aeb1-11e7-8d64-0242ac110006, UID in object meta: I1011 18:27:20.077579 1 controller_instance.go:146] Not doing work for ServiceInstance sns7/apb-push-sns-apb-q316z because it has been deleted