Hi David, On Wed, Oct 18, 2023 at 01:49:08PM +0200, David Marchand wrote: > Hello Simon, > > On Fri, Oct 13, 2023 at 2:53 PM David Marchand > <david.march...@redhat.com> wrote: > > 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: "" > > Did you manage to reproduce the issue? > Do you want me to change something in the patch?
Sorry, no, I didn't have a chance to reproduce the problem. But also, no, I don't have any changes to request. _______________________________________________ dev mailing list d...@openvswitch.org https://mail.openvswitch.org/mailman/listinfo/ovs-dev