diff mbox

[ovs-dev] tests: Add and improve stp tests.

Message ID 1489060189-13109-1-git-send-email-nic@opencloud.tech
State Accepted
Headers show

Commit Message

nickcooper-zhangtonghao March 9, 2017, 11:49 a.m. UTC
This patch makes the stp tests more stable and
adds the test for fdb/mdb flushing when topology
is changed.

Signed-off-by: nickcooper-zhangtonghao <nic@opencloud.tech>
---
 tests/stp.at | 163 +++++++++++++++++++++++++++++++++++++++++++++++++++++++----
 1 file changed, 154 insertions(+), 9 deletions(-)

Comments

Ben Pfaff March 17, 2017, 8:14 p.m. UTC | #1
On Thu, Mar 09, 2017 at 03:49:49AM -0800, nickcooper-zhangtonghao wrote:
> This patch makes the stp tests more stable and
> adds the test for fdb/mdb flushing when topology
> is changed.
> 
> Signed-off-by: nickcooper-zhangtonghao <nic@opencloud.tech>

Thanks for the tests!  I applied this to master.
Joe Stringer March 20, 2017, 9:15 p.m. UTC | #2
On 9 March 2017 at 03:49, nickcooper-zhangtonghao <nic@opencloud.tech> wrote:
> This patch makes the stp tests more stable and
> adds the test for fdb/mdb flushing when topology
> is changed.
>
> Signed-off-by: nickcooper-zhangtonghao <nic@opencloud.tech>
> ---
>  tests/stp.at | 163 +++++++++++++++++++++++++++++++++++++++++++++++++++++++----
>  1 file changed, 154 insertions(+), 9 deletions(-)
>
> diff --git a/tests/stp.at b/tests/stp.at
> index 8b64218..20f7940 100644
> --- a/tests/stp.at
> +++ b/tests/stp.at
> @@ -374,7 +374,12 @@ m4_define([STRIP_USED], [[sed '
>  ']])
>  m4_define([FILTER_STP_TOPOLOGY], [[
>  grep 'STP state change' | sed '
> -    s/.*ofproto_dpif|.*|//
> +    s/.*ofproto_dpif|.*|port .*:/port <>:/
> +']])
> +
> +m4_define([FILTER_STP_TOPOLOGY_FORWARDING], [[
> +grep 'learning to forwarding' | sed '
> +  s/.*ofproto_dpif|.*|port .*:/port <>:/
>  ']])
>
>  AT_SETUP([STP - dummy interface])
> @@ -423,8 +428,8 @@ ovs-appctl time/warp 3000
>  ovs-appctl time/warp 3000
>
>  AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY], [0], [dnl
> -port p1: STP state changed from disabled to listening
> -port p2: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
>  ])
>
>  AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(7),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.0.0.2,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep STP], [0], [dnl
> @@ -445,14 +450,15 @@ ovs-appctl time/warp 3000
>  ovs-appctl time/warp 3000
>  ovs-appctl time/warp 3000
>  ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
>
>  AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY], [0], [dnl
> -port p1: STP state changed from disabled to listening
> -port p2: STP state changed from disabled to listening
> -port p1: STP state changed from listening to learning
> -port p2: STP state changed from listening to learning
> -port p1: STP state changed from learning to forwarding
> -port p2: STP state changed from learning to forwarding
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from listening to learning
> +port <>: STP state changed from listening to learning
> +port <>: STP state changed from learning to forwarding
> +port <>: STP state changed from learning to forwarding
>  ])
>
>  AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(7),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.0.0.2,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep Datapath], [0], [dnl
> @@ -462,5 +468,144 @@ AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(8),eth(src=50:54:00:00:00:
>  Datapath actions: 2
>  ])
>
> +AT_CLEANUP
> +
> +AT_SETUP([STP - flush the fdb and mdb when topology changed])
> +OVS_VSWITCHD_START([])
> +
> +# setting as below, the br0 will be root bridge and p5 will be blocked.
> +AT_CHECK([
> +    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
> +], [0])
> +
> +AT_CHECK([ovs-appctl vlog/set ofproto_dpif:dbg])
> +
> +AT_CHECK([ovs-ofctl add-flow br0 action=normal])
> +AT_CHECK([ovs-ofctl add-flow br1 action=normal])
> +AT_CHECK([ovs-ofctl add-flow br2 action=normal])
> +
> +AT_CHECK([
> +    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
> +], [0])
> +
> +
> +ovs-appctl time/stop
> +
> +# give time for STP to move initially
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +
> +AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY], [0], [dnl
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
> +port <>: STP state changed from disabled to listening
> +])
> +
> +# give time for STP to synchronize
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +ovs-appctl time/warp 3000
> +
> +AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY_FORWARDING], [0], [dnl
> +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
> +port <>: STP state changed from learning to forwarding
> +])
> +
> +# root bridge sends query packet
> +# we don't want to lose that message, so send it twice
> +AT_CHECK([ovs-appctl netdev-dummy/receive br0 \
> +        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'])
> +
> +ovs-appctl time/warp 1000
> +AT_CHECK([ovs-appctl netdev-dummy/receive br0 \
> +        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'])
> +
> +OVS_WAIT_UNTIL([ovs-appctl fdb/show br0 | grep '00:0c:29:a0:27:d1'])
> +OVS_WAIT_UNTIL([ovs-appctl fdb/show br1 | grep '00:0c:29:a0:27:d1'])
> +OVS_WAIT_UNTIL([ovs-appctl fdb/show br2 | grep '00:0c:29:a0:27:d1'])
> +
> +OVS_WAIT_UNTIL([ovs-appctl mdb/show br0 | grep 'querier'])

Hmm, on my system this test just times out on this line and I get the
dreaded 'hard failure' (ie, it tried several times and the condition
never became true).

(My system is a bit weird, with newer kernel, python3 by default and
other things, but I don't see how any of that relates to this
particular problem..)

Here's my testsuite log:

#                             -*- compilation -*-
2180. stp.at:473: testing STP - flush the fdb and mdb when topology changed ...
../../tests/stp.at:474: ovsdb-tool create conf.db
$abs_top_srcdir/vswitchd/vswitch.ovsschema
../../tests/stp.at:474: ovsdb-server --detach --no-chdir --pidfile
--log-file --remote=punix:$OVS_RUNDIR/db.sock
stderr:
2017-03-20T21:06:42Z|00001|vlog|INFO|opened log file
/home/joe/git/openvswitch/_build-gcc/tests/testsuite.dir/2180/ovsdb-server.log
../../tests/stp.at:474: sed < stderr '
/vlog|INFO|opened log file/d
/ovsdb_server|INFO|ovsdb-server (Open vSwitch)/d'
../../tests/stp.at:474: ovs-vsctl --no-wait init
../../tests/stp.at:474: ovs-vswitchd --enable-dummy --disable-system
--detach --no-chdir --pidfile --log-file -vvconn -vofproto_dpif
-vunixctl
stderr:
2017-03-20T21:06:42Z|00001|vlog|INFO|opened log file
/home/joe/git/openvswitch/_build-gcc/tests/testsuite.dir/2180/ovs-vswitchd.log
2017-03-20T21:06:42Z|00002|ovs_numa|INFO|Discovered 4 CPU cores on NUMA node 0
2017-03-20T21:06:42Z|00003|ovs_numa|INFO|Discovered 1 NUMA nodes and 4 CPU cores
2017-03-20T21:06:42Z|00004|reconnect|INFO|unix:/home/joe/git/openvswitch/_build-gcc/tests/testsuite.dir/2180/db.sock:
connecting...
2017-03-20T21:06:42Z|00005|reconnect|INFO|unix:/home/joe/git/openvswitch/_build-gcc/tests/testsuite.dir/2180/db.sock:
connected
../../tests/stp.at:474: sed < stderr '
/ovs_numa|INFO|Discovered /d
/vlog|INFO|opened log file/d
/vswitchd|INFO|ovs-vswitchd (Open vSwitch)/d
/reconnect|INFO|/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'
../../tests/stp.at:474: add_of_br 0
../../tests/stp.at:477:
    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

../../tests/stp.at:495: ovs-appctl vlog/set ofproto_dpif:dbg
../../tests/stp.at:497: ovs-ofctl add-flow br0 action=normal
../../tests/stp.at:498: ovs-ofctl add-flow br1 action=normal
../../tests/stp.at:499: ovs-ofctl add-flow br2 action=normal
../../tests/stp.at:501:
    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

warped
warped
../../tests/stp.at:523: cat ovs-vswitchd.log |
grep 'STP state change' | sed '
    s/.*ofproto_dpif|.*|port .*:/port <>:/
'
warped
warped
warped
warped
warped
warped
warped
warped
warped
warped
../../tests/stp.at:545: cat ovs-vswitchd.log |
grep 'learning to forwarding' | sed '
  s/.*ofproto_dpif|.*|port .*:/port <>:/
'
../../tests/stp.at:555: ovs-appctl netdev-dummy/receive br0 \
        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'
warped
../../tests/stp.at:559: ovs-appctl netdev-dummy/receive br0 \
        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'
LOCAL     1  00:0c:29:a0:27:d1    0
    3     1  00:0c:29:a0:27:d1    0
    6     1  00:0c:29:a0:27:d1    0
../../tests/stp.at:566: hard failure
2180. stp.at:473: 2180. STP - flush the fdb and mdb when topology
changed (stp.at:473): FAILED (stp.at:566)
Ben Pfaff March 20, 2017, 9:21 p.m. UTC | #3
On Mon, Mar 20, 2017 at 02:15:24PM -0700, Joe Stringer wrote:
> On 9 March 2017 at 03:49, nickcooper-zhangtonghao <nic@opencloud.tech> wrote:
> > +ovs-appctl time/warp 1000
> > +AT_CHECK([ovs-appctl netdev-dummy/receive br0 \
> > +        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'])
> > +
> > +OVS_WAIT_UNTIL([ovs-appctl fdb/show br0 | grep '00:0c:29:a0:27:d1'])
> > +OVS_WAIT_UNTIL([ovs-appctl fdb/show br1 | grep '00:0c:29:a0:27:d1'])
> > +OVS_WAIT_UNTIL([ovs-appctl fdb/show br2 | grep '00:0c:29:a0:27:d1'])
> > +
> > +OVS_WAIT_UNTIL([ovs-appctl mdb/show br0 | grep 'querier'])
> 
> Hmm, on my system this test just times out on this line and I get the
> dreaded 'hard failure' (ie, it tried several times and the condition
> never became true).
> 
> (My system is a bit weird, with newer kernel, python3 by default and
> other things, but I don't see how any of that relates to this
> particular problem..)

As a minor point here, I can at least confirm that I did run the tests
before applying them and that they pass on my system (and I've run them
since applying too), so that there is really likely to be some kind of
difference between machines.
Joe Stringer March 20, 2017, 9:24 p.m. UTC | #4
On 20 March 2017 at 14:21, Ben Pfaff <blp@ovn.org> wrote:
> On Mon, Mar 20, 2017 at 02:15:24PM -0700, Joe Stringer wrote:
>> On 9 March 2017 at 03:49, nickcooper-zhangtonghao <nic@opencloud.tech> wrote:
>> > +ovs-appctl time/warp 1000
>> > +AT_CHECK([ovs-appctl netdev-dummy/receive br0 \
>> > +        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'])
>> > +
>> > +OVS_WAIT_UNTIL([ovs-appctl fdb/show br0 | grep '00:0c:29:a0:27:d1'])
>> > +OVS_WAIT_UNTIL([ovs-appctl fdb/show br1 | grep '00:0c:29:a0:27:d1'])
>> > +OVS_WAIT_UNTIL([ovs-appctl fdb/show br2 | grep '00:0c:29:a0:27:d1'])
>> > +
>> > +OVS_WAIT_UNTIL([ovs-appctl mdb/show br0 | grep 'querier'])
>>
>> Hmm, on my system this test just times out on this line and I get the
>> dreaded 'hard failure' (ie, it tried several times and the condition
>> never became true).
>>
>> (My system is a bit weird, with newer kernel, python3 by default and
>> other things, but I don't see how any of that relates to this
>> particular problem..)
>
> As a minor point here, I can at least confirm that I did run the tests
> before applying them and that they pass on my system (and I've run them
> since applying too), so that there is really likely to be some kind of
> difference between machines.

Right, Travis seems happy too so most likely it's something to do with
my setup. I'm open to ideas about what might cause this.
nickcooper-zhangtonghao March 21, 2017, 12:47 a.m. UTC | #5
I tested it via command as below for a long time.

while true; do make check TESTSUITEFLAGS='-k stp'; done

But it’s ok. I try to find what might cause this.


Thanks.
Nick

> On Mar 21, 2017, at 5:24 AM, Joe Stringer <joe@ovn.org> wrote:
> 
> Right, Travis seems happy too so most likely it's something to do with
> my setup. I'm open to ideas about what might cause this.
Joe Stringer March 21, 2017, 12:56 a.m. UTC | #6
On 20 March 2017 at 17:47, nickcooper-zhangtonghao <nic@opencloud.tech> wrote:
> I tested it via command as below for a long time.
>
> while true; do make check TESTSUITEFLAGS='-k stp'; done
>
> But it’s ok. I try to find what might cause this.

OK, I think it's pretty reliably failing on my system so there must be
something else related to the environment. Hopefully the other report
will have a lead
towards more information.
nickcooper-zhangtonghao March 21, 2017, 1:11 p.m. UTC | #7
Hi Joe, I don’t reproduce the issue. You resolve it ? 
I submitted a patch which may fix one issue on ubuntu.
I am really sorry about it.

Thanks.
Nick

> On Mar 21, 2017, at 8:56 AM, Joe Stringer <joe@ovn.org> wrote:
> 
> On 20 March 2017 at 17:47, nickcooper-zhangtonghao <nic@opencloud.tech <mailto:nic@opencloud.tech>> wrote:
>> I tested it via command as below for a long time.
>> 
>> while true; do make check TESTSUITEFLAGS='-k stp'; done
>> 
>> But it’s ok. I try to find what might cause this.
> 
> OK, I think it's pretty reliably failing on my system so there must be
> something else related to the environment. Hopefully the other report
> will have a lead
> towards more information.
Alin Serdean March 21, 2017, 5:58 p.m. UTC | #8
Hi Nick,

Sorry for dropping late to the party 😊. 

I have no idea what the root cause is, but maybe this will help with your debugging:
http://64.119.130.115/ovs/3d8e7354f5e981dee3301268fc498efcec6521e9/testsuite.dir/2180/testsuite.log.gz
The issue is p5 changes from disabled to listening and blocking afterwards:
"> 2017-03-21T07:04:56.099Z|00088|ofproto_dpif|DBG|port p5: STP state changed from listening to blocking"

This happens when you slow down the system. I managed to reproduce on Ubuntu as well (if I enforce parallel on all the tests) with the same symptom:
```
root@ubuntu:/home/ubuntu/ovs# cat tests/testsuite.dir/2180/testsuite.log | grep blocking
+port <>: STP state changed from listening to blocking
> 2017-03-21T17:04:36.128Z|00091|ofproto_dpif|DBG|port p5: STP state changed from listening to blocking

root@ubuntu:/home/ubuntu/ovs# cat tests/testsuite.dir/2180/ | grep blocking
cleanup           conf.db           .conf.db.~lock~   ovsdb-server.log  ovs-vswitchd.log  run               stderr            testsuite.log
root@ubuntu:/home/ubuntu/ovs# cat tests/testsuite.dir/2180/ovs-vswitchd.log | grep blocking
2017-03-21T17:04:36.128Z|00091|ofproto_dpif|DBG|port p5: STP state changed from listening to blocking
root@ubuntu:/home/ubuntu/ovs# uname -a
Linux ubuntu 4.4.0-31-generic #50-Ubuntu SMP Wed Jul 13 00:07:12 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
```
https://patchwork.ozlabs.org/patch/741524/  will fix it because the port p5 is listening at one point.

Thanks,
Alin.
> > On Mar 21, 2017, at 8:56 AM, Joe Stringer <joe@ovn.org> wrote:

> >

> > On 20 March 2017 at 17:47, nickcooper-zhangtonghao

> <nic@opencloud.tech <mailto:nic@opencloud.tech>> wrote:

> >> I tested it via command as below for a long time.

> >>

> >> while true; do make check TESTSUITEFLAGS='-k stp'; done

> >>

> >> But it’s ok. I try to find what might cause this.

> >

> > OK, I think it's pretty reliably failing on my system so there must be

> > something else related to the environment. Hopefully the other report

> > will have a lead towards more information.

> 

> _______________________________________________

> dev mailing list

> dev@openvswitch.org

> https://mail.openvswitch.org/mailman/listinfo/ovs-dev
nickcooper-zhangtonghao March 22, 2017, 1:16 a.m. UTC | #9
> On Mar 22, 2017, at 1:58 AM, Alin Serdean <aserdean@cloudbasesolutions.com> wrote:
> 
> Hi Nick,
> 
> Sorry for dropping late to the party 😊. 
> 
> I have no idea what the root cause is, but maybe this will help with your debugging:
> http://64.119.130.115/ovs/3d8e7354f5e981dee3301268fc498efcec6521e9/testsuite.dir/2180/testsuite.log.gz <http://64.119.130.115/ovs/3d8e7354f5e981dee3301268fc498efcec6521e9/testsuite.dir/2180/testsuite.log.gz>
> The issue is p5 changes from disabled to listening and blocking afterwards:
> "> 2017-03-21T07:04:56.099Z|00088|ofproto_dpif|DBG|port p5: STP state changed from listening to blocking"
> 
> This happens when you slow down the system. I managed to reproduce on Ubuntu as well (if I enforce parallel on all the tests) with the same symptom:
> ```
> root@ubuntu:/home/ubuntu/ovs# cat tests/testsuite.dir/2180/testsuite.log | grep blocking
> +port <>: STP state changed from listening to blocking
>> 2017-03-21T17:04:36.128Z|00091|ofproto_dpif|DBG|port p5: STP state changed from listening to blocking
> root@ubuntu:/home/ubuntu/ovs# cat tests/testsuite.dir/2180/ | grep blocking
> cleanup           conf.db           .conf.db.~lock~   ovsdb-server.log  ovs-vswitchd.log  run               stderr            testsuite.log
> root@ubuntu:/home/ubuntu/ovs# cat tests/testsuite.dir/2180/ovs-vswitchd.log | grep blocking
> 2017-03-21T17:04:36.128Z|00091|ofproto_dpif|DBG|port p5: STP state changed from listening to blocking
> root@ubuntu:/home/ubuntu/ovs# uname -a
> Linux ubuntu 4.4.0-31-generic #50-Ubuntu SMP Wed Jul 13 00:07:12 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
> ```
> https://patchwork.ozlabs.org/patch/741524/ <https://patchwork.ozlabs.org/patch/741524/>  will fix it because the port p5 is listening at one point.
> 
> Thanks,
> Alin.

Thanks for your help. This patch (https://patchwork.ozlabs.org/patch/741524/ <https://patchwork.ozlabs.org/patch/741524/>) fixes the bug reported at :
http://101.96.8.164/64.119.130.115/ovs/3d8e7354f5e981dee3301268fc498efcec6521e9/testsuite.dir/2180/testsuite.log.gz <http://101.96.8.164/64.119.130.115/ovs/3d8e7354f5e981dee3301268fc498efcec6521e9/testsuite.dir/2180/testsuite.log.gz>

The other issue is that stp is timeout when running to the line on Joe’s machine.

OVS_WAIT_UNTIL([ovs-appctl fdb/show br0 | grep '00:0c:29:a0:27:d1’])
OVS_WAIT_UNTIL([ovs-appctl fdb/show br1 | grep '00:0c:29:a0:27:d1’])
OVS_WAIT_UNTIL([ovs-appctl fdb/show br2 | grep '00:0c:29:a0:27:d1’])

Today, I try to reproduce it and fix it. More helpful info will be post here.
Thanks for your help again.
nickcooper-zhangtonghao March 23, 2017, 6:50 a.m. UTC | #10
Hi, the new patch has been submitted. It fixes the issue on
ubuntu and newer kernel (4.10.4). You can review and tested it.

http://patchwork.ozlabs.org/patch/742517/ <http://patchwork.ozlabs.org/patch/742517/>
diff mbox

Patch

diff --git a/tests/stp.at b/tests/stp.at
index 8b64218..20f7940 100644
--- a/tests/stp.at
+++ b/tests/stp.at
@@ -374,7 +374,12 @@  m4_define([STRIP_USED], [[sed '
 ']])
 m4_define([FILTER_STP_TOPOLOGY], [[
 grep 'STP state change' | sed '
-    s/.*ofproto_dpif|.*|//
+    s/.*ofproto_dpif|.*|port .*:/port <>:/
+']])
+
+m4_define([FILTER_STP_TOPOLOGY_FORWARDING], [[
+grep 'learning to forwarding' | sed '
+  s/.*ofproto_dpif|.*|port .*:/port <>:/
 ']])
 
 AT_SETUP([STP - dummy interface])
@@ -423,8 +428,8 @@  ovs-appctl time/warp 3000
 ovs-appctl time/warp 3000
 
 AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY], [0], [dnl
-port p1: STP state changed from disabled to listening
-port p2: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
 ])
 
 AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(7),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.0.0.2,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep STP], [0], [dnl
@@ -445,14 +450,15 @@  ovs-appctl time/warp 3000
 ovs-appctl time/warp 3000
 ovs-appctl time/warp 3000
 ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
 
 AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY], [0], [dnl
-port p1: STP state changed from disabled to listening
-port p2: STP state changed from disabled to listening
-port p1: STP state changed from listening to learning
-port p2: STP state changed from listening to learning
-port p1: STP state changed from learning to forwarding
-port p2: STP state changed from learning to forwarding
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from listening to learning
+port <>: STP state changed from listening to learning
+port <>: STP state changed from learning to forwarding
+port <>: STP state changed from learning to forwarding
 ])
 
 AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(7),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.0.0.2,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep Datapath], [0], [dnl
@@ -462,5 +468,144 @@  AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(8),eth(src=50:54:00:00:00:
 Datapath actions: 2
 ])
 
+AT_CLEANUP
+
+AT_SETUP([STP - flush the fdb and mdb when topology changed])
+OVS_VSWITCHD_START([])
+
+# setting as below, the br0 will be root bridge and p5 will be blocked.
+AT_CHECK([
+    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
+], [0])
+
+AT_CHECK([ovs-appctl vlog/set ofproto_dpif:dbg])
+
+AT_CHECK([ovs-ofctl add-flow br0 action=normal])
+AT_CHECK([ovs-ofctl add-flow br1 action=normal])
+AT_CHECK([ovs-ofctl add-flow br2 action=normal])
+
+AT_CHECK([
+    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
+], [0])
+
+
+ovs-appctl time/stop
+
+# give time for STP to move initially
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+
+AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY], [0], [dnl
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
+port <>: STP state changed from disabled to listening
+])
+
+# give time for STP to synchronize
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+
+AT_CHECK([cat ovs-vswitchd.log | FILTER_STP_TOPOLOGY_FORWARDING], [0], [dnl
+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
+port <>: STP state changed from learning to forwarding
+])
+
+# root bridge sends query packet
+# we don't want to lose that message, so send it twice
+AT_CHECK([ovs-appctl netdev-dummy/receive br0 \
+        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'])
+
+ovs-appctl time/warp 1000
+AT_CHECK([ovs-appctl netdev-dummy/receive br0 \
+        '01005E010101000C29A027D18100000108004500001C000100004002CBCBAC102201E00101011114EEEB00000000'])
+
+OVS_WAIT_UNTIL([ovs-appctl fdb/show br0 | grep '00:0c:29:a0:27:d1'])
+OVS_WAIT_UNTIL([ovs-appctl fdb/show br1 | grep '00:0c:29:a0:27:d1'])
+OVS_WAIT_UNTIL([ovs-appctl fdb/show br2 | grep '00:0c:29:a0:27:d1'])
+
+OVS_WAIT_UNTIL([ovs-appctl mdb/show br0 | grep 'querier'])
+OVS_WAIT_UNTIL([ovs-appctl mdb/show br1 | grep 'querier'])
+OVS_WAIT_UNTIL([ovs-appctl mdb/show br2 | grep 'querier'])
+
+# del p2 on the br0, the topology will be changed
+AT_CHECK([ovs-vsctl del-port br0 p2])
+
+# give time for STP to synchronize
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+
+ovs-appctl time/warp 3000
+ovs-appctl time/warp 3000
+
+# check fdb and mdb
+AT_CHECK([ovs-appctl fdb/show br0], [0], [dnl
+ port  VLAN  MAC                Age
+])
+AT_CHECK([ovs-appctl fdb/show br1], [0], [dnl
+ port  VLAN  MAC                Age
+])
+AT_CHECK([ovs-appctl fdb/show br2], [0], [dnl
+ port  VLAN  MAC                Age
+])
+
+AT_CHECK([ovs-appctl mdb/show br0], [0], [dnl
+ port  VLAN  GROUP                Age
+])
+AT_CHECK([ovs-appctl mdb/show br1], [0], [dnl
+ port  VLAN  GROUP                Age
+])
+AT_CHECK([ovs-appctl mdb/show br2], [0], [dnl
+ port  VLAN  GROUP                Age
+])
+
 OVS_VSWITCHD_STOP
 AT_CLEANUP