[ovs-dev] [PATCH] ovn: Fix the failing "2335: ovn -- ACL logging" test case

[Lance Richardson]

> From: nusiddiq at redhat.com
> To: dev at openvswitch.org
> Sent: Monday, 31 July, 2017 2:20:53 PM
> Subject: [ovs-dev] [PATCH] ovn: Fix the failing "2335: ovn -- ACL logging"	test case
> 
> From: Numan Siddique <nusiddiq at redhat.com>
> 
> The test case is failing mainly because of timing issue. Looking into the
> ovn-controller.log it is evident that the last packet injected just before
> the
> AT_CHECK, is still not processed by ovn-controller. To fix this issue,
> OVS_WAIT_UNTIL function is used.
> 
> Fixes: d383eed59589 ("ovn: Add support for ACL logging.")
> CC: Justin Pettit <jpettit at ovn.org>
> Signed-off-by: Numan Siddique <nusiddiq at redhat.com>
> ---
>  tests/ovn.at | 25 ++++++++++++++++++++-----
>  1 file changed, 20 insertions(+), 5 deletions(-)
> 
> diff --git a/tests/ovn.at b/tests/ovn.at
> index cf356552f..0eef4d554 100644
> --- a/tests/ovn.at
> +++ b/tests/ovn.at
> @@ -5803,6 +5803,10 @@ packet="inport==\"lp1\" && eth.src==$lp1_mac &&
> eth.dst==$lp2_mac &&
>          ip4 && ip.ttl==64 && ip4.src==$lp1_ip && ip4.dst==$lp2_ip &&
>          tcp && tcp.flags==2 && tcp.src==4361 && tcp.dst==81"
>  as hv ovs-appctl -t ovn-controller inject-pkt "$packet"
> +echo "name=\"drop-flow\", verdict=drop, severity=alert:
> tcp,vlan_tci=0x0000,\
> +dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,\
> +nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4361,\
> +tp_dst=81,tcp_flags=syn" > expected_logs
>  
>  # Send packet that should be allowed without logging.
>  packet="inport==\"lp1\" && eth.src==$lp1_mac && eth.dst==$lp2_mac &&
> @@ -5815,6 +5819,10 @@ packet="inport==\"lp1\" && eth.src==$lp1_mac &&
> eth.dst==$lp2_mac &&
>          ip4 && ip.ttl==64 && ip4.src==$lp1_ip && ip4.dst==$lp2_ip &&
>          tcp && tcp.flags==2 && tcp.src==4363 && tcp.dst==83"
>  as hv ovs-appctl -t ovn-controller inject-pkt "$packet"
> +echo "name=\"allow-flow\", verdict=allow, severity=info:
> tcp,vlan_tci=0x0000,\
> +dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,\
> +nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4363,tp_dst=83,\
> +tcp_flags=syn" >> expected_logs
>  
>  # Send packet that should allow related flows without logging.
>  packet="inport==\"lp1\" && eth.src==$lp1_mac && eth.dst==$lp2_mac &&
> @@ -5827,6 +5835,10 @@ packet="inport==\"lp1\" && eth.src==$lp1_mac &&
> eth.dst==$lp2_mac &&
>          ip4 && ip.ttl==64 && ip4.src==$lp1_ip && ip4.dst==$lp2_ip &&
>          tcp && tcp.flags==2 && tcp.src==4365 && tcp.dst==85"
>  as hv ovs-appctl -t ovn-controller inject-pkt "$packet"
> +echo "name=\"<unnamed>\", verdict=allow, severity=info:
> tcp,vlan_tci=0x0000,\
> +dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,\
> +nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4365,tp_dst=85,\
> +tcp_flags=syn" >> expected_logs
>  
>  # Send packet that should allow related flows with logging.
>  packet="inport==\"lp1\" && eth.src==$lp1_mac && eth.dst==$lp2_mac &&
> @@ -5839,12 +5851,15 @@ packet="inport==\"lp1\" && eth.src==$lp1_mac &&
> eth.dst==$lp2_mac &&
>          ip4 && ip.ttl==64 && ip4.src==$lp1_ip && ip4.dst==$lp2_ip &&
>          tcp && tcp.flags==2 && tcp.src==4367 && tcp.dst==87"
>  as hv ovs-appctl -t ovn-controller inject-pkt "$packet"
> +echo "name=\"reject-flow\", verdict=reject, severity=alert: tcp,\
> +vlan_tci=0x0000,dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,\
> +nw_src=192.168.1.2,nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,\
> +tp_src=4367,tp_dst=87,tcp_flags=syn" >> expected_logs
>  
> -AT_CHECK([grep 'acl_log' hv/ovn-controller.log | sed 's/.*name=/name=/'],
> [0], [dnl
> -name="drop-flow", verdict=drop, severity=alert:
> tcp,vlan_tci=0x0000,dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4361,tp_dst=81,tcp_flags=syn
> -name="allow-flow", verdict=allow, severity=info:
> tcp,vlan_tci=0x0000,dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4363,tp_dst=83,tcp_flags=syn
> -name="<unnamed>", verdict=allow, severity=info:
> tcp,vlan_tci=0x0000,dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4365,tp_dst=85,tcp_flags=syn
> -name="reject-flow", verdict=reject, severity=alert:
> tcp,vlan_tci=0x0000,dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4367,tp_dst=87,tcp_flags=syn
> +
> +OVS_WAIT_UNTIL([
> +    grep 'acl_log' hv/ovn-controller.log | sed 's/.*name=/name='/ > acl_logs
> +    test "`cat expected_logs`" = "`cat acl_logs`"
>  ])
>  
>  OVN_CLEANUP([hv])
> --
> 2.13.3


Hi Numan,

Maybe something like the patch below would be better (it's smaller, anyway).

Regards,

   Lance


diff --git a/tests/ovn.at b/tests/ovn.at
index cf356552f..40fa817f9 100644
--- a/tests/ovn.at
+++ b/tests/ovn.at
@@ -5840,6 +5840,8 @@ packet="inport==\"lp1\" && eth.src==$lp1_mac && eth.dst==$lp2_mac &&
         tcp && tcp.flags==2 && tcp.src==4367 && tcp.dst==87"
 as hv ovs-appctl -t ovn-controller inject-pkt "$packet"
 
+OVS_WAIT_UNTIL([ test 4 = $(grep -c 'acl_log' hv/ovn-controller.log) ])
+
 AT_CHECK([grep 'acl_log' hv/ovn-controller.log | sed 's/.*name=/name=/'], [0], [dnl
 name="drop-flow", verdict=drop, severity=alert: tcp,vlan_tci=0x0000,dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4361,tp_dst=81,tcp_flags=syn
 name="allow-flow", verdict=allow, severity=info: tcp,vlan_tci=0x0000,dl_src=f0:00:00:00:00:01,dl_dst=f0:00:00:00:00:02,nw_src=192.168.1.2,nw_dst=192.168.1.3,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=4363,tp_dst=83,tcp_flags=syn