On Thu, Mar 5, 2015 at 11:53 PM, Ben Pfaff <b...@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@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@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@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@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@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@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@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@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@ovs-system: flow_dump_start success 2015-03-06T03:01:10.897Z|00167|dpif(revalidator670)|DBG|system@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@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@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@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@ovs-system: dumped all flows 2015-03-06T03:01:10.898Z|00172|dpif(revalidator670)|DBG|system@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@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@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@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@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@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@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?
_______________________________________________ discuss mailing list discuss@openvswitch.org http://openvswitch.org/mailman/listinfo/discuss
