Hi,
I've upgrade my AS5300 IOS to 12.3(15) to solve the missing
Called-Station-Id attribute (and other problems with 12.2T)
Unfortunately 12.3(15) comes with a new problem. After an usual PPP
authentication/negotiation without any error, PPP doesn't "Add Route"
and terminates the session.
Apparently this is only happening with calls that are being
pre-authenticated using dnis. All this authentication process is being
received correctly by the RADIUS server and it's sending PASS replies.
This the final debug with a 12.2T14 (doesn't have this particularly
problem):
Jun 23 19:54:27.827: Vi3 EVT: IPCP Packet 0 0x62335724
Jun 23 19:54:27.827: Vi3 IPCP: I CONFREQ [ACKrcvd] id 7 len 28
Jun 23 19:54:27.827: Vi3 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:54:27.827: Vi3 IPCP: Address 195.23.192.176 (0x0306C317C0B0)
Jun 23 19:54:27.827: Vi3 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:54:27.827: Vi3 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:54:27.827: Vi3 IPCP: O CONFACK [ACKrcvd] id 7 len 28
Jun 23 19:54:27.827: Vi3 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:54:27.827: Vi3 IPCP: Address 195.23.192.176 (0x0306C317C0B0)
Jun 23 19:54:27.831: Vi3 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:54:27.831: Vi3 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:54:27.831: Vi3 IPCP: State is Open
Jun 23 19:54:27.831: Vi3 EVT: IPCP UP 0 0x633AD524
Jun 23 19:54:27.843: Vi3 EVT: Add Route 0 0xC317C0B0
Jun 23 19:54:27.843: Vi3 IPCP: Install route to 195.23.192.176
Jun 23 19:54:27.843: Vi3 IPCP: Add link info for cef entry 195.23.192.176
This is the final debug with 12.3(15):
Jun 23 19:55:00.766: Vi15 EVT: IPCP Packet 0 0x6242C0A0
Jun 23 19:55:00.766: Vi15 IPCP: I CONFREQ [ACKrcvd] id 7 len 28
Jun 23 19:55:00.766: Vi15 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:55:00.766: Vi15 IPCP: Address 195.23.192.104 (0x0306C317C068)
Jun 23 19:55:00.766: Vi15 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:55:00.766: Vi15 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:55:00.766: Vi15 IPCP: O CONFACK [ACKrcvd] id 7 len 28
Jun 23 19:55:00.770: Vi15 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:55:00.770: Vi15 IPCP: Address 195.23.192.104 (0x0306C317C068)
Jun 23 19:55:00.770: Vi15 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:55:00.770: Vi15 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:55:00.770: Vi15 IPCP: State is Open
Jun 23 19:55:00.778: Vi15 EVT: IPCP UP 0 0x62FFAFFC
Jun 23 19:55:00.778: Vi15 EVT: Soft Disc 0 0x00000000
Jun 23 19:55:00.782: Vi15 PPP: Sending Acct Event[Down] id[28A]
Jun 23 19:55:00.782: Vi15 IPCP: State is Closed
Jun 23 19:55:00.782: Vi15 PPP: Block vaccess from being freed [0x50]
Jun 23 19:55:00.782: Vi15 PPP: Unlocked by [0x10] Still Locked by [0x40]
Jun 23 19:55:00.782: Vi15 PPP: Phase is TERMINATING
Jun 23 19:55:00.782: Vi15 LCP: O TERMREQ [Open] id 2 len 4
Jun 23 19:55:00.782: As34 EVT: Hard Disc 0 0x00000000
Jun 23 19:55:00.786: As34 PPP: Sending Acct Event[Down] id[28A]
Jun 23 19:55:00.786: As34 PPP: Phase is TERMINATING
Jun 23 19:55:00.786: As34 LCP: State is Closed
Jun 23 19:55:00.786: As34 PPP: Phase is DOWN
Jun 23 19:55:00.786: As34 PPP SSS: Send DISCONNECT to mgr_hdl[9C0003C0]
Jun 23 19:55:00.794: Vi15 EVT: Cleanup IP 0 0x00000000
Also checking the output of "show ppp queues" we can see that and "IPCP UP"
event doesn't trigger an "Add route" event:
#sh ppp queues
5 Event Queues
size max kicks starts false suspends ticks(ms)
1 PPP Events 0 8 26381 26326 10 0 20
5 PPP Bind 0 0 0 0 0 0 20
3 PPP IPCP 0 3 267 267 0 0 20
2 PPP IP Route 0 2 131 131 0 0 100
4 PPP Hooks 0 1 268 268 0 0 20
34 Events
# Q Name Events Queued MaxQueued Suspends usec/evt max/evt
1 1 Setup 71 0 2 0 35 61
2* 1 Timer 25314 0 2 0 27 2008
3 1 Cstate 271 0 1 0 126 1653
4 1 Restart CP 130 0 2 0 6 9
5 UNREGISTERED
6 1 Hard Disc 63 0 1 0 895 1592
7 1 Soft Disc 61 0 1 0 2174 2654
8 1 Packet 433 0 4 0 424 2805
9 1 Auth Packet 71 0 1 0 228 299
10* 3 IPCP Packet 285 0 3 0 339 996
11* 2 Add Route 5 0 1 0 473 495
12* 2 Remove Route 4 0 1 0 282 288
13* 2 Remove Top 0 0 0 0 0 0
14* 2 Remove Flag 0 0 0 0 0 0
15* 2 Neg Addr Add 0 0 0 0 0 0
16* 2 Neg Addr Remov 0 0 0 0 0 0
17* 2 DHCP Opt Add 0 0 0 0 0 0
18* 2 DHCP Opt Del 0 0 0 0 0 0
19* 2 Cleanup IP 65 0 1 0 15 95
20* 2 IPCP UP 66 0 1 0 524 5646
21 1 Set LCP Open 63 0 1 0 1393 1744
22 1 Virtualize 4 0 1 0 653 704
23 1 Redirect 67 0 1 0 26 666
24 1 Forwarded 134 0 1 0 750 1402
25 4 Hook 268 0 1 0 132 509
26 1 AAA Response 201 0 2 0 940 2491
27 1 Static Bind 0 0 0 0 0 0
28 5 Dynamic Bind 0 0 0 0 0 0
29 1 Bound 0 0 0 0 0 0
30 1 Virtual Profil 63 0 1 0 1748 2136
31 1 Multilink Up 4 0 1 4 7 7
32 1 Multilink Down 3 0 1 0 2915 2937
33 1 Multilink Clea 0 0 0 0 0 0
34 UNREGISTERED
Pre-processed Requests LCP: 2 IPCP: 1
PPP Request Failures: 0
PPP Hold Queue Drops: 0
IPCP Skipped - Add Route: 0 AddrAdd: 0 AddrRem: 0
PPP Handles: alloc[3164] free[2905] outstanding[259]
On the 12.2T:
10 1 Auth Packet 19 0 1 0 243 292
11* 3 IPCP Packet 90 0 2 0 296 1141
12* 2 Add Route 16 0 1 0 571 594
13* 2 Remove Route 12 0 1 0 249 353
14* 2 Remove Top 0 0 0 0 0 0
15* 2 Remove Flag 0 0 0 0 0 0
16* 2 Neg Addr Add 0 0 0 0 0 0
17* 2 Neg Addr Remov 0 0 0 0 0 0
18* 2 IPCP UP 16 0 1 1 7470 12782
19 1 Set LCP Open 17 0 1 0 1231 1356
Does anyone have any idea about what could be the problem, or have
already run into it?
Best Regards,
--
Rodrigo
I've upgrade my AS5300 IOS to 12.3(15) to solve the missing
Called-Station-Id attribute (and other problems with 12.2T)
Unfortunately 12.3(15) comes with a new problem. After an usual PPP
authentication/negotiation without any error, PPP doesn't "Add Route"
and terminates the session.
Apparently this is only happening with calls that are being
pre-authenticated using dnis. All this authentication process is being
received correctly by the RADIUS server and it's sending PASS replies.
This the final debug with a 12.2T14 (doesn't have this particularly
problem):
Jun 23 19:54:27.827: Vi3 EVT: IPCP Packet 0 0x62335724
Jun 23 19:54:27.827: Vi3 IPCP: I CONFREQ [ACKrcvd] id 7 len 28
Jun 23 19:54:27.827: Vi3 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:54:27.827: Vi3 IPCP: Address 195.23.192.176 (0x0306C317C0B0)
Jun 23 19:54:27.827: Vi3 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:54:27.827: Vi3 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:54:27.827: Vi3 IPCP: O CONFACK [ACKrcvd] id 7 len 28
Jun 23 19:54:27.827: Vi3 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:54:27.827: Vi3 IPCP: Address 195.23.192.176 (0x0306C317C0B0)
Jun 23 19:54:27.831: Vi3 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:54:27.831: Vi3 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:54:27.831: Vi3 IPCP: State is Open
Jun 23 19:54:27.831: Vi3 EVT: IPCP UP 0 0x633AD524
Jun 23 19:54:27.843: Vi3 EVT: Add Route 0 0xC317C0B0
Jun 23 19:54:27.843: Vi3 IPCP: Install route to 195.23.192.176
Jun 23 19:54:27.843: Vi3 IPCP: Add link info for cef entry 195.23.192.176
This is the final debug with 12.3(15):
Jun 23 19:55:00.766: Vi15 EVT: IPCP Packet 0 0x6242C0A0
Jun 23 19:55:00.766: Vi15 IPCP: I CONFREQ [ACKrcvd] id 7 len 28
Jun 23 19:55:00.766: Vi15 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:55:00.766: Vi15 IPCP: Address 195.23.192.104 (0x0306C317C068)
Jun 23 19:55:00.766: Vi15 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:55:00.766: Vi15 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:55:00.766: Vi15 IPCP: O CONFACK [ACKrcvd] id 7 len 28
Jun 23 19:55:00.770: Vi15 IPCP: CompressType VJ 15 slots CompressSlotID (0x0206002D0F01)
Jun 23 19:55:00.770: Vi15 IPCP: Address 195.23.192.104 (0x0306C317C068)
Jun 23 19:55:00.770: Vi15 IPCP: PrimaryDNS 195.23.129.126 (0x8106C317817E)
Jun 23 19:55:00.770: Vi15 IPCP: SecondaryDNS 194.79.69.222 (0x8306C24F45DE)
Jun 23 19:55:00.770: Vi15 IPCP: State is Open
Jun 23 19:55:00.778: Vi15 EVT: IPCP UP 0 0x62FFAFFC
Jun 23 19:55:00.778: Vi15 EVT: Soft Disc 0 0x00000000
Jun 23 19:55:00.782: Vi15 PPP: Sending Acct Event[Down] id[28A]
Jun 23 19:55:00.782: Vi15 IPCP: State is Closed
Jun 23 19:55:00.782: Vi15 PPP: Block vaccess from being freed [0x50]
Jun 23 19:55:00.782: Vi15 PPP: Unlocked by [0x10] Still Locked by [0x40]
Jun 23 19:55:00.782: Vi15 PPP: Phase is TERMINATING
Jun 23 19:55:00.782: Vi15 LCP: O TERMREQ [Open] id 2 len 4
Jun 23 19:55:00.782: As34 EVT: Hard Disc 0 0x00000000
Jun 23 19:55:00.786: As34 PPP: Sending Acct Event[Down] id[28A]
Jun 23 19:55:00.786: As34 PPP: Phase is TERMINATING
Jun 23 19:55:00.786: As34 LCP: State is Closed
Jun 23 19:55:00.786: As34 PPP: Phase is DOWN
Jun 23 19:55:00.786: As34 PPP SSS: Send DISCONNECT to mgr_hdl[9C0003C0]
Jun 23 19:55:00.794: Vi15 EVT: Cleanup IP 0 0x00000000
Also checking the output of "show ppp queues" we can see that and "IPCP UP"
event doesn't trigger an "Add route" event:
#sh ppp queues
5 Event Queues
size max kicks starts false suspends ticks(ms)
1 PPP Events 0 8 26381 26326 10 0 20
5 PPP Bind 0 0 0 0 0 0 20
3 PPP IPCP 0 3 267 267 0 0 20
2 PPP IP Route 0 2 131 131 0 0 100
4 PPP Hooks 0 1 268 268 0 0 20
34 Events
# Q Name Events Queued MaxQueued Suspends usec/evt max/evt
1 1 Setup 71 0 2 0 35 61
2* 1 Timer 25314 0 2 0 27 2008
3 1 Cstate 271 0 1 0 126 1653
4 1 Restart CP 130 0 2 0 6 9
5 UNREGISTERED
6 1 Hard Disc 63 0 1 0 895 1592
7 1 Soft Disc 61 0 1 0 2174 2654
8 1 Packet 433 0 4 0 424 2805
9 1 Auth Packet 71 0 1 0 228 299
10* 3 IPCP Packet 285 0 3 0 339 996
11* 2 Add Route 5 0 1 0 473 495
12* 2 Remove Route 4 0 1 0 282 288
13* 2 Remove Top 0 0 0 0 0 0
14* 2 Remove Flag 0 0 0 0 0 0
15* 2 Neg Addr Add 0 0 0 0 0 0
16* 2 Neg Addr Remov 0 0 0 0 0 0
17* 2 DHCP Opt Add 0 0 0 0 0 0
18* 2 DHCP Opt Del 0 0 0 0 0 0
19* 2 Cleanup IP 65 0 1 0 15 95
20* 2 IPCP UP 66 0 1 0 524 5646
21 1 Set LCP Open 63 0 1 0 1393 1744
22 1 Virtualize 4 0 1 0 653 704
23 1 Redirect 67 0 1 0 26 666
24 1 Forwarded 134 0 1 0 750 1402
25 4 Hook 268 0 1 0 132 509
26 1 AAA Response 201 0 2 0 940 2491
27 1 Static Bind 0 0 0 0 0 0
28 5 Dynamic Bind 0 0 0 0 0 0
29 1 Bound 0 0 0 0 0 0
30 1 Virtual Profil 63 0 1 0 1748 2136
31 1 Multilink Up 4 0 1 4 7 7
32 1 Multilink Down 3 0 1 0 2915 2937
33 1 Multilink Clea 0 0 0 0 0 0
34 UNREGISTERED
Pre-processed Requests LCP: 2 IPCP: 1
PPP Request Failures: 0
PPP Hold Queue Drops: 0
IPCP Skipped - Add Route: 0 AddrAdd: 0 AddrRem: 0
PPP Handles: alloc[3164] free[2905] outstanding[259]
On the 12.2T:
10 1 Auth Packet 19 0 1 0 243 292
11* 3 IPCP Packet 90 0 2 0 296 1141
12* 2 Add Route 16 0 1 0 571 594
13* 2 Remove Route 12 0 1 0 249 353
14* 2 Remove Top 0 0 0 0 0 0
15* 2 Remove Flag 0 0 0 0 0 0
16* 2 Neg Addr Add 0 0 0 0 0 0
17* 2 Neg Addr Remov 0 0 0 0 0 0
18* 2 IPCP UP 16 0 1 1 7470 12782
19 1 Set LCP Open 17 0 1 0 1231 1356
Does anyone have any idea about what could be the problem, or have
already run into it?
Best Regards,
--
Rodrigo