Unable to connect - RADIUS/PPPoE

manpan · ‎04-11-2002

Im using a cisco3640 conected directly to a workstation(with a pppoe client/dialer) via ethernet(PPPoe enabled). the serial of the router connected to

another router wich connects to my radius server.

I'm trying to use RADIUS to authenticate a PPPoE session. The request

to authenticate was hit at radius but it was not able astablish connection.

Please refer to the log below.

From Radius log file(IMS)

09.04.2002 17.26.25-823 RADIUS[ 377] DBG ----- [Worker sent message (1 bytes)]

09.04.2002 17.26.25-823 RADIUS[ 375] DBG ----- [Available=11]

09.04.2002 17.26.25-823 RADIUS[ 375] DBG ----- [Incoming data on Worker socket]

09.04.2002 17.26.25-824 RADIUS[ 375] DBG ----- [Worker 1 is available!]

09.04.2002 17.26.25-824 RADIUS[ 375] DBG ----- []

09.04.2002 17.26.25-824 RADIUS[ 375] DBG ----- [Find free worker]

09.04.2002 17.26.26-395 RADIUS[ 375] DBG ----- [Available=6]

09.04.2002 17.26.26-395 RADIUS[ 375] DBG ----- [Incoming data on Access socket]

09.04.2002 17.26.26-395 RADIUS[ 375] DBG ----- [Read a message(79 bytes)]

09.04.2002 17.26.26-395 RADIUS[ 375] DBG ----- [Data read]

09.04.2002 17.26.26-395 RADIUS[ 375] DBG ----- []

09.04.2002 17.26.26-395 RADIUS[ 375] DBG ----- [Find free worker]

09.04.2002 17.26.26-395 RADIUS[ 375] DBG ----- [Sending request to worker]

09.04.2002 17.26.26-396 RADIUS[ 375] DBG ----- [Sent 99 bytes to worker]

09.04.2002 17.26.26-396 RADIUS[ 375] DBG ----- [Worker 1 is now busy!]

09.04.2002 17.26.26-396 RADIUS[ 377] DBG ----- [Dispatcher message ready]

09.04.2002 17.26.26-396 RADIUS[ 377] DBG ----- [Worker received 99 bytes]

09.04.2002 17.26.26-396 RADIUS[ 377] DBG ----- [Worker:handle_request() id=1, length=99, src_ip=203.121.6.154, src_port=1645, datal

en=79]

09.04.2002 17.26.26-396 RADIUS[ 377] DBG ----- [RawPacket]

0000 0113004F 8CEA8BDD 039CDA6B 9CD72EF0 ...O.......k....

0010 5CCE0F35 0406CB79 069A0506 00000001 \..5...y........

0020 3D060000 0005010A 61737568 61696D69 =.......asuhaimi

0030 03131481 4A432434 B3F480F7 08D31EAF ....JC$4........

0040 A09C7506 06000000 02070600 000001 ..u............

09.04.2002 17.26.26-397 RADIUS[ 377] DBG ----- [No Nas Cache Hit!]

09.04.2002 17.26.26-398 RADIUS[ 377] DBG ----- [Inserting into nas_cache!]

09.04.2002 17.26.26-398 RADIUS[ 377] DBG ----- []

09.04.2002 17.26.26-399 RADIUS[ 377] DBG ----- [Packet without VSAs and Acct-Session-Id]

09.04.2002 17.26.26-399 RADIUS[ 377] DBG ----- [av_pairs cache hit!]

09.04.2002 17.26.26-399 RADIUS[ 377] DBG ----- [Entity_ident cache hit!]

09.04.2002 17.26.26-399 RADIUS[ 377] DBG ----- [Found no matching entity_ident record - using default]

09.04.2002 17.26.26-399 RADIUS[ 377] DBG ----- [analyze_radius_packet() = [2]]

09.04.2002 17.26.26-400 RADIUS[ 377] DBG ----- [-- Handling Access Request --]

09.04.2002 17.26.26-400 RADIUS[ 377] DBG ----- [access_type = 9]

09.04.2002 17.26.26-400 RADIUS[ 377] DBG ----- [trace: IDAPIGetServiceByUserName(...'asuhaimi',9)]

09.04.2002 17.26.26-400 RADIUS[ 377] DBG ----- [No Clid cache hit!]

09.04.2002 17.26.26-401 RADIUS[ 377] DBG ----- [Inserting negative into clid_username_cache!]

09.04.2002 17.26.26-401 RADIUS[ 377] DBG ----- [No logon_record Cache Hit!]

09.04.2002 17.26.26-401 RADIUS[ 377] DBG ----- [trace: IDAPIGetLogonRecordByUsername(...'asuhaimi'(8),2)]

09.04.2002 17.26.26-402 RADIUS[ 377] DBG ----- [Inserting into Logon_record cache!]

09.04.2002 17.26.26-402 RADIUS[ 377] DBG ----- [Found user by username! pop_id=0, ispvn_id=2, password=asuhaimi, access_types=XX-X-

----------------X----------, has_clid= ]

09.04.2002 17.26.26-403 RADIUS[ 377] DBG ----- [Account does not have access_type 9!]

09.04.2002 17.26.26-403 RADIUS[ 377] DBG ----- [Rejected by VerifyUserAccess]

09.04.2002 17.26.26-403 RADIUS[ 377] DBG ----- [finish_access_request(...1,0,-1,...)]

09.04.2002 17.26.26-403 RADIUS[ 377] DBG ----- [Finishing access request for user asuhaimi]

09.04.2002 17.26.26-403 RADIUS[ 377] DBG ----- [Access rejected: Unknown username or service]

09.04.2002 17.26.26-404 RADIUS[ 377] DBG ----- [Packet sent (49 of 49 bytes) to ip=0xcb79069a:1645 via fd=6:]

0000 03130031 15AC8CB2 BCF8EF39 3114336B ...1.......91.3k

0010 302AC16E 121D556E 6B6E6F77 6E207573 0*.n..Unknown us

0020 65726E61 6D65206F 72207365 72766963 ername or servic

0030 65 e

=============end======================================

The statement [No Clid cache hit!] goes to the "Account does not have access_type 9!]" . What does this mean? Can anyone help me.

I have configured the accounting port and the authentication port

correctly on the router.

As u can see the username "suhaimi" is known by the RADIUS but

it can't authenticate!!.. please help.

tepatel · ‎04-13-2002

Looks to me that you may not have configured the ip address of the NAS in the radius server..If you can reach to radius server over the serial interface, then in the authentication request packet to radius server, source ip address will be the ip address of the serial interface. So you need to enter the ip address of the NAS as the ip address of serial interface..(unless you have modified it using the "ip radius source-interface command)

Just make sure that you have configured the correct ip address for NAS in radius server.

Following debug you can turn on to verify that.

debug radius

debug aaa authentication

manpan · ‎04-14-2002

The ip address of the serial has been specified in radius.

tepatel · ‎04-16-2002

If its not working then turn on follwoing debug on the router when that user tris to log in

debug aaa authentication

debug radius

debug aaa authorization

debug aaa per-user

Post it along with the config..

manpan · ‎04-16-2002

Router configuration (cisco3640)

================

//-----PPPoE RADIUS identification

aaa new-model

aaa authentication ppp default local group radius

aaa authorization network default local group radius

aaa accounting network default start-stop group radius

!

username din password 0 din

ip subnet-zero

!

//-----Enable virtual private dialup networking feature

vpdn enable

!

vpdn-group 1

accept-dialin

protocol pppoe

virtual-template 1

pppoe limit per-mac 60

!

//-----Enable pppoe on Ethernet interface. This interface connects to

//-----pppoe enabled clients.

interface Ethernet0/0

ip address 203.121.9.192 255.255.255.240

half-duplex

pppoe enable

!

//-----This interface connects to KLPOP for network access

interface Serial0/0

ip address 203.121.6.154 255.255.255.252

no fair-queue

!

//-----Creates Virtual-Access interface with ip address same as interface

//-----Ethernet0/0 above. Used to set the mtu size and specify ppp

//-----authentication method.

interface Virtual-Template1

mtu 1492

ip unnumbered Ethernet0/0

ppp authentication pap

!

//-----PPPoE RADIUS identification

radius-server host 203.121.16.84 auth-port 1812 acct-port 1646

radius-server retransmit 3

radius-server key secret

!

router Debug

==========

Router#

00:15:54: PPPoE 0: I PADI L:ffff.ffff.ffff R:00d0.590d.4864 Et0/0

FF FF FF FF FF FF 00 D0 59 0D 48 64 88 63 11 09

00 00 00 0E 01 03 00 06 00 D0 59 0D 48 64 01 01

00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ...

00:15:54: PPPoE 0: O PADO L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

00 D0 59 0D 48 64 00 30 80 75 29 C1 88 63 11 07

00 00 00 2C 01 03 00 06 00 D0 59 0D 48 64 01 01

00 00 01 02 00 06 52 6F 75 74 65 72 01 04 00 ...

00:15:54: PPPoE 0: I PADR L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

00 30 80 75 29 C1 00 D0 59 0D 48 64 88 63 11 19

00 00 00 22 01 03 00 06 00 D0 59 0D 48 64 01 01

00 00 01 04 00 10 D1 33 FA E0 C8 CB AE 94 FB ...

00:15:54: Vi1 VPDN: Bind interface direction=2

00:15:54: PPPoE 1: Creating

00:15:54: PPPoE 1: Created L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

00:15:54: PPPoE 1: O PADS L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

00 D0 59 0D 48 64 00 30 80 75 29 C1 88 63 11 65

00 01 00 22 01 03 00 06 00 D0 59 0D 48 64 01 01

00 00 01 04 00 10 D1 33 FA E0 C8 CB AE 94 FB ...

00:15:54: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

00:15:54: Vi1 AAA/AUTHOR/FSM: (0): LCP succeeds trivially

00:15:54: PPPoE 1: O L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

FF 03 C0 21 01 01 00 13 01 04 05 D4 03 05 C2 23

05 05 06 30 8F 06 90

00:15:54: PPPoE 1: I L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

C0 21 01 01 00 0A 05 06 6D 85 EC 03

00:15:54: PPPoE 1: O L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

FF 03 C0 21 02 01 00 0A 05 06 6D 85 EC 03

00:15:56: PPPoE 1: O L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

FF 03 C0 21 01 02 00 13 01 04 05 D4 03 05 C2 23

05 05 06 30 8F 06 90

00:15:56: PPPoE 1: I L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

C0 21 02 02 00 13 01 04 05 D4 03 05 C2 23 05 05

06 30 8F 06 90

00:15:56: PPPoE 1: O L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

FF 03 C2 23 01 0B 00 1B 10 0D 84 67 25 D4 00 3B

36 9C D7 2E F0 0A 3C 02 90 52 6F 75 74 65 72

00:15:56: PPPoE 1: I L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

C2 23 02 0B 00 1D 10 54 69 20 0B 75 39 61 27 A0

32 6F 12 CD 3C 63 29 61 73 75 68 61 69 6D 69

00:15:56: Vi1 VPDN: Looking for tunnel -- --

00:15:56: Vi1 VPDN: Continue PPP authentication for asuhaimi

00:15:56: AAA: parse name=Virtual-Access1 idb type=21 tty=-1

00:15:56: AAA: name=Virtual-Access1 flags=0x11 type=7 shelf=0 slot=0 adapter=0 port=1 channel=0

00:15:56: AAA/MEMORY: create_user (0x621E6370) user='asuhaimi' ruser='NULL' ds0=0 port='Virtual-Access1' rem_addr='' authen_type=CHAP service=PPP priv=1 initial_task_id='0'

00:15:56: AAA/AUTHEN/START (3927425925): port='Virtual-Access1' list='' action=LOGIN service=PPP

00:15:56: AAA/AUTHEN/START (3927425925): using "default" list

00:15:56: AAA/AUTHEN/START (3927425925): Method=radius (radius)

00:15:56: RADIUS: ustruct sharecount=2

00:15:56: Radius: radius_port_info() success=1 radius_nas_port=1

00:15:56: RADIUS: Initial Transmit Virtual-Access1 id 10 203.121.16.84:1812, Access-Request, len 79

00:15:56: Attribute 4 6 CB7909C1

00:15:56: Attribute 5 6 00000001

00:15:56: Attribute 61 6 00000005

00:15:56: Attribute 1 10 61737568

00:15:56: Attribute 3 19 0B546920

00:15:56: Attribute 6 6 00000002

00:15:56: Attribute 7 6 00000001

00:15:56: RADIUS: Received from id 10 203.121.16.84:1812, Access-Reject, len 49

00:15:56: Attribute 18 29 556E6B6E

00:15:56: AAA/AUTHEN (3927425925): status = FAIL

00:15:56: PPPoE 1: O L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

FF 03 C2 23 04 0B 00 1F 55 6E 6B 6E 6F 77 6E 20

75 73 65 72 6E 61 6D 65 20 6F 72 20 73 65 72 76

69 63 65

00:15:56: PPPoE 1: O L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

FF 03 C0 21 05 03 00 04

00:15:56: AAA/MEMORY: free_user (0x621E6370) user='asuhaimi' ruser='NULL' port='Virtual-Access1' rem_addr='' authen_type=CHAP service=PPP priv=1

00:15:56: Vi1 AAA/AUTHOR/PER-USER: Event LCP_DOWN

00:15:56: Vi1 AAA/AUTHOR: LCP_DOWN

00:15:56: PPPoE 1: I L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

C0 21 06 03 00 04

00:15:56: Vi1 AAA/AUTHOR/FSM: (0): LCP succeeds trivially

00:15:56: Vi1 VPDN: Cleanup

00:15:56: Vi1 VPDN: Reset

00:15:56: PPPoE 1: Shutting down

00:15:56: PPPoE 1: O PADT L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

00 D0 59 0D 48 64 00 30 80 75 29 C1 88 63 11 A7

00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00

00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ...

00:15:56: PPPoE 1: Destroying L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

00:15:56: Vi1 VPDN: Unbind interface

00:15:56: Vi1 VPDN: Reset

00:15:56: Vi1 VPDN: Unbind interface

00:15:56: Vi1 AAA/AUTHOR/PER-USER: Event LCP_DOWN

00:15:56: Vi1 AAA/AUTHOR: LCP_DOWN

00:15:56: PPPoE 1: I PADT L:0030.8075.29c1 R:00d0.590d.4864 Et0/0

00 30 80 75 29 C1 00 D0 59 0D 48 64 88 63 11 A7

00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00

00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ...

00:15:58: Vi1 AAA/AUTHOR/PER-USER: Event LCP_DOWN

00:15:58: Vi1 AAA/AUTHOR: LCP_DOWN

log from RADIUS

=============

09.04.2002 17.26.26-396 RADIUS[ 377] DBG ----- [Worker received 99 bytes]

09.04.2002 17.26.26-396 RADIUS[ 377] DBG ----- [Worker:handle_request() id=1,

length=99, src_ip=203.121.6.154, src_port=1645, datalen=79]

09.04.2002 17.26.26-396 RADIUS[ 377] DBG ----- [RawPacket]

0000 0113004F 8CEA8BDD 039CDA6B 9CD72EF0 ...O.......k....

0010 5CCE0F35 0406CB79 069A0506 00000001 \..5...y........

0020 3D060000 0005010A 61737568 61696D69 =.......asuhaimi

0030 03131481 4A432434 B3F480F7 08D31EAF ....JC$4........

0040 A09C7506 06000000 02070600 000001 ..u............

09.04.2002 17.26.26-397 RADIUS[ 377] DBG ----- [No Nas Cache Hit!]

>>>>>>>>>>As you could see the error begin with the "no Nas cache hit"

>>>>>>>>>>For my normal dial-up customers the radius logs are,

16.04.2002 16.20.36-898 RADIUS[ 366] DBG ----- [Worker received 208 bytes]

16.04.2002 16.20.36-898 RADIUS[ 366] DBG ----- [Worker:handle_request() id=1,

length=208, src_ip=203.121.19.133, src_port=1645, datalen=188]

16.04.2002 16.20.36-898 RADIUS[ 366] DBG ----- [RawPacket]

0000 013B00BC 25A3FD1B 343E8FBE DA6FF405 .;..%...4>...o..

0010 C3D555A0 01077573 65723102 12CFA5E1 ..U...user1.....

0020 6C724FC2 EB5C86CD 52736B15 1F0406CB lrO..\..Rsk.....

0030 79138505 0600000D 0A2C0B32 31383639 y........,.21869

0040 33363732 1A0E0000 01AD0000 98430000 3672.........C..

0050 11F21A0E 000001AD 00009889 00000000 ................

0060 06060000 00020706 00000001 1A0E0000 ................

0070 01AD0000 90190000 000E1A0E 000001AD ................

0080 0000901A 00000001 1A0E0000 01AD0000 ................

0090 901B0000 000A1A0E 000001AD 00009023 ...............#

00A0 00000001 1F0C3033 32373133 36393632 ......0327136962

00B0 1E063135 31373D06 00000000 ..1517=.....

16.04.2002 16.20.36-899 RADIUS[ 366] DBG ----- [Nas Cache Hit!]

16.04.2002 16.20.36-899 RADIUS[ 366] DBG ----- [NAS: id=313, name=glmrb_ras_002bn,

identifier=, secret=secret, pop_id=1, is_rfc_compliant=0, use_port_server=1, vendor_id=0 voip_enabled=0]

>>>>>>>>As you can see there is "Nas Cache Hit!" and the user got

>>>>>>>>authenticated successfully.

>>>>>>>>One thing i noticed is that the raw packet size of normal dial-up user

>>>>>>>>is large compared to pppoe dial method. Could this be the cause??

manpan · ‎04-17-2002

Here i provide the connectivity for my configuration.

Client/host (PPPoE) GW Ethernetport GW Serial port

203.121.9.195<----->203.121.9.193----203.121.6.154<======>RADIUS

The ip address of client is configured manually.

Really appreciate if u could help :-)

tepatel · ‎04-17-2002

You can see that the router did tried to contact RADIUS server for authentication but got following reply from it

00:15:56: AAA/AUTHEN (3927425925): status = FAIL

So the router is getting "authentication fail" message from the RADIUS server.

So its a problem in the RADIUS server..Make sure that the username and password is configured properly..

nurinalmas · ‎07-30-2002

Hi guys,

I have exactly the same setup and currently experiencing the same ERROR message.

When I tried authentication using the same RADIUS server for a TELNET connection to the router, authentication works fine. So can I say that my RADIUS configuration is OK, and it should work with PPPoE connections?

hweiwoo · ‎08-25-2002

in order to configure the RADIUS Port Identification for PPP,

To configure the LAC with the NAS-Port format for PPP over ATM, PPPoE over ATM.for example:

aaa new-model

aaa authentication ppp default local group radius

aaa authorization network default local group radius

aaa accounting network default start-stop group radius

radius-server host 171.69.69.66 auth-port 1645 acct-port 1646

radius-server retransmit 3

radius-server attribute nas-port format d

radius-server key rad123

!