Feb 16 13:14:33.886655 jdhcpd_jauthd_resp_cb: session-id:5 req-id:65539 logout success none Feb 16 13:14:33.886668 jdhcpd_user_logout_rply_proc: Got reply for user_logout, reply rqst_id = 65539 (session Id 5) Feb 16 13:14:33.886673 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Get SDB STATE for session Id 5 Feb 16 13:14:33.886681 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Got SDB SESSION STATE 3 for client session Id 5 Feb 16 13:14:33.886685 jdhcpd_user_logout_rply_proc: Got authd reply for user_logout in SDB state TERMINATING, for client 19.205.49.2, client session Id 5 Feb 16 13:14:33.886689 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 5 in state 4 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:33.886692 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:33.886697 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:33.886701 In state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: move onto the next state to delete a profile if there is one and set state to TERMINATED Feb 16 13:14:33.886705 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE --> LOCAL_SERVER_STATE_WAIT_CM_DELETE Feb 16 13:14:33.886709 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_CLIENT_MIRROR_ACK in state LOCAL_SERVER_STATE_WAIT_CM_DELETE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:33.886714 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_CM_DELETE --> LOCAL_SERVER_STATE_WAIT_PROF_DELETE Feb 16 13:14:33.886735 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_profile_request: Delete Profile dhcp-local-server-profile request for client session 5 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, flow = True Feb 16 13:14:33.990529 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] proflib_cb_handler: Profile ACK (SUCCESS) - res 0 Feb 16 13:14:33.990537 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] proflib_cb_handler: Config bits from profile:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , copied:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , interface name: Feb 16 13:14:33.990543 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:33.990549 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_local_server_state_wait_prof_delete: In client state LOCAL_SERVER_STATE_WAIT_PROF_DELETE: updating SDB with client session state SDB_SESSION_STATE_TERMINATED Feb 16 13:14:33.990554 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_session_db_client_session_state_set: setting session state 4 Feb 16 13:14:33.990620 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 5 Feb 16 13:14:33.990623 In state LOCAL_SERVER_STATE_WAIT_PROF_DELETE got CLIENT_EVENT_PROF_ACK, proceed with the user-terminated handshake Feb 16 13:14:33.990627 jdhcpd_auth_release_terminated: auth terminate initiated for session 5: flags1:0x20; flags2:0x86080 Feb 16 13:14:33.990630 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:33.990632 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:33.990635 Added client w/ session_id 5 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, to authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:33.990638 jdhcpd_auth_release_terminated_common: auth terminate request for session 5: flags1:0x20; flags2:0x86080 Feb 16 13:14:33.990645 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_PROF_DELETE --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED Feb 16 13:14:34.087661 jdhcpd_jauthd_resp_cb: session-id:5 req-id:65539 terminate success none Feb 16 13:14:34.087675 jdhcpd_user_terminated_rply_proc: Got user-session terminated REPLY from authd- reqId 65539, for client session Id 5 Feb 16 13:14:34.087687 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 5 in state 5 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:34.087690 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:34.087695 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_TERMINATED_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:34.087700 [MSTR][INFO] jdhcpd_request_delete_baseline_stats: ATTEMPT TO DELETE libstats; session_id = 5 Feb 16 13:14:34.087706 [MSTR][ERROR] jdhcpd_request_delete_baseline_stats: libstats delete: failed; error 3, session_id = 5 Feb 16 13:14:34.087711 [MSTR][WARN] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_session_db_client_delete: Failure (status 2) when deleting baseline stats for sessopm (client index 65539) Feb 16 13:14:34.087715 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_session_db_client_delete: Logging entry delete to file Feb 16 13:14:34.087719 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] jdhcpd_persistent_remove_entry_from_file: Entry remove not logged as it is not presistent Feb 16 13:14:34.087815 [MSTR][DEBUG] jdhcpd_session_db_entry_remove_common: Non-bundled SDB entry successfully deleted for session id 5: status = success (0) Feb 16 13:14:34.087823 [MSTR][WARN] jdhcpd_offer_delay_client_fsm_retry_queue_process: offer-delay: retry operation is aleady in progress/ no entries to process Feb 16 13:14:34.087828 [MSTR][WARN] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=5] safd_num_clients_bound_dec: NOK:decrementing safd(0xa77d780) bound clients counter for client (0xa0fb800) Feb 16 13:14:34.087836 [MSTR][INFO] jdhcpd_client_unset_pkt: *********** Unsetting v4 packet 0xa097390 Feb 16 13:14:39.779741 [MSTR][INFO] jdhcpd_smd_process_v4_pkt: **** 420 byte packet received on IFL index 536870916 **** Feb 16 13:14:39.779760 [MSTR][DEBUG] jdhcpd_packet_new: PACKET - Allocated new v4 packet 0xa097390 Feb 16 13:14:39.779772 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_io_process_ip_packet: LOCAL: recv pkt; sa 0.0.0.0; da 255.255.255.255; src_port 68; dst_port 67; len 300 Feb 16 13:14:39.779784 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP from == 0.0.0.0, port == 68 ]-- Feb 16 13:14:39.779795 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP size == 300, op == 1 ]-- Feb 16 13:14:39.779815 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP flags == 0 ]-- Feb 16 13:14:39.779821 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP htype == 1, hlen == 6 ]-- Feb 16 13:14:39.779827 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP hops == 0, xid == 77fefc7f ]-- Feb 16 13:14:39.779833 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP secs == 12, flags == 0000 ]-- Feb 16 13:14:39.779840 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP ciaddr == 0.0.0.0 ]-- Feb 16 13:14:39.779854 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP yiaddr == 0.0.0.0 ]-- Feb 16 13:14:39.779860 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP siaddr == 0.0.0.0 ]-- Feb 16 13:14:39.779866 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP giaddr == 0.0.0.0 ]-- Feb 16 13:14:39.779877 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP chaddr == 64 70 02 b4 eb 63 00 00 00 00 00 00 00 00 00 00 ]-- Feb 16 13:14:39.779883 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP sname == ]-- Feb 16 13:14:39.779890 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP file == ]-- Feb 16 13:14:39.779897 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 53, len 1, data DHCP-DISCOVER ]-- Feb 16 13:14:39.779906 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 12, len 8, data 43 6c 69 65 6e 74 2d 31 ]-- Feb 16 13:14:39.779918 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 55, len 18, data 01 1c 02 79 0f 06 0c 28 29 2a 1a 77 03 79 f9 21 fc 2a ]-- Feb 16 13:14:39.779925 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 255, len 0 ]-- Feb 16 13:14:39.779937 [MSTR][DEBUG] client_key_compose: Composing key (0xa7a3dc0) for cid_l 0, cid NULL, mac 64 70 02 b4 eb 63, htype 1, subnet 19.205.49.254, ifindx 0, opt82_l 0, opt82 NULL Feb 16 13:14:39.779944 [MSTR][DEBUG] client_key_compose: Successfully composed CK_TYPE_HW_ADDR_ON_SUBNET (2) client key object. Feb 16 13:14:39.779952 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_HW_ADDR_ON_SUBNET (2): subnet 19.205.49.254, MAC htype 1, Addr 64 70 02 b4 eb 63 Feb 16 13:14:39.779959 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_HW_ADDR_ON_SUBNET (2) other fields: subnet 19.205.49.254, ifindex 0, opt82_len 0, - Feb 16 13:14:39.779966 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_find_client_from_client_pdu: BOOTPREQUEST could not find client table ent Feb 16 13:14:39.779973 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_seckey_create: Creating seckey with opt60_opt82 Feb 16 13:14:39.779979 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_seckey_create: No option 60 - no need to create seckey for client Feb 16 13:14:39.779985 [MSTR][NOTE] jdhcpd_packet_handle: RECEIVE DISCOVER: stats_safd 0x0 , safd 0xa77d780 ge-0/0/0.3221225472 Feb 16 13:14:39.779992 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_process_forward_only_or_drop: Returning ... forward-only flags not set (flags=deaddead, rc_flags 8a4080d) for routing context 0 Feb 16 13:14:39.780002 [MSTR][INFO] cedb_entry_new_common: New client (0xa0fb800), family=INET, index=65540 Feb 16 13:14:39.780007 [MSTR][DEBUG] cedb_entry_new_common: DHCPv4 client entry ADDED, app_type 1 routing context default:default Feb 16 13:14:39.780019 [MSTR][DEBUG] jdhcpd_name_2_const: ifl ge-0/0/0.3221225472 fpc 0 pic 0 port 0 chnl 4294967295 chnl_max 4294967295 unit 3221225472 Feb 16 13:14:39.780026 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] cedb_entry_new_common: Newly created client entry is flow-based. Feb 16 13:14:39.780034 [MSTR][DEBUG][default:default][SVR][INET][SID=0] _jdhcpd_stale_timer_add: Added stale-timer for client:0xa0fb800 Feb 16 13:14:39.780041 [MSTR][DEBUG][default:default][SVR][INET][SID=0] jdhcpd_packet_handle: new client table entry created for ifindex 536870916 Feb 16 13:14:39.780049 [MSTR][DEBUG] jdhcpd_name_2_const: ifl ge-0/0/0.3221225472 fpc 0 pic 0 port 0 chnl 4294967295 chnl_max 4294967295 unit 3221225472 Feb 16 13:14:39.780056 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_process_offer_advertise_delay: Returning ... offer delay not set (flags=0, rc_flags 8a4080d) for routing context 0, rc(a0b4e00) Feb 16 13:14:39.780064 [MSTR][DEBUG][default:default][SVR][INET][SID=0] jdhcpd_packet_handle: Set client next-hop mac addr: 64 70 02 b4 eb 63 Feb 16 13:14:39.780071 [MSTR][INFO] [default:default][SVR][INET][SID=0] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_DISCOVER_PDU in state LOCAL_SERVER_STATE_INIT flags 1: 0x0 2: 0x80000 3: 0x0 nm: 0x0 Feb 16 13:14:39.780080 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_profile_get: No snapshot handle to recover SDB profile name Feb 16 13:14:39.780087 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_profile_get: Profile_get using regular profile dhcp-local-server-profile Feb 16 13:14:39.780095 [MSTR][INFO] jdhcpd_client_set_pkt: *********** Setting v4 packet 0xa097390 Feb 16 13:14:39.780111 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_save_incoming_packet_options: Updated client incoming dhcp-options with len 33 dhcp-options 35 01 01 0c 08 43 6c 69 65 6e 74 2d 31 37 12 01 1c 02 79 0f 06 0c 28 29 2a 1a 77 03 79 f9 21 fc 2a Feb 16 13:14:39.780277 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_decline_new_client_session: Incremented global in-flight logins - count is 1, session id 0 Feb 16 13:14:39.780287 [MSTR][DEBUG] jdhcpd_service_get: Service_get NO service name Feb 16 13:14:39.780294 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_access_profile_get: access_profile_get NO access-profile name Feb 16 13:14:39.780301 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: phy device name ge-0/0/0 Feb 16 13:14:39.780309 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting LR name default Feb 16 13:14:39.780315 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting RI name default Feb 16 13:14:39.780323 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: sdb username 6470.02b4.eb63 Feb 16 13:14:39.780329 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting profile name dhcp-local-server-profile Feb 16 13:14:39.780335 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: access profile name NOT configured Feb 16 13:14:39.780342 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting inner vlan_ID 384 Feb 16 13:14:39.780348 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting underlying interface ge-0/0/0.3221225472 Feb 16 13:14:39.780356 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting MAC addr 64:70:02:b4:eb:63 Feb 16 13:14:39.780365 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_session_db_create_v4_session_attributes: Setting IPv4 Addr Key 19.205.49.254 Feb 16 13:14:39.780380 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_session_db_create_v4_session_attributes: dhcp_options len 33, data 35 01 01 0c 08 43 6c 69 65 6e 74 2d 31 37 12 01 1c 02 79 0f 06 0c 28 29 2a 1a 77 03 79 f9 21 fc 2a Feb 16 13:14:39.780399 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_session_db_create_v4_session_attributes: adding dhcp_header to SDB len 44, data 01 01 06 00 77 fe fc 7f 00 0c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64 70 02 b4 eb 63 00 00 00 00 00 00 00 00 00 00 Feb 16 13:14:39.780406 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting physical interface name ge-0/0/0 Feb 16 13:14:39.780412 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting authd phy ifd name ge-0/0/0 Feb 16 13:14:39.780510 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_sdb_create_session: session DB create got INET entry id 6 Feb 16 13:14:39.780517 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_sdb_create_session: Adding shmlog fileter success for session id 6 Feb 16 13:14:39.780524 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_persistent_is_entry_in_file_allowed: client_type=1, client->state=0 Feb 16 13:14:39.780532 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_fill_client_sdb_private_data: Mirroring disabled (ha_graceful_switchover false) :: Feb 16 13:14:39.780540 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_fill_client_sdb_private_data: Allocated memory to store in SDB, total mirrored length 242, client length 242, dual stack peer client length 0, session-id 6 Feb 16 13:14:39.780548 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_write_private_data: Saved NON-DEMUX interface name ge-0/0/0.3221225472 into mirroring ha_info Feb 16 13:14:39.780556 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_write_private_data: ++++Added TLV for WHOLESALE LR name default length 7 Feb 16 13:14:39.780562 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_write_private_data: ++++Added TLV for WHOLESALE RI name default length 7 Feb 16 13:14:39.780568 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_write_private_data: Added TLV for last_packet_time length 4, last_packet_time: 1550322879 Feb 16 13:14:39.780575 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_write_private_data: ++++Added TLV for Incoming dhcp options length 33 Feb 16 13:14:39.780586 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_mirrorsdb_add_client: Successfully saved private data for 0.0.0.0 in SDB, length 242 Feb 16 13:14:39.780592 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_client_correlation_id_update: setting the client correlation_id 1 in state 0. Feb 16 13:14:39.780600 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_INIT --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ Feb 16 13:14:39.780607 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_auth_request: auth-request attempt initiated: flags1:0x20020; flags2:0x84000l flags3:0 Feb 16 13:14:39.780612 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:39.780616 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:39.780620 Added client w/ session_id 6 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ, to authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:39.850815 jdhcpd_jauthd_resp_cb: session-id:6 req-id:65540 login_v4 success none Feb 16 13:14:39.850840 jdhcpd_authenticate_rply_proc: Got reply for auth_request, reply auth_rqst_id = 65540- (session Id 6) Feb 16 13:14:39.850849 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 6 in state 1 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:39.850854 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:39.850859 jdhcpd_authenticate_rply_proc: auth login reply status for session 6: result:1; flags1:0x20020; flags2:0x84080 Feb 16 13:14:39.850884 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: got IP address 19.205.49.2 Feb 16 13:14:39.850891 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: failed to update IP Address in shmlog for 6. Feb 16 13:14:39.850897 [MSTR][DEBUG] jdhcpd_session_db_client_rc_key_create: SDB_LOGICAL_SYSTEM_NAME = default for session-id 6 Feb 16 13:14:39.850902 [MSTR][DEBUG] jdhcpd_session_db_client_rc_key_create: SDB_ROUTING_INSTANCE_NAME = default for session-id 6 Feb 16 13:14:39.850912 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: got pool name vl384, len 5 Feb 16 13:14:39.850919 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: got net mask 255.255.255.0 Feb 16 13:14:39.850930 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10053 Feb 16 13:14:39.850936 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10053 Feb 16 13:14:39.850942 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10053 Feb 16 13:14:39.850948 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10202 Feb 16 13:14:39.850965 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ flags 1: 0x20020 2: 0x84080 3: 0x0 nm: 0x0 Feb 16 13:14:39.850974 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_local_server_auth_request_ack_common: Auth request reply ip=19.205.49.2; pool name=vl384; wait_auth_login_req=1 Feb 16 13:14:39.850982 [MSTR][DEBUG] jdhcpd_pool_find: : cfg a347240, pool_name a347240, jdhcpd_pool_find Feb 16 13:14:39.850987 [MSTR][DEBUG] jdhcpd_pool_find: Pool vl384 found 0xa0f8100 w/ cfg container 0xa0a7000 Feb 16 13:14:39.850994 [MSTR][DEBUG] jdhcpd_pool_find: : cfg a347240, pool_name a347240, jdhcpd_pool_find Feb 16 13:14:39.850999 [MSTR][DEBUG] jdhcpd_pool_find: Pool vl384 found 0xa0f8100 w/ cfg container 0xa0a7000 Feb 16 13:14:39.851007 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_check_lease_validation_violation: No configuration for lease time violation validation Feb 16 13:14:39.851015 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_update_dynamic_variable_demux_ip: Added host address 19.205.49.2/32 to array variable junos-subscriber-demux-ip-address Feb 16 13:14:39.851050 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_profile_request: Add Profile dhcp-local-server-profile request for client session 6 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ, flow = True Feb 16 13:14:39.851058 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ --> LOCAL_SERVER_STATE_WAIT_PROF_INST Feb 16 13:14:39.990619 [MSTR][ERROR][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] proflib_cb_handler: Profile Addition NACK (FAILED) - res 8, Errored daemon "bbe-smgd", msg "Failed to create IFL", retry "FALSE" Feb 16 13:14:39.990639 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] proflib_cb_handler: Config bits from profile:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , copied:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , interface name: Feb 16 13:14:39.990649 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_INST flags 1: 0x20020 2: 0x84080 3: 0x0 nm: 0x0 Feb 16 13:14:39.990655 Got profile instantiate reply 8, updating SDB with client session state 1 Feb 16 13:14:39.990661 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_client_session_state_set: setting session state 1 Feb 16 13:14:39.990669 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_client_session_state_set: setting action bits to 3, config-bits:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 Feb 16 13:14:39.990743 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 6 Feb 16 13:14:39.990748 profile instantiate reply failed err: 8 LOCAL_SERVER_STATE_WAIT_PROF_INST Feb 16 13:14:39.990754 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_local_server_abort_client: In client state LOCAL_SERVER_STATE_WAIT_PROF_INST - client session Id 6 processing event CLIENT_EVENT_PROF_ACK client was aborted - transitioning to state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE Feb 16 13:14:39.990763 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_PROF_INST --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE Feb 16 13:14:39.990770 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_auth_release: auth logout initiated for session 6 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20020; flags2:0x84080 Feb 16 13:14:39.990778 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_auth_release_common: Release authd (request user logout): updating SDB with client session state SDB_SESSION_STATE_TERMINATING Feb 16 13:14:39.990784 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_client_session_state_set: setting session state 3 Feb 16 13:14:39.990846 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 6 Feb 16 13:14:39.990852 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_client_correlation_id_update: setting the client correlation_id 2 in state 4. Feb 16 13:14:39.990858 jdhcpd_auth_release_common: ISSU logout for client session id 6, decrement global in-flight logins (count is 0) Feb 16 13:14:39.990863 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:39.990867 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:39.990871 Added client w/ session_id 6 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE, to authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:39.990878 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_auth_release_common: auth logout requested for session 6 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20; flags2:0x86080 Feb 16 13:14:40.055714 jdhcpd_jauthd_resp_cb: session-id:6 req-id:65540 logout success none Feb 16 13:14:40.055727 jdhcpd_user_logout_rply_proc: Got reply for user_logout, reply rqst_id = 65540 (session Id 6) Feb 16 13:14:40.055734 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Get SDB STATE for session Id 6 Feb 16 13:14:40.055741 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Got SDB SESSION STATE 3 for client session Id 6 Feb 16 13:14:40.055747 jdhcpd_user_logout_rply_proc: Got authd reply for user_logout in SDB state TERMINATING, for client 19.205.49.2, client session Id 6 Feb 16 13:14:40.055753 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 6 in state 4 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:40.055757 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:40.055764 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:40.055770 In state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: move onto the next state to delete a profile if there is one and set state to TERMINATED Feb 16 13:14:40.055776 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE --> LOCAL_SERVER_STATE_WAIT_CM_DELETE Feb 16 13:14:40.055782 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_CLIENT_MIRROR_ACK in state LOCAL_SERVER_STATE_WAIT_CM_DELETE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:40.055790 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_CM_DELETE --> LOCAL_SERVER_STATE_WAIT_PROF_DELETE Feb 16 13:14:40.055815 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_profile_request: Delete Profile dhcp-local-server-profile request for client session 6 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, flow = True Feb 16 13:14:40.190644 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] proflib_cb_handler: Profile ACK (SUCCESS) - res 0 Feb 16 13:14:40.190653 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] proflib_cb_handler: Config bits from profile:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , copied:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , interface name: Feb 16 13:14:40.190661 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:40.190757 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_local_server_state_wait_prof_delete: In client state LOCAL_SERVER_STATE_WAIT_PROF_DELETE: updating SDB with client session state SDB_SESSION_STATE_TERMINATED Feb 16 13:14:40.190765 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_client_session_state_set: setting session state 4 Feb 16 13:14:40.190814 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 6 Feb 16 13:14:40.190818 In state LOCAL_SERVER_STATE_WAIT_PROF_DELETE got CLIENT_EVENT_PROF_ACK, proceed with the user-terminated handshake Feb 16 13:14:40.190823 jdhcpd_auth_release_terminated: auth terminate initiated for session 6: flags1:0x20; flags2:0x86080 Feb 16 13:14:40.190827 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:40.190839 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:40.190841 Added client w/ session_id 6 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, to authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:40.190844 jdhcpd_auth_release_terminated_common: auth terminate request for session 6: flags1:0x20; flags2:0x86080 Feb 16 13:14:40.190851 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_PROF_DELETE --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED Feb 16 13:14:40.259954 jdhcpd_jauthd_resp_cb: session-id:6 req-id:65540 terminate success none Feb 16 13:14:40.259966 jdhcpd_user_terminated_rply_proc: Got user-session terminated REPLY from authd- reqId 65540, for client session Id 6 Feb 16 13:14:40.259971 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 6 in state 5 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:40.259974 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:40.259979 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_TERMINATED_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:40.259984 [MSTR][INFO] jdhcpd_request_delete_baseline_stats: ATTEMPT TO DELETE libstats; session_id = 6 Feb 16 13:14:40.259990 [MSTR][ERROR] jdhcpd_request_delete_baseline_stats: libstats delete: failed; error 3, session_id = 6 Feb 16 13:14:40.259995 [MSTR][WARN] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_client_delete: Failure (status 2) when deleting baseline stats for sessopm (client index 65540) Feb 16 13:14:40.259999 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_session_db_client_delete: Logging entry delete to file Feb 16 13:14:40.260003 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] jdhcpd_persistent_remove_entry_from_file: Entry remove not logged as it is not presistent Feb 16 13:14:40.260126 [MSTR][DEBUG] jdhcpd_session_db_entry_remove_common: Non-bundled SDB entry successfully deleted for session id 6: status = success (0) Feb 16 13:14:40.260139 [MSTR][WARN] jdhcpd_offer_delay_client_fsm_retry_queue_process: offer-delay: retry operation is aleady in progress/ no entries to process Feb 16 13:14:40.260144 [MSTR][WARN] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=6] safd_num_clients_bound_dec: NOK:decrementing safd(0xa77d780) bound clients counter for client (0xa0fb800) Feb 16 13:14:40.260152 [MSTR][INFO] jdhcpd_client_unset_pkt: *********** Unsetting v4 packet 0xa097390 Feb 16 13:14:54.936884 [MSTR][INFO] jdhcpd_smd_process_v4_pkt: **** 420 byte packet received on IFL index 536870916 **** Feb 16 13:14:54.936897 [MSTR][DEBUG] jdhcpd_packet_new: PACKET - Allocated new v4 packet 0xa097390 Feb 16 13:14:54.936907 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_io_process_ip_packet: LOCAL: recv pkt; sa 0.0.0.0; da 255.255.255.255; src_port 68; dst_port 67; len 300 Feb 16 13:14:54.936915 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP from == 0.0.0.0, port == 68 ]-- Feb 16 13:14:54.936919 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP size == 300, op == 1 ]-- Feb 16 13:14:54.936923 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP flags == 0 ]-- Feb 16 13:14:54.936926 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP htype == 1, hlen == 6 ]-- Feb 16 13:14:54.936930 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP hops == 0, xid == 77fefc7f ]-- Feb 16 13:14:54.936933 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP secs == 27, flags == 0000 ]-- Feb 16 13:14:54.936937 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP ciaddr == 0.0.0.0 ]-- Feb 16 13:14:54.936941 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP yiaddr == 0.0.0.0 ]-- Feb 16 13:14:54.936944 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP siaddr == 0.0.0.0 ]-- Feb 16 13:14:54.936948 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP giaddr == 0.0.0.0 ]-- Feb 16 13:14:54.936955 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP chaddr == 64 70 02 b4 eb 63 00 00 00 00 00 00 00 00 00 00 ]-- Feb 16 13:14:54.936958 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP sname == ]-- Feb 16 13:14:54.936962 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ DHCP/BOOTP file == ]-- Feb 16 13:14:54.936966 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 53, len 1, data DHCP-DISCOVER ]-- Feb 16 13:14:54.936971 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 12, len 8, data 43 6c 69 65 6e 74 2d 31 ]-- Feb 16 13:14:54.936977 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 55, len 18, data 01 1c 02 79 0f 06 0c 28 29 2a 1a 77 03 79 f9 21 fc 2a ]-- Feb 16 13:14:54.936981 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472] --[ OPTION code 255, len 0 ]-- Feb 16 13:14:54.936989 [MSTR][DEBUG] client_key_compose: Composing key (0xa7a4040) for cid_l 0, cid NULL, mac 64 70 02 b4 eb 63, htype 1, subnet 19.205.49.254, ifindx 0, opt82_l 0, opt82 NULL Feb 16 13:14:54.936994 [MSTR][DEBUG] client_key_compose: Successfully composed CK_TYPE_HW_ADDR_ON_SUBNET (2) client key object. Feb 16 13:14:54.936998 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_HW_ADDR_ON_SUBNET (2): subnet 19.205.49.254, MAC htype 1, Addr 64 70 02 b4 eb 63 Feb 16 13:14:54.937002 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_HW_ADDR_ON_SUBNET (2) other fields: subnet 19.205.49.254, ifindex 0, opt82_len 0, - Feb 16 13:14:54.937006 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_find_client_from_client_pdu: BOOTPREQUEST could not find client table ent Feb 16 13:14:54.937010 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_seckey_create: Creating seckey with opt60_opt82 Feb 16 13:14:54.937014 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_seckey_create: No option 60 - no need to create seckey for client Feb 16 13:14:54.937018 [MSTR][NOTE] jdhcpd_packet_handle: RECEIVE DISCOVER: stats_safd 0x0 , safd 0xa77d780 ge-0/0/0.3221225472 Feb 16 13:14:54.937022 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_process_forward_only_or_drop: Returning ... forward-only flags not set (flags=deaddead, rc_flags 8a4080d) for routing context 0 Feb 16 13:14:54.937029 [MSTR][INFO] cedb_entry_new_common: New client (0xa0fb800), family=INET, index=65541 Feb 16 13:14:54.937033 [MSTR][DEBUG] cedb_entry_new_common: DHCPv4 client entry ADDED, app_type 1 routing context default:default Feb 16 13:14:54.937049 [MSTR][DEBUG] jdhcpd_name_2_const: ifl ge-0/0/0.3221225472 fpc 0 pic 0 port 0 chnl 4294967295 chnl_max 4294967295 unit 3221225472 Feb 16 13:14:54.937054 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] cedb_entry_new_common: Newly created client entry is flow-based. Feb 16 13:14:54.937059 [MSTR][DEBUG][default:default][SVR][INET][SID=0] _jdhcpd_stale_timer_add: Added stale-timer for client:0xa0fb800 Feb 16 13:14:54.937063 [MSTR][DEBUG][default:default][SVR][INET][SID=0] jdhcpd_packet_handle: new client table entry created for ifindex 536870916 Feb 16 13:14:54.937067 [MSTR][DEBUG] jdhcpd_name_2_const: ifl ge-0/0/0.3221225472 fpc 0 pic 0 port 0 chnl 4294967295 chnl_max 4294967295 unit 3221225472 Feb 16 13:14:54.937072 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472] jdhcpd_process_offer_advertise_delay: Returning ... offer delay not set (flags=0, rc_flags 8a4080d) for routing context 0, rc(a0b4e00) Feb 16 13:14:54.937080 [MSTR][DEBUG][default:default][SVR][INET][SID=0] jdhcpd_packet_handle: Set client next-hop mac addr: 64 70 02 b4 eb 63 Feb 16 13:14:54.937087 [MSTR][INFO] [default:default][SVR][INET][SID=0] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_DISCOVER_PDU in state LOCAL_SERVER_STATE_INIT flags 1: 0x0 2: 0x80000 3: 0x0 nm: 0x0 Feb 16 13:14:54.937096 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_profile_get: No snapshot handle to recover SDB profile name Feb 16 13:14:54.937103 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_profile_get: Profile_get using regular profile dhcp-local-server-profile Feb 16 13:14:54.937109 [MSTR][INFO] jdhcpd_client_set_pkt: *********** Setting v4 packet 0xa097390 Feb 16 13:14:54.937118 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_save_incoming_packet_options: Updated client incoming dhcp-options with len 33 dhcp-options 35 01 01 0c 08 43 6c 69 65 6e 74 2d 31 37 12 01 1c 02 79 0f 06 0c 28 29 2a 1a 77 03 79 f9 21 fc 2a Feb 16 13:14:54.937235 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_decline_new_client_session: Incremented global in-flight logins - count is 1, session id 0 Feb 16 13:14:54.937410 [MSTR][DEBUG] jdhcpd_service_get: Service_get NO service name Feb 16 13:14:54.937416 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_access_profile_get: access_profile_get NO access-profile name Feb 16 13:14:54.937421 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: phy device name ge-0/0/0 Feb 16 13:14:54.937426 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting LR name default Feb 16 13:14:54.937430 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting RI name default Feb 16 13:14:54.937435 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: sdb username 6470.02b4.eb63 Feb 16 13:14:54.937439 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting profile name dhcp-local-server-profile Feb 16 13:14:54.937442 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: access profile name NOT configured Feb 16 13:14:54.937446 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting inner vlan_ID 384 Feb 16 13:14:54.937450 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting underlying interface ge-0/0/0.3221225472 Feb 16 13:14:54.937455 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting MAC addr 64:70:02:b4:eb:63 Feb 16 13:14:54.937460 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_session_db_create_v4_session_attributes: Setting IPv4 Addr Key 19.205.49.254 Feb 16 13:14:54.937469 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_session_db_create_v4_session_attributes: dhcp_options len 33, data 35 01 01 0c 08 43 6c 69 65 6e 74 2d 31 37 12 01 1c 02 79 0f 06 0c 28 29 2a 1a 77 03 79 f9 21 fc 2a Feb 16 13:14:54.937479 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_session_db_create_v4_session_attributes: adding dhcp_header to SDB len 44, data 01 01 06 00 77 fe fc 7f 00 1b 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64 70 02 b4 eb 63 00 00 00 00 00 00 00 00 00 00 Feb 16 13:14:54.937483 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting physical interface name ge-0/0/0 Feb 16 13:14:54.937487 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=0] jdhcpd_sdb_create_session: setting authd phy ifd name ge-0/0/0 Feb 16 13:14:54.937553 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_sdb_create_session: session DB create got INET entry id 7 Feb 16 13:14:54.937557 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_sdb_create_session: Adding shmlog fileter success for session id 7 Feb 16 13:14:54.937561 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_persistent_is_entry_in_file_allowed: client_type=1, client->state=0 Feb 16 13:14:54.937566 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_fill_client_sdb_private_data: Mirroring disabled (ha_graceful_switchover false) :: Feb 16 13:14:54.937570 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_fill_client_sdb_private_data: Allocated memory to store in SDB, total mirrored length 242, client length 242, dual stack peer client length 0, session-id 7 Feb 16 13:14:54.937575 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_write_private_data: Saved NON-DEMUX interface name ge-0/0/0.3221225472 into mirroring ha_info Feb 16 13:14:54.937580 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_write_private_data: ++++Added TLV for WHOLESALE LR name default length 7 Feb 16 13:14:54.937583 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_write_private_data: ++++Added TLV for WHOLESALE RI name default length 7 Feb 16 13:14:54.937587 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_write_private_data: Added TLV for last_packet_time length 4, last_packet_time: 1550322894 Feb 16 13:14:54.937591 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_write_private_data: ++++Added TLV for Incoming dhcp options length 33 Feb 16 13:14:54.937598 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_mirrorsdb_add_client: Successfully saved private data for 0.0.0.0 in SDB, length 242 Feb 16 13:14:54.937602 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_client_correlation_id_update: setting the client correlation_id 1 in state 0. Feb 16 13:14:54.937607 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_INIT --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ Feb 16 13:14:54.937611 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_auth_request: auth-request attempt initiated: flags1:0x20020; flags2:0x84000l flags3:0 Feb 16 13:14:54.937614 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:54.937617 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:54.937619 Added client w/ session_id 7 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ, to authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:55.069292 jdhcpd_jauthd_resp_cb: session-id:7 req-id:65541 login_v4 success none Feb 16 13:14:55.069309 jdhcpd_authenticate_rply_proc: Got reply for auth_request, reply auth_rqst_id = 65541- (session Id 7) Feb 16 13:14:55.069316 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 7 in state 1 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:55.069324 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:55.069327 jdhcpd_authenticate_rply_proc: auth login reply status for session 7: result:1; flags1:0x20020; flags2:0x84080 Feb 16 13:14:55.069340 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: got IP address 19.205.49.2 Feb 16 13:14:55.069345 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: failed to update IP Address in shmlog for 7. Feb 16 13:14:55.069349 [MSTR][DEBUG] jdhcpd_session_db_client_rc_key_create: SDB_LOGICAL_SYSTEM_NAME = default for session-id 7 Feb 16 13:14:55.069352 [MSTR][DEBUG] jdhcpd_session_db_client_rc_key_create: SDB_ROUTING_INSTANCE_NAME = default for session-id 7 Feb 16 13:14:55.069359 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: got pool name vl384, len 5 Feb 16 13:14:55.069363 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: got net mask 255.255.255.0 Feb 16 13:14:55.069370 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10053 Feb 16 13:14:55.069374 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10053 Feb 16 13:14:55.069377 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10053 Feb 16 13:14:55.069381 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10202 Feb 16 13:14:55.069386 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ flags 1: 0x20020 2: 0x84080 3: 0x0 nm: 0x0 Feb 16 13:14:55.069391 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_local_server_auth_request_ack_common: Auth request reply ip=19.205.49.2; pool name=vl384; wait_auth_login_req=1 Feb 16 13:14:55.069396 [MSTR][DEBUG] jdhcpd_pool_find: : cfg a347240, pool_name a347240, jdhcpd_pool_find Feb 16 13:14:55.069400 [MSTR][DEBUG] jdhcpd_pool_find: Pool vl384 found 0xa0f8100 w/ cfg container 0xa0a7000 Feb 16 13:14:55.069405 [MSTR][DEBUG] jdhcpd_pool_find: : cfg a347240, pool_name a347240, jdhcpd_pool_find Feb 16 13:14:55.069408 [MSTR][DEBUG] jdhcpd_pool_find: Pool vl384 found 0xa0f8100 w/ cfg container 0xa0a7000 Feb 16 13:14:55.069412 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_check_lease_validation_violation: No configuration for lease time violation validation Feb 16 13:14:55.069417 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_update_dynamic_variable_demux_ip: Added host address 19.205.49.2/32 to array variable junos-subscriber-demux-ip-address Feb 16 13:14:55.069441 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_profile_request: Add Profile dhcp-local-server-profile request for client session 7 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ, flow = True Feb 16 13:14:55.069446 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ --> LOCAL_SERVER_STATE_WAIT_PROF_INST Feb 16 13:14:55.190700 [MSTR][ERROR][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] proflib_cb_handler: Profile Addition NACK (FAILED) - res 8, Errored daemon "bbe-smgd", msg "Failed to create IFL", retry "FALSE" Feb 16 13:14:55.190717 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] proflib_cb_handler: Config bits from profile:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , copied:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , interface name: Feb 16 13:14:55.190725 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_INST flags 1: 0x20020 2: 0x84080 3: 0x0 nm: 0x0 Feb 16 13:14:55.190729 Got profile instantiate reply 8, updating SDB with client session state 1 Feb 16 13:14:55.190733 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_client_session_state_set: setting session state 1 Feb 16 13:14:55.190738 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_client_session_state_set: setting action bits to 3, config-bits:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 Feb 16 13:14:55.190784 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 7 Feb 16 13:14:55.190786 profile instantiate reply failed err: 8 LOCAL_SERVER_STATE_WAIT_PROF_INST Feb 16 13:14:55.190791 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_local_server_abort_client: In client state LOCAL_SERVER_STATE_WAIT_PROF_INST - client session Id 7 processing event CLIENT_EVENT_PROF_ACK client was aborted - transitioning to state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE Feb 16 13:14:55.190797 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_PROF_INST --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE Feb 16 13:14:55.190801 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_auth_release: auth logout initiated for session 7 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20020; flags2:0x84080 Feb 16 13:14:55.190806 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_auth_release_common: Release authd (request user logout): updating SDB with client session state SDB_SESSION_STATE_TERMINATING Feb 16 13:14:55.190810 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_client_session_state_set: setting session state 3 Feb 16 13:14:55.190848 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 7 Feb 16 13:14:55.190852 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_client_correlation_id_update: setting the client correlation_id 2 in state 4. Feb 16 13:14:55.190856 jdhcpd_auth_release_common: ISSU logout for client session id 7, decrement global in-flight logins (count is 0) Feb 16 13:14:55.190859 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:55.190862 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:55.190864 Added client w/ session_id 7 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE, to authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:55.190868 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_auth_release_common: auth logout requested for session 7 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20; flags2:0x86080 Feb 16 13:14:55.269546 jdhcpd_jauthd_resp_cb: session-id:7 req-id:65541 logout success none Feb 16 13:14:55.269562 jdhcpd_user_logout_rply_proc: Got reply for user_logout, reply rqst_id = 65541 (session Id 7) Feb 16 13:14:55.269567 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Get SDB STATE for session Id 7 Feb 16 13:14:55.269577 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Got SDB SESSION STATE 3 for client session Id 7 Feb 16 13:14:55.269581 jdhcpd_user_logout_rply_proc: Got authd reply for user_logout in SDB state TERMINATING, for client 19.205.49.2, client session Id 7 Feb 16 13:14:55.269585 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 7 in state 4 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:55.269588 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:55.269601 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:55.269605 In state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: move onto the next state to delete a profile if there is one and set state to TERMINATED Feb 16 13:14:55.269609 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE --> LOCAL_SERVER_STATE_WAIT_CM_DELETE Feb 16 13:14:55.269613 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_CLIENT_MIRROR_ACK in state LOCAL_SERVER_STATE_WAIT_CM_DELETE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:55.269618 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_CM_DELETE --> LOCAL_SERVER_STATE_WAIT_PROF_DELETE Feb 16 13:14:55.269653 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_profile_request: Delete Profile dhcp-local-server-profile request for client session 7 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, flow = True Feb 16 13:14:55.390548 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] proflib_cb_handler: Profile ACK (SUCCESS) - res 0 Feb 16 13:14:55.390557 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] proflib_cb_handler: Config bits from profile:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , copied:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0 , interface name: Feb 16 13:14:55.390564 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:55.390571 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_local_server_state_wait_prof_delete: In client state LOCAL_SERVER_STATE_WAIT_PROF_DELETE: updating SDB with client session state SDB_SESSION_STATE_TERMINATED Feb 16 13:14:55.390597 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_client_session_state_set: setting session state 4 Feb 16 13:14:55.390642 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 7 Feb 16 13:14:55.390645 In state LOCAL_SERVER_STATE_WAIT_PROF_DELETE got CLIENT_EVENT_PROF_ACK, proceed with the user-terminated handshake Feb 16 13:14:55.390648 jdhcpd_auth_release_terminated: auth terminate initiated for session 7: flags1:0x20; flags2:0x86080 Feb 16 13:14:55.390651 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:55.390654 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0 Feb 16 13:14:55.390656 Added client w/ session_id 7 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, to authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:55.390659 jdhcpd_auth_release_terminated_common: auth terminate request for session 7: flags1:0x20; flags2:0x86080 Feb 16 13:14:55.390666 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_PROF_DELETE --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED Feb 16 13:14:55.469817 jdhcpd_jauthd_resp_cb: session-id:7 req-id:65541 terminate success none Feb 16 13:14:55.469836 jdhcpd_user_terminated_rply_proc: Got user-session terminated REPLY from authd- reqId 65541, for client session Id 7 Feb 16 13:14:55.469841 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 7 in state 5 from authd_restart_teardown list, count authd_restart_teardown_count 1 Feb 16 13:14:55.469844 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count Feb 16 13:14:55.469850 [MSTR][INFO] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] JDHCPD_CLIENT_EVENT: Client(0xa0fb800) got event CLIENT_EVENT_AUTH_TERMINATED_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED flags 1: 0x20 2: 0x86080 3: 0x0 nm: 0x0 Feb 16 13:14:55.469855 [MSTR][INFO] jdhcpd_request_delete_baseline_stats: ATTEMPT TO DELETE libstats; session_id = 7 Feb 16 13:14:55.469861 [MSTR][ERROR] jdhcpd_request_delete_baseline_stats: libstats delete: failed; error 3, session_id = 7 Feb 16 13:14:55.469866 [MSTR][WARN] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_client_delete: Failure (status 2) when deleting baseline stats for sessopm (client index 65541) Feb 16 13:14:55.469870 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_session_db_client_delete: Logging entry delete to file Feb 16 13:14:55.469874 [MSTR][DEBUG][default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] jdhcpd_persistent_remove_entry_from_file: Entry remove not logged as it is not presistent Feb 16 13:14:55.469975 [MSTR][DEBUG] jdhcpd_session_db_entry_remove_common: Non-bundled SDB entry successfully deleted for session id 7: status = success (0) Feb 16 13:14:55.469983 [MSTR][WARN] jdhcpd_offer_delay_client_fsm_retry_queue_process: offer-delay: retry operation is aleady in progress/ no entries to process Feb 16 13:14:55.469988 [MSTR][WARN] [default:default][SVR][INET][ge-0/0/0.3221225472][SID=7] safd_num_clients_bound_dec: NOK:decrementing safd(0xa77d780) bound clients counter for client (0xa0fb800) Feb 16 13:14:55.469996 [MSTR][INFO] jdhcpd_client_unset_pkt: *********** Unsetting v4 packet 0xa097390