Nov 14 15:10:01 clear-log[14163]: logfile cleared Nov 14 15:10:25.817242 authd_read_msg: Fresh msg arrival. fd=59, hdr_read=0, hdr_remnant=0, payload_read=0 payload_remnant=0 Nov 14 15:10:25.817309 fresh message conn=0x2c08000 Nov 14 15:10:25.817350 read fresh message conn=0x2c08000 hdr_remnant=0 hdr_read=32 Nov 14 15:10:25.817382 Read payload for new message. fd=59, rqst_len=59 Nov 14 15:10:25.817413 Read payload for new message. fd=59, payload_len=27, rqst_len=59, cookie=283496 Nov 14 15:10:25.817466 Process/Dispatch Client Message Nov 14 15:10:25.817500 New Process/Dispatch Client Message Nov 14 15:10:25.817550 authd_tlv_build_list_from_structusername (0x201d9f0) len:0 Nov 14 15:10:25.817587 authd_tlv_build_list_from_structprofile (0x201d67c) len:0 Nov 14 15:10:25.817623 authd_tlv_build_list_from_structpassword (0x201c824) len:0 Nov 14 15:10:25.817660 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:3 Nov 14 15:10:25.817696 authd_auth_aaa_msg_create aaa-key: username:() profile:() Nov 14 15:10:25.817731 Process Request Nov 14 15:10:25.817770 Client request received on conn-id:jdhcpd session-id:421560 Opcode:65, Subcode:0 Nov 14 15:10:25.817827 Taking a client snapshot, session-id:421560 Nov 14 15:10:25.817992 setAccountingInfo: NULL profile ? 0 Nov 14 15:10:25.818029 setAccountingInfo: service accounting order Nov 14 15:10:25.818087 Creating SubscriberASTEntry for session-id:421560, session name:OPT82NOIP.0DDF000701.8479739960C7 Nov 14 15:10:25.818138 UserAccess:OPT82NOIP.0DDF000701.8479739960C7 session-id:421560 state:login-request Nov 14 15:10:25.818279 fillSessionDBAttributes: session-id: 421560, ifdName: ge-1/1/1 Nov 14 15:10:25.818336 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:417 No access-profile found in the SDB for session-id:421560 Nov 14 15:10:25.818381 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:431 PhyIfdName found in the SDB for session-id:421560 Nov 14 15:10:25.818442 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:797 Querying the access-profile for user:OPT82NOIP.0DDF000701.8479739960C7 on LR/RI:default:default Nov 14 15:10:25.818537 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:809 Access Profile Name from context is Nov 14 15:10:25.818592 authd_get_auth_request_nas_attr: The request list is from aaa_msg Nov 14 15:10:25.819212 authd_get_auth_request_nas_attr: No interface SVLAN attribute from SDB Nov 14 15:10:25.819249 authd_get_auth_request_nas_attr: No interface ATM VPI attribute from SDB Nov 14 15:10:25.819282 authd_get_auth_request_nas_attr: No interface ATM VCI attribute from SDB Nov 14 15:10:25.819313 authd_get_auth_request_nas_attr: Recovered from SDB - VPI:-1 VCI:-1 NasPortType:15 Nov 14 15:10:25.819383 authd_get_interface_nas_port_options Interface Radius-Options for Interface ge-1/1/1 not found Nov 14 15:10:25.819473 authd_build_radius_nas_port_and_id: NASPortID = ge-1/1/1.1073934920:3551, NASPort = 10400ddf, CallingStationID = Nov 14 15:10:25.819794 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:945 Setting multi-acct-session-id to 0 Nov 14 15:10:25.819841 setAccountingInfo: NULL profile ? 46512244 Nov 14 15:10:25.819881 setAccountingInfo: service accounting order Nov 14 15:10:25.819924 updateCoaDynamicVariableValidation coaValidation: 0 Nov 14 15:10:25.819978 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:550 JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty Nov 14 15:10:25.820019 Bundle session id not found, setting to NULL Nov 14 15:10:25.820057 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:567 multi-acct-session-id set to 0 Nov 14 15:10:25.820099 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:688 access profile: CLIENTS Nov 14 15:10:25.820136 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:754 On-demand IP address set to 0 Nov 14 15:10:25.820188 UserAccess:OPT82NOIP.0DDF000701.8479739960C7 session-id:421560 Access-profile:CLIENTS Multi-Acct-Session-Id:0 Nov 14 15:10:25.820251 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=() Nov 14 15:10:25.820294 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x20d74d8 aaa msg=0x1f6e06c Nov 14 15:10:25.820333 ################################################################### Nov 14 15:10:25.820366 ########################### AUTH REQ RCVD ######################### Nov 14 15:10:25.820396 ################################################################### Nov 14 15:10:25.820426 Auth-FSM: Process Auth-Request for session-id:421560 Nov 14 15:10:25.820461 Framework: Starting authentication Nov 14 15:10:25.820497 authd_advance_module_for_aaa_request_msg: result:0 Nov 14 15:10:25.820537 Authd module start Nov 14 15:10:25.820568 authd_radius_start_auth: Starting RADIUS authentication Nov 14 15:10:25.820663 authd_radius_build_basic_auth_request: got params profile=CLIENTS, username=OPT82NOIP.0DDF000701.8479739960C7 Nov 14 15:10:25.820704 radius-access-request: User-Name added: OPT82NOIP.0DDF000701.8479739960C7 Nov 14 15:10:25.820738 radius-access-request: User-Password added: "" Nov 14 15:10:25.820796 radius-access-request: Service-Type added: 2 Nov 14 15:10:25.820848 radius-access-request: Chargeable-User-Identity added: Nov 14 15:10:25.820903 radius-access-request: Acct-Session-Id added: 421560 Nov 14 15:10:25.820998 radius-access-request: DHCP-Options (Juniper-ERX-VSA) added: 35 01 01 37 07 01 79 03 21 06 2a 8a 0c 08 4d 69 6b 72 6f 54 69 6b 3d 07 01 4c 5e 0c 46 50 79 52 1e 01 05 0d df 00 07 01 02 06 84 79 73 99 60 c7 09 0d 00 00 0c f8 08 01 06 53 77 69 74 63 68 Nov 14 15:10:25.821056 radius-access-request: DHCP-MAC-Address (Juniper-ERX-VSA) added: 4c5e.0c46.5079 Nov 14 15:10:25.821113 radius-access-request: NAS-Port added: 10 40 0d df Nov 14 15:10:25.821155 radius-access-request: NAS-Port-Id added: ge-1/1/1.1073934920:3551 Nov 14 15:10:25.821201 radius-access-request: NAS-Port-Type added: 15 Nov 14 15:10:25.821272 radius-access-request: Agent-Circuit-Id (DSL Forum-VSA) Sub-Attribute added: ^M Nov 14 15:10:25.821317 radius-access-request: Agent-Remote-Id (DSL Forum-VSA) Sub-Attribute added: <84>ys<99>` Nov 14 15:10:25.821367 authd_create_application_specific_radius_server: Evaluating RADIUS server 0xc21c59a1 to add to the server list Nov 14 15:10:25.821411 Verify source address 5c267f03 (92.38.127.3) in routing instance index=0 Nov 14 15:10:25.821870 REQUEST: AUTHEN - module_index 0 module(radius) return: ASYNC Nov 14 15:10:25.821939 UserAccess:OPT82NOIP.0DDF000701.8479739960C7 session-id:421560 state:start ge-1/1/1.1073934920:3551 Nov 14 15:10:25.821979 Auth-FSM: GRES-Mirror for session-id:421560 state:AuthStart(1) Nov 14 15:10:25.876026 authd_radius_get_config:Using radius option config from access stanza Nov 14 15:10:25.876552 loadDefaultService:: default service for the subscriber is empty Nov 14 15:10:25.876588 Radius result is CLIENT_REQ_STATUS_SUCCESS Nov 14 15:10:25.876639 Parsing RADIUS message for session-id:421560 Nov 14 15:10:25.876699 radius-access-accept: Acct-Interim-Interval received: 600 Nov 14 15:10:25.876748 radius-access-accept: Framed-Pool received: NoMoney-POOL Nov 14 15:10:25.876808 radius-access-accept: Activate-Service (Juniper-ERX-VSA) received: Tag (1) svc-nomoney-ipoe Nov 14 15:10:25.876859 Framework - module(radius) return: SUCCESS Nov 14 15:10:25.876900 authd_advance_module_for_aaa_response_msg: result:2 Nov 14 15:10:25.876952 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_astable.cc:1650 Client-session response-attr:: type:53 len:4 Nov 14 15:10:25.876998 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_astable.cc:1673client-session response-attr:: interim-interval:600 Nov 14 15:10:25.877043 ../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_astable.cc:1650 Client-session response-attr:: type:23 len:12 Nov 14 15:10:25.877355 Decoding incoming attributes Nov 14 15:10:25.877398 Subscriber attribute 10014, length 4 Nov 14 15:10:25.877465 Subscriber attribute 10005, length 4 Nov 14 15:10:25.877503 Subscriber attribute 33025, length 5 Nov 14 15:10:25.877540 Subscriber attribute 33026, length 6 Nov 14 15:10:25.877576 Subscriber attribute 10169, length 8 Nov 14 15:10:25.877613 Subscriber attribute 47, length 12544 Nov 14 15:10:25.877655 Received subscriber login request, subscriber session-id:421560 Nov 14 15:10:25.877704 Decoding attribute 47 length 12544 Nov 14 15:10:25.877742 Decoding attribute 10005 length 4 Nov 14 15:10:25.877777 Decoding attribute 10014 length 4 Nov 14 15:10:25.877811 Decoding attribute 10169 length 8 Nov 14 15:10:25.877845 Decoding attribute 33025 length 5 Nov 14 15:10:25.877892 Decoding attribute 33026 length 6 Nov 14 15:10:25.877953 Processing address request in default:default network 92.38.124.1 mac 4C:5E:0C:46:50:79 Nov 14 15:10:25.878003 Client Pool Name NoMoney-POOL set for session: 421560 Nov 14 15:10:25.878045 Processing rule Network-Match Nov 14 15:10:25.878080 ***************** START-NetworkMatch ******************** Nov 14 15:10:25.878117 DUMP of all addressRequest fields for subscriber session-id:421560 router default:default Nov 14 15:10:25.878162 client type jdhcpd client type 1 mac address 4C:5E:0C:46:50:79 Nov 14 15:10:25.878211 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 92.38.124.1 client pool name NoMoney-POOL Nov 14 15:10:25.878250 Framed-Pool-->SDB_USER_IP_POOL 'NoMoney-POOL' used for V4NA Nov 14 15:10:25.878294 V4NA: req: yes pool: NULL address: null Nov 14 15:10:25.878336 V6NA: req: no pool: NULL address: null Nov 14 15:10:25.878385 V6PD: req: no pool: NULL prefix: null/0 Nov 14 15:10:25.878432 V6NDRA: req: no pool: NULL ndra prefix: null/0 Nov 14 15:10:25.878470 ********************************************************* Nov 14 15:10:25.878521 NetworkMatch: Found a pool IPoE-Pool Nov 14 15:10:25.878563 NetworkMatch: calling addressGetNext for pool 'IPoE-Pool' Nov 14 15:10:25.878600 No host is found Nov 14 15:10:25.878657 Searching for available address in range IPoE-Pool, low=92.38.124.2, high=92.38.124.254, next=92.38.124.38 session-id:421560 Nov 14 15:10:25.878723 ****************** END-NetworkMatch ********************* Nov 14 15:10:25.878762 DUMP of all addressRequest fields for subscriber session-id:421560 router default:default Nov 14 15:10:25.878807 client type jdhcpd client type 1 mac address 4C:5E:0C:46:50:79 Nov 14 15:10:25.879264 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null network 92.38.124.1 client pool name NoMoney-POOL Nov 14 15:10:25.879305 Framed-Pool-->SDB_USER_IP_POOL 'NoMoney-POOL' used for V4NA Nov 14 15:10:25.879353 V4NA: req: yes pool: IPoE-Pool address: 92.38.124.38 Nov 14 15:10:25.879395 V6NA: req: no pool: NULL address: null Nov 14 15:10:25.879443 V6PD: req: no pool: NULL prefix: null/0 Nov 14 15:10:25.879490 V6NDRA: req: no pool: NULL ndra prefix: null/0 Nov 14 15:10:25.879528 ********************************************************* Nov 14 15:10:25.879565 Processing rule UserDefined:01 Nov 14 15:10:25.879598 ***************** START-CustomRules ********************* Nov 14 15:10:25.879633 DUMP of all addressRequest fields for subscriber session-id:421560 router default:default Nov 14 15:10:25.879679 client type jdhcpd client type 1 mac address 4C:5E:0C:46:50:79 Nov 14 15:10:25.879726 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null network 92.38.124.1 client pool name NoMoney-POOL Nov 14 15:10:25.879765 Framed-Pool-->SDB_USER_IP_POOL 'NoMoney-POOL' used for V4NA Nov 14 15:10:25.879812 V4NA: req: yes pool: IPoE-Pool address: 92.38.124.38 Nov 14 15:10:25.879853 V6NA: req: no pool: NULL address: null Nov 14 15:10:25.879904 V6PD: req: no pool: NULL prefix: null/0 Nov 14 15:10:25.879951 V6NDRA: req: no pool: NULL ndra prefix: null/0 Nov 14 15:10:25.879988 ********************************************************* Nov 14 15:10:25.880050 Searching for available address in range IPoE-Pool, low=92.38.124.2, high=92.38.124.254, next=92.38.124.39 session-id:421560 Nov 14 15:10:25.880117 ****************** END-CustomRules ********************** Nov 14 15:10:25.880156 DUMP of all addressRequest fields for subscriber session-id:421560 router default:default Nov 14 15:10:25.880202 client type jdhcpd client type 1 mac address 4C:5E:0C:46:50:79 Nov 14 15:10:25.880250 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null network 92.38.124.1 client pool name NoMoney-POOL Nov 14 15:10:25.880289 Framed-Pool-->SDB_USER_IP_POOL 'NoMoney-POOL' used for V4NA Nov 14 15:10:25.880335 V4NA: req: yes pool: IPoE-Pool address: 92.38.124.39 Nov 14 15:10:25.880376 V6NA: req: no pool: NULL address: null Nov 14 15:10:25.880424 V6PD: req: no pool: NULL prefix: null/0 Nov 14 15:10:25.880471 V6NDRA: req: no pool: NULL ndra prefix: null/0 Nov 14 15:10:25.880508 ********************************************************* Nov 14 15:10:25.880561 Pool::addressAssign: pool IPoE-Pool addr 92.38.124.39 range 92.38.124.2 session-id:421560 Nov 14 15:10:25.880620 Pool::addressAssign: pool IPoE-Pool addr 92.38.124.39 range 92.38.124.2 returning session-id:421560 Nov 14 15:10:25.880682 Trying to assign address 92.38.124.39 to subscriber session-id:421560 Nov 14 15:10:25.881021 Result have been returned with opcode=0, result=2 Nov 14 15:10:25.881062 ************* Results of Address Allocation ************* Nov 14 15:10:25.881101 DUMP of all addressRequest fields for subscriber session-id:421560 router default:default Nov 14 15:10:25.881146 client type jdhcpd client type 1 mac address 4C:5E:0C:46:50:79 Nov 14 15:10:25.881194 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null network 92.38.124.1 client pool name NoMoney-POOL Nov 14 15:10:25.881233 Framed-Pool-->SDB_USER_IP_POOL 'IPoE-Pool' used for V4NA Nov 14 15:10:25.881281 V4NA: req: yes pool: IPoE-Pool address: 92.38.124.39 Nov 14 15:10:25.881323 V6NA: req: no pool: NULL address: null Nov 14 15:10:25.881370 V6PD: req: no pool: NULL prefix: null/0 Nov 14 15:10:25.881444 V6NDRA: req: no pool: NULL ndra prefix: null/0 Nov 14 15:10:25.881482 ********************************************************* Nov 14 15:10:25.881532 authd_auth_update_local_server_address ::Searching access profile CLIENTS for local DNS Server Nov 14 15:10:25.881586 AuthFsm::current state=AuthStart(1) event=2 astEntry=0x20d74d8 aaa msg=0x1f6e06c Nov 14 15:10:25.882025 Auth-FSM: Process Auth-Response for session-id:421560 and client type broadband Nov 14 15:10:25.882060 createDynamicRequest: (2) received Nov 14 15:10:25.882158 requestString=svc-nomoney-ipoe Nov 14 15:10:25.882213 serviceName=svc-nomoney-ipoe,serviceString=svc-nomoney-ipoe Nov 14 15:10:25.882255 Decoding the Dynamic-Service=svc-nomoney-ipoe. Request= Nov 14 15:10:25.882314 Framework: auth result is 1. Performing post-auth operations Nov 14 15:10:25.882356 Framework: result is 1. Nov 14 15:10:25.882392 authd_auth_send_answer: conn=2c08000, reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), sub-id=421560, cookie=283496, rply_len=28, num_tlv_blocks=0 Nov 14 15:10:25.882441 ################################################################### Nov 14 15:10:25.882474 ######################### AUTH REQ ACK SENT ####################### Nov 14 15:10:25.882505 ################################################################### Nov 14 15:10:25.882548 Auth-FSM: GRES-Mirror for session-id:421560 state:AuthClntRespWait(4) Nov 14 15:10:25.882860 authd_auth_aaa_msg_destroy Nov 14 15:10:25.883191 authd_auth_aaa_msg_destructauth_aaa_msg: 0x1f6e06c Nov 14 15:10:25.883238 authd_write_conn: response is 0x2c0805c, total len is 28 and sent is 0 Nov 14 15:10:25.883916 authd_write_conn: response is 0x2c0805c, wrote 28 bytes Nov 14 15:10:25.940072 authd_read_msg: Fresh msg arrival. fd=59, hdr_read=0, hdr_remnant=0, payload_read=0 payload_remnant=0 Nov 14 15:10:25.940152 fresh message conn=0x2c08000 Nov 14 15:10:25.940193 read fresh message conn=0x2c08000 hdr_remnant=0 hdr_read=32 Nov 14 15:10:25.940226 Read payload for new message. fd=59, rqst_len=32 Nov 14 15:10:25.940374 Read payload for new message. fd=59, payload_len=0, rqst_len=32, cookie=283496 Nov 14 15:10:25.940422 Process/Dispatch Client Message Nov 14 15:10:25.940455 New Process/Dispatch Client Message Nov 14 15:10:25.940506 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Nov 14 15:10:25.940543 authd_auth_aaa_msg_create aaa-key: username:() profile:() Nov 14 15:10:25.940578 Process Request Nov 14 15:10:25.940617 Client request received on conn-id:jdhcpd session-id:421560 Opcode:1, Subcode:5 Nov 14 15:10:25.940659 ################################################################### Nov 14 15:10:25.940692 ################## CLIENT/FAMILY ACTIVE RCVD ###################### Nov 14 15:10:25.940723 ################################################################### Nov 14 15:10:25.940812 Removing client snapshot Nov 14 15:10:25.940873 haveServicesToProcess: session-id:421560, family: FAMILY_TYPE_INET, existing dynRequest, services Pending, Auth State AuthClntRespWait Nov 14 15:10:25.940918 Auth-FSM: reinterpretFsmEvent 12 to 15 Nov 14 15:10:25.940956 AuthFsm::current state=AuthClntRespWait(4) event=15 astEntry=0x20d74d8 aaa msg=0x1f6e06c Nov 14 15:10:25.940991 Auth-FSM: Trigger service creations received @ login. session-id:421560 dynrequest does exist Nov 14 15:10:25.941034 Dynamic Service Creation Handler Nov 14 15:10:25.941079 smmServiceCreate::index:0 service:svc-nomoney-ipoe marked-as-processed:0 Nov 14 15:10:25.941454 setAccountingInfo: NULL profile ? 0 Nov 14 15:10:25.941496 setAccountingInfo: service accounting order Nov 14 15:10:25.941551 UserAccess:OPT82NOIP.0DDF000701.8479739960C7 session-id:421560 service:svc-nomoney-ipoe service-session-id:421561 service-state:activate-init Nov 14 15:10:25.941590 getServiceSession: No jsrc policy name for this service Nov 14 15:10:25.941628 smmServiceCreate::Created :1 services entries Nov 14 15:10:25.941661 cleanServiceList: numRequests 1 Nov 14 15:10:25.941706 rebuildServiceRequestList: session-id:421560 requestedConfigBitsFamilyType 1 Nov 14 15:10:25.941826 requestString=svc-nomoney-ipoe Nov 14 15:10:25.941908 serviceName=svc-nomoney-ipoe,serviceString=svc-nomoney-ipoe Nov 14 15:10:25.941947 rebuildServiceRequestList: No jsrc policy name for this service at CoA Nov 14 15:10:25.941990 Dynamic Service Handler session-id:421560 Nov 14 15:10:25.942024 smmServiceHandler::index:0 service:svc-nomoney-ipoe marked-as-processed:0 Nov 14 15:10:25.942059 Found an existing service AST entry Nov 14 15:10:25.942589 ServiceFsm::current state=SvcInit(0) event=1 servAstEntry=0x20da370 service session-id:421561 Nov 14 15:10:25.942625 SMM-FSM: Start service creation for session-id:421561 Nov 14 15:10:25.942667 SMM-FSM: Active Family Mask Subscriber:2, Service:0, Request: -1610692200 Nov 14 15:10:25.942717 Instantiating a Dynamic-Service:svc-nomoney-ipoe for service session:421561 for subscriber:421560 config-bits:0x2239c0fe 0 0 0 0 0 Nov 14 15:10:25.943677 smmServiceHandler::numReqsProcessed:1 Nov 14 15:10:25.943714 authd_auth_aaa_msg_destroy Nov 14 15:10:25.943751 authd_auth_aaa_msg_destroy: removing msg from recv queue Nov 14 15:10:25.943796 authd_auth_aaa_msg_destructauth_aaa_msg: 0x1f6e06c Nov 14 15:10:25.943842 Auth-FSM: GRES-Mirror for session-id:421560 state:AuthServCreateRespWait(7) Nov 14 15:10:26.100249 smm_response_handle_callback Nov 14 15:10:26.100314 Ack/Nack from dyn-prof-lib for session-id:421561. result-code:0, applied_config_bits 0x6 0 0 0 0 0 Nov 14 15:10:26.100969 smmHandleDynProfileResponseUse Request Config Bits from ServiceRequest: 0x2239c0fe 0 0 0 0 0 Nov 14 15:10:26.101007 smmHandleDynProfileResponse: Family inet active Nov 14 15:10:26.101054 ServiceFsm::current state=SvcActivateStart(1) event=2 servAstEntry=0x20da370 service session-id:421561 Nov 14 15:10:26.101100 UserAccess:OPT82NOIP.0DDF000701.8479739960C7 session-id:421560 service:svc-nomoney-ipoe service-session-id:421561 service-state:active Nov 14 15:10:26.101187 persistOnlyPrivateDataWithState session-id:421561 new state 2 Nov 14 15:10:26.102311 SMM-FSM: Marking service Active for session-id:421561 Nov 14 15:10:26.102352 markAsProcessed: ServiceRequestEntry service session-id:421561 Nov 14 15:10:26.102388 About to check if all services have been processed Nov 14 15:10:26.102419 allServiceRequestsProcessed: session-id:421561 markedAsProcessed=1 Nov 14 15:10:26.102451 About to check if all services have been processed Nov 14 15:10:26.102480 allServiceRequestsProcessed: session-id:421561 markedAsProcessed=1 Nov 14 15:10:26.102514 Sending Service Processed Response Nov 14 15:10:26.102547 Service instantiations all succeeded for session-id:421560 Nov 14 15:10:26.102578 authEvent 16 Nov 14 15:10:26.103114 AuthFsm::current state=AuthServCreateRespWait(7) event=16 astEntry=0x20d74d8 aaa msg=0 Nov 14 15:10:26.103158 Forcing an updated client snapshot Nov 14 15:10:26.103196 Taking a client snapshot, session-id:421560 Nov 14 15:10:26.103344 resyncOnActivation: session-id: 421560, interfaceName: demux0.1073934921 Nov 14 15:10:26.103418 Auth-FSM: processSubActivation: Dynamic Request Complete, Dynamic Request Type 2 session-id:421560 Nov 14 15:10:26.103458 performFinalFunctions: initialServiceAtLoginRequest Nov 14 15:10:26.103498 checkForLoginLiService session-id: 421560 Nov 14 15:10:26.103533 ~CoARequest 20eb06c Nov 14 15:10:26.103564 cleanServiceList: numRequests 1 Nov 14 15:10:26.103598 markAsProcessed: ServiceRequestEntry service session-id:421561 Nov 14 15:10:26.103647 ~DynamicRequestEntry 20eb06c Nov 14 15:10:26.103683 Auth-FSM: Trigger Acct-Start and post Subscriber-Activated-Ack to the client daemon. session-id:421560 Nov 14 15:10:26.103715 Auth-FSM: Trigger Acct-Start. session-id:421560 Nov 14 15:10:26.103748 ======= Accounting START triggered ============== Nov 14 15:10:26.103787 checkLicense Nov 14 15:10:26.104446 AccFsm::current state=Acc-Init(0) event=1 astEntry=0x20d74d8 session-id:421560 Nov 14 15:10:26.104489 ACC-FSM:sendAccStart_a1 for session-id:421560 Nov 14 15:10:26.104524 Authd module Accounting Nov 14 15:10:26.104568 Authd acctg module start Nov 14 15:10:26.104621 authd_radius_send_acctg_msg: Starting RADIUS accounting Nov 14 15:10:26.104655 authd_radius_send_acctg_msg: got params profile=CLIENTS username=OPT82NOIP.0DDF000701.8479739960C7 acctg_id=(421560), ls=default, lr=default Nov 14 15:10:26.104709 radius-acct-start: User-Name added: OPT82NOIP.0DDF000701.8479739960C7 Nov 14 15:10:26.104749 radius-acct-start: Acct-Status-Type added: 1 Nov 14 15:10:26.104791 radius-acct-start: Acct-Session-Id added: 421560 Nov 14 15:10:26.104854 radius-acct-start: Service-Type added: 2 Nov 14 15:10:26.105380 radius-acct-start: Cos-Shaping-Rate (Juniper-ERX-VSA) added: Port Speed: 1000000k Nov 14 15:10:26.105465 radius-acct-start: Acct-Authentic added: 1 Nov 14 15:10:26.105516 radius-acct-start: Acct-Delay-Time added: 0 Nov 14 15:10:26.105611 radius-acct-start: DHCP-Options (Juniper-ERX-VSA) added: 35 01 01 37 07 01 79 03 21 06 2a 8a 0c 08 4d 69 6b 72 6f 54 69 6b 3d 07 01 4c 5e 0c 46 50 79 52 1e 01 05 0d df 00 07 01 02 06 84 79 73 99 60 c7 09 0d 00 00 0c f8 08 01 06 53 77 69 74 63 68 Nov 14 15:10:26.105669 radius-acct-start: DHCP-MAC-Address (Juniper-ERX-VSA) added: 4c5e.0c46.5079 Nov 14 15:10:26.105727 radius-acct-start: Event-Timestamp added: 2017-11-14 15:10:25 Nov 14 15:10:26.105776 radius-acct-start: Framed-IP-Address added: 92.38.124.39 Nov 14 15:10:26.105825 radius-acct-start: Framed-IP-Netmask added: 255.255.255.0 Nov 14 15:10:26.105949 radius-acct-start: NAS-Port added: 10 40 0d df Nov 14 15:10:26.106000 radius-acct-start: NAS-Port-Id added: ge-1/1/1.1073934920:3551 Nov 14 15:10:26.106052 radius-acct-start: NAS-Port-Type added: 15 Nov 14 15:10:26.106106 radius-acct-start: Agent-Circuit-Id (DSL Forum-VSA) Sub-Attribute added: ^M Nov 14 15:10:26.106151 radius-acct-start: Agent-Remote-Id (DSL Forum-VSA) Sub-Attribute added: <84>ys<99>` Nov 14 15:10:26.106205 authd_create_application_specific_radius_server: Evaluating RADIUS server 0xc21c59a1 to add to the server list Nov 14 15:10:26.106251 Verify source address 5c267f03 (92.38.127.3) in routing instance index=0 Nov 14 15:10:26.106587 accFsmExecute::new state=Acc-Start-Sent(1) Nov 14 15:10:26.106636 ======= Accounting IMMEDIATE Update triggered ============== Nov 14 15:10:26.107017 AccFsm::current state=Acc-Start-Sent(1) event=4 astEntry=0x20d74d8 session-id:421560 Nov 14 15:10:26.107064 accFsmExecute::new state=Acc-Interim-Sent(3) Nov 14 15:10:26.107543 authd_build_aaa_request: Found no dynRequest Nov 14 15:10:26.107578 ################################################################### Nov 14 15:10:26.107609 ################### CLIENT (RE)ACTIVATE ACK SENT #################### Nov 14 15:10:26.107640 ################################################################### Nov 14 15:10:26.107679 authd_auth_send_answer: conn=2c08000, reply-code=1 (OK), result-subopcode=5 (SESSION_IPV4_ACTIVATE), sub-id=421560, cookie=283496, rply_len=28, num_tlv_blocks=0 Nov 14 15:10:26.107740 UserAccess:OPT82NOIP.0DDF000701.8479739960C7 session-id:421560 state:access-granted ge-1/1/1.1073934920:3551 Nov 14 15:10:26.107782 Auth-FSM: GRES-Mirror for session-id:421560 state:AuthStateActive(9) Nov 14 15:10:26.108051 authd_auth_aaa_msg_destroy Nov 14 15:10:26.108105 authd_auth_aaa_msg_destructauth_aaa_msg: 0x1f6f0b0 Nov 14 15:10:26.108140 authd_write_conn: response is 0x2c0805c, total len is 28 and sent is 0 Nov 14 15:10:26.108742 authd_write_conn: response is 0x2c0805c, wrote 28 bytes Nov 14 15:10:26.108984 authd_radius_get_config:Using radius option config from access stanza Nov 14 15:10:26.109046 Radius result is CLIENT_REQ_STATUS_SUCCESS Nov 14 15:10:26.109081 authd_radius_acctg_callback Result is :(CLIENT_REQ_STATUS_SUCCESS) reply_code:(Accounting-Response) 5 sub-id: 421560 Nov 14 15:10:26.109129 ======= Accounting RESPONSE Received ============== Nov 14 15:10:26.109175 AccFsm::current state=Acc-Interim-Sent(3) event=2 astEntry=0x20d74d8 session-id:421560 Nov 14 15:10:26.109210 ACC-FSM:processAccStartRsp_a2 for session-id:421560 Nov 14 15:10:26.109249 accFsmExecute::new state=Acc-Interim-Sent(3) Nov 14 15:10:26.462955 serviceRadiusRequestQueues Serviced 2 RADIUS requests Nov 14 15:10:26.463072 serviceRadiusRequestQueues Queue CLIENTS has 0 requests, peak is 0 Nov 14 15:10:26.538097 Interim stats call back 421560 Nov 14 15:10:26.538173 ======= Accounting Volume INTERIM triggered ============== Nov 14 15:10:26.538230 calcAndAddVolumeStats libstats_substats_difference (&stats.ls_app_cleared, &stats.ls_local) Nov 14 15:10:26.538274 libstats_substats_difference (&stats.ls_ipv6_app_cleared, &stats.ls_ipv6_local) Nov 14 15:10:26.538324 AccFsm::current state=Acc-Interim-Sent(3) event=5 astEntry=0x20d74d8 session-id:421560 Nov 14 15:10:26.538361 ACC-FSM:sendAccInterim_a4 for session-id:421560 Nov 14 15:10:26.538395 Authd module Accounting Nov 14 15:10:26.538440 Authd acctg module start Nov 14 15:10:26.538471 authd_radius_send_acctg_msg: Starting RADIUS accounting Nov 14 15:10:26.538504 authd_radius_send_acctg_msg: got params profile=CLIENTS username=OPT82NOIP.0DDF000701.8479739960C7 acctg_id=(421560), ls=default, lr=default Nov 14 15:10:26.538558 radius-acct-interim: User-Name added: OPT82NOIP.0DDF000701.8479739960C7 Nov 14 15:10:26.538599 radius-acct-interim: Acct-Status-Type added: 3 Nov 14 15:10:26.538644 radius-acct-interim: Acct-Session-Id added: 421560 Nov 14 15:10:26.538694 radius-acct-interim: Acct-Input-Octets added: 0 Nov 14 15:10:26.538740 radius-acct-interim: Acct-Output-Octets added: 0 Nov 14 15:10:26.538785 radius-acct-interim: Acct-Session-Time added: 1 Nov 14 15:10:26.538829 radius-acct-interim: Acct-Input-Packets added: 0 Nov 14 15:10:26.538880 radius-acct-interim: Acct-Output-Packets added: 0 Nov 14 15:10:26.538944 radius-acct-interim: Service-Type added: 2 Nov 14 15:10:26.539464 radius-acct-interim: Cos-Shaping-Rate (Juniper-ERX-VSA) added: Port Speed: 1000000k Nov 14 15:10:26.539545 radius-acct-interim: Acct-Authentic added: 1 Nov 14 15:10:26.539595 radius-acct-interim: Acct-Delay-Time added: 0 Nov 14 15:10:26.539690 radius-acct-interim: DHCP-Options (Juniper-ERX-VSA) added: 35 01 01 37 07 01 79 03 21 06 2a 8a 0c 08 4d 69 6b 72 6f 54 69 6b 3d 07 01 4c 5e 0c 46 50 79 52 1e 01 05 0d df 00 07 01 02 06 84 79 73 99 60 c7 09 0d 00 00 0c f8 08 01 06 53 77 69 74 63 68 Nov 14 15:10:26.539787 radius-acct-interim: DHCP-MAC-Address (Juniper-ERX-VSA) added: 4c5e.0c46.5079 Nov 14 15:10:26.539846 radius-acct-interim: Event-Timestamp added: 2017-11-14 15:10:26 Nov 14 15:10:26.539901 radius-acct-interim: Framed-IP-Address added: 92.38.124.39 Nov 14 15:10:26.539950 radius-acct-interim: Framed-IP-Netmask added: 255.255.255.0 Nov 14 15:10:26.539998 radius-acct-interim: Input-Gigapackets (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.540046 radius-acct-interim: Acct-Input-Gigawords added: 0 Nov 14 15:10:26.540584 radius-acct-interim: NAS-Port added: 10 40 0d df Nov 14 15:10:26.540628 radius-acct-interim: NAS-Port-Id added: ge-1/1/1.1073934920:3551 Nov 14 15:10:26.540675 radius-acct-interim: NAS-Port-Type added: 15 Nov 14 15:10:26.540721 radius-acct-interim: Output-Gigapackets (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.540768 radius-acct-interim: Acct-Output-Gigawords added: 0 Nov 14 15:10:26.540815 radius-acct-interim: IPv6-Acct-Input-Octets (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.540863 radius-acct-interim: IPv6-Acct-Output-Octets (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.540915 radius-acct-interim: IPv6-Acct-Input-Packets (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.540963 radius-acct-interim: IPv6-Acct-Output-Packets (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.541010 radius-acct-interim: IPv6-Acct-Input-Gigawords (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.541057 radius-acct-interim: IPv6-Acct-Output-Gigawords (Juniper-ERX-VSA) added: 0 Nov 14 15:10:26.541111 radius-acct-interim: Agent-Circuit-Id (DSL Forum-VSA) Sub-Attribute added: ^M Nov 14 15:10:26.541155 radius-acct-interim: Agent-Remote-Id (DSL Forum-VSA) Sub-Attribute added: <84>ys<99>` Nov 14 15:10:26.541205 authd_create_application_specific_radius_server: Evaluating RADIUS server 0xc21c59a1 to add to the server list Nov 14 15:10:26.541251 Verify source address 5c267f03 (92.38.127.3) in routing instance index=0 Nov 14 15:10:26.541577 accFsmExecute::new state=Acc-Interim-Sent(3) Nov 14 15:10:26.544288 authd_radius_get_config:Using radius option config from access stanza Nov 14 15:10:26.544348 Radius result is CLIENT_REQ_STATUS_SUCCESS Nov 14 15:10:26.544385 authd_radius_acctg_callback Result is :(CLIENT_REQ_STATUS_SUCCESS) reply_code:(Accounting-Response) 5 sub-id: 421560 Nov 14 15:10:26.544433 ======= Accounting RESPONSE Received ============== Nov 14 15:10:26.544478 AccFsm::current state=Acc-Interim-Sent(3) event=7 astEntry=0x20d74d8 session-id:421560 Nov 14 15:10:26.544512 ACC-FSM:processAccInterimRsp_a5 for session-id:421560 Nov 14 15:10:26.544550 accFsmExecute::new state=Acc-Interim-Sent(3) Nov 14 15:10:27.462894 serviceRadiusRequestQueues Serviced 1 RADIUS requests Nov 14 15:10:27.462979 serviceRadiusRequestQueues Queue CLIENTS has 0 requests, peak is 0