ospf micro-loop

Problemy związane z routingiem

Moderatorzy: mikrobi, aron, garfield, gangrena, Seba

Wiadomość
Autor
razor
wannabe
wannabe
Posty: 105
Rejestracja: 13 paź 2006, 22:02
Lokalizacja: Warszawa

ospf micro-loop

#1

#1 Post autor: razor » 23 lut 2018, 17:37

Cześć,
walczę z tematem szybkiej konwergencji routingu OSPF. Uproszczona topologia wygląda następująco:

SVC_A --(area100)-- COR_A -(area 0)--- COR_B --(area200)-- SVC_B

T=0 -> SVC_A rozgłasza trasę 0/0 jako LSA_type5 E2 ze static'a
T=1s -> SVC_B zaczyna rozgłaszać trasę 0/0 ze static'a
T=5-6s -> pętla pomiędzy SVC_A i COR_A
T=6s -> SVC_A przestaje rozgłaszać trasę 0/0

COR_A preferuje 0/0 do SVC_A jeżeli ten ją rozgłasza, analogicznie COR_B preferuje via SVC_B .

Przerobiłem lekturę INE o tuningu OSPF'a dodając w konfigu

Kod: Zaznacz cały

router ospf 2
  timers throttle spf 10 100 1000
  timers lsa-arrival 50
  timers throttle lsa 10 100 1000
Niestety bez oczekiwanej zmiany - konwergencja routingu dalej trwa około 700-800ms.

Platforma N9300, soft najnowszy I7.2
Logi z SVC_A:

Kod: Zaznacz cały

Event-log z tablicy RIB:
2018 Feb 22 22:54:28.560376 urib: (test): "ospf-2": 0.0.0.0/0, promoted best path nh 20.208.31.17%Ethernet1/45.20, metric [110/1] route-type type-2 tag 0x00000000 flags 0x00000000
2018 Feb 22 22:54:28.560373 urib: (test): "ospf-2": 0.0.0.0/0, promoted best path nh 20.208.31.21%Ethernet1/46.20, metric [110/1] route-type type-2 tag 0x00000000 flags 0x00000000

Event log z procesu OSPF:
2018 Feb 22 22:54:29.316275 ospf 2 [10509]: (test) : SPF run 224 FINISHED
2018 Feb 22 22:54:29.315745 ospf 2 [10509]: (test) : Done examining as-external (type-5/type-7) LSA, prefix count 1, last prefix version 156
2018 Feb 22 22:54:29.315708 ospf 2 [10509]: (test) : Examining as-external (type-5/type-7) LSA
2018 Feb 22 22:54:29.315701 ospf 2 [10509]: (test) : SPF run 224 STARTED with flags 0x8, vpn superbackbone changed flag is FALSE
2018 Feb 22 22:54:28.562772 ospf 2 [10509]: (test) : Flushing ext route 0.0.0.0/0
Jak widać o 22:54:28.56 SVC_A przełącza się na default po OSPF (lokalny static routa 0/0 jest usuwana). W tym samym czasie w procesie OSPF SVC_A robi flush 0/0.
Kalkulacja SPF jest robiona z opóźnieniem około 750ms. Przez te 750ms SVC_A widzi 0/0 via COR_A natomiast COR_A przez SVC_A.

Dlaczego mamy takie opóźnienie w kalkulacji? Czy SPF nie powinien się uruchomić po 10ms od zmiany topologii zgodnie z tym co jest w konfiguracji?


Co ciekawe bez tuningu timerów czasy kalkulacji są praktycznie te same więc może to jednak bug w sofcie?

Awatar użytkownika
gangrena
CCIE/CCDE
CCIE/CCDE
Posty: 2344
Rejestracja: 08 mar 2004, 12:17
Lokalizacja: Wawa

Re: ospf micro-loop

#2

#2 Post autor: gangrena » 25 lut 2018, 00:08

Skoro masz sprzęt, to zmierz czas przełączenia w data plane. Konwergencja w control-plane to nie tylko RIB i SPF. Poza timestamps też mogą mieć przesunięcia skoro mówisz, że bez tuningu jest tak samo.

razor
wannabe
wannabe
Posty: 105
Rejestracja: 13 paź 2006, 22:02
Lokalizacja: Warszawa

Re: ospf micro-loop

#3

#3 Post autor: razor » 25 lut 2018, 00:29

W data-plane jest to samo. Stąd ten wątek, że przy zmianie topologii mamy packet-loss.
Mam złapany ruch na span porcie gdzie widać ping-pong'a i TTL expired.

Awatar użytkownika
gangrena
CCIE/CCDE
CCIE/CCDE
Posty: 2344
Rejestracja: 08 mar 2004, 12:17
Lokalizacja: Wawa

Re: ospf micro-loop

#4

#4 Post autor: gangrena » 25 lut 2018, 15:40

razor pisze:
25 lut 2018, 00:29
W data-plane jest to samo. Stąd ten wątek, że przy zmianie topologii mamy packet-loss.
Mam złapany ruch na span porcie gdzie widać ping-pong'a i TTL expired.
Straty w ruchu zawsze jakieś będą, uloops również. Pytanie, co zmierzyłeś w data plane? Tam powinna być widoczna różnica w zmianie timerów.

razor
wannabe
wannabe
Posty: 105
Rejestracja: 13 paź 2006, 22:02
Lokalizacja: Warszawa

Re: ospf micro-loop

#5

#5 Post autor: razor » 25 lut 2018, 16:12

Test był prosty: ping z interwałem 100ms na loopback urządzenia COR_A z urządzenia za SVC_A.
Ze stratami mogę się pogodzić - ważne żeby zrozumieć ich przyczynę.
Nie doszukałem się nigdzie skąd może wynikać te ~750ms opóźnienia w uruchomieniu SPF'a (jeżeli dobrze interpretuje logi).
Za opóźnienie powinien odpowiadać throttle start time = 10ms.
Spróbuje to jeszcze przelabować to na IOS/IOS-XE.

Awatar użytkownika
gangrena
CCIE/CCDE
CCIE/CCDE
Posty: 2344
Rejestracja: 08 mar 2004, 12:17
Lokalizacja: Wawa

Re: ospf micro-loop

#6

#6 Post autor: gangrena » 26 lut 2018, 12:19

Ile zmierzyłeś przerwy w data plane dla SPF initial 10 ms i 5 sec? To da odpowiedź, czy jest to skorelowane z control plane. Może czasy są z pewnym opóźnieniem. 750 ms to za długo przy SPF initial timer 50 ms, ale w rzeczywistości może być mniej. Stąd pytanie o pomiary. Oprócz tego ustaw carrier-delay dla pewności na 0 ms, sprawdź, czy nie ma jakiegoś dampeningu ustawionego.

razor
wannabe
wannabe
Posty: 105
Rejestracja: 13 paź 2006, 22:02
Lokalizacja: Warszawa

Re: ospf micro-loop

#7

#7 Post autor: razor » 26 lut 2018, 23:36

Zrobiłem mini lab na 2 routerkach z IOS'em i tutaj całość kalkulacji zamyka się w około 20ms więc błyskiem.
Na nexusach źródłem problemu jest urządzenie które generuje LSA Update.
Widać to bardzo ładnie z event-loga ospf'a:

Generowanie LSA:

Kod: Zaznacz cały

2018 Feb 26 22:58:30.562802 ospf 2 [7170]: (test) : Scheduling SPF - LSA flush, 0.0.0.0(0x5)20.208.31.254 (0x80000003) (0xd9f2) (3600)(O)
A tutaj flooding LSA - widać z jakim opóźnieniem:

Kod: Zaznacz cały

2018 Feb 26 22:58:31.183011 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on port-channel4096.20
2018 Feb 26 22:58:31.183001 ospf 2 [7170]: (test) : Building LSU on port-channel4096.20
2018 Feb 26 22:58:31.163418 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/48.20
2018 Feb 26 22:58:31.163408 ospf 2 [7170]: (test) : Building LSU on Ethernet1/48.20
2018 Feb 26 22:58:31.113055 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/10.20
2018 Feb 26 22:58:31.113048 ospf 2 [7170]: (test) : Building LSU on Ethernet1/10.20
2018 Feb 26 22:58:31.113002 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/47.20
2018 Feb 26 22:58:31.112993 ospf 2 [7170]: (test) : Building LSU on Ethernet1/47.20
2018 Feb 26 22:58:31.093000 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/9.20
2018 Feb 26 22:58:31.092987 ospf 2 [7170]: (test) : Building LSU on Ethernet1/9.20
Manipulowanie "timers throttle lsa" nie daje żadnej zmiany.

Awatar użytkownika
gangrena
CCIE/CCDE
CCIE/CCDE
Posty: 2344
Rejestracja: 08 mar 2004, 12:17
Lokalizacja: Wawa

Re: ospf micro-loop

#8

#8 Post autor: gangrena » 27 lut 2018, 01:26

Wcześniej podałeś output z timestamps z "Flushing ext route" oraz przeliczenia SPF. Różnica między tymi eventami nie zależy od generowania LSA. Zatem ponawiam pytanie - Ile zmierzyłeś przerwy w data plane dla SPF initial timer 10 ms oraz 5 sec? Może się okazać, że niepotrzebnie diagnozujesz control plane. Być może jest tylko kosmetyka z timestamps.

razor
wannabe
wannabe
Posty: 105
Rejestracja: 13 paź 2006, 22:02
Lokalizacja: Warszawa

Re: ospf micro-loop

#9

#9 Post autor: razor » 27 lut 2018, 13:47

Chwilowo środowisko testowe mam rozwalone więc pomiarów nie zrobię.

gangrena pisze:
27 lut 2018, 01:26
Wcześniej podałeś output z timestamps z "Flushing ext route" oraz przeliczenia SPF. Różnica między tymi eventami nie zależy od generowania LSA.
Hmm? Chyba się nie rozumiemy.
Konwergencja data plane jest wprost zależna od control plane.

RouterX w stanie początkowym w tablicy RIB ma trasę statyczną którą rozgłasza w OSPF jako External. W OSPF DB jest jeszcze druga trasa rozgłaszana przez innego ASBR'a.
W T=0 routerX traci trasę statyczną - jest to wynik trackingu podpiętego pod wpis statyczny.
W event logu widać natychmiastowe przełaczenie w lokalnym RIB ze static'a na OSPF.

T=0 mamy log o flushu LSA:

Kod: Zaznacz cały

2018 Feb 26 22:58:30.562802 ospf 2 [7170]: (test) : Scheduling SPF - LSA flush, 0.0.0.0(0x5)20.208.31.254 (0x80000003) (0xd9f2) (3600)(O)
T=~600ms mamy w logu ostatnie LSU do sąsiada:

Kod: Zaznacz cały

2018 Feb 26 22:58:31.183011 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on port-channel4096.20
2018 Feb 26 22:58:31.183001 ospf 2 [7170]: (test) : Building LSU on port-channel4096.20
2018 Feb 26 22:58:31.163418 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/48.20
2018 Feb 26 22:58:31.163408 ospf 2 [7170]: (test) : Building LSU on Ethernet1/48.20
2018 Feb 26 22:58:31.113055 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/10.20
2018 Feb 26 22:58:31.113048 ospf 2 [7170]: (test) : Building LSU on Ethernet1/10.20
2018 Feb 26 22:58:31.113002 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/47.20
2018 Feb 26 22:58:31.112993 ospf 2 [7170]: (test) : Building LSU on Ethernet1/47.20
2018 Feb 26 22:58:31.093000 ospf 2 [7170]: (test) : Built LSU with 1 LSAs on Ethernet1/9.20
2018 Feb 26 22:58:31.092987 ospf 2 [7170]: (test) : Building LSU on Ethernet1/9.20
Sąsiad w przedziale czasowym T=(0,~600ms) w RIB cały czas widział 0/0 przez routerX. Dopiero o otrzymaniu LSU może rozpocząć kalkulacją w oparciu o zadany SPF start-time.
Event log SPF'a z sąsiada:

Kod: Zaznacz cały

2018 Feb 26 22:58:31.349704 ospf 2 [13133]: (test) : AF SPF DONE 
2018 Feb 26 22:58:31.349169 ospf 2 [13133]: (test) : AF SPF START 
2018 Feb 26 22:58:31.113831 ospf 2 [13133]: (test) : Scheduling SPF timer in 200.000 msec
2018 Feb 26 22:58:31.113826 ospf 2 [13133]: (test) : SPF requested computation bits now 8
2018 Feb 26 22:58:31.113821 ospf 2 [13133]: (test) : 0.0.0.0(0x5)20.208.31.254 (0x80000003) (0xd9f2) (3600), scheduling incremental external route calculation

Logi z CP korelują się dokładnie z blackholowaniem ruchu.

Awatar użytkownika
gangrena
CCIE/CCDE
CCIE/CCDE
Posty: 2344
Rejestracja: 08 mar 2004, 12:17
Lokalizacja: Wawa

Re: ospf micro-loop

#10

#10 Post autor: gangrena » 27 lut 2018, 23:07

razor pisze:
27 lut 2018, 13:47
gangrena pisze:
27 lut 2018, 01:26
Wcześniej podałeś output z timestamps z "Flushing ext route" oraz przeliczenia SPF. Różnica między tymi eventami nie zależy od generowania LSA.
Hmm? Chyba się nie rozumiemy.
Konwergencja data plane jest wprost zależna od control plane.
Zależna może być, ale nie musi. Może być propocjonalnie zależna, ale już nie koniecznie liniowo. Stąd pytanie o uzyskane czasy w data plane, gdyż za bardzo skupiasz się na control plane. Z wcześniej podanych logów wynika, że generowanie LSA nie miało wpływu:

Kod: Zaznacz cały

2018 Feb 22 22:54:29.316275 ospf 2 [10509]: (test) : SPF run 224 FINISHED
2018 Feb 22 22:54:29.315745 ospf 2 [10509]: (test) : Done examining as-external (type-5/type-7) LSA, prefix count 1, last prefix version 156
2018 Feb 22 22:54:29.315708 ospf 2 [10509]: (test) : Examining as-external (type-5/type-7) LSA
2018 Feb 22 22:54:29.315701 ospf 2 [10509]: (test) : SPF run 224 STARTED with flags 0x8, vpn superbackbone changed flag is FALSE
2018 Feb 22 22:54:28.562772 ospf 2 [10509]: (test) : Flushing ext route 0.0.0.0/0
W ostatnich logach jest już inny wynik i różnica w czasach między Flushing ext route, a SPF run. Widać, że jest potencjalnie przerwa ~600ms do czasu wygenerowania LSU. Może jest jeszcze jakaś bezwładność między faktycznym wycofaniem trasy statycznej, a mechanizmem detekcji. Jaka jest konfiguracja tej detekcji? Sprawdź ewentualnie alternatywy.

razor
wannabe
wannabe
Posty: 105
Rejestracja: 13 paź 2006, 22:02
Lokalizacja: Warszawa

Re: ospf micro-loop

#11

#11 Post autor: razor » 17 cze 2018, 14:59

Informacyjnie problem powiązany jest z CSCug80089. Co prawda bug dotyczy N7k ale jak pokazuje życie N9k też są podatne.
Problem podobno rozwiązany w najnowszym 7.0(3)I7(4).

ODPOWIEDZ