Creating default "automationbroker" CR results in frozen ASB operator stuck on "injecting owner reference" #1138

djwhatle · 2018-11-26T19:05:59Z

Bug: Creating default "automationbroker" CR results in frozen ASB operator

What happened

Set up OpenShift v3.11 cluster with OLM and latest ASB CSV
Created automation-broker CR with default values in automation-broker namespace
automation-broker-operator container freezes while running ASB creation playbook

CR I created with default params (doesn't work):

apiVersion: automationbroker.io/v1alpha1
kind: AutomationBroker
metadata:
  name: automation-broker
  namespace: automation-broker
spec:
  createBrokerNamespace: 'false'
  waitForBroker: 'false'

ASB Operator Logs:

time="2018-11-26T16:31:32Z" level=info msg="Go Version: go1.10.4"
time="2018-11-26T16:31:32Z" level=info msg="Go OS/Arch: linux/amd64"
time="2018-11-26T16:31:32Z" level=info msg="operator-sdk Version: 0.0.6+git"
time="2018-11-26T16:31:32Z" level=info msg="Starting to serve on 127.0.0.1:8888\n"
time="2018-11-26T16:31:32Z" level=info msg="Watching automationbroker.io/v1alpha1, AutomationBroker, default"
{"level":"info","ts":1543249892.549802,"logger":"kubebuilder.controller","caller":"controller/controller.go:120","msg":"Starting EventSource","Controller":"automationbroker-controller","Source":{"Type":{"apiVersion":"automationbroker.io/v1alpha1","kind":"AutomationBroker"}}}
{"level":"info","ts":1543249892.5502899,"logger":"kubebuilder.controller","caller":"controller/controller.go:120","msg":"Starting EventSource","Controller":"automationbroker-controller","SourceError":"json: unsupported type: <-chan event.GenericEvent"}
{"level":"info","ts":1543249892.6506014,"logger":"kubebuilder.controller","caller":"controller/controller.go:134","msg":"Starting Controller","Controller":"automationbroker-controller"}
{"level":"info","ts":1543249892.7509446,"logger":"kubebuilder.controller","caller":"controller/controller.go:153","msg":"Starting workers","Controller":"automationbroker-controller","WorkerCount":1}
time="2018-11-26T16:31:45Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=8258902912821821880
time="2018-11-26T16:31:46Z" level=info msg="[playbook task]: automation-broker : Set broker namespace state=present" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:46Z" level=info msg="[playbook task]: automation-broker : Verify service catalog is installed" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:48Z" level=error msg="[failed]: [playbook task] 'Verify service catalog is installed' failed with task_args - msg=Service Catalog must be installed, that=[u'\"servicecatalog.k8s.io\" in lookup(\"k8s\", cluster_info=\"api_groups\")']" component=logging_event_handler event_type=runner_on_failed gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:48Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=8258902912821821880
time="2018-11-26T16:31:48Z" level=error msg="error from ansible-runner: exit status 2" component=runner job=8258902912821821880 name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:48Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=5459287199784753161
time="2018-11-26T16:31:49Z" level=info msg="[playbook task]: automation-broker : Set broker namespace state=present" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:49Z" level=info msg="[playbook task]: automation-broker : Verify service catalog is installed" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:51Z" level=error msg="[failed]: [playbook task] 'Verify service catalog is installed' failed with task_args - msg=Service Catalog must be installed, that=[u'\"servicecatalog.k8s.io\" in lookup(\"k8s\", cluster_info=\"api_groups\")']" component=logging_event_handler event_type=runner_on_failed gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:51Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=5459287199784753161
time="2018-11-26T16:31:51Z" level=error msg="error from ansible-runner: exit status 2" component=runner job=5459287199784753161 name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:51Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=2015931357020424987
time="2018-11-26T16:31:52Z" level=info msg="[playbook task]: automation-broker : Set broker namespace state=present" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:52Z" level=info msg="[playbook task]: automation-broker : Verify service catalog is installed" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:53Z" level=error msg="[failed]: [playbook task] 'Verify service catalog is installed' failed with task_args - msg=Service Catalog must be installed, that=[u'\"servicecatalog.k8s.io\" in lookup(\"k8s\", cluster_info=\"api_groups\")']" component=logging_event_handler event_type=runner_on_failed gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:53Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=2015931357020424987
time="2018-11-26T16:31:53Z" level=error msg="error from ansible-runner: exit status 2" component=runner job=2015931357020424987 name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:53Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=446230090832441730
time="2018-11-26T16:31:55Z" level=info msg="[playbook task]: automation-broker : Set broker namespace state=present" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:55Z" level=info msg="[playbook task]: automation-broker : Verify service catalog is installed" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:55Z" level=error msg="[failed]: [playbook task] 'Verify service catalog is installed' failed with task_args - msg=Service Catalog must be installed, that=[u'\"servicecatalog.k8s.io\" in lookup(\"k8s\", cluster_info=\"api_groups\")']" component=logging_event_handler event_type=runner_on_failed gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:55Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=446230090832441730
time="2018-11-26T16:31:55Z" level=error msg="error from ansible-runner: exit status 2" component=runner job=446230090832441730 name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:56Z" level=info msg="dropping event that is not a JobEvent" component=eventapi job=583322328950460987
time="2018-11-26T16:31:57Z" level=info msg="[playbook task]: automation-broker : Set broker namespace state=present" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:57Z" level=info msg="[playbook task]: automation-broker : Verify service catalog is installed" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:57Z" level=info msg="[playbook task]: automation-broker : Verify broker namespace exists" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:57Z" level=info msg="[playbook task]: automation-broker : Verify the broker has no outstanding service instances if deprovisioning" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:57Z" level=info msg="[playbook task]: automation-broker : Create dashboard redirector route if OpenShift" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" name=automation-broker namespace=automation-broker
time="2018-11-26T16:31:59Z" level=info msg="injecting owner reference"

What you expected to happen

ASB Operator provisions broker successfully in response to automation-broker CR being created, even when default params are provided.

Workaround

Creating this CR instead will result in a working Automation Broker instance:

apiVersion: "automationbroker.io/v1alpha1"                                        
kind: "AutomationBroker"                                                          
metadata:                                                                          
  name: automation-broker                                                        
  namespace: automation-broker                                                    
spec:                                                                                                                   
  createBrokerNamespace: false                                                    
  waitForBroker: false                                                            
  brokerLocalOpenshiftEnabled: true

How to reproduce it

Set up a v3.11 env in catasb, subscribe the automation-broker namespace to the Automation Broker Operator, and create the default automationbroker CR to see the freeze.

The text was updated successfully, but these errors were encountered:

djwhatle · 2018-11-26T19:09:57Z

I need to determine what about the modified CR leads to a successful provision. Unfortunately, pretty inconvenient thing to test since I haven't found a way to retry without resetting the whole cluster.

djzager · 2018-11-26T19:12:57Z

sounds similar to this one #1105

djzager · 2018-11-26T19:13:17Z

Is it possible that the broker operator needs to be rebuilt with the latest ansible operator image?

djwhatle · 2018-11-26T19:27:25Z

@djzager definitely possible. To my knowledge, hasn't been rebuilt in a while.

P.S. had a conversation with @mhrivnak on this and found out that it's possible to clean up in this scenario by manually editing the automationbroker CR and deleting the finalizers section. Should allow for quicker troubleshooting.

djwhatle · 2018-11-26T20:42:46Z

@djzager I rebuilt the ASB operator image using the latest AO base image from water-hole and tried provisioning with the default CR again... still have the same issue with lockup.

Note the updated operator-sdk version number in these new logs:

time="2018-11-26T20:39:58Z" level=info msg="Watching automation-broker namespace."
time="2018-11-26T20:39:58Z" level=info msg="Go Version: go1.10.5"
time="2018-11-26T20:39:58Z" level=info msg="Go OS/Arch: linux/amd64"
time="2018-11-26T20:39:58Z" level=info msg="operator-sdk Version: v0.1.1+git"
time="2018-11-26T20:39:58Z" level=info msg="Starting to serve on 127.0.0.1:8888\n"
time="2018-11-26T20:39:58Z" level=info msg="Watching automationbroker.io/v1alpha1, AutomationBroker"
{"level":"info","ts":1543264798.8120434,"logger":"kubebuilder.controller","caller":"controller/controller.go:120","msg":"Starting EventSource","Controller":"automationbroker-controller","Source":"kind source: automationbroker.io/v1alpha1, Kind=AutomationBroker"}
{"level":"info","ts":1543264798.9125986,"logger":"kubebuilder.controller","caller":"controller/controller.go:134","msg":"Starting Controller","Controller":"automationbroker-controller"}
{"level":"info","ts":1543264799.012966,"logger":"kubebuilder.controller","caller":"controller/controller.go:153","msg":"Starting workers","Controller":"automationbroker-controller","WorkerCount":1}
time="2018-11-26T20:40:19Z" level=info msg="[playbook task]: automation-broker : Set broker namespace state=present" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" job=2155918680542341066 name=automation-broker namespace=automation-broker
time="2018-11-26T20:40:19Z" level=info msg="[playbook task]: automation-broker : Verify service catalog is installed" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" job=2155918680542341066 name=automation-broker namespace=automation-broker
time="2018-11-26T20:40:20Z" level=info msg="[playbook task]: automation-broker : Verify broker namespace exists" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" job=2155918680542341066 name=automation-broker namespace=automation-broker
time="2018-11-26T20:40:20Z" level=info msg="[playbook task]: automation-broker : Verify the broker has no outstanding service instances if deprovisioning" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" job=2155918680542341066 name=automation-broker namespace=automation-broker
time="2018-11-26T20:40:20Z" level=info msg="[playbook task]: automation-broker : Create dashboard redirector route if OpenShift" component=logging_event_handler event_type=playbook_on_task_start gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" job=2155918680542341066 name=automation-broker namespace=automation-broker
time="2018-11-26T20:40:21Z" level=info msg="injecting owner reference"

djwhatle · 2018-11-27T16:12:35Z

@djzager updated my original issue comment. As indicated by the issue you linked that Erik originally wrote, adding brokerLocalOpenshiftEnabled: true to the CR spec fixes the issue:

apiVersion: "automationbroker.io/v1alpha1"                                        
kind: "AutomationBroker"                                                          
[...]                                        
spec:                                                                                                                   
[...]                                   
  brokerLocalOpenshiftEnabled: true

djwhatle · 2018-11-27T17:07:29Z

Had a discussion/found a potential solution for this issue with @djzager and @jmontleon .

After rebuilding ASB operator on the latest ansible-operator image from water-hole based on operator-sdk v0.1.1, using the default CR spec values did work, but lead to very slow completion of each run of the AO reconciliation loop.

Noticed in the ASB operator logs that "Broker ready status" was the final action that ran before seeing "exiting successfully":

time="2018-11-27T16:33:19Z" level=info msg="[playbook debug]: msg=Broker ready status: [u'True']" component=logging_event_handler event_type=runner_on_ok gvk="automationbroker.io/v1alpha1, Kind=AutomationBroker" job=295688355826356509 name=automation-broker namespace=automation-broker

Thought this delayed "Broker ready" message was strange because we specified to not wait for broker readiness so that the reconciliation loop would run quicker:

spec:                                                                                                                   
  [...]
  waitForBroker: "false"                                                          
  [...]

Seeing that the operator was still waiting for broker deploy to complete, we hypothesized that "false" was not parsed as a boolean with value false by the playbook, and that instead the string "false" was being interpreted as a truthy value. When using the OLM web UI, pre-filled spec values always gets stringified as such.

Turns out removing waitForBroker from the spec vars and letting the default value of false get used sped up the reconciliation loop, and now it doesn't feel like the reconciliation loop is freezing at all.

I've verified that removing the quotes around waitForBroker also solves the issue, but since OLM adds the quotes...

Proposed solution

Remove waitForBroker as a default var in sample CR
Add casts from string to boolean in the ASB deploy playbook
Update official ASB operator image to use latest ansible-operator image from water-hole

fabianvf · 2018-11-27T19:01:04Z

Whoops finger slipped, please ignore above activity. Proposal makes sense to me, good find on the source of the issue. I wonder if there are other values failing more silently in similar ways.

djwhatle · 2018-11-27T19:18:27Z

Good point, other quoted boolean values provided in the spec are going to be misinterpreted as well (unless we have boolean casts in place for some vars but not others).

I went ahead and updated docker.io/automationbroker/automation-broker-operator:latest with an operator-sdk v0.1.1 based image, so if you're using catasb to play with this stuff you should be able to successfully deploy ASB with the operator consistently without changing the CR spec.

If you do remove the waitForBroker value specification the reconciliation loop should speed up significantly.

openshift-bot · 2020-08-30T09:48:15Z

Issues go stale after 90d of inactivity.

Mark the issue as fresh by commenting /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.
Exclude this issue from closing by commenting /lifecycle frozen.

If this issue is safe to close now please do so with /close.

/lifecycle stale

jmrodri · 2020-09-20T01:12:00Z

/close

openshift-ci-robot · 2020-09-20T01:12:16Z

@jmrodri: Closing this issue.

In response to this:

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

djwhatle self-assigned this Nov 26, 2018

fabianvf closed this as completed Nov 27, 2018

fabianvf reopened this Nov 27, 2018

openshift-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Aug 30, 2020

openshift-ci-robot closed this as completed Sep 20, 2020

Creating default "automationbroker" CR results in frozen ASB operator stuck on "injecting owner reference" #1138

Creating default "automationbroker" CR results in frozen ASB operator stuck on "injecting owner reference" #1138

djwhatle commented Nov 26, 2018 •

edited

djwhatle commented Nov 26, 2018

djzager commented Nov 26, 2018

djzager commented Nov 26, 2018

djwhatle commented Nov 26, 2018

djwhatle commented Nov 26, 2018

djwhatle commented Nov 27, 2018

djwhatle commented Nov 27, 2018 •

edited

fabianvf commented Nov 27, 2018

djwhatle commented Nov 27, 2018 •

edited

openshift-bot commented Aug 30, 2020

jmrodri commented Sep 20, 2020

openshift-ci-robot commented Sep 20, 2020

Creating default "automationbroker" CR results in frozen ASB operator stuck on "injecting owner reference" #1138

Creating default "automationbroker" CR results in frozen ASB operator stuck on "injecting owner reference" #1138

Comments

djwhatle commented Nov 26, 2018 • edited

Bug: Creating default "automationbroker" CR results in frozen ASB operator

What happened

What you expected to happen

Workaround

How to reproduce it

djwhatle commented Nov 26, 2018

djzager commented Nov 26, 2018

djzager commented Nov 26, 2018

djwhatle commented Nov 26, 2018

djwhatle commented Nov 26, 2018

djwhatle commented Nov 27, 2018

djwhatle commented Nov 27, 2018 • edited

fabianvf commented Nov 27, 2018

djwhatle commented Nov 27, 2018 • edited

openshift-bot commented Aug 30, 2020

jmrodri commented Sep 20, 2020

openshift-ci-robot commented Sep 20, 2020

djwhatle commented Nov 26, 2018 •

edited

djwhatle commented Nov 27, 2018 •

edited

djwhatle commented Nov 27, 2018 •

edited