Bug 1562732 - Deleting serviceinstance fail occasionally
Summary: Deleting serviceinstance fail occasionally
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Service Broker
Version: 3.9.0
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 3.10.0
Assignee: Jesus M. Rodriguez
QA Contact: Zihan Tang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-04-02 09:41 UTC by Zihan Tang
Modified: 2018-07-30 19:12 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Cause: Invalid deprovision response combined with an error during deprovision caused deprovisions to fail occasionally. Consequence: Deprovisions would fail. Fix: Return the proper deprovision response body with the operation key, as well as a variety of changes to the deprovision workflow to address other bugs fixed the failed jobs. Result: Deprovisions will have a higher likelihood of succeeding now.
Clone Of:
Environment:
Last Closed: 2018-07-30 19:11:39 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:1816 None None None 2018-07-30 19:12:03 UTC

Description Zihan Tang 2018-04-02 09:41:25 UTC
Description of problem:
Deleting a serviceintance  failed occasionally. 
with message:
  Warning  DeprovisionCallFailed                    8m (x7 over 25m)   service-catalog-controller-manager  Deprovision call failed: Error occurred during deprovision. Please contact administrator if it persists.


Version-Release number of selected component (if applicable):
ASB: 1.1.17

How reproducible:
Random

Steps to Reproduce:
1. Provision Postgresql apb from Web console , and create binding.
2. Delete serviceinstance In Web console.

Actual results:
delete serviceinstance failed.
Asb log:
0.129.0.1 - - [02/Apr/2018:09:05:34 +0000] "DELETE /ansible-service-broker/v2/service_instances/5cdd0bea-d0da-4648-826e-da82366310af/service_bindings/ab83aa2f-da36-4bd6-9d4c-cdd4dbf2785c?plan_id=9783fc2e859f9179833a7dd003baa841&service_id=d5915e05b253df421efe6e41fb6a66ba HTTP/1.1" 200 3
[2018-04-02T09:05:34.653Z] [INFO] - ASYNC deprovision in progress
[2018-04-02T09:05:34.653Z] [NOTICE] - ============================================================
[2018-04-02T09:05:34.653Z] [NOTICE] -                       DEPROVISIONING                        
[2018-04-02T09:05:34.653Z] [NOTICE] - ============================================================
[2018-04-02T09:05:34.653Z] [NOTICE] - ServiceInstance.Id: d5915e05b253df421efe6e41fb6a66ba
[2018-04-02T09:05:34.653Z] [NOTICE] - ServiceInstance.Name: rh-postgresql-apb
[2018-04-02T09:05:34.653Z] [NOTICE] - ServiceInstance.Image: registry.access.stage.redhat.com/openshift3/postgresql-apb:v3.9
[2018-04-02T09:05:34.653Z] [NOTICE] - ServiceInstance.Description: SCL PostgreSQL apb implementation
[2018-04-02T09:05:34.653Z] [NOTICE] - ============================================================
10.129.0.1 - - [02/Apr/2018:09:05:34 +0000] "DELETE /ansible-service-broker/v2/service_instances/5cdd0bea-d0da-4648-826e-da82366310af?accepts_incomplete=true&plan_id=9783fc2e859f9179833a7dd003baa841&service_id=d5915e05b253df421efe6e41fb6a66ba HTTP/1.1" 202 58
[2018-04-02T09:05:34.681Z] [NOTICE] - Creating RoleBinding apb-262e13c7-ee23-468f-9eaa-5037c01ad509
[2018-04-02T09:05:34.751Z] [INFO] - Deprovision requested for instance 5cdd0bea-d0da-4648-826e-da82366310af, but job is already in progress
10.129.0.1 - - [02/Apr/2018:09:05:34 +0000] "DELETE /ansible-service-broker/v2/service_instances/5cdd0bea-d0da-4648-826e-da82366310af?accepts_incomplete=true&plan_id=9783fc2e859f9179833a7dd003baa841&service_id=d5915e05b253df421efe6e41fb6a66ba HTTP/1.1" 202 3
[2018-04-02T09:05:34.767Z] [NOTICE] - Creating RoleBinding apb-262e13c7-ee23-468f-9eaa-5037c01ad509
[2018-04-02T09:05:34.833Z] [INFO] - Deprovision requested for instance 5cdd0bea-d0da-4648-826e-da82366310af, but job is already in progress
10.129.0.1 - - [02/Apr/2018:09:05:34 +0000] "DELETE /ansible-service-broker/v2/service_instances/5cdd0bea-d0da-4648-826e-da82366310af?accepts_incomplete=true&plan_id=9783fc2e859f9179833a7dd003baa841&service_id=d5915e05b253df421efe6e41fb6a66ba HTTP/1.1" 202 3
[2018-04-02T09:05:34.864Z] [INFO] - Successfully created apb sandbox: [ apb-262e13c7-ee23-468f-9eaa-5037c01ad509 ], with edit permissions in namespace rh-postgresql-apb-depr-2frdc
[2018-04-02T09:05:34.864Z] [INFO] - Running post create sandbox fuctions if defined.
10.129.0.1 - - [02/Apr/2018:09:05:34 +0000] "GET /ansible-service-broker/v2/service_instances/5cdd0bea-d0da-4648-826e-da82366310af/last_operation?operation=8d7d7bed-731a-48a8-bc58-3b02cd33a53f&plan_id=9783fc2e859f9179833a7dd003baa841&service_id=d5915e05b253df421efe6e41fb6a66ba HTTP/1.1" 200 29
[2018-04-02T09:05:34.872Z] [INFO] - Proxy configuration present. Applying to APB before execution:
[2018-04-02T09:05:34.872Z] [INFO] - HTTP_PROXY=""
[2018-04-02T09:05:34.872Z] [INFO] - HTTPS_PROXY=""
[2018-04-02T09:05:34.872Z] [INFO] - NO_PROXY=""
[2018-04-02T09:05:34.872Z] [NOTICE] - Creating pod "apb-262e13c7-ee23-468f-9eaa-5037c01ad509" in the rh-postgresql-apb-depr-2frdc namespace
10.129.0.1 - - [02/Apr/2018:09:05:35 +0000] "GET /ansible-service-broker/v2/service_instances/5cdd0bea-d0da-4648-826e-da82366310af/last_operation?operation=8d7d7bed-731a-48a8-bc58-3b02cd33a53f&plan_id=9783fc2e859f9179833a7dd003baa841&service_id=d5915e05b253df421efe6e41fb6a66ba HTTP/1.1" 200 29
10.129.0.1 - - [02/Apr/2018:09:05:39 +0000] "GET /ansible-service-broker/v2/service_instances/5cdd0bea-d0da-4648-826e-da82366310af/last_operation?operation=8d7d7bed-731a-48a8-bc58-3b02cd33a53f&plan_id=9783fc2e859f9179833a7dd003baa841&service_id=d5915e05b253df421efe6e41fb6a66ba HTTP/1.1" 200 29
[2018-04-02T09:05:43.917Z] [ERROR] - Problem executing apb [apb-262e13c7-ee23-468f-9eaa-5037c01ad509] deprovision
[2018-04-02T09:05:43.917Z] [INFO] - Destroying APB sandbox...
[2018-04-02T09:05:43.919Z] [ERROR] - Unable to retrieve pod - pods "apb-262e13c7-ee23-468f-9eaa-5037c01ad509" not found
[2018-04-02T09:05:43.926Z] [NOTICE] - Successfully deleted rolebinding apb-262e13c7-ee23-468f-9eaa-5037c01ad509, namespace rh-postgresql-apb-depr-2frdc
[2018-04-02T09:05:43.93Z] [NOTICE] - Successfully deleted rolebinding apb-262e13c7-ee23-468f-9eaa-5037c01ad509, namespace test2
[2018-04-02T09:05:44.448Z] [ERROR] - broker::Deprovision error occurred. No API token found for service account "apb-262e13c7-ee23-468f-9eaa-5037c01ad509", retry after the token is automatically created and added to the service account

sand box : the pod is deleted or not created.
[root@host-172-16-120-7 ~]# oc project rh-postgresql-apb-depr-2frdc
Now using project "rh-postgresql-apb-depr-2frdc" on server "https://172.16.120.7:8443".
[root@host-172-16-120-7 ~]# oc get pod 
No resources found.
[root@host-172-16-120-7 ~]# 

serviceisntance: 
[root@host-172-16-120-7 ~]# oc describe serviceinstance
Name:         rh-postgresql-apb-5plf8
Namespace:    test2
Labels:       <none>
Annotations:  <none>
API Version:  servicecatalog.k8s.io/v1beta1
Kind:         ServiceInstance
Metadata:
  Creation Timestamp:             2018-04-02T08:57:53Z
  Deletion Grace Period Seconds:  0
  Deletion Timestamp:             2018-04-02T09:05:33Z
  Finalizers:
    kubernetes-incubator/service-catalog
  Generate Name:     rh-postgresql-apb-
  Generation:        2
  Resource Version:  53271
  Self Link:         /apis/servicecatalog.k8s.io/v1beta1/namespaces/test2/serviceinstances/rh-postgresql-apb-5plf8
  UID:               edc3f392-3653-11e8-b85d-0a580a810004
Spec:
  Cluster Service Class External Name:  rh-postgresql-apb
  Cluster Service Class Ref:
    Name:                              d5915e05b253df421efe6e41fb6a66ba
  Cluster Service Plan External Name:  dev
  Cluster Service Plan Ref:
    Name:       9783fc2e859f9179833a7dd003baa841
  External ID:  5cdd0bea-d0da-4648-826e-da82366310af
  Parameters From:
    Secret Key Ref:
      Key:          parameters
      Name:         rh-postgresql-apb-parameters2276z
  Update Requests:  0
  User Info:
    Extra:
      Scopes . Authorization . Openshift . Io:
        user:full
    Groups:
      system:authenticated:oauth
      system:authenticated
    UID:       
    Username:  zitang
Status:
  Async Op In Progress:  true
  Conditions:
    Last Transition Time:  2018-04-02T09:05:47Z
    Message:               Deprovision call failed: Error occurred during deprovision. Please contact administrator if it persists.
    Reason:                DeprovisionCallFailed
    Status:                Unknown
    Type:                  Ready
  Current Operation:       Deprovision
  Deprovision Status:      Required
  External Properties:
    Cluster Service Plan External ID:    9783fc2e859f9179833a7dd003baa841
    Cluster Service Plan External Name:  dev
    Parameter Checksum:                  48714955b4a3ca03d8b05d8ec6a5efe332e889c5864870a8b5604832899eb47b
    Parameters:
      Postgresql _ Database:  <redacted>
      Postgresql _ Password:  <redacted>
      Postgresql _ User:      <redacted>
      Postgresql _ Version:   <redacted>
    User Info:
      Extra:
        Scopes . Authorization . Openshift . Io:
          user:full
      Groups:
        system:authenticated:oauth
        system:authenticated
      UID:                        
      Username:                   zitang
  Last Operation:                 8d7d7bed-731a-48a8-bc58-3b02cd33a53f
  Operation Start Time:           2018-04-02T09:05:34Z
  Orphan Mitigation In Progress:  false
  Reconciled Generation:          1
Events:
  Type     Reason                                   Age                From                                Message
  ----     ------                                   ----               ----                                -------
  Warning  ErrorWithParameters                      33m                service-catalog-controller-manager  failed to prepare parameters nil: secrets "rh-postgresql-apb-parameters2276z" not found
  Normal   Provisioning                             33m                service-catalog-controller-manager  The instance is being provisioned asynchronously
  Normal   ProvisionedSuccessfully                  33m                service-catalog-controller-manager  The instance was provisioned successfully
  Warning  DeprovisionBlockedByExistingCredentials  25m (x2 over 25m)  service-catalog-controller-manager  All associated ServiceBindings must be removed before this ServiceInstance can be deleted
  Normal   Deprovisioning                           25m                service-catalog-controller-manager  The instance is being deprovisioned asynchronously
  Warning  DeprovisionCallFailed                    8m (x7 over 25m)   service-catalog-controller-manager  Deprovision call failed: Error occurred during deprovision. Please contact administrator if it persists.

broker-config
[root@host-172-16-120-7 ~]# oc get  cm broker-config -o yaml
apiVersion: v1
data:
  broker-config: "registry:\n  - type: rhcc\n    name: rh\n    url:  registry.access.stage.redhat.com\n
    \   org:  \n    tag:  v3.9\n    white_list: [.*-apb$]\n\n    auth_type: \"\"\n
    \   auth_name: \"\"\n  - type: local_openshift\n    name: localregistry\n    namespaces:
    ['openshift']\n    white_list: []\n\ndao:\n  etcd_host: asb-etcd.openshift-ansible-service-broker.svc\n
    \ etcd_port: 2379\n  etcd_ca_file: /var/run/secrets/kubernetes.io/serviceaccount/service-ca.crt\n
    \ etcd_client_cert: /var/run/asb-etcd-auth/client.crt\n  etcd_client_key: /var/run/asb-etcd-auth/client.key\nlog:\n
    \ stdout: true\n  level: info\n  color: true\nopenshift:\n  host: \"\"\n  ca_file:
    \"\"\n  bearer_token_file: \"\"\n  sandbox_role: edit\n  image_pull_policy: IfNotPresent\n
    \ keep_namespace: false\n  keep_namespace_on_error: true\nbroker:\n  dev_broker:
    false\n  bootstrap_on_startup: true\n  refresh_interval: 600s\n  launch_apb_on_bind:
    false\n  output_request: false\n  recovery: true\n  ssl_cert_key: /etc/tls/private/tls.key\n
    \ ssl_cert: /etc/tls/private/tls.crt\n  auto_escalate: False\n  auth:\n    - type:
    basic\n      enabled: false\n"
kind: ConfigMap
metadata:
  creationTimestamp: 2018-04-02T02:20:40Z
  labels:
    app: openshift-ansible-service-broker
  name: broker-config
  namespace: openshift-ansible-service-broker
  resourceVersion: "2481"
  selfLink: /api/v1/namespaces/openshift-ansible-service-broker/configmaps/broker-config
  uid: 704f8dbc-361c-11e8-a1fa-fa163ef0378d

Expected results:
Delete serviceinstance successfully.

Additional info:
1. I can not reproduce this bug in the same env after this failure.
2. When the deletion failed, the status of cluserserviceclass and clusterserviceplan are right. and the client (apb) can list out all apbs.

Comment 1 Jesus M. Rodriguez 2018-05-01 15:24:26 UTC
Please retest this with a new Automation Broker 1.2.8, as a lot has changed in this area of code to fix a variety of issues including some of the deprovision issues.

Comment 2 Zihan Tang 2018-05-02 05:46:11 UTC
Thanks Jesus,
We will run regression test in recent run ,  If it can not reproduced , we'll mark it as verified.

Comment 3 Jesus M. Rodriguez 2018-05-09 18:40:43 UTC
Before re-testing, we should wait for this fix to arrive in a build. I think it is related.

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

Comment 4 Jesus M. Rodriguez 2018-05-11 12:07:46 UTC
Available in asb 1.2.11

Comment 5 Zihan Tang 2018-05-31 09:29:25 UTC
In recent runs against 3.10, we haven't reproduce it. So mark it as Verified.
If we reproduce in 3.10 once again, I'll reopen it.

Comment 7 errata-xmlrpc 2018-07-30 19:11:39 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/RHBA-2018:1816


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