[ovs-dev] [PATCH v2 3/4] Add file descriptor persistence where possible
Anton Ivanov
anton.ivanov at cambridgegreys.com
Tue Feb 25 08:02:23 UTC 2020
I have worked around it. Looking at the source I can guarantee that it is a work-around and not a 100% fix, but it has survived an overnight loop run on a 6 core/12 thread 3.5 GHz Ryzen.
The root cause is that instead of using a proper packet oriented interface (f.e SOCK_SEQPACKET or SOCK_DATAGRAM) interface, the dummy network device used in tests uses:
1. Unix Domain socket via the stream-unix/stream-fd which provides a stream abstraction, not a packet one.
2. Has no packet framing
3. Writes and waits on the same stream fd out of different threads.
Any one of these are not the right things to do. Unfortunately, fixing it properly will require both fixing netdev-dummy and a large number of tests which use it, so I have "taped over" it for the time being.
I will send the updated patchset as well as (hopefully) the first patches on top which multi-thread IO/SSL/JSON/(hopefully some processing) sometimes later this week.
Brgds,
A.
On 24/02/2020 14:59, Anton Ivanov wrote:
> This is not an stp failure, it is stp showing an underlying netdev-dummy issue similar to the netlink one earlier on.
>
> Brgds,
>
> 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/
More information about the dev
mailing list