Unwanted IPv6 static route flap
I am struggling to understand and ideally eliminate an unwanted flap (i.e. delete and re-add) of an IPv6 route on node M, when a neighbouring node R restarts, and R is configured to advertise that IPv6 route statically. Here is the config on R to advertise the route: protocol static { # IP blocks for this host. route fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 blackhole; } BIRD6 on node R is killed (with -9) at 12:22:08, and restarts (with the -R flag) at 12:22:14. The flap (in the kernel routing table) is detected by running "ip -ts monitor route" on the monitor node M. It reports this at 12:22:17: [2020-02-29T12:22:17.954263] Deleted fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 dev eth0 proto bird metric 1024 pref medium [2020-02-29T12:22:17.954470] fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122 via 2001:20::2 dev eth0 proto bird metric 1024 pref medium Here is the BIRD6 log on R, from when it restarted, until it reached a steady state. R's peering to M is "Mesh_2001_20__1". 2020-02-29T12:22:14.214961381Z bird: device1: Initializing 2020-02-29T12:22:14.215018144Z bird: direct1: Initializing 2020-02-29T12:22:14.215035765Z bird: Mesh_2001_20__8: Initializing 2020-02-29T12:22:14.215047665Z bird: Mesh_2001_20__1: Initializing 2020-02-29T12:22:14.215057649Z bird: Mesh_2001_20__3: Initializing 2020-02-29T12:22:14.215144477Z bird: device1: Starting 2020-02-29T12:22:14.215369797Z bird: device1: Connected to table master 2020-02-29T12:22:14.215402544Z bird: device1: State changed to feed 2020-02-29T12:22:14.215431056Z bird: direct1: Starting 2020-02-29T12:22:14.215439899Z bird: direct1: Connected to table master 2020-02-29T12:22:14.215447877Z bird: direct1: State changed to feed 2020-02-29T12:22:14.215456544Z bird: Mesh_2001_20__8: Starting 2020-02-29T12:22:14.215523493Z bird: Mesh_2001_20__3: Starting 2020-02-29T12:22:14.215716006Z bird: Graceful restart started 2020-02-29T12:22:14.215742864Z bird: Started 2020-02-29T12:22:14.215757668Z bird: direct1: State changed to up 2020-02-29T12:22:14.215770554Z bird: device1: State changed to up 2020-02-29T12:22:14.948167365Z bird: Mesh_2001_20__3: Connected to table master 2020-02-29T12:22:14.948234648Z bird: Mesh_2001_20__3: State changed to wait 2020-02-29T12:22:15.951638881Z bird: Mesh_2001_20__8: Connected to table master 2020-02-29T12:22:15.951703218Z bird: Mesh_2001_20__8: State changed to wait 2020-02-29T12:22:16.953066987Z bird: Mesh_2001_20__1: Connected to table master 2020-02-29T12:22:16.953132676Z bird: Mesh_2001_20__1: State changed to wait 2020-02-29T12:22:16.953154658Z bird: Graceful restart done 2020-02-29T12:22:16.95316785Z bird: Mesh_2001_20__8: State changed to feed 2020-02-29T12:22:16.953180658Z bird: Mesh_2001_20__1: State changed to feed 2020-02-29T12:22:16.953194942Z bird: Mesh_2001_20__3: State changed to feed 2020-02-29T12:22:17.953827137Z bird: Mesh_2001_20__8: State changed to up 2020-02-29T12:22:17.953880171Z bird: Mesh_2001_20__1: State changed to up 2020-02-29T12:22:17.953894204Z bird: Mesh_2001_20__3: State changed to up (There could be some errors here, because I've manually separated logs from both BIRD and BIRD6 that were going into the same file, and they both log with prefix "bird:".) And on M, from when R was killed, until reaching a steady state following R restart. M's peering to R is "Mesh_2001_20__2". 2020-02-29T12:22:08.943087384Z bird: Mesh_2001_20__2: State changed to start 2020-02-29T12:22:16.952861163Z bird: Mesh_2001_20__2: State changed to feed 2020-02-29T12:22:16.952950901Z bird: Mesh_2001_20__2: State changed to up Can anyone help to explain why I get the IPv6 route flap on node M, and if there is a way of eliminating it? The peering config on R is # Template for all BGP clients template bgp bgp_template { debug { states }; description "Connection to BGP peer"; local as 64512; multihop; gateway recursive; import all; export filter calico_export_to_bgp_peers; source address 2001:20::2; add paths on; graceful restart; connect delay time 2; connect retry time 5; error wait time 5,30; } protocol bgp Mesh_2001_20__1 from bgp_template { neighbor 2001:20::1 as 64512; } and the same on M but with ::1 and ::2 swapped, and __2 instead of __1. By the way, my setup also has exactly parallel IPv4 config and routes, and I reliably do _not_ see a similar flap for the corresponding IPv4 route. Many thanks, Neil
On Sat, Feb 29, 2020 at 1:05 PM Neil Jerram <neil@tigera.io> wrote:
I am struggling to understand and ideally eliminate an unwanted flap (i.e. delete and re-add) of an IPv6 route on node M, when a neighbouring node R restarts, and R is configured to advertise that IPv6 route statically. [...]
FYI I have just tried the same test again with DBG(...) statements compiled in, in the hope that that might reveal strange timing in the static protocol processing. Unfortunately I don't think it revealed anything suspicious. There is a line with static_add(fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122,2) almost immediately after BIRD6 start-up, and 2 seconds before the "Graceful restart done" log. So it doesn't look - for example - like the static processing is being deferred until after "Graceful restart done". Possibly interesting that I do not see any "Installing static route" line, but maybe that is because that route was present in the kernel and so has already been copied into the BIRD6 core by the kernel protocol. The complete log is below, in case it reveals more clues to someone else! As in the previous run, the unwanted route flap was observed on the other node just after the BGP session reached state Up. (I think at 16:59:44.795, but have unfortunately lost the exact output now.) Best wishes, Neil Merged (sorry) logs for BIRD and BIRD6: 2020-03-02T16:59:41.58460202Z Parsing configuration file `/etc/calico/confd/config/bird.cfg' 2020-03-02T16:59:41.584628001Z Parsing configuration file `/etc/calico/confd/config/bird6.cfg' 2020-03-02T16:59:41.585771719Z bird6: device1: Initializingbird: 2020-03-02T16:59:41.585818652Z bird6: direct1: Initializing 2020-03-02T16:59:41.58584128Z bird: direct1: Initializingbird6: 2020-03-02T16:59:41.585935985Z bird: Mesh_172_17_0_5: Initializingbird6: 2020-03-02T16:59:41.585981801Z bird: Mesh_172_17_0_3: Initializingbird6: 2020-03-02T16:59:41.586024543Z bird: done 2020-03-02T16:59:41.586130702Z bird6: Protocol start 2020-03-02T16:59:41.586193279Z bird: device1: Starting 2020-03-02T16:59:41.58709367Z bird6: IFA change notification (1) for tunl0:192.168.110.128 2020-03-02T16:59:41.587183626Z bird6: device1: State changed to feeddevice1 reporting state transition HUNGRY/DOWN -> */UP 2020-03-02T16:59:41.587332806Z bird: device1: Connected to table masterstatic_add(fd00:10:244:0:1cc0:b1ac:ad47:e7c0/122,2) 2020-03-02T16:59:41.587408514Z bird: device1: State changed to feed 2020-03-02T16:59:41.587664691Z bird6: direct1: Starting 2020-03-02T16:59:41.587740399Z bird6: Kicking kernel1 up 2020-03-02T16:59:41.587822811Z bird6: direct1: State changed to feed 2020-03-02T16:59:41.587859128Z bird6: Mesh_2001_20__8: Starting 2020-03-02T16:59:41.587985681Z bird: bird6: direct1: StartingMesh_2001_20__8: State changed to start 2020-03-02T16:59:41.588075077Z bird6: bird: Mesh_2001_20__1: Startingdirect1: Connected to table master 2020-03-02T16:59:41.58826728Z bird: Mesh_2001_20__1 reporting state transition HUNGRY/DOWN -> */START 2020-03-02T16:59:41.588285997Z direct1: State changed to feedbird6: 2020-03-02T16:59:41.588345781Z bird: Mesh_172_17_0_5: StartingKicking Mesh_2001_20__3 up 2020-03-02T16:59:41.588385171Z bird6: Mesh_2001_20__3: StartingBGP: Startup. 2020-03-02T16:59:41.588520104Z bird: bird6: Mesh_172_17_0_5: State changed to startMesh_2001_20__3: State changed to start 2020-03-02T16:59:41.588601958Z bird: Mesh_172_17_0_3: Startingbird6: 2020-03-02T16:59:41.588650567Z bird6: Started 2020-03-02T16:59:41.588713145Z bird: Mesh_172_17_0_3: State changed to start 2020-03-02T16:59:41.588776561Z bird: Announcing routes to new protocol device1 2020-03-02T16:59:41.588838859Z bird6: olock: 0000555556bb6b20 acquired immediately 2020-03-02T16:59:41.58892183Z bird: Announcing interfaces to new protocol static1 2020-03-02T16:59:41.588999773Z bird: Graceful restart startedFeeding protocol static1 finished 2020-03-02T16:59:41.589046985Z bird: Announcing interfaces to new protocol direct1 2020-03-02T16:59:41.589203429Z bird6: direct1: State changed to up 2020-03-02T16:59:41.589266566Z bird: BGP: Got lock 2020-03-02T16:59:41.589579174Z bird: direct1: State changed to up 2020-03-02T16:59:41.774914181Z bird6: Mesh_2001_20__8: Connected to table master 2020-03-02T16:59:41.774983464Z bird6: Mesh_2001_20__8: State changed to wait 2020-03-02T16:59:42.372436086Z bird: Mesh_172_17_0_3: Connected to table master 2020-03-02T16:59:42.372457597Z bird: Mesh_172_17_0_3: State changed to wait 2020-03-02T16:59:42.776392912Z bird6: Mesh_2001_20__3: Connected to table master 2020-03-02T16:59:42.776416378Z bird6: Mesh_2001_20__3: State changed to wait 2020-03-02T16:59:43.081266214Z bird: Mesh_172_17_0_5: Connected to table master 2020-03-02T16:59:43.081286329Z bird: Mesh_172_17_0_5: State changed to wait 2020-03-02T16:59:43.19352288Z bird: Mesh_172_17_0_4: Connected to table master 2020-03-02T16:59:43.193545788Z bird: Mesh_172_17_0_4: State changed to wait 2020-03-02T16:59:43.19394472Z bird: Graceful restart done 2020-03-02T16:59:43.194007298Z bird: Mesh_172_17_0_5: State changed to feed 2020-03-02T16:59:43.194044733Z bird: Mesh_172_17_0_3: State changed to feed 2020-03-02T16:59:43.194076301Z bird: Mesh_172_17_0_4: State changed to feed 2020-03-02T16:59:43.778698281Z bird6: Mesh_2001_20__1: Connected to table master 2020-03-02T16:59:43.778712249Z bird6: Mesh_2001_20__1: State changed to wait 2020-03-02T16:59:43.779284946Z bird6: Graceful restart done 2020-03-02T16:59:43.779327688Z bird6: Mesh_2001_20__8: State changed to feed 2020-03-02T16:59:43.779351993Z bird6: Mesh_2001_20__1: State changed to feed 2020-03-02T16:59:43.779383282Z bird6: Mesh_2001_20__3: State changed to feed 2020-03-02T16:59:44.195069776Z bird: Mesh_172_17_0_5: State changed to up 2020-03-02T16:59:44.195572352Z bird: Mesh_172_17_0_3: State changed to up 2020-03-02T16:59:44.196010954Z bird: Mesh_172_17_0_4: State changed to up 2020-03-02T16:59:44.780565328Z bird6: Mesh_2001_20__8: State changed to up 2020-03-02T16:59:44.78083687Z bird6: Mesh_2001_20__1: State changed to up 2020-03-02T16:59:44.781566569Z bird6: Mesh_2001_20__3: State changed to up
On Mon, Mar 02, 2020 at 05:35:01PM +0000, Neil Jerram wrote:
On Sat, Feb 29, 2020 at 1:05 PM Neil Jerram <neil@tigera.io> wrote:
I am struggling to understand and ideally eliminate an unwanted flap (i.e. delete and re-add) of an IPv6 route on node M, when a neighbouring node R restarts, and R is configured to advertise that IPv6 route statically. [...]
FYI I have just tried the same test again with DBG(...) statements compiled in, in the hope that that might reveal strange timing in the static protocol processing. Unfortunately I don't think it revealed anything suspicious. There is a line with
Hi I would guess that the issue is more in node M than in node R. The fact that it happens only for IPv6 can be explained by implementation of Kernel protocol, which uses replace operation for IPv4 (since 2.0.5), but only remove/add for IPv6. Technically, the kernel protocol should detect that the new route is the same as old one and avoid pushing it to the kernel, but perhaps for some reason it pushes it anyway and causes the flap. To debug this isse, it would be useful to enable 'debug { events, routes }' on BGP and Kernel on node M. One could see if there are any withdraws, or just updates. -- Elen sila lumenn' omentielvo Ondrej 'Santiago' Zajicek (email: santiago@crfreenet.org) OpenPGP encrypted e-mails preferred (KeyID 0x11DEADC3, wwwkeys.pgp.net) "To err is human -- to blame it on a computer is even more so."
On Tue, Mar 3, 2020 at 2:37 PM Ondrej Zajicek <santiago@crfreenet.org> wrote:
On Mon, Mar 02, 2020 at 05:35:01PM +0000, Neil Jerram wrote:
On Sat, Feb 29, 2020 at 1:05 PM Neil Jerram <neil@tigera.io> wrote:
I am struggling to understand and ideally eliminate an unwanted flap (i.e. delete and re-add) of an IPv6 route on node M, when a neighbouring node R restarts, and R is configured to advertise that IPv6 route statically. [...]
FYI I have just tried the same test again with DBG(...) statements compiled in, in the hope that that might reveal strange timing in the static protocol processing. Unfortunately I don't think it revealed anything suspicious. There is a line with
Hi
I would guess that the issue is more in node M than in node R. The fact that it happens only for IPv6 can be explained by implementation of Kernel protocol, which uses replace operation for IPv4 (since 2.0.5), but only remove/add for IPv6. Technically, the kernel protocol should detect that the new route is the same as old one and avoid pushing it to the kernel, but perhaps for some reason it pushes it anyway and causes the flap.
To debug this isse, it would be useful to enable 'debug { events, routes }' on BGP and Kernel on node M. One could see if there are any withdraws, or just updates.
Thanks Ondrej. 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 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 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 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 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 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 The BGP protocol for node R on node M is Mesh_2001_20__2. I will work on understanding this myself, but probably you will be able to see the key points here more readily than me! Best wishes, Neil
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
participants (2)
-
Neil Jerram -
Ondrej Zajicek