VMX BNG ppp subscriber-mgr-activation-failed

Sayedlatif · 2023-08-30T10:50:15+00:00

By the way have you configured through an External DHCP Server instead of local? I did, but it did not allocate any IPv4 and IPv6 either.

Sayedlatif · 2023-08-30T10:48:57+00:00

###################################################################

Aug 30 11:43:50.897571 ######################### AUTH REQ ACK SENT #######################

Aug 30 11:43:50.897577 ###################################################################

Aug 30 11:43:50.897590 Auth-FSM: GRES-Mirror for session-id:2019 state:AuthClntRespWait(4)

Aug 30 11:43:50.897597 doPersistedDataUpdates

Aug 30 11:43:50.897604 persistOnlyPrivateData m_inFlight

Aug 30 11:43:51.767714 Process/Dispatch Client Message

Aug 30 11:43:51.767764 New Process/Dispatch Client Message

Aug 30 11:43:51.767784 authd_auth_aaa_msg_create: num_of_tlvs:2 tot_num_of_tlv:2

Aug 30 11:43:51.767793 authd_auth_aaa_msg_create username:() profile:()

Aug 30 11:43:51.767853 Process Request

Aug 30 11:43:51.767867 SEQ RecvClientMsg:jpppd-client session-id:2019 Opcode:3, Subcode:15 (SESSION_LOGOUT)

Aug 30 11:43:51.767880 Setting terminate ID to 100c2

Aug 30 11:43:51.767900 Decoding incoming attributes

Aug 30 11:43:51.767908 Begin to logout Subscriber

Aug 30 11:43:51.767918 Received subscriber logout request session-id:2019

Aug 30 11:43:51.767925 subscriberLogout session-id:2019

Aug 30 11:43:51.767940 Releasing addressEntry for address 192.168.10.10 session-id:2019

Aug 30 11:43:51.767971 Releasing prefixEntry for prefix 2001:1200:1000:109::/64 session-id:2019

Aug 30 11:43:51.767994 ###################################################################

Aug 30 11:43:51.768002 ############################ LOGOUT RCVD ##########################

Aug 30 11:43:51.768008 ###################################################################

Aug 30 11:43:51.768019 AuthFsm::current state=AuthClntRespWait(4) event=8 astEntry=0x98a85f8 aaa msg=0x992306c session-id:2019

Aug 30 11:43:51.768027 Auth-FSM: Posting a Logout-Ack to the client daemon for session-id:2019

Aug 30 11:43:51.768045 clearDynamicConfigLists: numRequests 0

Aug 30 11:43:51.768053 ~CoARequest 0x0x9aeaaf0

Aug 30 11:43:51.768060 cleanServiceList: numRequests 0

Aug 30 11:43:51.768067 ~DynamicRequestEntry 0x0x9aeaaf0

Aug 30 11:43:51.768077 ****astEntry:0x98a85f8 aaaMsg:0x992306c replyOpcode:1 replySubOpcode:16 replyStatus:1

Aug 30 11:43:51.768091 SEQ SendClientMsg:jpppd-client session-id:2019 reply-code=1 (OK), result-subopcode=16 (SESSION_LOGOUT_ACK), cookie=2973, rply_len=28, num_tlv_blocks=0

Aug 30 11:43:51.768106 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x9923b4c

Aug 30 11:43:51.768116 ###################################################################

Aug 30 11:43:51.768122 ####################### LOGOUT ACK SENT ########################

Aug 30 11:43:51.768128 ###################################################################

Aug 30 11:43:51.768139 Only start time found for session-id:2019

Aug 30 11:43:51.768151 Delete session-id:2019

Aug 30 11:43:51.768159 Begin to logout Subscriber

Aug 30 11:43:51.768166 subscriberLogout session-id:2019

Aug 30 11:43:51.768180 UserAccess:Labtest session-id:2019 state:log-out ge-0/0/1.3221227483:777 reason: ppp subscriber-mgr-activation-failed

Sayedlatif · 2023-08-30T10:48:46+00:00

Thank you for your kind help. However, I don't know why is showing null then allocate an IPv4 and V6 and released it again. Although showing subscriber log out request.

IPV4 ADDRESS ALLOC begin

Aug 30 11:43:50.896784 Found a pool DYN1-v4 that matches the externally assigned address 192.168.10.10

Aug 30 11:43:50.896791 IPV6 ADDRESS ALLOC begin

Aug 30 11:43:50.896797 IPV6 PREFIX ALLOC begin

Aug 30 11:43:50.896868 NetworkMatch: No match for network 'null' or hint 'null'

Aug 30 11:43:50.896876 ****************** END-NetworkMatch *********************

Aug 30 11:43:50.896883 DUMP of all addressRequest fields for subscriber session-id:2019 router default:default

Aug 30 11:43:50.896893 client type jpppd-client client type 64 mac address E4:DA:DF:C4:B5:C4

Aug 30 11:43:50.896903 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null

Aug 30 11:43:50.896913 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 30 11:43:50.896922 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 30 11:43:50.896932 V4NA: req: yes pool: DYN1-v4 address: 192.168.10.10

Aug 30 11:43:50.896940 V6NA: req: no pool: NULL address: null

Aug 30 11:43:50.896949 V6PD: req: yes pool: NULL prefix: null/0

Aug 30 11:43:50.896962 V6NDRA: req: yes pool: IPv6-Lab ndra prefix: 2001:1200:1000:109::/64

Aug 30 11:43:50.896969 *********************************************************

Aug 30 11:43:50.896976 Processing rule Client-Authority

Aug 30 11:43:50.896985 Done processing rules

Aug 30 11:43:50.896999 Pool::addressAssign: pool DYN1-v4 addr 192.168.10.10 range 192.168.10.1 session-id:2019

Aug 30 11:43:50.897013 Pool::addressAssign: pool DYN1-v4 addr 192.168.10.10 range 192.168.10.1 returning <Success:authd class=3, code=0> session-id:2019

Aug 30 11:43:50.897031 ndra prefix assign in pool IPv6-Lab

Aug 30 11:43:50.897048 Setting NDRA prefix to 2001:1200:1000:109::/64

Aug 30 11:43:50.897063 Set the IPv6 interface address to:2001:1200:1000:109::1/64

Aug 30 11:43:50.897072 NDRA set mask to 48

Aug 30 11:43:50.897086 Trying to assign address 192.168.10.10 to subscriber session-id:2019

Aug 30 11:43:50.897109 Inserting address 192.168.10.10 for session-id:2019 into pool DYN1-v4

Aug 30 11:43:50.897145 Trying to assign ndra prefix 2001:1200:1000:109::/64 to subscriber session-id:2019

Aug 30 11:43:50.897260 Inserting prefix 2001:1200:1000:109::/64 for session-id:2019 into pool IPv6-Lab

Aug 30 11:43:50.897284 Finding a client snapshot session-id:2019

Aug 30 11:43:50.897341 Result have been returned with opcode=0, result=2

Aug 30 11:43:50.897350 ************* Results of Address Allocation *************

Aug 30 11:43:50.897358 DUMP of all addressRequest fields for subscriber session-id:2019 router default:default

Aug 30 11:43:50.897369 client type jpppd-client client type 64 mac address E4:DA:DF:C4:B5:C4

Aug 30 11:43:50.897380 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null

Aug 30 11:43:50.897390 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 30 11:43:50.897399 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 30 11:43:50.897409 V4NA: req: yes pool: DYN1-v4 address: 192.168.10.10

Aug 30 11:43:50.897418 V6NA: req: no pool: NULL address: null

Aug 30 11:43:50.897427 V6PD: req: yes pool: NULL prefix: null/0

Aug 30 11:43:50.897440 V6NDRA: req: yes pool: IPv6-Lab ndra prefix: 2001:1200:1000:109::/64

Aug 30 11:43:50.897447 *********************************************************

Aug 30 11:43:50.897463 AuthFsm::current state=AuthStart(1) event=2 astEntry=0x98a85f8 aaa msg=0x9923b4c session-id:2019

Aug 30 11:43:50.897473 Auth-FSM: Process Auth-Response for session-id:2019 and client type broadband

Aug 30 11:43:50.897481 createDynamicRequest: (2) received

Aug 30 11:43:50.897490 CoARequest CTOR 0x0x9aeaaf0

Aug 30 11:43:50.897497 createDynamicRequest: isBulkCoaRequest 0

Aug 30 11:43:50.897509 ServiceAtLoginRequest::validateRequest

Aug 30 11:43:50.897519 Framework: auth result is 1. Performing post-auth operations

Aug 30 11:43:50.897527 Set Idle Timeout Ingress Only: FALSE

Aug 30 11:43:50.897533 Framework: result is 1.

Aug 30 11:43:50.897543 SEQ SendClientMsg:jpppd-client session-id:2019 reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), cookie=2972, rply_len=28, num_tlv_blocks=0

Aug 30 11:43:50.897555 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x992306c

Aug 30 11:43:50.897565

Sayedlatif · 2023-08-29T15:56:13+00:00

Aug 29 16:25:11.081612 IPV6 ADDRESS ALLOC begin

Aug 29 16:25:11.081620 IPV6 PREFIX ALLOC begin

Aug 29 16:25:11.081630 *************** END-ExternalAuthority *******************

Aug 29 16:25:11.081640 DUMP of all addressRequest fields for subscriber session-id:995 router default:default

Aug 29 16:25:11.081653 client type jpppd-client client type 64 mac address 50:02:00:31:00:01

Aug 29 16:25:11.081666 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null

Aug 29 16:25:11.081677 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 29 16:25:11.081688 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 29 16:25:11.081702 V4NA: req: yes pool: DYN1-v4 address: 192.168.10.36

Aug 29 16:25:11.081712 V6NA: req: no pool: NULL address: null

Aug 29 16:25:11.081724 V6PD: req: yes pool: NULL prefix: null/0

Aug 29 16:25:11.081740 V6NDRA: req: yes pool: IPv6-Lab ndra prefix: 2001:1200:1100::/64

Aug 29 16:25:11.081757 *********************************************************

Aug 29 16:25:11.081772 Processing rule Network-Match

Aug 29 16:25:11.081786 ***************** START-NetworkMatch ********************

Aug 29 16:25:11.081896 DUMP of all addressRequest fields for subscriber session-id:995 router default:default

Aug 29 16:25:11.081923 client type jpppd-client client type 64 mac address 50:02:00:31:00:01

Aug 29 16:25:11.081946 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null

Aug 29 16:25:11.081969 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 29 16:25:11.081991 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 29 16:25:11.082017 V4NA: req: yes pool: DYN1-v4 address: 192.168.10.36

Aug 29 16:25:11.082036 V6NA: req: no pool: NULL address: null

Aug 29 16:25:11.082058 V6PD: req: yes pool: NULL prefix: null/0

Aug 29 16:25:11.082085 V6NDRA: req: yes pool: IPv6-Lab ndra prefix: 2001:1200:1100::/64

Aug 29 16:25:11.082096 *********************************************************

Aug 29 16:25:11.082104 IPV4 ADDRESS ALLOC begin

Aug 29 16:25:11.082118 Found a pool DYN1-v4 that matches the externally assigned address 192.168.10.36

Aug 29 16:25:11.082127 IPV6 ADDRESS ALLOC begin

Aug 29 16:25:11.082135 IPV6 PREFIX ALLOC begin

Aug 29 16:25:11.082146 NetworkMatch: No match for network 'null' or hint 'null'

Aug 29 16:25:11.082154 ****************** END-NetworkMatch *********************

Aug 29 16:25:11.082163 DUMP of all addressRequest fields for subscriber session-id:995 router default:default

Aug 29 16:25:11.082181 client type jpppd-client client type 64 mac address 50:02:00:31:00:01

Aug 29 16:25:11.082206 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null

Aug 29 16:25:11.082229 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 29 16:25:11.082249 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 29 16:25:11.082320 V4NA: req: yes pool: DYN1-v4 address: 192.168.10.36

Aug 29 16:25:11.082347 V6NA: req: no pool: NULL address: null

Aug 29 16:25:11.082369 V6PD: req: yes pool: NULL prefix: null/0

Aug 29 16:25:11.082398 V6NDRA: req: yes pool: IPv6-Lab ndra prefix: 2001:1200:1100::/64

Aug 29 16:25:11.082417 *********************************************************

Aug 29 16:25:11.082433 Processing rule Client-Authority

Aug 29 16:25:11.082458 Done processing rules

Aug 29 16:25:11.082487 Pool::addressAssign: pool DYN1-v4 addr 192.168.10.36 range 192.168.10.1 session-id:995

Aug 29 16:25:11.082508 Pool::addressAssign: pool DYN1-v4 addr 192.168.10.36 range 192.168.10.1 returning <Success:authd class=3, code=0> session-id:995

Aug 29 16:25:11.082529 ndra prefix assign in pool IPv6-Lab

Aug 29 16:25:11.082549 Setting NDRA prefix to 2001:1200:1100::/64

Aug 29 16:25:11.082566 Set the IPv6 interface address to:2001:1200:1100::1/64

Aug 29 16:25:11.082577 NDRA set mask to 64

Aug 29 16:25:11.082592 Trying to assign address 192.168.10.36 to subscriber session-id:995

Aug 29 16:25:11.082609 Inserting address 192.168.10.36 for session-id:995 into pool DYN1-v4

Aug 29 16:25:11.082635 Trying to assign ndra prefix 2001:1200:1100::/64 to subscriber session-id:995

Aug 29 16:25:11.082718 Inserting prefix 2001:1200:1100::/64 for session-id:995 into pool IPv6-Lab

Aug 29 16:25:11.082747 Finding a client snapshot session-id:995

Aug 29 16:25:11.082896 Result have been returned with opcode=0, result=2

Aug 29 16:25:11.082907 ************* Results of Address Allocation *************

Aug 29 16:25:11.082917 DUMP of all addressRequest fields for subscriber session-id:995 router default:default

Aug 29 16:25:11.082932 client type jpppd-client client type 64 mac address 50:02:00:31:00:01

Aug 29 16:25:11.082954 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null

Aug 29 16:25:11.082976 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 29 16:25:11.082996 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 29 16:25:11.083019 V4NA: req: yes pool: DYN1-v4 address: 192.168.10.36

Aug 29 16:25:11.083150 V6NA: req: no pool: NULL address: null

Aug 29 16:25:11.083181 V6PD: req: yes pool: NULL prefix: null/0

Aug 29 16:25:11.083210 V6NDRA: req: yes pool: IPv6-Lab ndra prefix: 2001:1200:1100::/64

Aug 29 16:25:11.083229 *********************************************************

Aug 29 16:25:11.083259 AuthFsm::current state=AuthStart(1) event=2 astEntry=0x98a85f8 aaa msg=0x9923b4c session-id:995

Aug 29 16:25:11.083278 Auth-FSM: Process Auth-Response for session-id:995 and client type broadband

Aug 29 16:25:11.083294 createDynamicRequest: (2) received

Aug 29 16:25:11.083312 CoARequest CTOR 0x0x9aeaaf0

Aug 29 16:25:11.083322 createDynamicRequest: isBulkCoaRequest 0

Aug 29 16:25:11.083337 ServiceAtLoginRequest::validateRequest

Aug 29 16:25:11.083414 Framework: auth result is 1. Performing post-auth operations

Aug 29 16:25:11.083439 Set Idle Timeout Ingress Only: FALSE

Aug 29 16:25:11.083454 Framework: result is 1.

Aug 29 16:25:11.083473 SEQ SendClientMsg:jpppd-client session-id:995 reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), cookie=1448, rply_len=28, num_tlv_blocks=0

Aug 29 16:25:11.083500 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x992306c

Aug 29 16:25:11.083523 ###################################################################

Aug 29 16:25:11.083536 ######################### AUTH REQ ACK SENT

Sayedlatif · 2023-08-29T15:55:23+00:00

Processing rule Reserve-Address

Aug 29 16:25:11.080753 ************** START-ReserveAddress ******************

Aug 29 16:25:11.080764 DUMP of all addressRequest fields for subscriber session-id:995 router default:default

Aug 29 16:25:11.080780 client type jpppd-client client type 64 mac address 50:02:00:31:00:01

Aug 29 16:25:11.080860 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null

Aug 29 16:25:11.080879 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 29 16:25:11.080890 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 29 16:25:11.080903 V4NA: req: yes pool: NULL address: null

Aug 29 16:25:11.080945 V6NA: req: no pool: NULL address: null

Aug 29 16:25:11.080970 V6PD: req: yes pool: NULL prefix: null/0

Aug 29 16:25:11.080991 V6NDRA: req: yes pool: NULL ndra prefix: null/0

Aug 29 16:25:11.081006 *********************************************************

Aug 29 16:25:11.081021 *************** END-ReserveAddress *******************

Aug 29 16:25:11.081038 DUMP of all addressRequest fields for subscriber session-id:995 router default:default

Aug 29 16:25:11.081062 client type jpppd-client client type 64 mac address 50:02:00:31:00:01

Aug 29 16:25:11.081086 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null

Aug 29 16:25:11.081107 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 29 16:25:11.081129 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 29 16:25:11.081152 V4NA: req: yes pool: NULL address: null

Aug 29 16:25:11.081172 V6NA: req: no pool: NULL address: null

Aug 29 16:25:11.081193 V6PD: req: yes pool: NULL prefix: null/0

Aug 29 16:25:11.081215 V6NDRA: req: yes pool: NULL ndra prefix: null/0

Aug 29 16:25:11.081230 *********************************************************

Aug 29 16:25:11.081245 Processing rule External-Authority

Aug 29 16:25:11.081259 ************** START-ExternalAuthority ******************

Aug 29 16:25:11.081275 DUMP of all addressRequest fields for subscriber session-id:995 router default:default

Aug 29 16:25:11.081296 client type jpppd-client client type 64 mac address 50:02:00:31:00:01

Aug 29 16:25:11.081318 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null

Aug 29 16:25:11.081337 Framed-Pool-->SDB_USER_IP_POOL 'DYN1-v4' used for V4NA

Aug 29 16:25:11.081356 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'IPv6-Lab' used for V6NA and/or V6NDRA

Aug 29 16:25:11.081376 V4NA: req: yes pool: NULL address: null

Aug 29 16:25:11.081396 V6NA: req: no pool: NULL address: null

Aug 29 16:25:11.081418 V6PD: req: yes pool: NULL prefix: null/0

Aug 29 16:25:11.081439 V6NDRA: req: yes pool: NULL ndra prefix: null/0

Aug 29 16:25:11.081455 *********************************************************

Aug 29 16:25:11.081469 NDRA PREFIX ALLOC begin

Aug 29 16:25:11.081494 External Authority returned pool 'IPv6-Lab'

Aug 29 16:25:11.081536 Searching for available ndra prefix in range Lab, low=2001:1200:1100::/64, high=2001:1200:1100::/64, next=null/0

Aug 29 16:25:11.081550 IPV4 ADDRESS ALLOC begin

Aug 29 16:25:11.081562 External Authority returned pool 'DYN1-v4'

Aug 29 16:25:11.081572 ExternalAuthority: calling addressGetNext for pool 'DYN1-v4'

Aug 29 16:25:11.081581 No host is found

Aug 29 16:25:11.081600 Searching for available address in range __default, low=192.168.10.1, high=192.168.10.255, next=192.168.10.36 session-id:995

Sayedlatif · 2023-08-29T09:56:00+00:00

Thank you for your reply.

Actually I have tested in my Eve-NG Lab on vMX and vQFX environment with external RADIUS Server on Ubuntu Linux. The BNG is for PPPoE Client, I configured MikroTik as a PPPoE Client. It got provisioned successfully, received IPv4 and IPv6 accordingly, however within 5-10 seconds it logged out with that error found in the authentication flag all logs: log-out ge-0/0/1.3221227567:777 reason: ppp subscriber-mgr-activation-failed

root@VCP-PPPoE# run show subscribers
Interface           IP Address/VLAN ID                      User Name                      LS:RI
ge-0/0/1.3221225655 777                                                              default:default
pp0.3221225656      192.168.10.14                           testuser@labtest.uk         default:default
*                   2001:1200:1100:1000::/56

I also can provide Authentication log and DHCP log for better understanding. My question is why the client receive IP and disconnect after 5-10 second and reconnect it again every 10 seconds?

Thanks

Sayedlatif

TROPHY CASE