Hello Simon,
On Tue, Oct 10, 2023 at 5:10 PM Simon Horman <ho...@ovn.org> wrote:
>
> On Mon, Oct 09, 2023 at 05:06:51PM +0200, David Marchand wrote:
> > A main thread executing the 'revalidator/purge' command could race with
> > revalidator threads that can be dumping/sweeping the purged flows at the
> > same time.
> >
> > This race can be reproduced (with dpif debug logs) by running the
> > conntrack - ICMP related unit tests with the userspace datapath:
> >
> > 2023-10-09T14:11:55.242Z|00177|unixctl|DBG|received request
> > revalidator/purge[], id=0
> > 2023-10-09T14:11:55.242Z|00044|dpif(revalidator17)|DBG|netdev@ovs-netdev:
> > flow_dump ufid:68ff6817-fb3b-4b30-8412-9cf175318294 <empty>,
> > packets:0, bytes:0, used:never
> > 2023-10-09T14:11:55.242Z|00178|dpif|DBG|netdev@ovs-netdev: flow_del
> > ufid:07046e91-30a6-4862-9048-1a76b5a88a5b
> > recirc_id(0),dp_hash(0),skb_priority(0),in_port(2),skb_mark(0),
> > ct_state(0),ct_zone(0),ct_mark(0),ct_label(0),
> > packet_type(ns=0,id=0),
> > eth(src=a6:0a:bf:e2:f3:f2,dst=62:23:0f:f6:2c:75),
> > eth_type(0x0800),ipv4(src=10.1.1.1,dst=10.1.1.2,proto=17,tos=0,
> > ttl=64,frag=no),udp(src=37380,dst=10000), packets:0, bytes:0,
> > used:never
> > ...
> > 2023-10-09T14:11:55.242Z|00049|dpif(revalidator17)|WARN|netdev@ovs-netdev:
> > failed to flow_get (No such file or directory)
> > ufid:07046e91-30a6-4862-9048-1a76b5a88a5b <empty>, packets:0,
> > bytes:0, used:never
> > 2023-10-09T14:11:55.242Z|00050|ofproto_dpif_upcall(revalidator17)|WARN|
> > Failed to acquire udpif_key corresponding to unexpected flow
> > (No such file or directory):
> > ufid:07046e91-30a6-4862-9048-1a76b5a88a5b
> > ...
> > 2023-10-09T14:11:55.242Z|00183|unixctl|DBG|replying with success, id=0: ""
> >
> > To avoid this race, a first part of the fix is to pause (if not already
> > paused) the revalidators while the main thread is purging the datapath
> > flows.
> >
> > Then a second issue is observed by running the same unit test with the
> > kernel datapath. Its dpif implementation dumps flows via a netlink request
> > (see dpif_flow_dump_create(), dpif_netlink_flow_dump_create(),
> > nl_dump_start(), nl_sock_send__()) in the leader revalidator thread,
> > before pausing revalidators:
> >
> > 2023-10-09T14:44:28.742Z|00122|unixctl|DBG|received request
> > revalidator/purge[], id=0
> > ...
> > 2023-10-09T14:44:28.742Z|00125|dpif|DBG|system@ovs-system: flow_del
> > ufid:70102d81-30a1-44b9-aa76-3d02a9ffd2c9 recirc_id(0),dp_hash(0),
> > skb_priority(0),in_port(2),skb_mark(0),ct_state(0),ct_zone(0),
> > ct_mark(0),ct_label(0),eth(src=a6:0a:bf:e2:f3:f2,
> > dst=ff:ff:ff:ff:ff:ff),eth_type(0x0806),arp(sip=10.1.1.1,
> > tip=10.1.1.2,op=1,sha=a6:0a:bf:e2:f3:f2,tha=00:00:00:00:00:00),
> > packets:0, bytes:0, used:never
> > ...
> > 2023-10-09T14:44:28.742Z|00129|unixctl|DBG|replying with success, id=0: ""
> > ...
> > 2023-10-09T14:44:28.742Z|00006|dpif(revalidator21)|DBG|system@ovs-system:
> > flow_dump ufid:70102d81-30a1-44b9-aa76-3d02a9ffd2c9 <empty>,
> > packets:0, bytes:0, used:never
> > ...
> > 2023-10-09T14:44:28.742Z|00012|dpif(revalidator21)|WARN|system@ovs-system:
> > failed to flow_get (No such file or directory)
> > ufid:70102d81-30a1-44b9-aa76-3d02a9ffd2c9 <empty>, packets:0,
> > bytes:0, used:never
> > 2023-10-09T14:44:28.742Z|00013|ofproto_dpif_upcall(revalidator21)|WARN|
> > Failed to acquire udpif_key corresponding to unexpected flow
> > (No such file or directory):
> > ufid:70102d81-30a1-44b9-aa76-3d02a9ffd2c9
> >
> > To avoid evaluating already deleted flows, the second part of the fix is
> > to ensure that dumping from the leader revalidator thread is done out of
> > any pause request.
> >
> > Fixes: 98bb4286970d ("tests: Add command to purge revalidators of flows.")
> > Signed-off-by: David Marchand <david.march...@redhat.com>
> > ---
>
> Hi David,
>
> I'm not having much luck reproducing the above.
> Any guidance would be much appreciated.
Sorry, my fault.
I wrote and tested this series against my system-dpdk series (patch 7
pulls the system-traffic.at tests in check-dpdk).
https://patchwork.ozlabs.org/project/openvswitch/list/?series=371864&state=%2A&archive=both
I can't reproduce the issue with check-system-userspace on the current master.
But I do reproduce a failure on this test with check-kernel (rarely)
on the current master, on my fedora 37 system.
If I enable dpif:dbg logs in the test, it is more frequent:
$ git diff
diff --git a/tests/system-traffic.at b/tests/system-traffic.at
index 418cd32fec..0844ada0fd 100644
--- a/tests/system-traffic.at
+++ b/tests/system-traffic.at
@@ -3654,6 +3654,7 @@ AT_SETUP([conntrack - ICMP related])
AT_SKIP_IF([test $HAVE_NC = no])
CHECK_CONNTRACK()
OVS_TRAFFIC_VSWITCHD_START()
+AT_CHECK([ovs-appctl vlog/set dpif:dbg])
ADD_NAMESPACES(at_ns0, at_ns1)
# while true; do make -C build check-kernel TESTSUITEFLAGS="-d 78" ||
break; done
...
78: conntrack - ICMP related FAILED
(system-traffic.at:3687)
Then, looking for the flow that triggers a warning log message:
# grep -E 'unixctl|544ea5f9-7b93-48e4-a5da-ec76be873602'
build/tests/system-kmod-testsuite.dir/078/ovs-vswitchd.log
2023-10-13T12:26:01.151Z|00037|unixctl|DBG|received request
vlog/set["dpif:dbg"], id=0
2023-10-13T12:26:01.151Z|00038|unixctl|DBG|replying with success, id=0: ""
2023-10-13T12:26:01.269Z|00002|dpif(handler2)|DBG|system@ovs-system:
put[create] ufid:544ea5f9-7b93-48e4-a5da-ec76be873602
recirc_id(0),dp_hash(0/0),skb_priority(0/0),in_port(2),skb_mark(0/0),ct_state(0/0x24),ct_zone(0/0),ct_mark(0),ct_label(0/0),eth(src=a6:0a:bf:e2:f3:f2,dst=ff:ff:ff:ff:ff:ff),eth_type(0x0806),arp(sip=10.1.1.1,tip=10.1.1.2,op=1,sha=a6:0a:bf:e2:f3:f2/00:00:00:00:00:00,tha=00:00:00:00:00:00/00:00:00:00:00:00),
actions:1,3
2023-10-13T12:26:01.274Z|00122|unixctl|DBG|received request
revalidator/purge[], id=0
2023-10-13T12:26:01.274Z|00025|dpif(revalidator18)|DBG|system@ovs-system:
flow_dump ufid:544ea5f9-7b93-48e4-a5da-ec76be873602 <empty>,
packets:0, bytes:0, used:never
2023-10-13T12:26:01.274Z|00123|dpif|DBG|system@ovs-system: flow_del
ufid:544ea5f9-7b93-48e4-a5da-ec76be873602
recirc_id(0),dp_hash(0),skb_priority(0),in_port(2),skb_mark(0),ct_state(0),ct_zone(0),ct_mark(0),ct_label(0),eth(src=a6:0a:bf:e2:f3:f2,dst=ff:ff:ff:ff:ff:ff),eth_type(0x0806),arp(sip=10.1.1.1,tip=10.1.1.2,op=1,sha=a6:0a:bf:e2:f3:f2,tha=00:00:00:00:00:00),
packets:0, bytes:0, used:never
2023-10-13T12:26:01.274Z|00029|dpif(revalidator18)|WARN|system@ovs-system:
failed to flow_get (No such file or directory)
ufid:544ea5f9-7b93-48e4-a5da-ec76be873602 <empty>, packets:0, bytes:0,
used:never
2023-10-13T12:26:01.274Z|00030|ofproto_dpif_upcall(revalidator18)|WARN|Failed
to acquire udpif_key corresponding to unexpected flow (No such file or
directory): ufid:544ea5f9-7b93-48e4-a5da-ec76be873602
2023-10-13T12:26:01.275Z|00128|unixctl|DBG|replying with success, id=0: ""
2023-10-13T12:26:01.331Z|00157|unixctl|DBG|received request
exit["--cleanup"], id=0
2023-10-13T12:26:01.391Z|00165|unixctl|DBG|replying with success, id=0: ""
--
David Marchand
_______________________________________________
dev mailing list
d...@openvswitch.org
https://mail.openvswitch.org/mailman/listinfo/ovs-dev
