Sep 10 23:47:32.839996 authd_config_read: old seq 101 and new one 102 Sep 10 23:47:32.849244 Termintate-code: no configuration Sep 10 23:47:32.849537 host-name changed in system config Sep 10 23:47:32.853114 Extensible Services mode turned OFF Sep 10 23:47:32.853273 accounting-backup-options: no configuration Sep 10 23:47:32.853317 AaaService::configRead Sep 10 23:47:32.853343 AaaService::configReadAccess Sep 10 23:47:32.853444 lookForTheMissing callback: default:default Sep 10 23:47:32.853582 Config changed for a AaaService Sep 10 23:47:32.853627 Config changed for routing context default:default Sep 10 23:47:32.856907 Duplicate Address Protection disabled for routing context default:default Sep 10 23:47:32.857287 Config changed for pool junosDHCPPool1 Sep 10 23:47:32.857559 Updating pool junosDHCPPool1, network 192.168.1.0/24 Sep 10 23:47:32.857621 xauthAttrsSet: start Sep 10 23:47:32.857661 xauthAttrsSet: xauth does not be configed Sep 10 23:47:32.860838 Config changed for range junosRange Sep 10 23:47:32.860962 Deleting all hosts in pool junosDHCPPool1 Sep 10 23:47:32.861026 Config changed for pool junosDHCPPool2 Sep 10 23:47:32.861113 Updating pool junosDHCPPool2, network 192.168.2.0/24 Sep 10 23:47:32.861167 xauthAttrsSet: start Sep 10 23:47:32.861203 xauthAttrsSet: xauth does not be configed Sep 10 23:47:32.861268 Config changed for range junosRange Sep 10 23:47:32.861330 Deleting all hosts in pool junosDHCPPool2 Sep 10 23:47:32.861386 Config changed for pool dyn-vpn-address-pool Sep 10 23:47:32.861454 Updating pool dyn-vpn-address-pool, network 192.168.199.0/24 Sep 10 23:47:32.861501 xauthAttrsSet: start Sep 10 23:47:32.861558 xauthAttrsSet: dns primary ip-address 192.168.90.10 Sep 10 23:47:32.861613 xauthAttrsSet: dns secondary ip-address 192.168.90.11 Sep 10 23:47:32.861673 Remove range __default low 192.168.199.1 in pool dyn-vpn-address-pool Sep 10 23:47:32.864841 Decrement range count by 0 hosts for __default with low 192.168.199.1 high 192.168.199.255 with current total 255 in pool dyn-vpn-address-pool Sep 10 23:47:32.864976 Deleting all hosts in pool dyn-vpn-address-pool Sep 10 23:47:32.865253 Domain-map config changed. Routing context:default:default Sep 10 23:47:32.865327 Domain-map config deleted. Routing context:default:default Sep 10 23:47:32.865477 configReadTunnelSwitchProfiles: no tunnel-switch profiles configured Sep 10 23:47:32.865524 AaaService::configReadAaaAttachment Sep 10 23:47:32.865552 delVrfTable: deleting vrf table Sep 10 23:47:32.870306 addVrfEntry: Added VRF to table default; 0 Sep 10 23:47:32.870393 Config deleted for AAA routing context default:default Sep 10 23:47:32.870544 Config deleted for AAA routing context default:default Sep 10 23:47:32.870639 Config deleted for AAA routing context default:default Sep 10 23:47:32.874121 Clearing rule list Sep 10 23:47:32.874212 Clearing rule list Sep 10 23:47:32.874255 Adding rule External-Authority for client jdhcpd-client Sep 10 23:47:32.874290 Adding rule Network-Match for client jdhcpd-client Sep 10 23:47:32.874324 Adding rule External-Authority for client jdhcpd-test-client Sep 10 23:47:32.874358 Adding rule Network-Match for client jdhcpd-test-client Sep 10 23:47:32.877053 authd_access_server_read: Reading Configuration for access Sep 10 23:47:32.877121 authd_access_server_free: Deleting Configuration de3d24 Sep 10 23:47:32.877171 authd_access_profile_pending_acct_data_cache:Access profile unint exit: PendAPTable empty = 1 Sep 10 23:47:32.877266 authd_access_profile_pool_change: succeed to find out profile dyn-vpn-access-profile Sep 10 23:47:32.877318 address-assignment pool value dyn-vpn-address-pool, profile pool name dyn-vpn-address-pool. Sep 10 23:47:32.880044 authd_access_profile_pool_change: pool(dyn-vpn-address-pool) under profile is no change Sep 10 23:47:32.880267 authd_check_and_send_acct_off: Not sending ACCT-OFF for profile: dyn-vpn-access-profile, as send_acct_status_on_config_change flag not enabled. Sep 10 23:47:32.880339 Deleting RADIUS request queue for profile: dyn-vpn-access-profile Sep 10 23:47:32.880418 disable RADIUS request queue disabled for profile: dyn-vpn-access-profile Sep 10 23:47:32.880467 authd_access_server_free: Deleting Configuration 1a1ecd4 Sep 10 23:47:32.880601 got authentication order value 1 Sep 10 23:47:32.880649 authorization order called Sep 10 23:47:32.880676 provisioning order called Sep 10 23:47:32.880709 read accounting configurations Sep 10 23:47:32.880772 Acc-order is NOT configured Sep 10 23:47:32.880834 Accounting option: accounting-stop-on-failure NOT configured Sep 10 23:47:32.880885 Accounting option: accounting-stop-on-deny NOT configured Sep 10 23:47:32.883063 Accounting option: immediate-update NOT configured Sep 10 23:47:32.883119 Accounting option: acc_wait_for_acct_on_ack NOT configured Sep 10 23:47:32.883170 Accounting option: send_acct_status_on_config_change NOT configured Sep 10 23:47:32.883229 Accounting option: ancp_speed_change_immediate_update NOT configured Sep 10 23:47:32.883269 Accounting Interval not configured Sep 10 23:47:32.883304 Accounting Interval not configured Sep 10 23:47:32.883346 Accounting option: duplication NOT configured Sep 10 23:47:32.883402 Accounting option: duplication filter is not configured Sep 10 23:47:32.883458 Accounting option: duplication-vrf NOT configured Sep 10 23:47:32.883507 Service acct-order not configured Sep 10 23:47:32.883553 Service acct-stats-type not configured Sep 10 23:47:32.883588 Service acct-interval not configured Sep 10 23:47:32.883641 Accounting coa-no-override not configured Sep 10 23:47:32.883678 address-assignment pool called Sep 10 23:47:32.883721 address-assignment pool value dyn-vpn-address-pool. Sep 10 23:47:32.883751 authd_config_read_radius_attributes radius stanza not cfg under profile:3817a724 Sep 10 23:47:32.883782 authd_access_server_read: Reading Configuration for profile Sep 10 23:47:32.883809 authd_access_server_free: Deleting Configuration 1a1ecd4 Sep 10 23:47:32.883841 authd_access_profile_config_read_params dyn-vpn-access-profile status 1 Sep 10 23:47:32.883883 Creating RADIUS request queue for profile: dyn-vpn-access-profile Sep 10 23:47:32.885184 Dumping Profile dyn-vpn-access-profile Sep 10 23:47:32.885253 Auth order count=1, order = 1 0 Sep 10 23:47:32.885279 Accounting Options: Accounting Order=0, stop_on_aaa_fail=0, stop_on_access_deny=0, immediate_update=0, coa_immediate_update=0, address_change_immediate_update=0, interval=0, stat_type=1, dup_en=0 Sep 10 23:47:32.885310 Session Options: groups_len=0, idle_timeout=0, session_timeout=0 Sep 10 23:47:32.885335 Client name filter: domain=[], count=0, separator=@ Sep 10 23:47:32.885376 authd_radius_module_config_init: result=SUCCESS Sep 10 23:47:32.885449 authd_read_profiles_radius_callback: Read radius server under [access profile dyn-vpn-access-profile] Sep 10 23:47:32.885522 Got the profile name:dyn-vpn-access-profile Sep 10 23:47:32.885562 No Radius options configured for the profile: dyn-vpn-access-profile Sep 10 23:47:32.885591 Cleanup ignore list for profile:dyn-vpn-access-profile for all msg-types Sep 10 23:47:32.885691 Cleanup exclude list for profile:dyn-vpn-access-profile for all msg-types Sep 10 23:47:32.885799 Dumping Access radius config ----------- Sep 10 23:47:32.885843 Radius options options-at-default=1 Sep 10 23:47:32.885867 Radius options revert-interval=60 request-rate=500 Sep 10 23:47:32.885891 Radius options access-loop-id-local=0 ether-port-type-virtual=0 ether_port_type_override=15 if-desc-format-sub-if=0 if-desc-format-adapter=0 acct-session-id-format=0 vlan-nas-port-stacked-format=0 override-nas-info=0 nas-identifier= Sep 10 23:47:32.885937 Radius options nas-port-id-delimiter="#" nas-port-id-format NID=0 IID=0 ACI=0 ARI=0 Sep 10 23:47:32.887042 Radius options calling-station-id-delimiter="#" calling-station-id-format NID=0 IID=0 ACI=0 ARI=0 MAC=0 ALIAS=0 SVLAN=0 VLAN=0 Sep 10 23:47:32.887075 Radius options remote-circuit-id-delimiter="#" remote-circuit-id-format ACI=0 ARI=0 remote-circuit-id-override-CSI=0, remote-circuit-id-fallback=0 Sep 10 23:47:32.887754 Radius options Unique-NAS-port=0 Unique-NAS-Port-chassis-id=0 Unique-NAS-Port-chassis-id-width=0 Sep 10 23:47:32.887819 Radius options NAS-port-extended-format ae-width= 0 slot-width=0 adapter_width=0 port_width=0 pw_width=0 svlan_width=0 vlan_width=0 coa_dynamic_variable_validation=0 Sep 10 23:47:32.887854 Radius options NAS-port-extended-format atm slot-width=0 adapter_width=0 port_width=0 vpi_width=0 vci_width=0 Sep 10 23:47:32.887882 Radius options client_auth_algorithm=0 client_acct_algorithm=0 juniper_dsl_attributes=0 Sep 10 23:47:32.887907 Radius options ip_address_change_notify=0 ip_address_change_notify_msg= Sep 10 23:47:32.887931 Radius options timeout_grace=10 Sep 10 23:47:32.889032 Radius options extensible_service_required_at_login=FALSE Sep 10 23:47:32.889067 Radius options dynamic_profile_service_required_at_login=TRUE Sep 10 23:47:32.889093 Radius options no-radius-queues=0 no-max-outstanding=0 Sep 10 23:47:32.889118 Done ----------- Sep 10 23:47:32.889154 Dumping dyn-vpn-access-profile radius servers ----------- Sep 10 23:47:32.889189 Radius options options-at-default=1 Sep 10 23:47:32.889213 Radius options revert-interval=60 request-rate=500 Sep 10 23:47:32.889237 Radius options access-loop-id-local=0 ether-port-type-virtual=0 ether_port_type_override=15 if-desc-format-sub-if=0 if-desc-format-adapter=0 acct-session-id-format=0 vlan-nas-port-stacked-format=0 override-nas-info=0 nas-identifier= Sep 10 23:47:32.889268 Radius options nas-port-id-delimiter="#" nas-port-id-format NID=0 IID=0 ACI=0 ARI=0 Sep 10 23:47:32.889295 Radius options calling-station-id-delimiter="#" calling-station-id-format NID=0 IID=0 ACI=0 ARI=0 MAC=0 ALIAS=0 SVLAN=0 VLAN=0 Sep 10 23:47:32.889324 Radius options remote-circuit-id-delimiter="#" remote-circuit-id-format ACI=0 ARI=0 remote-circuit-id-override-CSI=0, remote-circuit-id-fallback=0 Sep 10 23:47:32.889351 Radius options Unique-NAS-port=0 Unique-NAS-Port-chassis-id=0 Unique-NAS-Port-chassis-id-width=0 Sep 10 23:47:32.889377 Radius options NAS-port-extended-format ae-width= 0 slot-width=0 adapter_width=0 port_width=0 pw_width=0 svlan_width=0 vlan_width=0 coa_dynamic_variable_validation=0 Sep 10 23:47:32.889432 Radius options NAS-port-extended-format atm slot-width=0 adapter_width=0 port_width=0 vpi_width=0 vci_width=0 Sep 10 23:47:32.889464 Radius options client_auth_algorithm=0 client_acct_algorithm=0 juniper_dsl_attributes=0 Sep 10 23:47:32.889490 Radius options ip_address_change_notify=0 ip_address_change_notify_msg= Sep 10 23:47:32.889515 Radius options timeout_grace=10 Sep 10 23:47:32.889538 Radius options extensible_service_required_at_login=FALSE Sep 10 23:47:32.889562 Radius options dynamic_profile_service_required_at_login=TRUE Sep 10 23:47:32.889586 Done ----------- Sep 10 23:47:32.889765 Got the profile name:dyn-vpn-access-profile Sep 10 23:47:32.889811 No Radius options configured for the profile: dyn-vpn-access-profile Sep 10 23:47:32.889841 Cleanup ignore list for profile:dyn-vpn-access-profile for all msg-types Sep 10 23:47:32.889905 Cleanup exclude list for profile:dyn-vpn-access-profile for all msg-types Sep 10 23:47:32.891079 Framework: CONFIG RELOAD - Sep 10 23:47:32.891156 Local : start authd_local_module_config_clean Sep 10 23:47:32.891182 Local : start profiles_tree_destroy Sep 10 23:47:32.891208 Local : start delete_profile_node_data Sep 10 23:47:32.891258 pool(dyn-vpn-address-pool) is found Sep 10 23:47:32.891306 Local : delete_profile - clients tree for profile dyn-vpn-access-profile destroyed Sep 10 23:47:32.891338 Local : profiles_tree_destroy - destroyed Sep 10 23:47:32.891364 Local : profiles tree destroyed successfully Sep 10 23:47:32.891388 Local : start authd_local_module_config_init Sep 10 23:47:32.891414 Local : start authd_config_read_access_profiles_clients Sep 10 23:47:32.891438 Local : DAX_WALK_CONFIGURED Sep 10 23:47:32.891490 Local : start callback walk_profiles_cb Sep 10 23:47:32.891527 Local : walk-flag!= DAX_WALK_DELTA Sep 10 23:47:32.891551 Local : Item Changed Sep 10 23:47:32.891590 Local : profile dyn-vpn-access-profile Sep 10 23:47:32.891630 Local : start callback walk_clients_cb Sep 10 23:47:32.891700 Local : Item Changed Sep 10 23:47:32.891737 Local : client Sep 10 23:47:32.891763 Local : start add_client Sep 10 23:47:32.891787 Local : start add_profile Sep 10 23:47:32.893576 Local : creating/adding a new profile node Sep 10 23:47:32.893609 Local : start clients_tree_init Sep 10 23:47:32.893639 Local : creating/adding new client Sep 10 23:47:32.893669 Local : start update_client_data Sep 10 23:47:32.893904 Local : authd_config_read_xauth_attrs: not configure client xauth Sep 10 23:47:32.893951 Local : update_client_data - succeeded Sep 10 23:47:32.895033 Local : Done Sep 10 23:47:32.895097 Local : ** PROFILE dyn-vpn-access-profile ** Sep 10 23:47:32.895125 Local : client= , groups_len=0 Sep 10 23:47:32.895152 Framework: CONFIG RELOAD - Sep 10 23:47:32.895183 LDAP:CONFIG: result=SUCCESS Sep 10 23:47:32.895256 LDAP:CONFIG: Read ldap server under [access profile dyn-vpn-access-profile] Sep 10 23:47:32.895295 Dumping Access ldap config ----------- Sep 10 23:47:32.895332 Ldap options revert-interval=600, base-dn=, user-dn-search=assemble Sep 10 23:47:32.895358 Ldap assemble options cn=cn Sep 10 23:47:32.895382 Done ----------- Sep 10 23:47:32.895417 Dumping dyn-vpn-access-profile ldap servers ----------- Sep 10 23:47:32.895451 Ldap options revert-interval=600, base-dn=, user-dn-search=assemble Sep 10 23:47:32.895476 Ldap assemble options cn=cn Sep 10 23:47:32.895499 Done ----------- Sep 10 23:47:32.895551 Framework: CONFIG RELOAD - Sep 10 23:47:32.895584 SECURID:CONFIG: securid not configured Sep 10 23:47:32.895610 SECURID:CONFIG: securid configuration read SUCCEEDED Sep 10 23:47:32.895874 Dumping Access securid config ----------- Sep 10 23:47:32.895927 Securid server = UNCONFIGURED, file = UNCONFIGURED Sep 10 23:47:32.895953 Done ----------- Sep 10 23:47:32.895988 SECURID:CONFIG: sdconf.rec file location not configured. Sep 10 23:47:32.897051 Framework: CONFIG RELOAD - Sep 10 23:47:32.897102 Framework: CONFIG RELOAD - Sep 10 23:47:32.897169 authd_apply_acctg_config Sep 10 23:47:32.897211 authd_access_profile_apply_dynreq_config Build dynreq server list for profile:(dyn-vpn-access-profile) Sep 10 23:47:32.897246 authd_radius_dynreq_server_create error - no radius servers configured for profile dyn-vpn-access-profile Sep 10 23:47:32.897274 Creation of DM Server failed Sep 10 23:47:32.897373 authd_cfg_interfaces_cb: Interface not interested Sep 10 23:47:32.897636 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/0] Sep 10 23:47:32.899472 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/1] Sep 10 23:47:32.899663 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/2] Sep 10 23:47:32.899808 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/3] Sep 10 23:47:32.899958 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/4] Sep 10 23:47:32.901101 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/5] Sep 10 23:47:32.901331 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/6] Sep 10 23:47:32.901482 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/7] Sep 10 23:47:32.901642 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/8] Sep 10 23:47:32.901787 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/9] Sep 10 23:47:32.901933 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/10] Sep 10 23:47:32.903121 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/11] Sep 10 23:47:32.903341 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/12] Sep 10 23:47:32.903489 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/13] Sep 10 23:47:32.903633 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/14] Sep 10 23:47:32.903787 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/15] Sep 10 23:47:32.905423 authd_cfg_interfaces_cb: Interface fxp0 not interested Sep 10 23:47:32.905546 authd_cfg_interfaces_cb: Interface irb not interested Sep 10 23:47:32.905763 authd_config_read_interface: Radius-Options dax_query (interface) ret 0 Sep 10 23:47:32.909264 === Configuration reload succeeded === Sep 11 00:00:56.875827 authd_read_msg: Fresh msg arrival. fd=46, hdr_read=0, hdr_remnant=0, payload_read=0 payload_remnant=0 Sep 11 00:00:56.875915 fresh message conn=0x2924000 Sep 11 00:00:56.875953 read fresh message conn=0x2924000 hdr_remnant=0 hdr_read=32 Sep 11 00:00:56.875982 Read payload for new message. fd=46, rqst_len=98 Sep 11 00:00:56.876007 Read payload for new message. fd=46, payload_len=66, rqst_len=98, cookie=3 Sep 11 00:00:56.876054 Process/Dispatch Client Message Sep 11 00:00:56.876084 New Process/Dispatch Client Message Sep 11 00:00:56.876130 authd_tlv_build_list_from_struct username ( ) len:9 Sep 11 00:00:56.876159 authd_tlv_build_list_from_struct username l =10 offset =56 Sep 11 00:00:56.876191 authd_tlv_build_list_from_struct profile (0xf0a180) len:22 Sep 11 00:00:56.876219 authd_tlv_build_list_from_struct profile l =23 offset =66 Sep 11 00:00:56.876248 authd_tlv_build_list_from_struct password (0xf0a0f8) len:8 Sep 11 00:00:56.876275 authd_tlv_build_list_from_struct password l =9 offset =89 Sep 11 00:00:56.876304 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:3 Sep 11 00:00:56.876332 authd_auth_aaa_msg_create profile:(dyn-vpn-access-profile) Sep 11 00:00:56.876361 Process Request Sep 11 00:00:56.876394 Client request received on conn-id:CONN2924000:1 session-id:0 Opcode:1, Subcode:0 Sep 11 00:00:56.876449 create_subscriber_session_entry: Generated SubSessID 9256304617720733588 Sep 11 00:00:56.876527 Creating SubscriberASTEntry for session-id:9256304617720733588, session name: Sep 11 00:00:56.876575 setAccountingInfo: dyn-vpn-access-profile Sep 11 00:00:56.876612 setAccountingInfo: service accounting order Sep 11 00:00:56.878967 UserAccess: session-id:9256304617720733588 Access-profile:dyn-vpn-access-profile Multi-Acct-Session-Id:0 Sep 11 00:00:56.879051 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(dyn-vpn-access-profile), username=( ) Sep 11 00:00:56.879142 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x182b06c aaa msg=0xe5b06c Sep 11 00:00:56.879189 ################################################################### Sep 11 00:00:56.879219 ########################### AUTH REQ RCVD ######################### Sep 11 00:00:56.879244 ################################################################### Sep 11 00:00:56.879269 Auth-FSM: Process Auth-Request for session-id:9256304617720733588 Sep 11 00:00:56.879311 Framework: Starting authentication Sep 11 00:00:56.879345 authd_advance_module_for_aaa_request_msg: result:0 Sep 11 00:00:56.879379 Authd module start session-id:9256304617720733588 Sep 11 00:00:56.879414 Local : authd_local_start_auth: got params profile=dyn-vpn-access-profile, username= Sep 11 00:00:56.879441 Local : start authd_local_lookup Sep 11 00:00:56.879467 Local : profile dyn-vpn-access-profile found Sep 11 00:00:56.879493 Local : client found Sep 11 00:00:56.879519 Local : passwords matched Sep 11 00:00:56.879544 authd_auth_module_start: session-id:9256304617720733588 result = 2 start_auth; state = 0 Sep 11 00:00:56.879582 REQUEST: AUTHEN - module_index 0 module(password) return: SUCCESS Sep 11 00:00:56.879615 authd_auth_update_local_server_address Searching access profile dyn-vpn-access-profile for local DNS Server Sep 11 00:00:56.879644 Framework: auth result is 1. Performing post-auth operations Sep 11 00:00:56.879672 (authd_update_session_options) num_tlv_blocks:0 Sep 11 00:00:56.879697 Framework: Initialising response list Sep 11 00:00:56.879735 Framework: Updating session timeout (599999940) in response for user ' ' from profile 'dyn-vpn-access-profile' Sep 11 00:00:56.879764 Framework: length of first client-group if already present = 0 Sep 11 00:00:56.879790 Framework: result is 1. Sep 11 00:00:56.879817 authd_auth_send_answer: conn=2924000, reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), session-id:9256304617720733588, cookie=3, rply_len=4476, num_tlv_blocks=1 Sep 11 00:00:56.880473 sess_timeout: 599999940 Sep 11 00:00:56.880511 authd_auth_send_answer,tlv_begin:800 tot_tlv_buf_len:0 num_tlv_blocks:0 Sep 11 00:00:56.880539 authd_auth_send_answer, rply_len:4476 Sep 11 00:00:56.880565 authd_auth_send_answer: conn is 2924000 response is 2941000 result is 1, cookie = 3 rply_len:4476 num_tlv_block = 0 Sep 11 00:00:56.880632 Delete session-id:9256304617720733588 Sep 11 00:00:56.881167 Begin to logout Subscriber session-id:9256304617720733588 Sep 11 00:00:56.881247 UserAccess: session-id:9256304617720733588 state:log-out Sep 11 00:00:56.881445 authd_auth_aaa_msg_destroy Sep 11 00:00:56.881509 authd_auth_aaa_msg_destructauth_aaa_msg: 0xe5b06c Sep 11 00:00:56.881548 authd_write_conn: response is 0x292405c, total len is 4476 and sent is 0 Sep 11 00:00:56.881611 authd_write_conn: response is 0x292405c, wrote 4476 bytes Sep 11 00:14:02.396935 Process/Dispatch Client Message Sep 11 00:14:02.397026 New Process/Dispatch Client Message Sep 11 00:14:02.397074 authd_tlv_build_list_from_struct username l =1 offset =56 Sep 11 00:14:02.397105 authd_tlv_build_list_from_struct profile l =1 offset =57 Sep 11 00:14:02.397139 authd_tlv_build_list_from_struct password l =1 offset =58 Sep 11 00:14:02.397170 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Sep 11 00:14:02.397199 authd_auth_aaa_msg_create profile:() Sep 11 00:14:02.397228 Process Request Sep 11 00:14:02.397262 Client request received on conn-id:jdhcpd-client session-id:1 Opcode:64, Subcode:0 Sep 11 00:14:02.397307 Taking a client snapshot, session-id:1 Sep 11 00:14:02.402114 Creating SubscriberASTEntry for session-id:1, session name: Sep 11 00:14:02.404246 fillSessionDBAttributes: session-id:1, ifdName: irb Sep 11 00:14:02.404339 No access-profile found in the SDB for session-id:1 Sep 11 00:14:02.404387 PhyIfdName found in the SDB for session-id:1 Sep 11 00:14:02.404436 InterfaceName found in the SDB for session-id:1 Sep 11 00:14:02.406302 Querying the access-profile for user: on LR/RI:default:default Sep 11 00:14:02.406413 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:994 Failed to lookup an access-profile for session-id:1 with LS:RI key:default:default Sep 11 00:14:02.408365 authd_build_radius_nas_port_and_id: NASPortID = , NASPort = 0, CallingStationID = Sep 11 00:14:02.411896 Finding a client snapshot session-id:1 Sep 11 00:14:02.415084 Setting multi-acct-session-id to 0 Sep 11 00:14:02.415129 setAccountingInfo: Sep 11 00:14:02.415158 setAccountingInfo: service accounting order Sep 11 00:14:02.415199 updateCoaDynamicVariableValidation coaValidation: 0 Sep 11 00:14:02.415513 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:3742 Did not find dynamic-profile in the SDB for session-id:1 Sep 11 00:14:02.415580 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:693JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty Sep 11 00:14:02.415619 Bundle session id not found, setting to NULL Sep 11 00:14:02.415817 multi-acct-session-id set to 0 Sep 11 00:14:02.417519 On-demand IP address set to 0 Sep 11 00:14:02.419488 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=() Sep 11 00:14:02.419565 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x182b06c aaa msg=0xe5b06c Sep 11 00:14:02.419600 ################################################################### Sep 11 00:14:02.419627 ########################### AUTH REQ RCVD ######################### Sep 11 00:14:02.419652 ################################################################### Sep 11 00:14:02.419676 Auth-FSM: Process Auth-Request for session-id:1 Sep 11 00:14:02.420383 Framework: Starting authentication Sep 11 00:14:02.420418 authd_access_profile_get: Bad profile name . Sep 11 00:14:02.420448 authd_auth_begin_authentication: invoking none server Sep 11 00:14:02.420475 authd_advance_module_for_aaa_request_msg: result:0 Sep 11 00:14:02.420508 Authd module start session-id:1 Sep 11 00:14:02.423146 UserAccess: session-id:1 state:start Sep 11 00:14:02.423252 authd_auth_module_start: session-id:1 result = 2 start_auth; state = 0 Sep 11 00:14:02.423294 REQUEST: AUTHEN - module_index 0 module(none) return: SUCCESS Sep 11 00:14:02.426123 Finding a client snapshot session-id:1 Sep 11 00:14:02.426439 authd_access_profile_get: Bad profile name . Sep 11 00:14:02.429906 Decoding incoming attributes Sep 11 00:14:02.429989 Subscriber attribute 10005, length 4 Sep 11 00:14:02.430022 Subscriber attribute 10169, length 3 Sep 11 00:14:02.431807 Received subscriber login request, subscriber session-id:1 Sep 11 00:14:02.437308 Decoding attribute 10005 length 4 Sep 11 00:14:02.437388 Decoding attribute 10169 length 3 Sep 11 00:14:02.437453 Processing address request in default:default network 192.168.0.1 mac 6C:40:08:B6:4C:38 Sep 11 00:14:02.437899 Processing rule External-Authority Sep 11 00:14:02.438078 ************** START-ExternalAuthority ****************** Sep 11 00:14:02.438264 DUMP of all addressRequest fields for subscriber session-id:1 router default:default Sep 11 00:14:02.438477 client type jdhcpd-client client type 1 mac address 6C:40:08:B6:4C:38 Sep 11 00:14:02.438538 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 11 00:14:02.438584 V4NA: req: yes pool: NULL address: null Sep 11 00:14:02.438621 V6NA: req: no pool: NULL address: null Sep 11 00:14:02.438808 V6PD: req: no pool: NULL prefix: null/0 Sep 11 00:14:02.438863 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 11 00:14:02.438894 ********************************************************* Sep 11 00:14:02.438960 *************** END-ExternalAuthority ******************* Sep 11 00:14:02.439006 DUMP of all addressRequest fields for subscriber session-id:1 router default:default Sep 11 00:14:02.439049 client type jdhcpd-client client type 1 mac address 6C:40:08:B6:4C:38 Sep 11 00:14:02.439091 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 11 00:14:02.439167 V4NA: req: yes pool: NULL address: null Sep 11 00:14:02.439207 V6NA: req: no pool: NULL address: null Sep 11 00:14:02.439246 V6PD: req: no pool: NULL prefix: null/0 Sep 11 00:14:02.439287 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 11 00:14:02.439318 ********************************************************* Sep 11 00:14:02.439348 Processing rule Network-Match Sep 11 00:14:02.439374 ***************** START-NetworkMatch ******************** Sep 11 00:14:02.439405 DUMP of all addressRequest fields for subscriber session-id:1 router default:default Sep 11 00:14:02.439446 client type jdhcpd-client client type 1 mac address 6C:40:08:B6:4C:38 Sep 11 00:14:02.439487 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 11 00:14:02.439528 V4NA: req: yes pool: NULL address: null Sep 11 00:14:02.439563 V6NA: req: no pool: NULL address: null Sep 11 00:14:02.439601 V6PD: req: no pool: NULL prefix: null/0 Sep 11 00:14:02.439639 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 11 00:14:02.440351 ********************************************************* Sep 11 00:14:02.440624 NetworkMatch: No match for network '192.168.0.1' or hint 'null' Sep 11 00:14:02.440673 ****************** END-NetworkMatch ********************* Sep 11 00:14:02.440709 DUMP of all addressRequest fields for subscriber session-id:1 router default:default Sep 11 00:14:02.440761 client type jdhcpd-client client type 1 mac address 6C:40:08:B6:4C:38 Sep 11 00:14:02.440809 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 11 00:14:02.440859 V4NA: req: yes pool: NULL address: null Sep 11 00:14:02.440899 V6NA: req: no pool: NULL address: null Sep 11 00:14:02.440942 V6PD: req: no pool: NULL prefix: null/0 Sep 11 00:14:02.440981 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 11 00:14:02.441011 ********************************************************* Sep 11 00:14:02.441082 Result have been returned with opcode=0, result=12 Sep 11 00:14:02.441121 ************* Results of Address Allocation ************* Sep 11 00:14:02.441154 DUMP of all addressRequest fields for subscriber session-id:1 router default:default Sep 11 00:14:02.441198 client type jdhcpd-client client type 1 mac address 6C:40:08:B6:4C:38 Sep 11 00:14:02.441239 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 11 00:14:02.441285 V4NA: req: yes pool: NULL address: null Sep 11 00:14:02.441321 V6NA: req: no pool: NULL address: null Sep 11 00:14:02.441360 V6PD: req: no pool: NULL prefix: null/0 Sep 11 00:14:02.441397 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 11 00:14:02.441427 ********************************************************* Sep 11 00:14:02.441471 Framework: auth result is 15. Performing post-auth operations Sep 11 00:14:02.441501 Framework: result is 15. Sep 11 00:14:02.441534 authd_auth_send_answer: conn=28b3000, reply-code=14 (ADDRALLOC FAIL), result-subopcode=15 (INTERNAL_ERROR), session-id:1, cookie=65544, rply_len=28, num_tlv_blocks=0 Sep 11 00:14:02.441589 Delete session-id:1 Sep 11 00:14:02.441624 Begin to logout Subscriber session-id:1 Sep 11 00:14:02.441661 UserAccess: session-id:1 state:log-out Sep 11 00:14:02.441777 Removing client snapshot session-id:1 Sep 11 00:14:02.443604 findSession: AST-Table couldn't find the session-id:1