[ovs-discuss] MAC learning table does not always update

Fri Mar 6 17:10:00 UTC 2015

On Thu, Mar 5, 2015 at 11:53 PM, Ben Pfaff <blp at nicira.com> wrote:

> On Thu, Mar 05, 2015 at 10:42:12PM -0600, Cheng Jin wrote:
> > Attached please find the log file. Thanks for your time and help.
>
> Thanks.  I'm adding back the mailing list to continue the discussion.
>
> Consider 00:00:00:00:00:02 in bridge s1 (it would be a lot easier to
> read the log if there were only one bridge, by the way).  We initially
> see this getting learned on port s1-eth1 (in_port(2)) when a packet
> arrives for it.  OVS forwards the packet and sets up a kernel cache
> entry:
>
>     2015-03-06T03:01:06.923Z|00019|dpif(handler671)|DBG|system at ovs-system:
> miss upcall:
>
> dp_hash(0),recirc_id(0),skb_priority(0),in_port(2),skb_mark(0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0806),arp(sip=10.0.0.2,tip=10.0.0.1,op=2,sha=00:00:00:00:00:02,tha=00:00:00:00:00:01))
>
> arp,metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:02,dl_dst=00:00:00:00:00:01,arp_spa=10.0.0.2,arp_tpa=10.0.0.1,arp_op=2,arp_sha=00:00:00:00:00:02,arp_tha=00:00:00:00:00:01
>
> 2015-03-06T03:01:06.923Z|00020|ofproto_dpif_xlate(handler671)|DBG|bridge
> s1: learned that 00:00:00:00:00:02 is on port s1-eth1 in VLAN 100
>     2015-03-06T03:01:06.923Z|00021|dpif(handler671)|DBG|system at ovs-system:
> put[create]
> dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(2),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0806),arp(sip=
> 10.0.0.2/0.0.0.0,tip=10.0.0.1/0.0.0.0,op=2/0,sha=00:00:00:00:00:02/00:00:00:00:00:00,tha=00:00:00:00:00:01/00:00:00:00:00:00)),
> actions:pop_vlan,4
>     2015-03-06T03:01:06.923Z|00022|dpif(handler671)|DBG|system at ovs-system:
> execute pop_vlan,4 on packet
> arp,metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:02,dl_dst=00:00:00:00:00:01,arp_spa=10.0.0.2,arp_tpa=10.0.0.1,arp_op=2,arp_sha=00:00:00:00:00:02,arp_tha=00:00:00:00:00:01
>
> A few seconds later, a packet with the same source arrives on s1-eth2
> (in_port(3)).  OVS learns the new port for the MAC and again forwards
> the packet and sets up a kernel cache entry:
>
>     2015-03-06T03:01:11.367Z|00036|dpif(handler671)|DBG|system at ovs-system:
> miss upcall:
>
> dp_hash(0),recirc_id(0),skb_priority(0),in_port(3),skb_mark(0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap()
>
> metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:02,dl_dst=00:00:00:00:00:01,dl_type=0x05ff
>     2015-03-06T03:01:11.367Z|00037|dpif(handler671)|DBG|system at ovs-system:
> get_stats success
>
> 2015-03-06T03:01:11.367Z|00038|ofproto_dpif_xlate(handler671)|DBG|bridge
> s1: learned that 00:00:00:00:00:02 is on port s1-eth2 in VLAN 100
>     2015-03-06T03:01:11.368Z|00039|dpif(handler671)|DBG|system at ovs-system:
> put[create]
> dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(3),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(),
> actions:pop_vlan,4
>     2015-03-06T03:01:11.368Z|00040|dpif(handler671)|DBG|system at ovs-system:
> execute pop_vlan,4 on packet
> metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:02,dl_dst=00:00:00:00:00:01,dl_type=0x05ff
>     2015-03-06T03:01:11.368Z|04443|dpif|DBG|system at ovs-system: execute 10
> on packet
> metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:02,dl_dst=00:00:00:00:00:01,dl_type=0x05ff
>
> This is when things get murky.  About 79 ms later, another 5 packets
> arrive with the same MAC arrives on the original port, s1-eth1 (you can
> tell the time and the count from "idle" and packets" below).

Actually the ping packets periodically come (one ping per second), so all
the counters reach "packets:4" before OVS learns the new port (s1-eth2,
namely in_port(3)).

2015-03-06T03:01:10.896Z|00166|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump_start success
2015-03-06T03:01:10.897Z|00167|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(8),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x0800),ipv4(src=
10.0.0.2/0.0.0.0,dst=10.0.0.1/0.0.0.0,proto=1/0,tos=0/0,ttl=64/0,frag=no/0xff),icmp(type=0/0,code=0/0),
packets:4, bytes:392, used:0.449s, actions:push_vlan(vid=100,pcp=0),6
2015-03-06T03:01:10.897Z|00168|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(2),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0800),ipv4(src=
10.0.0.2/0.0.0.0,dst=10.0.0.1/0.0.0.0,proto=1/0,tos=0/0,ttl=64/0,frag=no/0xff),icmp(type=0/0,code=0/0)),
packets:4, bytes:392, used:0.449s, actions:pop_vlan,4
2015-03-06T03:01:10.897Z|00169|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(4),skb_mark(0/0),eth(src=00:00:00:00:00:01,dst=00:00:00:00:00:02),eth_type(0x0800),ipv4(src=
10.0.0.1/0.0.0.0,dst=10.0.0.2/0.0.0.0,proto=1/0,tos=0/0,ttl=64/0,frag=no/0xff),icmp(type=8/0,code=0/0),
packets:4, bytes:392, used:0.949s, actions:push_vlan(vid=100,pcp=0),2
2015-03-06T03:01:10.897Z|00170|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(6),skb_mark(0/0),eth(src=00:00:00:00:00:01,dst=00:00:00:00:00:02),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0800),ipv4(src=
10.0.0.1/0.0.0.0,dst=10.0.0.2/0.0.0.0,proto=1/0,tos=0/0,ttl=64/0,frag=no/0xff),icmp(type=8/0,code=0/0)),
packets:4, bytes:392, used:0.949s, actions:pop_vlan,8
2015-03-06T03:01:10.897Z|00171|dpif(revalidator670)|DBG|system at ovs-system:
dumped all flows
2015-03-06T03:01:10.898Z|00172|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump_done success

What confusing me is that: after the switch learns the new port
(in_port(3)) to the same MAC (00:00:00:00:00:02), why it does not forward
the packet received from h1 (in_port(4)) to the new port? Instead, it still
forwards the packet to the old port (in_port(2)) even before it relearns
the old port.

2015-03-06T03:01:11.369Z|00177|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(3),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(),
packets:0, bytes:0, used:never, actions:pop_vlan,4
2015-03-06T03:01:11.369Z|00178|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(2),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0800),ipv4(src=
10.0.0.2/0.0.0.0,dst=10.0.0.1/0.0.0.0,proto=1/0,tos=0/0,ttl=64/0,frag=no/0xff),icmp(type=0/0,code=0/0)),
packets:4, bytes:392, used:0.920s, actions:pop_vlan,4
2015-03-06T03:01:11.369Z|00179|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(4),skb_mark(0/0),eth(src=00:00:00:00:00:01,dst=00:00:00:00:00:02),eth_type(0x0800),ipv4(src=
10.0.0.1/0.0.0.0,dst=10.0.0.2/0.0.0.0,proto=1/0,tos=0/0,ttl=64/0,frag=no/0xff),icmp(type=8/0,code=0/0),
packets:5, bytes:490, used:0.420s, actions:push_vlan(vid=100,pcp=0),2

The first two rules have the same source and destination MAC but different
in_ports, and the third rule has one of the two in_ports as output port.
Seems to me these rules did not properly reflect the symmetric property of
standard Ethernet forwarding. When a packet with source MAC
00:00:00:00:00:02 reaches the switch from a port, the packet with
destination MAC 00:00:00:00:00:02 should also leaves at the same port, but
it leaves at another port.

The kernel
> cache entry for that flow is still there, so userspace only notices the
> next time it checks the kernel cache statistics.  At that point, it
> re-learns the old address:
>
>
> 2015-03-06T03:01:11.871Z|00201|dpif(revalidator670)|DBG|system at ovs-system:
> flow_dump
> dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(3),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(),
> packets:0, bytes:0, used:never, actions:pop_vlan,4
>
> 2015-03-06T03:01:11.872Z|00202|dpif(revalidator670)|DBG|system at ovs-system:
> flow_dump
> dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(2),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0800),ipv4(src=
> 10.0.0.2/0.0.0.0,dst=10.0.0.1/0.0.0.0,proto=1/0,tos=0/0,ttl=64/0,frag=no/0xff),icmp(type=0/0,code=0/0)),
> packets:5, bytes:490, used:0.421s, actions:pop_vlan,4
>
> 2015-03-06T03:01:11.872Z|00203|ofproto_dpif_xlate(revalidator670)|DBG|bridge
> s1: learned that 00:00:00:00:00:02 is on port s1-eth1 in VLAN 100
>
> Similarly, there's another packet on s1-eth2 a bit later and that port
> is relearned:
>
>
> 2015-03-06T03:01:12.377Z|00222|dpif(revalidator670)|DBG|system at ovs-system:
> flow_dump
> dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(3),skb_mark(0/0),eth(src=00:00:00:00:00:02,dst=00:00:00:00:00:01),eth_type(0x8100),vlan(vid=100,pcp=0),encap(),
> packets:1, bytes:42, used:0.005s, actions:pop_vlan,4
>
> 2015-03-06T03:01:12.377Z|00223|ofproto_dpif_xlate(revalidator670)|DBG|bridge
> s1: learned that 00:00:00:00:00:02 is on port s1-eth2 in VLAN 100
>
> and so on
>
> In other words, I see that MAC bouncing back and forth because there's
> continuing traffic for it arriving on both ports.  There is some
> hysteresis to the bouncing because it only gets processed when OVS looks
> at kernel statistics.
>
> If this isn't the MAC that you're having trouble with (in that log) then
> can you be specific about which MAC and bridge you're looking at?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://openvswitch.org/pipermail/ovs-discuss/attachments/20150306/abb69f9a/attachment-0002.html>