Sep 10 09:57:36.816213 initialize: aaa ls:default aaa ri:default; target ls:default target ri: default Sep 10 09:57:36.919876 AaaService::RoutingContext::assign, ls default, ri default, tn null Sep 10 09:57:36.920041 setTargetRoutingContextdefault:default Sep 10 09:57:36.920069 AaaService::RoutingContext::assign, ls default, ri default, tn null Sep 10 09:57:36.920099 setRoutingContext: Access Profile Name is on LR/RI:default:default Sep 10 09:57:36.920353 authd_build_radius_nas_port_and_id: nas-port-id-format order is disabled Sep 10 09:57:36.920381 authd_build_req_attr_list_from_sdb_data: The request list is from aaa_msg Sep 10 09:57:36.921682 Taking a client snapshot, session-id:4240 Sep 10 09:57:36.921972 authd_get_auth_request_nas_attr: No Agent Circuit ID attribute from SDB Sep 10 09:57:36.922002 authd_get_auth_request_nas_attr: No Agent Remote ID attribute from SDB Sep 10 09:57:36.922025 authd_get_auth_request_nas_attr: No interface SVLAN attribute from SDB Sep 10 09:57:36.922049 authd_get_auth_request_nas_attr: No interface VLAN attribute from SDB Sep 10 09:57:36.922072 authd_get_auth_request_nas_attr: No interface ATM VPI attribute from SDB Sep 10 09:57:36.922096 authd_get_auth_request_nas_attr: No interface ATM VCI attribute from SDB Sep 10 09:57:36.922120 authd_get_auth_request_nas_attr: Recovered from SDB - VPI:-1 VCI:-1 NasPortType:5 Sep 10 09:57:36.922166 NASPortID ins and outs: phy = [si-1/0/0] ifn = [si] uifn = [si-1/0/0.3221229707], ae:0 s:1 a:0 p:0 c:0 su:3221229707 sv:-1 v:-1 Sep 10 09:57:36.922204 authd_get_interface_nas_port_options: Not interested in interface si-1/0/0 Sep 10 09:57:36.922236 Taking a client snapshot, session-id:4240 Sep 10 09:57:36.922285 Taking a client snapshot, session-id:4240 Sep 10 09:57:36.922321 authd_build_radius_nas_port_and_id: NASPortID = Ip:5.5.5.5:123.0.0.1:33886:8829:62417:1317:18019557, NASPort = 10000fff, CallingStationID = Sep 10 09:57:36.924680 Finding a client snapshot session-id:4240 Sep 10 09:57:36.924894 setRoutingContext: Setting multi-acct-session-id to 0 Sep 10 09:57:36.924965 setAccountingInfo: aaa-profile Sep 10 09:57:36.924990 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.925016 setAccountingInfo: service accounting order 0 Sep 10 09:57:36.925040 updateCoaDynamicVariableValidation coaValidation: 0 Sep 10 09:57:36.925090 updateDynamicProfile: session-id:4240, old dynamic profile empty, new dynamic profile DYN-PROF-1$$01 Sep 10 09:57:36.925122 JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty Sep 10 09:57:36.925150 Bundle session id not found, setting to NULL Sep 10 09:57:36.925172 multi-acct-session-id set to 0 Sep 10 09:57:36.925194 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.925220 access profile: aaa-profile Sep 10 09:57:36.925243 On-demand IP address set to 0 Sep 10 09:57:36.925275 SLimit: getEligibleProfile: session-limit is OFF access-profile:aaa-profile session-id:4240 Sep 10 09:57:36.925345 UserAccess:testusername@testing.net session-id:4240 Access-profile:aaa-profile Multi-Acct-Session-Id:0 ACCESS_REQUEST Sep 10 09:57:36.925399 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=() Sep 10 09:57:36.925453 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x330006c aaa msg=0x2807768 session-id:4240 Sep 10 09:57:36.925510 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.925537 ################################################################### Sep 10 09:57:36.925556 ########################### AUTH REQ RCVD ######################### Sep 10 09:57:36.925576 ################################################################### Sep 10 09:57:36.925599 Auth-FSM: Process Auth-Request for session-id:4240 username profile Sep 10 09:57:36.926086 Auth-FSM: Process Auth-Request for session-id:4240 Sep 10 09:57:36.926110 Framework: Starting authentication Sep 10 09:57:36.926132 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.926155 authd_advance_module_for_aaa_request_msg: result:0 Sep 10 09:57:36.926286 Authd module start session-id:4240 Sep 10 09:57:36.926310 authd_radius_start_auth: Starting RADIUS authentication session-id:4240 Sep 10 09:57:36.926369 authd_radius_get_config: profile aaa-profile Sep 10 09:57:36.926392 authd_radius_get_config: profile aaa-profile in arm_profile_radius_tree Sep 10 09:57:36.926414 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.926520 authd_radius_build_basic_auth_request: session-id:4240 profile=aaa-profile, username=testusername@testing.net Sep 10 09:57:36.926549 radius-access-request: User-Name added: testusername@testing.net Sep 10 09:57:36.926571 radius-access-request: User-Password added: "" Sep 10 09:57:36.926603 Taking a client snapshot, session-id:4240 Sep 10 09:57:36.926657 radius-access-request: Service-Type added: 2 Sep 10 09:57:36.926700 radius-access-request: Framed-Protocol added: 1 Sep 10 09:57:36.926740 radius-access-request: Tunnel-Type added: Tag () 3 Sep 10 09:57:36.926777 radius-access-request: Tunnel-Medium-Type added: Tag () 1 Sep 10 09:57:36.926814 radius-access-request: Tunnel-Client-Endpoint added: 123.0.0.1 Sep 10 09:57:36.926849 radius-access-request: Tunnel-Server-Endpoint added: 5.5.5.5 Sep 10 09:57:36.926883 radius-access-request: Tunnel-Assignment-ID added: 33886 Sep 10 09:57:36.926919 radius-access-request: Tunnel-Client-Auth-ID added: lts.01 Sep 10 09:57:36.926953 radius-access-request: Tunnel-Server-Auth-ID added: Cust24 Sep 10 09:57:36.926987 radius-access-request: Chargeable-User-Identity added: Sep 10 09:57:36.927024 radius-access-request: Acct-Tunnel-Connection added: 0018019557 Sep 10 09:57:36.927057 radius-access-request: Acct-Session-Id added: 4240 Sep 10 09:57:36.927092 radius-access-request: Calling-Station-Id added: BBEU07295297 Sep 10 09:57:36.927132 radius-access-request: DHCP-MAC-Address (Juniper-ERX-VSA) added: 0000.0000.0000 Sep 10 09:57:36.927172 radius-access-request: NAS-Identifier added: Cust24 Sep 10 09:57:36.927204 radius-access-request: NAS-Port added: 10 00 0f ff Sep 10 09:57:36.927246 radius-access-request: NAS-Port-Id added: Ip:5.5.5.5:123.0.0.1:33886:8829:62417:1317:18019557 Sep 10 09:57:36.927275 radius-access-request: NAS-Port-Type added: 5 Sep 10 09:57:36.927311 radius-access-request: L2tp-Tx-connect-speed (Juniper-ERX-VSA) added: 1881000 Sep 10 09:57:36.927348 radius-access-request: L2tp-Rx-connect-speed (Juniper-ERX-VSA) added: 723000 Sep 10 09:57:36.947503 radius-access-request: Client-Profile-Name (Juniper-ERX-VSA) added: DYN-PROF-1: Sep 10 09:57:36.947622 radius-access-request: PPPoE-Description (Juniper-ERX-VSA) added: pppoe 00:00:00:00:00:00 Sep 10 09:57:36.947700 authd_create_application_specific_radius_server: Evaluating RADIUS server 2.2.2.2 to add to the server list Sep 10 09:57:36.947725 Evaluating RADIUS server 2.2.2.2 to add to the server list Sep 10 09:57:36.947749 Verify source address 53da8fc0 in routing instance index=0 Sep 10 09:57:36.947857 authd_radius_server_add: server 2.2.2.2 retry 3, timeout 3 Sep 10 09:57:36.948027 authd_create_application_specific_radius_server: Evaluating RADIUS server 1.1.1.1 to add to the server list Sep 10 09:57:36.948058 Evaluating RADIUS server 1.1.1.1 to add to the server list Sep 10 09:57:36.948081 Verify source address 53da8fc0 in routing instance index=0 Sep 10 09:57:36.948150 authd_radius_server_add: server 1.1.1.1 retry 3, timeout 3 Sep 10 09:57:36.948178 processSessionAttributeNasAddress 4240 Sep 10 09:57:36.948200 processSessionAttributeNasAddress return false Sep 10 09:57:36.957933 authd_radius_get_config: profile aaa-profile Sep 10 09:57:36.958013 authd_radius_get_config: profile aaa-profile in arm_profile_radius_tree Sep 10 09:57:36.963460 Request queued successfully Sep 10 09:57:36.963570 REQUEST: AUTHEN - module_index 0 module(radius) return: ASYNC Sep 10 09:57:36.963622 UserAccess:testusername@testing.net session-id:4240 state:start Ip:5.5.5.5:123.0.0.1:33886:8829:62417:1317:18019557 Sep 10 09:57:36.966559 Auth-FSM: GRES-Mirror for session-id:4240 state:AuthStart(1) Sep 10 09:57:36.971897 authd_radius_get_config: profile aaa-profile Sep 10 09:57:36.971955 authd_radius_get_config: profile aaa-profile in arm_profile_radius_tree Sep 10 09:57:36.971976 RadiusServer: authd_radius_mark_servers_dead : 2 servers radius config, probably config changed Sep 10 09:57:36.972001 RadiusServer: server[0] used for last request - 2.2.2.2 Sep 10 09:57:36.972078 loadDefaultService:: default service for the subscriber is empty Sep 10 09:57:36.972102 Radius result is CLIENT_REQ_STATUS_SUCCESS Sep 10 09:57:36.972143 Parsing RADIUS message for session-id:4240 Sep 10 09:57:36.976694 radius-access-accept: Tunnel-Password received: "" Sep 10 09:57:36.976775 radius-access-accept: Tunnel-Server-Endpoint received: 5.5.5.5 Sep 10 09:57:36.976813 radius-access-accept: Framed-IP-Address received: 192.168.5.5 Sep 10 09:57:36.976843 radius-access-accept: Tunnel-Client-Auth-ID received: lts.01 Sep 10 09:57:36.976873 radius-access-accept: Tunnel-Type received: Tag () 3 Sep 10 09:57:36.976903 radius-access-accept: Framed-IP-Netmask received: 255.255.255.255 Sep 10 09:57:36.976934 radius-access-accept: Framed-Protocol received: 1 Sep 10 09:57:36.976962 radius-access-accept: Tunnel-Medium-Type received: Tag () 1 Sep 10 09:57:36.976991 radius-access-accept: Service-Type received: 2 Sep 10 09:57:36.977032 Framework - module(radius) return: SUCCESS Sep 10 09:57:36.977054 authd_advance_module_for_aaa_response_msg: result:2 Sep 10 09:57:36.977084 Taking a client snapshot, session-id:4240 Sep 10 09:57:36.977119 setAuthResponseAttributes: Client-session response-attr:: type:21 len:4 Sep 10 09:57:36.977147 setAuthResponseAttributes: Client-session response-attr:: type:22 len:4 Sep 10 09:57:36.977172 setAuthResponseAttributes: Client-session response-attr:: type:79 len:4 Sep 10 09:57:36.977196 setAuthResponseAttributes: Client-session response-attr:: type:78 len:4 Sep 10 09:57:36.977221 Taking a client snapshot, session-id:4240 Sep 10 09:57:36.977269 createTunnelDefinitionList calloc_aaa_msg_attr_from_pool 82 Sep 10 09:57:36.977388 Finding a client snapshot session-id:4240 Sep 10 09:57:36.979576 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.979601 authd_auth_update_local_server_address ::Searching access profile aaa-profile for local DNS Server Sep 10 09:57:36.979628 domain-name-server added 8.8.8.8 Sep 10 09:57:36.979650 domain-name-server added 8.8.4.4 Sep 10 09:57:36.979778 AuthFsm::current state=AuthStart(1) event=2 astEntry=0x330006c aaa msg=0x2807768 session-id:4240 Sep 10 09:57:36.979808 Auth-FSM: Process Auth-Response for session-id:4240 and client type broadband Sep 10 09:57:36.979835 SLimit: getEligibleProfile: session-limit is OFF access-profile:aaa-profile session-id:4240 Sep 10 09:57:36.979857 createDynamicRequest: (2) received Sep 10 09:57:36.979899 CoARequest CTOR 0x0x331806c Sep 10 09:57:36.979923 createDynamicRequest: isBulkCoaRequest 0 Sep 10 09:57:36.979947 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.979975 ServiceAtLoginRequest::validateRequest Sep 10 09:57:36.980013 ################################################################### Sep 10 09:57:36.980035 ######################### AUTH REQ ACK SENT ####################### Sep 10 09:57:36.980055 ################################################################### Sep 10 09:57:36.980084 Framework: auth result is 1. Performing post-auth operations Sep 10 09:57:36.980107 authd_access_profile_get: profile aaa-profile found Sep 10 09:57:36.985808 Finding a client snapshot session-id:4240 Sep 10 09:57:36.985944 Set Session Timeout Strict: FALSE Sep 10 09:57:36.985967 Set Idle Timeout Ingress Only: FALSE Sep 10 09:57:36.985990 Framework: result is 1. Sep 10 09:57:36.986025 SEQ SendClientMsg:jpppd-client session-id:4240 reply-code=10 (OK TUNNELLED), result-subopcode=1 (ACCESS_OK), cookie=12703 ex_cookie=0x8f rply_len=28, num_tlv_blocks=0 Sep 10 09:57:36.986121 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x280706c Sep 10 09:57:36.986219 Auth-FSM: GRES-Mirror for session-id:4240 state:AuthClntRespWait(4) Sep 10 09:57:36.986273 doPersistedDataUpdates Sep 10 09:57:36.986296 persistOnlyPrivateData m_inFlight Sep 10 09:57:37.214805 Process/Dispatch Client Message Sep 10 09:57:37.214863 New Process/Dispatch Client Message Sep 10 09:57:37.214902 authd_auth_aaa_msg_create: num_of_tlvs:2 tot_num_of_tlv:2 Sep 10 09:57:37.214926 authd_auth_aaa_msg_create username:() profile:() Sep 10 09:57:37.214950 Process Request Sep 10 09:57:37.214976 SEQ RecvClientMsg:jpppd-client session-id:4240 Opcode:3, Subcode:15 (SESSION_LOGOUT) Sep 10 09:57:37.215045 Setting terminate ID to 20169 Sep 10 09:57:37.215104 Decoding incoming attributes Sep 10 09:57:37.215128 Begin to logout Subscriber Sep 10 09:57:37.215182 ################################################################### Sep 10 09:57:37.215204 ############################ LOGOUT RCVD ########################## Sep 10 09:57:37.215225 ################################################################### Sep 10 09:57:37.215255 AuthFsm::current state=AuthClntRespWait(4) event=8 astEntry=0x330006c aaa msg=0x280706c session-id:4240 Sep 10 09:57:37.215280 Auth-FSM: Posting a Logout-Ack to the client daemon for session-id:4240 Sep 10 09:57:37.215323 clearDynamicConfigLists: numRequests 0 Sep 10 09:57:37.215347 ~CoARequest 0x0x331806c Sep 10 09:57:37.215368 cleanServiceList: numRequests 0 Sep 10 09:57:37.215390 ~DynamicRequestEntry 0x0x331806c Sep 10 09:57:37.215420 ****astEntry:0x330006c aaaMsg:0x280706c replyOpcode:1 replySubOpcode:16 replyStatus:1 Sep 10 09:57:37.215459 SEQ SendClientMsg:jpppd-client session-id:4240 reply-code=1 (OK), result-subopcode=16 (SESSION_LOGOUT_ACK), cookie=12704 ex_cookie=0x9e rply_len=28, num_tlv_blocks=0 Sep 10 09:57:37.215505 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x2807768 Sep 10 09:57:37.215538 ################################################################### Sep 10 09:57:37.215560 ####################### LOGOUT ACK SENT ######################## Sep 10 09:57:37.215580 ################################################################### Sep 10 09:57:37.215642 UserAccess:testusername@testing.net session-id:4240 state:login-request Ip:5.5.5.5:123.0.0.1:33886:8829:62417:1317:18019557 Sep 10 09:57:37.215669 Auth-FSM: GRES-Mirror for session-id:4240 state:AuthInit(0) Sep 10 09:57:37.514722 Process/Dispatch Client Message Sep 10 09:57:37.514786 New Process/Dispatch Client Message Sep 10 09:57:37.514824 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Sep 10 09:57:37.514847 authd_auth_aaa_msg_create username:() profile:() Sep 10 09:57:37.514871 Process Request Sep 10 09:57:37.514897 SEQ RecvClientMsg:jpppd-client session-id:4240 Opcode:1, Subcode:17 (CLIENT_SESSION_CLEANUP_REQ) Sep 10 09:57:37.514944 AuthFsm::current state=AuthInit(0) event=22 astEntry=0x330006c aaa msg=0x2807768 session-id:4240 Sep 10 09:57:37.514969 Auth-FSM: Trigger Acct-Stop, Save off client-msg-cookie. session-id:4240 Sep 10 09:57:37.514990 ################################################################### Sep 10 09:57:37.515010 ########################### TERMINATE REQ RCVD ######################### Sep 10 09:57:37.515029 ################################################################### Sep 10 09:57:37.515058 authd_auth_aaa_msg_destroy: removing msg from recv queue Sep 10 09:57:37.515453 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x2807768 Sep 10 09:57:37.515498 subscriberLogoutV4 session-id:4240 Sep 10 09:57:37.515527 subscriberLogoutV6 session-id:4240 Sep 10 09:57:37.515557 ****astEntry:0x330006c aaaMsg:0 replyOpcode:1 replySubOpcode:18 replyStatus:1 Sep 10 09:57:37.515586 authd_build_aaa_request: Found no dynRequest Sep 10 09:57:37.515614 SEQ SendClientMsg:jpppd-client session-id:4240 reply-code=1 (OK), result-subopcode=18 (CLIENT_SESSION_CLEANUP_ACK), cookie=12705 ex_cookie=0x9f rply_len=28, num_tlv_blocks=0 Sep 10 09:57:37.515645 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x280706c Sep 10 09:57:37.515675 ################################################################### Sep 10 09:57:37.515696 ####################### TERMINATE ACK SENT ######################## Sep 10 09:57:37.515802 ################################################################### Sep 10 09:57:37.515831 Delete session-id:4240 Sep 10 09:57:37.515855 deleteSession isAuthdLiteClient: 0 isSessionCreateByAuthd: 0 session-id:4240 Sep 10 09:57:37.515878 Begin to logout Subscriber Sep 10 09:57:37.515901 subscriberLogoutV4 session-id:4240 Sep 10 09:57:37.515925 subscriberLogoutV6 session-id:4240 Sep 10 09:57:37.515981 UserAccess:testusername@testing.net session-id:4240 state:log-out Ip:5.5.5.5:123.0.0.1:33886:8829:62417:1317:18019557 reason: l2tp session-create-failed-invalid-config