Bug 1586005

Summary: [ASB]Cannot get the job state of servicebinding when enable the async
Product: OpenShift Container Platform Reporter: Jian Zhang <jiazha>
Component: Service BrokerAssignee: Jesus M. Rodriguez <jesusr>
Status: CLOSED ERRATA QA Contact: Jian Zhang <jiazha>
Severity: medium Docs Contact:
Priority: medium    
Version: 3.10.0CC: aos-bugs, jmatthew, mhrivnak
Target Milestone: ---   
Target Release: 3.10.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
undefined
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-07-30 19:17:19 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:

Description Jian Zhang 2018-06-05 09:49:56 UTC
Description of problem:
Got below errors when querying the servicebinding job state:

[2018-06-05T09:12:12.112Z] [ERROR] - Unable to get the job state: a4d2ae46-c6e8-441e-9afa-44de59e0297a - <nil>
[2018-06-05T09:12:12.112Z] [WARNING] - unable to find job state: [5bc5dc12-689b-11e8-bee8-0a580a80000e]. error: [unable to find job state a4d2ae46-c6e8-441e-9afa-44de59e0297a]
[2018-06-05T09:12:12.112Z] [DEBUG] - state: failed
[2018-06-05T09:12:12.112Z] [DEBUG] - description: 
10.129.0.1 - - [05/Jun/2018:09:12:12 +0000] "GET /ansible-service-broker/v2/service_instances/5bc5dc12-689b-11e8-bee8-0a580a80000e/last_operation?operation=a4d2ae46-c6e8-441e-9afa-44de59e0297a&service_id=dh-postgresql-apb-dvgx2&plan_id=7f4a5e35e4af2beb70076e72fab0b7ff HTTP/1.1" 500 85


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

How reproducible:
always

Steps to Reproduce:
1. Enable the async feature and config an APB that support async binding. Like below:
...
registry:
  - type: dockerhub
    name: dh
    url:  https://registry.hub.docker.com 
    org: mhrivnak
    tag:  latest
    white_list: [.*-apb$]

broker:
  ...
  launch_apb_on_bind: true

2. Provision the PostgreSQL APB.

3. Create a binding by using below script:
#cat bind.sh
INSTANCE_ID="5bc5dc12-689b-11e8-bee8-0a580a80000e"
#BINDING_ID=$(uuidgen)
BINDING_ID=$1
PLAN_UUID="7f4a5e35e4af2beb70076e72fab0b7ff"
SERVICE_UUID="dh-postgresql-apb-dvgx2"
IDENTITY=$(echo -n '{"groups":["system:authenticated:oauth","system:authenticated"],"scopes.authorization.openshift.io":["user:full"],"uid":"","username":"jiazha"}'|base64 -w 0)

echo "binding ID: $BINDING_ID"

req="{
  \"plan_id\": \"$PLAN_UUID\",
  \"service_id\": \"$SERVICE_UUID\",
  \"context\": \"blog-project\",
  \"app_guid\":\"\",
  \"bind_resource\":{},
  \"parameters\": {}
}"

curl \
    -k -i \
    -X PUT \
    -H "Authorization: bearer $(oc whoami -t)" \
    -H "Content-type: application/json" \
    -H "Accept: application/json" \
    -H "X-Broker-API-Originating-Identity: kubernetes $IDENTITY" \
    -d "$req" \
    "https://asb-1338-openshift-ansible-service-broker.apps.0604-gke.qe.rhcloud.com/ansible-service-broker/v2/service_instances/$INSTANCE_ID/service_bindings/$BINDING_ID?accepts_incomplete=true"

[jzhang@localhost ~]$ ./bind.sh cc0c3bf2-ff17-4885-88f7-27e662097b4f
binding ID: cc0c3bf2-ff17-4885-88f7-27e662097b4f
HTTP/1.1 202 Accepted
Content-Type: application/json
Date: Tue, 05 Jun 2018 09:11:28 GMT
Content-Length: 58
Set-Cookie: 89a6d633054ded194d4e1360cdc1fbef=edbd392e806b18e638b002712fe75aed; path=/; HttpOnly; Secure

{
  "operation": "a4d2ae46-c6e8-441e-9afa-44de59e0297a"
}

4, Then, we can get the job id: "a4d2ae46-c6e8-441e-9afa-44de59e0297a", then query the job status.
[jzhang@localhost ~]$ cat last_operation.sh 
OPERATION_ID=$1
INSTANCE_ID="5bc5dc12-689b-11e8-bee8-0a580a80000e"
PLAN_UUID="7f4a5e35e4af2beb70076e72fab0b7ff"
SERVICE_UUID="dh-postgresql-apb-dvgx2"
IDENTITY=$(echo -n '{"groups":["system:authenticated:oauth","system:authenticated"],"scopes.authorization.openshift.io":["user:full"],"uid":"","username":"jiazha"}'|base64 -w 0)

curl \
    -k -i \
    -X GET \
    -H "Authorization: bearer $(oc whoami -t)" \
    -H "Content-type: application/json" \
    -H "Accept: application/json" \
    -H "X-Broker-API-Originating-Identity: kubernetes $IDENTITY" \
    "https://asb-1338-openshift-ansible-service-broker.apps.0604-gke.qe.rhcloud.com/ansible-service-broker/v2/service_instances/$INSTANCE_ID/last_operation?operation=$OPERATION_ID&service_id=$SERVICE_UUID&plan_id=$PLAN_UUID"


Actual results:
[jzhang@localhost ~]$ ./last_operation.sh a4d2ae46-c6e8-441e-9afa-44de59e0297a
HTTP/1.1 500 Internal Server Error
Content-Type: application/json
Date: Tue, 05 Jun 2018 09:12:12 GMT
Content-Length: 85
Set-Cookie: 89a6d633054ded194d4e1360cdc1fbef=edbd392e806b18e638b002712fe75aed; path=/; HttpOnly; Secure

{
  "description": "unable to find job state a4d2ae46-c6e8-441e-9afa-44de59e0297a"
}


Expected results:
Should get the servicebinding job state success.

Additional info:
We can get the job id from the description info, but the job id(A 4 D 2 Ae 46 - C 6 E 8 - 441 E - 9 Afa - 44 De 59 E 0297 A) changed to uppercase letters and injected whitespace.

[root@qe-jiazha-manualmaster-etcd-1 ~]# oc describe bundlebinding cc0c3bf2-ff17-4885-88f7-27e662097b4f
Name:         cc0c3bf2-ff17-4885-88f7-27e662097b4f
Namespace:    openshift-ansible-service-broker
Labels:       <none>
Annotations:  <none>
API Version:  automationbroker.io/v1alpha1
Kind:         BundleBinding
Metadata:
  Cluster Name:        
  Creation Timestamp:  2018-06-05T09:11:28Z
  Generation:          1
  Resource Version:    56294
  Self Link:           /apis/automationbroker.io/v1alpha1/namespaces/openshift-ansible-service-broker/bundlebindings/cc0c3bf2-ff17-4885-88f7-27e662097b4f
  UID:                 6dc09dae-68a0-11e8-ac8f-fa163ee5a5fd
Spec:
  Bundle Instance:
    Name:      5bc5dc12-689b-11e8-bee8-0a580a80000e
  Parameters:  {"_apb_last_requesting_user":"jiazha","_apb_plan_id":"dev","_apb_provision_creds":{"DB_ADMIN_PASSWORD":"O3GozFBwclayh4rxqrGj","DB_HOST":"postgresql","DB_NAME":"admin","DB_PASSWORD":"test","DB_PORT":"5432","DB_TYPE":"postgres","DB_USER":"admin"},"_apb_service_binding_id":"cc0c3bf2-ff17-4885-88f7-27e662097b4f","_apb_service_class_id":"dh-postgresql-apb-dvgx2","_apb_service_instance_id":"5bc5dc12-689b-11e8-bee8-0a580a80000e"}
Status:
  Jobs:
    A 4 D 2 Ae 46 - C 6 E 8 - 441 E - 9 Afa - 44 De 59 E 0297 A:
      Description:         bind job completed
      Last Modified Time:  2018-06-05T09:11:36Z
      Method:              bind
      Podname:             
      State:               succeeded
  Last Description:        bind job completed
  State:                   succeeded
Events:                    <none>

Comment 1 Jesus M. Rodriguez 2018-06-05 20:45:16 UTC
Your last_operation script is incorrect. The OSB spec defines the last_operation url for BINDINGS to be:

/v2/service_instances/$INSTANCE_ID/service_bindings/$BINDING_ID/last_operation?operation=...

### OSB spec regarding async binds
https://github.com/mattmcneeney/servicebroker/blob/43ba40883f07f0cc6841b5539a06ed51788d725e/spec.md#route-2

### last_operation.sh script changes
you need a second argument which should be the binding id, the same one passed to bind.sh. The url needs to have the service_bindings/ in it.

BINDING_ID=$2
....

"https://asb-1338-openshift-ansible-service-broker.apps.0604-gke.qe.rhcloud.com/ansible-service-broker/v2/service_instances/$INSTANCE_ID/service_bindings/$BINDING_ID/last_operation?operation=$OPERATION_ID&service_id=$SERVICE_UUID&plan_id=$PLAN_UUID"

### using correct url in the script results in finding the jobstate
$ ./last_operation.sh c9660714-cc45-4413-aebf-f2f52b4666da e8926ce5-1d5f-46f1-b678-f1e1d2864764
HTTP/1.1 200 OK
Content-Type: application/json
Date: Tue, 05 Jun 2018 20:37:57 GMT
Content-Length: 66
Set-Cookie: 89a6d633054ded194d4e1360cdc1fbef=19d7735c752d40bedc1b0307fbbf73e0; path=/; HttpOnly; Secure
Cache-control: private

{
  "state": "succeeded",
  "description": "bind job completed"
}

Comment 2 Jesus M. Rodriguez 2018-06-05 20:47:03 UTC
Please retest by doing the following:

1) copy your last_operation.sh to binding_last_operation.sh
2) use the correct url in binding_last_operation.sh
3) perform the steps you did above, except use the new binding_last_operation.sh script to monitor async binding jobs

Comment 3 Jesus M. Rodriguez 2018-06-05 20:49:46 UTC
Here's one I've used in the past:
https://github.com/openshift/ansible-service-broker/blob/master/test/last_operation_bind.sh

Comment 4 Jesus M. Rodriguez 2018-06-05 22:46:59 UTC
I do not think the `oc describe` is a bug with the broker. That would most likely be a bug with oc command.

Comment 5 Jian Zhang 2018-06-06 02:38:02 UTC
Jesus,

Thank you for your clarification! It works well, verify it. 
I will new a bug for the `oc describe` issue. Thanks!

[jzhang@localhost ~]$ ./bind.sh bc56461c-5a9a-49ba-8bbc-24b494bfd998
binding ID: bc56461c-5a9a-49ba-8bbc-24b494bfd998
HTTP/1.1 202 Accepted
Content-Type: application/json
Date: Wed, 06 Jun 2018 02:20:15 GMT
Content-Length: 58
Set-Cookie: 89a6d633054ded194d4e1360cdc1fbef=0f001a834304cdacf8138c84a8b240cc; path=/; HttpOnly; Secure

{
  "operation": "d6a0a5ea-0849-47de-8108-aed4acfc910c"
}
[jzhang@localhost ~]$ ./last_operation.sh d6a0a5ea-0849-47de-8108-aed4acfc910c bc56461c-5a9a-49ba-8bbc-24b494bfd998
HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 06 Jun 2018 02:20:33 GMT
Content-Length: 66
Set-Cookie: 89a6d633054ded194d4e1360cdc1fbef=0f001a834304cdacf8138c84a8b240cc; path=/; HttpOnly; Secure
Cache-control: private

{
  "state": "succeeded",
  "description": "bind job completed"
}

Comment 7 errata-xmlrpc 2018-07-30 19:17:19 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