show log general.log Aug 3 16:02:41.998547 Process/Dispatch Client Message Aug 3 16:02:41.998571 New Process/Dispatch Client Message Aug 3 16:02:41.998585 authd_tlv_build_list_from_struct username l =1 offset =56 Aug 3 16:02:41.998592 authd_tlv_build_list_from_struct profile l =1 offset =57 Aug 3 16:02:41.998599 authd_tlv_build_list_from_struct password l =1 offset =58 Aug 3 16:02:41.998606 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Aug 3 16:02:41.998613 authd_auth_aaa_msg_create username:() profile:() Aug 3 16:02:41.998620 Process Request Aug 3 16:02:41.998628 SEQ RecvClientMsg:jpppd-client session-id:228 Opcode:4929, Subcode:0 (ACCESS_REQUEST) Aug 3 16:02:41.998636 Taking a client snapshot, session-id:228 Aug 3 16:02:41.998654 getSubscriberAaaOptionsName Aug 3 16:02:41.998667 authd_build_req_attr_list_from_sdb_data: The request list is from sdb Aug 3 16:02:41.998680 createSubscriberSession UserName (test) for session-id:228 from SDB Aug 3 16:02:41.998700 Creating SubscriberASTEntry for session-id:228, session name:test Aug 3 16:02:41.998715 fillSessionDBAttributes: session-id:228, ifdName: xe-0/1/7 Aug 3 16:02:41.998724 Found Bbe Flow Id 111 in SDB for session-id:228 Aug 3 16:02:41.998731 No access-profile found in the SDB for session-id:228 Aug 3 16:02:41.998737 Bbe Domain Id found in the SDB for session-id:228 Aug 3 16:02:41.998744 PhyIfdName found in the SDB for session-id:228 Aug 3 16:02:41.998752 InterfaceName found in the SDB for session-id:228 Aug 3 16:02:41.998761 aaa ls:default aaa ri:default; target ls:default target ri: default Aug 3 16:02:41.998768 setTargetRoutingContextdefault:default Aug 3 16:02:41.998775 Querying the access-profile for user:test on LR/RI:default:default Aug 3 16:02:41.998783 Access Profile Name from context is Aug 3 16:02:41.998794 authd_build_radius_nas_port_and_id: nas-port-id-format order is disabled Aug 3 16:02:41.998800 authd_build_req_attr_list_from_sdb_data: The request list is from aaa_msg Aug 3 16:02:41.998808 authd_get_auth_request_nas_attr: No Agent Circuit ID attribute from SDB Aug 3 16:02:41.998814 authd_get_auth_request_nas_attr: No Agent Remote ID attribute from SDB Aug 3 16:02:41.998819 authd_get_auth_request_nas_attr: No interface SVLAN attribute from SDB Aug 3 16:02:41.998825 authd_get_auth_request_nas_attr: No interface ATM VPI attribute from SDB Aug 3 16:02:41.998830 authd_get_auth_request_nas_attr: No interface ATM VCI attribute from SDB Aug 3 16:02:41.998836 authd_get_auth_request_nas_attr: Recovered from SDB - VPI:-1 VCI:-1 NasPortType:15 Aug 3 16:02:41.998853 authd_get_interface_nas_port_options Interface Radius-Options for Interface xe-0/1/7 not found Aug 3 16:02:41.998866 authd_build_radius_nas_port_and_id: NASPortID = TESTE, NASPort = 1c0018f, CallingStationID = Aug 3 16:02:41.998880 Finding a client snapshot session-id:228 Aug 3 16:02:41.998919 Setting multi-acct-session-id to 0 Aug 3 16:02:41.998928 setAccountingInfo: Access-Profile Aug 3 16:02:41.998936 setAccountingInfo: service accounting order 0 Aug 3 16:02:41.998942 updateCoaDynamicVariableValidation coaValidation: 0 Aug 3 16:02:41.998953 JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty Aug 3 16:02:41.998960 Bundle session id not found, setting to NULL Aug 3 16:02:41.998966 multi-acct-session-id set to 0 Aug 3 16:02:41.998973 access profile: Access-Profile Aug 3 16:02:41.998979 On-demand IP address set to 0 Aug 3 16:02:41.998990 UserAccess:test session-id:228 Access-profile:Access-Profile Multi-Acct-Session-Id:0 ACCESS_REQUEST Aug 3 16:02:41.998996 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=() Aug 3 16:02:41.999009 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x9b3406c aaa msg=0x99366d8 session-id:228 Aug 3 16:02:41.999018 ################################################################### Aug 3 16:02:41.999023 ########################### AUTH REQ RCVD ######################### Aug 3 16:02:41.999028 ################################################################### Aug 3 16:02:41.999042 Auth-FSM: Process Auth-Request for session-id:228 username profile Aug 3 16:02:41.999048 Auth-FSM: Process Auth-Request for session-id:228 Aug 3 16:02:41.999054 Framework: Starting authentication Aug 3 16:02:41.999060 authd_advance_module_for_aaa_request_msg: result:0 Aug 3 16:02:41.999068 Authd module start session-id:228 Aug 3 16:02:41.999073 authd_radius_start_auth: Starting RADIUS authentication session-id:228 Aug 3 16:02:41.999098 authd_radius_get_config:Using radius option config from access profile stanza Aug 3 16:02:41.999121 authd_radius_build_basic_auth_request: session-id:228 profile=Access-Profile, username=test Aug 3 16:02:41.999129 radius-access-request: User-Name added: test Aug 3 16:02:41.999207 Failed to correlate access line for UIFL "xe-0/1/7.399" Aug 3 16:02:41.999219 radius-access-request: Service-Type added: 2 Aug 3 16:02:41.999227 radius-access-request: Framed-Protocol added: 1 Aug 3 16:02:41.999235 radius-access-request: CHAP-Password added: "" Aug 3 16:02:41.999243 radius-access-request: CHAP-Challenge added: "" Aug 3 16:02:41.999253 radius-access-request: Chargeable-User-Identity added: Aug 3 16:02:41.999261 radius-access-request: Acct-Session-Id added: 228 Aug 3 16:02:41.999273 radius-access-request: DHCP-MAC-Address (Juniper-ERX-VSA) added: cc06.xxxx.xxxx Aug 3 16:02:41.999293 radius-access-request: NAS-Identifier added: PPPoE-Server Aug 3 16:02:41.999302 radius-access-request: NAS-Port tunnel client nas port is not found Aug 3 16:02:41.999310 radius-access-request: NAS-Port added: 01 c0 01 8f Aug 3 16:02:41.999317 radius-access-request: NAS-Port-Id added: TESTE Aug 3 16:02:41.999323 radius-access-request: NAS-Port-Type added: 5 Aug 3 16:02:41.999334 radius-access-request: PPPoE-Description (Juniper-ERX-VSA) added: pppoe cc:xx:xx:xxxx:xx Aug 3 16:02:41.999359 authd_create_application_specific_radius_server: Evaluating RADIUS server x.x.x.x to add to the server list Aug 3 16:02:41.999367 Evaluating RADIUS server x.x.x.x to add to the server list Aug 3 16:02:41.999373 Verify source address bad10fae in routing instance index=0 Aug 3 16:02:41.999403 authd_radius_server_add: server x.x.x.x retry 4, timeout 3 Aug 3 16:02:41.999418 authd_create_application_specific_radius_server: Evaluating RADIUS server y.y.y.y to add to the server list Aug 3 16:02:41.999423 Evaluating RADIUS server y.y.y.y to add to the server list Aug 3 16:02:41.999429 Verify source address bad10fae in routing instance index=0 Aug 3 16:02:41.999446 authd_radius_server_add: server y.y.y.y retry 4, timeout 3 Aug 3 16:02:41.999454 processSessionAttributeNasAddress 228 Aug 3 16:02:41.999459 processSessionAttributeNasAddress return false Aug 3 16:02:41.999471 authd_radius_get_config:Using radius option config from access profile stanza Aug 3 16:02:41.999521 Request queued successfully Aug 3 16:02:41.999532 REQUEST: AUTHEN - module_index 0 module(radius) return: ASYNC Aug 3 16:02:41.999541 UserAccess:test session-id:228 state:start TESTE Aug 3 16:02:41.999549 Auth-FSM: GRES-Mirror for session-id:228 state:AuthStart(1) Aug 3 16:02:42.004258 authd_radius_get_config:Using radius option config from access profile stanza Aug 3 16:02:42.004270 RadiusServer: server[0] used for last request - x.x.x.x Aug 3 16:02:42.004287 loadDefaultService:: default service for the subscriber is empty Aug 3 16:02:42.004294 Radius result is CLIENT_REQ_STATUS_SUCCESS Aug 3 16:02:42.004305 Parsing RADIUS message for session-id:228 Aug 3 16:02:42.004316 radius-access-accept: Framed-Protocol received: 1 Aug 3 16:02:42.004322 RADIUS Attribute: Parse Error: "Unsupported attribute type" Radius Standard Attr-Type: 13 Aug 3 16:02:42.004338 radius-access-accept: Framed-MTU received: 1500 Aug 3 16:02:42.004347 radius-access-accept: Acct-Interim-Interval received: 600 Aug 3 16:02:42.004352 RADIUS Attribute: Parse Error: "Unsupported attribute type" Radius Standard Attr-Type: 230 Aug 3 16:02:42.004374 radius-access-accept: Activate-Service (Juniper-ERX-VSA) received: Tag (1) FIREWALL Aug 3 16:02:42.004383 radius-access-accept: Activate-Service (Juniper-ERX-VSA) received: Tag (2) INTERNET(61440K,625K,8192K,625K) Aug 3 16:02:42.004392 Framework - module(radius) return: SUCCESS Aug 3 16:02:42.004398 authd_advance_module_for_aaa_response_msg: result:2 Aug 3 16:02:42.004408 Client-session response-attr:: type:79 len:4 Aug 3 16:02:42.004417 Client-session response-attr:: type:53 len:4 Aug 3 16:02:42.004423 client-session response-attr:: interim-interval:600 Aug 3 16:02:42.004441 authd_update_session_dynamic_attributes: Client-session response-dyn-attr:: name:junos-interface-mtu, len:4, value: 1500, encode 0 Aug 3 16:02:42.004451 Finding a client snapshot session-id:228 Aug 3 16:02:42.004483 authd_auth_update_local_server_address ::Searching access profile Access-Profile for local DNS Server Aug 3 16:02:42.004492 domain-name-server added x.x.x.x Aug 3 16:02:42.004498 domain-name-server added 8.8.8.8 Aug 3 16:02:42.004519 domain-name-server-v6 added 2001:4860:4860::8888 Aug 3 16:02:42.004526 domain-name-server-v6 added 2001:4860:4860::8844 Aug 3 16:02:42.004547 domain-name-server-v6 added 2001:4860:4860::8888 Aug 3 16:02:42.004553 domain-name-server-v6 added 2001:4860:4860::8888 len:20 Aug 3 16:02:42.004560 domain-name-server-v6 added 2001:4860:4860::8844 Aug 3 16:02:42.004565 domain-name-server-v6 added 2001:4860:4860::8844 len:20 Aug 3 16:02:42.004576 Decoding incoming attributes Aug 3 16:02:42.004584 Subscriber attribute 10005, length 4 Aug 3 16:02:42.004590 Subscriber attribute 10167, length 52 Aug 3 16:02:42.004597 Subscriber attribute 10081, length 17 Aug 3 16:02:42.004603 Subscriber attribute 10183, length 8 Aug 3 16:02:42.004610 Received subscriber login request, subscriber-session-id:228 Aug 3 16:02:42.004621 Decoding attribute 10005 length 4 Aug 3 16:02:42.004628 Decoding attribute 10081 length 17 Aug 3 16:02:42.004634 Decoding attribute 10167 length 52 Aug 3 16:02:42.004640 Decoding attribute 10183 length 8 Aug 3 16:02:42.004652 Processing address request in default:default network 255.255.255.254 mac XX:XX:XX:XX:XX:XX Aug 3 16:02:42.004659 readSessionEntry Aug 3 16:02:42.004674 Processing rule Reserve-Address Aug 3 16:02:42.004680 ************** START-ReserveAddress ****************** Aug 3 16:02:42.004687 DUMP of all addressRequest fields for subscriber session-id:228 router default:default Aug 3 16:02:42.004695 client type jpppd-client client type 64 mac address XX:XX:XX:XX:XX:XX Aug 3 16:02:42.004705 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null Aug 3 16:02:42.004713 V4NA: req: yes pool: NULL address: null Aug 3 16:02:42.004719 V6NA: req: no pool: NULL address: null Aug 3 16:02:42.004726 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:42.004733 V6NDRA: req: yes pool: NULL ndra prefix: null/0 Aug 3 16:02:42.004738 ********************************************************* Aug 3 16:02:42.004744 *************** END-ReserveAddress ******************* Aug 3 16:02:42.004750 DUMP of all addressRequest fields for subscriber session-id:228 router default:default Aug 3 16:02:42.004758 client type jpppd-client client type 64 mac address XX:XX:XX:XX:XX:XX Aug 3 16:02:42.004767 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null Aug 3 16:02:42.004774 V4NA: req: yes pool: NULL address: null Aug 3 16:02:42.004780 V6NA: req: no pool: NULL address: null Aug 3 16:02:42.004786 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:42.004792 V6NDRA: req: yes pool: NULL ndra prefix: null/0 Aug 3 16:02:42.004797 ********************************************************* Aug 3 16:02:42.004803 Processing rule External-Authority Aug 3 16:02:42.004808 ************** START-ExternalAuthority ****************** Aug 3 16:02:42.004814 DUMP of all addressRequest fields for subscriber session-id:228 router default:default Aug 3 16:02:42.004826 client type jpppd-client client type 64 mac address XX:XX:XX:XX:XX:XX Aug 3 16:02:42.004834 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null Aug 3 16:02:42.004842 V4NA: req: yes pool: NULL address: null Aug 3 16:02:42.004847 V6NA: req: no pool: NULL address: null Aug 3 16:02:42.004853 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:42.004859 V6NDRA: req: yes pool: NULL ndra prefix: null/0 Aug 3 16:02:42.004865 ********************************************************* Aug 3 16:02:42.004870 NDRA PREFIX ALLOC begin Aug 3 16:02:42.004876 IPV4 ADDRESS ALLOC begin Aug 3 16:02:42.004882 IPV6 ADDRESS ALLOC begin Aug 3 16:02:42.004888 IPV6 PREFIX ALLOC begin Aug 3 16:02:42.004894 *************** END-ExternalAuthority ******************* Aug 3 16:02:42.004900 DUMP of all addressRequest fields for subscriber session-id:228 router default:default Aug 3 16:02:42.004908 client type jpppd-client client type 64 mac address XX:XX:XX:XX:XX:XX Aug 3 16:02:42.004916 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null Aug 3 16:02:42.004923 V4NA: req: yes pool: NULL address: null Aug 3 16:02:42.004929 V6NA: req: no pool: NULL address: null Aug 3 16:02:42.004935 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:42.004941 V6NDRA: req: yes pool: NULL ndra prefix: null/0 Aug 3 16:02:42.004947 ********************************************************* Aug 3 16:02:42.004953 Processing rule Network-Match Aug 3 16:02:42.004958 ***************** START-NetworkMatch ******************** Aug 3 16:02:42.004964 DUMP of all addressRequest fields for subscriber session-id:228 router default:default Aug 3 16:02:42.004972 client type jpppd-client client type 64 mac address XX:XX:XX:XX:XX:XX Aug 3 16:02:42.004980 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network 255.255.255.254 null Aug 3 16:02:42.004987 V4NA: req: yes pool: NULL address: null Aug 3 16:02:42.004993 V6NA: req: no pool: NULL address: null Aug 3 16:02:42.004999 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:42.005005 V6NDRA: req: yes pool: NULL ndra prefix: null/0 Aug 3 16:02:42.005010 ********************************************************* Aug 3 16:02:42.005016 IPV4 ADDRESS ALLOC begin Aug 3 16:02:42.005021 Just get the first pool with addresses Aug 3 16:02:42.005028 NetworkMatch: Found a pool v4-p1-pool Aug 3 16:02:42.005035 NetworkMatch: calling getAddress for pool 'v4-p1-pool' Aug 3 16:02:42.005041 No host is found Aug 3 16:02:42.005052 Searching for available address in range v4-range-0, low=x.x.x.x, high=y.y.y.y, next=x.x.x.x session-id:228 Aug 3 16:02:42.005059 IPV6 ADDRESS ALLOC begin Aug 3 16:02:42.005065 IPV6 PREFIX ALLOC begin Aug 3 16:02:42.005071 NetworkMatch: No match for network 'null' or hint 'null' Aug 3 16:02:42.005095 ****************** END-NetworkMatch ********************* Aug 3 16:02:42.005103 DUMP of all addressRequest fields for subscriber session-id:228 router default:default Aug 3 16:02:42.005111 client type jpppd-client client type 64 mac address XX:XX:XX:XX:XX:XX Aug 3 16:02:42.005119 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null Aug 3 16:02:42.005128 V4NA: req: yes pool: v4-p1-pool address: XXX.XXX.XX.XXX Aug 3 16:02:42.005134 V6NA: req: no pool: NULL address: null Aug 3 16:02:42.005141 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:42.005147 V6NDRA: req: yes pool: NULL ndra prefix: null/0 Aug 3 16:02:42.005152 ********************************************************* Aug 3 16:02:42.005158 Processing rule Client-Authority Aug 3 16:02:42.005164 Done processing rules Aug 3 16:02:42.005170 Processing Local Ndra rule Aug 3 16:02:42.005175 NDRA requested, but neighbor-discovery-router-advertisement is not configured Aug 3 16:02:42.005189 Pool::addressAssign: pool v4-p1-pool addr XXX.XXX.XX.XXX range XXX.XXX.XX.XXX session-id:228 Aug 3 16:02:42.005201 Pool::addressAssign: pool v4-p1-pool addr XXX.XXX.XX.XXX range XXX.XXX.XX.XXX returning session-id:228 Aug 3 16:02:42.005216 Trying to assign address XXX.XXX.XX.XXX to subscriber session-id:228 Aug 3 16:02:42.005247 Inserting address XXX.XXX.XX.XXX for session-id:228 into pool v4-p1-pool Aug 3 16:02:42.005261 Finding a client snapshot session-id:228 Aug 3 16:02:42.005296 Result have been returned with opcode=0, result=2 Aug 3 16:02:42.005304 ************* Results of Address Allocation ************* Aug 3 16:02:42.005310 DUMP of all addressRequest fields for subscriber session-id:228 router default:default Aug 3 16:02:42.005319 client type jpppd-client client type 64 mac address XX:XX:XX:XX:XX:XX Aug 3 16:02:42.005328 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null Aug 3 16:02:42.005335 Framed-Pool-->SDB_USER_IP_POOL 'v4-p1-pool' used for V4NA Aug 3 16:02:42.005344 V4NA: req: yes pool: v4-p1-pool address: XXX.XXX.XX.XXX Aug 3 16:02:42.005350 V6NA: req: no pool: NULL address: null Aug 3 16:02:42.005357 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:42.005363 V6NDRA: req: yes pool: NULL ndra prefix: null/0 Aug 3 16:02:42.005368 ********************************************************* Aug 3 16:02:42.005381 AuthFsm::current state=AuthStart(1) event=2 astEntry=0x9b3406c aaa msg=0x99366d8 session-id:228 Aug 3 16:02:42.005387 Auth-FSM: Process Auth-Response for session-id:228 and client type broadband Aug 3 16:02:42.005394 createDynamicRequest: (2) received Aug 3 16:02:42.005400 CoARequest CTOR 0x0x9b38af8 Aug 3 16:02:42.005406 createDynamicRequest: isBulkCoaRequest 0 Aug 3 16:02:42.005416 buildAndAddRequest:4760 session-id:228 activate FIREWALL Aug 3 16:02:42.005455 ServiceActivate: request=FIREWALL, serviceName=FIREWALL, serviceString=FIREWALL Aug 3 16:02:42.005462 buildAndAddRequest:4819 Setting subSessionId 228 and NO serviceSessionId Aug 3 16:02:42.005469 finishAddRequest:4610 Aug 3 16:02:42.005475 ServiceActivate::validateRequest Aug 3 16:02:42.005486 Decoding the Dynamic-Service=FIREWALL. Request= Aug 3 16:02:42.005495 finishAddRequest:4662 Aug 3 16:02:42.005501 buildAndAddRequest:4760 session-id:228 activate INTERNET(61440K,625K,8192K,625K) Aug 3 16:02:42.005512 ServiceActivate: request=INTERNET(61440K,625K,8192K,625K), serviceName=INTERNET, serviceString=INTERNET(61440K,625K,8192K,625K) Aug 3 16:02:42.005518 buildAndAddRequest:4819 Setting subSessionId 228 and NO serviceSessionId Aug 3 16:02:42.005524 finishAddRequest:4610 Aug 3 16:02:42.005529 ServiceActivate::validateRequest Aug 3 16:02:42.005539 Decoding the Dynamic-Service=INTERNET. Request= Aug 3 16:02:42.005553 finishAddRequest:4662 Aug 3 16:02:42.005560 ServiceAtLoginRequest::validateRequest Aug 3 16:02:42.005567 ################################################################### Aug 3 16:02:42.005572 ######################### AUTH REQ ACK SENT ####################### Aug 3 16:02:42.005577 ################################################################### Aug 3 16:02:42.005583 Framework: auth result is 1. Performing post-auth operations Aug 3 16:02:42.005590 Set Idle Timeout Ingress Only: FALSE Aug 3 16:02:42.005596 Framework: result is 1. Aug 3 16:02:42.005603 SEQ SendClientMsg:jpppd-client session-id:228 reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), cookie=260 ex_cookie=0x8f rply_len=28, num_tlv_blocks=0 Aug 3 16:02:42.005614 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x9936d44 Aug 3 16:02:42.005624 Auth-FSM: GRES-Mirror for session-id:228 state:AuthClntRespWait(4) Aug 3 16:02:42.005630 doPersistedDataUpdates Aug 3 16:02:42.005636 persistOnlyPrivateData m_inFlight Aug 3 16:02:42.298782 Process/Dispatch Client Message Aug 3 16:02:42.298805 New Process/Dispatch Client Message Aug 3 16:02:42.298817 authd_auth_aaa_msg_create: num_of_tlvs:1 tot_num_of_tlv:1 Aug 3 16:02:42.298830 authd_auth_aaa_msg_create username:() profile:() Aug 3 16:02:42.298836 Process Request Aug 3 16:02:42.298845 SEQ RecvClientMsg:jpppd-client session-id:228 Opcode:1, Subcode:4 (SESSION_IPV4_ACTIVATE) Aug 3 16:02:42.298856 ################################################################### Aug 3 16:02:42.298862 ################## CLIENT/FAMILY ACTIVE RCVD ###################### Aug 3 16:02:42.298867 ################################################################### Aug 3 16:02:42.298890 haveServicesToInstantiate: session-id:228, family: FAMILY_TYPE_INET, existing dynRequest, services Pending, Auth State AuthClntRespWait Aug 3 16:02:42.298898 Auth-FSM: reinterpretFsmEvent 12 to 15 Aug 3 16:02:42.298907 AuthFsm::current state=AuthClntRespWait(4) event=15 astEntry=0x9b3406c aaa msg=0x9936d44 session-id:228 Aug 3 16:02:42.298913 Auth-FSM: Trigger service creations received @ login. session-id:228 dynrequest does exist Aug 3 16:02:42.298922 Dynamic Service Creation Handler session-id:228 Aug 3 16:02:42.298928 smmServiceCreate::index:0 service:FIREWALL marked-as-processed:0 Aug 3 16:02:42.298938 Setting smiFlags=3 in SDB Aug 3 16:02:42.298979 createServiceSession Subscriber 228 created service 229 Aug 3 16:02:42.298994 UserAccess:test session-id:228 service:FIREWALL service-session-id:229 service-state:activate-init Aug 3 16:02:42.299003 smmServiceCreate: Family NOT Set 0 Aug 3 16:02:42.299009 smmServiceCreate::index:1 service:INTERNET marked-as-processed:0 Aug 3 16:02:42.299017 Setting smiFlags=3 in SDB Aug 3 16:02:42.299046 createServiceSession Subscriber 228 created service 230 Aug 3 16:02:42.299056 UserAccess:test session-id:228 service:INTERNET service-session-id:230 service-state:activate-init Aug 3 16:02:42.299069 smmServiceCreate: Family NOT Set 1 Aug 3 16:02:42.299091 smmServiceCreate::Created :2 services entries Aug 3 16:02:42.299098 cleanServiceList: numRequests 2 Aug 3 16:02:42.299107 rebuildServiceRequestList: session-id:228 requestedConfigBitsFamilyType 1, requests 1 Aug 3 16:02:42.299149 ServiceActivate: request=FIREWALL, serviceName=FIREWALL, serviceString=FIREWALL Aug 3 16:02:42.299161 ServiceActivate: request=INTERNET, serviceName=INTERNET, serviceString=INTERNET Aug 3 16:02:42.299168 Found an existing service AST entry session-id:229 for FIREWALL Aug 3 16:02:42.299174 Postponing processing of bulk service:FIREWALL Aug 3 16:02:42.299179 Found an existing service AST entry session-id:230 for INTERNET Aug 3 16:02:42.299184 Postponing processing of bulk service:INTERNET Aug 3 16:02:42.299191 Found an existing service AST entry session-id:229 for FIREWALL Aug 3 16:02:42.299201 persistOnlyPrivateDataWithState:866 session-id:229 with new state -1 Aug 3 16:02:42.299211 Found an existing service AST entry session-id:230 for INTERNET Aug 3 16:02:42.299219 persistOnlyPrivateDataWithState:866 session-id:230 with new state -1 Aug 3 16:02:42.299230 Instantiating dynamic-profile:PPPOE-PROFILE$$13 service-session-id:228 subscriber-session-id:228 config-bits:0xfe 0xc0 Aug 3 16:02:42.299263 authd_auth_aaa_msg_destroy: removing msg from recv queue Aug 3 16:02:42.299271 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x9936d44 Aug 3 16:02:42.299279 Auth-FSM: GRES-Mirror for session-id:228 state:AuthServCreateRespWait(7) Aug 3 16:02:42.299285 doPersistedDataUpdates Aug 3 16:02:42.299298 persistOnlyPrivateData m_inFlight Aug 3 16:02:42.299310 Process/Dispatch Client Message Aug 3 16:02:42.299316 New Process/Dispatch Client Message Aug 3 16:02:42.299324 authd_auth_aaa_msg_create: num_of_tlvs:1 tot_num_of_tlv:1 Aug 3 16:02:42.299330 authd_auth_aaa_msg_create username:() profile:() Aug 3 16:02:42.299335 Process Request Aug 3 16:02:42.299343 SEQ RecvClientMsg:jpppd-client session-id:228 Opcode:1, Subcode:5 (SESSION_IPV6_ACTIVATE) Aug 3 16:02:42.326138 smm_response_handle_callback Aug 3 16:02:42.326154 Ack/Nack from dyn-prof-lib subscriber-session-id:228 session-id:228. result-code:0, applied_config_bits 0xfe 0xc0 Aug 3 16:02:42.326167 No Associated Service Aug 3 16:02:42.326173 Have Dynamic Request Aug 3 16:02:42.326180 Subscriber callback received session-id:228 Aug 3 16:02:42.326195 Found an existing service AST entry session-id:229 for FIREWALL Aug 3 16:02:42.326202 Bulked services found in service request entries Aug 3 16:02:42.326210 Final result code = 0 for service session-id:229 Aug 3 16:02:42.326221 result-code is ACK, ERROR-MESSAGE is <> Aug 3 16:02:42.326230 smmHandleDynProfileResponse Use Request Config Bits from ServiceRequest: 0xfe 0xc0 Aug 3 16:02:42.326236 smmHandleDynProfileResponse: ADD Family inet active Aug 3 16:02:42.326242 Setting session start time in service session-id:229 Aug 3 16:02:42.326250 Resetting terminate ID to 0 Aug 3 16:02:42.326260 ServiceFsm::current state=SvcActivateStart(1) event=2 servAstEntry=0x9be206c service session-id:229 Aug 3 16:02:42.326269 UserAccess:test session-id:228 service:FIREWALL service-session-id:229 service-state:active Aug 3 16:02:42.326283 updateAcctSessionId session-id:229 Aug 3 16:02:42.326296 SMM-FSM: Marking service Active for session-id:229 Aug 3 16:02:42.326303 persistPrivateData session-id:229 Aug 3 16:02:42.326310 persistOnlyPrivateDataWithState session-id:229 new state 2 Aug 3 16:02:42.326331 SMM-FSM: Service active mirror session for session-id:229 Aug 3 16:02:42.326339 smmGetServiceRequest: Use serviceEntry->getDynamicRequestEntry Aug 3 16:02:42.326345 markAsProcessed: ServiceRequestEntry service session-id:229 Aug 3 16:02:42.326352 About to check if all services have been processed Aug 3 16:02:42.326357 allServiceRequestsProcessed: session-id:229 markedAsProcessed=1 Aug 3 16:02:42.326363 allServiceRequestsProcessed: session-id:230 markedAsProcessed=0 Aug 3 16:02:42.326369 Found an existing service AST entry session-id:230 for INTERNET Aug 3 16:02:42.326375 Bulked services found in service request entries Aug 3 16:02:42.326382 Final result code = 0 for service session-id:230 Aug 3 16:02:42.326389 result-code is ACK, ERROR-MESSAGE is <> Aug 3 16:02:42.326397 smmHandleDynProfileResponse Use Request Config Bits from ServiceRequest: 0xfe 0xc0 Aug 3 16:02:42.326402 smmHandleDynProfileResponse: ADD Family inet active Aug 3 16:02:42.326408 Setting session start time in service session-id:230 Aug 3 16:02:42.326414 Resetting terminate ID to 0 Aug 3 16:02:42.326423 ServiceFsm::current state=SvcActivateStart(1) event=2 servAstEntry=0x9be241c service session-id:230 Aug 3 16:02:42.326430 UserAccess:test session-id:228 service:INTERNET(61440K,625K,8192K,625K) service-session-id:230 service-state:active Aug 3 16:02:42.326440 updateAcctSessionId session-id:230 Aug 3 16:02:42.326445 SMM-FSM: Marking service Active for session-id:230 Aug 3 16:02:42.326451 persistPrivateData session-id:230 Aug 3 16:02:42.326458 persistOnlyPrivateDataWithState session-id:230 new state 2 Aug 3 16:02:42.326469 SMM-FSM: Service active mirror session for session-id:230 Aug 3 16:02:42.326476 smmGetServiceRequest: Use serviceEntry->getDynamicRequestEntry Aug 3 16:02:42.326481 markAsProcessed: ServiceRequestEntry service session-id:230 Aug 3 16:02:42.326487 About to check if all services have been processed Aug 3 16:02:42.326492 allServiceRequestsProcessed: session-id:229 markedAsProcessed=1 Aug 3 16:02:42.326497 allServiceRequestsProcessed: session-id:230 markedAsProcessed=1 Aug 3 16:02:42.326503 Sending Service Processed Response Aug 3 16:02:42.326509 ======= Service accounting START triggered ============== Aug 3 16:02:42.326519 servReqWorker: reqType = 1 service_id=229 isAccountingEnabled= 0 interval= 0 getStatsType= 2 isAcctViaLocal= 0 Aug 3 16:02:42.326526 ======= Service accounting START triggered ============== Aug 3 16:02:42.326534 servReqWorker: reqType = 1 service_id=230 isAccountingEnabled= 0 interval= 0 getStatsType= 2 isAcctViaLocal= 0 Aug 3 16:02:42.326540 Service instantiations succeeded/no-undo for session-id:228 Aug 3 16:02:42.326545 authEvent 16 Aug 3 16:02:42.326555 AuthFsm::current state=AuthServCreateRespWait(7) event=16 astEntry=0x9b3406c aaa msg=0x0 session-id:228 Aug 3 16:02:42.326565 Forcing an updated client snapshot session-id:228 Aug 3 16:02:42.326572 Taking a client snapshot, session-id:228 Aug 3 16:02:42.326596 resyncOnActivation: session-id:228, interfaceName: pp0.3221225563 Aug 3 16:02:42.326605 resyncOnActivation: Flow Id: 111 Aug 3 16:02:42.326614 setTargetRoutingContextdefault:default Aug 3 16:02:42.326621 Auth-FSM: processSubActivation: Dynamic Request Complete, Dynamic Request Type 2 session-id:228 Aug 3 16:02:42.326628 performFinalFunctions: initialServiceAtLoginRequest Aug 3 16:02:42.326634 ~CoARequest 0x0x9b38af8 Aug 3 16:02:42.326639 cleanServiceList: numRequests 2 Aug 3 16:02:42.326646 cleanServiceList: For service FIREWALL session-id:229, processed Yes, action Service Add Aug 3 16:02:42.326653 markAsProcessed: ServiceRequestEntry service session-id:229 Aug 3 16:02:42.326658 cleanServiceList: For service INTERNET session-id:230, processed Yes, action Service Add Aug 3 16:02:42.326664 markAsProcessed: ServiceRequestEntry service session-id:230 Aug 3 16:02:42.326673 ~DynamicRequestEntry 0x0x9b38af8 Aug 3 16:02:42.326679 Auth-FSM: Trigger Acct-Start and post Subscriber-Activated-Ack to the client daemon. session-id:228 Aug 3 16:02:42.326685 Auth-FSM: Trigger Acct-Start. session-id:228 Aug 3 16:02:42.326691 ======= Subscriber accounting START triggered ============== Aug 3 16:02:42.326699 Finding a client snapshot session-id:228 Aug 3 16:02:42.326738 AccFsm::current state=Acc-Init(0) event=1 session-id:228 Aug 3 16:02:42.326745 ACC-FSM:sendAccStart_a1 for session-id:228 Aug 3 16:02:42.326751 sendAuthModuleAcctReports Aug 3 16:02:42.326757 Authd module Accounting Aug 3 16:02:42.326765 Authd acctg module start Aug 3 16:02:42.326771 authd_radius_send_acctg_msg: Starting RADIUS accounting session-id:228 Aug 3 16:02:42.326776 authd_radius_send_acctg_msg: session-id:228 profile=Access-Profile username=test acctg_id=(228), ls=default, lr=default Aug 3 16:02:42.326787 radius-acct-start: User-Name added: test Aug 3 16:02:42.326794 Accounting START event time not set, setting to subscriber start time Aug 3 16:02:42.326801 radius-acct-start: Acct-Status-Type added: 1 Aug 3 16:02:42.326808 radius-acct-start: Acct-Session-Id added: 228 Aug 3 16:02:42.326820 radius-acct-start: Event-Timestamp added: 2018-08-03 16:02:42 Aug 3 16:02:42.326896 Failed to correlate access line for UIFL "xe-0/1/7.399" Aug 3 16:02:42.326906 radius-acct-start: Acct-Delay-Time added: 0 Aug 3 16:02:42.326916 radius-acct-start: Service-Type added: 2 Aug 3 16:02:42.326924 radius-acct-start: Framed-Protocol added: 1 Aug 3 16:02:42.326936 storeFilterNameList failed for subscriber session-id:228 result = -7 Aug 3 16:02:42.326943 clearFilterNameList for subscriber session-id:228 Aug 3 16:02:42.326952 radius-acct-start: Cos-Shaping-Rate (Juniper-ERX-VSA) added: Port speed: 10000000k Aug 3 16:02:42.326974 radius-acct-start: Framed-Interface-Id added: e1 f5 9a 52 ff 67 6c 28 Aug 3 16:02:42.326982 radius-acct-start: Acct-Authentic added: 1 Aug 3 16:02:42.326993 radius-acct-start: DHCP-MAC-Address (Juniper-ERX-VSA) added: cc06.xxxx.xxxx Aug 3 16:02:42.327005 radius-acct-start: Framed-IP-Address added: XXX.XXX.XX.XXX Aug 3 16:02:42.327014 radius-acct-start: Framed-IP-Netmask added: 255.255.255.255 Aug 3 16:02:42.327022 radius-acct-start: NAS-Identifier added: PPPoE-Server Aug 3 16:02:42.327029 radius-acct-start: NAS-Port tunnel client nas port is not found Aug 3 16:02:42.327036 radius-acct-start: NAS-Port added: 01 c0 01 8f Aug 3 16:02:42.327043 radius-acct-start: NAS-Port-Id added: TESTE Aug 3 16:02:42.327049 radius-acct-start: NAS-Port-Type added: 5 Aug 3 16:02:42.327059 radius-acct-start: Virtual-Router (Juniper-ERX-VSA) added: default:default Aug 3 16:02:42.327069 radius-acct-start: PPPoE-Description (Juniper-ERX-VSA) added: pppoe cc:xx:xx:xxxx:xx Aug 3 16:02:42.327119 radius-acct-start: Acct-Request_Reason (Juniper-ERX-VSA) populated with Acct-Request-Reason 4 Aug 3 16:02:42.327128 radius-acct-start: Acct-Request_Reason (Juniper-ERX-VSA) added: 4 Aug 3 16:02:42.327164 authd_create_application_specific_radius_server: Evaluating RADIUS server x.x.x.x to add to the server list Aug 3 16:02:42.327171 Evaluating RADIUS server x.x.x.x to add to the server list Aug 3 16:02:42.327177 Verify source address bad10fae in routing instance index=0 Aug 3 16:02:42.327208 authd_radius_server_add: server x.x.x.x retry 4, timeout 3 Aug 3 16:02:42.327222 authd_create_application_specific_radius_server: Evaluating RADIUS server y.y.y.y to add to the server list Aug 3 16:02:42.327228 Evaluating RADIUS server y.y.y.y to add to the server list Aug 3 16:02:42.327233 Verify source address bad10fae in routing instance index=0 Aug 3 16:02:42.327250 authd_radius_server_add: server y.y.y.y retry 4, timeout 3 Aug 3 16:02:42.327258 processSessionAttributeNasAddress 228 Aug 3 16:02:42.327264 processSessionAttributeNasAddress return false Aug 3 16:02:42.327326 Request queued successfully Aug 3 16:02:42.327340 accFsmExecute::new state=Acc-Start-Sent(1) Aug 3 16:02:42.327350 Subscriber accounting: subscriber-session-id:228 reqType: pfed: initial interval: 600 threshold-type: 0 Aug 3 16:02:42.327356 phyIfdName = xe-0/1/7 Aug 3 16:02:42.327394 authd_build_aaa_request: Found no dynRequest Aug 3 16:02:42.327402 authd_activate_notify(): enter MODULE-TYPE is 5 Aug 3 16:02:42.327407 authd_activate_notify(): no provisioning module specified Aug 3 16:02:42.327412 ################################################################### Aug 3 16:02:42.327417 ################### CLIENT (RE)ACTIVATE ACK SENT (SESSION_IPV4_ACTIVATE) #################### Aug 3 16:02:42.327423 ################################################################### Aug 3 16:02:42.327429 SEQ SendClientMsg:jpppd-client session-id:228 reply-code=1 (OK), result-subopcode=4 (SESSION_IPV4_ACTIVATE), cookie=261 ex_cookie=0x96 rply_len=28, num_tlv_blocks=0 Aug 3 16:02:42.327442 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x99366d8 Aug 3 16:02:42.327452 UserAccess:test session-id:228 state:access-granted TESTE Aug 3 16:02:42.327460 Auth-FSM: GRES-Mirror for session-id:228 state:AuthStateActive(9) Aug 3 16:02:42.327466 doPersistedDataUpdates Aug 3 16:02:42.327472 persistOnlyPrivateData m_inFlight Aug 3 16:02:42.327492 ################################################################### Aug 3 16:02:42.327499 ################## CLIENT/FAMILY ACTIVE RCVD ###################### Aug 3 16:02:42.327504 ################################################################### Aug 3 16:02:42.327520 haveServicesToInstantiate: session-id:228, family: FAMILY_TYPE_INET6, services Pending, Auth State AuthStateActive Aug 3 16:02:42.327528 Auth-FSM: reinterpretFsmEvent 12 to 15 Aug 3 16:02:42.327536 AuthFsm::current state=AuthStateActive(9) event=15 astEntry=0x9b3406c aaa msg=0x9936d44 session-id:228 Aug 3 16:02:42.327541 Auth-FSM: Trigger service creations received @ login. session-id:228 dynrequest does NOT exist Aug 3 16:02:42.327547 createDynamicRequest: (2) received Aug 3 16:02:42.327553 CoARequest CTOR 0x0x9b38af8 Aug 3 16:02:42.327559 createDynamicRequest: isBulkCoaRequest 0 Aug 3 16:02:42.327567 ServiceAtLoginRequest::validateRequest Aug 3 16:02:42.327573 rebuildServiceRequestList: session-id:228 requestedConfigBitsFamilyType 8, requests 1 Aug 3 16:02:42.327618 ServiceActivate: request=INTERNET, serviceName=INTERNET, serviceString=INTERNET Aug 3 16:02:42.327626 Found an existing service AST entry session-id:230 for INTERNET Aug 3 16:02:42.327632 Postponing processing of bulk service:INTERNET Aug 3 16:02:42.327637 Found an existing service AST entry session-id:230 for INTERNET Aug 3 16:02:42.327646 persistOnlyPrivateDataWithState:866 session-id:230 with new state -1 Aug 3 16:02:42.327658 Instantiating dynamic-profile:PPPOE-PROFILE$$13 service-session-id:228 subscriber-session-id:228 config-bits:0 0x2f 0xc Aug 3 16:02:42.327693 authd_auth_aaa_msg_destroy: removing msg from recv queue Aug 3 16:02:42.327700 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x9936d44 Aug 3 16:02:42.327710 doPersistedDataUpdates Aug 3 16:02:42.327715 persistOnlyPrivateData m_inFlight Aug 3 16:02:42.351396 authd_radius_get_config:Using radius option config from access profile stanza Aug 3 16:02:42.351409 RadiusServer: server[0] used for last request - x.x.x.x Aug 3 16:02:42.351418 Radius result is CLIENT_REQ_STATUS_SUCCESS Aug 3 16:02:42.351424 authd_radius_acctg_callback Result is :(CLIENT_REQ_STATUS_SUCCESS) reply_code:(Accounting-Response) 5 session-id:228 Aug 3 16:02:42.351435 ======= Accounting RESPONSE Received ============== Aug 3 16:02:42.351444 AccFsm::current state=Acc-Start-Sent(1) event=2 session-id:228 Aug 3 16:02:42.351450 ACC-FSM:processAccStartRsp_a2 for session-id:228 Aug 3 16:02:42.351456 persistOnlyPrivateData m_inFlight Aug 3 16:02:42.351466 accFsmExecute::new state=Acc-Start-Sent(1) Aug 3 16:02:42.426099 smm_response_handle_callback Aug 3 16:02:42.426111 Ack/Nack from dyn-prof-lib subscriber-session-id:228 session-id:228. result-code:0, applied_config_bits 0 0x2f 0xc Aug 3 16:02:42.426118 No Associated Service Aug 3 16:02:42.426124 Have Dynamic Request Aug 3 16:02:42.426130 Subscriber callback received session-id:228 Aug 3 16:02:42.426142 Found an existing service AST entry session-id:230 for INTERNET Aug 3 16:02:42.426149 Bulked services found in service request entries Aug 3 16:02:42.426156 Final result code = 0 for service session-id:230 Aug 3 16:02:42.426166 result-code is ACK, ERROR-MESSAGE is <> Aug 3 16:02:42.426174 smmHandleDynProfileResponse Use Request Config Bits from ServiceRequest: 0 0x2f 0xc Aug 3 16:02:42.426179 smmHandleDynProfileResponse: ADD Family inet6 active Aug 3 16:02:42.426189 servReqWorker: reqType = 2 service_id=230 isAccountingEnabled= 0 interval= 0 getStatsType= 2 isAcctViaLocal= 0 Aug 3 16:02:42.426196 Session start time already set in service session-id:230 Aug 3 16:02:42.426202 Resetting terminate ID to 0 Aug 3 16:02:42.426211 ServiceFsm::current state=SvcActivateStart(1) event=2 servAstEntry=0x9be241c service session-id:230 Aug 3 16:02:42.426219 UserAccess:test session-id:228 service:INTERNET(61440K,625K,8192K,625K) service-session-id:230 service-state:active Aug 3 16:02:42.426224 SMM-FSM: Marking service Active for session-id:230 Aug 3 16:02:42.426230 persistPrivateData session-id:230 Aug 3 16:02:42.426237 persistOnlyPrivateDataWithState session-id:230 new state 2 Aug 3 16:02:42.426253 SMM-FSM: Service active mirror session for session-id:230 Aug 3 16:02:42.426260 smmGetServiceRequest: Use serviceEntry->getDynamicRequestEntry Aug 3 16:02:42.426266 markAsProcessed: ServiceRequestEntry service session-id:230 Aug 3 16:02:42.426272 About to check if all services have been processed Aug 3 16:02:42.426277 allServiceRequestsProcessed: session-id:230 markedAsProcessed=1 Aug 3 16:02:42.426283 Sending Service Processed Response Aug 3 16:02:42.426294 Service instantiations succeeded/no-undo for session-id:228 Aug 3 16:02:42.426301 authEvent 16 Aug 3 16:02:42.426311 AuthFsm::current state=AuthStateActive(9) event=16 astEntry=0x9b3406c aaa msg=0x0 session-id:228 Aug 3 16:02:42.426317 Forcing an updated client snapshot session-id:228 Aug 3 16:02:42.426323 Taking a client snapshot, session-id:228 Aug 3 16:02:42.426343 Auth-FSM: processSubActivation: Dynamic Request Complete, Dynamic Request Type 2 session-id:228 Aug 3 16:02:42.426351 persistOnlyPrivateData Aug 3 16:02:42.426364 performFinalFunctions: Aug 3 16:02:42.426370 ~CoARequest 0x0x9b38af8 Aug 3 16:02:42.426375 cleanServiceList: numRequests 1 Aug 3 16:02:42.426381 cleanServiceList: For service INTERNET session-id:230, processed Yes, action Service Add Aug 3 16:02:42.426388 markAsProcessed: ServiceRequestEntry service session-id:230 Aug 3 16:02:42.426395 ~DynamicRequestEntry 0x0x9b38af8 Aug 3 16:02:42.426403 authd_build_aaa_request: Found no dynRequest Aug 3 16:02:42.426409 authd_activate_notify(): enter MODULE-TYPE is 5 Aug 3 16:02:42.426414 authd_activate_notify(): no provisioning module specified Aug 3 16:02:42.426419 ################################################################### Aug 3 16:02:42.426430 ################### CLIENT (RE)ACTIVATE ACK SENT (SESSION_IPV6_ACTIVATE) #################### Aug 3 16:02:42.426436 ################################################################### Aug 3 16:02:42.426442 SEQ SendClientMsg:jpppd-client session-id:228 reply-code=1 (OK), result-subopcode=5 (SESSION_IPV6_ACTIVATE), cookie=262 ex_cookie=0x97 rply_len=28, num_tlv_blocks=0 Aug 3 16:02:42.426452 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x99373b0 Aug 3 16:02:43.199838 findSession AST-Table couldn't find the session-id:231 Aug 3 16:02:43.199859 Process/Dispatch Client Message Aug 3 16:02:43.199865 New Process/Dispatch Client Message Aug 3 16:02:43.199875 authd_tlv_build_list_from_struct username l =1 offset =56 Aug 3 16:02:43.199883 authd_tlv_build_list_from_struct profile l =1 offset =57 Aug 3 16:02:43.199889 authd_tlv_build_list_from_struct password l =1 offset =58 Aug 3 16:02:43.199897 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Aug 3 16:02:43.199903 authd_auth_aaa_msg_create username:() profile:() Aug 3 16:02:43.199910 Process Request Aug 3 16:02:43.199918 SEQ RecvClientMsg:jdhcpd-client session-id:231 Opcode:2432, Subcode:0 (ACCESS_REQUEST) Aug 3 16:02:43.199928 Taking a client snapshot, session-id:231 Aug 3 16:02:43.199961 Creating SubscriberASTEntry for session-id:231, session name: Aug 3 16:02:43.199977 No access-profile found in the SDB for session-id:231 Aug 3 16:02:43.199984 Bbe Domain Id found in the SDB for session-id:231 Aug 3 16:02:43.199991 PhyIfdName found in the SDB for session-id:231 Aug 3 16:02:43.199999 InterfaceName found in the SDB for session-id:231 Aug 3 16:02:43.200007 aaa ls:default aaa ri:default; target ls:default target ri: default Aug 3 16:02:43.200015 setTargetRoutingContextdefault:default Aug 3 16:02:43.200022 Querying the access-profile for user: on LR/RI:default:default Aug 3 16:02:43.200029 Access Profile Name from context is Aug 3 16:02:43.200040 authd_build_radius_nas_port_and_id: nas-port-id-format order is disabled Aug 3 16:02:43.200047 authd_build_req_attr_list_from_sdb_data: The request list is from aaa_msg Aug 3 16:02:43.200071 authd_get_auth_request_nas_attr: No Agent Circuit ID attribute from SDB Aug 3 16:02:43.200090 authd_get_auth_request_nas_attr: No Agent Remote ID attribute from SDB Aug 3 16:02:43.200096 authd_get_auth_request_nas_attr: No interface SVLAN attribute from SDB Aug 3 16:02:43.200102 authd_get_auth_request_nas_attr: No interface VLAN attribute from SDB Aug 3 16:02:43.200107 authd_get_auth_request_nas_attr: No interface ATM VPI attribute from SDB Aug 3 16:02:43.200112 authd_get_auth_request_nas_attr: No interface ATM VCI attribute from SDB Aug 3 16:02:43.200118 authd_get_auth_request_nas_attr: Recovered from SDB - VPI:-1 VCI:-1 NasPortType:15 Aug 3 16:02:43.200133 authd_get_interface_nas_port_options Interface Radius-Options for Interface xe-0/1/7 not found Aug 3 16:02:43.200147 authd_build_radius_nas_port_and_id: NASPortID = PPPOE-INTERFACE, NASPort = fff, CallingStationID = Aug 3 16:02:43.200162 Finding a client snapshot session-id:231 Aug 3 16:02:43.200205 Setting multi-acct-session-id to 0 Aug 3 16:02:43.200214 setAccountingInfo: Access-Profile Aug 3 16:02:43.200221 setAccountingInfo: service accounting order 0 Aug 3 16:02:43.200228 updateCoaDynamicVariableValidation coaValidation: 0 Aug 3 16:02:43.200237 ../../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:4854 Did not find dynamic-profile in the SDB for session-id:231 Aug 3 16:02:43.200245 JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty Aug 3 16:02:43.200251 Bundle session id not found, setting to NULL Aug 3 16:02:43.200257 multi-acct-session-id set to 0 Aug 3 16:02:43.200265 access profile: Access-Profile Aug 3 16:02:43.200271 On-demand IP address set to 0 Aug 3 16:02:43.200281 UserAccess: session-id:231 Access-profile:Access-Profile Multi-Acct-Session-Id:0 ACCESS_REQUEST Aug 3 16:02:43.200294 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=() Aug 3 16:02:43.200315 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x9b34684 aaa msg=0x99373b0 session-id:231 Aug 3 16:02:43.200323 ################################################################### Aug 3 16:02:43.200328 ########################### AUTH REQ RCVD ######################### Aug 3 16:02:43.200333 ################################################################### Aug 3 16:02:43.200339 Auth-FSM: Process Auth-Request for session-id:231 username <> profile Aug 3 16:02:43.200345 Auth-FSM: Process Auth-Request V6 for session-id:231 Aug 3 16:02:43.200350 Framework: Starting authentication Aug 3 16:02:43.200358 authd_auth_begin_authentication: invoking none server Aug 3 16:02:43.200363 authd_advance_module_for_aaa_request_msg: result:0 Aug 3 16:02:43.200371 Authd module start session-id:231 Aug 3 16:02:43.200379 UserAccess: session-id:231 state:start PPPOE-INTERFACE Aug 3 16:02:43.200386 authd_auth_module_start: session-id:231 result = 2 start_auth; state = 0 Aug 3 16:02:43.200392 REQUEST: AUTHEN - module_index 0 module(none) return: SUCCESS Aug 3 16:02:43.200415 Finding a client snapshot session-id:231 Aug 3 16:02:43.200423 authd_auth_update_local_server_address ::Searching access profile Access-Profile for local DNS Server Aug 3 16:02:43.200431 domain-name-server added x.x.x.x Aug 3 16:02:43.200437 domain-name-server added 8.8.8.8 Aug 3 16:02:43.200465 domain-name-server-v6 added 2001:4860:4860::8888 Aug 3 16:02:43.200472 domain-name-server-v6 added 2001:4860:4860::8844 Aug 3 16:02:43.200499 domain-name-server-v6 added 2001:4860:4860::8888 Aug 3 16:02:43.200505 domain-name-server-v6 added 2001:4860:4860::8888 len:20 Aug 3 16:02:43.200511 domain-name-server-v6 added 2001:4860:4860::8844 Aug 3 16:02:43.200516 domain-name-server-v6 added 2001:4860:4860::8844 len:20 Aug 3 16:02:43.200532 Decoding incoming attributes Aug 3 16:02:43.200540 Subscriber attribute 10006, length 16 Aug 3 16:02:43.200548 Received subscriber login request, subscriber-session-id:231 Aug 3 16:02:43.200559 Decoding attribute 10006 length 16 Aug 3 16:02:43.200569 Processing address request in default:default network null mac HH:HH:HH:HH:HH:HH Aug 3 16:02:43.200577 readSessionEntry Aug 3 16:02:43.200591 Processing rule Reserve-Address Aug 3 16:02:43.200597 ************** START-ReserveAddress ****************** Aug 3 16:02:43.200603 DUMP of all addressRequest fields for subscriber session-id:231 router default:default Aug 3 16:02:43.200612 client type jdhcpd-client client type 1 mac address HH:HH:HH:HH:HH:HH Aug 3 16:02:43.200624 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network null 2001:db8:1000::1 Aug 3 16:02:43.200632 V4NA: req: no pool: NULL address: null Aug 3 16:02:43.200639 V6NA: req: yes pool: NULL address: null Aug 3 16:02:43.200646 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:43.200652 V6NDRA: req: no pool: NULL ndra prefix: null/0 Aug 3 16:02:43.200658 ********************************************************* Aug 3 16:02:43.200664 *************** END-ReserveAddress ******************* Aug 3 16:02:43.200670 DUMP of all addressRequest fields for subscriber session-id:231 router default:default Aug 3 16:02:43.200678 client type jdhcpd-client client type 1 mac address HH:HH:HH:HH:HH:HH Aug 3 16:02:43.200688 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network null 2001:db8:1000::1 Aug 3 16:02:43.200695 V4NA: req: no pool: NULL address: null Aug 3 16:02:43.200701 V6NA: req: yes pool: NULL address: null Aug 3 16:02:43.200707 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:43.200713 V6NDRA: req: no pool: NULL ndra prefix: null/0 Aug 3 16:02:43.200719 ********************************************************* Aug 3 16:02:43.200725 Processing rule External-Authority Aug 3 16:02:43.200730 ************** START-ExternalAuthority ****************** Aug 3 16:02:43.200740 DUMP of all addressRequest fields for subscriber session-id:231 router default:default Aug 3 16:02:43.200748 client type jdhcpd-client client type 1 mac address HH:HH:HH:HH:HH:HH Aug 3 16:02:43.200758 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network null 2001:db8:1000::1 Aug 3 16:02:43.200765 V4NA: req: no pool: NULL address: null Aug 3 16:02:43.200771 V6NA: req: yes pool: NULL address: null Aug 3 16:02:43.200777 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:43.200783 V6NDRA: req: no pool: NULL ndra prefix: null/0 Aug 3 16:02:43.200789 ********************************************************* Aug 3 16:02:43.200794 NDRA PREFIX ALLOC begin Aug 3 16:02:43.200799 IPV4 ADDRESS ALLOC begin Aug 3 16:02:43.200804 IPV6 ADDRESS ALLOC begin Aug 3 16:02:43.200810 IPV6 PREFIX ALLOC begin Aug 3 16:02:43.200816 *************** END-ExternalAuthority ******************* Aug 3 16:02:43.200823 DUMP of all addressRequest fields for subscriber session-id:231 router default:default Aug 3 16:02:43.200831 client type jdhcpd-client client type 1 mac address HH:HH:HH:HH:HH:HH Aug 3 16:02:43.200840 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network null 2001:db8:1000::1 Aug 3 16:02:43.200847 V4NA: req: no pool: NULL address: null Aug 3 16:02:43.200853 V6NA: req: yes pool: NULL address: null Aug 3 16:02:43.200859 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:43.200865 V6NDRA: req: no pool: NULL ndra prefix: null/0 Aug 3 16:02:43.200870 ********************************************************* Aug 3 16:02:43.200876 Processing rule Network-Match Aug 3 16:02:43.200882 ***************** START-NetworkMatch ******************** Aug 3 16:02:43.200888 DUMP of all addressRequest fields for subscriber session-id:231 router default:default Aug 3 16:02:43.200896 client type jdhcpd-client client type 1 mac address HH:HH:HH:HH:HH:HH Aug 3 16:02:43.200906 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null null network null 2001:db8:1000::1 Aug 3 16:02:43.200913 V4NA: req: no pool: NULL address: null Aug 3 16:02:43.200919 V6NA: req: yes pool: NULL address: null Aug 3 16:02:43.200925 V6PD: req: yes pool: NULL prefix: null/0 Aug 3 16:02:43.200931 V6NDRA: req: no pool: NULL ndra prefix: null/0 Aug 3 16:02:43.200936 ********************************************************* Aug 3 16:02:43.200941 IPV4 ADDRESS ALLOC begin Aug 3 16:02:43.200947 IPV6 ADDRESS ALLOC begin Aug 3 16:02:43.200954 NetworkMatch: Found a pool v6-ia-na-pool Aug 3 16:02:43.200961 NetworkMatch: calling getAddress for pool 'v6-ia-na-pool' Aug 3 16:02:43.200967 No host is found Aug 3 16:02:43.200983 Searching for available address in range v6-range-0, low=2001:db8:1000::2, high=2001:db8:1000::ffff:ffff, next=2001:db8:1000::7 session-id:231 Aug 3 16:02:43.200991 IPV6 PREFIX ALLOC begin Aug 3 16:02:43.200997 NetworkMatch: Found a pool v6-ia-na-pool Aug 3 16:02:43.201003 NetworkMatch: calling getAddress for pool 'v6-ia-na-pool' Aug 3 16:02:43.201008 No host is found Aug 3 16:02:43.201022 Searching for available address in range v6-range-0, low=2001:db8:1000::2, high=2001:db8:1000::ffff:ffff, next=2001:db8:1000::8 session-id:231 Aug 3 16:02:43.201028 ****************** END-NetworkMatch ********************* Aug 3 16:02:43.201035 DUMP of all addressRequest fields for subscriber session-id:231 router default:default Aug 3 16:02:43.201042 client type jdhcpd-client client type 1 mac address HH:HH:HH:HH:HH:HH Aug 3 16:02:43.201052 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network null 2001:db8:1000::1 Aug 3 16:02:43.201060 V4NA: req: no pool: NULL address: null Aug 3 16:02:43.201069 V6NA: req: yes pool: v6-ia-na-pool address: 2001:db8:1000::8 Aug 3 16:02:43.201076 V6PD: req: yes pool: v6-ia-na-pool prefix: null/0 Aug 3 16:02:43.201102 V6NDRA: req: no pool: NULL ndra prefix: null/0 Aug 3 16:02:43.201107 ********************************************************* Aug 3 16:02:43.201115 Done processing rules Aug 3 16:02:43.201126 Pool::addressAssign: pool v6-ia-na-pool addr 2001:db8:1000::8 range null session-id:231 Aug 3 16:02:43.201138 Pool::addressAssign: pool v6-ia-na-pool addr 2001:db8:1000::8 range null returning session-id:231 Aug 3 16:02:43.201146 Setting mask to 64 Aug 3 16:02:43.201162 Trying to assign address 2001:db8:1000::8 to subscriber session-id:231 Aug 3 16:02:43.201175 Inserting address 2001:db8:1000::8 for session-id:231 into pool v6-ia-na-pool Aug 3 16:02:43.201185 Finding a client snapshot session-id:231 Aug 3 16:02:43.201222 Result have been returned with opcode=0, result=2 Aug 3 16:02:43.201228 ************* Results of Address Allocation ************* Aug 3 16:02:43.201235 DUMP of all addressRequest fields for subscriber session-id:231 router default:default Aug 3 16:02:43.201243 client type jdhcpd-client client type 1 mac address HH:HH:HH:HH:HH:HH Aug 3 16:02:43.201254 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network null 2001:db8:1000::1 Aug 3 16:02:43.201261 Framed-IPv6-Pool-->SDB_USER_IPV6_POOL 'v6-ia-na-pool' used for V6NA and/or V6NDRA Aug 3 16:02:43.201268 Jnpr-IPv6-Delegated-Pool-Name-->SDB_DELEGATED_IPV6_POOL 'v6-ia-na-pool' used for V6PD only Aug 3 16:02:43.201275 V4NA: req: no pool: NULL address: null Aug 3 16:02:43.201283 V6NA: req: yes pool: v6-ia-na-pool address: 2001:db8:1000::8 Aug 3 16:02:43.201290 V6PD: req: yes pool: v6-ia-na-pool prefix: null/0 Aug 3 16:02:43.201297 V6NDRA: req: no pool: NULL ndra prefix: null/0 Aug 3 16:02:43.201310 ********************************************************* Aug 3 16:02:43.201318 authd_auth_update_local_server_address ::Searching access profile Access-Profile for local DNS Server Aug 3 16:02:43.201326 domain-name-server added x.x.x.x Aug 3 16:02:43.201332 domain-name-server added 8.8.8.8 Aug 3 16:02:43.201361 domain-name-server-v6 added 2001:4860:4860::8888 Aug 3 16:02:43.201367 domain-name-server-v6 added 2001:4860:4860::8844 Aug 3 16:02:43.201393 domain-name-server-v6 added 2001:4860:4860::8888 Aug 3 16:02:43.201399 domain-name-server-v6 added 2001:4860:4860::8888 len:20 Aug 3 16:02:43.201405 domain-name-server-v6 added 2001:4860:4860::8844 Aug 3 16:02:43.201410 domain-name-server-v6 added 2001:4860:4860::8844 len:20 Aug 3 16:02:43.201419 Framework: auth result is 1. Performing post-auth operations Aug 3 16:02:43.201426 Set Idle Timeout Ingress Only: FALSE Aug 3 16:02:43.201432 Framework: result is 1. Aug 3 16:02:43.201438 SEQ SendClientMsg:jdhcpd-client session-id:231 reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), cookie=65630 ex_cookie=0x111 rply_len=28, num_tlv_blocks=0 Aug 3 16:02:43.201449 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x993606c Aug 3 16:02:43.201457 loadDefaultService:: default service for the subscriber is empty Aug 3 16:02:43.201463 createDynamicRequest: (2) received Aug 3 16:02:43.201470 CoARequest CTOR 0x0x9b38af8 Aug 3 16:02:43.201476 createDynamicRequest: isBulkCoaRequest 0 Aug 3 16:02:43.201485 ServiceAtLoginRequest::validateRequest Aug 3 16:02:43.201496 Auth-FSM: GRES-Mirror for session-id:231 state:AuthClntRespWait(4) Aug 3 16:02:43.201502 doPersistedDataUpdates Aug 3 16:02:43.201507 persistOnlyPrivateData m_inFlight Aug 3 16:02:44.200638 Process/Dispatch Client Message Aug 3 16:02:44.200664 New Process/Dispatch Client Message Aug 3 16:02:44.200678 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Aug 3 16:02:44.200685 authd_auth_aaa_msg_create username:() profile:() Aug 3 16:02:44.200692 Process Request Aug 3 16:02:44.200701 SEQ RecvClientMsg:jdhcpd-client session-id:231 Opcode:1, Subcode:5 (SESSION_IPV6_ACTIVATE) Aug 3 16:02:44.200713 ################################################################### Aug 3 16:02:44.200719 ################## CLIENT/FAMILY ACTIVE RCVD ###################### Aug 3 16:02:44.200725 ################################################################### Aug 3 16:02:44.200752 haveServicesToInstantiate: session-id:231, family: FAMILY_TYPE_INET6, existing dynRequest, NO services Pending, Auth State AuthClntRespWait Aug 3 16:02:44.200764 AuthFsm::current state=AuthClntRespWait(4) event=12 astEntry=0x9b34684 aaa msg=0x993606c session-id:231 Aug 3 16:02:44.200771 Forcing an updated client snapshot session-id:231 Aug 3 16:02:44.200778 Taking a client snapshot, session-id:231 Aug 3 16:02:44.200821 Releasing addressEntry for address 2001:db8:1000::8 session-id:231 Aug 3 16:02:44.200851 Inserting address 2001:db8:1000::8 for session-id:231 into pool v6-ia-na-pool Aug 3 16:02:44.200863 resyncOnActivation: session-id:231, interfaceName: pp0.3221225563 Aug 3 16:02:44.200870 resyncOnActivation: Flow Id: 111 Aug 3 16:02:44.200880 setTargetRoutingContextdefault:default Aug 3 16:02:44.200887 Auth-FSM: processSubActivation: Dynamic Request Complete, Dynamic Request Type 2 session-id:231 Aug 3 16:02:44.200894 performFinalFunctions: initialServiceAtLoginRequest Aug 3 16:02:44.200901 ~CoARequest 0x0x9b38af8 Aug 3 16:02:44.200907 cleanServiceList: numRequests 0 Aug 3 16:02:44.200913 ~DynamicRequestEntry 0x0x9b38af8 Aug 3 16:02:44.200920 authd_activate_notify(): enter MODULE-TYPE is 5 Aug 3 16:02:44.200925 authd_activate_notify(): no provisioning module specified Aug 3 16:02:44.200930 ################################################################### Aug 3 16:02:44.200936 ################### CLIENT (RE)ACTIVATE ACK SENT (SESSION_IPV6_ACTIVATE) #################### Aug 3 16:02:44.200941 ################################################################### Aug 3 16:02:44.200949 SEQ SendClientMsg:jdhcpd-client session-id:231 reply-code=1 (OK), result-subopcode=5 (SESSION_IPV6_ACTIVATE), cookie=65630 ex_cookie=0x117 rply_len=28, num_tlv_blocks=0 Aug 3 16:02:44.200961 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x99373b0 Aug 3 16:02:44.200971 UserAccess: session-id:231 state:access-granted PPPOE-INTERFACE Aug 3 16:02:44.200980 Auth-FSM: GRES-Mirror for session-id:231 state:AuthStateActive(9) Aug 3 16:02:44.200986 doPersistedDataUpdates Aug 3 16:02:44.200992 persistOnlyPrivateData Aug 3 16:02:44.201004 Process/Dispatch Client Message Aug 3 16:02:44.201010 New Process/Dispatch Client Message Aug 3 16:02:44.201018 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Aug 3 16:02:44.201024 authd_auth_aaa_msg_create username:() profile:() Aug 3 16:02:44.201030 Process Request Aug 3 16:02:44.201037 SEQ RecvClientMsg:jdhcpd-client session-id:228 Opcode:1, Subcode:46 (TRIGGER_ADDR_CHANGE_IMM_INTRM) Aug 3 16:02:44.201048 AuthFsm::current state=AuthStateActive(9) event=56 astEntry=0x9b3406c aaa msg=0x99373b0 session-id:228 Aug 3 16:02:44.201055 Forcing an updated client snapshot session-id:228 Aug 3 16:02:44.201063 Taking a client snapshot, session-id:228 Aug 3 16:02:44.201126 Unable to create address entry Aug 3 16:02:44.201140 Failed to create address entry 2001:db8:1000::8 Aug 3 16:02:44.201179 Auth-FSM: Process Trigger-Addr-Change-Imm-Intrm-Upd for session-id :228 Aug 3 16:02:44.201192 SEQ SendClientMsg:jdhcpd-client session-id:228 reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), cookie=40 ex_cookie=0x11a rply_len=28, num_tlv_blocks=0 Aug 3 16:02:44.201203 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x993606c