[cisco-nas] Disco after apparently successful connect.
Aaron Leonard
Aaron at Cisco.COM
Mon Jan 3 12:40:01 EST 2011
Well I think that's your problem. Your RADIUS server is sending
down attributes that say to use filters called "in-block-smtp-nb"
and "out-block-smtp-n", but your router doesn't have any such
filters defined.
So either add the ACLs on the router, or reconfigure the RADIUS
server not to send these attributes, or I guess you could turn
off AAA authorization, if you don't want to honor the per-user attributes.
(maybe "debug aaa per-user" is the missing one that would say
for sure?)
Hth,
Aaron
----
On 1/3/2011 10:22 AM, jfmays at launchpad.win.net (Joe Mays) wrote:
>> Hm. Might be an issue with some of the RADIUS attributes.
>> Please add "debug aaa authorization", "debug sss events",
>> "debug sss aaa authorization events".
>
> I tried that. Will attach the results to this message.
>
>> Maybe the access lists? (in-block-smtp-nb and out-block-smtp-n)
>
> I only have one access list on the box at the moment, that is
> referenced by OSPF.
>
> ip access-list standard allow-our-nets
> permit 216.24.0.0 0.0.63.255
> permit 24.235.0.0 0.0.31.255
>
> So now....
>
> gw1.armplc#show debug
> General OS:
> AAA Authorization debugging is on
> Generic IP:
> IP peer address activity debugging is on
> SSS:
> SSS events debugging is on
> SSS AAA authorization event 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
>
>
> *Jan 3 09:16:29.906: AAA/BIND(0000263F): Bind i/f Virtual-Template1
> *Jan 3 09:16:29.906: SSS INFO: Element type is Access-Type, long
> value is 3
> *Jan 3 09:16:29.906: SSS INFO: Element type is Switch-Id, long value
> is -872413686
> *Jan 3 09:16:29.906: SSS INFO: Element type is Nasport, ptr value is
> 64787528
> *Jan 3 09:16:29.906: SSS INFO: Element type is AAA-Id, long value is
> 9791
> *Jan 3 09:16:29.906: SSS INFO: Element type is AAA-ACCT_ENBL, long
> value is 1
> *Jan 3 09:16:29.906: SSS INFO: Element type is AccIe-Hdl, ptr value
> is 3400060A
> *Jan 3 09:16:29.906: SSS MGR [uid:730]: Handling Policy Authorize (1
> pending sessions)
> *Jan 3 09:16:29.910: SSS PM [uid:730]: RM/VPDN disabled: RM/VPDN
> author not needed
> *Jan 3 09:16:29.910: SSS PM [uid:730]: VPDN disabled: AAA author not
> needed
> *Jan 3 09:16:29.910: SSS PM [uid:730]: SGBP disabled: SGF author not
> needed
> *Jan 3 09:16:29.910: SSS PM [uid:730]: No more authorization methods
> left to try, providing default service
> *Jan 3 09:16:29.910: SSS PM [uid:730]: Received Service Request
> *Jan 3 09:16:29.910: SSS PM [uid:730]: Handling Service Direction
> *Jan 3 09:16:29.910: SSS PM [uid:730]: Policy reply - Local terminate
> *Jan 3 09:16:29.910: SSS MGR [uid:730]: Got reply Local-Term from PM
> *Jan 3 09:16:29.910: SSS MGR [uid:730]: Handling
> Send-Client-Local-Term event
> *Jan 3 09:16:29.910: EVT: Dynamic Bind 0 0x64771914
> *Jan 3 09:16:29.910: ppp730 PPP: Send Message[Dynamic Bind Response]
> *Jan 3 09:16:29.910: ppp730 EVT: Bound 4 0x00000000
> *Jan 3 09:16:29.910: ppp730 PPP: Using default call direction
> *Jan 3 09:16:29.910: ppp730 PPP: Treating connection as a dedicated
> line
> *Jan 3 09:16:29.910: ppp730 PPP: Session handle[600060E] Session
> id[730]
> *Jan 3 09:16:29.910: ppp730 PPP: Phase is ESTABLISHING, Active Open
> *Jan 3 09:16:29.910: ppp730 PPP: Authorization required
> *Jan 3 09:16:29.910: ppp730 AAA/AUTHOR/LCP: Authorization succeeds
> trivially
> gw1.armplc#
> *Jan 3 09:16:29.910: ppp730 LCP: O CONFREQ [Closed] id 1 len 18
> *Jan 3 09:16:29.910: ppp730 LCP: MRU 1400 (0x01040578)
> *Jan 3 09:16:29.910: ppp730 LCP: AuthProto PAP (0x0304C023)
> *Jan 3 09:16:29.910: ppp730 LCP: MagicNumber 0x10D68438
> (0x050610D68438)
> *Jan 3 09:16:29.962: ppp730 EVT: Packet 0 0x63BD0360
> *Jan 3 09:16:29.962: ppp730 LCP: I CONFREQ [REQsent] id 165 len 10
> *Jan 3 09:16:29.962: ppp730 LCP: MagicNumber 0x53652626
> (0x050653652626)
> *Jan 3 09:16:29.962: ppp730 LCP: O CONFACK [REQsent] id 165 len 10
> *Jan 3 09:16:29.962: ppp730 LCP: MagicNumber 0x53652626
> (0x050653652626)
> gw1.armplc#
> *Jan 3 09:16:31.910: ppp730 LCP: TIMEout: State ACKsent
> *Jan 3 09:16:31.910: ppp730 LCP: O CONFREQ [ACKsent] id 2 len 18
> *Jan 3 09:16:31.910: ppp730 LCP: MRU 1400 (0x01040578)
> *Jan 3 09:16:31.910: ppp730 LCP: AuthProto PAP (0x0304C023)
> *Jan 3 09:16:31.910: ppp730 LCP: MagicNumber 0x10D68438
> (0x050610D68438)
> *Jan 3 09:16:31.930: ppp730 EVT: Packet 0 0x63203BD4
> *Jan 3 09:16:31.930: ppp730 LCP: I CONFACK [ACKsent] id 2 len 18
> *Jan 3 09:16:31.930: ppp730 LCP: MRU 1400 (0x01040578)
> *Jan 3 09:16:31.930: ppp730 LCP: AuthProto PAP (0x0304C023)
> *Jan 3 09:16:31.930: ppp730 LCP: MagicNumber 0x10D68438
> (0x050610D68438)
> *Jan 3 09:16:31.930: ppp730 LCP: State is Open
> *Jan 3 09:16:31.930: ppp730 PPP: Phase is AUTHENTICATING, by this end
> *Jan 3 09:16:31.930: ppp730 EVT: Packet 0 0x632041CC
> *Jan 3 09:16:31.930: ppp730 LCP: I ECHOREQ [Open] id 0 len 8 magic
> 0x53652626
> *Jan 3 09:16:31.930: ppp730 LCP: O ECHOREP [Open] id 0 len 8 magic
> 0x10D68438
> *Jan 3 09:16:31.930: ppp730 EVT: Auth Packet 0 0x63202FE4
> *Jan 3 09:16:31.930: ppp730 PAP: I AUTH-REQ id 248 len 27 from
> "dennis at win.net"
> *Jan 3 09:16:31.930: ppp730 PAP: Authenticating peer dennis at win.net
> *Jan 3 09:16:31.930: ppp730 PPP: Phase is FORWARDING, Attempting
> Forward
> *Jan 3 09:16:31.930: ppp730 EVT: Hook 1 0x00000000
> *Jan 3 09:16:31.930: ppp730 EVT: Hook 1 0x00000000
> *Jan 3 09:16:31.930: ppp730 EVT: Forwarded 0 0x00000000
> *Jan 3 09:16:31.930: ppp730 PPP: Phase is AUTHENTICATING,
> Unauthenticated User
> *Jan 3 09:16:31.930: ppp730 PPP: Sent PAP LOGIN Request
> *Jan 3 09:16:31.934: RADIUS/ENCODE(0000263F):Orig. component type =
> PPoE
> *Jan 3 09:16:31.934: RADIUS(0000263F): Storing nasport 16384 in
> rad_db
> *Jan 3 09:16:31.934: RADIUS(0000263F): Config NAS IP: 216.24.30.16
> *Jan 3 09:16:31.934: RADIUS/ENCODE(0000263F): acct_session_id: 9791
> *Jan 3 09:16:31.934: RADIUS(0000263F): sending
> *Jan 3 09:16:31.934: RADIUS(0000263F): Send Access-Request to
> 216.24.27.201:1645 id 1645/11, len 140
> *Jan 3 09:16:31.934: RADIUS: authenticator 86 31 D9 69 38 02 D2 68 -
> F5 C1 7F 98 D3 1D F6 C3
> *Jan 3 09:16:31.934: RADIUS: Vendor, Cisco [26] 41
> *Jan 3 09:16:31.934: RADIUS: Cisco AVpair [1] 35
> "client-mac-address=6468.0cbe.d481"
> *Jan 3 09:16:31.934: RADIUS: Framed-Protocol [7] 6 PPP
> [1]
> *Jan 3 09:16:31.934: RADIUS: User-Name [1] 16
> "dennis at win.net"
> *Jan 3 09:16:31.934: RADIUS: User-Password [2] 18 *
> *Jan 3 09:16:31.934: RADIUS: NAS-Port-Type [61] 6 Virtual
> [5]
> *Jan 3 09:16:31.934: RADIUS: Vendor, Cisco [26] 15
> *Jan 3 09:16:31.934: RADIUS: cisco-nas-port [2] 9 "1/0/0/2"
> *Jan 3 09:16:31.934: RADIUS: NAS-Port [5] 6 16384
> *Jan 3 09:16:31.934: RADIUS: Service-Type [6] 6 Framed
> [2]
> *Jan 3 09:16:31.934: RADIUS: NAS-IP-Address [4] 6
> 216.24.30.16
> *Jan 3 09:16:31.938: RADIUS: Received from id 1645/11
> 216.24.27.201:1645, Access-Accept, len 88
> *Jan 3 09:16:31.938: RADIUS: authenticator 10 EB 7A 13 84 42 95 63 -
> 56 91 AF F1 C4 8D 84 8E
> *Jan 3 09:16:31.938: RADIUS: Framed-MTU [12] 6 1492
> *Jan 3 09:16:31.938: RADIUS: Filter-Id [11] 21
> *Jan 3 09:16:31.938: RADIUS: 69 6E 2D 62 6C 6F 63 6B 2D 73 6D 74 70
> 2D 6E 62 [in-block-smtp-nb]
> *Jan 3 09:16:31.938: RADIUS: 2E 69 6E
> [.in]
> *Jan 3 09:16:31.938: RADIUS: Filter-Id [11] 23
> *Jan 3 09:16:31.938: RADIUS: 6F 75 74 2D 62 6C 6F 63 6B 2D 73 6D 74
> 70 2D 6E [out-block-smtp-n]
> *Jan 3 09:16:31.938: RADIUS: 62 2E 6F 75 74
> [b.out]
> *Jan 3 09:16:31.938: RADIUS: Framed-IP-Address [8] 6
> 255.255.255.254
> *Jan 3 09:16:31.938: RADIUS: Framed-Protocol [7] 6 PPP
> [1]
> *Jan 3 09:16:31.938: RADIUS: Service-Type [6] 6 Framed
> [2]
> *Jan 3 09:16:31.938: RADIUS(0000263F): Received from id 1645/11
> *Jan 3 09:16:31.938: ppp730 EVT: AAA Response 0 0x647AD22C
> *Jan 3 09:16:31.938: ppp730 PPP: Received LOGIN Response PASS
> *Jan 3 09:16:31.938: ppp730 PPP/AAA: Check Attr: Framed-MTU
> *Jan 3 09:16:31.938: ppp730 PPP/AAA: Check Attr: inacl: Peruser
> *Jan 3 09:16:31.938: ppp730 PPP/AAA: Check Attr: outacl: Peruser
> *Jan 3 09:16:31.938: ppp730 PPP/AAA: Check Attr: addr
> *Jan 3 09:16:31.942: ppp730 PPP/AAA: Check Attr: Framed-Protocol
> *Jan 3 09:16:31.942: ppp730 PPP/AAA: Check Attr: service-type
> *Jan 3 09:16:31.942: ppp730 PPP: Phase is FORWARDING, Attempting
> Forward
> *Jan 3 09:16:31.942: ppp730 EVT: Hook 1 0x00000000
> *Jan 3 09:16:31.942: ppp730 PPP: Send Message[Connect Local]
> *Jan 3 09:16:31.942: EVT: Static Bind 0 0x64771914
> *Jan 3 09:16:31.942: ppp730 PPP: Bind to [Virtual-Access2.1]
> *Jan 3 09:16:31.942: AAA/BIND(0000263F): Bind i/f Virtual-Access2.1
> *Jan 3 09:16:31.942: Vi2.1 PPP: Send Message[Static Bind Response]
> *Jan 3 09:16:31.942: Vi2.1 EVT: Hook 1 0x00000000
> *Jan 3 09:16:31.942: Vi2.1 EVT: Forwarded 0 0x00000000
> *Jan 3 09:16:31.942: Vi2.1 PPP: Phase is AUTHENTICATING,
> Authenticated User
> *Jan 3 09:16:31.942: AAA/AUTHOR (0x263F): Pick method list 'default'
> *Jan 3 09:16:31.942: Vi2.1 PPP: Sent LCP AUTHOR Request
> *Jan 3 09:16:31.942: AAA/AUTHOR (0x263F): Pick method list 'default'
> *Jan 3 09:16:31.942: Vi2.1 PPP: Sent IPCP AUTHOR Request
> *Jan 3 09:16:31.942: RADIUS/ENCODE(0000263F): send packet; PASS
> *Jan 3 09:16:31.942: RADIUS/ENCODE(0000263F): send packet; PASS
> *Jan 3 09:16:31.942: Vi2.1 EVT: AAA Response 0 0x64786880
> *Jan 3 09:16:31.942: Vi2.1 LCP: Received AAA AUTHOR Response PASS
> *Jan 3 09:16:31.942: Vi2.1 PPP/AAA: Check Attr: Framed-MTU
> *Jan 3 09:16:31.942: Vi2.1 PPP/AAA: Check Attr: inacl: Peruser
> *Jan 3 09:16:31.942: Vi2.1 PPP/AAA: Check Attr: outacl: Peruser
> *Jan 3 09:16:31.942: Vi2.1 PPP/AAA: Check Attr: addr
> *Jan 3 09:16:31.942: Vi2.1 PPP/AAA: Check Attr: Framed-Protocol
> *Jan 3 09:16:31.942: Vi2.1 PPP/AAA: Check Attr: service-type
> *Jan 3 09:16:31.942: Vi2.1 AAA/AUTHOR/FSM: We can start LCP
> *Jan 3 09:16:31.942: Vi2.1 EVT: AAA Response 0 0x64020BA8
> *Jan 3 09:16:31.946: Vi2.1 IPCP: Received AAA AUTHOR Response PASS
> *Jan 3 09:16:31.946: Vi2.1 PPP/AAA: Check Attr: Framed-MTU
> *Jan 3 09:16:31.946: Vi2.1 PPP/AAA: Check Attr: inacl: Peruser
> *Jan 3 09:16:31.946: Vi2.1 PPP/AAA: Check Attr: outacl: Peruser
> *Jan 3 09:16:31.946: Vi2.1 PPP/AAA: Check Attr: addr
> *Jan 3 09:16:31.946: Vi2.1 PPP/AAA: Check Attr: Framed-Protocol
> *Jan 3 09:16:31.946: Vi2.1 PPP/AAA: Check Attr: service-type
> *Jan 3 09:16:31.946: Vi2.1 AAA/AUTHOR/FSM: We can start IPCP
> *Jan 3 09:16:31.946: Vi2.1 AAA/AUTHOR/LCP: Process Author
> *Jan 3 09:16:31.946: Vi2.1 AAA/AUTHOR/LCP: Process Attr: service-type
> *Jan 3 09:16:31.946: Vi2.1 AAA/AUTHOR/LCP: Process Attr: service-type
> *Jan 3 09:16:31.946: Vi2.1 PAP: O AUTH-ACK id 248 len 5
> *Jan 3 09:16:31.946: Vi2.1 PPP: Phase is UP
> *Jan 3 09:16:31.946: Vi2.1 AAA/AUTHOR/IPCP: Already authorized
> *Jan 3 09:16:31.946: Vi2.1 AAA/AUTHOR/FSM: We can start IPCP
> *Jan 3 09:16:31.946: Vi2.1 IPCP: O CONFREQ [Closed] id 1 len 10
> *Jan 3 09:16:31.946: Vi2.1 IPCP: Address 216.24.12.193
> (0x0306D8180CC1)
> *Jan 3 09:16:31.946: Vi2.1 PPP: Process pending ncp packets
> *Jan 3 09:16:32.590: Vi2.1 PPP: I pkt type 0x8021, datagramsize 24
> link[ip]
> *Jan 3 09:16:32.590: Vi2.1 PPP: I pkt type 0x8021, datagramsize 12
> link[ip]
> *Jan 3 09:16:32.590: Vi2.1 EVT: IPCP Packet 0 0x632047C4
> *Jan 3 09:16:32.590: Vi2.1 IPCP: I CONFREQ [REQsent] id 18 len 22
> *Jan 3 09:16:32.590: Vi2.1 IPCP: Address 0.0.0.0 (0x030600000000)
> *Jan 3 09:16:32.590: Vi2.1 IPCP: PrimaryDNS 0.0.0.0
> (0x810600000000)
> *Jan 3 09:16:32.590: Vi2.1 IPCP: SecondaryDNS 0.0.0.0
> (0x830600000000)
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Start. Her address
> 0.0.0.0, we want 0.0.0.0
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: No remote address; FIP
> says use address pool
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Processing AV inacl
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Processing AV outacl
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Processing AV addr
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Processing AV inacl
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Processing AV outacl
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Processing AV addr
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Authorization succeeded
> *Jan 3 09:16:32.590: Vi2.1 AAA/AUTHOR/IPCP: Done. Her address
> 0.0.0.0, we want 0.0.0.0
> *Jan 3 09:16:32.590: Vi2.1: Pools to search : pppoepool
> *Jan 3 09:16:32.590: Vi2.1: Invoking POOL_GET: pppoepool
> *Jan 3 09:16:32.590: Vi2.1: Returned from POOL_GET: pppoepool
> *Jan 3 09:16:32.590: Vi2.1: Pool pppoepool returned address =
> 216.24.12.100
> *Jan 3 09:16:32.590: Vi2.1 IPCP: Pool returned 216.24.12.100
> *Jan 3 09:16:32.594: Vi2.1 AAA/AUTHOR/IPCP: no author-info for
> primary dns
> *Jan 3 09:16:32.594: Vi2.1 AAA/AUTHOR/IPCP: no author-info for
> seconday dns
> *Jan 3 09:16:32.594: Vi2.1 IPCP: O CONFNAK [REQsent] id 18 len 22
> gw1.armplc#
> *Jan 3 09:16:32.594: Vi2.1 IPCP: Address 216.24.12.100
> (0x0306D8180C64)
> *Jan 3 09:16:32.594: Vi2.1 IPCP: PrimaryDNS 216.24.27.3
> (0x8106D8181B03)
> *Jan 3 09:16:32.594: Vi2.1 IPCP: SecondaryDNS 24.235.0.25
> (0x830618EB0019)
> *Jan 3 09:16:32.594: Vi2.1 EVT: IPCP Packet 0 0x63BCF178
> *Jan 3 09:16:32.594: Vi2.1 IPCP: I CONFACK [REQsent] id 1 len 10
> *Jan 3 09:16:32.594: Vi2.1 IPCP: Address 216.24.12.193
> (0x0306D8180CC1)
> *Jan 3 09:16:33.294: Vi2.1 PPP: I pkt type 0x8021, datagramsize 24
> link[ip]
> *Jan 3 09:16:33.294: Vi2.1 EVT: IPCP Packet 0 0x632038D8
> *Jan 3 09:16:33.294: Vi2.1 IPCP: I CONFREQ [ACKrcvd] id 19 len 22
> *Jan 3 09:16:33.294: Vi2.1 IPCP: Address 216.24.12.100
> (0x0306D8180C64)
> *Jan 3 09:16:33.294: Vi2.1 IPCP: PrimaryDNS 216.24.27.3
> (0x8106D8181B03)
> *Jan 3 09:16:33.294: Vi2.1 IPCP: SecondaryDNS 24.235.0.25
> (0x830618EB0019)
> *Jan 3 09:16:33.294: Vi2.1 AAA/AUTHOR/IPCP: no author-info for
> primary dns
> *Jan 3 09:16:33.294: Vi2.1 AAA/AUTHOR/IPCP: no author-info for
> seconday dns
> *Jan 3 09:16:33.294: Vi2.1 IPCP: O CONFACK [ACKrcvd] id 19 len 22
> *Jan 3 09:16:33.294: Vi2.1 IPCP: Address 216.24.12.100
> (0x0306D8180C64)
> *Jan 3 09:16:33.294: Vi2.1 IPCP: PrimaryDNS 216.24.27.3
> (0x8106D8181B03)
> *Jan 3 09:16:33.294: Vi2.1 IPCP: SecondaryDNS 24.235.0.25
> (0x830618EB0019)
> *Jan 3 09:16:33.294: Vi2.1 IPCP: State is Open
> *Jan 3 09:16:33.294: Vi2.1 EVT: IPCP UP 0 0x6477DFFC
> *Jan 3 09:16:33.294: AAA/AUTHOR: Processing PerUser AV inacl
> *Jan 3 09:16:33.314: Vi2.1 EVT: Soft Disc 0 0x00000000
> *Jan 3 09:16:33.314: Vi2.1 PPP: Sending Acct Event[Down] id[263F]
> *Jan 3 09:16:33.314: Vi2.1 IPCP: State is Closed
> *Jan 3 09:16:33.314: Vi2.1 set_ip_peer(0): new address
> *Jan 3 09:16:33.314: ip_free_pool: Vi2.1: address = 216.24.12.100 (2)
> *Jan 3 09:16:33.314: Vi2.1: Invoking POOL_FREE for 216.24.12.100
> *Jan 3 09:16:33.314: Vi2.1: Returned from POOL_FREE for 216.24.12.100
> gw1.armplc#0.0.0.0
> *Jan 3 09:16:33.314: Vi2.1 PPP: Phase is TERMINATING
> *Jan 3 09:16:33.314: Vi2.1 LCP: O TERMREQ [Open] id 3 len 4
> *Jan 3 09:16:33.318: Vi2.1 EVT: Cleanup IP 0 0x00000000
> *Jan 3 09:16:33.810: Vi2.1 PPP: I pkt type 0xC021, datagramsize 6
> link[ppp]
> *Jan 3 09:16:33.810: Vi2.1 EVT: Packet 0 0x63BD1548
> *Jan 3 09:16:33.810: Vi2.1 LCP: I TERMACK [TERMsent] id 3 len 4
> *Jan 3 09:16:33.810: Vi2.1 LCP: State is Closed
> *Jan 3 09:16:33.810: Vi2.1 PPP: Phase is DOWN
> *Jan 3 09:16:33.810: Vi2.1 PPP: Send Message[Disconnect]
> *Jan 3 09:16:33.814: SSS MGR [uid:730]: Processing a client
> disconnect
> *Jan 3 09:16:33.814: SSS MGR [uid:730]: Handling
> Send-Service-Disconnect event
> gw1.armplc#term no mon
> gw1.armplc#
>
>
>
>
>
>>
>> ----
>>
>> 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