OSPFd (and probably BGP): Can't bring up neighbors on 1st attempt

[mwinter-osr]

This is found on FreeBSD 12.0 with latest master.

Whenever I try to establish OSPF neighbors after a reboot of the FRR node, the neighbors can't be established.
It seems to be fixed if Interfaces are configured first and OSPF removed, then re-added - or something similar. Running ANVL a 2nd time seems to fix it, so it might be some initialization issue.

This bug is most likely not OSPF specific and causes similar issues for OSPF6 and BGP

[mwinter-osr]

It seems one of my test systems had an issue and caused wrong failures which broke the bisect.
I retested and it looks like it is commit sha 8ba26ec which breaks FreeBSD
Merge pull request #3419 from opensourcerouting/freebsd-route-warning

PR #3419 seems to be the issue.

Testing further to get more details.

[mwinter-osr]

The specific PR is #3419 and the specific commit within the PR is sha 86c57af

[mwinter-osr]

Issue got fixed for OSPFv3, but still exists for BGP (based on same commit which broke it)
Re-Opening the issue

[mwinter-osr]

To further comment on this:
The issue in the BGP tests are static routes. ie this config, applied after a fresh boot on a FreeBSD 12 system:

Current configuration:
!
frr version 6.1-dev-20190116151536-git.8ba26ec
frr defaults traditional
hostname comp28-dut
log file zebra.log
log commands
log file bgpd.log
bgp route-map delay-timer 1
log file staticd.log
no service integrated-vtysh-config
username root nopassword
!
debug zebra events
debug zebra packet recv
debug zebra kernel
debug zebra rib
debug zebra nht
debug bgp as4
debug bgp as4 segment
debug bgp keepalives
debug bgp neighbor-events
debug bgp nht
debug bgp updates in
debug bgp updates out
debug bgp zebra
!
password zebra
enable password zebra
!
ipv6 route 3ffe:5:0:6::/64 fc00:192:168:1::102
!
interface eth2
 ip address 192.168.1.101/24
 ipv6 address fc00:192:168:1::101/64
!
interface eth3
 ip address 192.168.2.101/24
 ipv6 address fc00:192:168:2::101/64
!
router bgp 500
 bgp router-id 192.168.1.101
 neighbor fc00:192:168:1::1 remote-as 65538
 neighbor fc00:192:168:1::1 ebgp-multihop 255
 neighbor fc00:192:168:1::1 timers 60 180
 neighbor fc00:192:168:1::1 timers connect 10
 !
 address-family ipv4 unicast
  network 192.168.1.0/24
  network 192.168.2.0/24
  redistribute static
 exit-address-family
 !
 address-family ipv6 unicast
  network fc00:192:168:1::/64
  network fc00:192:168:2::/64
  redistribute static
  neighbor fc00:192:168:1::1 activate
  maximum-paths ibgp 1
 exit-address-family
 rfp full-table-download off
!
line vty
!
end

but the static route does't seem to make it into the routing table:

comp28-dut# show ipv6 route
Codes: K - kernel route, C - connected, S - static, R - RIPng,
       O - OSPFv3, I - IS-IS, B - BGP, N - NHRP, T - Table,
       v - VNC, V - VNC-Direct, A - Babel, D - SHARP, F - PBR,
       f - OpenFabric,
       > - selected route, * - FIB route

K>* ::/96 [0/0] unreachable (ICMP unreachable), 00:04:52
K>* ::ffff:0.0.0.0/96 [0/0] unreachable (ICMP unreachable), 00:04:52
C>* 2001:470:113:300::/64 is directly connected, eth0, 00:04:52
K>* fe80::/10 [0/0] unreachable (ICMP unreachable), 00:04:52
C>* fe80::/64 is directly connected, lo, 00:04:52
C * fe80::/64 is directly connected, eth0, 00:04:52
K>* ff02::/16 [0/0] unreachable (ICMP unreachable), 00:04:52

even with the connected interface up:

comp28-dut# sh int eth3
Interface eth3 is up, line protocol is up
  Link ups:       1    last: 2019/01/17 02:15:51.21
  Link downs:     0    last: (never)
  vrf: default
  index 4 metric 1 mtu 1500 speed 1000 
  flags: <UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST>
  Type: Ethernet
  HWaddr: 00:1e:99:99:99:02
  inet 192.168.2.101/0 broadcast 192.168.2.255
  inet6 fc00:192:168:2::101/0
  inet6 fe80::21e:99ff:fe99:9902/0
  Interface Type Other
    input packets 11, bytes 901, dropped 0, multicast packets 2
    input errors 0
    output packets 16, bytes 1474, multicast packets 5
    output errors 0
    collisions 0

Relevant section from zebra.log when the static was added:

2019/01/17 02:16:32 ZEBRA: zebra message comes from socket [18]
2019/01/17 02:16:32 ZEBRA: Rx'd ZAPI message
2019/01/17 02:16:32 ZEBRA:  Length: 30
2019/01/17 02:16:32 ZEBRA: Command: ZEBRA_NEXTHOP_REGISTER
2019/01/17 02:16:32 ZEBRA:     VRF: 0
2019/01/17 02:16:32 ZEBRA: 
0x0000000801b9db20: 00 1e fe 06 00 00 00 00 ........
0x0000000801b9db28: 00 13 00 00 1c 80 fc 00 ........
0x0000000801b9db30: 01 92 01 68             ...h    

2019/01/17 02:16:32 ZEBRA: zebra message comes from socket [18]
2019/01/17 02:16:32 ZEBRA: Rx'd ZAPI message
2019/01/17 02:16:32 ZEBRA:  Length: 32
2019/01/17 02:16:32 ZEBRA: Command: ZEBRA_ROUTE_DELETE
2019/01/17 02:16:32 ZEBRA:     VRF: 0
2019/01/17 02:16:32 ZEBRA: 
0x0000000801b9db20: 00 20 fe 06 00 00 00 00 . ......
0x0000000801b9db28: 00 08 03 00 00 00 00 08 ........
0x0000000801b9db30: 00 03 01 1c 40 3f       ....@?  

2019/01/17 02:16:32 ZEBRA: Read 2 packets
2019/01/17 02:16:32 ZEBRA: rnh_register msg from client static: hdr->length=20, type=nexthop vrf=0

2019/01/17 02:16:32 ZEBRA: 0: Add RNH fc00:192:168:1::102/128 type 0
2019/01/17 02:16:32 ZEBRA: 0: Client static registers for RNH fc00:192:168:1::102/128 type 0
2019/01/17 02:16:32 ZEBRA: 0:fc00:192:168:1::102/128: Evaluate RNH, type 0 (force)
2019/01/17 02:16:32 ZEBRA: 0:fc00:192:168:1::102/128: NH has become unresolved
2019/01/17 02:16:32 ZEBRA: 0:fc00:192:168:1::102/128: Notifying client static about NH (unreachable)
2019/01/17 02:16:32 ZEBRA: 0:3ffe:5:0:6::/64 doesn't exist in rib
2019/01/17 02:16:32 ZEBRA: vty[??]@(config)# end

[qlyoung]

@mwinter-osr if you're still seeing this after the above 2 PR's please reopen it.