ASR9k BNG Radius issue

Yury Kamiakou · ‎07-31-2013

Hi folks.

I'm deploying BNG at ASR9k with IOS XR 4.3.1 and have some problems with RADIUS exchange. My current config is:

radius source-interface Loopback220 vrf default

radius-server host x.y.z.198 auth-port 1812 acct-port 1813

key test

!

aaa attribute format USERNAME

format-string length 253 "%s" outer-vlan-id

!

aaa attribute format NAS_PORT_FORMAT

circuit-id plus remote-id separator .

!

aaa radius attribute nas-port format e SSSSAAPPPPPVVVVVVVVVVVVVVVVVVVVV

aaa radius attribute nas-port-id format NAS_PORT_FORMAT

aaa group server radius BNG

server x.y.z.198 auth-port 1812 acct-port 1813

source-interface Loopback220

!

aaa accounting subscriber default group BNG

aaa authorization subscriber default group BNG

aaa authentication subscriber default group BNG

aaa authentication ppp default group BNG

!

dhcp ipv4

vrf INTERNET proxy profile IPV4_GROUP

profile IPV4_GROUP proxy

class INTERNET

match vrf INTERNET

helper-address vrf INTERNET x1.y1.z1.77 giaddr x2.y2.z2.129

!

limit lease per-remote-id 150

relay information option vpn

relay information option

relay information policy keep

relay information option allow-untrusted

!

interface TenGigE0/1/0/0.1 proxy profile IPV4_GROUP

!

Radius server is reachable from BNG with loopback220 source IP address.

!

interface TenGigE0/1/0/0.1

ipv4 point-to-point

ipv4 unnumbered Loopback200

service-policy type control subscriber IP_POLICY_BASIC

encapsulation dot1q 145 second-dot1q 1960

ipsubscriber ipv4 l2-connected

initiator dhcp

!

dynamic-template

type ipsubscriber IP_BASIC

ipv4 unnumbered Loopback200

!

class-map type control subscriber match-any DHCP

match protocol dhcpv4

end-class-map

!

policy-map type control subscriber IP_POLICY_BASIC

event session-start match-first

class type control subscriber DHCP do-until-failure

10 activate dynamic-template IP_BASIC

20 authorize aaa list default format USERNAME password test

!

end-policy-map

!

Radius debug info:

LC/0/1/CPU0:Aug 1 00:19:41.493 FET: radiusd[322]: ENTERING 'handle_nas_req'

LC/0/1/CPU0:Aug 1 00:19:41.493 FET: radiusd[322]: ENTERING 'radiusd_get_nas_identifier'

LC/0/1/CPU0:Aug 1 00:19:41.493 FET: radiusd[322]: ENTERING 'build_radius_pkt'

LC/0/1/CPU0:Aug 1 00:19:41.493 FET: radiusd[322]: EXITTING 'radiusd_get_nas_identifier'

LC/0/1/CPU0:Aug 1 00:19:41.493 FET: radiusd[322]: ENTERING 'build_radius_pkt_from_list'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: ENTERING 'radiusd_get_prepend_nas_id_to_session_id'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: EXITTING 'radiusd_get_prepend_nas_id_to_session_id'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: EXITTING 'build_radius_pkt_from_list'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: EXITTING 'build_radius_pkt'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: ENTERING 'radius_send_request_message'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: ENTERING 'radius_get_next_server'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: Server x.y.z.198/1812/1813 is UP & Quarantined: NO

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: radius_get_next_server: Setting the preferred server handle to NULL

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: Sending request to x.y.z.198:1812, with retry_limit: 3 and delay: 5

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: EXITTING 'radius_get_next_server'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: ENTERING 'radius_set_ident_sock'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: EXITTING 'radius_set_ident_sock'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: ENTERING 'radius_ctx_db_insert_rctx'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: EXITTING (value 1) 'radius_ctx_db_insert_rctx'

LC/0/1/CPU0:Aug 1 00:19:41.494 FET: radiusd[322]: Sending request with id : 14/1347259508

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: ENTERING 'send_radius_packet'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: ENTERING 'radius_add_mand_attrs'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: EXITTING 'radius_add_mand_attrs'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: ENTERING 'radius_get_nas_ip_address'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Calling best local address using daemon address=x.y.z.198

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: ENTERING 'get_ip_addr_from_fib'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Address x.y.z.198 does not have a source address

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Got IP address: 0.0.0.0

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: IP source address aaa util format: 0.0.0.0

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: EXITTING 'get_ip_addr_from_fib'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: NAS best local address = 0.0.0.0

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: EXITTING 'radius_get_nas_ip_address'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Reencoding NAS-IP prev 0.0.0.0 new 0.0.0.0

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: ENTERING 'radius_get_next_server'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Server x.y.z.198/1812/1813 is UP & Quarantined: NO

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Failed aaa_sg_server_get_next_server with error 'qos-ea' detected the 'fatal' condition 'set exp imposition in egress is not permitted' rc = AFDF1600

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: EXITTING 'radius_get_next_server' with error [A247C800] 'Subsystem(1167)' detected the 'fatal' condition 'Code(36)'

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: NAS-IP-Address not found, Moving to next server in the server group

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Nas-IP-Address not found, dropping request

LC/0/1/CPU0:Aug 1 00:19:41.495 FET: radiusd[322]: Failed to send the request

Any workaround or recommendation to solve the issue?

narvenka · ‎08-07-2013

Looks like the request itself not getting out of the box because of unreachablity or the

source-interface Loopback220 not exist. Can you check on that ?

Vladimir Miropolskyj · ‎03-06-2014

a have same problem on 5.1.1 software

aaa accounting system default start-stop group BNG

aaa group server radius BNG

server-private XX.XXX.XXX.8 auth-port 1812 acct-port 1813

key 7 000500140D551F031D324D5A490D000406

!

source-interface Loopback1

!

aaa authentication ppp default group BNG

aaa authentication login default local

!

dynamic-template

type ppp PPP_TPL

ppp authentication chap

ppp ipcp dns 8.8.8.8

ipv4 unnumbered Loopback2

!

interface Loopback1

ipv4 address 10.254.254.254 255.255.255.255

!

interface Loopback2

ipv4 address 10.254.254.253 255.255.255.255

!

interface MgmtEth0/RSP0/CPU0/0

ipv4 address 10.252.0.90 255.255.255.0

!

interface MgmtEth0/RSP0/CPU0/1

shutdown

!

interface TenGigE0/0/2/1.556

ipv4 address 10.56.0.1 255.255.255.0

service-policy type control subscriber PPP_PM

pppoe enable bba-group pppoe

encapsulation dot1q 556

aaa attribute format NAS_PORT_FORMAT

circuit-id plus remote-id separator .

!

aaa radius attribute nas-port format e SSAAPPPPQQQQQQQQQQVVVVVVVVVVUUUU type 32

aaa radius attribute nas-port format e SSAAPPPPQQQQQQQQQQVVVVVVVVVVUUUU

aaa radius attribute nas-port-id format NAS_PORT_FORMAT

aaa accounting subscriber default group BNG

aaa authorization subscriber default group BNG

aaa authentication subscriber default group BNG

pppoe bba-group pppoe

service selection disable

!

class-map type control subscriber match-any PPP

match protocol ppp

end-class-map

!

policy-map type control subscriber PPP_PM

event session-start match-first

class type control subscriber PPP do-until-failure

1 activate dynamic-template PPP_TPL

!

event session-activate match-first

class type control subscriber PPP do-until-failure

1 authenticate aaa list default

!

end-policy-map

Radius -server sends Access-Accept but on its router it isn't visible

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: Send Access-Request to XX.XXX.XXX.8:1812 id 169, len 220

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: authenticator D3 8C BA E1 87 32 81 3C - E7 47 78 79 20 C1 AC 57

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: Vendor,Cisco [26] 41

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: Cisco AVpair [1] 35 client-mac-address=000e.0c75.b6d9

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: Acct-Session-Id [44] 10 0400003b

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: NAS-Port [5] 6 2701140681

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: NAS-Port-Id [87] 3 .

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: Vendor,Cisco [26] 9

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: cisco-nas-port [2] 3 .

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: User-Name [1] 11 user1

LC/0/0/CPU0:Mar 6 15:48:32.499 : radiusd[327]: RADIUS: Service-Type [6] 6 Framed[0]

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: CHAP-Password [3] 19 *

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: CHAP-Challenge [60] 18 r^K d ^BZ-^E^B^_^S^Xd^U)

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: Unsuppoted attribute.

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: Vendor,Cisco [26] 33

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: Cisco AVpair [1] 27 connect-progress=LCP Open

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: Framed-Protocol [7] 6 PPP[0]

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: NAS-Port-Type [61] 6 PPPoEoVLAN[0]

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: Event-Timestamp [55] 6 1394102897

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: Nas-Identifier [32] 14 asr9k_pppoe

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: RADIUS: NAS-IP-Address [4] 6 XX.XXX.XXX.9

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: Updating last used server

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: EXITTING 'send_radius_packet'

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: Got global deadtime 0

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: Using global deadtime = 0 sec

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: ENTERING 'start_dead_detect_timer'

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: EXITTING 'start_dead_detect_timer'

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: ENTERING 'radius_timer_update'

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: EXITTING 'radius_timer_update'

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: Updated timer thread rad_ident 169 remote_port 1812 remote_addr 0x30fb908c, socket 1342480676 rctx 0x5015b530

LC/0/0/CPU0:Mar 6 15:48:32.500 : radiusd[327]: ENTERING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: EXITTING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: ENTERING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: EXITTING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: ENTERING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: EXITTING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: ENTERING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: EXITTING 'radius_timer_set_addl_context'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: Successfully sent packet and started timeout handler for rctx 0x5015b530

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: EXITTING 'radius_send_request_message'

LC/0/0/CPU0:Mar 6 15:48:32.501 : radiusd[327]: EXITTING 'radius_timeout_handler'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: ENTERING 'radius_timeout_handler'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: ENTERING 'radius_timer_get_addl_context'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: Timeout happened for req rad_ident 169 remote_port 1812 remote_addr 0x50 socket 1342480676 rctx 5015b530

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: ENTERING 'radius_ctx_db_get_and_remove_rctx'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: rctx found is 0x5015b530

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: EXITTING 'radius_ctx_db_get_and_remove_rctx'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: ENTERING 'radius_send_request_message'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: Reached retry count for the server 3,Trying to move to next server

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: ENTERING 'radius_get_next_server'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: Server XX.XXX.XXX28/1812/1813 is UP & Quarantined: NO

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: EXITTING 'radius_get_next_server' with error [A247C800] 'Subsystem(1167)' detected the 'fatal' condition 'Code(36)'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: EXITTING 'radius_send_request_message' with error [A247C800] 'Subsystem(1167)' detected the 'fatal' condition 'Code(36)'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: ENTERING 'rad_nas_reply_to_client'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: rad_nas_reply_to_client: Received response from id : 169,packet type 1

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: rad_nas_reply_to_client: Sending failover message to client

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: EXITTING 'rad_nas_reply_to_client'

LC/0/0/CPU0:Mar 6 15:48:37.508 : radiusd[327]: EXITTING 'radius_timeout_handler'

I tried with group of radius and without it and different source-interface interfaces doesn't help

There are thoughts where to look?

Vladimir Pysarenco · ‎03-20-2014

Try to create a bundle and bind service-policy to bundle subinterface, not to physical subinterface.

Creation sessions from physical interface is possible from 5.1.1 and may be some features don't works.

On bundle interfaces all works fine.