Bug 1874745

Summary:	[ovn-northd] No rate limiting on WARN log messages for missing Chassis records.
Product:	Red Hat Enterprise Linux Fast Datapath	Reporter:	Dumitru Ceara <dceara>
Component:	ovn2.13	Assignee:	Dumitru Ceara <dceara>
Status:	CLOSED ERRATA	QA Contact:	Jianlin Shi <jishi>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	FDP 20.E	CC:	ctrautma, jishi, ralongi
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	ovn2.13-20.06.2-4.el7fdp	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2020-09-16 16:01:25 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:

Description Dumitru Ceara 2020-09-02 07:03:18 UTC

Description of problem:

There's no rate limiting for "Chassis not exist for Chassis_Private record" logs in ovn-northd. This information is useful but it shouldn't spam the log at every ovn-northd iteration.

Version-Release number of selected component (if applicable):
ovn2.13-20.06.2-3.el7fdp
ovn2.13-20.06.2-3.el8fdp

How reproducible:


Steps to Reproduce:
1. Bring up ovn-northd and ovn-controller.
2. Forcefully stop ovn-controller (e.g., kill)
3. Destroy the Chassis record from the SB (ovn-sbctl destroy Chassis .)
4. Run "ovn-nbctl --wait=sb sync" in a loop.

Actual results:
This log is generated at every iteration 'Chassis not exist for Chassis_Private record'.

Expected results:
The log should be rate limited.

Additional info:
Fixed upstream: https://github.com/ovn-org/ovn/commit/81e88122985caf35b6c60b8d04e16cd0b53aa2b7

Comment 2 Jianlin Shi 2020-09-04 01:19:42 UTC

test with following script:

systemctl start openvswitch                          
systemctl start ovn-northd
ovn-nbctl set-connection ptcp:6641                                         
ovn-sbctl set-connection ptcp:6642
ovs-vsctl set open . external_ids:system-id=hv1 external_ids:ovn-remote=tcp:20.0.31.25:6642 external_ids:ovn-encap-type=geneve external_ids:ovn-encap-ip=20.0.31.25
#systemctl restart ovn-controller
ovn-controller unix:/run/openvswitch/db.sock -vconsole:emer -vsyslog:err -vfile:info --user openvswitch:openvswitch --no-chdir --log-file=/var/log/ovn/ovn-controller.log --pidfile=/run/ovn/ovn-controller.pid --detach
controller_pid=$(cat /run/ovn/ovn-controller.pid)

#ovs-vsctl set bridge br-int other_config:hwaddr="3e:5d:ff:25:10:f8"
ovn-nbctl lr-add rtr
ovn-nbctl lrp-add rtr rtr-ls 00:00:00:00:01:00 42.42.42.1/24
ovn-nbctl ls-add ls
ovn-nbctl lsp-add ls ls-rtr
ovn-nbctl lsp-set-addresses ls-rtr 00:00:00:00:01:00
ovn-nbctl lsp-set-type ls-rtr router
ovn-nbctl lsp-set-options ls-rtr router-port=rtr-ls
ovn-nbctl lsp-add ls vm1
ovn-nbctl lsp-set-addresses vm1 00:00:00:00:00:01
ovn-nbctl lsp-add ls vm2
ovn-nbctl lsp-set-addresses vm2 00:00:00:00:00:02
ip netns add vm1
ovs-vsctl add-port br-int vm1 -- set interface vm1 type=internal
ip link set vm1 netns vm1
ip netns exec vm1 ip link set vm1 address 00:00:00:00:00:01
ip netns exec vm1 ip addr add 42.42.42.2/24 dev vm1
ip netns exec vm1 ip link set vm1 up
ovs-vsctl set Interface vm1 external_ids:iface-id=vm1

ip netns add vm2
ovs-vsctl add-port br-int vm2 -- set interface vm2 type=internal
ip link set vm2 netns vm2
ip netns exec vm2 ip link set vm2 address 00:00:00:00:00:02
ip netns exec vm2 ip addr add 42.42.42.3/24 dev vm2
ip netns exec vm2 ip link set vm2 up
ovs-vsctl set Interface vm2 external_ids:iface-id=vm2

kill -9 $controller_pid
ovn-sbctl destroy chassis .
for i in {1..5}
do
        ovn-nbctl --wait=sb sync
done

cat /var/log/ovn/ovn-northd.log

reproduced on ovn20.06.2-3:

[root@dell-per740-12 bz1874745]# rpm -qa | grep -E "openvswitch|ovn"
openvswitch2.13-2.13.0-48.el7fdp.x86_64                         
ovn2.13-host-20.06.2-3.el7fdp.x86_64
openvswitch-selinux-extra-policy-1.0-15.el7fdp.noarch      
ovn2.13-central-20.06.2-3.el7fdp.x86_64            
ovn2.13-debuginfo-20.06.2-3.el7fdp.x86_64
ovn2.13-20.06.2-3.el7fdp.x86_64

+ cat /var/log/ovn/ovn-northd.log          
2020-09-04T01:16:29.287Z|00001|vlog|INFO|opened log file /var/log/ovn/ovn-northd.log
2020-09-04T01:16:29.294Z|00002|reconnect|INFO|unix:/run/ovn/ovnnb_db.sock: connecting...
2020-09-04T01:16:29.294Z|00003|reconnect|INFO|unix:/run/ovn/ovnsb_db.sock: connecting...
2020-09-04T01:16:29.294Z|00004|reconnect|INFO|unix:/run/ovn/ovnnb_db.sock: connected
2020-09-04T01:16:29.294Z|00005|reconnect|INFO|unix:/run/ovn/ovnsb_db.sock: connected                                                                                                                       
2020-09-04T01:16:29.294Z|00006|ovn_northd|INFO|ovn-northd lock acquired. This ovn-northd instance is now active.
2020-09-04T01:16:29.811Z|00007|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1                                                                                                      2020-09-04T01:16:29.826Z|00008|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.827Z|00009|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.828Z|00010|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.842Z|00011|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.844Z|00012|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.845Z|00013|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.855Z|00014|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.857Z|00015|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.858Z|00016|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.865Z|00017|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.866Z|00018|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.867Z|00019|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.874Z|00020|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.875Z|00021|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1
2020-09-04T01:16:29.876Z|00022|ovn_northd|WARN|Chassis not exist for Chassis_Private record, name: hv1

Verified on ovn20.06.2-4:

[root@dell-per740-12 bz1874745]# rpm -qa | grep -E "openvswitch|ovn"
openvswitch2.13-2.13.0-48.el7fdp.x86_64
ovn2.13-host-20.06.2-4.el7fdp.x86_64
openvswitch-selinux-extra-policy-1.0-15.el7fdp.noarch
ovn2.13-debuginfo-20.06.2-3.el7fdp.x86_64
ovn2.13-central-20.06.2-4.el7fdp.x86_64
ovn2.13-20.06.2-4.el7fdp.x86_64

+ cat /var/log/ovn/ovn-northd.log
2020-09-04T01:18:55.946Z|00001|vlog|INFO|opened log file /var/log/ovn/ovn-northd.log
2020-09-04T01:18:55.953Z|00002|reconnect|INFO|unix:/run/ovn/ovnnb_db.sock: connecting...
2020-09-04T01:18:55.953Z|00003|reconnect|INFO|unix:/run/ovn/ovnsb_db.sock: connecting...
2020-09-04T01:18:55.953Z|00004|reconnect|INFO|unix:/run/ovn/ovnnb_db.sock: connected
2020-09-04T01:18:55.953Z|00005|reconnect|INFO|unix:/run/ovn/ovnsb_db.sock: connected
2020-09-04T01:18:55.953Z|00006|ovn_northd|INFO|ovn-northd lock acquired. This ovn-northd instance is now active.
2020-09-04T01:18:56.467Z|00007|ovn_northd|WARN|Chassis does not exist for Chassis_Private record, name: hv1

<=== only one line

Comment 6 errata-xmlrpc 2020-09-16 16:01:25 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 (ovn2.13 bug fix and enhancement 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/RHBA-2020:3769