Bug 1761505

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: juriarte
Version: 4.2.0Keywords: Triaged
Target Milestone: ---   
Target Release: 4.3.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1761507 (view as bug list) Environment:
Last Closed: 2020-01-23 11:07:31 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:
Bug Depends On:    
Bug Blocks: 1761507    

Description Luis Tomas Bolivar 2019-10-14 14:30:30 UTC
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 2 Jon Uriarte 2019-10-24 15:08:30 UTC
Verified in 4.3.0-0.nightly-2019-10-22-165241 build on top of OSP 13 2019-10-01.1 puddle.

After executing openshift/origin e2e kubernetes/conformance tests none of these messages were found,
so the issue was not be 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 4 errata-xmlrpc 2020-01-23 11:07:31 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-2020:0062