Dial-access and Voice with 5350

marcelo.zilio · ‎04-23-2003

I have a 5350 router, and it has two E1 interfaces. The first E1 are linked with PBX (ISDN Q-Sig) and the second E1 I used to remote access with E1 R2 linked with PSTN. The problem with remote access is that some users get a password error from radius. The odd fact is that with RAS Lucent MAX it works, but when I put the 5350, it doesn't work.

Below the configuration:

---

version 12.2

service timestamps debug datetime msec localtime show-timezone

service timestamps log datetime msec localtime show-timezone

service password-encryption

!

hostname 5350

!

no boot startup-test

logging buffered 20480 debugging

aaa new-model

!

aaa authentication login default local

aaa authentication enable default enable

aaa authentication ppp default if-needed group radius local

aaa authorization exec default if-authenticated group radius

aaa authorization network default if-authenticated group radius

aaa accounting network default start-stop group radius

aaa session-id common

!

resource-pool disable

calltracker enable

spe default-firmware spe-firmware-1

!

ip subnet-zero

ip cef

!

frame-relay switching

isdn switch-type primary-qsig

isdn voice-call-failure 0

!

voice call send-alert

voice call carrier capacity active

voice rtp send-recv

!

voice service voip

fax protocol t38 ls-redundancy 0 hs-redundancy 0

!

mta receive maximum-recipients 0

!

controller E1 3/0

pri-group timeslots 1-31

!

controller E1 3/1

framing NO-CRC4

ds0-group 0 timeslots 1-15,17-31 type r2-digital r2-compelled ani

cas-custom 0

country brazil

category 2

answer-signal group-b 1

!

interface FastEthernet0/0

ip address x.x.x.x x.x.x.x

duplex auto

speed auto

!

interface FastEthernet0/1

no ip address

shutdown

duplex auto

speed auto

!

interface Serial3/0:15

no ip address

isdn switch-type primary-qsig

isdn overlap-receiving

isdn incoming-voice modem

isdn bchan-number-order ascending

isdn sending-complete

no cdp enable

!

interface Group-Async0

ip unnumbered FastEthernet0/0

encapsulation ppp

ip tcp header-compression

async mode dedicated

peer default ip address pool mypool

ppp authentication pap

group-range 1/00 1/59

!

ip local pool mypool x.x.x.x x.x.x.x

ip classless

ip route 0.0.0.0 0.0.0.0 x.x.x.x

no ip http server

!

radius-server host x.x.x.x auth-port 1645 acct-port 1646

radius-server retransmit 3

radius-server timeout 60

radius-server key <removed>

radius-server authorization permit missing Service-Type

call rsvp-sync

!

voice-port 3/0:D

bearer-cap Speech

!

voice-port 3/1:0

compand-type a-law

!

mgcp profile default

!

dial-peer cor custom

!

dial-peer voice 8400 pots

application data_dialpeer

incoming called-number 8400

port 3/1:0

forward-digits all

!

dial-peer voice 1000 pots

destination-pattern 1...

direct-inward-dial

port 3/0:D

forward-digits all

!

dial-peer voice 1001 pots

destination-pattern 8...

direct-inward-dial

port 3/0:D

forward-digits all

!

dial-peer voice 2000 voip

destination-pattern 12..

session target ipv4:x.x.x.x

dtmf-relay rtp-nte

ip qos dscp cs5 media

!

5350#sh ver

Cisco Internetwork Operating System Software

IOS (tm) 5350 Software (C5350-IS-M), Version 12.2(11)T8, RELEASE SOFTWARE (fc1)

TAC Support: http://www.cisco.com/tac

Compiled Thu 27-Mar-03 22:32 by hqluong

Image text-base: 0x60008948, data-base: 0x61380000

ROM: System Bootstrap, Version 12.2(1r)1, RELEASE SOFTWARE (fc1)

BOOTLDR: 5350 Software (C5350-BOOT-M), Experimental Version 12.1(20000922:142008) [nag-flo_t_0110 101]

5350 uptime is 1 day, 3 hours, 44 minutes

System returned to ROM by reload at 00:23:01 brz Fri Jan 21 2000

System image file is "flash:c5350-is-mz.122-11.T8.bin"

cisco AS5350 (R7K) processor (revision T) with 131072K/65536K bytes of memory.

Processor board ID JAE070401D5

R7000 CPU at 250Mhz, Implementation 39, Rev 1.0, 256KB L2, 2048KB L3 Cache

Last reset from IOS reload

Channelized E1, Version 1.0.

Bridging software.

X.25 software, Version 3.0.0.

Primary Rate ISDN software, Version 1.1.

Manufacture Cookie Info:

EEPROM Type 0x0001, EEPROM Version 0x01, Board ID 0x32,

Board Hardware Version 3.34, Item Number 800-5171-02,

Board Revision C0, Serial Number JAE070401D5,

PLD/ISP Version 2.2, Manufacture Date 24-Jan-2003.

Processor 0x14, MAC Address 0x0B5FDAB22

Backplane HW Revision 1.0, Flash Type 5V

2 FastEthernet/IEEE 802.3 interface(s)

37 Serial network interface(s)

60 terminal line(s)

2 Channelized E1/PRI port(s)

512K bytes of non-volatile configuration memory.

32768K bytes of processor board System flash (Read/Write)

8192K bytes of processor board Boot flash (Read/Write)

Configuration register is 0x2102

5350#

---

Any idea?

best regards.

makchitale · ‎04-23-2003

If I understand correctly only some dialin users get this error message. Is it always the same users or any random user runs into this issue?

Can you please collect the following debugs for these failed calls:

deb aaa authen / deb aaa author / deb radius / deb aaa per-user / deb ppp nego

Do we see any modem retrain/ speedshift during this call?

deb modem / deb csm modem / deb cas will be useful as well.

Thanks, Mak.

tepatel · ‎04-23-2003

It would be interesting to see what radius records shows for that failed calls due to "radius error". If the RADIUS is rejecting the user because of the whatever reason we should be able to see that in the radius logs and also on the Access Server.

Try to get the debug as requested for the failed call only.

marcelo.zilio · ‎04-24-2003

Hi,

Some users can connect and some user cannot, but the number of users that cannot connect was increasing. So I come back to the Max Lucent to prevent another troubles with this users.

At the radius log, there was "Multiple logins" messages like this, that is not true:

<<< Apr 17 07:08:26: [11945]: Auth.warning: Multiple logins: [copercaf] CLID 452411710 (from nas nas-caf-lucent) max. 1

Apr 17 07:19:42: [11977]: Auth.notice: assuming `copercaf' is logged in >>>

Today I put the AS5350 another time to work, but only with this service (whitout another E1 ISDN Q.Sig), to collect debugs. During all day I have no problems.

I was thinking if this can be a DSP problem, once that it use the same DSP to data and voice, and maybe the router can be make somethink wrong due the configuration... and when it works only data, it works fine.

thanks

tepatel · ‎04-24-2003

If radius is rejecting it..nothing can be done on AS5350. We have no reports that DSP is having issue with data and voice calls togather.

As per the log that you have posted, it is complaining about multiple login request for the same user "copercaf" from the Lucent NAS "nas-caf-lucent".

So with AS5350, we need to see the debug for "debug radius" and other as requested in the earlier reply.

marcelo.zilio · ‎04-25-2003

Hi,

Here is the debug aaa authe/ aaa autho/ radius/ ppp nego/ aaa per from one user.

This occurs when I've got a connection error.

cfw-5350-voip#

Jan 23 22:54:40.568 brz: As1/27 PPP: Treating connection as a dedicated line

Jan 23 22:54:40.568 brz: As1/27 PPP: Phase is ESTABLISHING, Active Open

Jan 23 22:54:40.568 brz: As1/27 AAA/AUTHOR/LCP: Authorization succeeds trivially

Jan 23 22:54:40.568 brz: As1/27 LCP: O CONFREQ [Closed] id 1 len 24

Jan 23 22:54:40.568 brz: As1/27 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jan 23 22:54:40.568 brz: As1/27 LCP: AuthProto PAP (0x0304C023)

Jan 23 22:54:40.568 brz: As1/27 LCP: MagicNumber 0x0B6667C6 (0x05060B6667C6)

Jan 23 22:54:40.568 brz: As1/27 LCP: PFC (0x0702)

Jan 23 22:54:40.568 brz: As1/27 LCP: ACFC (0x0802)

Jan 23 22:54:40.764 brz: As1/27 LCP: I CONFREQ [REQsent] id 0 len 36

Jan 23 22:54:40.764 brz: As1/27 LCP: ACCM 0x00000000 (0x020600000000)

Jan 23 22:54:40.764 brz: As1/27 LCP: MagicNumber 0x64ED4C02 (0x050664ED4C02)

Jan 23 22:54:40.764 brz: As1/27 LCP: PFC (0x0702)

Jan 23 22:54:40.764 brz: As1/27 LCP: ACFC (0x0802)

Jan 23 22:54:40.764 brz: As1/27 LCP: Callback 6 (0x0D0306)

Jan 23 22:54:40.764 brz: As1/27 LCP: MRRU 1614 (0x1104064E)

Jan 23 22:54:40.764 brz: As1/27 LCP: EndpointDisc 3 00a0.c9bc.ed61 (0x13090300A0C9BCED61)

Jan 23 22:54:40.764 brz: As1/27 LCP: O CONFREJ [REQsent] id 0 len 11

Jan 23 22:54:40.764 brz: As1/27 LCP: Callback 6 (0x0D0306)

Jan 23 22:54:40.764 brz: As1/27 LCP: MRRU 1614 (0x1104064E)

Jan 23 22:54:40.904 brz: As1/27 LCP: I CONFREQ [REQsent] id 1 len 29

Jan 23 22:54:40.904 brz: As1/27 LCP: ACCM 0x00000000 (0x020600000000)

Jan 23 22:54:40.904 brz: As1/27 LCP: MagicNumber 0x64ED4C02 (0x050664ED4C02)

Jan 23 22:54:40.904 brz: As1/27 LCP: PFC (0x0702)

Jan 23 22:54:40.904 brz: As1/27 LCP: ACFC (0x0802)

Jan 23 22:54:40.908 brz: As1/27 LCP: EndpointDisc 3 00a0.c9bc.ed61 (0x13090300A0C9BCED61)

Jan 23 22:54:40.908 brz: As1/27 LCP: O CONFACK [REQsent] id 1 len 29

Jan 23 22:54:40.908 brz: As1/27 LCP: ACCM 0x00000000 (0x020600000000)

cfw-5350-voip#

Jan 23 22:54:40.908 brz: As1/27 LCP: MagicNumber 0x64ED4C02 (0x050664ED4C02)

Jan 23 22:54:40.908 brz: As1/27 LCP: PFC (0x0702)

Jan 23 22:54:40.908 brz: As1/27 LCP: ACFC (0x0802)

Jan 23 22:54:40.908 brz: As1/27 LCP: EndpointDisc 3 00a0.c9bc.ed61 (0x13090300A0C9BCED61)

cfw-5350-voip#

Jan 23 22:54:42.572 brz: As1/27 LCP: TIMEout: State ACKsent

Jan 23 22:54:42.572 brz: As1/27 LCP: O CONFREQ [ACKsent] id 2 len 24

Jan 23 22:54:42.572 brz: As1/27 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jan 23 22:54:42.572 brz: As1/27 LCP: AuthProto PAP (0x0304C023)

Jan 23 22:54:42.572 brz: As1/27 LCP: MagicNumber 0x0B6667C6 (0x05060B6667C6)

Jan 23 22:54:42.572 brz: As1/27 LCP: PFC (0x0702)

Jan 23 22:54:42.572 brz: As1/27 LCP: ACFC (0x0802)

Jan 23 22:54:42.772 brz: As1/27 LCP: I CONFACK [ACKsent] id 2 len 24

Jan 23 22:54:42.772 brz: As1/27 LCP: ACCM 0x000A0000 (0x0206000A0000)

Jan 23 22:54:42.772 brz: As1/27 LCP: AuthProto PAP (0x0304C023)

Jan 23 22:54:42.772 brz: As1/27 LCP: MagicNumber 0x0B6667C6 (0x05060B6667C6)

Jan 23 22:54:42.772 brz: As1/27 LCP: PFC (0x0702)

Jan 23 22:54:42.772 brz: As1/27 LCP: ACFC (0x0802)

Jan 23 22:54:42.772 brz: As1/27 LCP: State is Open

Jan 23 22:54:42.772 brz: As1/27 PPP: Phase is AUTHENTICATING, by this end

Jan 23 22:54:42.784 brz: As1/27 LCP: I IDENTIFY [Open] id 2 len 18 magic 0x64ED4C02 MSRASV5.00

Jan 23 22:54:42.792 brz: As1/27 LCP: I IDENTIFY [Open] id 3 len 24 magic 0x64ED4C02 MSRAS-1-NOTEBOOK

Jan 23 22:54:42.800 brz: As1/27 PAP: I AUTH-REQ id 4 len 17 from "aroeira"

Jan 23 22:54:42.800 brz: As1/27 PAP: Authenticating peer aroeira

Jan 23 22:54:42.800 brz: As1/27 PPP: Phase is FORWARDING, Attempting Forward

Jan 23 22:54:42.800 brz: As1/27 PPP: Phase is AUTHENTICATING, Unauthenticated User

Jan 23 22:54:42.800 brz: AAA/AUTHEN/PPP (0000001D): Pick method list 'default'

Jan 23 22:54:42.800 brz: RADIUS: AAA Unsupported [134] 9

Jan 23 22:54:42.800 brz: RADIUS: 41 73 79 6E 63 31 2F [Async1/]

Jan 23 22:54:42.800 brz: RADIUS(0000001D): Storing nasport 243 in rad_db

Jan 23 22:54:42.800 brz: RADIUS/ENCODE(0000001D): acct_session_id: 23

Jan 23 22:54:42.800 brz: RADIUS(0000001D): sending

Jan 23 22:54:42.800 brz: RADIUS: Send to unknown id 21 200.250.x.x:1645, Access-Request, len 94

Jan 23 22:54:42.800 brz: RADIUS: authenticator 25 44 47 FA 2F F5 73 3A - 55 E4 B0 B8 69 DF 75 CE

Jan 23 22:54:42.800 brz: RADIUS: Framed-Protocol [7] 6 PPP [1]

Jan 23 22:54:42.800 brz: RADIUS: User-Name [1] 9 "aroeira"

Jan 23 22:54:42.800 brz: RADIUS: User-Password [2] 18 *

Jan 23 22:54:42.800 brz: RADIUS: NAS-Port [5] 6 243

Jan 23 22:54:42.800 brz: RADIUS: NAS-Port-Type [61] 6 Async [0]

Jan 23 22:54:42.800 brz: RADIUS: Calling-Station-Id [31] 11

cfw-5350-voip#"452248020"

Jan 23 22:54:42.800 brz: RADIUS: Called-Station-Id [30] 6 "8400"

Jan 23 22:54:42.800 brz: RADIUS: Service-Type [6] 6 Framed [2]

Jan 23 22:54:42.800 brz: RADIUS: NAS-IP-Address [4] 6 10.1.199.198

cfw-5350-voip#

Jan 23 22:54:44.760 brz: As1/27 PAP: I AUTH-REQ id 5 len 17 from "aroeira"

Jan 23 22:54:44.760 brz: As1/27 PAP: Ignoring Additional Request

Jan 23 22:54:45.416 brz: AAA/ACCT/DS0: channel=29, ds1=1, t3=0, slot=3, ds0=50335773

cfw-5350-voip#

Jan 23 22:54:46.760 brz: As1/27 PAP: I AUTH-REQ id 6 len 17 from "aroeira"

Jan 23 22:54:46.764 brz: As1/27 PAP: Ignoring Additional Request

Jan 23 22:54:46.940 brz: RADIUS: Received from id 21 200.250.x.x:1645, Access-Reject, len 67

Jan 23 22:54:46.940 brz: RADIUS: authenticator 62 B4 88 31 62 AE 96 8C - A7 5D 1B A0 3A 37 6E CE

Jan 23 22:54:46.940 brz: RADIUS: Reply-Message [18] 47

Jan 23 22:54:46.944 brz: RADIUS: 0D 0A 59 6F 75 20 61 72 65 20 61 6C 72 65 61 64 [??You are alread]

Jan 23 22:54:46.944 brz: RADIUS: 79 20 6C 6F 67 67 65 64 20 69 6E 20 2D 20 61 63 [y logged in - ac]

Jan 23 22:54:46.944 brz: RADIUS: 63 65 73 73 20 64 65 6E 69 65 64 0D 0A [cess denied??]

Jan 23 22:54:46.944 brz: RADIUS: Received from id 1D

Jan 23 22:54:46.944 brz: As1/27 PAP: O AUTH-NAK id 6 len 50 msg is "MJYou are already logged in - access deniedMJ"

Jan 23 22:54:46.944 brz: As1/27 PPP: Sending Acct Event[Down] id[1D]

Jan 23 22:54:46.944 brz: As1/27 PPP: Phase is TERMINATING

Jan 23 22:54:46.944 brz: As1/27 LCP: O TERMREQ [Open] id 3 len 4

Jan 23 22:54:47.104 brz: As1/27 LCP: I TERMACK [TERMsent] id 3 len 4

Jan 23 22:54:47.104 brz: As1/27 LCP: State is Closed

Jan 23 22:54:47.104 brz: As1/27 PPP: Phase is DOWN

cfw-5350-voip#

Jan 23 22:54:47.104 brz: AAA/ACCT/DS0: channel=0, ds1=1, t3=0, slot=3, ds0=50335744

Jan 23 22:54:47.104 brz: As1/27 PPP: Phase is ESTABLISHING, Passive Open

Jan 23 22:54:47.104 brz: As1/27 LCP: State is Listen

Jan 23 22:54:47.108 brz: As1/27 LCP: State is Closed

Jan 23 22:54:47.108 brz: As1/27 PPP: Phase is DOWN

cfw-5350-voip#

Jan 23 22:54:52.108 brz: As1/27 LCP: State is Closed

cfw-5350-voip#

====

The error message include "nas-caf-lucent" because this name is associated wiht NAS IP, but it was a AS5350.

When I've got this debug, this user is not logged at radius, but I still receive duplicate connected message.

regards

makchitale · ‎04-25-2003

The Radius is rejecting the call: Jan 23 22:54:46.940 brz: RADIUS: Received from id 21 200.250.x.x:1645, Access-Reject, len 67.

It further says, Jan 23 22:54:46.944 brz: As1/27 PAP: O AUTH-NAK id 6 len 50 msg is "MJYou are already logged in - access deniedMJ"

On the radius double check that we already have a user with that username logged in, also for testing sake on Radius enable multiple simultaneous login.

Thanks, Mak.