[cisco-nas] Disco after apparently successful connect.
Joe Mays
jfmays at launchpad.win.net
Fri Dec 31 14:16:24 EST 2010
Hello. Dealing with a problem that is mysterious to me, but not to
someone more knowledgeable, I expect.
I have a cisco 7206 that is configured to accept PPPoE requests from
comtrend DSL modems. The modem's are connection through a VLAN running
through a Zhone Bitstorm DSL switch. Everything about the PPP
authentication seems to work, then immediately at the end, right after
IPCP UP, the cisco (I think, but it's possible that it's a response to
the modem) seems to send a software request for a disconnect. That is
to say, it looks like everything about the process succeeds, then the
cisco seems to just "hang up".
Show ver info for the 7206 is attached to the end of this message. If
there is anything else I can offer, like config snippets or something,
I'm happy to do so.
Here are the things I am debugging. If there is anything else I can
debug, please let me know.
gw1.armplc#show debug
Generic IP:
IP peer address activity debugging is on
PPP:
PPP event debugging is on
PPP detailed event debugging is on
PPP authentication debugging is on
PPP protocol errors debugging is on
PPP protocol negotiation debugging is on
PPP packet display debugging is on
Radius protocol debugging is on
Radius packet protocol (authentication) debugging is on
Here is the output.
*Dec 31 11:02:44.866: EVT: Dynamic Bind 0 0x646FDB30
*Dec 31 11:02:44.866: ppp927 PPP: Send Message[Dynamic Bind Response]
*Dec 31 11:02:44.866: ppp927 EVT: Bound 4 0x00000000
*Dec 31 11:02:44.866: ppp927 PPP: Using default call direction
*Dec 31 11:02:44.866: ppp927 PPP: Treating connection as a dedicated
line
*Dec 31 11:02:44.866: ppp927 PPP: Session handle[10000F00] Session
id[927]
*Dec 31 11:02:44.866: ppp927 PPP: Phase is ESTABLISHING, Active Open
*Dec 31 11:02:44.866: ppp927 PPP: Authorization required
*Dec 31 11:02:44.866: ppp927 LCP: O CONFREQ [Closed] id 1 len 18
*Dec 31 11:02:44.866: ppp927 LCP: MRU 1400 (0x01040578)
*Dec 31 11:02:44.866: ppp927 LCP: AuthProto PAP (0x0304C023)
*Dec 31 11:02:44.866: ppp927 LCP: MagicNumber 0x7BBB1377
(0x05067BBB1377)
*Dec 31 11:02:44.922: ppp927 EVT: Packet 0 0x63BCEC40
*Dec 31 11:02:44.922: ppp927 LCP: I CONFREQ [REQsent] id 220 len 10
*Dec 31 11:02:44.922: ppp927 LCP: MagicNumber 0x5CBE21FE
(0x05065CBE21FE)
*Dec 31 11:02:44.922: ppp927 LCP: O CONFACK [REQsent] id 220 len 10
*Dec 31 11:02:44.922: ppp927 LCP: MagicNumber 0x5CBE21FE
(0x05065CBE21FE)
*Dec 31 11:02:46.862: ppp927 LCP: TIMEout: State ACKsent
*Dec 31 11:02:46.862: ppp927 LCP: O CONFREQ [ACKsent] id 2 len 18
*Dec 31 11:02:46.862: ppp927 LCP: MRU 1400 (0x01040578)
*Dec 31 11:02:46.862: ppp927 LCP: AuthProto PAP (0x0304C023)
*Dec 31 11:02:46.862: ppp927 LCP: MagicNumber 0x7BBB1377
(0x05067BBB1377)
*Dec 31 11:02:46.882: ppp927 EVT: Packet 0 0x63203BD4
*Dec 31 11:02:46.882: ppp927 LCP: I CONFACK [ACKsent] id 2 len 18
*Dec 31 11:02:46.882: ppp927 LCP: MRU 1400 (0x01040578)
*Dec 31 11:02:46.882: ppp927 LCP: AuthProto PAP (0x0304C023)
*Dec 31 11:02:46.882: ppp927 LCP: MagicNumber 0x7BBB1377
(0x05067BBB1377)
*Dec 31 11:02:46.882: ppp927 LCP: State is Open
*Dec 31 11:02:46.882: ppp927 PPP: Phase is AUTHENTICATING, by this end
*Dec 31 11:02:46.882: ppp927 EVT: Packet 0 0x63BD071C
*Dec 31 11:02:46.882: ppp927 LCP: I ECHOREQ [Open] id 0 len 8 magic
0x5CBE21FE
*Dec 31 11:02:46.882: ppp927 LCP: O ECHOREP [Open] id 0 len 8 magic
0x7BBB1377
*Dec 31 11:02:46.886: ppp927 EVT: Auth Packet 0 0x63202CE8
*Dec 31 11:02:46.886: ppp927 PAP: I AUTH-REQ id 240 len 27 from
"dennis at win.net"
*Dec 31 11:02:46.886: ppp927 PAP: Authenticating peer dennis at win.net
*Dec 31 11:02:46.886: ppp927 PPP: Phase is FORWARDING, Attempting
Forward
*Dec 31 11:02:46.886: ppp927 EVT: Hook 1 0x00000000
*Dec 31 11:02:46.886: ppp927 EVT: Hook 1 0x00000000
*Dec 31 11:02:46.886: ppp927 EVT: Forwarded 0 0x00000000
*Dec 31 11:02:46.886: ppp927 PPP: Phase is AUTHENTICATING,
Unauthenticated User
*Dec 31 11:02:46.886: ppp927 PPP: Sent PAP LOGIN Request
*Dec 31 11:02:46.886: RADIUS/ENCODE(000022C0):Orig. component type =
PPoE
*Dec 31 11:02:46.886: RADIUS(000022C0): Storing nasport 16384 in
rad_db
*Dec 31 11:02:46.886: RADIUS(000022C0): Config NAS IP: 216.24.30.16
*Dec 31 11:02:46.886: RADIUS/ENCODE(000022C0): acct_session_id: 8896
*Dec 31 11:02:46.886: RADIUS(000022C0): sending
*Dec 31 11:02:46.886: RADIUS(000022C0): Send Access-Request to
216.24.27.201:1645 id 1645/7, len 140
*Dec 31 11:02:46.886: RADIUS: authenticator 98 0F 01 F2 C1 C5 80 14 -
AC 72 87 38 5B 67 68 38
*Dec 31 11:02:46.886: RADIUS: Vendor, Cisco [26] 41
*Dec 31 11:02:46.886: RADIUS: Cisco AVpair [1] 35
"client-mac-address=6468.0cbe.d481"
*Dec 31 11:02:46.886: RADIUS: Framed-Protocol [7] 6 PPP
[1]
*Dec 31 11:02:46.886: RADIUS: User-Name [1] 16
"dennis at win.net"
*Dec 31 11:02:46.886: RADIUS: User-Password [2] 18 *
*Dec 31 11:02:46.886: RADIUS: NAS-Port-Type [61] 6 Virtual
[5]
*Dec 31 11:02:46.886: RADIUS: Vendor, Cisco [26] 15
*Dec 31 11:02:46.886: RADIUS: cisco-nas-port [2] 9 "1/0/0/2"
*Dec 31 11:02:46.886: RADIUS: NAS-Port [5] 6 16384
*Dec 31 11:02:46.886: RADIUS: Service-Type [6] 6 Framed
[2]
*Dec 31 11:02:46.886: RADIUS: NAS-IP-Address [4] 6
216.24.30.16
*Dec 31 11:02:46.890: RADIUS: Received from id 1645/7
216.24.27.201:1645, Access-Accept, len 88
*Dec 31 11:02:46.890: RADIUS: authenticator 08 D1 82 50 B2 19 AA 42 -
D4 E2 E1 99 52 70 1E 7B
*Dec 31 11:02:46.890: RADIUS: Framed-MTU [12] 6 1492
*Dec 31 11:02:46.890: RADIUS: Filter-Id [11] 21
*Dec 31 11:02:46.890: RADIUS: 69 6E 2D 62 6C 6F 63 6B 2D 73 6D 74 70
2D 6E 62 [in-block-smtp-nb]
*Dec 31 11:02:46.890: RADIUS: 2E 69 6E
[.in]
*Dec 31 11:02:46.890: RADIUS: Filter-Id [11] 23
*Dec 31 11:02:46.890: RADIUS: 6F 75 74 2D 62 6C 6F 63 6B 2D 73 6D 74
70 2D 6E [out-block-smtp-n]
*Dec 31 11:02:46.890: RADIUS: 62 2E 6F 75 74
[b.out]
*Dec 31 11:02:46.890: RADIUS: Framed-IP-Address [8] 6
255.255.255.254
*Dec 31 11:02:46.890: RADIUS: Framed-Protocol [7] 6 PPP
[1]
*Dec 31 11:02:46.890: RADIUS: Service-Type [6] 6 Framed
[2]
*Dec 31 11:02:46.894: RADIUS(000022C0): Received from id 1645/7
*Dec 31 11:02:46.894: ppp927 EVT: AAA Response 0 0x63EFC6F0
*Dec 31 11:02:46.894: ppp927 PPP: Received LOGIN Response PASS
*Dec 31 11:02:46.894: ppp927 PPP: Phase is FORWARDING, Attempting
Forward
*Dec 31 11:02:46.894: ppp927 EVT: Hook 1 0x00000000
*Dec 31 11:02:46.894: ppp927 PPP: Send Message[Connect Local]
*Dec 31 11:02:46.894: EVT: Static Bind 0 0x646FDB30
*Dec 31 11:02:46.894: ppp927 PPP: Bind to [Virtual-Access1.1]
*Dec 31 11:02:46.894: Vi1.1 PPP: Send Message[Static Bind Response]
*Dec 31 11:02:46.894: Vi1.1 EVT: Hook 1 0x00000000
*Dec 31 11:02:46.894: Vi1.1 EVT: Forwarded 0 0x00000000
*Dec 31 11:02:46.894: Vi1.1 PPP: Phase is AUTHENTICATING,
Authenticated User
*Dec 31 11:02:46.894: Vi1.1 PPP: Sent LCP AUTHOR Request
*Dec 31 11:02:46.894: Vi1.1 PPP: Sent IPCP AUTHOR Request
*Dec 31 11:02:46.894: RADIUS/ENCODE(000022C0): send packet; PASS
*Dec 31 11:02:46.894: RADIUS/ENCODE(000022C0): send packet; PASS
*Dec 31 11:02:46.894: Vi1.1 EVT: AAA Response 0 0x63E5555C
*Dec 31 11:02:46.894: Vi1.1 LCP: Received AAA AUTHOR Response PASS
*Dec 31 11:02:46.894: Vi1.1 EVT: AAA Response 0 0x645AE5F8
*Dec 31 11:02:46.898: Vi1.1 IPCP: Received AAA AUTHOR Response PASS
*Dec 31 11:02:46.898: Vi1.1 PAP: O AUTH-ACK id 240 len 5
*Dec 31 11:02:46.898: Vi1.1 PPP: Phase is UP
*Dec 31 11:02:46.898: Vi1.1 IPCP: O CONFREQ [Closed] id 1 len 10
*Dec 31 11:02:46.898: Vi1.1 IPCP: Address 216.24.12.193
(0x0306D8180CC1)
*Dec 31 11:02:46.898: Vi1.1 PPP: Process pending ncp packets
*Dec 31 11:02:46.918: Vi1.1 PPP: I pkt type 0x8021, datagramsize 24
link[ip]
*Dec 31 11:02:46.918: Vi1.1 EVT: IPCP Packet 0 0x63BCF238
*Dec 31 11:02:46.918: Vi1.1 IPCP: I CONFREQ [REQsent] id 208 len 22
*Dec 31 11:02:46.918: Vi1.1 IPCP: Address 0.0.0.0 (0x030600000000)
*Dec 31 11:02:46.918: Vi1.1 IPCP: PrimaryDNS 0.0.0.0
(0x810600000000)
*Dec 31 11:02:46.918: Vi1.1 IPCP: SecondaryDNS 0.0.0.0
(0x830600000000)
*Dec 31 11:02:46.918: Vi1.1 AAA/AUTHOR/IPCP: Start. Her address
0.0.0.0, we want 0.0.0.0
*Dec 31 11:02:46.918: Vi1.1 AAA/AUTHOR/IPCP: No remote address; FIP
says use address pool
*Dec 31 11:02:46.918: Vi1.1 AAA/AUTHOR/IPCP: Done. Her address
0.0.0.0, we want 0.0.0.0
*Dec 31 11:02:46.918: Vi1.1 PPP: I pkt type 0x8021, datagramsize 12
link[ip]
*Dec 31 11:02:46.918: Vi1.1: Pools to search : pppoepool
*Dec 31 11:02:46.918: Vi1.1: Invoking POOL_GET: pppoepool
*Dec 31 11:02:46.918: Vi1.1: Returned from POOL_GET: pppoepool
*Dec 31 11:02:46.918: Vi1.1: Pool pppoepool returned address =
216.24.12.100
*Dec 31 11:02:46.918: Vi1.1 IPCP: Pool returned 216.24.12.100
*Dec 31 11:02:46.918: Vi1.1 IPCP: O CONFNAK [REQsent] id 208 len 22
*Dec 31 11:02:46.918: Vi1.1 IPCP: Address 216.24.12.100
(0x0306D8180C64)
*Dec 31 11:02:46.918: Vi1.1 IPCP: PrimaryDNS 216.24.27.3
(0x8106D8181B03)
*Dec 31 11:02:46.918: Vi1.1 IPCP: SecondaryDNS 24.235.0.25
(0x830618EB0019)
*Dec 31 11:02:46.918: Vi1.1 EVT: IPCP Packet 0 0x63BCFE28
*Dec 31 11:02:46.918: Vi1.1 IPCP: I CONFACK [REQsent] id 1 len 10
*Dec 31 11:02:46.918: Vi1.1 IPCP: Address 216.24.12.193
(0x0306D8180CC1)
*Dec 31 11:02:47.274: Vi1.1 PPP: I pkt type 0x8021, datagramsize 24
link[ip]
*Dec 31 11:02:47.274: Vi1.1 EVT: IPCP Packet 0 0x63202FE4
*Dec 31 11:02:47.274: Vi1.1 IPCP: I CONFREQ [ACKrcvd] id 209 len 22
*Dec 31 11:02:47.274: Vi1.1 IPCP: Address 216.24.12.100
(0x0306D8180C64)
*Dec 31 11:02:47.274: Vi1.1 IPCP: PrimaryDNS 216.24.27.3
(0x8106D8181B03)
*Dec 31 11:02:47.274: Vi1.1 IPCP: SecondaryDNS 24.235.0.25
(0x830618EB0019)
*Dec 31 11:02:47.274: Vi1.1 IPCP: O CONFACK [ACKrcvd] id 209 len 22
*Dec 31 11:02:47.274: Vi1.1 IPCP: Address 216.24.12.100
(0x0306D8180C64)
*Dec 31 11:02:47.274: Vi1.1 IPCP: PrimaryDNS 216.24.27.3
(0x8106D8181B03)
*Dec 31 11:02:47.274: Vi1.1 IPCP: SecondaryDNS 24.235.0.25
(0x830618EB0019)
*Dec 31 11:02:47.274: Vi1.1 IPCP: State is Open
*Dec 31 11:02:47.274: Vi1.1 EVT: IPCP UP 0 0x647AC0D0
*Dec 31 11:02:47.274: Vi1.1 EVT: Soft Disc 0 0x00000000
*Dec 31 11:02:47.274: Vi1.1 PPP: Sending Acct Event[Down] id[22C0]
*Dec 31 11:02:47.274: Vi1.1 IPCP: State is Closed
*Dec 31 11:02:47.274: Vi1.1 set_ip_peer(0): new address
*Dec 31 11:02:47.274: ip_free_pool: Vi1.1: address = 216.24.12.100 (2)
*Dec 31 11:02:47.274: Vi1.1: Invoking POOL_FREE for 216.24.12.100
*Dec 31 11:02:47.278: Vi1.1: Returned from POOL_FREE for
216.24.12.1000.0.0.0
*Dec 31 11:02:47.278: Vi1.1 PPP: Phase is TERMINATING
*Dec 31 11:02:47.278: Vi1.1 LCP: O TERMREQ [Open] id 3 len 4
*Dec 31 11:02:47.278: Vi1.1 EVT: Cleanup IP 0 0x00000000
*Dec 31 11:02:48.106: Vi1.1 PPP: I pkt type 0xC021, datagramsize 6
link[ppp]
*Dec 31 11:02:48.106: Vi1.1 EVT: Packet 0 0x63BCEF3C
*Dec 31 11:02:48.106: Vi1.1 LCP: I TERMACK [TERMsent] id 3 len 4
*Dec 31 11:02:48.106: Vi1.1 LCP: State is Closed
*Dec 31 11:02:48.106: Vi1.1 PPP: Phase is DOWN
*Dec 31 11:02:48.106: Vi1.1 PPP: Send Message[Disconnect]
Show ver info....
Cisco Internetwork Operating System Software
IOS (tm) 7200 Software (C7200-IS-M), Version 12.3(16), RELEASE
SOFTWARE (fc4)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2005 by cisco Systems, Inc.
Compiled Tue 23-Aug-05 22:49 by ssearch
Image text-base: 0x60008AF4, data-base: 0x61CC0000
ROM: System Bootstrap, Version 12.1(20000710:044039) [nlaw-121E_npeb
117], DEVELOPMENT SOFTWARE
BOOTLDR: 7200 Software (C7200-IS-M), Version 12.3(16), RELEASE
SOFTWARE (fc4)
gw1.armplc uptime is 3 weeks, 16 hours, 43 minutes
System returned to ROM by reload at 18:17:39 UTC Thu Dec 9 2010
System image file is "slot0:c7200-is-mz.123-16.bin"
Last reload reason: Reload command
cisco 7206VXR (NPE400) processor (revision A) with 491520K/32768K
bytes of memory.
Processor board ID 29496245
R7000 CPU at 350MHz, Implementation 39, Rev 3.2, 256KB L2 Cache
6 slot VXR midplane, Version 2.7
Last reset from power-on
Bridging software.
X.25 software, Version 3.0.0.
Primary Rate ISDN software, Version 1.1.
PCI bus mb0_mb1 (Slots 0, 1, 3 and 5) has a capacity of 600 bandwidth
points.
Current configuration on bus mb0_mb1 has a total of 470 bandwidth
points.
This configuration is within the PCI bus capacity and is supported.
PCI bus mb2 (Slots 2, 4, 6) has a capacity of 600 bandwidth points.
Current configuration on bus mb2 has a total of 380 bandwidth points
This configuration is within the PCI bus capacity and is supported.
Please refer to the following document "Cisco 7200 Series Port
Adaptor Hardware Configuration Guidelines" on CCO <www.cisco.com>,
for c7200 bandwidth points oversubscription/usage guidelines.
2 FastEthernet/IEEE 802.3 interface(s)
3 Serial network interface(s)
1 ATM network interface(s)
1 Channelized T3 port(s)
125K bytes of non-volatile configuration memory.
20480K bytes of Flash PCMCIA card at slot 0 (Sector size 128K).
4096K bytes of Flash internal SIMM (Sector size 256K).
Configuration register is 0x2102
--
"Perhaps you stared into a river. There was somebody near you who
loved you. They were about to touch you. You could feel this before it
happened. Then it happened."
-- Richard Brautigan, "In Watermelon Sugar"
More information about the cisco-nas
mailing list