Archiv für den Monat: März 2015

PPPoE Connection schlägt mit C886VAJ-K9 und IOS 15.4(3)M2 fehl

Beim heutigen testen eines neuen C886VAJ-K9 mit IOS 15.4(3)M2 stieß ich auf ein Problem bei der Zuweisung der öffentlichen IP Adresse während der ADSL/VDSL Einwahl. Im Log war ersichtlich, dass der Dialer up war und ca. 30 Sekunden später wieder abfiehl.

000213: *Mar 15 09:24:52: %DIALER-6-BIND: Interface Vi2 bound to profile Di1
000217: *Mar 15 09:24:52: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
000213: *Mar 15 09:24:52: %DIALER-6-BIND: Interface Vi2 bound to profile Di1
000219: *Mar 15 09:24:52: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up000223: *Mar 15 09:25:23: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di1
000225: *Mar 15 09:25:23: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to down
000226: *Mar 15 09:25:23: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down

Die IP Interface Brief-Summary zeigte, dass zwar Status und Protocol up waren, aber die IP-Adresse war noch unassigned:

router1#sh ip int brief | i Di
Dialer1                    unassigned   YES IPCP   up                    up

Um CRC oder Header Fehler auf dem VDSL auszuschließen kontrollierte ich die entsprechenden Counter:

router1#sh controllers vdsL 0 | i Err
CRC Errors:               0                0             0                 0
Header Errors:            0                0             0                 0

Bisherige Tests im Labor mit einem C1921-SEC-K9 und dem IOS 15.2(4)M7 verliefen ohne Probleme. Insofern entschied ich mich den Router zuerst auf 15.3(3)M5 zuheben. Auch hier die Einwahl ohne Probleme. Das Upgrade auf 15.4(3)M1 auf dem C1921-SEC-K9 klappte auch, allerdings zeigte dieser dann die identischen Probleme bei der Zuweisung der öffentlichen IP am Dialer-Interface.

Das auf dem C1921-SEC-K9 mit IOS 15.4(3)M1 durchgeführte Debugging der PPP-Negotiation zeigte die Ursache:

[…]
000158: *Mar 15 10:23:42: Vi2 CHAP: I SUCCESS id 1 len 42 msg is „CHAP authentication success, unit 8114“
000159: *Mar 15 10:23:42: Vi2 PPP: Phase is FORWARDING, Attempting Forward
000160: *Mar 15 10:23:42: Vi2 PPP: Phase is ESTABLISHING, Finish LCP
000161: *Mar 15 10:23:42: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
000162: *Mar 15 10:23:42: Vi2 PPP: No AAA accounting method list
000163: *Mar 15 10:23:42: Vi2 PPP: Phase is UP
000164: *Mar 15 10:23:42: Vi2 IPCP: Protocol configured, start CP. state[Initial]
000165: *Mar 15 10:23:42: Vi2 IPCP: Event[OPEN] State[Initial to Starting]
000166: *Mar 15 10:23:42: Vi2 IPCP: O CONFREQ [Starting] id 1 len 10
000167: *Mar 15 10:23:42: Vi2 IPCP:    Address 0.0.0.0 (0x030600000000)
000168: *Mar 15 10:23:42: Vi2 IPCP: Event[UP] State[Starting to REQsent]
000169: *Mar 15 10:23:42: Vi2 PPP: Control packet rate limit 10 reached
000170: *Mar 15 10:23:42: Vi2 PPP: Entering block state for 30 seconds
000171: *Mar 15 10:23:42: Vi2 PPP: Packet throttled, Dropping packet
000172: *Mar 15 10:23:42: Vi2 PPP: Packet throttled, Dropping packet
000173: *Mar 15 10:23:45: Vi2 PPP: Packet throttled, Dropping packet

Es verdichtete sich die Vermutung, dass sich die Default-Parameter zw. IOS 15.2(4)M7 und IOS 15.4(3)M2 auf dem C1921-SEC-K9  geändert haben, wodurch sich ggf. auch das Problem auf dem C886VAJ-K9 erklären könnte. Dieser zeigte im PPP-Debugugging die gleichen Throtteling-Meldungen.

Insofern verglich ich mit dem Befehl show running-config all | i ppp zw. den beiden IOS 15.2(4)M7 und IOS 15.4(3)M1 und es fiel der neue PPP Default-Parameter ppp packet throttle 10 1 30 auf. In der Tat zeigte sich das Blocking auch mit dem Kommando:

router1#sh ppp throttled
Ingress Port         Uniq ID          Remaining Block Time
———————————————————-
Virtual-Access2         5                  27 Seconds

Da ich weder in den Release-Notes noch in den Whitepapers zu den jeweilgen IOS Versionen fündig wurde, versuchte ich mit  ppp packet throttle 20 1 30 einen Schuss ins Blaue um so die neuen Default-Werte etwas zu enthärten – erfolgreich. Letztendlich erlaubte ich pro Sekunde 10 weitere Control-Pakete was die Policy etwas abschwächte und nun die Zuweisung der IP Adresse via IPCP auf dem Dialer-Interface gelang:

[…]
000141: *Mar 15 10:51:50: Vi2 CHAP: I SUCCESS id 1 len 43 msg is „CHAP authentication success, unit 13163“
000142: *Mar 15 10:51:50: Vi2 PPP: Phase is FORWARDING, Attempting Forward
000143: *Mar 15 10:51:50: Vi2 PPP: Phase is ESTABLISHING, Finish LCP
000144: *Mar 15 10:51:50: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
000145: *Mar 15 10:51:50: Vi2 PPP: No AAA accounting method list
000146: *Mar 15 10:51:50: Vi2 PPP: Phase is UP
000147: *Mar 15 10:51:50: Vi2 IPCP: Protocol configured, start CP. state[Initial]
000148: *Mar 15 10:51:50: Vi2 IPCP: Event[OPEN] State[Initial to Starting]
000149: *Mar 15 10:51:50: Vi2 IPCP: O CONFREQ [Starting] id 1 len 10
000150: *Mar 15 10:51:50: Vi2 IPCP:    Address 0.0.0.0 (0x030600000000)
000151: *Mar 15 10:51:50: Vi2 IPCP: Event[UP] State[Starting to REQsent]
000152: *Mar 15 10:51:50: Vi2 IPCP: I CONFREQ [REQsent] id 162 len 10
000153: *Mar 15 10:51:50: Vi2 IPCP:    Address a.a.a.a (0x030657BAE067)
000154: *Mar 15 10:51:50: Vi2 IPCP: O CONFACK [REQsent] id 162 len 10
000155: *Mar 15 10:51:50: Vi2 IPCP:    Address a.a.a.a  (0x030657BAE067)
000156: *Mar 15 10:51:50: Vi2 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
000157: *Mar 15 10:51:50: Vi2 IPCP: I CONFNAK [ACKsent] id 1 len 10
000158: *Mar 15 10:51:50: Vi2 IPCP:    Address b.b.b.b (0x03065DC67EC5)
000159: *Mar 15 10:51:50: Vi2 IPCP: O CONFREQ [ACKsent] id 2 len 10
000160: *Mar 15 10:51:50: Vi2 IPCP:    Address b.b.b.b (0x03065DC67EC5)
000161: *Mar 15 10:51:50: Vi2 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
000162: *Mar 15 10:51:51: Vi2 IPCP: I CONFACK [ACKsent] id 2 len 10
000163: *Mar 15 10:51:51: Vi2 IPCP:    Address b.b.b.b (0x03065DC67EC5)
000164: *Mar 15 10:51:51: Vi2 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
000165: *Mar 15 10:51:51: Vi2 IPCP: State is Open
000166: *Mar 15 10:51:51: Di1 IPCP: Install negotiated IP interface address b.b.b.b

Die IP Interface Brief-Summary nun auch die erfolgreiche Zuweisung der öffentlichen IP adresse:

asl1#sh ip int brief | i Di
Dialer1                    a.a.a.aYES IPCP   up                    up