Unwanted IPv6 static route flap

[Neil Jerram]

Hi Ondrej,

I've added my guesses below, about what the logs mean.  Would you mind
taking a look and commenting further?

[...]  Here is a case where node R was killed (-9) at 15:50:03 and
> restarted at 15:50:08.  Node M saw this route flap at 15:50:11:
>
> [2020-03-04T15:50:11.257106] Deleted fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122
> via 2001:20::2 dev eth0 proto bird metric 1024 pref medium
> [2020-03-04T15:50:11.257459] fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via
> 2001:20::2 dev eth0 proto bird metric 1024 pref medium
>
> Here is the node M log with "debug all", for both v4 and v6, from when R
> restarted until the route flap:
>
> 2020-03-04T15:50:09.246741514Z KRT: Scanning routing table
> 2020-03-04T15:50:09.246805309Z BGP: connect_timeout
> 2020-03-04T15:50:09.246820405Z BGP: Closing connection
> 2020-03-04T15:50:09.246830788Z BGP: Connecting
> 2020-03-04T15:50:09.246843075Z bird: Mesh_172_17_0_2: Connecting to
> 172.17.0.2 from local address 172.17.0.3
> 2020-03-04T15:50:09.246852834Z KRT: Got 2001:20::/64, type=1, oif=36,
> table=254, prid=2, proto=kernel1
> 2020-03-04T15:50:09.246861952Z KRT: Got
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122, type=1, oif=36, table=254, prid=12,
> proto=kernel1
>

I presume this indicates this BIRD6 seeing that the e7c0 route is present
in the kernel routing table.


> 2020-03-04T15:50:09.246871442Z KRT: Got
> fd00:10:244:0:586d:4461:e980:a280/128, type=1, oif=6, table=254, prid=3,
> proto=kernel1
> 2020-03-04T15:50:09.246879832Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.246889555Z KRT: Got
> fd00:10:244:0:586d:4461:e980:a280/122, type=6, oif=1, table=254, prid=12,
> proto=kernel1
> 2020-03-04T15:50:09.246898969Z KRT: Got
> fd00:10:244:0:58fd:b191:5c13:9cc0/122, type=1, oif=36, table=254, prid=12,
> proto=kernel1
> 2020-03-04T15:50:09.246908792Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.24691778Z KRT: Got fe80::/64, type=1, oif=36,
> table=254, prid=2, proto=kernel1
> 2020-03-04T15:50:09.246927197Z KRT: Ignoring route - strange class/scope
> 2020-03-04T15:50:09.246935966Z KRT: Got fe80::/64, type=1, oif=6,
> table=254, prid=2, proto=kernel1
> 2020-03-04T15:50:09.246944298Z KRT: Ignoring route - strange class/scope
> 2020-03-04T15:50:09.247009224Z KRT: Got ::1/128, type=2, oif=1, table=255,
> prid=2, proto=(none)
> 2020-03-04T15:50:09.247065042Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247088778Z KRT: Got 2001:20::/128, type=4, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.247115256Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247131555Z KRT: Got 2001:20::1/128, type=2, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.247145697Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247159089Z KRT: Got fd00:10:96::ac35/128, type=2,
> oif=3, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.24717877Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247192816Z KRT: Got fe80::/128, type=4, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.247206392Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247219343Z KRT: Got fe80::/128, type=4, oif=6,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.247262729Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247279256Z KRT: Got fe80::42:acff:fe11:3/128, type=2,
> oif=36, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.247294287Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247307585Z KRT: Got fe80::ecee:eeff:feee:eeee/128,
> type=2, oif=6, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.247322176Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247335799Z KRT: Got ff00::/8, type=1, oif=36,
> table=255, prid=3, proto=(none)
> 2020-03-04T15:50:09.247349484Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.24736411Z KRT: Got ff00::/8, type=1, oif=2, table=255,
> prid=3, proto=(none)
> 2020-03-04T15:50:09.247378221Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247391919Z KRT: Got ff00::/8, type=1, oif=6,
> table=255, prid=3, proto=(none)
> 2020-03-04T15:50:09.247405262Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.247417972Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.247439521Z KRT: Pruning table master
> 2020-03-04T15:50:09.247455481Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.247554245Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.247607455Z KRT: Pruning inherited routes
> 2020-03-04T15:50:09.247630001Z fd00:10:244:0:586d:4461:e980:a280/128:
> uptodate (metric=1024)
> 2020-03-04T15:50:09.24764445Z KRT: Scanning interfaces
> 2020-03-04T15:50:09.247654547Z bird6: device1: Scanning interfaces
> 2020-03-04T15:50:09.247664209Z BGP: Waiting for connect success
> 2020-03-04T15:50:09.247672821Z KRT: Scanning routing table
> 2020-03-04T15:50:09.247735015Z KIF: IF1(lo) goes up (mtu=65536,flg=10049)
> 2020-03-04T15:50:09.247758005Z KRT: Got 0.0.0.0/0, type=1, oif=36,
> table=254, prid=3, proto=kernel1
> 2020-03-04T15:50:09.247773084Z KIF: IF2(tunl0) goes up (mtu=1440,flg=100c1)
> 2020-03-04T15:50:09.247786978Z KRT: Got 172.17.0.0/16, type=1, oif=36,
> table=254, prid=2, proto=kernel1
> 2020-03-04T15:50:09.247800431Z KIF: IF3(kube-ipvs0) goes up
> (mtu=1500,flg=82)
> 2020-03-04T15:50:09.247813312Z KRT: Got 192.168.82.0/26, type=1, oif=2,
> table=254, prid=12, proto=kernel1
> 2020-03-04T15:50:09.24783563Z KIF: IF6(cali8cac6bddbc7) goes up
> (mtu=1440,flg=11043)
> 2020-03-04T15:50:09.247851668Z KIF: IF36(eth0) goes up (mtu=1500,flg=11043)
> 2020-03-04T15:50:09.247866271Z KRT: Got 192.168.110.128/26, type=1,
> oif=2, table=254, prid=12, proto=kernel1
> 2020-03-04T15:50:09.247877588Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.247887009Z KRT: Got 192.168.162.128/26, type=6,
> oif=-1, table=254, prid=12, proto=kernel1
> 2020-03-04T15:50:09.247897047Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.247909529Z KRT: Got 192.168.162.129/32, type=1,
> oif=6, table=254, prid=3, proto=kernel1
> 2020-03-04T15:50:09.247922738Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.247936079Z KRT: Got 192.168.195.192/26, type=1,
> oif=2, table=254, prid=12, proto=kernel1
> 2020-03-04T15:50:09.247950491Z KRT: Got 192.168.195.194/32, type=1,
> oif=2, table=254, prid=0, proto=kernel1
> 2020-03-04T15:50:09.247965204Z KRT: Ignoring route - proto unspec
> 2020-03-04T15:50:09.247981588Z KRT: Got 10.96.0.1/32, type=2, oif=3,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.247996158Z KIF: IF1(lo): added IPA ::1, flg 80000, net
> ::1/128, brd ::1, opp ::
> 2020-03-04T15:50:09.248010666Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248023519Z KRT: Got 10.96.0.10/32, type=2, oif=3,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248031562Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248078034Z KIF: IF3(kube-ipvs0): added IPA
> fd00:10:96::ac35, flg 80000, net fd00:10:96::ac35/128, brd
> fd00:10:96::ac35, opp ::
> 2020-03-04T15:50:09.248096436Z KRT: Got 10.96.139.174/32, type=2, oif=3,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.24811125Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248126598Z KRT: Got 127.0.0.0/32, type=3, oif=1,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248141107Z KIF: IF6(cali8cac6bddbc7): added IPA
> fe80::ecee:eeff:feee:eeee, flg 0, net fe80::/64, brd
> fe80::ffff:ffff:ffff:ffff, opp ::
> 2020-03-04T15:50:09.248161213Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248175116Z KRT: Got 127.0.0.0/8, type=2, oif=1,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248188541Z KIF: IF36(eth0): added IPA 2001:20::1, flg
> 0, net 2001:20::/64, brd 2001:20::ffff:ffff:ffff:ffff, opp ::
> 2020-03-04T15:50:09.248201047Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248211099Z KRT: Got 127.0.0.1/32, type=2, oif=1,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248221199Z KIF: IF36(eth0): added IPA
> fe80::42:acff:fe11:3, flg 0, net fe80::/64, brd fe80::ffff:ffff:ffff:ffff,
> opp ::
> 2020-03-04T15:50:09.24823302Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248246842Z KRT: Got 127.255.255.255/32, type=3,
> oif=1, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248259358Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248273776Z KRT: Got 172.17.0.0/32, type=3, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248286895Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248299546Z KRT: Got 172.17.0.3/32, type=2, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248314329Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248326176Z KRT: Got 172.17.255.255/32, type=3,
> oif=36, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248340421Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248353604Z KRT: Got 192.168.162.128/32, type=2,
> oif=2, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248396709Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248410649Z KRT: Got 192.168.162.128/32, type=3,
> oif=2, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:09.248424182Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:09.248432641Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.248444232Z KRT: Pruning table master
> 2020-03-04T15:50:09.248455103Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.248467991Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.248481917Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.248495733Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:09.248507692Z KRT: Pruning inherited routes
> 2020-03-04T15:50:09.248520821Z 0.0.0.0/0: uptodate (metric=0)
> 2020-03-04T15:50:09.248533995Z 192.168.162.129/32: uptodate (metric=0)
> 2020-03-04T15:50:09.248548157Z KRT: Scanning interfaces
> 2020-03-04T15:50:09.248562678Z bird: device1: Scanning interfaces
> 2020-03-04T15:50:09.248634912Z KIF: IF1(lo) goes up (mtu=65536,flg=10049)
> 2020-03-04T15:50:09.248654262Z KIF: IF2(tunl0) goes up (mtu=1440,flg=100c1)
> 2020-03-04T15:50:09.248667478Z KIF: IF3(kube-ipvs0) goes up
> (mtu=1500,flg=82)
> 2020-03-04T15:50:09.248679741Z KIF: IF6(cali8cac6bddbc7) goes up
> (mtu=1440,flg=11043)
> 2020-03-04T15:50:09.24869377Z KIF: IF36(eth0) goes up (mtu=1500,flg=11043)
> 2020-03-04T15:50:09.248707404Z KIF: IF1(lo): added IPA 127.0.0.1, flg 0,
> net 127.0.0.0/8, brd 127.255.255.255, opp 0.0.0.0
> 2020-03-04T15:50:09.248721777Z KIF: IF2(tunl0): added IPA 192.168.162.128,
> flg 80000, net 192.168.162.128/32, brd 192.168.162.128, opp 0.0.0.0
> 2020-03-04T15:50:09.24875919Z KIF: IF3(kube-ipvs0): added IPA 10.96.0.10,
> flg 80000, net 10.96.0.10/32, brd 10.96.0.10, opp 0.0.0.0
> 2020-03-04T15:50:09.248774578Z KIF: IF3(kube-ipvs0): added IPA 10.96.0.1,
> flg 80000, net 10.96.0.1/32, brd 10.96.0.1, opp 0.0.0.0
> 2020-03-04T15:50:09.248787796Z KIF: IF3(kube-ipvs0): added IPA
> 10.96.139.174, flg 80000, net 10.96.139.174/32, brd 10.96.139.174, opp
> 0.0.0.0
> 2020-03-04T15:50:09.248801387Z KIF: IF36(eth0): added IPA 172.17.0.3, flg
> 0, net 172.17.0.0/16, brd 172.17.255.255, opp 0.0.0.0
> 2020-03-04T15:50:09.248813862Z bird: Mesh_172_17_0_2: Connected
> 2020-03-04T15:50:09.248826279Z BGP: Sending open
> 2020-03-04T15:50:09.248838704Z BGP: Scheduling packet type 1
> 2020-03-04T15:50:09.248853116Z BGP: kicking TX
> 2020-03-04T15:50:09.248867125Z bird: Mesh_172_17_0_2: Sending
> OPEN(ver=4,as=64512,hold=240,id=ac110003)
> 2020-03-04T15:50:09.248917898Z BGP: RX hook: Got 63 bytes
> 2020-03-04T15:50:09.248934749Z BGP: Got packet 01 (63 bytes)
> 2020-03-04T15:50:09.248950737Z bird: Mesh_172_17_0_2: Got
> OPEN(as=64512,hold=240,id=ac110002)
> 2020-03-04T15:50:09.248966303Z BGP: Hold timer set to 240, keepalive to
> 80, AS to 64512, ID to ac110002, AS4 session to 1
> 2020-03-04T15:50:09.248980707Z BGP: Scheduling packet type 4
> 2020-03-04T15:50:09.248994608Z BGP: kicking TX
> 2020-03-04T15:50:09.249010838Z bird: Mesh_172_17_0_2: Sending KEEPALIVE
> 2020-03-04T15:50:09.249025237Z BGP: RX hook: Got 19 bytes
> 2020-03-04T15:50:09.249041602Z BGP: Got packet 04 (19 bytes)
> 2020-03-04T15:50:09.249055904Z bird: Mesh_172_17_0_2: Got KEEPALIVE
> 2020-03-04T15:50:09.249070942Z bird: Mesh_172_17_0_2: BGP session
> established
> 2020-03-04T15:50:09.249086311Z BGP: UP!!!
> 2020-03-04T15:50:09.249101679Z Mesh_172_17_0_2 reporting state transition
> HAPPY/START -> */UP
> 2020-03-04T15:50:09.249115749Z Mesh_172_17_0_2: Scheduling meal
> 2020-03-04T15:50:09.249129837Z bird: Mesh_172_17_0_2: State changed to feed
> 2020-03-04T15:50:09.249144331Z Feeding protocol Mesh_172_17_0_2
> 2020-03-04T15:50:09.249158675Z Feeding protocol Mesh_172_17_0_2 continued
> 2020-03-04T15:50:09.249173112Z Announcing routes to new protocol
> Mesh_172_17_0_2
> 2020-03-04T15:50:09.249188304Z Running filter
> `calico_export_to_bgp_peers'...done (3)
> 2020-03-04T15:50:09.249203949Z bird: Mesh_172_17_0_2 < filtered out
> 0.0.0.0/0 via 172.17.0.1 on eth0
> 2020-03-04T15:50:09.249218774Z bird: Mesh_172_17_0_2 < rejected by
> protocol 192.168.110.128/26 via 172.17.0.2 on eth0
> 2020-03-04T15:50:09.24923382Z bird: Mesh_172_17_0_2 < rejected by protocol
> 192.168.82.0/26 via 172.17.0.5 on eth0
> 2020-03-04T15:50:09.249247862Z bird: Mesh_172_17_0_2 < rejected by
> protocol 192.168.195.192/26 via 172.17.0.4 on eth0
> 2020-03-04T15:50:09.249262073Z Running filter
> `calico_export_to_bgp_peers'...done (2)
> 2020-03-04T15:50:09.249276515Z bird: Mesh_172_17_0_2 < added
> 192.168.162.128/26 blackhole
> 2020-03-04T15:50:09.249290957Z BGP: Got route 192.168.162.128/26 up
> 2020-03-04T15:50:09.249306466Z Creating bucket.
> 2020-03-04T15:50:09.249320685Z BGP: Scheduling packet type 2
> 2020-03-04T15:50:09.249334842Z Running filter
> `calico_export_to_bgp_peers'...done (3)
> 2020-03-04T15:50:09.24934932Z bird: Mesh_172_17_0_2 < filtered out
> 192.168.162.128/32 dev tunl0
> 2020-03-04T15:50:09.249364445Z Running filter
> `calico_export_to_bgp_peers'...done (3)
> 2020-03-04T15:50:09.24937825Z bird: Mesh_172_17_0_2 < filtered out
> 192.168.162.129/32 dev cali8cac6bddbc7
> 2020-03-04T15:50:09.249391382Z Running filter
> `calico_export_to_bgp_peers'...done (3)
> 2020-03-04T15:50:09.24940507Z bird: Mesh_172_17_0_2 < filtered out
> 172.17.0.0/16 dev eth0
> 2020-03-04T15:50:09.249418815Z Feeding protocol Mesh_172_17_0_2 finished
> 2020-03-04T15:50:09.249447337Z bird: Mesh_172_17_0_2: State changed to up
> 2020-03-04T15:50:09.249461645Z BGP: Scheduling packet type 2
> 2020-03-04T15:50:09.249475753Z BGP: kicking TX
> 2020-03-04T15:50:09.249490907Z Processing bucket 0000555557021ba0
> 2020-03-04T15:50:09.249505903Z Attribute 01 (1 bytes, flags 40)
> 2020-03-04T15:50:09.249520285Z Attribute 02 (0 bytes, flags 40)
> 2020-03-04T15:50:09.249534754Z Attribute 03 (4 bytes, flags 40)
> 2020-03-04T15:50:09.249549382Z Attribute 05 (4 bytes, flags 40)
> 2020-03-04T15:50:09.249563745Z Dequeued route 192.168.162.128/26
> 2020-03-04T15:50:09.249578227Z bird: Mesh_172_17_0_2: Sending UPDATE
> 2020-03-04T15:50:09.249592887Z Deleting empty bucket 0000555557021ba0
> 2020-03-04T15:50:09.24960707Z bird: Mesh_172_17_0_2: Sending END-OF-RIB
> 2020-03-04T15:50:10.250941727Z BGP: Incoming connection from 2001:20::2
> port 53505
> 2020-03-04T15:50:10.25100382Z bird6: Mesh_2001_20__2: Incoming connection
> from 2001:20::2 (port 53505) accepted
> 2020-03-04T15:50:10.251028737Z BGP: Sending open
> 2020-03-04T15:50:10.251044532Z BGP: Scheduling packet type 1
> 2020-03-04T15:50:10.251059599Z BGP: kicking TX
> 2020-03-04T15:50:10.251071469Z bird6: Mesh_2001_20__2: Sending
> OPEN(ver=4,as=64512,hold=240,id=ac110003)
> 2020-03-04T15:50:10.252332027Z BGP: RX hook: Got 63 bytes
> 2020-03-04T15:50:10.25237946Z BGP: Got packet 01 (63 bytes)
> 2020-03-04T15:50:10.252399422Z bird6: Mesh_2001_20__2: Got
> OPEN(as=64512,hold=240,id=ac110002)
> 2020-03-04T15:50:10.252415598Z BGP: Hold timer set to 240, keepalive to
> 80, AS to 64512, ID to ac110002, AS4 session to 1
> 2020-03-04T15:50:10.252439287Z BGP: Scheduling packet type 4
> 2020-03-04T15:50:10.252453834Z BGP: kicking TX
> 2020-03-04T15:50:10.252464763Z bird6: Mesh_2001_20__2: Sending KEEPALIVE
> 2020-03-04T15:50:10.253102292Z BGP: RX hook: Got 19 bytes
> 2020-03-04T15:50:10.253132439Z BGP: Got packet 04 (19 bytes)
> 2020-03-04T15:50:10.253148868Z bird6: Mesh_2001_20__2: Got KEEPALIVE
> 2020-03-04T15:50:10.253170356Z bird6: Mesh_2001_20__2: BGP session
> established
> 2020-03-04T15:50:10.253190165Z BGP: UP!!!
> 2020-03-04T15:50:10.253205073Z Mesh_2001_20__2 reporting state transition
> HAPPY/START -> */UP
> 2020-03-04T15:50:10.25322086Z Mesh_2001_20__2: Scheduling meal
> 2020-03-04T15:50:10.253235671Z bird6: Mesh_2001_20__2: State changed to
> feed
> 2020-03-04T15:50:10.253249294Z Feeding protocol Mesh_2001_20__2
> 2020-03-04T15:50:10.253258967Z Feeding protocol Mesh_2001_20__2 continued
> 2020-03-04T15:50:10.253266931Z Announcing routes to new protocol
> Mesh_2001_20__2
> 2020-03-04T15:50:10.253276208Z Running filter
> `calico_export_to_bgp_peers'...done (2)
> 2020-03-04T15:50:10.253290268Z bird6: Mesh_2001_20__2 < added
> fd00:10:244:0:586d:4461:e980:a280/122 blackhole
> 2020-03-04T15:50:10.253301947Z BGP: Got route
> fd00:10:244:0:586d:4461:e980:a280/122 up
> 2020-03-04T15:50:10.253313259Z Creating bucket.
> 2020-03-04T15:50:10.253327684Z BGP: Scheduling packet type 2
> 2020-03-04T15:50:10.253341534Z Running filter
> `calico_export_to_bgp_peers'...done (3)
> 2020-03-04T15:50:10.253350322Z bird6: Mesh_2001_20__2 < filtered out
> fd00:10:244:0:586d:4461:e980:a280/128 dev cali8cac6bddbc7
> 2020-03-04T15:50:10.253364301Z Running filter
> `calico_export_to_bgp_peers'...done (3)
> 2020-03-04T15:50:10.253372521Z bird6: Mesh_2001_20__2 < filtered out
> 2001:20::/64 dev eth0
> 2020-03-04T15:50:10.2533812Z bird6: Mesh_2001_20__2 < rejected by protocol
> fd00:10:244:0:58fd:b191:5c13:9cc0/122 via 2001:20::3 on eth0
> 2020-03-04T15:50:10.253390384Z bird6: Mesh_2001_20__2 < rejected by
> protocol fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 on eth0
>

Here we are 2s after BIRD6 restart.  Is this BIRD6 looking at the routes in
the local kernel and deciding whether to export them to its BGP peers?

At this point, I don't believe this BIRD6 has yet *received* the e7c0 route
again from Mesh_2001_20__2.


> 2020-03-04T15:50:10.253399959Z Feeding protocol Mesh_2001_20__2 finished
> 2020-03-04T15:50:10.253432938Z bird6: Mesh_2001_20__2: State changed to up
> 2020-03-04T15:50:10.253444309Z BGP: Scheduling packet type 2
> 2020-03-04T15:50:10.253452592Z BGP: kicking TX
> 2020-03-04T15:50:10.253460975Z Processing bucket 0000555555dfe420
> 2020-03-04T15:50:10.25346923Z Attribute 01 (1 bytes, flags 40)
> 2020-03-04T15:50:10.25347761Z Attribute 02 (0 bytes, flags 40)
> 2020-03-04T15:50:10.253487113Z Attribute 05 (4 bytes, flags 40)
> 2020-03-04T15:50:10.25350068Z Dequeued route
> fd00:10:244:0:586d:4461:e980:a280/122
> 2020-03-04T15:50:10.253514208Z Attribute 0e (42 bytes, flags 80)
> 2020-03-04T15:50:10.253522744Z bird6: Mesh_2001_20__2: Sending UPDATE
> 2020-03-04T15:50:10.253530604Z Deleting empty bucket 0000555555dfe420
> 2020-03-04T15:50:10.253538422Z bird6: Mesh_2001_20__2: Sending END-OF-RIB
> 2020-03-04T15:50:11.253764583Z KRT: Scanning interfaces
> 2020-03-04T15:50:11.25383745Z bird6: device1: Scanning interfaces
> 2020-03-04T15:50:11.253887546Z KIF: IF1(lo) goes up (mtu=65536,flg=10049)
> 2020-03-04T15:50:11.253902966Z KIF: IF2(tunl0) goes up (mtu=1440,flg=100c1)
> 2020-03-04T15:50:11.253916537Z KIF: IF3(kube-ipvs0) goes up
> (mtu=1500,flg=82)
> 2020-03-04T15:50:11.253931398Z KIF: IF6(cali8cac6bddbc7) goes up
> (mtu=1440,flg=11043)
> 2020-03-04T15:50:11.253943237Z KIF: IF36(eth0) goes up (mtu=1500,flg=11043)
> 2020-03-04T15:50:11.253974158Z KIF: IF1(lo): added IPA ::1, flg 80000, net
> ::1/128, brd ::1, opp ::
> 2020-03-04T15:50:11.254024015Z KIF: IF3(kube-ipvs0): added IPA
> fd00:10:96::ac35, flg 80000, net fd00:10:96::ac35/128, brd
> fd00:10:96::ac35, opp ::
> 2020-03-04T15:50:11.254047398Z KIF: IF6(cali8cac6bddbc7): added IPA
> fe80::ecee:eeff:feee:eeee, flg 0, net fe80::/64, brd
> fe80::ffff:ffff:ffff:ffff, opp ::
> 2020-03-04T15:50:11.254063128Z KIF: IF36(eth0): added IPA 2001:20::1, flg
> 0, net 2001:20::/64, brd 2001:20::ffff:ffff:ffff:ffff, opp ::
> 2020-03-04T15:50:11.254078935Z KIF: IF36(eth0): added IPA
> fe80::42:acff:fe11:3, flg 0, net fe80::/64, brd fe80::ffff:ffff:ffff:ffff,
> opp ::
> 2020-03-04T15:50:11.254092728Z KRT: Scanning routing table
> 2020-03-04T15:50:11.25413487Z KRT: Got 2001:20::/64, type=1, oif=36,
> table=254, prid=2, proto=kernel1
> 2020-03-04T15:50:11.25415363Z KRT: Got
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122, type=1, oif=36, table=254, prid=12,
> proto=kernel1
> 2020-03-04T15:50:11.254164119Z KRT: Got
> fd00:10:244:0:586d:4461:e980:a280/128, type=1, oif=6, table=254, prid=3,
> proto=kernel1
> 2020-03-04T15:50:11.254175746Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:11.254188796Z KRT: Got
> fd00:10:244:0:586d:4461:e980:a280/122, type=6, oif=1, table=254, prid=12,
> proto=kernel1
> 2020-03-04T15:50:11.254283224Z KRT: Got
> fd00:10:244:0:58fd:b191:5c13:9cc0/122, type=1, oif=36, table=254, prid=12,
> proto=kernel1
> 2020-03-04T15:50:11.254318016Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:11.254335065Z KRT: Got fe80::/64, type=1, oif=36,
> table=254, prid=2, proto=kernel1
> 2020-03-04T15:50:11.254350178Z KRT: Ignoring route - strange class/scope
> 2020-03-04T15:50:11.254472086Z KRT: Got fe80::/64, type=1, oif=6,
> table=254, prid=2, proto=kernel1
> 2020-03-04T15:50:11.254500919Z KRT: Ignoring route - strange class/scope
> 2020-03-04T15:50:11.254512685Z KRT: Got ::1/128, type=2, oif=1, table=255,
> prid=2, proto=(none)
> 2020-03-04T15:50:11.254521732Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254530077Z KRT: Got 2001:20::/128, type=4, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:11.254538211Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254546883Z KRT: Got 2001:20::1/128, type=2, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:11.254555491Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254563599Z KRT: Got fd00:10:96::ac35/128, type=2,
> oif=3, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:11.254600998Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254615195Z KRT: Got fe80::/128, type=4, oif=36,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:11.254624445Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254635211Z KRT: Got fe80::/128, type=4, oif=6,
> table=255, prid=2, proto=(none)
> 2020-03-04T15:50:11.254646553Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254659762Z KRT: Got fe80::42:acff:fe11:3/128, type=2,
> oif=36, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:11.254670086Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254683633Z KRT: Got fe80::ecee:eeff:feee:eeee/128,
> type=2, oif=6, table=255, prid=2, proto=(none)
> 2020-03-04T15:50:11.254697735Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254710567Z KRT: Got ff00::/8, type=1, oif=36,
> table=255, prid=3, proto=(none)
> 2020-03-04T15:50:11.254719301Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254727431Z KRT: Got ff00::/8, type=1, oif=2,
> table=255, prid=3, proto=(none)
> 2020-03-04T15:50:11.254736273Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.25474529Z KRT: Got ff00::/8, type=1, oif=6, table=255,
> prid=3, proto=(none)
> 2020-03-04T15:50:11.254754378Z KRT: Ignoring route - unknown table 255
> 2020-03-04T15:50:11.254763132Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:11.254776483Z KRT: Pruning table master
> 2020-03-04T15:50:11.254790207Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:11.254799595Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:11.254831733Z KRT: Pruning inherited routes
> 2020-03-04T15:50:11.254842769Z fd00:10:244:0:586d:4461:e980:a280/128:
> uptodate (metric=1024)
> 2020-03-04T15:50:11.256894131Z BGP: RX hook: Got 111 bytes
> 2020-03-04T15:50:11.256979051Z BGP: Got packet 02 (82 bytes)
> 2020-03-04T15:50:11.257024509Z bird6: Mesh_2001_20__2: Got UPDATE
> 2020-03-04T15:50:11.257040575Z Sizes: withdrawn=0, attrs=59, NLRI=0
> 2020-03-04T15:50:11.257054067Z BGP: Parsing attributes
> 2020-03-04T15:50:11.257068745Z Attr 01 40 1
> 2020-03-04T15:50:11.257083598Z Attr 02 40 0
> 2020-03-04T15:50:11.25709827Z Attr 05 40 4
> 2020-03-04T15:50:11.257113016Z Attr 0e 80 42
> 2020-03-04T15:50:11.257128231Z NLRI AF=2 sub=1 len=39
> 2020-03-04T15:50:11.257189797Z Add fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122
> 2020-03-04T15:50:11.257207985Z bird6: Mesh_2001_20__2 > added
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 on eth0
>

I think this means this BIRD6 receiving the e7c0 route from Mesh_2001_20__2
- is that right?

2020-03-04T15:50:11.257223847Z bird6: Mesh_2001_20__8 < rejected by
> protocol fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 on eth0
> 2020-03-04T15:50:11.257239326Z bird6: Mesh_2001_20__3 < rejected by
> protocol fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 on eth0
> 2020-03-04T15:50:11.257256297Z bird6: Mesh_2001_20__2 < rejected by
> protocol fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 on eth0
> 2020-03-04T15:50:11.257270473Z BGP: Got packet 02 (29 bytes)
> 2020-03-04T15:50:11.257285672Z bird6: Mesh_2001_20__2: Got UPDATE
> 2020-03-04T15:50:11.257300413Z Sizes: withdrawn=0, attrs=6, NLRI=0
> 2020-03-04T15:50:11.257316312Z BGP: Parsing attributes
> 2020-03-04T15:50:11.257330382Z Attr 0f 80 3
> 2020-03-04T15:50:11.257345353Z bird6: Mesh_2001_20__2: Got END-OF-RIB
> 2020-03-04T15:50:11.257360035Z bird6: Mesh_2001_20__2: Neighbor graceful
> restart done
> 2020-03-04T15:50:11.257375484Z Pruning route table master
> 2020-03-04T15:50:11.257390138Z bird6: Mesh_2001_20__2 > removed [replaced]
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 on eth0
>

Is "removed [replaced]" correct here?  Is this the cause of the observed
route flap?


> 2020-03-04T15:50:11.257405096Z BGP: Got route
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 down
> 2020-03-04T15:50:11.257443755Z BGP: Scheduling packet type 2
> 2020-03-04T15:50:11.257459135Z BGP: Got route
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 down
> 2020-03-04T15:50:11.257474149Z BGP: Scheduling packet type 2
> 2020-03-04T15:50:11.257489172Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:11.257503396Z Running filter
> `calico_kernel_programming'...done (2)
> 2020-03-04T15:50:11.257521838Z
> nl_send_route(fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122,op=0)
> 2020-03-04T15:50:11.257555033Z
> nl_send_route(fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122,op=0)
> 2020-03-04T15:50:11.257571646Z
> nl_send_route(fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122,op=600)
> 2020-03-04T15:50:11.257587015Z BGP: kicking TX
> 2020-03-04T15:50:11.257600455Z Withdrawn routes:
> 2020-03-04T15:50:11.257614953Z Dequeued route
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122
>

Is it expected that e7c0 is shown here as a withdrawn route?  I would
expect "withdrawn" to mean that the peer had withdrawn it, and I don't
believe that has actually happened here.


> 2020-03-04T15:50:11.257902007Z Attribute 0f (24 bytes, flags 80)
> 2020-03-04T15:50:11.257997418Z bird6: Mesh_2001_20__8: Sending UPDATE
> 2020-03-04T15:50:11.258026482Z BGP: kicking TX
> 2020-03-04T15:50:11.258042446Z Withdrawn routes:
> 2020-03-04T15:50:11.258060895Z Dequeued route
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122
> 2020-03-04T15:50:11.258074666Z Attribute 0f (24 bytes, flags 80)
> 2020-03-04T15:50:11.258088857Z bird6: Mesh_2001_20__3: Sending UPDATE
> 2020-03-04T15:50:11.258138862Z KRT: Received async route notification (25)
> 2020-03-04T15:50:11.258163062Z KRT: Got
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122, type=1, oif=36, table=254, prid=12,
> proto=kernel1
> 2020-03-04T15:50:11.258179983Z KRT: Ignoring route - echo
> 2020-03-04T15:50:11.258195125Z BGP: RX hook: Got 50 bytes
> 2020-03-04T15:50:11.258209426Z BGP: Got packet 02 (50 bytes)
> 2020-03-04T15:50:11.258223518Z bird6: Mesh_2001_20__3: Got UPDATE
> 2020-03-04T15:50:11.258236264Z Sizes: withdrawn=0, attrs=27, NLRI=0
> 2020-03-04T15:50:11.258249812Z BGP: Parsing attributes
> 2020-03-04T15:50:11.258263316Z Attr 0f 80 24
> 2020-03-04T15:50:11.258279266Z NLRI AF=2 sub=1 len=21
> 2020-03-04T15:50:11.258293723Z Withdraw
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122
> 2020-03-04T15:50:11.258308432Z KRT: Received async route notification (24)
> 2020-03-04T15:50:11.258323263Z KRT: Got
> fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122, type=1, oif=36, table=254, prid=12,
> proto=kernel1
> 2020-03-04T15:50:11.258339029Z KRT: Ignoring route - echo
> 2020-03-04T15:50:11.642617031Z KRT: Scanning interfaces
>

I'm trying to close out an analysis of BIRD(6)'s graceful restart behaviour
when one of the nodes in our network is restarted, and I'd ideally like to
understand if the route flap here indicates something wrong with my BIRD6
config; or if this is a known BIRD6 limitation that can't be worked around
with different config.

Many thanks,
     Neil
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://trubka.network.cz/pipermail/bird-users/attachments/20200310/573cdc7a/attachment.htm>