[cisco-nas] Disco after apparently successful connect.

Aaron Leonard Aaron at Cisco.COM
Mon Jan 3 10:53:05 EST 2011 

Hm.  Might be an issue with some of the RADIUS attributes.
Please add "debug aaa authorization", "debug sss events",
"debug sss aaa authorization events".

Maybe the access lists?  (in-block-smtp-nb and out-block-smtp-n)

----

On 12/31/2010 12:16 PM, jfmays at launchpad.win.net (Joe Mays) wrote:
> 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"
>
> _______________________________________________
> cisco-nas mailing list
> cisco-nas at puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-nas

More information about the cisco-nas mailing list