Mailing List Archive

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@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@win.net"
> *Dec 31 11:02:46.886: ppp927 PAP: Authenticating peer dennis@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@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@puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-nas
_______________________________________________
cisco-nas mailing list
cisco-nas@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-nas

> 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@win.net"
*Jan 3 09:16:31.930: ppp730 PAP: Authenticating peer dennis@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@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@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@win.net"
> > *Dec 31 11:02:46.886: ppp927 PAP: Authenticating peer
dennis@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@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@puck.nether.net
> > https://puck.nether.net/mailman/listinfo/cisco-nas

_______________________________________________
cisco-nas mailing list
cisco-nas@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-nas

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@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@win.net"
> *Jan 3 09:16:31.930: ppp730 PAP: Authenticating peer dennis@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@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@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@win.net"
>>> *Dec 31 11:02:46.886: ppp927 PAP: Authenticating peer
> dennis@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@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@puck.nether.net
>>> https://puck.nether.net/mailman/listinfo/cisco-nas
_______________________________________________
cisco-nas mailing list
cisco-nas@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-nas

> 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.

It was! I defined those access lists on the new cisco just as they are
on the others and everything works fine now. Thanks so much for your
help!

Joe Mays

_______________________________________________
cisco-nas mailing list
cisco-nas@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-nas

Glad I could help! It sure would have been nice if the
debugs that you had turned on at first (which sure seemed
like they should have been enough) would have told you
what was happening.

Cheers,

Aaron

----

On 1/3/2011 6:12 PM, jfmays@launchpad.win.net (Joe Mays) wrote:
>> 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.
>
> It was! I defined those access lists on the new cisco just as they are
> on the others and everything works fine now. Thanks so much for your
> help!
>
> Joe Mays
_______________________________________________
cisco-nas mailing list
cisco-nas@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-nas