mchesnutt@AU-FW-01# run show log AUTH Sep 9 18:03:37.674793 authd_config_read: old seq 86 and new one 87 Sep 9 18:03:37.691338 Termintate-code: no configuration Sep 9 18:03:37.691656 host-name changed in system config Sep 9 18:03:37.699644 Extensible Services mode turned OFF Sep 9 18:03:37.707953 accounting-backup-options: no configuration Sep 9 18:03:37.708040 AaaService::configRead Sep 9 18:03:37.708068 AaaService::configReadAccess Sep 9 18:03:37.708201 lookForTheMissing callback: default:default Sep 9 18:03:37.708341 Config changed for a AaaService Sep 9 18:03:37.708384 Config changed for routing context default:default Sep 9 18:03:37.708556 Duplicate Address Protection disabled for routing context default:default Sep 9 18:03:37.715460 Config changed for pool junosDHCPPool1 Sep 9 18:03:37.715783 Updating pool junosDHCPPool1, network 192.168.1.0/24 Sep 9 18:03:37.715851 xauthAttrsSet: start Sep 9 18:03:37.715888 xauthAttrsSet: xauth does not be configed Sep 9 18:03:37.721780 Config changed for range junosRange Sep 9 18:03:37.721906 Deleting all hosts in pool junosDHCPPool1 Sep 9 18:03:37.721970 Config changed for pool junosDHCPPool2 Sep 9 18:03:37.728256 Updating pool junosDHCPPool2, network 192.168.2.0/24 Sep 9 18:03:37.728325 xauthAttrsSet: start Sep 9 18:03:37.728361 xauthAttrsSet: xauth does not be configed Sep 9 18:03:37.728436 Config changed for range junosRange Sep 9 18:03:37.728512 Deleting all hosts in pool junosDHCPPool2 Sep 9 18:03:37.728578 Config changed for pool dyn-vpn-address-pool Sep 9 18:03:37.728650 Updating pool dyn-vpn-address-pool, network 192.168.199.0/24 Sep 9 18:03:37.728698 xauthAttrsSet: start Sep 9 18:03:37.728755 xauthAttrsSet: dns primary ip-address Sep 9 18:03:37.728810 xauthAttrsSet: dns secondary ip-address Sep 9 18:03:37.728871 Remove range __default low 192.168.199.1 in pool dyn-vpn-address-pool Sep 9 18:03:37.728942 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 9 18:03:37.729019 Deleting all hosts in pool dyn-vpn-address-pool Sep 9 18:03:37.734844 Domain-map config changed. Routing context:default:default Sep 9 18:03:37.734939 Domain-map config deleted. Routing context:default:default Sep 9 18:03:37.735090 configReadTunnelSwitchProfiles: no tunnel-switch profiles configured Sep 9 18:03:37.742135 AaaService::configReadAaaAttachment Sep 9 18:03:37.748594 delVrfTable: deleting vrf table Sep 9 18:03:37.751035 addVrfEntry: Added VRF to table default; 0 Sep 9 18:03:37.751119 Config deleted for AAA routing context default:default Sep 9 18:03:37.756730 Config deleted for AAA routing context default:default Sep 9 18:03:37.756943 Config deleted for AAA routing context default:default Sep 9 18:03:37.762440 Clearing rule list Sep 9 18:03:37.762550 Clearing rule list Sep 9 18:03:37.762594 Adding rule External-Authority for client jdhcpd-client Sep 9 18:03:37.762628 Adding rule Network-Match for client jdhcpd-client Sep 9 18:03:37.762660 Adding rule External-Authority for client jdhcpd-test-client Sep 9 18:03:37.762691 Adding rule Network-Match for client jdhcpd-test-client Sep 9 18:03:37.767686 authd_access_server_read: Reading Configuration for access Sep 9 18:03:37.767761 authd_access_server_free: Deleting Configuration dd1ca4 Sep 9 18:03:37.767811 authd_access_profile_pending_acct_data_cache:Access profile unint exit: PendAPTable empty = 1 Sep 9 18:03:37.767966 authd_access_profile_pool_change: succeed to find out profile dyn-vpn-access-profile Sep 9 18:03:37.768022 address-assignment pool value dyn-vpn-address-pool, profile pool name dyn-vpn-address-pool. Sep 9 18:03:37.774417 authd_access_profile_pool_change: pool(dyn-vpn-address-pool) under profile is no change Sep 9 18:03:37.778809 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 9 18:03:37.778911 Deleting RADIUS request queue for profile: dyn-vpn-access-profile Sep 9 18:03:37.778944 disable RADIUS request queue disabled for profile: dyn-vpn-access-profile Sep 9 18:03:37.779060 authd_access_server_free: Deleting Configuration 29214d4 Sep 9 18:03:37.779157 got authentication order value 1 Sep 9 18:03:37.779198 authorization order called Sep 9 18:03:37.779224 provisioning order called Sep 9 18:03:37.779256 read accounting configurations Sep 9 18:03:37.779318 Acc-order is NOT configured Sep 9 18:03:37.779378 Accounting option: accounting-stop-on-failure NOT configured Sep 9 18:03:37.779430 Accounting option: accounting-stop-on-deny NOT configured Sep 9 18:03:37.779477 Accounting option: immediate-update NOT configured Sep 9 18:03:37.784788 Accounting option: acc_wait_for_acct_on_ack NOT configured Sep 9 18:03:37.784889 Accounting option: send_acct_status_on_config_change NOT configured Sep 9 18:03:37.784953 Accounting option: ancp_speed_change_immediate_update NOT configured Sep 9 18:03:37.784995 Accounting Interval not configured Sep 9 18:03:37.785028 Accounting Interval not configured Sep 9 18:03:37.785073 Accounting option: duplication NOT configured Sep 9 18:03:37.785133 Accounting option: duplication filter is not configured Sep 9 18:03:37.785184 Accounting option: duplication-vrf NOT configured Sep 9 18:03:37.785234 Service acct-order not configured Sep 9 18:03:37.785281 Service acct-stats-type not configured Sep 9 18:03:37.785315 Service acct-interval not configured Sep 9 18:03:37.785367 Accounting coa-no-override not configured Sep 9 18:03:37.785403 address-assignment pool called Sep 9 18:03:37.785448 address-assignment pool value dyn-vpn-address-pool. Sep 9 18:03:37.785477 authd_config_read_radius_attributes radius stanza not cfg under profile:3817a824 Sep 9 18:03:37.785507 authd_access_server_read: Reading Configuration for profile Sep 9 18:03:37.785534 authd_access_server_free: Deleting Configuration 2b1e4d4 Sep 9 18:03:37.789718 authd_access_profile_config_read_params dyn-vpn-access-profile status 1 Sep 9 18:03:37.789823 Creating RADIUS request queue for profile: dyn-vpn-access-profile Sep 9 18:03:37.789914 Dumping Profile dyn-vpn-access-profile Sep 9 18:03:37.789948 Auth order count=1, order = 1 0 Sep 9 18:03:37.789973 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 9 18:03:37.790005 Session Options: groups_len=0, idle_timeout=0, session_timeout=0 Sep 9 18:03:37.790030 Client name filter: domain=[], count=0, separator=@ Sep 9 18:03:37.790068 authd_radius_module_config_init: result=SUCCESS Sep 9 18:03:37.790139 authd_read_profiles_radius_callback: Read radius server under [access profile dyn-vpn-access-profile] Sep 9 18:03:37.790207 Got the profile name:dyn-vpn-access-profile Sep 9 18:03:37.790247 No Radius options configured for the profile: dyn-vpn-access-profile Sep 9 18:03:37.792222 Cleanup ignore list for profile:dyn-vpn-access-profile for all msg-types Sep 9 18:03:37.792366 Cleanup exclude list for profile:dyn-vpn-access-profile for all msg-types Sep 9 18:03:37.792483 Dumping Access radius config ----------- Sep 9 18:03:37.792528 Radius options options-at-default=1 Sep 9 18:03:37.794453 Radius options revert-interval=60 request-rate=500 Sep 9 18:03:37.794496 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 9 18:03:37.794529 Radius options nas-port-id-delimiter="#" nas-port-id-format NID=0 IID=0 ACI=0 ARI=0 Sep 9 18:03:37.794555 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 9 18:03:37.794584 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 9 18:03:37.799447 Radius options Unique-NAS-port=0 Unique-NAS-Port-chassis-id=0 Unique-NAS-Port-chassis-id-width=0 Sep 9 18:03:37.799513 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 9 18:03:37.799547 Radius options NAS-port-extended-format atm slot-width=0 adapter_width=0 port_width=0 vpi_width=0 vci_width=0 Sep 9 18:03:37.799574 Radius options client_auth_algorithm=0 client_acct_algorithm=0 juniper_dsl_attributes=0 Sep 9 18:03:37.799599 Radius options ip_address_change_notify=0 ip_address_change_notify_msg= Sep 9 18:03:37.799624 Radius options timeout_grace=10 Sep 9 18:03:37.799647 Radius options extensible_service_required_at_login=FALSE Sep 9 18:03:37.804444 Radius options dynamic_profile_service_required_at_login=TRUE Sep 9 18:03:37.804488 Radius options no-radius-queues=0 no-max-outstanding=0 Sep 9 18:03:37.804514 Done ----------- Sep 9 18:03:37.804549 Dumping dyn-vpn-access-profile radius servers ----------- Sep 9 18:03:37.804584 Radius options options-at-default=1 Sep 9 18:03:37.804607 Radius options revert-interval=60 request-rate=500 Sep 9 18:03:37.804632 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 9 18:03:37.804663 Radius options nas-port-id-delimiter="#" nas-port-id-format NID=0 IID=0 ACI=0 ARI=0 Sep 9 18:03:37.808824 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 9 18:03:37.808908 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 9 18:03:37.808939 Radius options Unique-NAS-port=0 Unique-NAS-Port-chassis-id=0 Unique-NAS-Port-chassis-id-width=0 Sep 9 18:03:37.808964 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 9 18:03:37.809024 Radius options NAS-port-extended-format atm slot-width=0 adapter_width=0 port_width=0 vpi_width=0 vci_width=0 Sep 9 18:03:37.809052 Radius options client_auth_algorithm=0 client_acct_algorithm=0 juniper_dsl_attributes=0 Sep 9 18:03:37.809078 Radius options ip_address_change_notify=0 ip_address_change_notify_msg= Sep 9 18:03:37.809103 Radius options timeout_grace=10 Sep 9 18:03:37.809126 Radius options extensible_service_required_at_login=FALSE Sep 9 18:03:37.809150 Radius options dynamic_profile_service_required_at_login=TRUE Sep 9 18:03:37.809174 Done ----------- Sep 9 18:03:37.809364 Got the profile name:dyn-vpn-access-profile Sep 9 18:03:37.809417 No Radius options configured for the profile: dyn-vpn-access-profile Sep 9 18:03:37.809446 Cleanup ignore list for profile:dyn-vpn-access-profile for all msg-types Sep 9 18:03:37.809510 Cleanup exclude list for profile:dyn-vpn-access-profile for all msg-types Sep 9 18:03:37.809614 Framework: CONFIG RELOAD - Sep 9 18:03:37.809647 Local : start authd_local_module_config_clean Sep 9 18:03:37.809673 Local : start profiles_tree_destroy Sep 9 18:03:37.809699 Local : start delete_profile_node_data Sep 9 18:03:37.813986 pool(dyn-vpn-address-pool) is found Sep 9 18:03:37.814084 Local : delete_profile - clients tree for profile dyn-vpn-access-profile destroyed Sep 9 18:03:37.814118 Local : profiles_tree_destroy - destroyed Sep 9 18:03:37.814143 Local : profiles tree destroyed successfully Sep 9 18:03:37.814168 Local : start authd_local_module_config_init Sep 9 18:03:37.814194 Local : start authd_config_read_access_profiles_clients Sep 9 18:03:37.814219 Local : DAX_WALK_CONFIGURED Sep 9 18:03:37.814277 Local : start callback walk_profiles_cb Sep 9 18:03:37.814311 Local : walk-flag!= DAX_WALK_DELTA Sep 9 18:03:37.814336 Local : Item Changed Sep 9 18:03:37.814376 Local : profile dyn-vpn-access-profile Sep 9 18:03:37.814416 Local : start callback walk_clients_cb Sep 9 18:03:37.814444 Local : Item Changed Sep 9 18:03:37.814513 Local : client mchesnutt Sep 9 18:03:37.814547 Local : start add_client Sep 9 18:03:37.814571 Local : start add_profile Sep 9 18:03:37.819470 Local : creating/adding a new profile node Sep 9 18:03:37.819503 Local : start clients_tree_init Sep 9 18:03:37.819534 Local : creating/adding new client Sep 9 18:03:37.819562 Local : start update_client_data Sep 9 18:03:37.819762 Local : authd_config_read_xauth_attrs: not configure client xauth Sep 9 18:03:37.822905 Local : update_client_data - succeeded Sep 9 18:03:37.825496 Local : Done Sep 9 18:03:37.825541 Local : ** PROFILE dyn-vpn-access-profile ** Sep 9 18:03:37.825568 Local : client=, groups_len=0 Sep 9 18:03:37.825595 Framework: CONFIG RELOAD - Sep 9 18:03:37.825627 LDAP:CONFIG: result=SUCCESS Sep 9 18:03:37.825703 LDAP:CONFIG: Read ldap server under [access profile dyn-vpn-access-profile] Sep 9 18:03:37.825741 Dumping Access ldap config ----------- Sep 9 18:03:37.825777 Ldap options revert-interval=600, base-dn=, user-dn-search=assemble Sep 9 18:03:37.825803 Ldap assemble options cn=cn Sep 9 18:03:37.829292 Done ----------- Sep 9 18:03:37.829390 Dumping dyn-vpn-access-profile ldap servers ----------- Sep 9 18:03:37.829427 Ldap options revert-interval=600, base-dn=, user-dn-search=assemble Sep 9 18:03:37.829453 Ldap assemble options cn=cn Sep 9 18:03:37.829476 Done ----------- Sep 9 18:03:37.829520 Framework: CONFIG RELOAD - Sep 9 18:03:37.829561 SECURID:CONFIG: securid not configured Sep 9 18:03:37.829587 SECURID:CONFIG: securid configuration read SUCCEEDED Sep 9 18:03:37.845007 Dumping Access securid config ----------- Sep 9 18:03:37.845102 Securid server = UNCONFIGURED, file = UNCONFIGURED Sep 9 18:03:37.845129 Done ----------- Sep 9 18:03:37.845163 SECURID:CONFIG: sdconf.rec file location not configured. Sep 9 18:03:37.845188 Framework: CONFIG RELOAD - Sep 9 18:03:37.845214 Framework: CONFIG RELOAD - Sep 9 18:03:37.845243 authd_apply_acctg_config Sep 9 18:03:37.845277 authd_access_profile_apply_dynreq_config Build dynreq server list for profile:(dyn-vpn-access-profile) Sep 9 18:03:37.847383 authd_radius_dynreq_server_create error - no radius servers configured for profile dyn-vpn-access-profile Sep 9 18:03:37.847593 Creation of DM Server failed Sep 9 18:03:37.847707 authd_cfg_interfaces_cb: Interface not interested Sep 9 18:03:37.851910 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/0] Sep 9 18:03:37.855819 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/1] Sep 9 18:03:37.870147 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/2] Sep 9 18:03:37.870441 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/3] Sep 9 18:03:37.870617 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/4] Sep 9 18:03:37.870784 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/5] Sep 9 18:03:37.870947 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/6] Sep 9 18:03:37.875217 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/7] Sep 9 18:03:37.875497 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/8] Sep 9 18:03:37.875668 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/9] Sep 9 18:03:37.875833 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/10] Sep 9 18:03:37.875993 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/11] Sep 9 18:03:37.880246 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/12] Sep 9 18:03:37.880535 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/13] Sep 9 18:03:37.880705 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/14] Sep 9 18:03:37.880868 authd_cfg_interfaces_cb: DAX_ITEM_CHANGED [interface] ifd[ge-0/0/15] Sep 9 18:03:37.885599 authd_cfg_interfaces_cb: Interface fxp0 not interested Sep 9 18:03:37.885729 authd_cfg_interfaces_cb: Interface irb not interested Sep 9 18:03:37.885774 authd_config_read_interface: Radius-Options dax_query (interface) ret 0 Sep 9 18:03:37.897474 === Configuration reload succeeded === Sep 9 18:04:01.748331 Process/Dispatch Client Message Sep 9 18:04:01.748423 New Process/Dispatch Client Message Sep 9 18:04:01.748469 authd_tlv_build_list_from_struct username l =1 offset =56 Sep 9 18:04:01.748499 authd_tlv_build_list_from_struct profile l =1 offset =57 Sep 9 18:04:01.748527 authd_tlv_build_list_from_struct password l =1 offset =58 Sep 9 18:04:01.748561 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Sep 9 18:04:01.751031 authd_auth_aaa_msg_create profile:() Sep 9 18:04:01.751109 Process Request Sep 9 18:04:01.751147 Client request received on conn-id:jdhcpd-client session-id:7436 Opcode:64, Subcode:0 Sep 9 18:04:01.751195 Taking a client snapshot, session-id:7436 Sep 9 18:04:01.751440 Creating SubscriberASTEntry for session-id:7436, session name: Sep 9 18:04:01.752240 fillSessionDBAttributes: session-id:7436, ifdName: irb Sep 9 18:04:01.752331 No access-profile found in the SDB for session-id:7436 Sep 9 18:04:01.752375 PhyIfdName found in the SDB for session-id:7436 Sep 9 18:04:01.752419 InterfaceName found in the SDB for session-id:7436 Sep 9 18:04:01.752471 Querying the access-profile for user: on LR/RI:default:default Sep 9 18:04:01.752514 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:994 Failed to lookup an access-profile for session-id:7436 with LS:RI key:default:default Sep 9 18:04:01.752553 authd_build_radius_nas_port_and_id: NASPortID = , NASPort = 0, CallingStationID = Sep 9 18:04:01.752636 Finding a client snapshot session-id:7436 Sep 9 18:04:01.752990 Setting multi-acct-session-id to 0 Sep 9 18:04:01.753030 setAccountingInfo: Sep 9 18:04:01.753056 setAccountingInfo: service accounting order Sep 9 18:04:01.753094 updateCoaDynamicVariableValidation coaValidation: 0 Sep 9 18:04:01.753136 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:3742 Did not find dynamic-profile in the SDB for session-id:7436 Sep 9 18:04:01.753222 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:693JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty Sep 9 18:04:01.753264 Bundle session id not found, setting to NULL Sep 9 18:04:01.753293 multi-acct-session-id set to 0 Sep 9 18:04:01.755076 On-demand IP address set to 0 Sep 9 18:04:01.755174 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=() Sep 9 18:04:01.755223 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x181806c aaa msg=0xe495e0 Sep 9 18:04:01.755255 ################################################################### Sep 9 18:04:01.755282 ########################### AUTH REQ RCVD ######################### Sep 9 18:04:01.755306 ################################################################### Sep 9 18:04:01.755330 Auth-FSM: Process Auth-Request for session-id:7436 Sep 9 18:04:01.755359 Framework: Starting authentication Sep 9 18:04:01.755388 authd_access_profile_get: Bad profile name . Sep 9 18:04:01.755416 authd_auth_begin_authentication: invoking none server Sep 9 18:04:01.755440 authd_advance_module_for_aaa_request_msg: result:0 Sep 9 18:04:01.755474 Authd module start session-id:7436 Sep 9 18:04:01.755682 UserAccess: session-id:7436 state:start Sep 9 18:04:01.755752 authd_auth_module_start: session-id:7436 result = 2 start_auth; state = 0 Sep 9 18:04:01.756609 REQUEST: AUTHEN - module_index 0 module(none) return: SUCCESS Sep 9 18:04:01.756715 Finding a client snapshot session-id:7436 Sep 9 18:04:01.756947 Decoding incoming attributes Sep 9 18:04:01.756990 Subscriber attribute 10005, length 4 Sep 9 18:04:01.757021 Subscriber attribute 10169, length 3 Sep 9 18:04:01.757049 Subscriber attribute 39, length 47360 Sep 9 18:04:01.757083 Received subscriber login request, subscriber session-id:7436 Sep 9 18:04:01.757147 Decoding attribute 39 length 47360 Sep 9 18:04:01.757180 Decoding attribute 10005 length 4 Sep 9 18:04:01.757209 Decoding attribute 10169 length 3 Sep 9 18:04:01.757296 Processing address request in default:default network 192.168.0.1 mac 54:33:CB:48:70:8F Sep 9 18:04:01.757351 Processing rule External-Authority Sep 9 18:04:01.757379 ************** START-ExternalAuthority ****************** Sep 9 18:04:01.757409 DUMP of all addressRequest fields for subscriber session-id:7436 router default:default Sep 9 18:04:01.757452 client type jdhcpd-client client type 1 mac address 54:33:CB:48:70:8F Sep 9 18:04:01.757496 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:04:01.757539 V4NA: req: yes pool: NULL address: null Sep 9 18:04:01.757575 V6NA: req: no pool: NULL address: null Sep 9 18:04:01.757618 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:04:01.757655 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:04:01.757684 ********************************************************* Sep 9 18:04:01.757719 *************** END-ExternalAuthority ******************* Sep 9 18:04:01.757751 DUMP of all addressRequest fields for subscriber session-id:7436 router default:default Sep 9 18:04:01.757791 client type jdhcpd-client client type 1 mac address 54:33:CB:48:70:8F Sep 9 18:04:01.757831 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:04:01.757870 V4NA: req: yes pool: NULL address: null Sep 9 18:04:01.757903 V6NA: req: no pool: NULL address: null Sep 9 18:04:01.757941 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:04:01.757976 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:04:01.758004 ********************************************************* Sep 9 18:04:01.758033 Processing rule Network-Match Sep 9 18:04:01.758058 ***************** START-NetworkMatch ******************** Sep 9 18:04:01.758087 DUMP of all addressRequest fields for subscriber session-id:7436 router default:default Sep 9 18:04:01.758214 client type jdhcpd-client client type 1 mac address 54:33:CB:48:70:8F Sep 9 18:04:01.758279 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:04:01.758325 V4NA: req: yes pool: NULL address: null Sep 9 18:04:01.758360 V6NA: req: no pool: NULL address: null Sep 9 18:04:01.758398 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:04:01.758435 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:04:01.758463 ********************************************************* Sep 9 18:04:01.758509 NetworkMatch: No match for network '192.168.0.1' or hint 'null' Sep 9 18:04:01.758541 ****************** END-NetworkMatch ********************* Sep 9 18:04:01.758571 DUMP of all addressRequest fields for subscriber session-id:7436 router default:default Sep 9 18:04:01.758614 client type jdhcpd-client client type 1 mac address 54:33:CB:48:70:8F Sep 9 18:04:01.758656 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:04:01.759342 V4NA: req: yes pool: NULL address: null Sep 9 18:04:01.759384 V6NA: req: no pool: NULL address: null Sep 9 18:04:01.759426 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:04:01.759462 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:04:01.759491 ********************************************************* Sep 9 18:04:01.759528 Result have been returned with opcode=0, result=12 Sep 9 18:04:01.759560 ************* Results of Address Allocation ************* Sep 9 18:04:01.759593 DUMP of all addressRequest fields for subscriber session-id:7436 router default:default Sep 9 18:04:01.759641 client type jdhcpd-client client type 1 mac address 54:33:CB:48:70:8F Sep 9 18:04:01.759683 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:04:01.759724 V4NA: req: yes pool: NULL address: null Sep 9 18:04:01.759759 V6NA: req: no pool: NULL address: null Sep 9 18:04:01.759796 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:04:01.759870 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:04:01.759905 ********************************************************* Sep 9 18:04:01.759948 Framework: auth result is 15. Performing post-auth operations Sep 9 18:04:01.759976 Framework: result is 15. Sep 9 18:04:01.760008 authd_auth_send_answer: conn=289d000, reply-code=14 (ADDRALLOC FAIL), result-subopcode=15 (INTERNAL_ERROR), session-id:7436, cookie=96381, rply_len=28, num_tlv_blocks=0 Sep 9 18:04:01.760045 authd_auth_aaa_msg_destroy Sep 9 18:04:01.760195 authd_auth_aaa_msg_destructauth_aaa_msg: 0xe4906c Sep 9 18:04:01.760270 Delete session-id:7436 Sep 9 18:04:01.760307 Begin to logout Subscriber session-id:7436 Sep 9 18:04:01.760344 UserAccess: session-id:7436 state:log-out Sep 9 18:04:01.760447 Removing client snapshot session-id:7436 Sep 9 18:04:01.760509 findSession: AST-Table couldn't find the session-id:7436 Sep 9 18:05:28.324777 Process/Dispatch Client Message Sep 9 18:05:28.324870 New Process/Dispatch Client Message Sep 9 18:05:28.324917 authd_tlv_build_list_from_struct username l =1 offset =56 Sep 9 18:05:28.324949 authd_tlv_build_list_from_struct profile l =1 offset =57 Sep 9 18:05:28.324978 authd_tlv_build_list_from_struct password l =1 offset =58 Sep 9 18:05:28.325008 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0 Sep 9 18:05:28.325037 authd_auth_aaa_msg_create profile:() Sep 9 18:05:28.325071 Process Request Sep 9 18:05:28.325104 Client request received on conn-id:jdhcpd-client session-id:7437 Opcode:64, Subcode:0 Sep 9 18:05:28.325150 Taking a client snapshot, session-id:7437 Sep 9 18:05:28.325391 Creating SubscriberASTEntry for session-id:7437, session name: Sep 9 18:05:28.325941 fillSessionDBAttributes: session-id:7437, ifdName: irb Sep 9 18:05:28.326023 No access-profile found in the SDB for session-id:7437 Sep 9 18:05:28.326076 PhyIfdName found in the SDB for session-id:7437 Sep 9 18:05:28.326131 InterfaceName found in the SDB for session-id:7437 Sep 9 18:05:28.326189 Querying the access-profile for user: on LR/RI:default:default Sep 9 18:05:28.326275 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:994 Failed to lookup an access-profile for session-id:7437 with LS:RI key:default:default Sep 9 18:05:28.326322 authd_build_radius_nas_port_and_id: NASPortID = , NASPort = 0, CallingStationID = Sep 9 18:05:28.326400 Finding a client snapshot session-id:7437 Sep 9 18:05:28.326631 Setting multi-acct-session-id to 0 Sep 9 18:05:28.327336 setAccountingInfo: Sep 9 18:05:28.327366 setAccountingInfo: service accounting order Sep 9 18:05:28.327400 updateCoaDynamicVariableValidation coaValidation: 0 Sep 9 18:05:28.327449 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:3742 Did not find dynamic-profile in the SDB for session-id:7437 Sep 9 18:05:28.327499 ../../../../../../src/junos/usr.sbin/authd/aaa-service/authd_aaa_subscriber_entry.cc:693JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty Sep 9 18:05:28.327537 Bundle session id not found, setting to NULL Sep 9 18:05:28.327705 multi-acct-session-id set to 0 Sep 9 18:05:28.327763 On-demand IP address set to 0 Sep 9 18:05:28.327821 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=() Sep 9 18:05:28.327873 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x181806c aaa msg=0xe4906c Sep 9 18:05:28.327908 ################################################################### Sep 9 18:05:28.327935 ########################### AUTH REQ RCVD ######################### Sep 9 18:05:28.327959 ################################################################### Sep 9 18:05:28.327984 Auth-FSM: Process Auth-Request for session-id:7437 Sep 9 18:05:28.328014 Framework: Starting authentication Sep 9 18:05:28.328043 authd_access_profile_get: Bad profile name . Sep 9 18:05:28.328072 authd_auth_begin_authentication: invoking none server Sep 9 18:05:28.328102 authd_advance_module_for_aaa_request_msg: result:0 Sep 9 18:05:28.328176 Authd module start session-id:7437 Sep 9 18:05:28.328219 UserAccess: session-id:7437 state:start Sep 9 18:05:28.328263 authd_auth_module_start: session-id:7437 result = 2 start_auth; state = 0 Sep 9 18:05:28.328299 REQUEST: AUTHEN - module_index 0 module(none) return: SUCCESS Sep 9 18:05:28.328372 Finding a client snapshot session-id:7437 Sep 9 18:05:28.328611 Decoding incoming attributes Sep 9 18:05:28.328658 Subscriber attribute 10005, length 4 Sep 9 18:05:28.328689 Subscriber attribute 10169, length 3 Sep 9 18:05:28.328718 Subscriber attribute 39, length 47360 Sep 9 18:05:28.328753 Received subscriber login request, subscriber session-id:7437 Sep 9 18:05:28.328802 Decoding attribute 39 length 47360 Sep 9 18:05:28.328834 Decoding attribute 10005 length 4 Sep 9 18:05:28.328863 Decoding attribute 10169 length 3 Sep 9 18:05:28.328913 Processing address request in default:default network 192.168.0.1 mac EC:AD:B8:27:6E:F1 Sep 9 18:05:28.328961 Processing rule External-Authority Sep 9 18:05:28.328990 ************** START-ExternalAuthority ****************** Sep 9 18:05:28.329020 DUMP of all addressRequest fields for subscriber session-id:7437 router default:default Sep 9 18:05:28.329062 client type jdhcpd-client client type 1 mac address EC:AD:B8:27:6E:F1 Sep 9 18:05:28.329108 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:05:28.329151 V4NA: req: yes pool: NULL address: null Sep 9 18:05:28.329186 V6NA: req: no pool: NULL address: null Sep 9 18:05:28.329226 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:05:28.329262 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:05:28.329291 ********************************************************* Sep 9 18:05:28.329328 *************** END-ExternalAuthority ******************* Sep 9 18:05:28.329360 DUMP of all addressRequest fields for subscriber session-id:7437 router default:default Sep 9 18:05:28.329399 client type jdhcpd-client client type 1 mac address EC:AD:B8:27:6E:F1 Sep 9 18:05:28.330230 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:05:28.330292 V4NA: req: yes pool: NULL address: null Sep 9 18:05:28.330328 V6NA: req: no pool: NULL address: null Sep 9 18:05:28.330370 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:05:28.330406 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:05:28.330435 ********************************************************* Sep 9 18:05:28.330465 Processing rule Network-Match Sep 9 18:05:28.330492 ***************** START-NetworkMatch ******************** Sep 9 18:05:28.330525 DUMP of all addressRequest fields for subscriber session-id:7437 router default:default Sep 9 18:05:28.330567 client type jdhcpd-client client type 1 mac address EC:AD:B8:27:6E:F1 Sep 9 18:05:28.330621 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:05:28.330666 V4NA: req: yes pool: NULL address: null Sep 9 18:05:28.330700 V6NA: req: no pool: NULL address: null Sep 9 18:05:28.330737 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:05:28.330774 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:05:28.330802 ********************************************************* Sep 9 18:05:28.330852 NetworkMatch: No match for network '192.168.0.1' or hint 'null' Sep 9 18:05:28.330883 ****************** END-NetworkMatch ********************* Sep 9 18:05:28.330914 DUMP of all addressRequest fields for subscriber session-id:7437 router default:default Sep 9 18:05:28.330953 client type jdhcpd-client client type 1 mac address EC:AD:B8:27:6E:F1 Sep 9 18:05:28.330992 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:05:28.331032 V4NA: req: yes pool: NULL address: null Sep 9 18:05:28.331066 V6NA: req: no pool: NULL address: null Sep 9 18:05:28.331107 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:05:28.331359 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:05:28.331397 ********************************************************* Sep 9 18:05:28.331433 Result have been returned with opcode=0, result=12 Sep 9 18:05:28.331462 ************* Results of Address Allocation ************* Sep 9 18:05:28.331492 DUMP of all addressRequest fields for subscriber session-id:7437 router default:default Sep 9 18:05:28.331531 client type jdhcpd-client client type 1 mac address EC:AD:B8:27:6E:F1 Sep 9 18:05:28.331572 REQUESTING: OldStyle 0 OldStyleFilled 0 hint null network 192.168.0.1 client pool name Sep 9 18:05:28.332278 V4NA: req: yes pool: NULL address: null Sep 9 18:05:28.332356 V6NA: req: no pool: NULL address: null Sep 9 18:05:28.332397 V6PD: req: no pool: NULL prefix: null/0 Sep 9 18:05:28.332432 V6NDRA: req: no pool: NULL ndra prefix: null/0 Sep 9 18:05:28.332460 ********************************************************* Sep 9 18:05:28.332504 Framework: auth result is 15. Performing post-auth operations Sep 9 18:05:28.332535 Framework: result is 15. Sep 9 18:05:28.332567 authd_auth_send_answer: conn=289d000, reply-code=14 (ADDRALLOC FAIL), result-subopcode=15 (INTERNAL_ERROR), session-id:7437, cookie=96384, rply_len=28, num_tlv_blocks=0 Sep 9 18:05:28.332604 authd_auth_aaa_msg_destroy Sep 9 18:05:28.332751 authd_auth_aaa_msg_destructauth_aaa_msg: 0xe495e0 Sep 9 18:05:28.332820 Delete session-id:7437 Sep 9 18:05:28.332862 Begin to logout Subscriber session-id:7437 Sep 9 18:05:28.332898 UserAccess: session-id:7437 state:log-out Sep 9 18:05:28.333001 Removing client snapshot session-id:7437 Sep 9 18:05:28.333063 findSession: AST-Table couldn't find the session-id:7437