On 4/1/25 3:15 AM, Ilia Baikov wrote:
> Hello,
Hi Ilia,
> So the things go way deeper and it becomes way strange as i initially
> thought.
> I've migrated to L3 networking using ovn-bgp-agent, in order to reduce
> ARP packets flooded over all ports attached to br-int. However this
> didn't help at all and some VMs loses external connectivity (but VMs
> ports didn't get flooded by hundreds pps of ARP).
>
> 2025-04-01T01:03:51.368Z|00035|ofproto_dpif_xlate(handler12)|WARN|
> Dropped 131 log messages in last 55 seconds (most recently, 10 seconds
> ago) due to excessive rate
> 2025-04-01T01:03:51.368Z|00036|ofproto_dpif_xlate(handler12)|WARN|over
> 4096 resubmit actions on bridge br-int while processing
> udp,in_port=473,vlan_tci=0x0000,dl_src=fa:16:3e:66:0c:6e,dl_dst=ff:ff:ff:ff:ff:ff,nw_src=83.217.210.206,nw_dst=255.255.255.255,nw_tos=0,nw_ecn=0,nw_ttl=64,nw_frag=no,tp_src=5678,tp_dst=5678
> 2025-04-01T01:04:35.392Z|00054|ofproto_dpif_upcall(handler60)|WARN|
> Dropped 133 log messages in last 57 seconds (most recently, 13 seconds
> ago) due to excessive rate
> 2025-04-01T01:04:35.392Z|00055|ofproto_dpif_upcall(handler60)|WARN|Flow:
> udp,in_port=277,vlan_tci=0x0000,dl_src=fa:16:3e:24:f1:f7,dl_dst=ff:ff:ff:ff:ff:ff,nw_src=83.217.210.148,nw_dst=83.217.210.255,nw_tos=0,nw_ecn=0,nw_ttl=64,nw_frag=no,tp_src=137,tp_dst=137
>
> bridge("br-int")
> ----------------
> 0. in_port=277, priority 100, cookie 0xa70f8aad
> set_field:0x5d/0xffff->reg13
> set_field:0x2->reg11
> set_field:0x3->reg12
> set_field:0x2->metadata
> set_field:0x2ac->reg14
> set_field:0/0xffff0000->reg13
> resubmit(,8)
> 8. metadata=0x2, priority 50, cookie 0xecab0c71
> set_field:0/0x1000->reg10
> resubmit(,73)
> 73. reg14=0x2ac,metadata=0x2, priority 80, cookie 0xa70f8aad
> set_field:0x1000/0x1000->reg10
> move:NXM_NX_REG10[12]->NXM_NX_XXREG0[111]
> -> NXM_NX_XXREG0[111] is now 0x1
> resubmit(,9)
> 9. reg0=0x8000/0x8000,metadata=0x2, priority 50, cookie 0x1a158a65
> drop
>
> Final flow:
> udp,reg0=0x8000,reg10=0x1000,reg11=0x2,reg12=0x3,reg13=0x5d,reg14=0x2ac,metadata=0x2,in_port=277,vlan_tci=0x0000,dl_src=fa:16:3e:24:f1:f7,dl_dst=ff:ff:ff:ff:ff:ff,nw_src=83.217.210.148,nw_dst=83.217.210.255,nw_tos=0,nw_ecn=0,nw_ttl=64,nw_frag=no,tp_src=137,tp_dst=137
> Megaflow:
> recirc_id=0,eth,ip,in_port=277,dl_src=fa:16:3e:24:f1:f7,nw_frag=no
> Datapath actions: drop
> 2025-04-01T01:04:48.434Z|00015|ofproto_dpif_xlate(handler58)|WARN|
> Dropped 7 log messages in last 55 seconds (most recently, 13 seconds
> ago) due to excessive rate
> 2025-04-01T01:04:48.435Z|00016|ofproto_dpif_xlate(handler58)|WARN|over
> 4096 resubmit actions on bridge br-int while processing
> arp,in_port=487,vlan_tci=0x0000,dl_src=fa:16:3e:de:2a:ce,dl_dst=ff:ff:ff:ff:ff:ff,arp_spa=185.255.178.119,arp_tpa=185.255.178.1,arp_op=1,arp_sha=fa:16:3e:de:2a:ce,arp_tha=00:00:00:00:00:00
> 2025-04-01T01:05:51.377Z|00017|ofproto_dpif_xlate(handler46)|WARN|
> Dropped 7 log messages in last 61 seconds (most recently, 29 seconds
> ago) due to excessive rate
> 2025-04-01T01:05:51.377Z|00018|ofproto_dpif_xlate(handler46)|WARN|over
> 4096 resubmit actions on bridge br-int while processing
> udp,in_port=473,vlan_tci=0x0000,dl_src=fa:16:3e:66:0c:6e,dl_dst=ff:ff:ff:ff:ff:ff,nw_src=83.217.210.206,nw_dst=255.255.255.255,nw_tos=0,nw_ecn=0,nw_ttl=64,nw_frag=no,tp_src=5678,tp_dst=5678
> 2025-04-01T01:05:51.377Z|00019|ofproto_dpif_upcall(handler46)|WARN|
> Dropped 8 log messages in last 63 seconds (most recently, 29 seconds
> ago) due to excessive rate
> 2025-04-01T01:05:51.377Z|00020|ofproto_dpif_upcall(handler46)|WARN|Flow:
> udp,in_port=278,vlan_tci=0x0000,dl_src=fa:16:3e:66:0c:6e,dl_dst=ff:ff:ff:ff:ff:ff,nw_src=83.217.210.206,nw_dst=255.255.255.255,nw_tos=0,nw_ecn=0,nw_ttl=64,nw_frag=no,tp_src=5678,tp_dst=5678
>
> bridge("br-int")
> ----------------
> 0. in_port=278, priority 100, cookie 0xd191f4de
> set_field:0x5e/0xffff->reg13
> set_field:0x2->reg11
> set_field:0x3->reg12
> set_field:0x2->metadata
> set_field:0x33d->reg14
> set_field:0/0xffff0000->reg13
> resubmit(,8)
> 8. metadata=0x2, priority 50, cookie 0xecab0c71
> set_field:0/0x1000->reg10
> resubmit(,73)
> 73. reg14=0x33d,metadata=0x2, priority 80, cookie 0xd191f4de
> set_field:0x1000/0x1000->reg10
> move:NXM_NX_REG10[12]->NXM_NX_XXREG0[111]
> -> NXM_NX_XXREG0[111] is now 0x1
> resubmit(,9)
> 9. reg0=0x8000/0x8000,metadata=0x2, priority 50, cookie 0x1a158a65
> drop
>
> Final flow:
> udp,reg0=0x8000,reg10=0x1000,reg11=0x2,reg12=0x3,reg13=0x5e,reg14=0x33d,metadata=0x2,in_port=278,vlan_tci=0x0000,dl_src=fa:16:3e:66:0c:6e,dl_dst=ff:ff:ff:ff:ff:ff,nw_src=83.217.210.206,nw_dst=255.255.255.255,nw_tos=0,nw_ecn=0,nw_ttl=64,nw_frag=no,tp_src=5678,tp_dst=5678
> Megaflow:
> recirc_id=0,eth,ip,in_port=278,dl_src=fa:16:3e:66:0c:6e,nw_frag=no
> Datapath actions: drop
>
> When i'm seeing this issue on mentioned IPs i can see that VM tries to
> resolve default gateway mac address but with no success since ARP is
> dropped somewhere because of resubmits and drop action on datapath. I
> guess now this is not related to OVN controller. Meanwhile DHCP works
> pretty good :)
Glad to hear about DHCP.
> Option broadcast-arps-to-all-routers is disabled at both of provider
> network Logical Switches.
>
> Could there be any solution for this?
It's not a solution, more of a change to confirm whether this is causing
issues, but could you please try with this commit?
https://github.com/dceara/ovn/commit/fac23e2f6ef6effe3f9a2e0310e78d085750488b
The commit disables flooding of ARP requests that target OVN owned
router IPs to non-router ports. It's not something that can be accepted
as is because it breaks some other things, e.g., OVN generated GARP
requests will not be forwarded properly.
The patch applies on top of the ovn main branch. If you want to try it
out on older branches the easiest way is to just ignore the test changes.
Looking forward to hear how it went.
Thanks,
Dumitru
>
> Regards,
> Ilia Baikov
>
> 26.03.2025 12:34, Ilia Baikov пишет:
>> Got my hands on this, back to debugging. Seems like kernel runs stable
>> # uname -r
>> 6.14.0-061400-generic
>> Meanwhile there is no unrecognized(27) related logs.
>> tail -f /var/log/kolla/openvswitch/ovn-controller.log | grep -i "dhcp"
>> 2025-03-26T09:23:08.086Z|38050|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
>> fa:16:3e:9c:f4:45 185.255.178.131
>> 2025-03-26T09:23:08.086Z|38052|pinctrl(ovn_pinctrl0)|DBG|pinctrl
>> received packet-in | opcode=PUT_DHCP_OPTS| OF_Table_ID=0|
>> OF_Cookie_ID=0xfb6fb11d| in-port=5| src-mac=fa:16:3e:9c:f4:45, dst-
>> mac=ff:ff:ff:ff:ff:ff| src-ip=0.0.0.0, dst-ip=255.255.255.255
>> 2025-03-26T09:23:11.084Z|38054|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
>> fa:16:3e:9c:f4:45 185.255.178.131
>> 2025-03-26T09:23:11.085Z|38056|pinctrl(ovn_pinctrl0)|DBG|pinctrl
>> received packet-in | opcode=PUT_DHCP_OPTS| OF_Table_ID=0|
>> OF_Cookie_ID=0xfb6fb11d| in-port=5| src-mac=fa:16:3e:9c:f4:45, dst-
>> mac=ff:ff:ff:ff:ff:ff| src-ip=0.0.0.0, dst-ip=255.255.255.255
>> 2025-03-26T09:23:26.606Z|38058|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
>> fa:16:3e:9c:f4:45 185.255.178.131
>> 2025-03-26T09:23:26.606Z|38060|pinctrl(ovn_pinctrl0)|DBG|pinctrl
>> received packet-in | opcode=PUT_DHCP_OPTS| OF_Table_ID=0|
>> OF_Cookie_ID=0xfb6fb11d| in-port=5| src-mac=fa:16:3e:9c:f4:45, dst-
>> mac=ff:ff:ff:ff:ff:ff| src-ip=0.0.0.0, dst-ip=255.255.255.255
>> 2025-03-26T09:23:27.704Z|38062|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
>> fa:16:3e:9c:f4:45 185.255.178.131
>> 2025-03-26T09:23:27.704Z|38064|pinctrl(ovn_pinctrl0)|DBG|pinctrl
>> received packet-in | opcode=PUT_DHCP_OPTS| OF_Table_ID=0|
>> OF_Cookie_ID=0xfb6fb11d| in-port=5| src-mac=fa:16:3e:9c:f4:45, dst-
>> mac=ff:ff:ff:ff:ff:ff| src-ip=0.0.0.0, dst-ip=255.255.255.255
>> 2025-03-26T09:23:28.383Z|38066|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
>> fa:16:3e:9c:f4:45 185.255.178.131
>> 2025-03-26T09:23:28.383Z|38068|pinctrl(ovn_pinctrl0)|DBG|pinctrl
>> received packet-in | opcode=PUT_DHCP_OPTS| OF_Table_ID=0|
>> OF_Cookie_ID=0xfb6fb11d| in-port=5| src-mac=fa:16:3e:9c:f4:45, dst-
>> mac=ff:ff:ff:ff:ff:ff| src-ip=0.0.0.0, dst-ip=255.255.255.255
>> 2025-03-26T09:23:53.984Z|38070|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
>> fa:16:3e:50:22:c4 185.255.178.170
>> 2025-03-26T09:23:53.984Z|38072|pinctrl(ovn_pinctrl0)|DBG|pinctrl
>> received packet-in | opcode=PUT_DHCP_OPTS| OF_Table_ID=0|
>> OF_Cookie_ID=0xa020594| in-port=184| src-mac=fa:16:3e:50:22:c4, dst-
>> mac=30:b6:4f:5f:db:a0| src-ip=185.255.178.170, dst-ip=185.255.178.1
>> 2025-03-26T09:24:51.866Z|38074|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
>> fa:16:3e:18:ac:4a 89.169.15.224
>> 2025-03-26T09:24:51.866Z|38076|pinctrl(ovn_pinctrl0)|DBG|pinctrl
>> received packet-in | opcode=PUT_DHCP_OPTS| OF_Table_ID=0|
>> OF_Cookie_ID=0xa020594| in-port=156| src-mac=fa:16:3e:18:ac:4a, dst-
>> mac=30:b6:4f:5f:db:a0| src-ip=89.169.15.224, dst-ip=89.169.15.1
>>
>> And yes, there is logs about resubmit actions which are expected as
>> you said.
>> ->reg15
>> continuation.actions=unroll_xlate(table=0, cookie=0),resubmit(,32)
>> continuation.actions=unroll_xlate(table=0, cookie=0),resubmit(,32)
>> OFPT_FLOW_MOD (OF1.5) (xid=0x235760): ADD table:8
>> priority=110,icmp6,reg10=0x10000/0x10000,reg15=0x28a,metadata=0x2,dl_src=fa:16:3e:48:61:ad,icmp_type=2,icmp_code=0
>> cookie:0xd1588295
>> actions=push:NXM_NX_REG14[],push:NXM_NX_REG15[],pop:NXM_NX_REG14[],pop:NXM_NX_REG15[],resubmit(,9)
>> OFPT_FLOW_MOD (OF1.5) (xid=0x235761): ADD table:8
>> priority=110,icmp,reg10=0x10000/0x10000,reg15=0x28a,metadata=0x2,dl_src=fa:16:3e:48:61:ad,icmp_type=3,icmp_code=4
>> cookie:0xd1588295
>> actions=push:NXM_NX_REG14[],push:NXM_NX_REG15[],pop:NXM_NX_REG14[],pop:NXM_NX_REG15[],resubmit(,9)
>> OFPT_FLOW_MOD (OF1.5) (xid=0x23577b): ADD table:80
>> priority=100,reg14=0x28a,metadata=0x2 cookie:0xa17d67d7
>> actions=set_field:0x9->reg11,set_field:0xa->reg12,resubmit(,8)
>> OFPT_FLOW_MOD (OF1.5) (xid=0x23577c): ADD table:43
>> priority=100,reg15=0x28a,metadata=0x2 cookie:0xa17d67d7
>> actions=set_field:0x1->reg15,resubmit(,43
>>
>> OFPT_PACKET_OUT (OF1.5) (xid=0x235622): in_port=CONTROLLER
>> actions=set_field:0x2->metadata,set_field:0x503-
>> >reg14,resubmit(CONTROLLER,8) data_len=42
>> OFPT_PACKET_OUT (OF1.5) (xid=0x235622): in_port=CONTROLLER
>> actions=set_field:0x2->metadata,set_field:0x503-
>> >reg14,resubmit(CONTROLLER,8) data_len=42
>> continuation.actions=unroll_xlate(table=0, cookie=0),resubmit(,32)
>> continuation.actions=unroll_xlate(table=0, cookie=0),resubmit(,32)
>> continuation.actions=unroll_xlate(table=0, cookie=0),resubmit(,32)
>> continuation.actions=unroll_xlate(table=0, cookie=0),resubmit(,32)
>>
>> top - 09:29:33 up 16:58, 3 users, load average: 37.70, 37.39, 36.95
>> Threads: 114 total, 13 running, 101 sleeping, 0 stopped, 0 zombie
>> %Cpu(s): 27.5 us, 11.2 sy, 0.0 ni, 60.3 id, 0.5 wa, 0.0 hi, 0.6
>> si, 0.0 st
>> MiB Mem : 773901.8 total, 323685.3 free, 423865.0 used, 26351.4 buff/
>> cache
>> MiB Swap: 8192.0 total, 8192.0 free, 0.0 used. 345358.7 avail
>> Mem
>>
>> #top -H -p $(pidof ovs-vswitchd)
>> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+
>> COMMAND
>> 6212 root 20 0 8388104 662016 7940 R 22.3 0.1 32:13.87
>> revalidator102
>> 6200 root 20 0 8388104 662016 7940 R 21.6 0.1 73:01.76
>> revalidator90
>> 6202 root 20 0 8388104 662016 7940 R 20.6 0.1 32:13.77
>> revalidator92
>> 6217 root 20 0 8388104 662016 7940 R 20.3 0.1 26:07.50
>> revalidator107
>> 6214 root 20 0 8388104 662016 7940 R 18.9 0.1 39:12.60
>> revalidator104
>> 6219 root 20 0 8388104 662016 7940 R 18.6 0.1 25:57.96
>> revalidator109
>> 6211 root 20 0 8388104 662016 7940 R 17.6 0.1 39:20.20
>> revalidator101
>> 6207 root 20 0 8388104 662016 7940 R 13.6 0.1 17:53.31
>> revalidator97
>> 6204 root 20 0 8388104 662016 7940 R 13.0 0.1 32:34.67
>> revalidator94
>> 6209 root 20 0 8388104 662016 7940 R 12.6 0.1 35:55.88
>> revalidator100
>> 6213 root 20 0 8388104 662016 7940 R 12.6 0.1 18:04.43
>> revalidator103
>> 6220 root 20 0 8388104 662016 7940 R 12.3 0.1 5:52.71
>> revalidator110
>> 6218 root 20 0 8388104 662016 7940 R 12.0 0.1 9:09.66
>> revalidator108
>> 6215 root 20 0 8388104 662016 7940 S 8.6 0.1 22:22.27
>> revalidator105
>> 6221 root 20 0 8388104 662016 7940 S 8.6 0.1 4:44.93
>> revalidator111
>> 6208 root 20 0 8388104 662016 7940 S 8.0 0.1 22:55.17
>> revalidator98
>> 6203 root 20 0 8388104 662016 7940 S 6.0 0.1 38:52.72
>> revalidator93
>> 6206 root 20 0 8388104 662016 7940 S 6.0 0.1 22:11.55
>> revalidator96
>> 6216 root 20 0 8388104 662016 7940 S 4.3 0.1 33:14.52
>> revalidator106
>>
>> Sometimes revalidator processes drops to 5-10%, sometimes to 30%. I
>> guess this behaviour is because of resubmit actions?. So far so good
>> controller feeling fine, but there could be some sort of freezes on
>> sending DHCPREPLY.
>>
>> top -H -p $(pidof ovn-controller)
>> top - 09:30:55 up 16:59, 3 users, load average: 35.73, 36.70, 36.73
>> Threads: 5 total, 0 running, 5 sleeping, 0 stopped, 0 zombie
>> %Cpu(s): 27.7 us, 10.6 sy, 0.0 ni, 60.8 id, 0.3 wa, 0.0 hi, 0.6
>> si, 0.0 st
>> MiB Mem : 773901.8 total, 323758.4 free, 423785.6 used, 26357.8 buff/
>> cache
>> MiB Swap: 8192.0 total, 8192.0 free, 0.0 used. 345438.0 avail
>> Mem
>>
>> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+
>> COMMAND
>> 5045 root 20 0 396500 83836 4432 S 0.7 0.0 11:46.59
>> ovn-controller
>> 5412 root 20 0 396500 83836 4432 S 0.0 0.0 0:06.23
>> ovn_pinctrl0
>> 5413 root 20 0 396500 83836 4432 S 0.0 0.0 0:00.00
>> urcu1
>> 5414 root 20 0 396500 83836 4432 S 0.0 0.0 0:00.20
>> ovn_statctrl2
>> 6103 root 20 0 396500 83836 4432 S 0.0 0.0 0:04.10
>> stopwatch3
>>
>>
>> Trying to reproduce on a real-world environment. There is 300
>> instances running with about 300Mbps network traffic in total.
>> Is there more logs or debug i can provide?
>>
>
_______________________________________________
discuss mailing list
disc...@openvswitch.org
https://mail.openvswitch.org/mailman/listinfo/ovs-discuss
