Bug 1567847

Marko, you've done a lot of work on this area. Would you take a look?

I'm unable to reproduce this. In my case, the provision request is only sent once. The behavior you're seeing is consistent with an older version of the service catalog.

Please confirm that you're really running v0.1.13 of the service catalog. This issue was fixed in v0.1.11. 

To see the controller's version, please run: oc logs -f controller-manager-htxcv -n kube-service-catalog | head

*** Bug 1570578 has been marked as a duplicate of this bug. ***

When provision apb , I find logs in asb: 
[2018-04-26T05:59:18.611Z] [INFO] - All Jobs for instance: f41d69a8-4916-11e8-9198-0a580a800003 in state:  in progress - 
[]apb.JobState{apb.JobState{Token:"822e03f4-8929-4f58-b98f-99f153e37be2", State:"in progress", Podname:"", Method:"provision", Error:"", Description:"action started"}}
[2018-04-26T05:59:18.611Z] [INFO] - Provision requested for instance f41d69a8-4916-11e8-9198-0a580a800003, but job is already in progress
[2018-04-26T05:59:18.611Z] [ERROR] - provision error provision in progress

It's not always reproduced,  about 80%. 

controller version: v0.1.13
in the log : Service Catalog version v0.0.0-master+$Format:%h$ (built 2018-04-25T14:16:15Z)
# oc exec controller-manager-f2q9t  -- /usr/bin/service-catalog --version
v3.10.0-0.29.0;Upstream:v0.1.13

Where are you getting the Service Catalog image from? I'd like to try this out with the exact same image, because I still haven't been able to reproduce this bug with the images I've tried (which includes v0.1.13).

And when I use the 
service-catalog: v3.10.0-0.32.0;Upstream:v0.1.13  and ASB:v1.2.7 
 
still find the issue in asb when provision 
[2018-05-04T09:20:41.507Z] [INFO] - All Jobs for instance: 695336f2-4f7c-11e8-9ef9-0a580a800005 in state:  in progress - 
[]apb.JobState{apb.JobState{Token:"d934a5b8-8bda-4498-9351-31d465204e21", State:"in progress", Podname:"", Method:"provision", Error:"", Description:"action started"}}
[2018-05-04T09:20:41.507Z] [INFO] - Provision requested for instance 695336f2-4f7c-11e8-9ef9-0a580a800005, but job is already in progress
[2018-05-04T09:20:41.507Z] [ERROR] - provision error provision in progress

In asb 1.2.10, service-catalog v3.10.0-0.38.0;Upstream:v0.1.16
this bug is 'NOT ALWAYS' reproduced.

If it is the first time provision the certain apb(no this serviceinstance exist in all namespace), it's not reproduced.
if provision the apb for the second time (more than one this intance exist in all namespace), this will be reproduced.

ASB logs like: 
[2018-05-14T09:38:18.559Z] [INFO] - All Jobs for instance: 86b216c0-575a-11e8-be4e-0a580a800003 in state:  in progress - 
[]apb.JobState{apb.JobState{Token:"8065f043-e832-451d-a2ec-c255f382c427", State:"in progress", Podname:"", Method:"provision", Error:"", Description:"action started"}}
[2018-05-14T09:38:18.559Z] [INFO] - Provision requested for instance 86b216c0-575a-11e8-be4e-0a580a800003, but job is already in progress
[2018-05-14T09:38:18.559Z] [ERROR] - provision error provision in progress

@Marko, we're closing down bugs for 3.10.  We need to fix this ASAP or move the target release out to 3.11.  I'm thinking we probably want to bump this out, do you agree?

I still can't reproduce this. I've provisioned five "PostgreSQL (APB)" services in different namespaces and there is always only one provision request. 

I'm using service catalog v0.1.19. 

Are you sure you don't have two instances of the controller manager running? Possibly in different namespaces?

Please attach the full logs of the controller manager (with --v 6) so we can confirm that it's in fact a single controller sending multiple requests to the ansible service broker.

I use service catalog v3.10.0-0.50.0;Upstream:v0.1.19,
but this is not always reproduced.
I use mysql-apb and maria-apb , and reproduced this time:
asb log:
[2018-05-24T03:21:25.992Z] [INFO] - All Jobs for instance: 89bac308-5f01-11e8-9f13-0a580a800005 in state:  in progress - 
[]apb.JobState{apb.JobState{Token:"9ff3413a-1517-47c4-951c-038677ae7149", State:"in progress", Podname:"", Method:"provision", Error:"", Description:"action started"}}
[2018-05-24T03:21:25.992Z] [INFO] - Provision requested for instance 89bac308-5f01-11e8-9f13-0a580a800005, but job is already in progress
[2018-05-24T03:21:25.992Z] [ERROR] - provision error provision in progress
10.128.0.1 - - [24/May/2018:03:21:25 +0000] "PUT /ansible-service-broker/v2/service_instances/89bac308-5f01-11e8-9f13-0a580a800005?accepts_incomplete=true HTTP/1.1" 202 58
time="2018-05-24T03:21:26Z" level=info msg="Successfully created apb sandbox: [ %s ], with %s permissions in namespace %sapb-05c186c9-c41b-478e-8a2a-4a1807529f1ceditdh-mysql-apb-prov-nd2cf"
time="2018-05-24T03:21:26Z" level=info msg="Running post create sandbox fuctions if defined."
.....
time="2018-05-24T03:23:18Z" level=info msg="Creating RoleBinding apb-ed3e0c6f-3fed-4be8-b7ca-d1a70ff47452"
[2018-05-24T03:23:18.508Z] [INFO] - All Jobs for instance: cc64c254-5f01-11e8-9f13-0a580a800005 in state:  in progress - 
[]apb.JobState{apb.JobState{Token:"5833e48d-250a-4e24-8a32-f04dd2c62b78", State:"in progress", Podname:"", Method:"provision", Error:"", Description:"action started"}}
[2018-05-24T03:23:18.508Z] [INFO] - Provision requested for instance cc64c254-5f01-11e8-9f13-0a580a800005, but job is already in progress
[2018-05-24T03:23:18.508Z] [ERROR] - provision error provision in progress

Created attachment 1440933 [details]
controller log

Here's the controller's log when I provision postgresql-apb, mysql-apb, mariadb-apb.

The apbs I used is v3.10.0-0.32.0.0
I'm not sure whether it is caused by apb.

I was able to reproduce this last week and figure out what is causing it. 

This issue is almost always reproducible like this:

- oc apply -f serviceinstance.yaml ; sleep 1 ; oc apply -f secret.yaml

where the secret.yaml holds the secret that serviceinstance.yaml refers to in its `parametersFrom`. 

It doesn't matter if this is the first ServiceInstance you're provisioning or if there are existing instances in the cluster.

This problem isn't trivial to fix, so I'm moving this out of 3.10.

What is the impact of this bug?  Is it limited to confusion when reviewing the logs and events on the service instance because it appears the instance is provisioned multiple times?  With enough time, the instance is eventually provisioned and works, correct?

(In reply to Jay Boyd from comment #17)
> What is the impact of this bug?  Is it limited to confusion when reviewing
> the logs and events on the service instance because it appears the instance
> is provisioned multiple times?  
This is reported according to card: 
https://trello.com/c/oRfQX2Ih/110-5-catalog310-reconciliation-loop-rework
the asb log shows it receive mulitple request from service catalog

With enough time, the instance is eventually
> provisioned and works, correct?
Yes, it provisioned and works

Besides, for 3.11, asb didn't report this kind of log any more.

Thanks Zihan.