Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1860030

Summary:	kuryr-controller logs are awfully unreadable
Product:	OpenShift Container Platform	Reporter:	Michał Dulko <mdulko>
Component:	Networking	Assignee:	Michał Dulko <mdulko>
Networking sub component:	kuryr	QA Contact:	GenadiC <gcheresh>
Status:	CLOSED ERRATA	Docs Contact:
Severity:	medium
Priority:	medium	CC:	bbennett, ltomasbo, rlobillo
Version:	4.6	Keywords:	Triaged, UpcomingSprint
Target Milestone:	---
Target Release:	4.6.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:
Clones:	1860311 (view as bug list)		Environment:
Last Closed:	2020-10-27 16:16:44 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:
Embargoed:
Bug Depends On:
Bug Blocks:	1860311

Description Michał Dulko 2020-07-23 15:12:53 UTC

Description of problem:
There's a ton of tracebacks related to connection errors that are showing up in kuryr-controller logs, making them virtually unreadable without a decent amount of internal Kuryr knowledge.

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 4 rlobillo 2020-08-07 12:37:06 UTC

Verified on 4.6.0-0.nightly-2020-07-25-065959

Confirmed that connection errors and watchdogs messages are not present on the kuryr-controller logs:

[stack@undercloud-0 ~]$ oc logs -n openshift-kuryr kuryr-controller-5b5d467dd8-64bzd -f
2020-08-07 12:34:23.309 1 INFO kuryr_kubernetes.config [-] Logging enabled!
2020-08-07 12:34:23.309 1 INFO kuryr_kubernetes.config [-] /usr/bin/kuryr-k8s-controller version 4.6.0
2020-08-07 12:34:24.890 1 INFO os_vif [-] Loaded VIF plugins: linux_bridge, noop, ovs, noop, sriov
2020-08-07 12:34:24.898 1 INFO kuryr_kubernetes.controller.service [-] Configured handlers: ['vif', 'lb', 'lbaasspec', 'policy', 'pod_label', 'namespace', 'kuryrnetpolicy', 'kuryrnetwork']
2020-08-07 12:34:24.971 1 INFO kuryr_kubernetes.controller.drivers.lbaasv2 [-] Octavia supports ACLs for Amphora provider.
2020-08-07 12:34:24.971 1 INFO kuryr_kubernetes.controller.drivers.lbaasv2 [-] Octavia supports double listeners (different protocol, same port) for Amphora provider.
2020-08-07 12:34:24.972 1 INFO kuryr_kubernetes.controller.drivers.lbaasv2 [-] Octavia supports resource tags.
2020-08-07 12:34:25.063 1 INFO kuryr_kubernetes.controller.service [-] Loaded handlers: ['kuryrnetpolicy', 'kuryrnetwork', 'lb', 'lbaasspec', 'namespace', 'pod_label', 'policy', 'vif']
2020-08-07 12:34:25.073 1 WARNING oslo_config.cfg [-] Deprecated: Option "sg_mode" from group "octavia_defaults" is deprecated for removal (enforce_sg_rules option can be used instead).  Its value may be silently ignored in the future.
2020-08-07 12:34:25.081 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopped
2020-08-07 12:34:25.083 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' starting
2020-08-07 12:34:25.083 1 INFO kuryr_kubernetes.controller.service [-] Running in non-HA mode, starting watcher immediately.
2020-08-07 12:34:25.088 1 INFO kuryr_kubernetes.watcher [-] Started watching '/apis/networking.k8s.io/v1/networkpolicies'
2020-08-07 12:34:25.091 1 INFO kuryr_kubernetes.watcher [-] Started watching '/api/v1/namespaces'
2020-08-07 12:34:25.096 1 INFO kuryr_kubernetes.watcher [-] Started watching '/apis/openstack.org/v1/kuryrnetpolicies'
2020-08-07 12:34:25.101 1 INFO kuryr_kubernetes.watcher [-] Started watching '/api/v1/pods'
2020-08-07 12:34:25.105 1 INFO kuryr_kubernetes.watcher [-] Started watching '/api/v1/services'
2020-08-07 12:34:25.110 1 INFO kuryr_kubernetes.watcher [-] Started watching '/api/v1/endpoints'
2020-08-07 12:34:25.115 1 INFO kuryr_kubernetes.watcher [-] Started watching '/apis/openstack.org/v1/kuryrnetworks'


^C
[stack@undercloud-0 ~]$ oc rsh -n openshift-kuryr kuryr-controller-5b5d467dd8-64bzd date
Fri Aug  7 12:36:39 UTC 2020

Comment 5 Michał Dulko 2020-08-18 09:01:55 UTC

Seems like there might be some more tracebacks that are spamming the logs:

2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging Traceback (most recent call last):
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connectionpool.py", line 600, in urlopen
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     chunked=chunked)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connectionpool.py", line 343, in _make_request
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._validate_conn(conn)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connectionpool.py", line 839, in _validate_conn
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     conn.connect()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connection.py", line 344, in connect
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     ssl_context=context)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/util/ssl_.py", line 354, in ssl_wrap_socket
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return context.wrap_socket(sock, server_hostname=server_hostname)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 438, in wrap_socket
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return GreenSSLSocket(sock, *a, _context=self, **kw)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 128, in __init__
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self.do_handshake()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 301, in do_handshake
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     super(GreenSSLSocket, self).do_handshake)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 150, in _call_trampolining
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return func(*a, **kw)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib64/python3.6/ssl.py", line 1036, in do_handshake
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._sslobj.do_handshake()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib64/python3.6/ssl.py", line 648, in do_handshake
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._sslobj.do_handshake()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging OSError: [Errno 0] Error
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging 
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging During handling of the above exception, another exception occurred:
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging 
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging Traceback (most recent call last):
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/requests/adapters.py", line 449, in send
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     timeout=timeout
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connectionpool.py", line 638, in urlopen
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     _stacktrace=sys.exc_info()[2])
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/util/retry.py", line 368, in increment
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     raise six.reraise(type(error), error, _stacktrace)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/packages/six.py", line 692, in reraise
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     raise value.with_traceback(tb)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connectionpool.py", line 600, in urlopen
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     chunked=chunked)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connectionpool.py", line 343, in _make_request
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._validate_conn(conn)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connectionpool.py", line 839, in _validate_conn
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     conn.connect()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/connection.py", line 344, in connect
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     ssl_context=context)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/urllib3/util/ssl_.py", line 354, in ssl_wrap_socket
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return context.wrap_socket(sock, server_hostname=server_hostname)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 438, in wrap_socket
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return GreenSSLSocket(sock, *a, _context=self, **kw)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 128, in __init__
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self.do_handshake()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 301, in do_handshake
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     super(GreenSSLSocket, self).do_handshake)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/eventlet/green/ssl.py", line 150, in _call_trampolining
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return func(*a, **kw)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib64/python3.6/ssl.py", line 1036, in do_handshake
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._sslobj.do_handshake()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib64/python3.6/ssl.py", line 648, in do_handshake
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._sslobj.do_handshake()
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging urllib3.exceptions.ProtocolError: ('Connection aborted.', OSError(0, 'Error'))
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging 
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging During handling of the above exception, another exception occurred:
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging 
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging Traceback (most recent call last):
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/handlers/logging.py", line 37, in __call__
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._handler(event)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/handlers/retry.py", line 67, in __call__
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     self._k8s.get(obj_link)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/k8s_client.py", line 81, in get
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     headers=header)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/requests/api.py", line 75, in get
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return request('get', url, params=params, **kwargs)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/requests/api.py", line 60, in request
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     return session.request(method=method, url=url, **kwargs)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/requests/sessions.py", line 533, in request
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     resp = self.send(prep, **send_kwargs)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/requests/sessions.py", line 646, in send
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     r = adapter.send(request, **kwargs)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging   File "/usr/lib/python3.6/site-packages/requests/adapters.py", line 498, in send
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging     raise ConnectionError(err, request=request)
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging requests.exceptions.ConnectionError: ('Connection aborted.', OSError(0, 'Error'))
2020-08-17 10:40:21.245 1 ERROR kuryr_kubernetes.handlers.logging 
2020-08-17 10:40:21.253 1 ERROR kuryr_kubernetes.handlers.logging [-] Failed to handle event {'type': 'ADDED', 'object': {'kind': 'Namespace', 'apiVersion': 'v1', 'metadata': {'name': 'openshift-cluster-node-tuning-operator', 'selfLink': '/api/v1/namespaces/openshift-cluster-node-tuning-operator', 'uid': 'df907325-b35a-45be-8062-c39e86fbc05e', 'resourceVersion': '10837', 'creationTimestamp': '2020-08-17T10:13:22Z', 'annotations': {'openshift.io/node-selector': '', 'openshift.io/sa.scc.mcs': 's0:c21,c15', 'openshift.io/sa.scc.supplemental-groups': '1000450000/10000', 'openshift.io/sa.scc.uid-range': '1000450000/10000', 'openstack.org/kuryr-net-crd': 'ns-openshift-cluster-node-tuning-operator'}}, 'spec': {'finalizers': ['kubernetes']}, 'status': {'phase': 'Active'}}}: requests.exceptions.ConnectionError: ('Connection aborted.', OSError(0, 'Error'))

Comment 6 Ben Bennett 2020-09-03 13:48:09 UTC

Setting to 4.7 since this won't block 4.6.  But if you have a PR for this that is ready to merge to 4.6, please change the target.

Comment 9 rlobillo 2020-09-30 08:55:04 UTC

Verified on 4.6.0-0.nightly-2020-09-28-212756 over RHOS-16.1-RHEL-8-20200917.n.3 with OVN-Octavia provider.

Confirmed that connection errors and watchdogs messages are not present on the kuryr-controller logs while running NP and Conformace tests. Also OSError exceptions are not observed.

During the execution of above tests, https://bugzilla.redhat.com/show_bug.cgi?id=1883565 was identified and open.

Comment 11 errata-xmlrpc 2020-10-27 16:16:44 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 (OpenShift Container Platform 4.6 GA Images), 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:4196