pppoe - ppp (LCP) troubles

From
Basil Logachev (2:5020/400)
To
All (2:5054/37.63)
Date
2006-03-15T15:49:48Z
Area
RU.CISCO
From: "Basil Logachev" <lwa@geoilbent.pursatcom.ru>

Hello, All!

Есть 1721, которая должна поднимать 2 клиентские pppoe сессии. До
провайдера - радиоэзернетом, но не суть, т.к. до определенного момента
все работало нормально. Однажды провайдер поменял сетку (ип-адреса) - ну
казалось бы, что в этом такого - для клиентов должно быть все прозрачно.
Ан нет, поднятие сессии может продолжаться больше часа - таймауты на
фазе LCP. Причем не важно, одна сессия пытается подняться или обе сразу.
Конфиг и дебаги ниже

--------------------
vpdn-group 1
 request-dialin
  protocol pppoe
!
interface Ethernet0
 description *** Link to ISP
 ip address 192.168.14.3 255.255.255.248
 no ip proxy-arp
 no ip route-cache
 no ip mroute-cache
 half-duplex
 pppoe enable
 pppoe-client dial-pool-number 2
 pppoe-client dial-pool-number 1
 no cdp enable
!
interface Dialer0
 ip address negotiated
 ip access-group ext_in in
 ip mtu 1492
 ip nat outside
 encapsulation ppp
 dialer pool 1
 dialer-group 1
 no cdp enable
 ppp authentication pap callin
 ppp pap sent-username user_1 password 7 password_1
 crypto map sap
!
interface Dialer1
 ip address negotiated
 ip access-group ext_in in
 ip mtu 1492
 ip nat outside
 encapsulation ppp
 dialer pool 2
 dialer-group 2
 no cdp enable
 ppp authentication pap callin
 ppp pap sent-username user_2 password 7 password_2
 crypto map sap
!
--------------------
Строка crypto map sap нужна для поднятия шифрования

Дебаг несостоявшейся сессии:
--------------------
inetrtr#
Mar  9 16:23:43.496:  Sending PADI: Interface = Ethernet0
Mar  9 16:23:43.496: pppoe_send_padi:
         FF FF FF FF FF FF 00 0A B7 A1 74 CA 88 63 11 09
         00 00 00 0C 01 01 00 00 01 03 00 04 81 8C 25 A8 ...
Mar  9 16:23:43.500: PPPoE 0: I PADO R:000f.2404.8c60 L:000a.b7a1.74ca
Et0
         00 0A B7 A1 74 CA 00 0F 24 04 8C 60 88 63 11 07
         00 00 00 2E 01 01 00 00 01 03 00 04 81 8C 25 A8 ...
Mar  9 16:23:45.500:  PPPOE: we've got our pado and the pado timer went
off
Mar  9 16:23:45.500: OUT PADR from PPPoE Session
         00 0F 24 04 8C 60 00 0A B7 A1 74 CA 88 63 11 19
         00 00 00 2E 01 01 00 00 01 03 00 04 81 8C 25 A8 ...
Mar  9 16:23:45.504: PPPoE 34580: I PADS R:000f.2404.8c60
L:000a.b7a1.74ca Et0
         00 0A B7 A1 74 CA 00 0F 24 04 8C 60 88 63 11 65
         87 14 00 2E 01 01 00 00 01 03 00 04 81 8C 25 A8 ...
Mar  9 16:23:45.504: IN PADS from PPPoE Session
Mar  9 16:23:45.508: %DIALER-6-BIND: Interface Vi3 bound to profile Di1
Mar  9 16:23:45.508: PPPoE: Virtual Access interface obtained.
Mar  9 16:23:45.508: PPPoE : encap string prepared
Mar  9 16:23:45.508: [0]PPPoE 34580: data path set to Virtual Acess
Mar  9 16:23:45.528: Vi3 PPP: Phase is DOWN, Setup
Mar  9 16:23:45.528: Vi3 PPP: Using dialer call direction
Mar  9 16:23:45.528: Vi3 PPP: Treating connection as a callout
Mar  9 16:23:45.528: Vi3 PPP: Phase is ESTABLISHING, Active Open
Mar  9 16:23:45.528: Vi3 PPP: Authorization NOT required
Mar  9 16:23:45.532: Vi3 PPP: No remote authentication for call-out
Mar  9 16:23:45.532: Vi3 LCP: O CONFREQ [Closed] id 1 len 10
Mar  9 16:23:45.532: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:45.532: %LINK-3-UPDOWN: Interface Virtual-Access3, changed
state to up
Mar  9 16:23:45.536: Vi3 LCP: I CONFACK [REQsent] id 1 len 10
Mar  9 16:23:45.536: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:47.492: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:23:47.492: Vi3 LCP: O CONFREQ [ACKrcvd] id 2 len 10
Mar  9 16:23:47.492: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:47.496: Vi3 LCP: I CONFACK [REQsent] id 2 len 10
Mar  9 16:23:47.496: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:49.508: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:23:49.508: Vi3 LCP: O CONFREQ [ACKrcvd] id 3 len 10
Mar  9 16:23:49.508: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:49.512: Vi3 LCP: I CONFACK [REQsent] id 3 len 10
Mar  9 16:23:49.512: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:51.524: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:23:51.524: Vi3 LCP: O CONFREQ [ACKrcvd] id 4 len 10
Mar  9 16:23:51.524: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:51.528: Vi3 LCP: I CONFACK [REQsent] id 4 len 10
Mar  9 16:23:51.532: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:51.796: Vi2 PPP: Outbound cdp packet dropped, CDPCP state
is Listen
Mar  9 16:23:53.540: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:23:53.540: Vi3 LCP: O CONFREQ [ACKrcvd] id 5 len 10
Mar  9 16:23:53.540: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:53.544: Vi3 LCP: I CONFACK [REQsent] id 5 len 10
Mar  9 16:23:53.544: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:55.557: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:23:55.557: Vi3 LCP: O CONFREQ [ACKrcvd] id 6 len 10
Mar  9 16:23:55.557: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:55.561: Vi3 LCP: I CONFACK [REQsent] id 6 len 10
Mar  9 16:23:55.561: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:57.573: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:23:57.573: Vi3 LCP: O CONFREQ [ACKrcvd] id 7 len 10
Mar  9 16:23:57.573: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:57.577: Vi3 LCP: I CONFACK [REQsent] id 7 len 10
Mar  9 16:23:57.577: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:59.589: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:23:59.589: Vi3 LCP: O CONFREQ [ACKrcvd] id 8 len 10
Mar  9 16:23:59.589: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:23:59.593: Vi3 LCP: I CONFACK [REQsent] id 8 len 10
Mar  9 16:23:59.593: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:24:01.605: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:24:01.605: Vi3 LCP: O CONFREQ [ACKrcvd] id 9 len 10
Mar  9 16:24:01.605: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:24:01.609: Vi3 LCP: I CONFACK [REQsent] id 9 len 10
Mar  9 16:24:01.609: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:24:03.621: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:24:03.621: Vi3 LCP: O CONFREQ [ACKrcvd] id 10 len 10
Mar  9 16:24:03.621: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:24:03.625: Vi3 LCP: I CONFACK [REQsent] id 10 len 10
Mar  9 16:24:03.625: Vi3 LCP:    MagicNumber 0x0BD0F3B7 (0x05060BD0F3B7)
Mar  9 16:24:05.637: Vi3 LCP: TIMEout: State ACKrcvd
Mar  9 16:24:05.637:  PPPoE : Shutting down client session
Mar  9 16:24:05.637: [0]PPPoE 34580: O PADT R:000f.2404.8c60
L:000a.b7a1.74ca Et0
         00 0F 24 04 8C 60 00 0A B7 A1 74 CA 88 63 11 A7
         87 14 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ...
Mar  9 16:24:05.637: %DIALER-6-UNBIND: Interface Vi3 unbound from
profile Di1
Mar  9 16:24:05.641: Vi3 PPP: Block vaccess from being freed [0x10]
Mar  9 16:24:05.641: Vi3 LCP: State is Listen
Mar  9 16:24:05.641: %LINK-3-UPDOWN: Interface Virtual-Access3, changed
state to down
Mar  9 16:24:05.641: Vi3 PPP: Sending Acct Event[Down] id[C2]
Mar  9 16:24:05.645: Vi3 LCP: State is Closed
Mar  9 16:24:05.645: Vi3 PPP: Phase is DOWN
Mar  9 16:24:05.645: Vi3 PPP: Unlocked by [0x10] Still Locked by [0x2]
Mar  9 16:24:05.645: Vi3 PPP: Unlocked by [0x2] Still Locked by [0x0]
Mar  9 16:24:05.645: Vi3 PPP: Free previously blocked vaccess
inetrtr#
--------------------

То есть не доходит даже до аутентификации. Самое обидное, что
подставляешь писюк с RASPPPOE - все проходит на ура. Да и раньше ведь
работало...
Да, и еще:

inetrtr#sh ver
Cisco Internetwork Operating System Software
IOS (tm) C1700 Software (C1700-K9O3SY7-M), Version 12.2(13)T,  RELEASE
SOFTWARE (fc1)
TAC Support: http://www.cisco.com/tac
Copyright (c) 1986-2002 by cisco Systems, Inc.
Compiled Sat 16-Nov-02 14:14 by ccai
Image text-base: 0x80008120, data-base: 0x80E09160

ROM: System Bootstrap, Version 12.2(7r)XM1, RELEASE SOFTWARE (fc1)

inetrtr uptime is 2 hours, 19 minutes
System returned to ROM by power-on
System restarted at 14:17:05 EKT Tue Mar 14 2006
System image file is "flash:c1700-k9o3sy7-mz.122-13.T.bin"

cisco 1721 (MPC860P) processor (revision 0x100) with 56272K/9264K bytes
of memory.
Processor board ID FOC07030XAK (1547146075), with hardware revision 0000
MPC860P processor: part number 5, mask 2
Bridging software.
X.25 software, Version 3.0.0.
1 Ethernet/IEEE 802.3 interface(s)
1 FastEthernet/IEEE 802.3 interface(s)
1 Virtual Private Network (VPN) Module(s)
32K bytes of non-volatile configuration memory.
16384K bytes of processor board System flash (Read/Write)

Configuration register is 0x2102

With best regards, Basil Logachev.  E-mail: lwa@geoilbent.pursatcom.ru


--- ifmail v.2.15dev5.3
 * Origin: Ye 'Ol Disorganized NNTPCache groupie (2:5020/400)
SEEN-BY: 46/50 50/203 400/814 450/159 186 1024 451/30 461/43 640 465/11
SEEN-BY: 469/999 4616/3 4625/8 4626/6 4627/10 4641/444 5000/76 5000 5001/5001
SEEN-BY: 5006/1 5007/1 5010/70 5011/13 5015/28 221 5019/31 5020/175 400 545
SEEN-BY: 5020/639 715 758 830 937 982 1042 1057 1169 1521 1523 1604 1630 1909
SEEN-BY: 5020/1922 2020 2238 4441 5021/3 29 5022/128 5025/3 750 5026/14 45 49
SEEN-BY: 5027/12 5030/49 115 436 473 500 966 1063 1900 5034/13 5036/1 5040/47
SEEN-BY: 5042/13 5045/7 5049/1 36 5051/15 5053/16 5054/1 4 8 9 28 30 35 36 37
SEEN-BY: 5054/67 72 75 81 89 5057/1 5060/88 5061/15 5062/1 10 5063/3 5066/18
SEEN-BY: 5070/1222 5075/5 5077/70 5080/80 1003 5082/6 5083/21 5085/13 5090/108
SEEN-BY: 5093/57 5095/20 5096/18 6000/0 1 12 6001/3 10 6009/1
PATH: 5020/400 4441 545 5054/1 37