1860030 – kuryr-controller logs are awfully unreadable

Bug 1860030 - kuryr-controller logs are awfully unreadable

Summary: kuryr-controller logs are awfully unreadable

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	OpenShift Container Platform
Classification:	Red Hat
Component:	Networking
Sub Component:
Version:	4.6
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	---
Target Release:	4.6.0
Assignee:	Michał Dulko
QA Contact:	GenadiC
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	1860311
TreeView+	depends on / blocked

Reported:	2020-07-23 15:12 UTC by Michał Dulko
Modified:	2020-10-27 16:17 UTC (History)
CC List:	3 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Clones:	1860311 (view as bug list)
Environment:
Last Closed:	2020-10-27 16:16:44 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Priority	Status	Summary	Last Updated
Github	openshift kuryr-kubernetes pull 310	None	closed	Bug 1860030: Civilize logging	2020-09-29 14:23:13 UTC
Github	openshift kuryr-kubernetes pull 349	None	closed	Bug 1860030: Civilize logging vol 2	2020-09-29 14:23:14 UTC
Red Hat Product Errata	RHBA-2020:4196	None	None	None	2020-10-27 16:17:06 UTC

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

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