[cisco-bba] Many PPPoA/E users unable to stay connected to Cisco 7206VXR
Frank Bulk
frnkblk at iname.com
Thu Jul 17 23:10:02 EDT 2008
Last night we upgraded our transport network and the OC-3 card in shelf also
reset, causing all our DSL connections into our Cisco 7206VXR (with NPE400)
to drop. No problem, quite normal. The problem is that RADIUS was hammered
all morning with ~800 users *trying* to get in. The link would go up, many
times they would get an IP, but then drop after 10 to 15 seconds. We did
have 1600-1800 users in, mixture of PPPoA/E. After working with Cisco TAC
for some time they all of a sudden came in. But some time later the issue
re-occurred (it's possible that me issuing a "no mtu 1504" on the ATM
interface could have been the cause).
What I found strange were the "Replace XYZ code # id ## with id ##" lines in
the debug. TAC said that these messages show up when under load (with or
without debug turned). Based on what I can piece together, at 17:23:19 I
*should* have had
Vi1349 IPCP: I CONFREQ [ACKrcvd] id 39 len 22
Vi1349 IPCP: Address 0.0.0.0 (0x030600000000)
Vi1349 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
Vi1349 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
but instead I get those "Replace" messages. According to the TAC engineer,
it's possible that the BRAS' CPU was so busy processing and the incoming LCP
messages couldn't be processed in a timely manner. The "Replace" messages
are additional/identical packets coming from the DSL modem that the BRAS
hasn't yet processed. Several seconds later the modem gives up and issues a
termination request (I TERMREQ). Then the process repeats.
I upgraded from 12.2(26) to 12.2(31)SB11, but while that code let all 2400
PPPoA/E connections in almost immediately, the router crashed 3 times (the
crash trace has something to do with DHCP, says the tech, it appears to be a
new bug) so we moved to 12.4(19b). That code release is stable, but we had
the same problem as before with ~600 users not getting. But all of a
sudden, 20 minutes later, they were in. The only think we can speculate is
that some element of load reduced so they could properly be processed.
Has anyone seen these "Replace XYZ code" messages before, and if so, what
was solution? I would like to move to 12.2(31)SB12, but TAC says they don't
see any DHCP issues addressed, so it's not likely that moving to that
train/release would help me at all.
Regards,
Frank Bulk
============================================================================
========
Bad
============================================================================
========
Jul 17 17:22:17: Vi1349 PPP: Phase is ESTABLISHING, Passive Open [0 sess, 44
load]
Jul 17 17:22:17: Vi1349 LCP: State is Listen
Jul 17 17:22:21: Vi1349 LCP: I CONFREQ [Listen] id 54 len 10
Jul 17 17:22:21: Vi1349 LCP: MagicNumber 0x99B91EB0 (0x050699B91EB0)
Jul 17 17:22:21: Vi1349 LCP: O CONFREQ [Listen] id 119 len 14
Jul 17 17:22:21: Vi1349 LCP: AuthProto PAP (0x0304C023)
Jul 17 17:22:21: Vi1349 LCP: MagicNumber 0x0E319A2F (0x05060E319A2F)
Jul 17 17:22:21: Vi1349 LCP: O CONFACK [Listen] id 54 len 10
Jul 17 17:22:21: Vi1349 LCP: MagicNumber 0x99B91EB0 (0x050699B91EB0)
Jul 17 17:22:24: Vi1349 PPP: Replace PAP code 1 id 25 with id 26
Jul 17 17:22:28: Vi1349 PPP: Replace PAP code 1 id 26 with id 27
Jul 17 17:22:31: Vi1349 PPP: Replace PAP code 1 id 27 with id 28
Jul 17 17:22:31: Vi1349 LCP: I CONFACK [ACKsent] id 119 len 14
Jul 17 17:22:31: Vi1349 LCP: AuthProto PAP (0x0304C023)
Jul 17 17:22:31: Vi1349 LCP: MagicNumber 0x0E319A2F (0x05060E319A2F)
Jul 17 17:22:31: Vi1349 LCP: State is Open
Jul 17 17:22:31: Vi1349 PPP: Phase is AUTHENTICATING, by this end [0 sess,
2516 load]
Jul 17 17:22:31: Vi1349 PAP: I AUTH-REQ id 28 len 23 from "shannonvb"
Jul 17 17:22:31: Vi1349 PPP: Phase is FORWARDING [0 sess, 2516 load]
Jul 17 17:22:31: Vi1349 PPP: Phase is AUTHENTICATING [0 sess, 2516 load]
Jul 17 17:22:36: Vi1349 PPP: Replace PAP code 1 id 29 with id 30
Jul 17 17:22:39: Vi1349 PPP: Replace PAP code 1 id 30 with id 31
Jul 17 17:22:42: Vi1349 PPP: Replace PAP code 1 id 31 with id 32
Jul 17 17:22:45: Vi1349 PPP: Replace PAP code 1 id 32 with id 33
Jul 17 17:22:46: Vi1349 PAP: Authenticating peer shannonvb
Jul 17 17:22:46: Vi1349 PAP: O AUTH-ACK id 28 len 5
Jul 17 17:22:46: Vi1349 PPP: Phase is UP [0 sess, 3321 load]
Jul 17 17:22:46: Vi1349 IPCP: O CONFREQ [Closed] id 52 len 10
Jul 17 17:22:46: Vi1349 IPCP: Address 207.177.103.1 (0x0306CFB16701)
Jul 17 17:22:49: Vi1349 PPP: Replace IPCP code 1 id 7 with id 7
Jul 17 17:22:52: Vi1349 PPP: Replace IPCP code 1 id 7 with id 7
Jul 17 17:22:58: Vi1349 PPP: Replace LCP code 5 id 55 with id 56
Jul 17 17:23:06: Vi1349 PAP: I AUTH-REQ id 33 len 23 from "shannonvb"
Jul 17 17:23:06: Vi1349 PAP: Resending Auth-Ack
Jul 17 17:23:06: Vi1349 PAP: O AUTH-ACK id 33 len 5
Jul 17 17:23:07: Vi1349 PPP: Replace LCP code 1 id 57 with id 57
Jul 17 17:23:07: Vi1349 LCP: echo_cnt 2, sent id 3, line up
Jul 17 17:23:10: Vi1349 PPP: Replace LCP code 1 id 57 with id 57
Jul 17 17:23:17: Vi1349 LCP: echo_cnt 3, sent id 4, line up
Jul 17 17:23:18: Vi1349 IPCP: I CONFREQ [REQsent] id 7 len 28
Jul 17 17:23:18: Vi1349 IPCP: Address 0.0.0.0 (0x030600000000)
Jul 17 17:23:18: Vi1349 IPCP: CompressType VJ 15 slots CompressSlotID
(0x0206002D0F01)
Jul 17 17:23:18: Vi1349 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
Jul 17 17:23:18: Vi1349 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
Jul 17 17:23:18: Vi1349 AAA/AUTHOR/IPCP: Start. Her address 0.0.0.0, we
want 0.0.0.0
Jul 17 17:23:18: Vi1349 AAA/AUTHOR/IPCP: Done. Her address 0.0.0.0, we want
207.177.99.97
Jul 17 17:23:18: Vi1349 IPCP: O CONFREJ [REQsent] id 7 len 10
Jul 17 17:23:18: Vi1349 IPCP: CompressType VJ 15 slots CompressSlotID
(0x0206002D0F01)
Jul 17 17:23:18: Vi1349 IPCP: I CONFACK [REQsent] id 52 len 10
Jul 17 17:23:18: Vi1349 IPCP: Address 207.177.103.1 (0x0306CFB16701)
Jul 17 17:23:19: Vi1349 PPP: Replace LCP code 1 id 58 with id 58
Jul 17 17:23:22: Vi1349 PPP: Replace LCP code 1 id 58 with id 58
Jul 17 17:23:26: Vi1349 LCP: I TERMREQ [Open] id 56 len 32
Jul 17 17:23:26: Vi1349 LCP: (0x4E6F206E6574776F726B2070726F746F)
Jul 17 17:23:26: Vi1349 LCP: (0x636F6C732072756E6E696E67)
Jul 17 17:23:26: Vi1349 LCP: O TERMACK [Open] id 56 len 4
Jul 17 17:23:26: Vi1349 IPCP: State is Closed
Jul 17 17:23:26: Vi1349 PPP: Phase is TERMINATING [0 sess, 3064 load]
Jul 17 17:23:27: Vi1349 LCP: Interface transitioned, discarding packet
Jul 17 17:23:27: Vi1349 LCP: Interface transitioned, discarding packet
Jul 17 17:23:28: Vi1349 LCP: I CONFREQ [TERMsent] id 59 len 10
Jul 17 17:23:28: Vi1349 LCP: MagicNumber 0x96843D9B (0x050696843D9B)
Jul 17 17:23:28: Vi1349 LCP: Dropping packet, state is TERMsent
Jul 17 17:23:34: Vi1349 PPP: Replace LCP code 1 id 59 with id 59
Jul 17 17:23:34: Vi1349 LCP: I CONFREQ [TERMsent] id 59 len 10
Jul 17 17:23:34: Vi1349 LCP: MagicNumber 0x96843D9B (0x050696843D9B)
Jul 17 17:23:34: Vi1349 LCP: Dropping packet, state is TERMsent
Jul 17 17:23:39: Vi1349 LCP: TIMEout: State TERMsent
Jul 17 17:23:39: Vi1349 LCP: State is Closed
Jul 17 17:23:39: Vi1349 PPP: Phase is DOWN [0 sess, 43 load]
============================================================================
========
Good
============================================================================
========
Jul 17 16:20:33: Vi1349 PPP: Phase is ESTABLISHING, Active Open [0 sess, 1
load]
Jul 17 16:20:33: Vi1349 LCP: O CONFREQ [Closed] id 79 len 14
Jul 17 16:20:33: Vi1349 LCP: AuthProto PAP (0x0304C023)
Jul 17 16:20:33: Vi1349 LCP: MagicNumber 0x0DF5A9AB (0x05060DF5A9AB)
Jul 17 16:20:33: Vi1349 LCP: I CONFREQ [REQsent] id 37 len 10
Jul 17 16:20:33: Vi1349 LCP: MagicNumber 0xEA364E14 (0x0506EA364E14)
Jul 17 16:20:33: Vi1349 LCP: O CONFACK [REQsent] id 37 len 10
Jul 17 16:20:33: Vi1349 LCP: MagicNumber 0xEA364E14 (0x0506EA364E14)
Jul 17 16:20:33: Vi1349 LCP: I CONFACK [ACKsent] id 79 len 14
Jul 17 16:20:33: Vi1349 LCP: AuthProto PAP (0x0304C023)
Jul 17 16:20:33: Vi1349 LCP: MagicNumber 0x0DF5A9AB (0x05060DF5A9AB)
Jul 17 16:20:33: Vi1349 LCP: State is Open
Jul 17 16:20:33: Vi1349 PPP: Phase is AUTHENTICATING, by this end [0 sess,
19 load]
Jul 17 16:20:33: Vi1349 PAP: I AUTH-REQ id 215 len 23 from "shannonvb"
Jul 17 16:20:33: Vi1349 PPP: Phase is FORWARDING [0 sess, 20 load]
Jul 17 16:20:33: Vi1349 PPP: Phase is AUTHENTICATING [0 sess, 20 load]
Jul 17 16:20:33: Vi1349 PAP: Authenticating peer shannonvb
Jul 17 16:20:34: Vi1349 PAP: O AUTH-ACK id 215 len 5
Jul 17 16:20:34: Vi1349 PPP: Phase is UP [0 sess, 7 load]
Jul 17 16:20:34: Vi1349 IPCP: O CONFREQ [Closed] id 35 len 10
Jul 17 16:20:34: Vi1349 IPCP: Address 207.177.103.1 (0x0306CFB16701)
Jul 17 16:20:34: Vi1349 IPCP: I CONFREQ [REQsent] id 38 len 28
Jul 17 16:20:34: Vi1349 IPCP: Address 0.0.0.0 (0x030600000000)
Jul 17 16:20:34: Vi1349 IPCP: CompressType VJ 15 slots CompressSlotID
(0x0206002D0F01)
Jul 17 16:20:34: Vi1349 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
Jul 17 16:20:34: Vi1349 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
Jul 17 16:20:34: Vi1349 AAA/AUTHOR/IPCP: Start. Her address 0.0.0.0, we
want 0.0.0.0
Jul 17 16:20:34: Vi1349 AAA/AUTHOR/IPCP: Done. Her address 0.0.0.0, we want
207.177.99.97
Jul 17 16:20:34: Vi1349 IPCP: O CONFREJ [REQsent] id 38 len 10
Jul 17 16:20:34: Vi1349 IPCP: CompressType VJ 15 slots CompressSlotID
(0x0206002D0F01)
Jul 17 16:20:34: Vi1349 IPCP: I CONFACK [REQsent] id 35 len 10
Jul 17 16:20:34: Vi1349 IPCP: Address 207.177.103.1 (0x0306CFB16701)
Jul 17 16:20:34: Vi1349 IPCP: I CONFREQ [ACKrcvd] id 39 len 22
Jul 17 16:20:34: Vi1349 IPCP: Address 0.0.0.0 (0x030600000000)
Jul 17 16:20:34: Vi1349 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
Jul 17 16:20:34: Vi1349 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
Jul 17 16:20:34: Vi1349 AAA/AUTHOR/IPCP: Start. Her address 0.0.0.0, we
want 207.177.99.97
Jul 17 16:20:34: Vi1349 AAA/AUTHOR/IPCP: Done. Her address 0.0.0.0, we want
207.177.99.97
Jul 17 16:20:34: Vi1349 IPCP: O CONFNAK [ACKrcvd] id 39 len 22
Jul 17 16:20:34: Vi1349 IPCP: Address 207.177.99.97 (0x0306CFB16361)
Jul 17 16:20:34: Vi1349 IPCP: PrimaryDNS 199.120.69.1 (0x8106C7784501)
Jul 17 16:20:34: Vi1349 IPCP: SecondaryDNS 167.142.225.5 (0x8306A78EE105)
Jul 17 16:20:34: Vi1349 IPCP: I CONFREQ [ACKrcvd] id 40 len 22
Jul 17 16:20:34: Vi1349 IPCP: Address 207.177.99.97 (0x0306CFB16361)
Jul 17 16:20:34: Vi1349 IPCP: PrimaryDNS 199.120.69.1 (0x8106C7784501)
Jul 17 16:20:34: Vi1349 IPCP: SecondaryDNS 167.142.225.5 (0x8306A78EE105)
Jul 17 16:20:34: Vi1349 AAA/AUTHOR/IPCP: Start. Her address 207.177.99.97,
we want 207.177.99.97
Jul 17 16:20:34: Vi1349 AAA/AUTHOR/IPCP: Done. Her address 207.177.99.97,
we want 207.177.99.97
Jul 17 16:20:34: Vi1349 IPCP: O CONFACK [ACKrcvd] id 40 len 22
Jul 17 16:20:34: Vi1349 IPCP: Address 207.177.99.97 (0x0306CFB16361)
Jul 17 16:20:34: Vi1349 IPCP: PrimaryDNS 199.120.69.1 (0x8106C7784501)
Jul 17 16:20:34: Vi1349 IPCP: SecondaryDNS 167.142.225.5 (0x8306A78EE105)
Jul 17 16:20:34: Vi1349 IPCP: State is Open
Jul 17 16:20:34: Vi1349 IPCP: Install route to 207.177.99.97
More information about the cisco-bba
mailing list