RAS O2 posílá špatné PPPoE session ID

[Dz]

Hodně lidí se trápí s ipsecem na comtrendu, který se ne vždy naváže. Zjistil jsem, že problém je na RASu O2, který plete session ID staré a nové PPPoE session.


1. VDSL modem Comtrend v režimu bridge, PPPoE klient v linuxu
2. PPPoE spojení je navázáno, a veškerý traffic chodí pod jednou session ID (na tracech session 0x446)
3. PPPoE spojení je ukončeno (LCP, Term-Request) a znovu navázáno jako nová session 0x2822
4. Veškerý traffic chodí pod novou PPPoE session 0x2822 i odchozí (VDSL->internet) ipsec (isakmp)
5. Příchozí ipsec však chodí z RASu pod starou session 0x446 a ipsec spojení nelze navázat (příchozí traffic musí přijít pod správnou PPPoE session)

Pomůže pouze restart VDSL modemu, který jak opakuji funguje pouze jako bridge mezi 848 VLANou a ethernetem (PPPoE spojení se dělá až za ním).
Nejsem si jistý, zda je problém v síti O2 nebo na modemu, ale protože modem je v tomto nastavení transparentní, musí být problém na RASu O2.

Přikládám komentované tracy:

PPPoE spojení navázáno, ipsec navázán, traffic průchozí pod session 0x446:

00:14:09.968192 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 2/others I oakley-quick[E]
00:14:09.969179 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 2/others I oakley-quick[E]
00:14:09.969429 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 2/others I oakley-quick[E]
00:14:09.974672 PPPoE  [ses 0x446] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others R oakley-quick[E]
00:14:09.976879 PPPoE  [ses 0x446] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others R oakley-quick[E]
00:14:10.023140 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 2/others I oakley-quick[E]
00:14:10.045662 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 2/others I oakley-quick[E]
00:14:10.546090 PPPoE  [ses 0x446] IP 212.67.86.176 > 84.242.96.243: ESP(spi=0x3b349299,seq=0x1), length 116
00:14:10.592194 PPPoE  [ses 0x446] IP 84.242.96.243 > 212.67.86.176: ESP(spi=0x43f02d1d,seq=0x1), length 116
00:14:10.592930 PPPoE  [ses 0x446] IP 212.67.86.176 > 84.242.96.243: ESP(spi=0x3b349299,seq=0x2), length 212
00:14:10.601758 PPPoE  [ses 0x446] IP 212.67.86.176 > 84.242.96.243: ESP(spi=0x3b349299,seq=0x3), length 212
00:14:10.637442 PPPoE  [ses 0x446] IP 84.242.96.243 > 212.67.86.176: ESP(spi=0x43f02d1d,seq=0x2), length 196
00:14:10.646425 PPPoE  [ses 0x446] IP 84.242.96.243 > 212.67.86.176: ESP(spi=0x43f02d1d,seq=0x3), length 196

PPPoE spojení ukončeno:
00:14:24.781822 PPPoE  [ses 0x446] LCP, Term-Request (0x05), id 2, length 18
00:14:24.809728 PPPoE  [ses 0x446] LCP, Term-Ack (0x06), id 2, length 6

Nové PPPoE spojení navázáno pod session 0x2822:
00:14:32.355754 PPPoE PADI [Service-Name] [Host-Uniq 0xCA070000]
00:14:32.383366 PPPoE PADO [Host-Uniq 0xCA070000] [AC-Name "PR60B01PLZELI01-G61BQ2511Q04CS"] [Service-Name]
00:14:32.383597 PPPoE PADR [Service-Name] [Host-Uniq 0xCA070000]
00:14:32.522352 PPPoE PADS [ses 0x2822] [Service-Name] [Host-Uniq 0xCA070000] [AC-Name "PR60B01PLZELI01-G61BQ2511Q04CS"]
00:14:32.523954 PPPoE  [ses 0x2822] LCP, Conf-Request (0x01), id 1, length 16
00:14:32.551606 PPPoE  [ses 0x2822] LCP, Conf-Request (0x01), id 37, length 20
00:14:32.551613 PPPoE  [ses 0x2822] LCP, Conf-Ack (0x02), id 1, length 16
00:14:32.551719 PPPoE  [ses 0x2822] LCP, Conf-Nack (0x03), id 37, length 10
00:14:32.578823 PPPoE  [ses 0x2822] LCP, Conf-Request (0x01), id 38, length 21
00:14:32.578941 PPPoE  [ses 0x2822] LCP, Conf-Ack (0x02), id 38, length 21
00:14:32.578981 PPPoE  [ses 0x2822] LCP, Echo-Request (0x09), id 0, length 10
00:14:32.607343 PPPoE  [ses 0x2822] CHAP, Challenge (0x01), id 1, Value 9726c7766481e0767907dbf1270ae01b, Name PR60B01PLZELI01
00:14:32.607354 PPPoE  [ses 0x2822] LCP, Echo-Reply (0x0a), id 0, length 10
00:14:32.607678 PPPoE  [ses 0x2822] CHAP, Response (0x02), id 1, Value d0e4ad3ea7f5859dfef343dd290f5875, Name adsl3735
00:14:32.661837 PPPoE  [ses 0x2822] CHAP, Success (0x03), id 1, Msg CHAP authentication success, unit 323
00:14:32.661846 PPPoE  [ses 0x2822] IPCP, Conf-Request (0x01), id 207, length 12
00:14:32.662010 PPPoE  [ses 0x2822] IPCP, Conf-Request (0x01), id 1, length 12
00:14:32.662027 PPPoE  [ses 0x2822] IPCP, Conf-Ack (0x02), id 207, length 12
00:14:32.689576 PPPoE  [ses 0x2822] IPCP, Conf-Nack (0x03), id 1, length 12
00:14:32.689680 PPPoE  [ses 0x2822] IPCP, Conf-Request (0x01), id 2, length 12
00:14:32.718155 PPPoE  [ses 0x2822] IPCP, Conf-Ack (0x02), id 2, length 12

Trafic chodí pod novou session ID 0x2822:
00:14:33.847008 PPPoE  [ses 0x2822] IP 212.67.86.176 > 84.242.96.243: ESP(spi=0x3b349299,seq=0x4), length 116
00:14:35.357217 PPPoE  [ses 0x2822] IP 212.67.86.176 > 84.242.96.243: ESP(spi=0x3b349299,seq=0x5), length 116
00:14:36.870409 PPPoE  [ses 0x2822] IP 212.67.86.176 > 84.242.96.243: ESP(spi=0x3b349299,seq=0x6), length 116
00:14:39.591190 PPPoE  [ses 0x2822] IP 212.67.86.176 > 84.242.96.243: ESP(spi=0x3b349299,seq=0x7), length 132
00:14:44.108356 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 1 I ident
00:14:52.588748 PPPoE  [ses 0x2822] LCP, Echo-Request (0x09), id 1, length 10
00:14:52.614978 PPPoE  [ses 0x2822] LCP, Echo-Reply (0x0a), id 1, length 10
00:14:54.078686 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 1 I ident
00:14:54.108044 PPPoE PADT [ses 0x446]
00:15:07.486280 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others R inf[E]
00:15:07.486936 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others R inf[E]
00:15:07.487658 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others R inf[E]
00:15:07.488182 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others R inf[E]
00:15:07.488708 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others R inf[E]
00:15:07.489347 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others I inf[E]
00:15:07.490080 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 2/others I inf[E]
00:15:07.512537 PPPoE PADT [ses 0x446]
00:15:07.513496 PPPoE PADT [ses 0x446]
00:15:07.514482 PPPoE PADT [ses 0x446]
00:15:07.515234 PPPoE PADT [ses 0x446]
00:15:07.517234 PPPoE PADT [ses 0x446]
00:15:07.518236 PPPoE PADT [ses 0x446]
00:15:07.518985 PPPoE PADT [ses 0x446]
00:15:08.547783 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 1 I ident
00:15:08.576816 PPPoE PADT [ses 0x446]
00:15:12.609050 PPPoE  [ses 0x2822] LCP, Echo-Request (0x09), id 2, length 10
00:15:12.635370 PPPoE  [ses 0x2822] LCP, Echo-Reply (0x0a), id 2, length 10
00:15:18.558053 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 1 I ident
00:15:18.587499 PPPoE PADT [ses 0x446]

Ale příchozí isakmp přichází pod špatnou session id 0x446:
00:15:19.627528 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 1 I ident
00:15:32.629094 PPPoE  [ses 0x2822] LCP, Echo-Request (0x09), id 3, length 10
00:15:32.654493 PPPoE  [ses 0x2822] LCP, Echo-Reply (0x0a), id 3, length 10
00:15:38.578346 PPPoE  [ses 0x2822] IP 212.67.86.176.isakmp > 84.242.96.243.isakmp: isakmp: phase 1 I ident
00:15:38.607631 PPPoE PADT [ses 0x446]
00:15:52.649253 PPPoE  [ses 0x2822] LCP, Echo-Request (0x09), id 4, length 10
00:15:52.675872 PPPoE  [ses 0x2822] LCP, Echo-Reply (0x0a), id 4, length 10
00:15:57.440769 PPPoE  [ses 0x2822] IP 84.242.96.243.imaps > 212.67.86.176.49828: Flags [P.], seq 281:334, ack 313, win 63, length 53
00:15:57.442378 PPPoE  [ses 0x2822] IP 212.67.86.176.49828 > 84.242.96.243.imaps: Flags [P.], seq 313:387, ack 334, win 16262, length 74
00:15:57.496208 PPPoE  [ses 0x2822] IP 84.242.96.243.imaps > 212.67.86.176.49828: Flags [P.], seq 334:387, ack 387, win 63, length 53
00:15:57.497069 PPPoE  [ses 0x2822] IP 212.67.86.176.49828 > 84.242.96.243.imaps: Flags [P.], seq 387:461, ack 387, win 16248, length 74
00:15:57.542450 PPPoE  [ses 0x2822] IP 84.242.96.243.imaps > 212.67.86.176.49828: Flags [P.], seq 387:440, ack 461, win 63, length 53
00:15:57.543189 PPPoE  [ses 0x2822] IP 212.67.86.176.49828 > 84.242.96.243.imaps: Flags [P.], seq 461:551, ack 440, win 16235, length 90
00:15:57.588193 PPPoE  [ses 0x2822] IP 84.242.96.243.imaps > 212.67.86.176.49828: Flags [P.], seq 440:525, ack 551, win 63, length 85
00:15:57.590674 PPPoE  [ses 0x2822] IP 212.67.86.176.49828 > 84.242.96.243.imaps: Flags [P.], seq 551:625, ack 525, win 16214, length 74
00:15:57.634938 PPPoE  [ses 0x2822] IP 84.242.96.243.imaps > 212.67.86.176.49828: Flags [P.], seq 525:562, ack 625, win 63, length 37
00:15:57.841635 PPPoE  [ses 0x2822] IP 212.67.86.176.49828 > 84.242.96.243.imaps: Flags [.], ack 562, win 16205, length 0
00:15:57.883961 PPPoE  [ses 0x2822] IP 84.242.96.243.imaps > 212.67.86.176.49828: Flags [P.], seq 525:562, ack 625, win 63, length 37
00:15:57.884412 PPPoE  [ses 0x2822] IP 212.67.86.176.49828 > 84.242.96.243.imaps: Flags [.], ack 562, win 16205, options [nop,nop,sack 1 {525:562}], length 0
Opět příchozí isakmp pod špatnou session id 0x446:
00:15:59.294790 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 1 I ident
00:16:10.048493 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 1 I ident
00:16:12.669407 PPPoE  [ses 0x2822] LCP, Echo-Request (0x09), id 5, length 10
00:16:12.696252 PPPoE  [ses 0x2822] LCP, Echo-Reply (0x0a), id 5, length 10
00:16:19.920937 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 1 I ident
00:16:32.689568 PPPoE  [ses 0x2822] LCP, Echo-Request (0x09), id 6, length 10
00:16:32.715639 PPPoE  [ses 0x2822] LCP, Echo-Reply (0x0a), id 6, length 10
00:16:39.919308 PPPoE  [ses 0x446] IP 84.242.96.243.isakmp > 212.67.86.176.isakmp: isakmp: phase 1 I ident

[Reklama]

[anoname]

Zkuste navázat nové PPPoE po pauze asi 30 sekund. V nejhorším případě pauze tak dlouhé, jako trvá restart modemu.

[Kolemjdoucí]

PPPoE spojení ukončeno:
00:14:24.781822 PPPoE  [ses 0x446] LCP, Term-Request (0x05), id 2, length 18
00:14:24.809728 PPPoE  [ses 0x446] LCP, Term-Ack (0x06), id 2, length 6

Možná je toto ukončení špatně. Zkuste zapnout podrobnější výpis paketů, včetně sekce Data - viz http://tools.ietf.org/html/rfc1661.html#section-5.5 . Ten Term-Ack má nastavenou délku 6, to znamená že by tam měly být dva bajty Data. Pokud nejsou, protistrana může takový paket zahodit jako nevalidní to by mohlo vést k tomu co popisujete - neuzavřené spojení do kterého stále dostáváte nějaké IP pakety.

[Dz]

Toto jsem posílal technické podpoře:

Problém stále přetrvává, bylo by možné požádat O2 o předání problému vyššímu technickému levelu?
Přidávám tcpdumpy zachycující problem jak ze strany VDSL přípojky, tak z druhé strany ipsec tunelu.

Je zachycena následující situace po restartu modemu.

1. PPPoE spojení se session ID 0x2003 vytvořeno
2. ipsec tunel mezi 212.67.86.176 (strana VDSL) a 84.242.96.243 (IP adresa v síti UPC) úspěšně navázáno. Všechny pakety chodí pod správným PPPoE session ID 0x2003.
3. PPPoE spojení 0x2003 ukončeno (paket 94,95 v souboru pppoeprovlem_vdslside_2.cap)
4. Navázáno nové PPPoE spojení se session ID 0x21e6 (paket 99), TCP trafic je průchozí z obou stran pod novým session ID 0x21e6.
5. Nikoliv však IPSEC. RAS O2 posílá smetí ve starém ukončeném PPPoE session ID 0x2003 - posílá především ipsec v PPPoE id 0x2003 (paket např. 181) a PPPoE PADT pro dávno ukončené spojení session ID 0x2003 (např. paket 195)
6. Přestože je PPPoE spojení 0x21e6 průchozí pro TCP, IPSEC traffic odcházející z VDSL pod novým session id 0x21e6 vůbec na druhou stranu nedorazí.

Je zjevné, že je problém na RASu O2 s protokolem IPSEC po restartu PPPoE spojení.
Vlastně na stejný problém je upozorňováno na stránkách O2 guru http://www.o2.cz/osobni/forum/?forum_id=26&topic_id=830 :

"Mě osobně vestavěný IPSec klient funguje pouze jako iniciator, jako responder se mi ho rozchodit nepodařilo a chybí v něm možnost uložení certifikátů. Funguje na něm již i IPSec tunel jako průchozí (testoval jsem tedy sestavení jenom z LAN do WAN), ale jakmile se tunel zavře a znovu otevře, tak již skrz něj netečou žádná data, modem musím resnout, pak to zase funguje. Takže je to podle mne zase nějaký nedodělaný "

Tam lidé podezřívají problém ve firmwaru modemu Comtrend, který používají přímo jako konec ipsecu. Problém však není ve firmwaru modemu comtrend, ale jak dokládám na RASu O2.

Prosím o eskalaci tohoto problému na vyšší úroveň technické podpory O2. Získání těchto traců mě stálo hodně času.

Klidně jim můžete předat mé telefonní číslo (xxx xxx xxx) a mohu jim problém na požádání reprodukovat (ve chvíli, kdy by potřebovali tracovat na straně RASu).

Děkuji, s pozdravem
...

[Dz]

A toto přišlo jako odpověď:

"Ověřte mimo režim bridge. Máme za to, že bude závada nejspíše na zařízení ZKz, které navazuje PPP, ověřte ve standardním zapojení v režimu routingu. Ideálně několik dní pro sběr statistických dat."

Nezabili byste je? Jak můžu otestovat něco takového v režimu routingu, když IPSEC (bez NAT-T helpra) potřebuje veřejnou IP adresu.
Neskutečné.

Nemáte někdo kontakt v O2, který by tcpdumpu záchytu rozuměl?

[Reklama]

[Dz]

> Možná je toto ukončení špatně. Zkuste zapnout podrobnější výpis paketů, včetně sekce Data - viz http://tools.ietf.org/html/rfc1661.html#section-5.5 . Ten Term-Ack má nastavenou délku 6, to znamená že by tam měly být dva bajty Data. Pokud nejsou, protistrana může takový paket zahodit jako nevalidní to by mohlo vést k tomu co popisujete - neuzavřené spojení do kterého stále dostáváte nějaké IP pakety.

 Data

      The Data field is zero or more octets, and contains uninterpreted
      data for use by the sender.  The data may consist of any binary
      value.  The end of the field is indicated by the Length.

Takže 0 B je dle RFC v pořádku.

> Zkuste navázat nové PPPoE po pauze asi 30 sekund. V nejhorším případě pauze tak dlouhé, jako trvá restart modemu.

Zkoušel jsem vyčkat i přes 60 sekund a nepomohlo to.

Pokud má někdo zájem, mohu poskytnout tcpdumpy z obou stran.

[Kolemjdoucí]

> Možná je toto ukončení špatně. Zkuste zapnout podrobnější výpis paketů, včetně sekce Data - viz http://tools.ietf.org/html/rfc1661.html#section-5.5 . Ten Term-Ack má nastavenou délku 6, to znamená že by tam měly být dva bajty Data. Pokud nejsou, protistrana může takový paket zahodit jako nevalidní to by mohlo vést k tomu co popisujete - neuzavřené spojení do kterého stále dostáváte nějaké IP pakety.

 Data

      The Data field is zero or more octets, and contains uninterpreted
      data for use by the sender.  The data may consist of any binary
      value.  The end of the field is indicated by the Length.

Takže 0 B je dle RFC v pořádku.

0 B je dle RFC v pořádku, ale pak je třeba nastavit length na 4 a ne na 6. Jestliže nedáváte žádná Data (0 B) a k tomu length 6, zabere tato věta z RFC: "When a packet is received with an invalid Length field, the packet is silently discarded"

[Dz]

> 0 B je dle RFC v pořádku, ale pak je třeba nastavit length na 4 a ne na 6. Jestliže nedáváte žádná Data (0 B) a k tomu length 6, zabere tato věta z RFC: "When a packet is received with an invalid Length field, the packet is silently discarded"
 
Zaprvé ten Term-ACK posílá RAS (takže by to byla další buga RASu O2) a zadruhé je ta délka v pořádku. 1B code (termination ACK) + 1B identifier +
2B lenght field, což dává délku 4B.

[Dz]

Těch 6B v textovém výpisu bylo včetně PPP hlavičky. Ve wiresharku je lenght Term-ACK 4B a odpovídají.

[Kolemjdoucí]

> 0 B je dle RFC v pořádku, ale pak je třeba nastavit length na 4 a ne na 6. Jestliže nedáváte žádná Data (0 B) a k tomu length 6, zabere tato věta z RFC: "When a packet is received with an invalid Length field, the packet is silently discarded"
 
Zaprvé ten Term-ACK posílá RAS (takže by to byla další buga RASu O2) a zadruhé je ta délka v pořádku. 1B code (termination ACK) + 1B identifier +
2B lenght field, což dává délku 4B.

Já vím že délka 4 je s prázdnou sekcí Data v pořádku. V tom výpise ale máte "LCP, Term-Ack (0x06), id 2, length 6" takže proto jsem o tom začal psát. Každopádně teď když jste přidal informaci o tom že Term-Ack posílá RAS tak odvozuji že Term-Request posílá váš klient a mám pro vás návrh řešení: neposílejte Term-Request a zkuste místo toho posílat PADT, snad to bude fungovat lépe než Term-Request.

[Dz]

Tak se mi nepodařilo upravit rp-pppoe.so pppd plugin, aby při shození poslal PADT.

When a PADT is received, no further PPP traffic is allowed to be sent
   using that session.  Even normal PPP termination packets MUST NOT be
   sent after sending or receiving a PADT.  A PPP peer SHOULD use the
   PPP protocol itself to bring down a PPPoE session, but the PADT MAY
   be used when PPP can not be used.


   When LCP terminates, the Host and Access concentrator MUST stop using
   that PPPoE session.  If the Host wishes to start another PPP session,
   it MUST return to the PPPoE Discovery stage.

Takže RAS O2 zcela zjevně porušuje RFC.

Ale vypozoroval jsem, že když PPPoE spojení nechám shozené 5 minut, tak po nahození je ipsec průchozí.

[anoname]

Podle předchozích pozorování a názorů je pravděpodobné, že RAS považuje spojení za ukončené (přerušené) až po době, kdy se nevrátí poslední z keepalive paketů. Interval posílání i počet nedoručených keepalive by měl jít nastavit v konfiguraci PPPoE. Není to řešení problému, ale pokus o minimální prodlevu po rozpadu spojení.

Ještě k odpovědi z O2. VPN s ipsec by měla jít provozovat i za NATem bez helperu. Na straně serveru je potřeba forwardovat UDP 500 na místní adresu a VPN musí používat pouze ESP.