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

Sun Mar 8 03:24:08 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).  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?
>

One thing in the log about 00:00:00:00:00:01 in bridge s2 looks very weird
to me. s2 "learns" a port without any incoming packet.

Initially s2 learns that 00:00:00:00:00:01 is on port s2-eth1 (in_port(6))
when a packet arrives for it. Everything looks fine.

2015-03-06T03:01:06.921Z|00007|dpif(handler671)|DBG|system at ovs-system: miss
upcall:
dp_hash(0),recirc_id(0),skb_priority(0),in_port(6),skb_mark(0),eth(src=00:00:00:00:00:01,dst=ff:ff:ff:ff:ff:ff),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0806),arp(sip=10.0.0.1,tip=10.0.0.2,op=1,sha=00:00:00:00:00:01,tha=00:00:00:00:00:00))
arp,metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:01,dl_dst=ff:ff:ff:ff:ff:ff,arp_spa=10.0.0.1,arp_tpa=10.0.0.2,arp_op=1,arp_sha=00:00:00:00:00:01,arp_tha=00:00:00:00:00:00
2015-03-06T03:01:06.922Z|00009|ofproto_dpif_xlate(handler671)|DBG|bridge
s2: learned that 00:00:00:00:00:01 is on port s2-eth1 in VLAN 100
2015-03-06T03:01:06.922Z|00010|dpif(handler671)|DBG|system at ovs-system:
put[create]
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=ff:ff:ff:ff:ff:ff),eth_type(0x8100),vlan(vid=100,pcp=0),encap(eth_type(0x0806),arp(sip=
10.0.0.1/255.255.255.255,tip=10.0.0.2/255.255.255.255,op=1/0xff,sha=00:00:00:00:00:01/00:00:00:00:00:00,tha=00:00:00:00:00:00/00:00:00:00:00:00)),
actions:5,7,pop_vlan,8

A few seconds later, a packet with the same source arrives on s2-eth2
(in_port(7)). We expect s2 can adapt immediately and all the future packets
destining to 00:00:00:00:00:01 should be output to s2-eth2.
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.368Z|00042|dpif(handler671)|DBG|system at ovs-system: miss
upcall:
dp_hash(0),recirc_id(0),skb_priority(0),in_port(7),skb_mark(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()
metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:01,dl_dst=00:00:00:00:00:02,dl_type=0x05ff
2015-03-06T03:01:11.368Z|00043|ofproto_dpif_xlate(handler671)|DBG|bridge
s2: learned that 00:00:00:00:00:01 is on port s2-eth2 in VLAN 100
2015-03-06T03:01:11.368Z|00044|dpif(handler671)|DBG|system at ovs-system:
put[create]
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(7),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(),
actions:pop_vlan,8
2015-03-06T03:01:11.368Z|00045|dpif(handler671)|DBG|system at ovs-system:
execute pop_vlan,8 on packet
metadata=0,in_port=0,dl_vlan=100,dl_vlan_pcp=0,dl_src=00:00:00:00:00:01,dl_dst=00:00:00:00:00:02,dl_type=0x05ff

Everything looks fine so far, but the confusing part comes now. Since the
last time that s2 learnt the new port s2-eth2 for the MAC, no new packets
arrive at s2 but s2 learns the old port for the MAC again.
At the same time, the kernel cache entry for the reverse flow from
in_port(8) to port(6) gets deleted because it should adapt to the change of
s2's learned port:

2015-03-06T03:01:11.369Z|00175|dpif(revalidator670)|DBG|system at ovs-system:
flow_dump
dp_hash(0/0),recirc_id(0),skb_priority(0),in_port(7),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(),
packets:0, bytes:0, used:never, actions:pop_vlan,8
2015-03-06T03:01:11.369Z|00176|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.920s, actions:push_vlan(vid=100,pcp=0),6
2015-03-06T03:01:11.369Z|00180|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:5, bytes:490, used:0.420s, actions:pop_vlan,8
***2015-03-06T03:01:11.369Z|00181|ofproto_dpif_xlate(revalidator670)|DBG|bridge
s2: learned that 00:00:00:00:00:01 is on port s2-eth1 in VLAN 100***
2015-03-06T03:01:11.369Z|00182|dpif(revalidator670)|DBG|system at ovs-system:
flow_del
dp_hash(0),recirc_id(0),skb_priority(0),in_port(8),skb_mark(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,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=0,code=0),
packets:4, bytes:392, used:0.920s

About 82 ms later, a packet destining to 00:00:00:00:00:01 arrives at s2
and gets forwarded to the old port s2-eth1 (port(6)). The weird behavior
that s2 relearned the old port without any incoming packet violates our
expectation that s2 can adapt to the new port immediately.

2015-03-06T03:01:11.451Z|00047|dpif(handler671)|DBG|system at ovs-system: miss
upcall:
dp_hash(0),recirc_id(0),skb_priority(0),in_port(8),skb_mark(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,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=0,code=0)
icmp,metadata=0,in_port=0,vlan_tci=0x0000,dl_src=00:00:00:00:00:02,dl_dst=00:00:00:00:00:01,nw_src=10.0.0.2,nw_dst=10.0.0.1,nw_tos=0,nw_ecn=0,nw_ttl=64,icmp_type=0,icmp_code=0
2015-03-06T03:01:11.452Z|00048|dpif(handler671)|DBG|system at ovs-system:
put[create]
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),
actions:push_vlan(vid=100,pcp=0),6
2015-03-06T03:01:11.452Z|00049|dpif(handler671)|DBG|system at ovs-system:
execute push_vlan(vid=100,pcp=0),6 on packet
icmp,metadata=0,in_port=0,vlan_tci=0x0000,dl_src=00:00:00:00:00:02,dl_dst=00:00:00:00:00:01,nw_src=10.0.0.2,nw_dst=10.0.0.1,nw_tos=0,nw_ecn=0,nw_ttl=64,icmp_type=0,icmp_code=0

Could you please explain why the relearn behavior happened? Thanks!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://openvswitch.org/pipermail/ovs-discuss/attachments/20150307/707af853/attachment-0002.html>