FRR taking a long time to establishing dynamic neighbor (~300min) "not configured and not valid" #13799

CS-BryanP · 2023-06-14T23:32:40Z

CS-BryanP
Jun 14, 2023

FRR is running on a VM with 400 other cloned VMs and attempting to peer with two identically configured Arista switches. Given enough time, 3-4days, all VMs will eventually peer with both top of rack switches as expected. However any individual VM takes a longtime to establish.

Debugging on a random VM, I see this message in the console every 180secs until eventually the peering is established:

2023-06-14 22:21:42.143 [DEBG] bgpd: [TBYZV-W9M3D] [Event] fe80::febd:67ff:fe30:4ca5 connection rejected(VRF default:65333:default) - not configured and not valid for dynamic
2023-06-14 22:24:41.226 [DEBG] bgpd: [TBYZV-W9M3D] [Event] fe80::febd:67ff:fe30:4ca5 connection rejected(VRF default:65333:default) - not configured and not valid for dynamic

However Dynamic neighbors are configured.

localhost# sh run
Building configuration...

Current configuration:
!
frr version 8.5.1
frr defaults traditional
hostname localhost
log file /var/log/frr/frr.log
log stdout
log syslog
no ip forwarding
no ipv6 forwarding
bgp send-extra-data zebra
service integrated-vtysh-config
!
debug bgp neighbor-events
!
router bgp 65333
 bgp log-neighbor-changes
 no bgp ebgp-requires-policy
 bgp graceful-restart restart-time 0
 no bgp network import-check
 neighbor torswitch peer-group
 neighbor torswitch remote-as 4200000005
 neighbor torswitch description Internal Fabric Network
 neighbor torswitch timers connect 5
 neighbor torswitch capability dynamic
 neighbor torswitch capability extended-nexthop
 neighbor ens192 interface peer-group torswitch
 neighbor ens224 interface peer-group torswitch
 bgp fast-convergence
 !
 address-family ipv4 unicast
  redistribute connected route-map Loopback
  neighbor torswitch prefix-list allow-in in
  neighbor torswitch prefix-list host-routes-out out
 exit-address-family
 !
 address-family ipv6 unicast
  neighbor torswitch activate
 exit-address-family
exit
!
ip prefix-list allow-in seq 10 permit 0.0.0.0/0
ip prefix-list allow-in seq 100 deny 0.0.0.0/32 le 32
ip prefix-list host-routes-out seq 10 permit 10.160.0.0/14 ge 32
ip prefix-list host-routes-out seq 100 deny 0.0.0.0/32 le 32
!
route-map Loopback permit 10
 match ip address prefix-len 32
exit
!
route-map Loopback deny 100
exit
!
end

On the Top of Rack Switch

router bgp 4260167780
   router-id 10.160.0.8
   bgp default ipv4-unicast transport ipv6
   bgp default ipv6-unicast
   timers bgp 20 60
   graceful-restart restart-time 120
   maximum-paths 8
   neighbor ERS peer group
   neighbor ERS remote-as 65005
   neighbor ERS route-map default-route in
   neighbor ERS route-map server-loopbacks out
   neighbor ERS maximum-routes 12000
   neighbor INFRA-TEST peer group
   neighbor INFRA-TEST local-as 4200000005 no-prepend replace-as
   neighbor INFRA-TEST route-map server-loopbacks in
   neighbor INFRA-TEST route-map default-route out
   neighbor INFRA-TEST maximum-routes 12000
   neighbor 10.160.0.81 peer group ERS
   neighbor 10.160.0.82 peer group ERS
   neighbor interface Vl1222 peer-group INFRA-TEST remote-as 65333
   !
   address-family ipv4
      bgp next-hop address-family ipv6
      neighbor INFRA-TEST next-hop address-family ipv6 originate
   !
   address-family ipv6
      neighbor INFRA-TEST activate
      no neighbor INFRA-TEST graceful-restart

And I only reset one neighbor:

localhost# sh ip bgp su

IPv4 Unicast Summary (VRF default):
BGP router identifier 10.162.43.254, local AS number 65333 vrf-id 0
BGP table version 18
RIB entries 6, using 1152 bytes of memory
Peers 2, using 1449 KiB of memory
Peer groups 1, using 64 bytes of memory

Neighbor        V         AS   MsgRcvd   MsgSent   TblVer  InQ OutQ  Up/Down State/PfxRcd   PfxSnt Desc
ens192          4 4200000005      3004      2562        0    0    0 1d18h31m            1        3 N/A
ens224          4 4200000005      2458      2095        0    0    0 02:37:42         Idle        0 N/A

Total number of neighbors 2

So both neighbors are configured identically.

Once the neighbor is finally established debug see this:

2023-06-14 22:35:50.937 [DEBG] bgpd: [T04AP-5W1P3] [Event] connection from fe80::febd:67ff:fe30:4ca5 fd 28, active peer status 1 fd -1
2023-06-14 22:35:50.937 [DEBG] bgpd: [JYX7T-SMTAQ] bgp_peer_gr_init called ..
2023-06-14 22:35:50.937 [DEBG] bgpd: [YB7SD-E2DZS] [BGP_GR] Peer state changed  --to-->  : 4 : !
2023-06-14 22:35:50.938 [DEBG] bgpd: [VTCGN-KEKBQ] bgp_peer_gr_flags_update [BGP_GR] called !
2023-06-14 22:35:50.938 [DEBG] bgpd: [VBM1Z-TD8QM] [BGP_GR] Peer ens224 Flag PEER_FLAG_GRACEFUL_RESTART_HELPER : Set : !
2023-06-14 22:35:50.938 [DEBG] bgpd: [M49N5-G8MHD] [BGP_GR] Peer ens224 Flag PEER_FLAG_GRACEFUL_RESTART : UnSet : !
2023-06-14 22:35:50.938 [DEBG] bgpd: [SRJ2F-0FBJK] [BGP_GR] Peer ens224 Flag PEER_FLAG_GRACEFUL_RESTART_GLOBAL_INHERIT : Set : !
2023-06-14 22:35:50.938 [DEBG] bgpd: [VTCGN-KEKBQ] bgp_peer_gr_flags_update [BGP_GR] called !
2023-06-14 22:35:50.938 [DEBG] bgpd: [VBM1Z-TD8QM] [BGP_GR] Peer ens224 Flag PEER_FLAG_GRACEFUL_RESTART_HELPER : Set : !
2023-06-14 22:35:50.938 [DEBG] bgpd: [M49N5-G8MHD] [BGP_GR] Peer ens224 Flag PEER_FLAG_GRACEFUL_RESTART : UnSet : !
2023-06-14 22:35:50.938 [DEBG] bgpd: [SRJ2F-0FBJK] [BGP_GR] Peer ens224 Flag PEER_FLAG_GRACEFUL_RESTART_GLOBAL_INHERIT : Set : !
2023-06-14 22:35:50.938 [DEBG] bgpd: [T91AW-FGMHW] bgp_fsm_change_status : vrf default(0), Status: Active established_peers 1
2023-06-14 22:35:50.938 [DEBG] bgpd: [HKWM3-ZC5QP] ens224 fd 28 went from Idle to Active
2023-06-14 22:35:50.939 [DEBG] bgpd: [ZWCSR-M7FG9] ens224 [FSM] TCP_connection_open (Active->OpenSent), fd 28
2023-06-14 22:35:50.940 [DEBG] bgpd: [WECS1-Q4P17] ens224 passive open
2023-06-14 22:35:50.940 [DEBG] bgpd: [XKJ09-9VTZ7] ens224 Sending hostname cap with hn = localhost, dn = (null)
2023-06-14 22:35:50.940 [DEBG] bgpd: [N7XW0-DHZ4E] [BGP_GR] Sending helper Capability for Peer :ens224 :
2023-06-14 22:35:50.940 [DEBG] bgpd: [NCVS7-K8XXB] [BGP_GR] Sending N-Bit for peer: ens224
2023-06-14 22:35:50.940 [DEBG] bgpd: [JFFAN-DEGED] ens224 sending OPEN, version 4, my as 65333, holdtime 180, id 10.162.43.254
2023-06-14 22:35:50.940 [DEBG] bgpd: [T91AW-FGMHW] bgp_fsm_change_status : vrf default(0), Status: OpenSent established_peers 1
2023-06-14 22:35:50.940 [DEBG] bgpd: [HKWM3-ZC5QP] ens224 fd 28 went from Active to OpenSent
2023-06-14 22:35:50.941 [DEBG] bgpd: [WNM1E-D314G] ens224 rcv OPEN, version 4, remote-as (in open) 23456, holdtime 60, id 10.160.0.8
2023-06-14 22:35:50.942 [DEBG] bgpd: [QG29C-5TSVS] ens224 rcv OPEN w/ OPTION parameter len: 46
2023-06-14 22:35:50.942 [DEBG] bgpd: [NVZPF-5ST3B] ens224 rcvd OPEN w/ optional parameter type 2 (Capability) len 44
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has Route Refresh capability (2), length 0
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has Enhanced Route Refresh capability (70), length 0
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has 4-octet AS number capability (65), length 4
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has MultiProtocol Extensions capability (1), length 4
2023-06-14 22:35:50.942 [DEBG] bgpd: [VXVH9-3MXR0] ens224 OPEN has MultiProtocol Extensions capability for afi/safi: IPv4/unicast
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has MultiProtocol Extensions capability (1), length 4
2023-06-14 22:35:50.942 [DEBG] bgpd: [VXVH9-3MXR0] ens224 OPEN has MultiProtocol Extensions capability for afi/safi: IPv6/unicast
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has Graceful Restart capability (64), length 2
2023-06-14 22:35:50.942 [DEBG] bgpd: [KDY57-R1CN0] ens224 Peer has not restarted. Restart Time: 120, N-bit set: yes
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has AddPath capability (69), length 8
2023-06-14 22:35:50.942 [DEBG] bgpd: [SBSKM-G6QBW] ens224 OPEN has AddPath capability for afi/safi: IPv4/unicast, receive
2023-06-14 22:35:50.942 [DEBG] bgpd: [SBSKM-G6QBW] ens224 OPEN has AddPath capability for afi/safi: IPv6/unicast, receive
2023-06-14 22:35:50.942 [DEBG] bgpd: [SCW43-WN4M1] ens224 OPEN has Extended Next Hop Encoding capability (5), length 6
2023-06-14 22:35:50.942 [DEBG] bgpd: [XCS8V-P66M1] ens224 Received with afi/safi/next-hop afi: IPv4/unicast/2
2023-06-14 22:35:50.942 [DEBG] bgpd: [ZWCSR-M7FG9] ens224 [FSM] Receive_OPEN_message (OpenSent->OpenConfirm), fd 28
2023-06-14 22:35:50.942 [DEBG] bgpd: [T91AW-FGMHW] bgp_fsm_change_status : vrf default(0), Status: OpenConfirm established_peers 1
2023-06-14 22:35:50.942 [DEBG] bgpd: [HKWM3-ZC5QP] ens224 fd 28 went from OpenSent to OpenConfirm
2023-06-14 22:35:50.942 [DEBG] bgpd: [ZWCSR-M7FG9] ens224 [FSM] Receive_KEEPALIVE_message (OpenConfirm->Established), fd 28
2023-06-14 22:35:50.942 [DEBG] bgpd: [X9KQ0-V0CBB] ens224: peer transfer 0x55ad66ffc110 fd 28 -> 0x7f3961808010 fd -1)
2023-06-14 22:35:50.942 [DEBG] bgpd: [T91AW-FGMHW] bgp_fsm_change_status : vrf default(0), Status: Established established_peers 2
2023-06-14 22:35:50.942 [DEBG] bgpd: [HKWM3-ZC5QP] ens224 fd 28 went from OpenConfirm to Established
2023-06-14 22:35:50.942 [INFO] bgpd: [N9HHH-F8H1M] %ADJCHANGE: neighbor ens224(Unknown) in vrf default Up
2023-06-14 22:35:50.942 [DEBG] bgpd: [M452J-37M96] ens224(Unknown) Update Group Hash: sort: 2 UpdGrpFlags: 0 UpdGrpAFFlags: 16777219
2023-06-14 22:35:50.942 [DEBG] bgpd: [S4FCZ-AFJ7Z] ens224(Unknown) Update Group Hash: addpath: 3 UpdGrpCapFlag: 256 UpdGrpCapAFFlag: 18432 route_adv: 0 change local as: 0, as_path_loop_detection: 0
2023-06-14 22:35:50.942 [DEBG] bgpd: [Z8Q37-65KK3] ens224(Unknown) Update Group Hash: max packet size: 4096 pmax_out: 0 Peer Group: torswitch rmap out: (NONE)
2023-06-14 22:35:50.942 [DEBG] bgpd: [NTX3N-C3WZX] ens224(Unknown) Update Group Hash: dlist out: (NONE) plist out: host-routes-out aslist out: (NONE) usmap out: (NONE) advmap: (NONE)
2023-06-14 22:35:50.942 [DEBG] bgpd: [V8B3M-T6VFC] ens224(Unknown) Update Group Hash: default rmap: (NONE) shared network and afi active network: 0
2023-06-14 22:35:50.942 [DEBG] bgpd: [V53J3-2N7JP] ens224(Unknown) Update Group Hash: Lonesoul: 0 ORF prefix: 0 ORF old: 0 max prefix out: 0
2023-06-14 22:35:50.942 [DEBG] bgpd: [SQ314-QBJCR] ens224(Unknown) Update Group Hash key: 842611925
2023-06-14 22:35:50.942 [DEBG] bgpd: [M452J-37M96] ens224(Unknown) Update Group Hash: sort: 2 UpdGrpFlags: 0 UpdGrpAFFlags: 16777219
2023-06-14 22:35:50.942 [DEBG] bgpd: [S4FCZ-AFJ7Z] ens224(Unknown) Update Group Hash: addpath: 3 UpdGrpCapFlag: 256 UpdGrpCapAFFlag: 2048 route_adv: 0 change local as: 0, as_path_loop_detection: 0
2023-06-14 22:35:50.942 [DEBG] bgpd: [Z8Q37-65KK3] ens224(Unknown) Update Group Hash: max packet size: 4096 pmax_out: 0 Peer Group: torswitch rmap out: (NONE)
2023-06-14 22:35:50.942 [DEBG] bgpd: [NTX3N-C3WZX] ens224(Unknown) Update Group Hash: dlist out: (NONE) plist out: (NONE) aslist out: (NONE) usmap out: (NONE) advmap: (NONE)
2023-06-14 22:35:50.942 [DEBG] bgpd: [V8B3M-T6VFC] ens224(Unknown) Update Group Hash: default rmap: (NONE) shared network and afi active network: 1
2023-06-14 22:35:50.942 [DEBG] bgpd: [V53J3-2N7JP] ens224(Unknown) Update Group Hash: Lonesoul: 0 ORF prefix: 0 ORF old: 0 max prefix out: 0
2023-06-14 22:35:50.942 [DEBG] bgpd: [SQ314-QBJCR] ens224(Unknown) Update Group Hash key: 445727118
2023-06-14 22:35:50.942 [DEBG] bgpd: [GBN7X-KK0W4] [Event] Deleting stub connection for peer ens224
2023-06-14 22:35:50.943 [DEBG] bgpd: [T91AW-FGMHW] bgp_fsm_change_status : vrf default(0), Status: Deleted established_peers 2
2023-06-14 22:35:50.943 [DEBG] bgpd: [HKWM3-ZC5QP] ens224 fd -1 went from Idle to Deleted
2023-06-14 22:35:50.952 [DEBG] bgpd: [WT375-N4KPV] EOR REQ 0, EOR RCV 0
2023-06-14 22:35:50.952 [INFO] bgpd: [M59KS-A3ZXZ] bgp_update_receive: rcvd End-of-RIB for IPv6 Unicast from ens224 in vrf default
2023-06-14 22:35:50.952 [DEBG] bgpd: [P3D3N-3277A] ens224 [FSM] Timer (routeadv timer expire)
2023-06-14 22:35:50.955 [DEBG] bgpd: [ZP3RE-J4Q8C] send End-of-RIB for IPv6 Unicast to ens224
2023-06-14 22:35:51.945 [DEBG] bgpd: [WT375-N4KPV] EOR REQ 0, EOR RCV 0
2023-06-14 22:35:51.945 [INFO] bgpd: [M59KS-A3ZXZ] bgp_update_receive: rcvd End-of-RIB for IPv4 Unicast from ens224 in vrf default
2023-06-14 22:35:52.092 [DEBG] bgpd: [P3D3N-3277A] ens224 [FSM] Timer (routeadv timer expire)
2023-06-14 22:35:52.093 [DEBG] bgpd: [ZP3RE-J4Q8C] send End-of-RIB for IPv4 Unicast to ens224

I have attached a packet capture that shows the Arista switch establishing a TCP session and then sending a BGP Open message, but getting an explicit reset from FRR. Until eventually FRR decides to accept and turn up the session at Packet 6742 in the capture (around 300Min after I restarted the session).

bgp_ens224.pcap.zip

CS-BryanP · 2023-06-22T16:04:21Z

CS-BryanP
Jun 22, 2023
Author

I have been doing some testing with this and the problem seems to be related to the FRR specific neighbor cache.
With even just 100 other VMs in the same segment BGP peering takes a long time. However using ip6tables if i only accept ipv6 traffic from the routers, that blocks all the other VMs neighbor discovery packets, then next time my Top of Rack switch attempts to establish a connection, bgp is immediately established and I'm able to clear the neighbors and have them immediately establish again as expected.

For my particular test case the following ip6table rules provide a work around.

sudo ip6tables -A INPUT --src fe80::febd:67ff:fe30:4ca5 -j ACCEPT
sudo ip6tables -A INPUT --src fe80::febd:67ff:fe30:71c7 -j ACCEPT
sudo ip6tables iptables -A INPUT -j DROP

For the actual FRR problem the output of "show int XXX" has a list of ipv6 neighbors, however this list seems to be overwritten every time FRR receives a router-advertisement on that interface. So with hundreds of ipv6 speakers on an interface, the ipv6 neighbor table is constantly being overwritten.

localhost# sh int ens192
Interface ens192 is up, line protocol is up
  Link ups:       2    last: 2023/06/22 14:24:08.95
  Link downs:     0    last: (never)
  vrf: default
  index 2 metric 0 mtu 9000 speed 10000
  flags: <UP,BROADCAST,RUNNING,MULTICAST>
  Type: Ethernet
  HWaddr: 00:50:56:bf:0a:bc
  inet6 fe80::250:56ff:febf:abc/64
  Interface Type Other
  Interface Slave Type None
  protodown: off
  ND advertised reachable time is 0 milliseconds
  ND advertised retransmit interval is 0 milliseconds
  ND advertised hop-count limit is 64 hops
  ND router advertisements sent: 513 rcvd: 33514
  ND router advertisements are sent every 10 seconds
  ND router advertisements lifetime tracks ra-interval
  ND router advertisement default router preference is medium
  Hosts use stateless autoconfig for addresses.
  Neighbor address(s):
  inet6 fe80::250:56ff:febf:9c9f/128
localhost# sh int ens192
Interface ens192 is up, line protocol is up
  Link ups:       2    last: 2023/06/22 14:24:08.95
  Link downs:     0    last: (never)
  vrf: default
  index 2 metric 0 mtu 9000 speed 10000
  flags: <UP,BROADCAST,RUNNING,MULTICAST>
  Type: Ethernet
  HWaddr: 00:50:56:bf:0a:bc
  inet6 fe80::250:56ff:febf:abc/64
  Interface Type Other
  Interface Slave Type None
  protodown: off
  ND advertised reachable time is 0 milliseconds
  ND advertised retransmit interval is 0 milliseconds
  ND advertised hop-count limit is 64 hops
  ND router advertisements sent: 513 rcvd: 33524
  ND router advertisements are sent every 10 seconds
  ND router advertisements lifetime tracks ra-interval
  ND router advertisement default router preference is medium
  Hosts use stateless autoconfig for addresses.
  Neighbor address(s):
  inet6 fe80::250:56ff:febf:632d/128

Notice the number of advertisements received.

I suspect this is a bug here: https://github.com/FRRouting/frr/blob/master/zebra/rtadv.c in the function: rtadv_recv_packet
Specifically line 164
since it appears that it copies every single ipv6 router advertisement received to the same place, overwritting the previous value.

but I'm not a C Coder, so the issue may be elsewhere.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

FRR taking a long time to establishing dynamic neighbor (~300min) "not configured and not valid" #13799

{{title}}

Replies: 1 comment

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Select a reply

FRR taking a long time to establishing dynamic neighbor (~300min) "not configured and not valid" #13799

CS-BryanP Jun 14, 2023

Replies: 1 comment

CS-BryanP Jun 22, 2023 Author

CS-BryanP
Jun 14, 2023

CS-BryanP
Jun 22, 2023
Author