Bug 1761507

Summary: Neutron internal error when activating vif or adding subports to trunk crashes kuryr-controller
Product: OpenShift Container Platform Reporter: Luis Tomas Bolivar <ltomasbo>
Component: NetworkingAssignee: Luis Tomas Bolivar <ltomasbo>
Networking sub component: kuryr QA Contact: Jon Uriarte <juriarte>
Status: CLOSED ERRATA Docs Contact:
Severity: medium    
Priority: unspecified CC: gcheresh, juriarte, piqin
Version: 4.2.0Keywords: Triaged
Target Milestone: ---   
Target Release: 4.2.z   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1761505 Environment:
Last Closed: 2019-11-13 18:55:51 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1761505    
Bug Blocks:    

Description Luis Tomas Bolivar 2019-10-14 14:31:55 UTC 
+++ This bug was initially created as a clone of Bug #1761505 +++

Neutron errors when trying to check if a port is active or when trying to add new subports to a trunk may crash kuryr-controller, while they should simply be retried:

Activation error:
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging Traceback (most recent call last): │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/logging.py", line 37, in __call__ │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging self._handler(event) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/retry.py", line 56, in __call__ │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging self._handler(event) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/handlers/k8s_base.py", line 72, in __call__ │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging self.on_present(obj) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/handlers/vif.py", line 148, in on_present │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging self._drv_vif_pool.activate_vif(pod, vif) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/vif_pool.py", line 1052, in activate_vif │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging self._vif_drvs[vif_drv_alias].activate_vif(pod, vif) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/vif_pool.py", line 169, in activate_vif │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging self._drv_vif.activate_vif(pod, vif) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/neutron_vif.py", line 90, in activate_vif │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging port = neutron.show_port(vif.id).get('port') │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 799, in show_port │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging return self.get(self.port_path % (port), params=_params) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 354, in get │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging headers=headers, params=params) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 331, in retry_request │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging headers=headers, params=params) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 282, in do_request │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging headers=headers) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 340, in do_request │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging return self.request(url, method, **kwargs) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 328, in request │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging resp = super(SessionClient, self).request(*args, **kwargs) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/keystoneauth1/adapter.py", line 248, in request │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging return self.session.request(url, method, **kwargs) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/keystoneauth1/session.py", line 888, in request │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging resp = send(**kwargs) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python2.7/site-packages/keystoneauth1/session.py", line 995, in _send_request │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging raise exceptions.ConnectFailure(msg) │
2019-10-14 10:44:01.816 1 ERROR kuryr_kubernetes.handlers.logging ConnectFailure: Unable to establish connection to http://10.0.0.112:9696/v2.0/ports/811223fc-1a49-4d14-9e6f-3bf53e580990: ('Connection aborted.',│
 BadStatusLine("''",))

Sub2019-10-14 11:31:42.882 1 ERROR kuryr_kubernetes.controller.drivers.nested_vlan_vif [-] Error happened during subport addition to trunk: InternalServerError: Request Failed: internal server error while processin│g your request.
                                                                                                                                                                                                  │2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif Traceback (most recent call last): │2019-10-14 11:31:42.882 1 ERROR kuryr_kubernetes.controller.drivers.nested_vlan_vif File "/usr/lib/python2.7/site-packages/kuryr_kubernetes/controller/drivers/nested_vlan_vif.py", line 96, in request_vifs │2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif {'sub_ports': subports_info}) │2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 2132, in trunk_add_subports │2019-10-14 11:31:42.882 1 ERROR

kuryr_kubernetes.controller.drivers.nested_vlan_vif return self.put(self.subports_add_path % (trunk), body=body) 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 363, in put 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif headers=headers, params=params) 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 331, in retry_request 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif headers=headers, params=params) 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 294, in do_request 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif self._handle_fault_response(status_code, replybody, resp) 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 269, in _handle_fault_response 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif exception_handler_v20(status_code, error_body) 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 93, in exception_handler_v20 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif request_ids=request_ids) 2019-10-14 11:31:42.882 1 ERROR
kuryr_kubernetes.controller.drivers.nested_vlan_vif InternalServerError: Request Failed: internal server error while processing your request. 2019-10-14 11:31:42.882 1 ERROR

kuryr_kubernetes.controller.drivers.nested_vlan_vif Neutron server returns request_ids: ['req-4e9c19dc-4533-4ddf-b5c5-91d8f2a1e28c'] port addition error
Comment 3 Jon Uriarte 2019-10-28 14:46:13 UTC 
Verified on OCP 4.2.0-0.nightly-2019-10-25-135517 build on top of OSP 13 2019-10-01.1 puddle.
 
release image: registry.svc.ci.openshift.org/ocp/release@sha256:1d414ad7cf0b6b2829cdb137aae191ac8be2c6d3aed098c0facafd2c814e8c07

After executing openshift/origin e2e kubernetes/conformance tests none of these messages were found,
so the issue was not reproduced:

 · "Error happened during subport addition to trunk"
 · "Unable to obtain port information, retrying."

but the kuryr-controller pod was not restarted during the tests.

Fixing other BZs in parallel makes difficult to reproduce some issues as they depend on some others.
Comment 5 errata-xmlrpc 2019-11-13 18:55:51 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:3303