[ovs-dev] [PATCH v2 3/4] Add file descriptor persistence where possible

Mon Feb 24 14:17:16 UTC 2020

I have it reproduced now.

It is a race of some sort which is caused (or unmasked) by the epoll changes.

A (relatively) slow CPU (f.e. 4 core A10 at 3.5GHz) has zero failures.

A fast CPU (f.e. 6 core/12 thread Ryzen at 4GHz) fails nearly every time.

If it is (e)poll related - I will figure it out and update the patches. If it is something inherent which is presently being masked I will send the fixes separately.

A.

On 24/02/2020 12:58, Dumitru Ceara wrote:
> On Mon, Feb 24, 2020 at 11:47 AM Anton Ivanov
> <anton.ivanov at cambridgegreys.com> wrote:
>>
>>
>> On 19/02/2020 14:20, Dumitru Ceara wrote:
>>> On 2/18/20 7:12 AM, Anton Ivanov wrote:
>>>>
>>>> On 17/02/2020 14:48, Dumitru Ceara wrote:
>>>>> On 2/14/20 6:54 PM, anton.ivanov at cambridgegreys.com wrote:
>>>>>> From: Anton Ivanov <anton.ivanov at cambridgegreys.com>
>>>>>>
>>>>>> 1. Adds "persistent" behaviour where feasible (streams and signals).
>>>>>> These are waited upon in the same thread where they are created. This
>>>>>> allows them to be registered persistently with the OS (if possible)
>>>>>> as well as the OS to provide hints - is the FD ready, is it closed,
>>>>>> etc.
>>>>>>
>>>>>> 2. Removes unnecessary attempts to perform a read vs EAGAIN on a fd
>>>>>> which is not ready if that fd has been registered as "private" to the
>>>>>> thread which waits upon it.
>>>>>>
>>>>>> 3. No longer breaks other parts of OVS which create the fd in one
>>>>>> thread and waits upon it in others.
>>>>>>
>>>>>> 3. Adds support for EPOLL on Linux and can be expanded to cover similar
>>>>>> poll++ frameworks in other OSes.
>>>>>>
>>>>>> 4. Sets up the necessary infrastructure to make IO/SSL multi-threaded
>>>>>> using a "centeral (e)poll dispatcher + IO threads" pattern
>>>>>>
>>>>>> Signed-off-by: Anton Ivanov <anton.ivanov at cambridgegreys.com>
>>>>> Hi Anton,
>>>>>
>>>>> A couple of issues inline. Except for that:
>>>>>
>>>>> 1. The "STP - flush the fdb and mdb when topology changed" OVS test is
>>>>> failing with your patches applied:
>>>>>
>>>>> make check TESTSUITEFLAGS='-k "flush the fdb"'
>>>> I will have a look.
>>
>>
>> I cannot reproduce that. It succeeds every time - 20 out of 20 runs. Can you send me some logs please?
>>
>>
> 
> Hi Anton,
> 
> After rebasing to latest upstream master I see the failure less often.
> But it's still there.
> 
> I pasted the testsuite below.
> 
> Regards,
> Dumitru
> 
> $ cat tests/testsuite.dir/2185/testsuite.log
> #                             -*- compilation -*-
> 2185. stp.at:467: testing STP - flush the fdb and mdb when topology changed ...
> ./stp.at:468: ovsdb-tool create conf.db
> $abs_top_srcdir/vswitchd/vswitch.ovsschema
> ./stp.at:468: ovsdb-server --detach --no-chdir --pidfile --log-file
> --remote=punix:$OVS_RUNDIR/db.sock
> stderr:
> 2020-02-24T12:56:14Z|00001|vlog|INFO|opened log file
> /home/dceara/git-repos/ovs/tests/testsuite.dir/2185/ovsdb-server.log
> ./stp.at:468: sed < stderr '
> /vlog|INFO|opened log file/d
> /ovsdb_server|INFO|ovsdb-server (Open vSwitch)/d'
> ./stp.at:468: ovs-vsctl --no-wait init
> ./stp.at:468: ovs-vswitchd --enable-dummy --disable-system
> --disable-system-route  --detach --no-chdir --pidfile --log-file
> -vvconn -vofproto_dpif -vunixctl
> stderr:
> 2020-02-24T12:56:14Z|00001|vlog|INFO|opened log file
> /home/dceara/git-repos/ovs/tests/testsuite.dir/2185/ovs-vswitchd.log
> 2020-02-24T12:56:14Z|00002|ovs_numa|INFO|Discovered 8 CPU cores on NUMA node 0
> 2020-02-24T12:56:14Z|00003|ovs_numa|INFO|Discovered 1 NUMA nodes and 8 CPU cores
> 2020-02-24T12:56:14Z|00004|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/db.sock:
> connecting...
> 2020-02-24T12:56:14Z|00005|netlink_socket|INFO|netlink: could not
> enable listening to all nsid (Operation not permitted)
> 2020-02-24T12:56:14Z|00006|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/db.sock:
> connected
> ./stp.at:468: sed < stderr '
> /ovs_numa|INFO|Discovered /d
> /vlog|INFO|opened log file/d
> /vswitchd|INFO|ovs-vswitchd (Open vSwitch)/d
> /reconnect|INFO|/d
> /dpif_netlink|INFO|Generic Netlink family .ovs_datapath. does not exist/d
> /ofproto|INFO|using datapath ID/d
> /netdev_linux|INFO|.*device has unknown hardware address family/d
> /ofproto|INFO|datapath ID changed to fedcba9876543210/d
> /dpdk|INFO|DPDK Disabled - Use other_config:dpdk-init to enable/d
> /netlink_socket|INFO|netlink: could not enable listening to all nsid/d
> /probe tc:/d
> /tc: Using policy/d'
> ./stp.at:468: add_of_br 0
> ./stp.at:471:
>      ovs-vsctl -- \
>      set port br0 other_config:stp-enable=false -- \
>      set bridge br0 datapath-type=dummy -- \
>      set bridge br0 stp_enable=true mcast_snooping_enable=true \
>      other-config:hwaddr=aa:66:aa:66:00:00 -- \
>      add-br br1 -- \
>      set port br1 other_config:stp-enable=false -- \
>      set bridge br1 datapath-type=dummy -- \
>      set bridge br1 stp_enable=true mcast_snooping_enable=true \
>      other-config:hwaddr=aa:66:aa:66:00:01 -- \
>      add-br br2 -- \
>      set port br2 other_config:stp-enable=false -- \
>      set bridge br2 datapath-type=dummy -- \
>      set bridge br2 stp_enable=true mcast_snooping_enable=true \
>      other-config:hwaddr=aa:66:aa:66:00:02
> 
> ./stp.at:489: ovs-appctl vlog/set ofproto_dpif:dbg
> ./stp.at:490: ovs-appctl vlog/set ofproto_dpif_xlate:dbg
> ./stp.at:492: ovs-ofctl add-flow br0 action=normal
> ./stp.at:493: ovs-ofctl add-flow br1 action=normal
> ./stp.at:494: ovs-ofctl add-flow br2 action=normal
> ./stp.at:496:
>      ovs-vsctl add-port br0 p1 -- \
>          set interface p1 type=dummy
> options:pstream=punix:$OVS_RUNDIR/p1.sock ofport_request=1
>      ovs-vsctl add-port br0 p2 -- \
>          set interface p2 type=dummy
> options:stream=unix:$OVS_RUNDIR/p6.sock ofport_request=2
>      ovs-vsctl add-port br1 p3 -- \
>          set interface p3 type=dummy
> options:stream=unix:$OVS_RUNDIR/p1.sock ofport_request=3
>      ovs-vsctl add-port br1 p4 -- \
>          set interface p4 type=dummy
> options:pstream=punix:$OVS_RUNDIR/p4.sock ofport_request=4
>      ovs-vsctl add-port br2 p5 -- \
>          set interface p5 type=dummy
> options:stream=unix:$OVS_RUNDIR/p4.sock ofport_request=5
>      ovs-vsctl add-port br2 p6 -- \
>          set interface p6 type=dummy
> options:pstream=punix:$OVS_RUNDIR/p6.sock ofport_request=6
> 
> OK
> warped
> ./stp.at:517: cat ovs-vswitchd.log |
> grep 'disabled to listening' | sed '
>    s/.*ofproto_dpif|.*|port .*:/port <>:/
> '
> warped
> ./stp.at:529: cat ovs-vswitchd.log |
> grep 'learning to forwarding' | sed '
>    s/.*ofproto_dpif|.*|port .*:/port <>:/
> '
> --- - 2020-02-24 13:56:14.337746686 +0100
> +++ /home/dceara/git-repos/ovs/tests/testsuite.dir/at-groups/2185/stdout
> 2020-02-24 13:56:14.000000000 +0100
> @@ -3,4 +3,5 @@
>   port <>: STP state changed from learning to forwarding
>   port <>: STP state changed from learning to forwarding
>   port <>: STP state changed from learning to forwarding
> +port <>: STP state changed from learning to forwarding
> 
> ovsdb-server.log:
>> 2020-02-24T12:56:14.033Z|00001|vlog|INFO|opened log file /home/dceara/git-repos/ovs/tests/testsuite.dir/2185/ovsdb-server.log
>> 2020-02-24T12:56:14.038Z|00002|ovsdb_server|INFO|ovsdb-server (Open vSwitch) 2.13.90
> ovs-vswitchd.log:
>> 2020-02-24T12:56:14.059Z|00001|vlog|INFO|opened log file /home/dceara/git-repos/ovs/tests/testsuite.dir/2185/ovs-vswitchd.log
>> 2020-02-24T12:56:14.061Z|00002|ovs_numa|INFO|Discovered 8 CPU cores on NUMA node 0
>> 2020-02-24T12:56:14.061Z|00003|ovs_numa|INFO|Discovered 1 NUMA nodes and 8 CPU cores
>> 2020-02-24T12:56:14.061Z|00004|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/db.sock: connecting...
>> 2020-02-24T12:56:14.061Z|00005|netlink_socket|INFO|netlink: could not enable listening to all nsid (Operation not permitted)
>> 2020-02-24T12:56:14.061Z|00006|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/db.sock: connected
>> 2020-02-24T12:56:14.065Z|00007|bridge|INFO|ovs-vswitchd (Open vSwitch) 2.13.90
>> 2020-02-24T12:56:14.091Z|00008|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports recirculation
>> 2020-02-24T12:56:14.091Z|00009|ofproto_dpif|INFO|dummy at ovs-dummy: VLAN header stack length probed as 1
>> 2020-02-24T12:56:14.091Z|00010|ofproto_dpif|INFO|dummy at ovs-dummy: MPLS label stack length probed as 3
>> 2020-02-24T12:56:14.091Z|00011|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports truncate action
>> 2020-02-24T12:56:14.091Z|00012|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports unique flow ids
>> 2020-02-24T12:56:14.091Z|00013|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports clone action
>> 2020-02-24T12:56:14.091Z|00014|ofproto_dpif|INFO|dummy at ovs-dummy: Max sample nesting level probed as 10
>> 2020-02-24T12:56:14.091Z|00015|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports eventmask in conntrack action
>> 2020-02-24T12:56:14.091Z|00016|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_clear action
>> 2020-02-24T12:56:14.091Z|00017|ofproto_dpif|INFO|dummy at ovs-dummy: Max dp_hash algorithm probed to be 1
>> 2020-02-24T12:56:14.091Z|00018|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports check_pkt_len action
>> 2020-02-24T12:56:14.091Z|00019|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports timeout policy in conntrack action
>> 2020-02-24T12:56:14.091Z|00020|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_state
>> 2020-02-24T12:56:14.091Z|00021|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_zone
>> 2020-02-24T12:56:14.091Z|00022|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_mark
>> 2020-02-24T12:56:14.091Z|00023|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_label
>> 2020-02-24T12:56:14.091Z|00024|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_state_nat
>> 2020-02-24T12:56:14.091Z|00025|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_orig_tuple
>> 2020-02-24T12:56:14.091Z|00026|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports ct_orig_tuple6
>> 2020-02-24T12:56:14.091Z|00027|ofproto_dpif|INFO|dummy at ovs-dummy: Datapath supports IPv6 ND Extensions
>> 2020-02-24T12:56:14.100Z|00028|bridge|INFO|bridge br0: added interface br0 on port 65534
>> 2020-02-24T12:56:14.101Z|00029|bridge|INFO|bridge br0: using datapath ID fedcba9876543210
>> 2020-02-24T12:56:14.101Z|00030|connmgr|INFO|br0: added service controller "punix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/br0.mgmt"
>> 2020-02-24T12:56:14.113Z|00031|bridge|INFO|bridge br2: added interface br2 on port 65534
>> 2020-02-24T12:56:14.113Z|00032|bridge|INFO|bridge br1: added interface br1 on port 65534
>> 2020-02-24T12:56:14.113Z|00033|bridge|INFO|bridge br2: using datapath ID 0000aa66aa660002
>> 2020-02-24T12:56:14.113Z|00034|connmgr|INFO|br2: added service controller "punix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/br2.mgmt"
>> 2020-02-24T12:56:14.113Z|00035|bridge|INFO|bridge br1: using datapath ID 0000aa66aa660001
>> 2020-02-24T12:56:14.113Z|00036|connmgr|INFO|br1: added service controller "punix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/br1.mgmt"
>> 2020-02-24T12:56:14.120Z|00037|unixctl|DBG|received request vlog/set["ofproto_dpif:dbg"], id=0
>> 2020-02-24T12:56:14.120Z|00038|unixctl|DBG|replying with success, id=0: ""
>> 2020-02-24T12:56:14.124Z|00039|unixctl|DBG|received request vlog/set["ofproto_dpif_xlate:dbg"], id=0
>> 2020-02-24T12:56:14.124Z|00040|unixctl|DBG|replying with success, id=0: ""
>> 2020-02-24T12:56:14.129Z|00041|vconn|DBG|unix#2: sent (Success): OFPT_HELLO (OF1.5) (xid=0x1):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.129Z|00042|vconn|DBG|unix#2: received: OFPT_HELLO (xid=0x1):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.129Z|00043|vconn|DBG|unix#2: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.129Z|00044|vconn|DBG|unix#2: received: OFPST_TABLE request (xid=0x2):
>> 2020-02-24T12:56:14.130Z|00045|vconn|DBG|unix#2: sent (Success): OFPST_TABLE reply (xid=0x2):
>>    table 0:
>>      active=0, lookup=0, matched=0
>>      max_entries=1000000
>>      matching:
>>        exact match or wildcard: in_port eth_{src,dst,type} vlan_{vid,pcp} ip_{src,dst} nw_{proto,tos} tcp_{src,dst}
>>
>>    tables 1...253: ditto
>> 2020-02-24T12:56:14.130Z|00046|vconn|DBG|unix#3: sent (Success): OFPT_HELLO (OF1.5) (xid=0x2):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.130Z|00047|vconn|DBG|unix#3: received: OFPT_HELLO (xid=0x3):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.130Z|00048|vconn|DBG|unix#3: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.130Z|00049|vconn|DBG|unix#3: received: OFPT_FEATURES_REQUEST (xid=0x4):
>> 2020-02-24T12:56:14.130Z|00050|vconn|DBG|unix#3: sent (Success): OFPT_FEATURES_REPLY (xid=0x4): dpid:fedcba9876543210
>> n_tables:254, n_buffers:0
>> capabilities: FLOW_STATS TABLE_STATS PORT_STATS QUEUE_STATS ARP_MATCH_IP
>> actions: output enqueue set_vlan_vid set_vlan_pcp strip_vlan mod_dl_src mod_dl_dst mod_nw_src mod_nw_dst mod_nw_tos mod_tp_src mod_tp_dst
>>   LOCAL(br0): addr:aa:66:aa:66:00:00
>>       config:     0
>>       state:      0
>>       speed: 0 Mbps now, 0 Mbps max
>> 2020-02-24T12:56:14.131Z|00051|vconn|DBG|unix#4: sent (Success): OFPT_HELLO (OF1.5) (xid=0x3):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.131Z|00052|vconn|DBG|unix#4: received: OFPT_HELLO (xid=0x5):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.131Z|00053|vconn|DBG|unix#4: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.131Z|00054|vconn|DBG|unix#4: received: OFPT_FLOW_MOD (xid=0x6): ADD actions=NORMAL
>> 2020-02-24T12:56:14.131Z|00055|vconn|DBG|unix#4: received: OFPT_BARRIER_REQUEST (xid=0x7):
>> 2020-02-24T12:56:14.131Z|00056|vconn|DBG|unix#4: sent (Success): OFPT_BARRIER_REPLY (xid=0x7):
>> 2020-02-24T12:56:14.131Z|00057|connmgr|INFO|br0<->unix#4: 1 flow_mods in the last 0 s (1 adds)
>> 2020-02-24T12:56:14.136Z|00058|vconn|DBG|unix#5: sent (Success): OFPT_HELLO (OF1.5) (xid=0x4):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.136Z|00059|vconn|DBG|unix#5: received: OFPT_HELLO (xid=0x1):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.136Z|00060|vconn|DBG|unix#5: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.136Z|00061|vconn|DBG|unix#5: received: OFPST_TABLE request (xid=0x2):
>> 2020-02-24T12:56:14.136Z|00062|vconn|DBG|unix#5: sent (Success): OFPST_TABLE reply (xid=0x2):
>>    table 0:
>>      active=1, lookup=0, matched=0
>>      max_entries=1000000
>>      matching:
>>        exact match or wildcard: in_port eth_{src,dst,type} vlan_{vid,pcp} ip_{src,dst} nw_{proto,tos} tcp_{src,dst}
>>
>>    table 1:
>>      active=0, lookup=0, matched=0
>>      (same features)
>>
>>    tables 2...253: ditto
>> 2020-02-24T12:56:14.137Z|00063|vconn|DBG|unix#6: sent (Success): OFPT_HELLO (OF1.5) (xid=0x5):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.137Z|00064|vconn|DBG|unix#6: received: OFPT_HELLO (xid=0x3):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.137Z|00065|vconn|DBG|unix#6: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.137Z|00066|vconn|DBG|unix#6: received: OFPT_FEATURES_REQUEST (xid=0x4):
>> 2020-02-24T12:56:14.137Z|00067|vconn|DBG|unix#6: sent (Success): OFPT_FEATURES_REPLY (xid=0x4): dpid:0000aa66aa660001
>> n_tables:254, n_buffers:0
>> capabilities: FLOW_STATS TABLE_STATS PORT_STATS QUEUE_STATS ARP_MATCH_IP
>> actions: output enqueue set_vlan_vid set_vlan_pcp strip_vlan mod_dl_src mod_dl_dst mod_nw_src mod_nw_dst mod_nw_tos mod_tp_src mod_tp_dst
>>   LOCAL(br1): addr:aa:66:aa:66:00:01
>>       config:     0
>>       state:      0
>>       speed: 0 Mbps now, 0 Mbps max
>> 2020-02-24T12:56:14.137Z|00068|vconn|DBG|unix#7: sent (Success): OFPT_HELLO (OF1.5) (xid=0x6):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.137Z|00069|vconn|DBG|unix#7: received: OFPT_HELLO (xid=0x5):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.137Z|00070|vconn|DBG|unix#7: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.138Z|00071|vconn|DBG|unix#7: received: OFPT_FLOW_MOD (xid=0x6): ADD actions=NORMAL
>> 2020-02-24T12:56:14.138Z|00072|vconn|DBG|unix#7: received: OFPT_BARRIER_REQUEST (xid=0x7):
>> 2020-02-24T12:56:14.138Z|00073|vconn|DBG|unix#7: sent (Success): OFPT_BARRIER_REPLY (xid=0x7):
>> 2020-02-24T12:56:14.138Z|00074|connmgr|INFO|br1<->unix#7: 1 flow_mods in the last 0 s (1 adds)
>> 2020-02-24T12:56:14.143Z|00075|vconn|DBG|unix#8: sent (Success): OFPT_HELLO (OF1.5) (xid=0x7):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.143Z|00076|vconn|DBG|unix#8: received: OFPT_HELLO (xid=0x1):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.143Z|00077|vconn|DBG|unix#8: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.143Z|00078|vconn|DBG|unix#8: received: OFPST_TABLE request (xid=0x2):
>> 2020-02-24T12:56:14.143Z|00079|vconn|DBG|unix#8: sent (Success): OFPST_TABLE reply (xid=0x2):
>>    table 0:
>>      active=1, lookup=0, matched=0
>>      max_entries=1000000
>>      matching:
>>        exact match or wildcard: in_port eth_{src,dst,type} vlan_{vid,pcp} ip_{src,dst} nw_{proto,tos} tcp_{src,dst}
>>
>>    table 1:
>>      active=0, lookup=0, matched=0
>>      (same features)
>>
>>    tables 2...253: ditto
>> 2020-02-24T12:56:14.144Z|00080|vconn|DBG|unix#9: sent (Success): OFPT_HELLO (OF1.5) (xid=0x8):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.144Z|00081|vconn|DBG|unix#9: received: OFPT_HELLO (xid=0x3):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.144Z|00082|vconn|DBG|unix#9: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.144Z|00083|vconn|DBG|unix#9: received: OFPT_FEATURES_REQUEST (xid=0x4):
>> 2020-02-24T12:56:14.144Z|00084|vconn|DBG|unix#9: sent (Success): OFPT_FEATURES_REPLY (xid=0x4): dpid:0000aa66aa660002
>> n_tables:254, n_buffers:0
>> capabilities: FLOW_STATS TABLE_STATS PORT_STATS QUEUE_STATS ARP_MATCH_IP
>> actions: output enqueue set_vlan_vid set_vlan_pcp strip_vlan mod_dl_src mod_dl_dst mod_nw_src mod_nw_dst mod_nw_tos mod_tp_src mod_tp_dst
>>   LOCAL(br2): addr:aa:66:aa:66:00:02
>>       config:     0
>>       state:      0
>>       speed: 0 Mbps now, 0 Mbps max
>> 2020-02-24T12:56:14.144Z|00085|vconn|DBG|unix#10: sent (Success): OFPT_HELLO (OF1.5) (xid=0x9):
>>   version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2020-02-24T12:56:14.144Z|00086|vconn|DBG|unix#10: received: OFPT_HELLO (xid=0x5):
>>   version bitmap: 0x01
>> 2020-02-24T12:56:14.144Z|00087|vconn|DBG|unix#10: negotiated OpenFlow version 0x01 (we support version 0x06 and earlier, peer supports version 0x01)
>> 2020-02-24T12:56:14.145Z|00088|vconn|DBG|unix#10: received: OFPT_FLOW_MOD (xid=0x6): ADD actions=NORMAL
>> 2020-02-24T12:56:14.145Z|00089|vconn|DBG|unix#10: received: OFPT_BARRIER_REQUEST (xid=0x7):
>> 2020-02-24T12:56:14.145Z|00090|vconn|DBG|unix#10: sent (Success): OFPT_BARRIER_REPLY (xid=0x7):
>> 2020-02-24T12:56:14.145Z|00091|connmgr|INFO|br2<->unix#10: 1 flow_mods in the last 0 s (1 adds)
>> 2020-02-24T12:56:14.154Z|00092|bridge|INFO|bridge br0: added interface p1 on port 1
>> 2020-02-24T12:56:14.154Z|00093|ofproto_dpif|DBG|port p1: STP state changed from disabled to listening
>> 2020-02-24T12:56:14.164Z|00094|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connecting...
>> 2020-02-24T12:56:14.164Z|00095|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connection attempt failed (No such file or directory)
>> 2020-02-24T12:56:14.164Z|00096|bridge|INFO|bridge br0: added interface p2 on port 2
>> 2020-02-24T12:56:14.164Z|00097|ofproto_dpif|DBG|port p2: STP state changed from disabled to listening
>> 2020-02-24T12:56:14.174Z|00098|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connecting...
>> 2020-02-24T12:56:14.174Z|00099|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connection attempt failed (No such file or directory)
>> 2020-02-24T12:56:14.174Z|00100|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p1.sock: connecting...
>> 2020-02-24T12:56:14.174Z|00101|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p1.sock: connected
>> 2020-02-24T12:56:14.174Z|00102|bridge|INFO|bridge br1: added interface p3 on port 3
>> 2020-02-24T12:56:14.174Z|00103|ofproto_dpif|DBG|port p3: STP state changed from disabled to listening
>> 2020-02-24T12:56:14.183Z|00104|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connecting...
>> 2020-02-24T12:56:14.183Z|00105|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connection attempt failed (No such file or directory)
>> 2020-02-24T12:56:14.184Z|00106|bridge|INFO|bridge br1: added interface p4 on port 4
>> 2020-02-24T12:56:14.184Z|00107|ofproto_dpif|DBG|port p4: STP state changed from disabled to listening
>> 2020-02-24T12:56:14.193Z|00108|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connecting...
>> 2020-02-24T12:56:14.193Z|00109|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connection attempt failed (No such file or directory)
>> 2020-02-24T12:56:14.193Z|00110|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p4.sock: connecting...
>> 2020-02-24T12:56:14.193Z|00111|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p4.sock: connected
>> 2020-02-24T12:56:14.193Z|00112|bridge|INFO|bridge br2: added interface p5 on port 5
>> 2020-02-24T12:56:14.193Z|00113|ofproto_dpif|DBG|port p5: STP state changed from disabled to listening
>> 2020-02-24T12:56:14.203Z|00114|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connecting...
>> 2020-02-24T12:56:14.203Z|00115|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connection attempt failed (No such file or directory)
>> 2020-02-24T12:56:14.203Z|00116|bridge|INFO|bridge br2: added interface p6 on port 6
>> 2020-02-24T12:56:14.203Z|00117|ofproto_dpif|DBG|port p6: STP state changed from disabled to listening
>> 2020-02-24T12:56:14.208Z|00118|unixctl|DBG|received request netdev-dummy/set-admin-state["up"], id=0
>> 2020-02-24T12:56:14.208Z|00119|unixctl|DBG|replying with success, id=0: "OK"
>> 2020-02-24T12:56:14.212Z|00120|unixctl|DBG|received request time/stop[], id=0
>> 2020-02-24T12:56:14.212Z|00121|unixctl|DBG|replying with success, id=0: ""
>> 2020-02-24T12:56:14.215Z|00122|unixctl|DBG|received request time/warp["6000","3000"], id=0
>> 2020-02-24T12:56:14.225Z|00123|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connecting...
>> 2020-02-24T12:56:14.225Z|00124|reconnect|INFO|unix:/home/dceara/git-repos/ovs/tests/testsuite.dir/2185/p6.sock: connected
>> 2020-02-24T12:56:14.225Z|00125|unixctl|DBG|replying with success, id=0: "warped"
>> 2020-02-24T12:56:14.236Z|00126|ofproto_dpif_xlate|DBG|/proc/sys/net/core/netdev_max_backlog: using 1000 max_backlog
>> 2020-02-24T12:56:14.236Z|00127|unixctl|DBG|received request time/warp["30000","3000"], id=0
>> 2020-02-24T12:56:14.257Z|00128|memory|INFO|14512 kB peak resident set size after 12.2 seconds
>> 2020-02-24T12:56:14.257Z|00129|memory|INFO|handlers:5 ports:9 revalidators:3 rules:17
>> 2020-02-24T12:56:14.268Z|00130|ofproto_dpif|DBG|port p2: STP state changed from listening to learning
>> 2020-02-24T12:56:14.268Z|00131|ofproto_dpif|DBG|port p1: STP state changed from listening to learning
>> 2020-02-24T12:56:14.268Z|00132|ofproto_dpif|DBG|port p6: STP state changed from listening to learning
>> 2020-02-24T12:56:14.268Z|00133|ofproto_dpif|DBG|port p5: STP state changed from listening to learning
>> 2020-02-24T12:56:14.268Z|00134|ofproto_dpif|DBG|port p3: STP state changed from listening to learning
>> 2020-02-24T12:56:14.268Z|00135|ofproto_dpif|DBG|port p4: STP state changed from listening to learning
>> 2020-02-24T12:56:14.280Z|00001|ovs_rcu(urcu3)|WARN|blocked 3000 ms waiting for main to quiesce
>> 2020-02-24T12:56:14.280Z|00002|ovs_rcu(urcu3)|WARN|blocked 3000 ms waiting for main to quiesce
>> 2020-02-24T12:56:14.323Z|00136|stp|INFO|br0: detected topology change.
>> 2020-02-24T12:56:14.323Z|00137|stp|INFO|br0: detected topology change.
>> 2020-02-24T12:56:14.323Z|00138|ofproto_dpif|DBG|port p2: STP state changed from learning to forwarding
>> 2020-02-24T12:56:14.323Z|00139|ofproto_dpif|DBG|port p1: STP state changed from learning to forwarding
>> 2020-02-24T12:56:14.323Z|00140|stp|INFO|br2: detected topology change.
>> 2020-02-24T12:56:14.323Z|00141|stp|INFO|br2: detected topology change.
>> 2020-02-24T12:56:14.323Z|00142|ofproto_dpif|DBG|port p6: STP state changed from learning to forwarding
>> 2020-02-24T12:56:14.323Z|00143|ofproto_dpif|DBG|port p5: STP state changed from learning to forwarding
>> 2020-02-24T12:56:14.323Z|00144|stp|INFO|br1: detected topology change.
>> 2020-02-24T12:56:14.323Z|00145|ofproto_dpif|DBG|port p3: STP state changed from learning to forwarding
>> 2020-02-24T12:56:14.323Z|00146|ofproto_dpif|DBG|port p4: STP state changed from learning to forwarding
>> 2020-02-24T12:56:14.334Z|00147|unixctl|DBG|replying with success, id=0: "warped"
> 2185. stp.at:467: 2185. STP - flush the fdb and mdb when topology
> changed (stp.at:467): FAILED (stp.at:529)
> 
> 

-- 
Anton R. Ivanov
Cambridgegreys Limited. Registered in England. Company Number 10273661
https://www.cambridgegreys.com/