1676533 – kuryr-controller pod restarts continuously (liveness probe fails) due to a load balancer in error status

Bug 1676533 - kuryr-controller pod restarts continuously (liveness probe fails) due to a load balancer in error status

Summary: kuryr-controller pod restarts continuously (liveness probe fails) due to a lo...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat OpenStack
Classification:	Red Hat
Component:	openstack-kuryr-kubernetes
Sub Component:
Version:	14.0 (Rocky)
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	z2
Target Release:	14.0 (Rocky)
Assignee:	Luis Tomas Bolivar
QA Contact:	Jon Uriarte
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2019-02-12 13:55 UTC by Jon Uriarte
Modified:	2019-04-30 17:47 UTC (History)
CC List:	3 users (show)
Fixed In Version:	openstack-kuryr-kubernetes-0.5.4-0.20190220170509.17d2635.el7ost
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2019-04-30 17:47:41 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Priority	Status	Summary	Last Updated
Launchpad	1815880	None	None	None	2019-02-14 09:36:53 UTC
OpenStack gerrit	636890	'None'	MERGED	Ensure kuryr-controller recover from lb in ERROR status	2021-01-15 14:08:29 UTC
OpenStack gerrit	637724	'None'	MERGED	Ensure kuryr-controller recover from lb in ERROR status	2021-01-15 14:07:50 UTC
Red Hat Product Errata	RHBA-2019:0944	None	None	None	2019-04-30 17:47:49 UTC

Description Jon Uriarte 2019-02-12 13:55:54 UTC

Description of problem:

In a OCP 3.11 on OSP 13 deployment (with latest kuryr OSP 14 images), where the load balancer for Grafana service remains in ERROR status, the kuryr-controller pod
restarts continuously due to liveness probe fails. As there is one Openstack resource (Octavia load balancer) not ready, kuryr-controller is restarted without acting, but could try re-creating the load balancer. If not the cluster will not be recovered without manual intervention.


(shiftstack) [stack@undercloud-0 ~]$ openstack loadbalancer list 
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+
| id                                   | name                                                | project_id                       | vip_address    | provisioning_status | provider |
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+
| 6d7918e1-3325-4b7e-a1a8-e5f5786bbe75 | openshift.example.com-router_lb-4dkarghdhr2t        | 34dee1757cfd4587a280f14e7178df85 | 192.168.99.15  | ACTIVE              | octavia  |
| 2a3fe2be-ee6f-4d3e-9e44-06c43163095c | openshift-ansible-openshift.example.com-api-lb      | 34dee1757cfd4587a280f14e7178df85 | 172.30.0.1     | ACTIVE              | octavia  |
| 9c697e69-2092-4937-836c-d7fe469a4dac | default/registry-console                            | 34dee1757cfd4587a280f14e7178df85 | 172.30.69.211  | ACTIVE              | octavia  |
| 82a15f0c-d5f7-4f00-a04c-552bbfeaedca | default/docker-registry                             | 34dee1757cfd4587a280f14e7178df85 | 172.30.139.113 | ACTIVE              | octavia  |
| c8a82a05-d3a5-41a6-bc16-a792d51f6a40 | openshift-console/console                           | 34dee1757cfd4587a280f14e7178df85 | 172.30.184.73  | ACTIVE              | octavia  |
| c33d6f4e-d3e9-491e-b796-2fdaafd76802 | default/router                                      | 34dee1757cfd4587a280f14e7178df85 | 172.30.240.55  | ACTIVE              | octavia  |
| 3af9ccb5-8f01-4e35-97bb-99409fe77887 | openshift-monitoring/grafana                        | 34dee1757cfd4587a280f14e7178df85 | 172.30.65.194  | ERROR               | octavia  |
| 2eaf9773-765c-4b83-b370-d44bcea3c4c6 | openshift-monitoring/prometheus-k8s                 | 34dee1757cfd4587a280f14e7178df85 | 172.30.41.49   | ACTIVE              | octavia  |
| 97f288b6-c9a5-4db3-af14-5b1e737f3991 | openshift-monitoring/alertmanager-main              | 34dee1757cfd4587a280f14e7178df85 | 172.30.160.252 | ACTIVE              | octavia  |
| 00c6955f-0680-42ab-9fc9-324a359f5d03 | kuryr-namespace-1881136123/kuryr-service-1008340407 | 34dee1757cfd4587a280f14e7178df85 | 172.30.42.187  | ACTIVE              | octavia  |
| a6329735-93bf-41f2-b84e-84bc0133674f | kuryr-namespace-2076772217/kuryr-service-798555397  | 34dee1757cfd4587a280f14e7178df85 | 172.30.42.24   | ACTIVE              | octavia  |
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+

kuryr-controller logs:
---------------------

2019-02-12 13:35:12.108 1 INFO werkzeug [-] 192.168.99.10 - - [12/Feb/2019 13:35:12] "GET /alive HTTP/1.1" 200 -
2019-02-12 13:35:14.363 1 INFO kuryr_kubernetes.controller.managers.health [-] Kuryr Controller readiness verified.
2019-02-12 13:35:14.364 1 INFO werkzeug [-] 192.168.99.10 - - [12/Feb/2019 13:35:14] "GET /ready HTTP/1.1" 200 -
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging [-] Failed to handle event {u'object': {u'kind': u'Endpoints', u'subsets': [{u'addresses': [{u'ip': u'10.11.4.4', u'targetRe
f': {u'kind': u'Pod', u'resourceVersion': u'4694', u'namespace': u'openshift-monitoring', u'name': u'grafana-c7d5bc87c-q5v2x', u'uid': u'75d42baf-293c-11e9-ac53-fa163e4ed872'}, u'nodeName': 
u'infra-node-0.openshift.example.com'}], u'ports': [{u'protocol': u'TCP', u'name': u'https', u'port': 3000}]}], u'apiVersion': u'v1', u'metadata': {u'name': u'grafana', u'namespace': u'opens
hift-monitoring', u'resourceVersion': u'4695', u'creationTimestamp': u'2019-02-05T11:52:06Z', u'annotations': {u'openstack.org/kuryr-lbaas-spec': u'{"versioned_object.data": {"ip": "172.30.6
5.194", "lb_ip": null, "ports": [{"versioned_object.data": {"name": "https", "port": 3000, "protocol": "TCP"}, "versioned_object.name": "LBaaSPortSpec", "versioned_object.namespace": "kuryr_
kubernetes", "versioned_object.version": "1.0"}], "project_id": "34dee1757cfd4587a280f14e7178df85", "security_groups_ids": ["e1721617-e4a7-456a-b2f4-d3a7e44948df", "ceab5d40-be83-44c3-bd75-a
6bcaa0d21ff"], "subnet_id": "a69c1f10-4874-4f9e-b0a4-6466972615b2", "type": "ClusterIP"}, "versioned_object.name": "LBaaSServiceSpec", "versioned_object.namespace": "kuryr_kubernetes", "vers
ioned_object.version": "1.0"}'}, u'selfLink': u'/api/v1/namespaces/openshift-monitoring/endpoints/grafana', u'uid': u'75c2c99e-293c-11e9-ac53-fa163e4ed872'}}, u'type': u'ADDED'}: ResourceNot
Ready: Resource not ready: LBaaSLoadBalancer(id=3af9ccb5-8f01-4e35-97bb-99409fe77887,ip=172.30.65.194,name='openshift-monitoring/grafana',port_id=4d59f238-5b08-4e38-8028-631ba4b2201e,project
_id='34dee1757cfd4587a280f14e7178df85',provider='octavia',security_groups=[e1721617-e4a7-456a-b2f4-d3a7e44948df,ceab5d40-be83-44c3-bd75-a6bcaa0d21ff],subnet_id=a69c1f10-4874-4f9e-b0a4-646697
2615b2)                                                                                                                                                                                       
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging Traceback (most recent call last):
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/logging.py", line 37, in __call__
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     self._handler(event)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/retry.py", line 63, in __call__
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     self._handler.set_health_status(healthy=False)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     self.force_reraise()                                                                                                    
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     six.reraise(self.type_, self.value, self.tb)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/retry.py", line 55, in __call__
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     self._handler(event)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/k8s_base.py", line 75, in __call__
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     self.on_present(obj)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 243, in on_present            
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     if self._sync_lbaas_members(endpoints, lbaas_state, lbaas_spec):
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 318, in _sync_lbaas_members   
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     if self._sync_lbaas_pools(endpoints, lbaas_state, lbaas_spec):
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 428, in _sync_lbaas_pools     
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     if self._sync_lbaas_listeners(endpoints, lbaas_state, lbaas_spec):
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 488, in _sync_lbaas_listeners 
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     if self._add_new_listeners(endpoints, lbaas_spec, lbaas_state):                                                         
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 507, in _add_new_listeners    
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     service_type=lbaas_spec.type)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/lbaasv2.py", line 232, in ensure_listener      
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     self._find_listener)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/lbaasv2.py", line 489, in _ensure_provisioned  
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     self._wait_for_provisioning(loadbalancer, remaining)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/lbaasv2.py", line 528, in _wait_for_provisionin
g                                                                                                                                                                                             
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging     raise k_exc.ResourceNotReady(loadbalancer)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging ResourceNotReady: Resource not ready: LBaaSLoadBalancer(id=3af9ccb5-8f01-4e35-97bb-99409fe77887,ip=172.30.65.194,name='opens
hift-monitoring/grafana',port_id=4d59f238-5b08-4e38-8028-631ba4b2201e,project_id='34dee1757cfd4587a280f14e7178df85',provider='octavia',security_groups=[e1721617-e4a7-456a-b2f4-d3a7e44948df,ceab5d40-be83-44c3-bd75-a6bcaa0d21ff],subnet_id=a69c1f10-4874-4f9e-b0a4-6466972615b2)
2019-02-12 13:35:20.631 1 ERROR kuryr_kubernetes.handlers.logging
2019-02-12 13:35:22.108 1 INFO werkzeug [-] 192.168.99.10 - - [12/Feb/2019 13:35:22] "GET /alive HTTP/1.1" 500 -
2019-02-12 13:35:24.286 1 INFO kuryr_kubernetes.controller.managers.health [-] Kuryr Controller readiness verified.                                                                           
2019-02-12 13:35:24.287 1 INFO werkzeug [-] 192.168.99.10 - - [12/Feb/2019 13:35:24] "GET /ready HTTP/1.1" 200 -
2019-02-12 13:35:32.108 1 INFO werkzeug [-] 192.168.99.10 - - [12/Feb/2019 13:35:32] "GET /alive HTTP/1.1" 500 -
2019-02-12 13:35:34.255 1 INFO kuryr_kubernetes.controller.managers.health [-] Kuryr Controller readiness verified.
2019-02-12 13:35:34.256 1 INFO werkzeug [-] 192.168.99.10 - - [12/Feb/2019 13:35:34] "GET /ready HTTP/1.1" 200 -
2019-02-12 13:35:42.108 1 INFO werkzeug [-] 192.168.99.10 - - [12/Feb/2019 13:35:42] "GET /alive HTTP/1.1" 500 -
2019-02-12 13:35:42.419 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopping
2019-02-12 13:35:42.420 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/namespaces'
2019-02-12 13:35:42.420 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/pods'
2019-02-12 13:35:42.421 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/endpoints'
2019-02-12 13:35:42.421 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/services'
2019-02-12 13:35:42.421 1 INFO kuryr_kubernetes.watcher [-] No remaining active watchers, Exiting...
2019-02-12 13:35:42.422 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopping
2019-02-12 13:35:42.423 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopped


Version-Release number of selected component (if applicable):
"https://access.redhat.com/containers/#/registry.access.redhat.com/rhosp14/openstack-kuryr-controller/images/14.0-140"


How reproducible: A load balancer needs to be in ERROR status in order to reproduce it.


Steps to Reproduce:
1. Install OSP 13 with Octavia in a hybrid environment

2. Run OCP 3.11 installation playbooks
   · Use latest OSP 14 kuryr images (or 14.0-140 images):
        - openshift_openstack_kuryr_controller_image: "docker-registry.engineering.redhat.com/rhosp14/openstack-kuryr-controller:latest"                                                                
        - openshift_openstack_kuryr_cni_image: "docker-registry.engineering.redhat.com/rhosp14/openstack-kuryr-cni:latest"   

3. Check the kuryr-controller pod restart count does not increment.

Actual results:

NAMESPACE                    NAME                                                READY     STATUS             RESTARTS   AGE       IP              NODE                                 
openshift-infra              kuryr-controller-6c6d965c54-7r248                   1/1       Running            1842       7d        192.168.99.10   infra-node-0.openshift.example.com


Expected results:
kuryr-controller pod restart count should not increment so much.

Comment 7 Jon Uriarte 2019-04-16 10:26:12 UTC

Verified in:
 openstack-kuryr-kubernetes-common-0.5.4-0.20190220170509.17d2635.el7ost.noarch
 openstack-kuryr-kubernetes-controller-0.5.4-0.20190220170509.17d2635.el7ost.noarch

Verification steps:
1. Install OSP 14 with Octavia in a hybrid environment

2. Run OCP 3.11 installation playbooks
   · Use OSP 14.0-150 kuryr images

3. Create new project and pod
$ oc new-project bz1676533
$ oc run --image kuryr/demo demo
$ oc get pods
NAME           READY     STATUS    RESTARTS   AGE
demo-1-lttnh   1/1       Running   0          1m

4. Disable compute service so the new loadbalancer fails creating
$ openstack compute service list
+----+------------------+--------------------------+----------+---------+-------+----------------------------+
| ID | Binary           | Host                     | Zone     | Status  | State | Updated At                 |
+----+------------------+--------------------------+----------+---------+-------+----------------------------+
|  1 | nova-conductor   | controller-0.localdomain | internal | enabled | up    | 2019-04-16T08:13:16.000000 |
|  2 | nova-consoleauth | controller-0.localdomain | internal | enabled | up    | 2019-04-16T08:13:13.000000 |
|  3 | nova-scheduler   | controller-0.localdomain | internal | enabled | up    | 2019-04-16T08:13:22.000000 |
| 10 | nova-compute     | compute-0.localdomain    | nova     | enabled | up    | 2019-04-16T08:13:13.000000 |
+----+------------------+--------------------------+----------+---------+-------+----------------------------+

$ openstack compute service set --disable --disable-reason "Verifying BZ1676533" compute-0.localdomain nova-compute
$ openstack compute service list
+----+------------------+--------------------------+----------+----------+-------+----------------------------+
| ID | Binary           | Host                     | Zone     | Status   | State | Updated At                 |
+----+------------------+--------------------------+----------+----------+-------+----------------------------+
|  1 | nova-conductor   | controller-0.localdomain | internal | enabled  | up    | 2019-04-16T08:13:26.000000 |
|  2 | nova-consoleauth | controller-0.localdomain | internal | enabled  | up    | 2019-04-16T08:13:33.000000 |
|  3 | nova-scheduler   | controller-0.localdomain | internal | enabled  | up    | 2019-04-16T08:13:32.000000 |
| 10 | nova-compute     | compute-0.localdomain    | nova     | disabled | up    | 2019-04-16T08:13:33.000000 |
+----+------------------+--------------------------+----------+----------+-------+----------------------------+

5. Create a new service
$ oc expose dc/demo --port 80 --target-port 8080
$ oc get svc
NAME      TYPE        CLUSTER-IP       EXTERNAL-IP   PORT(S)   AGE
demo      ClusterIP   172.30.126.191   <none>        80/TCP    11s

6. Check the loadbalancer is in ERROR status
$ openstack loadbalancer list
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+
| id                                   | name                                                | project_id                       | vip_address    | provisioning_status | provider |
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+
| 9e2f81d3-e020-4e09-aec0-25f858d1014f | bz1676533/demo                                      | 33167bf65e17489aa9673acef89bca84 | 172.30.126.191 | ERROR               | amphora  |
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+

7. Enable compute service so a new loadbalancer can be created
$ openstack compute service set --enable compute-0.localdomain nova-compute                                                      
$ openstack compute service list
+----+------------------+--------------------------+----------+---------+-------+----------------------------+
| ID | Binary           | Host                     | Zone     | Status  | State | Updated At                 |
+----+------------------+--------------------------+----------+---------+-------+----------------------------+
|  1 | nova-conductor   | controller-0.localdomain | internal | enabled | up    | 2019-04-16T08:33:46.000000 |
|  2 | nova-consoleauth | controller-0.localdomain | internal | enabled | up    | 2019-04-16T08:33:53.000000 |
|  3 | nova-scheduler   | controller-0.localdomain | internal | enabled | up    | 2019-04-16T08:33:52.000000 |
| 10 | nova-compute     | compute-0.localdomain    | nova     | enabled | up    | 2019-04-16T08:33:53.000000 |
+----+------------------+--------------------------+----------+---------+-------+----------------------------+

8. Check kuryr controller logs:
2019-04-16 09:41:49.915 1 DEBUG kuryr_kubernetes.controller.drivers.lbaasv2 [-] Provisioning status ERROR for LBaaSLoadBalancer(id=ebd22a68-2147-4519-a602-cc6a89db201d,ip=172.30.131.110,name='bz1676533/demo',port_id=d8948bd5-8170-433c-8f0a-5de9ed7c18bf,project_id='33167bf65e17489aa9673acef89bca84',provider='amphora',security_groups=[ca290c54-9e52-4648-8611-ed2efd7cca22,35df2609-c458-4b2c-97c1-42f35415669d],subnet_id=d8
0efc17-83e6-4f82-a2ad-04febab26ef8), 199s remaining until timeout _wait_for_provisioning /usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/lbaasv2.py:558


2019-04-16 09:45:09.126 1 DEBUG kuryr_kubernetes.handlers.retry [-] Handler LoadBalancerHandler failed (attempt 1; ResourceNotReady: Resource not ready: LBaaSLoadBalancer(id=ebd22a68-2147-4519-a602-cc6a89db201d,
ip=172.30.131.110,name='bz1676533/demo',port_id=d8948bd5-8170-433c-8f0a-5de9ed7c18bf,project_id='33167bf65e17489aa9673acef89bca84',provider='amphora',security_groups=[ca290c54-9e52-4648-8611-ed2efd7cca22,35df260
9-c458-4b2c-97c1-42f35415669d],subnet_id=d80efc17-83e6-4f82-a2ad-04febab26ef8)), timeout exceeded (180 seconds) _sleep /usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/retry.py:78
2019-04-16 09:45:09.126 1 DEBUG kuryr_kubernetes.handlers.retry [-] Report handler unhealthy LoadBalancerHandler __call__ /usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/retry.py:62
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging [-] Failed to handle event {u'object': {u'kind': u'Endpoints', u'subsets': [{u'addresses': [{u'ip': u'10.11.22.12', u'targetRef': {u'kind': u'Pod
', u'resourceVersion': u'1638454', u'namespace': u'bz1676533', u'name': u'demo-1-lttnh', u'uid': u'607b357c-602b-11e9-8294-fa163e10e020'}, u'nodeName': u'app-node-1.openshift.example.com'}], u'ports': [{u'protoc
ol': u'TCP', u'port': 8080}]}], u'apiVersion': u'v1', u'metadata': {u'name': u'demo', u'labels': {u'run': u'demo'}, u'namespace': u'bz1676533', u'resourceVersion': u'1638587', u'creationTimestamp': u'2019-04-16T
09:40:06Z', u'annotations': {u'openstack.org/kuryr-lbaas-spec': u'{"versioned_object.data": {"ip": "172.30.131.110", "lb_ip": null, "ports": [{"versioned_object.data": {"name": null, "port": 80, "protocol": "TCP
"}, "versioned_object.name": "LBaaSPortSpec", "versioned_object.namespace": "kuryr_kubernetes", "versioned_object.version": "1.0"}], "project_id": "33167bf65e17489aa9673acef89bca84", "security_groups_ids": ["ca2
90c54-9e52-4648-8611-ed2efd7cca22", "35df2609-c458-4b2c-97c1-42f35415669d"], "subnet_id": "d80efc17-83e6-4f82-a2ad-04febab26ef8", "type": "ClusterIP"}, "versioned_object.name": "LBaaSServiceSpec", "versioned_obj
ect.namespace": "kuryr_kubernetes", "versioned_object.version": "1.0"}'}, u'selfLink': u'/api/v1/namespaces/bz1676533/endpoints/demo', u'uid': u'9de80e9f-602b-11e9-8294-fa163e10e020'}}, u'type': u'MODIFIED'}: Re
sourceNotReady: Resource not ready: LBaaSLoadBalancer(id=ebd22a68-2147-4519-a602-cc6a89db201d,ip=172.30.131.110,name='bz1676533/demo',port_id=d8948bd5-8170-433c-8f0a-5de9ed7c18bf,project_id='33167bf65e17489aa967
3acef89bca84',provider='amphora',security_groups=[ca290c54-9e52-4648-8611-ed2efd7cca22,35df2609-c458-4b2c-97c1-42f35415669d],subnet_id=d80efc17-83e6-4f82-a2ad-04febab26ef8)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging Traceback (most recent call last):
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/logging.py", line 37, in __call__
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     self._handler(event)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/retry.py", line 63, in __call__
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     self._handler.set_health_status(healthy=False)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     self.force_reraise()
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     six.reraise(self.type_, self.value, self.tb)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/retry.py", line 55, in __call__
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     self._handler(event)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/k8s_base.py", line 72, in __call__
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     self.on_present(obj)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 242, in on_present
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     if self._sync_lbaas_members(endpoints, lbaas_state, lbaas_spec):
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 327, in _sync_lbaas_members
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     if self._sync_lbaas_pools(endpoints, lbaas_state, lbaas_spec):
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 460, in _sync_lbaas_pools
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     if self._sync_lbaas_listeners(endpoints, lbaas_state, lbaas_spec):
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 520, in _sync_lbaas_listeners
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     if self._add_new_listeners(endpoints, lbaas_spec, lbaas_state):
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py", line 539, in _add_new_listeners
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     service_type=lbaas_spec.type)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/lbaasv2.py", line 257, in ensure_listener
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     self._find_listener)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/lbaasv2.py", line 521, in _ensure_provisioned
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     self._wait_for_provisioning(loadbalancer, remaining)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/lbaasv2.py", line 560, in _wait_for_provisioning
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging     raise k_exc.ResourceNotReady(loadbalancer)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging ResourceNotReady: Resource not ready: LBaaSLoadBalancer(id=ebd22a68-2147-4519-a602-cc6a89db201d,ip=172.30.131.110,name='bz1676533/demo',port_id=d
8948bd5-8170-433c-8f0a-5de9ed7c18bf,project_id='33167bf65e17489aa9673acef89bca84',provider='amphora',security_groups=[ca290c54-9e52-4648-8611-ed2efd7cca22,35df2609-c458-4b2c-97c1-42f35415669d],subnet_id=d80efc17
-83e6-4f82-a2ad-04febab26ef8)
2019-04-16 09:45:09.126 1 ERROR kuryr_kubernetes.handlers.logging 
2019-04-16 09:45:09.731 1 DEBUG kuryr_kubernetes.controller.managers.health [-] Kuryr Controller not healthy. liveness_status /usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/managers/health.py:95
2019-04-16 09:45:09.731 1 INFO werkzeug [-] 192.168.99.25 - - [16/Apr/2019 09:45:09] "GET /alive HTTP/1.1" 500 -
2019-04-16 09:45:09.761 1 INFO kuryr_kubernetes.controller.managers.health [-] Kuryr Controller readiness verified.
2019-04-16 09:45:09.762 1 INFO werkzeug [-] 192.168.99.25 - - [16/Apr/2019 09:45:09] "GET /ready HTTP/1.1" 200 -
2019-04-16 09:45:14.135 1 DEBUG kuryr_kubernetes.handlers.asynchronous [-] Asynchronous handler stopped processing group 9de80e9f-602b-11e9-8294-fa163e10e020 _done /usr/lib/python2.7/site-packages/kuryr_kubernet
es/handlers/asynchronous.py:102
2019-04-16 09:45:14.135 1 DEBUG kuryr_kubernetes.handlers.asynchronous [-] Asynchronous handler is idle _done /usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/asynchronous.py:111
2019-04-16 09:45:18.144 1 DEBUG kuryr_kubernetes.k8s_client [-] Get /healthz get /usr/lib/python2.7/site-packages/kuryr_kubernetes/k8s_client.py:69
2019-04-16 09:45:19.731 1 DEBUG kuryr_kubernetes.controller.managers.health [-] Kuryr Controller not healthy. liveness_status /usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/managers/health.py:95
2019-04-16 09:45:19.732 1 INFO werkzeug [-] 192.168.99.25 - - [16/Apr/2019 09:45:19] "GET /alive HTTP/1.1" 500 -
2019-04-16 09:45:19.785 1 INFO kuryr_kubernetes.controller.managers.health [-] Kuryr Controller readiness verified.
2019-04-16 09:45:19.786 1 INFO werkzeug [-] 192.168.99.25 - - [16/Apr/2019 09:45:19] "GET /ready HTTP/1.1" 200 -
2019-04-16 09:45:25.639 1 DEBUG oslo_concurrency.lockutils [-] Lock "return_to_pool_nested" acquired by "kuryr_kubernetes.controller.drivers.vif_pool._trigger_return_to_pool" :: waited 0.000s inner /usr/lib/pyth
on2.7/site-packages/oslo_concurrency/lockutils.py:273
2019-04-16 09:45:26.255 1 DEBUG oslo_concurrency.lockutils [-] Lock "return_to_pool_nested" released by "kuryr_kubernetes.controller.drivers.vif_pool._trigger_return_to_pool" :: held 0.615s inner /usr/lib/python
2.7/site-packages/oslo_concurrency/lockutils.py:285
2019-04-16 09:45:26.920 1 DEBUG kuryr_kubernetes.handlers.asynchronous [-] Asynchronous handler started processing b5ad7db5-57b4-11e9-8294-fa163e10e020 _run /usr/lib/python2.7/site-packages/kuryr_kubernetes/hand
lers/asynchronous.py:64
2019-04-16 09:45:27.921 1 DEBUG kuryr_kubernetes.handlers.dispatch [-] 1 handler(s) available __call__ /usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/dispatch.py:62
2019-04-16 09:45:27.922 1 DEBUG kuryr_kubernetes.controller.handlers.lbaas [-] LBaaS spec is missing for /api/v1/namespaces/openshift-monitoring/services/grafana _has_ip_changes /usr/lib/python2.7/site-packages/
kuryr_kubernetes/controller/handlers/lbaas.py:150
2019-04-16 09:45:27.923 1 DEBUG dogpile.lock [-] NeedRegenerationException _enter /usr/lib/python2.7/site-packages/dogpile/lock.py:90
2019-04-16 09:45:27.923 1 DEBUG dogpile.lock [-] no value, waiting for create lock _enter_create /usr/lib/python2.7/site-packages/dogpile/lock.py:123
2019-04-16 09:45:27.923 1 DEBUG dogpile.lock [-] value creation lock <dogpile.cache.backends.null.NullLock object at 0x7f8f701835d0> acquired _enter_create /usr/lib/python2.7/site-packages/dogpile/lock.py:127
2019-04-16 09:45:27.923 1 DEBUG dogpile.lock [-] Calling creation function _enter_create /usr/lib/python2.7/site-packages/dogpile/lock.py:144
2019-04-16 09:45:28.144 1 DEBUG kuryr_kubernetes.k8s_client [-] Get /healthz get /usr/lib/python2.7/site-packages/kuryr_kubernetes/k8s_client.py:69
2019-04-16 09:45:28.207 1 DEBUG dogpile.lock [-] Released creation lock _enter_create /usr/lib/python2.7/site-packages/dogpile/lock.py:150
2019-04-16 09:45:28.208 1 DEBUG kuryr_kubernetes.k8s_client [-] Get /api/v1/namespaces/openshift-monitoring get /usr/lib/python2.7/site-packages/kuryr_kubernetes/k8s_client.py:69
2019-04-16 09:45:28.227 1 DEBUG kuryr_kubernetes.k8s_client [-] Get /apis/openstack.org/v1/kuryrnets/ns-openshift-monitoring get /usr/lib/python2.7/site-packages/kuryr_kubernetes/k8s_client.py:69
2019-04-16 09:45:28.246 1 DEBUG kuryr_kubernetes.controller.handlers.lbaas [-] Setting LBaaSServiceSpec annotation: LBaaSServiceSpec(ip=172.30.196.164,lb_ip=None,ports=[LBaaSPortSpec],project_id='33167bf65e17489
aa9673acef89bca84',security_groups_ids=[6799bace-15df-4efa-abe6-6fa2ed46883a,35df2609-c458-4b2c-97c1-42f35415669d],subnet_id=d80efc17-83e6-4f82-a2ad-04febab26ef8,type='ClusterIP') _set_lbaas_spec /usr/lib/python
2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py:184
2019-04-16 09:45:28.247 1 DEBUG kuryr_kubernetes.k8s_client [-] Annotate /api/v1/namespaces/openshift-monitoring/endpoints/grafana: ['openstack.org/kuryr-lbaas-spec'] annotate /usr/lib/python2.7/site-packages/ku
ryr_kubernetes/k8s_client.py:142
2019-04-16 09:45:28.268 1 DEBUG kuryr_kubernetes.k8s_client [-] Annotate /api/v1/namespaces/openshift-monitoring/services/grafana: ['openstack.org/kuryr-lbaas-spec'] annotate /usr/lib/python2.7/site-packages/kur
yr_kubernetes/k8s_client.py:142
2019-04-16 09:45:28.800 1 DEBUG kuryr_kubernetes.handlers.dispatch [-] 1 handler(s) available __call__ /usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/dispatch.py:62
2019-04-16 09:45:28.809 1 DEBUG kuryr_kubernetes.controller.handlers.lbaas [-] Got LBaaSServiceSpec from annotation: LBaaSServiceSpec(ip=172.30.196.164,lb_ip=None,ports=[LBaaSPortSpec],project_id='33167bf65e1748
9aa9673acef89bca84',security_groups_ids=[6799bace-15df-4efa-abe6-6fa2ed46883a,35df2609-c458-4b2c-97c1-42f35415669d],subnet_id=d80efc17-83e6-4f82-a2ad-04febab26ef8,type='ClusterIP') _get_lbaas_spec /usr/lib/pytho
n2.7/site-packages/kuryr_kubernetes/controller/handlers/lbaas.py:211
2019-04-16 09:45:29.732 1 DEBUG kuryr_kubernetes.controller.managers.health [-] Kuryr Controller not healthy. liveness_status /usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/managers/health.py:95
2019-04-16 09:45:29.732 1 INFO werkzeug [-] 192.168.99.25 - - [16/Apr/2019 09:45:29] "GET /alive HTTP/1.1" 500 -
2019-04-16 09:45:29.828 1 INFO kuryr_kubernetes.controller.managers.health [-] Kuryr Controller readiness verified.
2019-04-16 09:45:29.829 1 INFO werkzeug [-] 192.168.99.25 - - [16/Apr/2019 09:45:29] "GET /ready HTTP/1.1" 200 -
2019-04-16 09:45:30.049 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopping

9. Check Kuryr controller pod is restarted
[openshift@master-0 ~]$ oc get pods -n kuryr
NAME                               READY     STATUS    RESTARTS   AGE
kuryr-cni-ds-5vm4t                 2/2       Running   0          10d
kuryr-cni-ds-8zs8w                 2/2       Running   0          10d
kuryr-cni-ds-mhpv2                 2/2       Running   0          10d
kuryr-cni-ds-wnckk                 2/2       Running   0          10d
kuryr-controller-859b5c897-mdstk   1/1       Running   1          16m

10. Check a new load balancer is created
$ openstack loadbalancer list

+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+
| id                                   | name                                                | project_id                       | vip_address    | provisioning_status | provider |
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+
| 1d919d49-8571-4f99-89ad-0d5b2963b7cb | bz1676533/demo                                      | 33167bf65e17489aa9673acef89bca84 | 172.30.131.110 | ACTIVE              | amphora  |
+--------------------------------------+-----------------------------------------------------+----------------------------------+----------------+---------------------+----------+

11. Check connectivity with the service
[openshift@master-0 ~]$ oc get svc
NAME      TYPE        CLUSTER-IP       EXTERNAL-IP   PORT(S)   AGE
demo      ClusterIP   172.30.131.110   <none>        80/TCP    15m

[openshift@master-0 ~]$ curl 172.30.131.110
demo-1-lttnh: HELLO! I AM ALIVE!!!

Comment 9 errata-xmlrpc 2019-04-30 17:47:41 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-2019:0944

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