Bug 1992641

Hi, it's not clear from the issue report if the logs are actually duplicates, or if similar style messages might be emitted from different contexts within ovn-controller into the logs. Could you please post a redacted ovn-controller.log as an attachment on this issue? Thanks.

Hello Mark,

Logs are actually generated by ingress and egress pipelines. But as packets (in most cases) are identical - we have duplicate lines in the log file that is a bit confusing. Please let me know if you still need exact logs from the controller.

Best regards,
Alex

Hi Alex, yes please provide logs. Also, if you can provide the ovn northbound database from a reproducer, we can have a look and determine if

1) This can be fixed through configuration, or
2) If this is a bug that needs to be fixed in OVN.

For now, I'm changing the priority from "low" to "unspecified" so that we can reprioritize at a later date.

If we cannot target FDP 21.I then let's target FDP 21.J.

OK, having two log entries for two ACLs makes sense, but it probably makes sense to put some differentiating factor in the log messages so that it's possible to know which of the two ACLs is which.

Patch posted for review: http://patchwork.ozlabs.org/project/ovn/list/?series=284087&state=*

v2 posted for review: http://patchwork.ozlabs.org/project/ovn/list/?series=284151&state=*

v3 posted for review: http://patchwork.ozlabs.org/project/ovn/list/?series=285670&state=*

v4 posted for review: http://patchwork.ozlabs.org/project/ovn/list/?series=286103&state=*

v5 posted for review: http://patchwork.ozlabs.org/project/ovn/list/?series=286297&state=*

Patch accepted upstream, will be available in the next OVN release.

https://github.com/ovn-org/ovn/commit/d7514abe1172dd677af1ce2e61c86ae3885eb344

Moving back to POST to make sure QE gets a change to test the feature.

Reproducer: 

systemctl start ovn-northd
ovn-nbctl set-connection ptcp:6641
ovn-sbctl set-connection ptcp:6642
systemctl start openvswitch
ovs-vsctl set open . external_ids:system-id=hv1
ovs-vsctl set open . external_ids:ovn-remote=tcp:172.16.1.1:6642
ovs-vsctl set open . external_ids:ovn-encap-type=geneve
ovs-vsctl set open . external_ids:ovn-encap-ip=172.16.1.1
systemctl start ovn-controller

ovn-nbctl ls-add ls1
ovn-nbctl lsp-add ls1 lp1
ovn-nbctl lsp-set-addresses lp1 "00:00:00:01:00:02 172.16.1.1 3001::1"
ovn-nbctl lsp-add ls1 lp2
ovn-nbctl lsp-set-addresses lp2 "00:00:00:02:00:02 172.16.1.2 3001::2"

ip netns add server0
ip link add veth0_s0 type veth peer name veth0_s0_p
ip link set veth0_s0 netns server0
ip netns exec server0 ip link set lo up
ip netns exec server0 ip link set veth0_s0 up
ip netns exec server0 ip link set veth0_s0 address 00:00:00:01:00:02
ip netns exec server0 ip addr add 172.16.1.1/24 dev veth0_s0
ip netns exec server0 ip -6 addr add 3001::1/64 dev veth0_s0
ovs-vsctl add-port br-int veth0_s0_p
ip link set veth0_s0_p up
ovs-vsctl set interface veth0_s0_p external_ids:iface-id=lp1

ip netns add client1
ip link add veth0_c1 type veth peer name veth0_c1_p
ip link set veth0_c1 netns client1
ip netns exec client1 ip link set lo up
ip netns exec client1 ip link set veth0_c1 up
ip netns exec client1 ip link set veth0_c1 address 00:00:00:02:00:02
ip netns exec client1 ip addr add 172.16.1.2/24 dev veth0_c1
ip netns exec client1 ip -6 addr add 3001::2/64 dev veth0_c1
ovs-vsctl add-port br-int veth0_c1_p
ip link set veth0_c1_p up
ovs-vsctl set interface veth0_c1_p external_ids:iface-id=lp2

ip netns exec server0 ping 172.16.1.2 -c 3

ovn-nbctl acl-add ls1 from-lport 1000 'tcp.dst==80' drop
ovn-nbctl --log --severity=alert --name=drop-flow acl-add ls1 from-lport 1000 'tcp.dst==81' drop

ovn-nbctl acl-add ls1 to-lport 1000 'tcp.dst==180' drop
ovn-nbctl --log --severity=alert --name=drop-flow acl-add ls1 to-lport 1000 'tcp.dst==181' drop

ovn-nbctl acl-add ls1 from-lport 1000 'tcp.dst==82' allow
ovn-nbctl --log --severity=info --name=allow-flow acl-add ls1 from-lport 1000 'tcp.dst==83' allow

ovn-nbctl acl-add ls1 to-lport 1000 'tcp.dst==82' allow
ovn-nbctl --log --severity=info --name=allow-flow acl-add ls1 to-lport 1000 'tcp.dst==83' allow

ovn-nbctl acl-add ls1 from-lport 1000 'tcp.dst==84' allow-related
ovn-nbctl --log acl-add ls1 from-lport 1000 'tcp.dst==85' allow-related

ovn-nbctl acl-add ls1 to-lport 1000 'tcp.dst==84' allow-related
ovn-nbctl --log acl-add ls1 to-lport 1000 'tcp.dst==85' allow-related

ovn-nbctl acl-add ls1 from-lport 1000 'tcp.dst==86' reject
ovn-nbctl --log --severity=alert --name=reject-flow acl-add ls1 from-lport 1000 'tcp.dst==87' reject

ovn-nbctl acl-add ls1 to-lport 1000 'tcp.dst==186' reject
ovn-nbctl --log --severity=alert --name=reject-flow acl-add ls1 to-lport 1000 'tcp.dst==187' reject

ovn-nbctl --wait=hv sync

ovn-sbctl dump-flows > sbflows

ip netns exec client1 nc -l -k 80 &
ip netns exec client1 nc -l -k 81 &
ip netns exec client1 nc -l -k 180 &
ip netns exec client1 nc -l -k 181 &
ip netns exec client1 nc -l -k 82 &
ip netns exec client1 nc -l -k 83 &
ip netns exec client1 nc -l -k 84 &
ip netns exec client1 nc -l -k 85 & 
ip netns exec client1 nc -l -k 86 &
ip netns exec client1 nc -l -k 87 &
ip netns exec client1 nc -l -k 186 &
ip netns exec client1 nc -l -k 187 &

# Send packet that should be dropped without logging in the ingress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4360 172.16.1.2 80 <<< hello
Ncat: Connection timed out.

# Send packet that should be dropped with logging in the ingress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4361 172.16.1.2 81 <<< hello
Ncat: Connection timed out.

# Send packet that should be dropped without logging in the eggress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4360 172.16.1.2 180 <<< hello
Ncat: Connection timed out.

# Send packet that should be dropped with logging in the egress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4361 172.16.1.2 181 <<< hello
Ncat: Connection timed out.

# Send packet that should be allowed without logging.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4362 172.16.1.2 82 <<< hello
hello

# Send packet that should be allowed with logging.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4363 172.16.1.2 83 <<< hello
hello

# Send packet that should allow related flows without logging.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4364 172.16.1.2 84 <<< hello
hello

# Send packet that should allow related flows with logging.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4365 172.16.1.2 85 <<< hello
hello

# Send packet that should be rejected without logging in the ingress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4366 172.16.1.2 86 <<< hello
Ncat: Connection refused.

# Send packet that should be rejected with logging in the ingress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4367 172.16.1.2 87 <<< hello
Ncat: Connection refused.

# Send packet that should be rejected without logging in the egress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4366 172.16.1.2 186 <<< hello
Ncat: Connection refused.

# Send packet that should be rejected with logging in the egress pipeline.
[root@bz-1992641 ~]# ip netns exec server0 nc -p 4367 172.16.1.2 187 <<< hello
Ncat: Connection refused.

# Reproduced on
[root@bz-1992641 ~]# rpm -qa |grep -E "ovn|openvswitch"
ovn-2021-central-21.12.0-32.el8fdp.x86_64
openvswitch-selinux-extra-policy-1.0-28.el8fdp.noarch
ovn-2021-host-21.12.0-32.el8fdp.x86_64
openvswitch2.15-2.15.0-93.el8fdp.x86_64
ovn-2021-21.12.0-32.el8fdp.x86_64

# ovn-controller acl_log duplicate entries. 
[root@bz-1992641 ~]# cat /var/log/ovn/ovn-controller.log |grep acl_log|sed 's/.*name=/name=/'|grep tcp_flags=syn| sort|uniq -c
      2 name="allow-flow", verdict=allow, severity=info: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4363,tp_dst=83,tcp_flags=syn
      4 name="drop-flow", verdict=drop, severity=alert: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4361,tp_dst=181,tcp_flags=syn
      4 name="drop-flow", verdict=drop, severity=alert: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4361,tp_dst=81,tcp_flags=syn
      1 name="reject-flow", verdict=reject, severity=alert: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4367,tp_dst=187,tcp_flags=syn
      1 name="reject-flow", verdict=reject, severity=alert: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4367,tp_dst=87,tcp_flags=syn
      2 name="<unnamed>", verdict=allow, severity=info: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4365,tp_dst=85,tcp_flags=syn

verified on
[root@bz-1992641 ~]# rpm -qa |grep -E "ovn|openvswitch"
ovn-2021-central-21.12.0-42.el8fdp.x86_64
openvswitch-selinux-extra-policy-1.0-28.el8fdp.noarch
openvswitch2.15-2.15.0-93.el8fdp.x86_64
ovn-2021-21.12.0-42.el8fdp.x86_64
ovn-2021-host-21.12.0-42.el8fdp.x86_64

# Duplicate entries exist where acl action is "drop", this is due to multiple retries of the syn packets. 
[root@bz-1992641 ~]# cat /var/log/ovn/ovn-controller.log |grep acl_log|sed 's/.*name=/name=/'|grep tcp_flags=syn| sort|uniq -c
      1 name="allow-flow", verdict=allow, severity=info, direction=from-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4363,tp_dst=83,tcp_flags=syn
      1 name="allow-flow", verdict=allow, severity=info, direction=to-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4363,tp_dst=83,tcp_flags=syn
      4 name="drop-flow", verdict=drop, severity=alert, direction=from-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4361,tp_dst=81,tcp_flags=syn
      4 name="drop-flow", verdict=drop, severity=alert, direction=to-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4361,tp_dst=181,tcp_flags=syn
      1 name="reject-flow", verdict=reject, severity=alert, direction=from-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4367,tp_dst=87,tcp_flags=syn
      1 name="reject-flow", verdict=reject, severity=alert, direction=to-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4367,tp_dst=187,tcp_flags=syn
      1 name="<unnamed>", verdict=allow, severity=info, direction=from-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4365,tp_dst=85,tcp_flags=syn
      1 name="<unnamed>", verdict=allow, severity=info, direction=to-lport: tcp,vlan_tci=0x0000,dl_src=00:00:00:01:00:02,dl_dst=00:00:00:02:00:02,nw_src=172.16.1.1,nw_dst=172.16.1.2,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4365,tp_dst=85,tcp_flags=syn
[root@bz-1992641 ~]#

Also verified on

[root@bz-1992641 ~]# rpm -qa |grep -E "ovn|openvswitch"
openvswitch-selinux-extra-policy-1.0-31.el9fdp.noarch
openvswitch2.16-2.16.0-52.el9fdp.x86_64
ovn22.03-22.03.0-9.el9fdp.x86_64
ovn22.03-central-22.03.0-9.el9fdp.x86_64
ovn22.03-host-22.03.0-9.el9fdp.x86_64

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 (ovn-2021 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-2022:1523