05-13-2025 03:49 AM
Hello community,
We use C8500 for PPPoE subscribers. Configuration via bba-group and virtual-template with aaa (Freeradius).
Freeradius receives the user and responds with an Access-Accept. According to the log, an IP address is also selected and is part of the Access-Accept response. However, no IP address is assigned to the client from the BRAS.
The log shows that no peer address is assigned.
Software:
Freeradius 3.2.1
C8500: 17.12.04b
Debugging options
PPP: PPP authentication debugging is on PPP protocol negotiation debugging is on PPPoE: PPPoE protocol events debugging is on PPPoE data packets debugging is on PPPoE protocol errors debugging is on PPPoE elog debugging is on Radius protocol debugging is on Radius protocol brief debugging is on Radius protocol verbose debugging is on Radius elog debugging debugging is on
Config for bba and virtual-template (Without radius server options)
bba-group pppoe global vendor-tag circuit-id service vendor-tag remote-id service vendor-tag dsl-sync-rate service ac name MY-BRAS sessions pre-auth limit ignore pado delay 0 ! bba-group pppoe BBA-PPPOE-61 virtual-template 61 vendor-tag remote-id service vendor-tag dsl-sync-rate service nas-port-id format c sessions per-mac limit 10 ! interface Virtual-Template61 description PPPoE Template VLAN61 mtu 1492 ip unnumbered Loopback1 no peer default ip address ppp authentication ms-chap-v2 pap pppoe-aaa-test ppp accounting pppoe-aaa-test ppp ipcp dns 8.8.8.8 1.1.1.1 ppp ipcp mask 255.255.255.128 ppp ipcp address required ppp ipcp address unique ip virtual-reassembly !
Radius logs with access-request, access-accept and stop
Tue May 13 10:00:19 2025 Packet-Type = Access-Request Framed-Protocol = PPP User-Name = "user1@login.mydomain.com" NAS-Port-Type = PPPoEoE NAS-Port = 4031774720 NAS-Port-Id = "ether 15/0/5:4096.0 0/0/0/0/0/0" Cisco-AVPair = "client-mac-address=e028.6ddc.9128" Service-Type = Framed-User NAS-IP-Address = 10.0.25.8 Event-Timestamp = "May 13 2025 10:00:19 CEST" Timestamp = 1747130419 Tue May 13 10:00:19 2025 Packet-Type = Access-Accept Framed-Protocol = PPP Acct-Interim-Interval = 600 WISPr-Bandwidth-Max-Down = 1034240 WISPr-Bandwidth-Max-Up = 1034240 Session-Timeout = 604800 Reply-Message = "PublicIPv4Pool" Service-Type = Framed-User Framed-IP-Address = 117.213.182.129 Timestamp = 1747130419 Tue May 13 10:00:19 2025 Acct-Session-Id = "ether 15/0/5:4096.0 0/0/0/0/0/0_0000106F" Framed-Protocol = PPP Cisco-AVPair = "ppp-disconnect-cause=Peer address required" User-Name = "user1@login.mydomain.com" Acct-Authentic = RADIUS Cisco-AVPair = "connect-progress=Call Up" Cisco-AVPair = "nas-tx-speed=1000000000" Cisco-AVPair = "nas-tx-speed-kbps=1000000" Cisco-AVPair = "nas-rx-speed=1000000000" Cisco-AVPair = "nas-rx-speed-kbps=1000000" Acct-Session-Time = 0 Acct-Input-Octets = 0 Acct-Output-Octets = 12 Acct-Input-Packets = 0 Acct-Output-Packets = 1 Acct-Terminate-Cause = NAS-Error Cisco-AVPair = "disc-cause-ext=PPP LCP Close" Acct-Status-Type = Stop NAS-Port-Type = PPPoEoE NAS-Port = 4031774720 NAS-Port-Id = "ether 15/0/5:4096.0 0/0/0/0/0/0" Cisco-AVPair = "client-mac-address=e028.6ddc.9128" Service-Type = Framed-User NAS-IP-Address = 10.0.25.8 Acct-Delay-Time = 0 Event-Timestamp = "May 13 2025 10:00:19 CEST" Acct-Unique-Session-Id = "6a7908e054ac176ddbf15999ec417ef2" Timestamp = 1747130419
Debug output from C8500
May 13 10:00:19.079: PPPoE 0: I PADI R:e028.6ddc.9128 L:ffff.ffff.ffff BD61 May 13 10:00:19.079: Service tag: NULL Tag May 13 10:00:19.079: PPPoE 0: O PADO, R:9433.d8ba.11bf L:e028.6ddc.9128 BD61 May 13 10:00:19.079: Service tag: NULL Tag May 13 10:00:19.080: PPPoE 0: I PADR R:e028.6ddc.9128 L:9433.d8ba.11bf BD61 May 13 10:00:19.080: Service tag: NULL Tag May 13 10:00:19.080: [182]PPPoE 182: Access IE handle allocated May 13 10:00:19.080: [182]PPPoE 182: AAA get retrieved attrs May 13 10:00:19.080: [182]PPPoE 182: AAA get nas port details May 13 10:00:19.080: [182]PPPoE 182: Error adjusting nas port format did May 13 10:00:19.080: dyn_attrs->xmit_rate: 1000000000 dyn_attrs->rcv_rate: 1000000000 May 13 10:00:19.080: [182]PPPoE 182: AAA get dynamic attrs May 13 10:00:19.080: [182]PPPoE 182: AAA unique ID DD allocated May 13 10:00:19.080: [182]PPPoE 182: No AAA accounting method list May 13 10:00:19.080: [182]PPPoE 182: Service request sent to SSS May 13 10:00:19.080: [182]PPPoE 182: Created, Service: None R:9433.d8ba.11bf L:e028.6ddc.9128 BD61 May 13 10:00:19.081: SSS PM [uid:182][7EAF93F2C758][AAA ID:221]: AAA author NOT needed May 13 10:00:19.081: [182]PPPoE 182: State NAS_PORT_POLICY_INQUIRY Event SSS MORE KEYS May 13 10:00:19.081: PPP: Alloc Context [7EAF7F0E70F8] May 13 10:00:19.081: ppp182 PPP: Phase is ESTABLISHING May 13 10:00:19.081: [182]PPPoE 182: data path set to PPP May 13 10:00:19.081: [182]PPPoE 182: Segment (SSS class): PROVISION May 13 10:00:19.081: [182]PPPoE 182: State PROVISION_PPP Event SSM PROVISIONED May 13 10:00:19.081: [182]PPPoE 182: O PADS R:e028.6ddc.9128 L:9433.d8ba.11bf BD61 May 13 10:00:19.081: [182]PPPoE 182: Unable to Add ANCP Line attributes to the PPPoE Authen attributes May 13 10:00:19.081: ppp182 PPP: Using vpn set call direction May 13 10:00:19.081: ppp182 PPP: Treating connection as a callin May 13 10:00:19.081: ppp182 PPP: Session handle[F50000B6] Session id[182] May 13 10:00:19.081: ppp182 LCP: Event[OPEN] State[Initial to Starting] May 13 10:00:19.081: ppp182 PPP LCP: Enter passive mode, state[Stopped] May 13 10:00:19.081: ppp182 LCP: I CONFREQ [Stopped] id 1 len 14 May 13 10:00:19.082: ppp182 LCP: MRU 1492 (0x010405D4) May 13 10:00:19.082: ppp182 LCP: MagicNumber 0x0158605F (0x05060158605F) May 13 10:00:19.082: ppp182 LCP: O CONFREQ [Stopped] id 1 len 19 May 13 10:00:19.082: ppp182 LCP: MRU 1492 (0x010405D4) May 13 10:00:19.082: ppp182 LCP: AuthProto MS-CHAP-V2 (0x0305C22381) May 13 10:00:19.082: ppp182 LCP: MagicNumber 0xD84DCEB9 (0x0506D84DCEB9) May 13 10:00:19.082: [182]PPPoE 182: O May 13 10:00:19.082: ppp182 LCP: O CONFACK [Stopped] id 1 len 14 May 13 10:00:19.082: ppp182 LCP: MRU 1492 (0x010405D4) May 13 10:00:19.082: ppp182 LCP: MagicNumber 0x0158605F (0x05060158605F) May 13 10:00:19.082: [182]PPPoE 182: O May 13 10:00:19.082: ppp182 LCP: Event[Receive ConfReq+] State[Stopped to ACKsent] May 13 10:00:19.082: ppp182 LCP: I CONFNAK [ACKsent] id 1 len 9 May 13 10:00:19.082: ppp182 LCP: AuthProto CHAP (0x0305C22305) May 13 10:00:19.082: ppp182 LCP: O CONFREQ [ACKsent] id 2 len 18 May 13 10:00:19.082: ppp182 LCP: MRU 1492 (0x010405D4) May 13 10:00:19.082: ppp182 LCP: AuthProto PAP (0x0304C023) May 13 10:00:19.082: ppp182 LCP: MagicNumber 0xD84DCEB9 (0x0506D84DCEB9) May 13 10:00:19.082: [182]PPPoE 182: O May 13 10:00:19.082: ppp182 LCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent] May 13 10:00:19.083: ppp182 LCP: I CONFACK [ACKsent] id 2 len 18 May 13 10:00:19.083: ppp182 LCP: MRU 1492 (0x010405D4) May 13 10:00:19.083: ppp182 LCP: AuthProto PAP (0x0304C023) May 13 10:00:19.083: ppp182 LCP: MagicNumber 0xD84DCEB9 (0x0506D84DCEB9) May 13 10:00:19.083: ppp182 LCP: Event[Receive ConfAck] State[ACKsent to Open] May 13 10:00:19.083: ppp182 PPP: Queue PAP code[1] id[1] May 13 10:00:19.090: ppp182 PPP: Phase is AUTHENTICATING, by this end May 13 10:00:19.090: ppp182 PAP: Redirect packet to ppp182 May 13 10:00:19.090: ppp182 PAP: I AUTH-REQ id 1 len 38 from "user1@login.mydomain.com" May 13 10:00:19.090: ppp182 PAP: Authenticating peer user1@login.mydomain.com May 13 10:00:19.090: ppp182 PPP: Phase is FORWARDING, Attempting Forward May 13 10:00:19.090: ppp182 LCP: State is Open May 13 10:00:19.090: ppp182 PPP: Phase is AUTHENTICATING, Unauthenticated User May 13 10:00:19.090: ppp182 PPP: Sent PAP LOGIN Request May 13 10:00:19.090: RADIUS/ENCODE(000000DD):Orig. component type = PPPoE May 13 10:00:19.090: RADIUS: DSL line rate attributes successfully added May 13 10:00:19.090: RADIUS/ENCODE: Skip encoding 0 length AAA attribute formatted-clid May 13 10:00:19.090: RADIUS: Format E value 0xF for character S with bitmask 0xF May 13 10:00:19.090: RADIUS: Format E port 0xF with bit 4 processed May 13 10:00:19.090: RADIUS: Format E value 0x0 for character A with bitmask 0xF May 13 10:00:19.090: RADIUS: Format E port 0xF0 with bit 8 processed May 13 10:00:19.090: RADIUS: Format E value 0x5 for character P with bitmask 0xF May 13 10:00:19.090: RADIUS: Format E port 0xF05 with bit 12 processed May 13 10:00:19.090: RADIUS: Format E value 0x0 for character V with bitmask 0xFFFFF May 13 10:00:19.090: RADIUS: Format E port 0xF0500000 with bit 32 processed May 13 10:00:19.090: RADIUS(000000DD): Config NAS IP: 10.0.25.8 May 13 10:00:19.090: vrfid: [65535] ipv6 tableid : [0] May 13 10:00:19.090: idb is NULL May 13 10:00:19.090: RADIUS(000000DD): Config NAS IPv6: :: May 13 10:00:19.090: RADIUS(000000DD): Send Access-Request to 192.168.203.132:1812 id 1645/164, len 168 May 13 10:00:19.090: RADIUS(000000DD): Sending a IPv4 Radius Packet May 13 10:00:19.091: RADIUS(000000DD): Started 5 sec timeout May 13 10:00:19.096: RADIUS: Received from id 1645/164 192.168.203.132:1812, Access-Accept, len 90 May 13 10:00:19.096: RADIUS/DECODE: unsupported WISPr VSA 8; IGNORE May 13 10:00:19.096: RADIUS/DECODE: unsupported WISPr VSA 7; IGNORE RADIUS/DECODE: Reply-Message fragments, 14, total 14 bytes May 13 10:00:19.096: ppp182 PPP: Received LOGIN Response PASS May 13 10:00:19.096: ppp182 PPP: Phase is FORWARDING, Attempting Forward May 13 12:00:19.098: %SYS-5-CONFIG_P: Configured programmatically by process VTEMPLATE Background Mgr from console as console May 13 10:00:19.098: [182]PPPoE 182: State LCP_NEGOTIATION Event SSS CONNECT LOCAL May 13 10:00:19.099: [182]PPPoE 182: Segment (SSS class): UPDATED May 13 10:00:19.099: [182]PPPoE 182: Segment (SSS class): BOUND May 13 10:00:19.099: [182]PPPoE 182: data path set to Virtual Acess May 13 10:00:19.099: [182]PPPoE 182: State LCP_NEGOTIATION Event SSM UPDATED May 13 10:00:19.099: Vi2.1 PPP: Phase is AUTHENTICATING, Authenticated User May 13 10:00:19.099: Vi2.1 PAP: O AUTH-ACK id 1 len 5 May 13 10:00:19.099: [182]PPPoE 182: O May 13 10:00:19.099: dyn_attrs->xmit_rate: 1000000000 dyn_attrs->rcv_rate: 1000000000 May 13 10:00:19.099: [182]PPPoE 182: AAA get dynamic attrs May 13 10:00:19.100: Vi2.1 PPP: Phase is UP May 13 10:00:19.100: Vi2.1 IPCP: Protocol configured, start CP. state[Initial] May 13 10:00:19.100: Vi2.1 IPCP: Event[OPEN] State[Initial to Starting] May 13 10:00:19.100: Vi2.1 IPCP: O CONFREQ [Starting] id 1 len 10 May 13 10:00:19.100: Vi2.1 IPCP: Address 117.213.177.74 (0x0306D971B14A) May 13 10:00:19.100: [182]PPPoE 182: O May 13 10:00:19.100: Vi2.1 IPCP: Event[UP] State[Starting to REQsent] May 13 10:00:19.100: RADIUS/ENCODE(000000DD):Orig. component type = PPPoE May 13 10:00:19.100: RADIUS/ENCODE(000000DD): Acct-session-id pre-pended with Nas Port = ether 15/0/5:4096.0 0/0/0/0/0/0 May 13 10:00:19.100: RADIUS/ENCODE: Skip encoding 0 length AAA attribute formatted-clid May 13 10:00:19.100: RADIUS: Format E value 0xF for character S with bitmask 0xF May 13 10:00:19.100: RADIUS: Format E port 0xF with bit 4 processed May 13 10:00:19.100: RADIUS: Format E value 0x0 for character A with bitmask 0xF May 13 10:00:19.100: RADIUS: Format E port 0xF0 with bit 8 processed May 13 10:00:19.100: RADIUS: Format E value 0x5 for character P with bitmask 0xF May 13 10:00:19.100: RADIUS: Format E port 0xF05 with bit 12 processed May 13 10:00:19.100: RADIUS: Format E value 0x0 for character V with bitmask 0xFFFFF May 13 10:00:19.100: RADIUS: Format E port 0xF0500000 with bit 32 processed May 13 10:00:19.100: RADIUS(000000DD): Config NAS IP: 10.0.25.8 May 13 10:00:19.100: vrfid: [65535] ipv6 tableid : [0] May 13 10:00:19.100: idb is NULL May 13 10:00:19.100: RADIUS(000000DD): Config NAS IPv6: :: May 13 10:00:19.100: [182]PPPoE 182: State PTA_BINDING Event STATIC BIND RESPONSE May 13 10:00:19.100: [182]PPPoE 182: Connected PTA May 13 10:00:19.100: RADIUS(000000DD): Send Accounting-Request to 192.168.203.132:1813 id 1646/129, len 242 May 13 10:00:19.100: RADIUS(000000DD): Sending a IPv4 Radius Packet May 13 10:00:19.100: RADIUS(000000DD): Started 5 sec timeout May 13 10:00:19.100: Vi2.1 IPCP: I CONFREQ [REQsent] id 2 len 22 May 13 10:00:19.100: Vi2.1 IPCP: Address 0.0.0.0 (0x030600000000) May 13 10:00:19.100: Vi2.1 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000) May 13 10:00:19.100: Vi2.1 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000) May 13 10:00:19.100: Vi2.1 IPCP AUTHOR: Done. Her address 0.0.0.0, we want 0.0.0.0 May 13 10:00:19.100: Vi2.1 IPCP: No peer address configured May 13 10:00:19.100: Vi2.1 IPCP: Neither side knows remote address May 13 10:00:19.100: Vi2.1 IPCP: Dual NCP check. V6 status from Ctx 1 May 13 10:00:19.100: Vi2.1 PPP DISC: Peer address required May 13 10:00:19.100: Vi2.1 PPP: Sending Acct Event[Down] id[DD] May 13 10:00:19.100: dyn_attrs->xmit_rate: 1000000000 dyn_attrs->rcv_rate: 1000000000 May 13 10:00:19.100: [182]PPPoE 182: AAA get dynamic attrs May 13 10:00:19.100: PPP: NET STOP send to AAA. May 13 10:00:19.100: Vi2.1 IPCP: O TERMREQ [REQsent] id 2 len 4 May 13 10:00:19.100: [182]PPPoE 182: O May 13 10:00:19.100: Vi2.1 IPCP: Event[CLOSE] State[REQsent to Closing] May 13 10:00:19.100: Vi2.1 IPV6CP: LCP not open, discarding packet May 13 10:00:19.100: Vi2.1 IPCP: Event[DOWN] State[Closing to Initial] May 13 10:00:19.100: Vi2.1 IPCP: Event[CLOSE] State[Initial to Initial] May 13 10:00:19.101: Vi2.1 LCP: O TERMREQ [Open] id 3 len 4 May 13 10:00:19.101: [182]PPPoE 182: O May 13 10:00:19.101: Vi2.1 LCP: Event[CLOSE] State[Open to Closing] May 13 10:00:19.101: Vi2.1 PPP: Phase is TERMINATING May 13 10:00:19.101: RADIUS/ENCODE(000000DD):Orig. component type = PPPoE May 13 10:00:19.101: RADIUS/ENCODE(000000DD): Acct-session-id pre-pended with Nas Port = ether 15/0/5:4096.0 0/0/0/0/0/0 May 13 10:00:19.101: RADIUS/ENCODE: Skip encoding 0 length AAA attribute formatted-clid May 13 10:00:19.101: RADIUS: Format E value 0xF for character S with bitmask 0xF May 13 10:00:19.101: RADIUS: Format E port 0xF with bit 4 processed May 13 10:00:19.101: RADIUS: Format E value 0x0 for character A with bitmask 0xF May 13 10:00:19.101: RADIUS: Format E port 0xF0 with bit 8 processed May 13 10:00:19.101: RADIUS: Format E value 0x5 for character P with bitmask 0xF May 13 10:00:19.101: RADIUS: Format E port 0xF05 with bit 12 processed May 13 10:00:19.101: RADIUS: Format E value 0x0 for character V with bitmask 0xFFFFF May 13 10:00:19.101: RADIUS: Format E port 0xF0500000 with bit 32 processed May 13 10:00:19.101: RADIUS(000000DD): Config NAS IP: 10.0.25.8 May 13 10:00:19.101: vrfid: [65535] ipv6 tableid : [0] May 13 10:00:19.101: idb is NULL May 13 10:00:19.101: RADIUS(000000DD): Config NAS IPv6: :: May 13 10:00:19.101: RADIUS(000000DD): Send Accounting-Request to 192.168.203.132:1813 id 1646/130, len 492 May 13 10:00:19.101: RADIUS(000000DD): Sending a IPv4 Radius Packet May 13 10:00:19.101: RADIUS(000000DD): Started 5 sec timeout May 13 10:00:19.101: Vi2.1 LCP: I TERMACK [Closing] id 3 len 4 May 13 10:00:19.101: Vi2.1 LCP: Event[Receive TermAck] State[Closing to Closed] May 13 10:00:19.101: Vi2.1 LCP: Event[DOWN] State[Closed to Initial] May 13 10:00:19.101: ppp_session_ntfy delete, topswidb Vi2.1, va Vi2.1, platform notify 0 May 13 10:00:19.101: Vi2.1 PPP: Phase is DOWN May 13 10:00:19.101: [182]PPPoE 182: State LOCALLY_TERMINATED Event PPP DISCONNECT May 13 10:00:19.101: [182]PPPoE 182: O PADT R:e028.6ddc.9128 L:9433.d8ba.11bf BD61 May 13 10:00:19.101: [182]PPPoE 182: Destroying R:e028.6ddc.9128 L:9433.d8ba.11bf BD61 May 13 10:00:19.101: PPPoE: Returning Vaccess Virtual-Access2.1 May 13 10:00:19.102: [182]PPPoE 182: AAA account stopped May 13 10:00:19.102: PPPoE 182: I PADT R:e028.6ddc.9128 L:9433.d8ba.11bf BD61 May 13 10:00:19.102: [182]PPPoE 182: Segment (SSS class): UNBOUND May 13 10:00:19.102: [182]PPPoE 182: Vi2.1 Block vaccess from being freed. May 13 10:00:19.103: [182]PPPoE 182: Segment (SSS class): UNPROVISION May 13 12:00:19.103: %SYS-5-CONFIG_P: Configured programmatically by process VTEMPLATE Background Mgr from console as console May 13 10:00:19.104: RADIUS: Removing all radius source-int. pointing to Virtual-Access2.1
Here is the important point, but why?
May 13 10:00:19.100: Vi2.1 IPCP: I CONFREQ [REQsent] id 2 len 22 May 13 10:00:19.100: Vi2.1 IPCP: Address 0.0.0.0 (0x030600000000) May 13 10:00:19.100: Vi2.1 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000) May 13 10:00:19.100: Vi2.1 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000) May 13 10:00:19.100: Vi2.1 IPCP AUTHOR: Done. Her address 0.0.0.0, we want 0.0.0.0 May 13 10:00:19.100: Vi2.1 IPCP: No peer address configured May 13 10:00:19.100: Vi2.1 IPCP: Neither side knows remote address
Thank you and best regards
Michael
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide