Bug 1970129 - OVS logging in must gather is missing previous logging levels
Summary: OVS logging in must gather is missing previous logging levels
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Networking
Version: 4.8
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: 4.9.0
Assignee: Nadia Pinaeva
QA Contact: Ross Brattain
URL:
Whiteboard:
Depends On:
Blocks: 2004122
TreeView+ depends on / blocked
 
Reported: 2021-06-09 20:46 UTC by Tim Rozet
Modified: 2021-10-18 17:34 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
If this bug requires documentation, please select an appropriate Doc Type value.
Clone Of:
Environment:
Last Closed: 2021-10-18 17:33:33 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github openshift cluster-network-operator pull 1142 0 None open Bug 1970129: Add env variable OVS_LOG_LEVEL for ovn nodes to setup ovs syslog level 2021-06-28 10:52:04 UTC
Github openshift machine-config-operator pull 2690 0 None open Bug 1970129: Set ovs syslog level to info 2021-07-23 14:23:18 UTC
Red Hat Product Errata RHSA-2021:3759 0 None None None 2021-10-18 17:34:03 UTC

Description Tim Rozet 2021-06-09 20:46:42 UTC
Description of problem:
When we had ovs pods we would get logging like:
2021-06-08T21:43:37.061047216Z ==> /host/var/log/openvswitch/ovs-vswitchd.log <==
2021-06-08T21:43:37.061047216Z 2021-06-08T21:43:37.060Z|02095|connmgr|INFO|br-int<->unix#15: 1710 flow_mods in the last 59 s (972 adds, 738 deletes)
2021-06-08T21:43:40.608332118Z 2021-06-08T21:43:40.608Z|02096|connmgr|INFO|br-ext<->unix#13791: 2 flow_mods in the last 0 s (2 adds)
2021-06-08T21:43:59.277323149Z 
2021-06-08T21:43:59.277323149Z ==> /host/var/log/openvswitch/ovsdb-server.log <==
2021-06-08T21:43:59.277323149Z 2021-06-08T21:43:59.277Z|00448|jsonrpc|WARN|unix#2212: send error: Broken pipe
2021-06-08T21:43:59.277568628Z 2021-06-08T21:43:59.277Z|00449|reconnect|WARN|unix#2212: connection dropped (Broken pipe)
2021-06-08T21:44:10.658779744Z 
2021-06-08T21:44:10.658779744Z ==> /host/var/log/openvswitch/ovs-vswitchd.log <==
2021-06-08T21:44:10.658779744Z 2021-06-08T21:44:10.658Z|02097|connmgr|INFO|br-ext<->unix#13803: 2 flow_mods in the last 0 s (2 adds)


connmgr and some other facilities were set to INFO level, but now with the must-gather method we are missing those outputs.

We need to ensure we get the same information we used to get from the pods with must-gather.

Comment 2 Ross Brattain 2021-07-19 16:18:30 UTC
@npinaeva it doesn't look like the changes in to PR cover the initial OVS setup in configure-ovs-network.sh.  Can we add ovs-appctl vlog/set "syslog:${OVS_SYS_LOG_LEVEL}" earlier in the process to log the br-ex setup, especially for the bonding and nmstate cases?

Comment 3 Ross Brattain 2021-07-19 17:32:58 UTC
ah, also just noticed PR 1142 doesn't seem to handle OpenShiftSDN case for $OVS_SYS_LOG_LEVEL?

Comment 4 Nadia Pinaeva 2021-07-20 08:15:44 UTC
Thank you for the comments, I discussed it with the team and we decided to move settings to machine-config-operator, so it will set OVS log level for both SDN and OVN plugins

Comment 6 Ross Brattain 2021-08-24 17:38:05 UTC
Verified on 4.9.0-0.nightly-2021-08-23-224104

Aug 24 14:40:16.942145 rbrattai-o49g21-qp2zd-master-0 systemd[1]: Starting Open vSwitch Forwarding Unit...
Aug 24 14:40:17.057342 rbrattai-o49g21-qp2zd-master-0 ovs-ctl[1204]: Inserting openvswitch module.
Aug 24 14:40:17.129463 rbrattai-o49g21-qp2zd-master-0 ovs-ctl[1204]: Starting ovs-vswitchd.
Aug 24 14:40:17.137954 rbrattai-o49g21-qp2zd-master-0 ovs-vsctl[1250]: ovs|00001|vsctl|INFO|Called as ovs-vsctl --no-wait add Open_vSwitch . external-ids hostname=rbrattai-o49g21-qp2zd-master-0
Aug 24 14:40:17.138657 rbrattai-o49g21-qp2zd-master-0 ovs-ctl[1204]: Enabling remote OVSDB managers.
Aug 24 14:40:17.147316 rbrattai-o49g21-qp2zd-master-0 systemd[1]: Started Open vSwitch Forwarding Unit.
Aug 24 14:40:18.390579 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00008|ofproto_dpif|INFO|system@ovs-system: Datapath supports recirculation
Aug 24 14:40:18.390874 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00009|ofproto_dpif|INFO|system@ovs-system: VLAN header stack length probed as 2
Aug 24 14:40:18.390968 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00010|ofproto_dpif|INFO|system@ovs-system: MPLS label stack length probed as 3
Aug 24 14:40:18.391008 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00011|ofproto_dpif|INFO|system@ovs-system: Datapath supports truncate action
Aug 24 14:40:18.391067 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00012|ofproto_dpif|INFO|system@ovs-system: Datapath supports unique flow ids


Aug 24 15:18:55.991918 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00295|connmgr|INFO|br-ex<->unix#708: 2 flow_mods in the last 0 s (2 adds)
Aug 24 15:19:11.035029 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00296|connmgr|INFO|br-ex<->unix#711: 2 flow_mods in the last 0 s (2 adds)
Aug 24 15:19:26.079296 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00297|connmgr|INFO|br-ex<->unix#714: 2 flow_mods in the last 0 s (2 adds)
Aug 24 15:19:29.801586 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00298|connmgr|INFO|br-int<->unix#1: 8 flow_mods in the 1 s starting 10 s ago (8 adds)
Aug 24 15:19:41.132910 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00299|connmgr|INFO|br-ex<->unix#717: 2 flow_mods in the last 0 s (2 adds)
Aug 24 15:19:56.176390 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00300|connmgr|INFO|br-ex<->unix#720: 2 flow_mods in the last 0 s (2 adds)
Aug 24 15:20:11.225446 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00301|connmgr|INFO|br-ex<->unix#723: 2 flow_mods in the last 0 s (2 adds)
Aug 24 15:20:26.271213 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00302|connmgr|INFO|br-ex<->unix#726: 2 flow_mods in the last 0 s (2 adds)
Aug 24 15:20:29.805222 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00303|connmgr|INFO|br-int<->unix#1: 8 flow_mods 59 s ago (8 deletes)
Aug 24 15:20:41.316578 rbrattai-o49g21-qp2zd-master-0 ovs-vswitchd[1242]: ovs|00304|connmgr|INFO|br-ex<->unix#729: 2 flow_mods in the last 0 s (2 adds)

ExecStart=/usr/share/openvswitch/scripts/ovs-ctl \
ExecStop=/usr/share/openvswitch/scripts/ovs-ctl --no-ovsdb-server stop
ExecReload=/usr/share/openvswitch/scripts/ovs-ctl --no-ovsdb-server \
ExecStartPre=-/bin/sh -c '/usr/bin/chown -R :$${OVS_USER_ID##*:} /var/lib/openvswitch'
ExecStartPre=-/bin/sh -c '/usr/bin/chown -R :$${OVS_USER_ID##*:} /etc/openvswitch'
ExecStartPre=-/bin/sh -c '/usr/bin/chown -R :$${OVS_USER_ID##*:} /run/openvswitch'
ExecStartPost=-/usr/bin/ovs-appctl vlog/set syslog:info
ExecReload=-/usr/bin/ovs-appctl vlog/set syslog:info
ExecStart=/usr/local/bin/configure-ovs.sh OVNKubernetes

Comment 9 errata-xmlrpc 2021-10-18 17:33:33 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 (Moderate: OpenShift Container Platform 4.9.0 bug fix and security update), 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/RHSA-2021:3759


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