Noticed that the traffic is not passing out filter, also the uid is different for each variable
Original Message:
Sent: 02-28-2024 05:15
From: DUMITRU POPOVICI
Subject: Juniper MX80 BRAS DHCP+Radius
Fixed the issue, now host is getting IP address, however ony UPLOAD traffic shape is working. Download is not shaped.
What can be wrong?
delele system services dhcp-local-server group DHCP-GROUP dynamic-profile svc-global-inet
delele system services dhcp-local-server group DHCP-GROUP service-profile svc-global-inet
delete dynamic-profiles svc-global-inet
set dynamic-profiles svc-global-inet variables SPEED_IN mandatory
set dynamic-profiles svc-global-inet variables SPEED_OUT mandatory
set dynamic-profiles svc-global-inet variables INET_IN uid
set dynamic-profiles svc-global-inet variables INET_OUT uid
set dynamic-profiles svc-global-inet variables POLICER_IN uid
set dynamic-profiles svc-global-inet variables POLICER_OUT uid
set dynamic-profiles svc-global-inet interfaces "$junos-interface-ifd-name" unit "$junos-interface-unit" family inet filter input "$INET_IN"
set dynamic-profiles svc-global-inet interfaces "$junos-interface-ifd-name" unit "$junos-interface-unit" family inet filter output "$INET_OUT"
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_IN" interface-specific
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_IN" term 1 then policer "$POLICER_IN"
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_IN" term 1 then service-accounting
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_IN" term 1 then accept
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_OUT" interface-specific
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_OUT" term 1 then policer "$POLICER_OUT"
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_OUT" term 1 then service-accounting
set dynamic-profiles svc-global-inet firewall family inet filter "$INET_OUT" term 1 then accept
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" filter-specific
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" if-exceeding bandwidth-limit "$SPEED_IN"
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" if-exceeding burst-size-limit 512k
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" then discard
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" filter-specific
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" if-exceeding bandwidth-limit "$SPEED_OUT"
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" if-exceeding burst-size-limit 512k
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" then discard
root@TEST# run show subscribers extensive
Type: DHCP
User Name: 64d1.548c.f997
IP Address: 100.105.105.6
IP Netmask: 255.255.255.0
Logical System: default
Routing Instance: default
Interface: ae0.2511
Interface type: Static
Underlying Interface: ae0.2511
MAC Address: 64:d1:54:8c:f9:97
State: Active
Radius Accounting ID: 784
Session ID: 784
PFE Flow ID: 1
VLAN Id: 2511
Agent Circuit ID: len 6
00 04 09 cf 01 15
Agent Remote ID: len 8
00 06 b8 be bf ab 02 80
Login Time: 2024-02-28 12:49:38 EET
Service Sessions: 1
DHCP Options: len 52
35 01 01 37 08 01 79 03 21 06 2a 8a 2b 0c 08 4d 69 6b 72 6f
54 69 6b 3d 07 01 64 d1 54 8c f9 97 52 12 01 06 00 04 09 cf
01 15 02 08 00 06 b8 be bf ab 02 80
IP Address Pool: DHCP-POOL
Accounting interval: 600
Service Session ID: 785
Service Session Name: svc-global-inet
State: Active
Family: inet
IPv4 Input Filter Name: INET_IN_UID1181-ae0.2511-in
IPv4 Output Filter Name: INET_OUT_UID1183-ae0.2511-out
Service Activation time: 2024-02-28 12:49:39 EET
Dynamic configuration:
INET_IN: INET_IN_UID1181
INET_OUT: INET_OUT_UID1183
POLICER_IN: POLICER_IN_UID1180
POLICER_OUT: POLICER_OUT_UID1182
SPEED_IN: 10m
SPEED_OUT: 10m
------------------------------
DUMITRU POPOVICI
Original Message:
Sent: 02-27-2024 04:49
From: DUMITRU POPOVICI
Subject: Juniper MX80 BRAS DHCP+Radius
Dear team,
Please help to setup a BRAS based on Juniper MX80 + MS-MIC-16G (for CGNAT)
ae0.2511 - CGNAT customers interface
ge-1/3/1 - World interface
Radius server - 192.168.200.32
Radius options:
(1, 'mikrotik1', 'Framed-IP-Address', '=', '100.105.105.6'),
(2, 'mikrotik1', 'ERX-Service-Activate:1', '+=', 'svc-global-inet(70m,70m)');
In case I use just "Framed-IP-Address", the host got the IP address and everything is working fine, however I need to shape my customers with dynamic policy, so I'm using
"ERX-Service-Activate:1". Unfortunately when I add "ERX-Service-Activate:1", the host is no more receiving the IP with DHCP
Juniper config and logs below:
set system services dhcp-local-server traceoptions file dhcplog
set system services dhcp-local-server traceoptions file size 2m
set system services dhcp-local-server traceoptions file files 2
set system services dhcp-local-server traceoptions flag all
set system services dhcp-local-server pool-match-order ip-address-first
set system services dhcp-local-server group DHCP-GROUP authentication username-include mac-address
set system services dhcp-local-server group DHCP-GROUP overrides
set system services dhcp-local-server group DHCP-GROUP dynamic-profile svc-global-inet
set system services dhcp-local-server group DHCP-GROUP service-profile svc-global-inet
set system services dhcp-local-server group DHCP-GROUP access-profile RADIUS-PROFILE
set system services dhcp-local-server group DHCP-GROUP interface ae0.2511
set system services subscriber-management enable
set system syslog user * any emergency
set system syslog file interactive-commands interactive-commands any
set system syslog file messages any notice
set system syslog file messages authorization info
set system commit synchronize
set system processes general-authentication-service traceoptions file authd_logfile
set system processes general-authentication-service traceoptions file size 10m
set system processes general-authentication-service traceoptions file files 3
set system processes general-authentication-service traceoptions flag all
set dynamic-profiles svc-global-ipoe
set dynamic-profiles svc-global-inet variables SPEED_IN default-value 10m
set dynamic-profiles svc-global-inet variables SPEED_OUT default-value 10m
set dynamic-profiles svc-global-inet variables POLICER_IN uid
set dynamic-profiles svc-global-inet variables POLICER_OUT uid
set dynamic-profiles svc-global-inet interfaces ae0 unit "$junos-interface-unit" family inet filter input "$SPEED_IN"
set dynamic-profiles svc-global-inet interfaces ae0 unit "$junos-interface-unit" family inet filter input precedence 50
set dynamic-profiles svc-global-inet interfaces ae0 unit "$junos-interface-unit" family inet filter output "$SPEED_OUT"
set dynamic-profiles svc-global-inet interfaces ae0 unit "$junos-interface-unit" family inet filter output precedence 50
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_IN" interface-specific
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_IN" term default then policer "$POLICER_IN"
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_IN" term default then service-accounting
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_IN" term default then accept
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_OUT" interface-specific
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_OUT" term default then policer "$POLICER_OUT"
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_OUT" term default then service-accounting
set dynamic-profiles svc-global-inet firewall family inet filter "$SPEED_OUT" term default then accept
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" filter-specific
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" logical-interface-policer
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" if-exceeding bandwidth-limit "$SPEED_IN"
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" if-exceeding burst-size-limit 512k
set dynamic-profiles svc-global-inet firewall policer "$POLICER_IN" then discard
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" filter-specific
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" logical-interface-policer
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" if-exceeding bandwidth-limit "$SPEED_OUT"
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" if-exceeding burst-size-limit 512k
set dynamic-profiles svc-global-inet firewall policer "$POLICER_OUT" then discard
set chassis redundancy graceful-switchover
set chassis aggregated-devices ethernet device-count 5
set chassis fpc 0 pic 0 inline-services
set chassis fpc 1 pic 0 adaptive-services service-package extension-provider package jservices-nat
set chassis network-services enhanced-ip
set services service-set INT-STYLE-SS-NAT1 nat-rules SRC-NAT1
set services service-set INT-STYLE-SS-NAT1 interface-service service-interface ms-0/2/0.0
set services nat pool p1 address 123.0.234.0/27
set services nat pool p1 port automatic random-allocation
set services nat pool p1 port deterministic-port-block-allocation block-size 7168
set services nat pool p11 address 100.105.105.0/27
set services nat rule SRC-NAT1 match-direction input
set services nat rule SRC-NAT1 term r1 from source-address 100.105.105.0/24
set services nat rule SRC-NAT1 term r1 then translated source-pool p1
set services nat rule SRC-NAT1 term r1 then translated translation-type deterministic-napt44
set interfaces xe-0/0/0 description NEXUS1-LSC-
set interfaces xe-0/0/1 description NEXUS1-LSC-
set interfaces ms-0/2/0 unit 0 family inet
set interfaces ge-1/3/0 description CLNT-LSC-
set interfaces ge-1/3/0 gigether-options 802.3ad ae0
set interfaces ge-1/3/1 unit 0 description WRLD
set interfaces ge-1/3/1 unit 0 family inet address 111.26.222.9/25
set interfaces ge-1/3/2 description CLNT-LSC-
set interfaces ge-1/3/2 gigether-options 802.3ad ae0
set interfaces ae0 enable
set interfaces ae0 vlan-tagging
set interfaces ae0 aggregated-ether-options minimum-links 1
set interfaces ae0 aggregated-ether-options link-speed 1g
set interfaces ae0 aggregated-ether-options lacp active
set interfaces ae0 unit 2511 vlan-id 2511
set interfaces ae0 unit 2511 family inet service input service-set INT-STYLE-SS-NAT1
set interfaces ae0 unit 2511 family inet service output service-set INT-STYLE-SS-NAT1
set interfaces ae0 unit 2511 family inet address 100.105.105.1/24
set interfaces fxp0 unit 0 description MGMGT
set interfaces fxp0 unit 0 family inet address 192.168.200.31/24
set forwarding-options dhcp-relay overrides
set forwarding-options dhcp-relay server-group DHCP-GROUP
set routing-options nonstop-routing
set routing-options static route 0.0.0.0/0 next-hop 111.26.222.1
set access radius-server 192.168.200.32 port 1812
set access radius-server 192.168.200.32 accounting-port 1813
set access radius-server 192.168.200.32 secret "very-secret"
set access radius-server 192.168.200.32 source-address 192.168.200.31
set access profile RADIUS-PROFILE authentication-order radius
set access profile RADIUS-PROFILE radius authentication-server 192.168.200.32
set access profile RADIUS-PROFILE radius accounting-server 192.168.200.32
set access profile RADIUS-PROFILE radius options calling-station-id-delimiter *
set access profile RADIUS-PROFILE radius options calling-station-id-format mac-address
set access profile RADIUS-PROFILE radius options calling-station-id-format stacked-vlan
set access profile RADIUS-PROFILE radius options calling-station-id-format vlan
set access profile RADIUS-PROFILE radius options accounting-session-id-format decimal
set access profile RADIUS-PROFILE radius options client-authentication-algorithm round-robin
set access profile RADIUS-PROFILE radius options client-accounting-algorithm round-robin
set access profile RADIUS-PROFILE accounting order radius
set access profile RADIUS-PROFILE accounting immediate-update
set access profile RADIUS-PROFILE accounting coa-immediate-update
set access profile RADIUS-PROFILE accounting address-change-immediate-update
set access profile RADIUS-PROFILE accounting update-interval 10
set access profile RADIUS-PROFILE accounting statistics volume-time
set access profile RADIUS-PROFILE accounting wait-for-acct-on-ack
set access profile RADIUS-PROFILE accounting send-acct-status-on-config-change
set access address-assignment pool DHCP-POOL family inet network 100.105.105.0/24
set access address-assignment pool DHCP-POOL family inet range DHCP-RANGE low 100.105.105.2
set access address-assignment pool DHCP-POOL family inet range DHCP-RANGE high 100.105.105.254
set access address-assignment pool DHCP-POOL family inet dhcp-attributes maximum-lease-time 86400
set access address-assignment pool DHCP-POOL family inet dhcp-attributes name-server 8.8.8.8
set access address-assignment pool DHCP-POOL family inet dhcp-attributes router 100.105.105.1
% tail -f /var/log/authd_logfile
Feb 27 12:25:15.456261 Process/Dispatch Client Message
Feb 27 12:25:15.456406 New Process/Dispatch Client Message
Feb 27 12:25:15.456664 authd_tlv_build_list_from_struct username l =1 offset =56
Feb 27 12:25:15.456750 authd_tlv_build_list_from_struct profile l =1 offset =57
Feb 27 12:25:15.456932 authd_tlv_build_list_from_struct password l =1 offset =58
Feb 27 12:25:15.457029 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0
Feb 27 12:25:15.457292 authd_auth_aaa_msg_create: profile:()
Feb 27 12:25:15.457384 Process Request
Feb 27 12:25:15.457570 SEQ RecvClientMsg:jdhcpd-client session-id:219 Opcode:65, Subcode:0 (ACCESS_REQUEST)
Feb 27 12:25:15.457663 Taking a client snapshot, session-id:219
Feb 27 12:25:15.457883 getSubscriberAaaOptionsName
Feb 27 12:25:15.457991 authd_build_req_attr_list_from_sdb_data: The request list is from sdb
Feb 27 12:25:15.458261 Creating SubscriberASTEntry for session-id:219, session name:64d1.548c.f997
Feb 27 12:25:15.458455 fillSessionDBAttributes: session-id:219, ifdName: ae0
Feb 27 12:25:15.458533 : Found the access-profile in the SDB for session-id:219 access-profile: RADIUS-PROFILE
Feb 27 12:25:15.458582 Bbe Domain Id found in the SDB for session-id:219
Feb 27 12:25:15.458629 PhyIfdName found in the SDB for session-id:219
Feb 27 12:25:15.458694 aaa ls:default aaa ri:default; target ls:default target ri: default
Feb 27 12:25:15.458745 setTargetRoutingContextdefault:default
Feb 27 12:25:15.458788 Access Profile Name is <RADIUS-PROFILE> on LR/RI:default:default
Feb 27 12:25:15.458853 authd_build_radius_nas_port_and_id: nas-port-id-format order is disabled
Feb 27 12:25:15.458892 authd_build_req_attr_list_from_sdb_data: The request list is from aaa_msg
Feb 27 12:25:15.458955 authd_get_auth_request_nas_attr: No interface SVLAN attribute from SDB
Feb 27 12:25:15.459006 authd_get_auth_request_nas_attr: No interface ATM VPI attribute from SDB
Feb 27 12:25:15.459047 authd_get_auth_request_nas_attr: No interface ATM VCI attribute from SDB
Feb 27 12:25:15.459089 authd_get_auth_request_nas_attr: Recovered from SDB - VPI:-1 VCI:-1 NasPortType:15
Feb 27 12:25:15.459165 authd_get_interface_nas_port_options Interface Radius-Options for Interface ae0 not found
Feb 27 12:25:15.459219 authd_get_interface_description: interface name attribute not available from SDB
Feb 27 12:25:15.459328 authd_get_interface_description: interface name attribute not available from SDB
Feb 27 12:25:15.459380 authd_build_radius_nas_port_and_id: NASPortID = ae0:2511, NASPort = 9cf, CallingStationID = 64-d1-54-8c-f9-97**2511
Feb 27 12:25:15.459468 Finding a client snapshot session-id:219
Feb 27 12:25:15.460002 Setting multi-acct-session-id to 0
Feb 27 12:25:15.460056 setAccountingInfo: RADIUS-PROFILE
Feb 27 12:25:15.460102 setAccountingInfo: service accounting order 0
Feb 27 12:25:15.460142 updateCoaDynamicVariableValidation coaValidation: 0
Feb 27 12:25:15.460213 JSRC: NOT calling jsrc restore function: - notify off - jsrc id empty
Feb 27 12:25:15.460260 Bundle session id not found, setting to NULL
Feb 27 12:25:15.460299 multi-acct-session-id set to 0
Feb 27 12:25:15.460346 access profile: RADIUS-PROFILE
Feb 27 12:25:15.460385 On-demand IP address set to 0
Feb 27 12:25:15.460441 UserAccess:64d1.548c.f997 session-id:219 Access-profile:RADIUS-PROFILE Multi-Acct-Session-Id:0
Feb 27 12:25:15.460483 authd_auth_modules_pre_feed_sanity: message passed sanity test profile=(), username=()
Feb 27 12:25:15.460546 AuthFsm::current state=AuthInit(0) event=1 astEntry=0x301f06c aaa msg=0x25a706c session-id:219
Feb 27 12:25:15.460596 ###################################################################
Feb 27 12:25:15.460631 ########################### AUTH REQ RCVD #########################
Feb 27 12:25:15.460664 ###################################################################
Feb 27 12:25:15.460697 Auth-FSM: Process Auth-Request for session-id:219
Feb 27 12:25:15.460738 Framework: Starting authentication
Feb 27 12:25:15.460777 authd_advance_module_for_aaa_request_msg: result:0
Feb 27 12:25:15.460820 Authd module start session-id:219
Feb 27 12:25:15.460854 authd_radius_start_auth: Starting RADIUS authentication session-id:219
Feb 27 12:25:15.460896 authd_radius_get_config:Using radius option config from access profile stanza
Feb 27 12:25:15.461208 authd_radius_build_basic_auth_request: session-id:219 profile=RADIUS-PROFILE, username=64d1.548c.f997
Feb 27 12:25:15.461254 radius-access-request: User-Name added: 64d1.548c.f997
Feb 27 12:25:15.461290 radius-access-request: User-Password added: ""
Feb 27 12:25:15.461367 radius-access-request: Service-Type added: 2
Feb 27 12:25:15.461440 radius-access-request: Chargeable-User-Identity added:
Feb 27 12:25:15.461498 radius-access-request: Acct-Session-Id added: 219
Feb 27 12:25:15.461554 radius-access-request: Calling-Station-Id added: 64-d1-54-8c-f9-97**2511
Feb 27 12:25:15.461647 radius-access-request: DHCP-Options (Juniper-ERX-VSA) added: 35 01 01 37 08 01 79 03 21 06 2a 8a 2b 0c 08 4d 69 6b 72 6f 54 69 6b 3d 07 01 64 d1 54 8c f9 97 52 12 01 06 00 04 09 cf 01 15 02 08 00 06 b8 be bf ab 02 80
Feb 27 12:25:15.461712 radius-access-request: DHCP-MAC-Address (Juniper-ERX-VSA) added: 64d1.548c.f997
Feb 27 12:25:15.462379 radius-access-request: NAS-Identifier added: TEST
Feb 27 12:25:15.462446 radius-access-request: NAS-Port added: 00 00 09 cf
Feb 27 12:25:15.462490 radius-access-request: NAS-Port-Id added: ae0:2511
Feb 27 12:25:15.462539 radius-access-request: NAS-Port-Type added: 15
Feb 27 12:25:15.462604 radius-access-request: PPPoE-Description (Juniper-ERX-VSA) added: pppoe 64:d1:54:8c:f9:97
Feb 27 12:25:15.462670 radius-access-request: Agent-Circuit-Id (DSL Forum-VSA) Sub-Attribute added:
Feb 27 12:25:15.462718 radius-access-request: Agent-Remote-Id (DSL Forum-VSA) Sub-Attribute added:
Feb 27 12:25:15.462782 radius-access-request: DHCP-First-Relay-IPv4-Address (Juniper-ERX-VSA) added: 100.105.105.1
Feb 27 12:25:15.462863 authd_create_application_specific_radius_server: Evaluating RADIUS server 192.168.200.32 to add to the server list
Feb 27 12:25:15.462904 Evaluating RADIUS server 192.168.200.32 to add to the server list
Feb 27 12:25:15.462943 Verify source address c0a8c81f in routing instance index=0
Feb 27 12:25:15.463059 authd_radius_server_add: server 192.168.200.32 retry 3, timeout 3
Feb 27 12:25:15.463106 processSessionAttributeNasAddress 219
Feb 27 12:25:15.463140 processSessionAttributeNasAddress return false
Feb 27 12:25:15.463291 Request queued successfully
Feb 27 12:25:15.463341 REQUEST: AUTHEN - module_index 0 module(radius) return: ASYNC
Feb 27 12:25:15.463395 UserAccess:64d1.548c.f997 session-id:219 state:start ae0:2511
Feb 27 12:25:15.463440 Auth-FSM: GRES-Mirror for session-id:219 state:AuthStart(1)
Feb 27 12:25:15.476492 authd_radius_get_config:Using radius option config from access profile stanza
Feb 27 12:25:15.476947 RadiusServer: server[0] used for last request - 192.168.200.32
Feb 27 12:25:15.477202 Radius result is CLIENT_REQ_STATUS_SUCCESS
Feb 27 12:25:15.477393 Parsing RADIUS message for session-id:219
Feb 27 12:25:15.477617 radius-access-accept: Service-Type received: 2
Feb 27 12:25:15.477724 radius-access-accept: Framed-IP-Address received: 100.105.105.6
Feb 27 12:25:15.477927 radius-access-accept: Framed-IP-Netmask received: 255.255.255.0
Feb 27 12:25:15.478042 radius-access-accept: Activate-Service (Juniper-ERX-VSA) received: Tag (1) svc-global-inet(70m,70m)
Feb 27 12:25:15.478272 Framework - module(radius) return: SUCCESS
Feb 27 12:25:15.478357 authd_advance_module_for_aaa_response_msg: result:2
Feb 27 12:25:15.478556 Client-session response-attr:: type:78 len:4
Feb 27 12:25:15.478653 Client-session response-attr:: type:21 len:4
Feb 27 12:25:15.478843 Client-session response-attr:: type:22 len:4
Feb 27 12:25:15.479173 Finding a client snapshot session-id:219
Feb 27 12:25:15.479494 Decoding incoming attributes
Feb 27 12:25:15.479704 Subscriber attribute 10005, length 4
Feb 27 12:25:15.479795 Subscriber attribute 10180, length 15
Feb 27 12:25:15.479979 Subscriber attribute 10182, length 4
Feb 27 12:25:15.480065 Subscriber attribute 33025, length 6
Feb 27 12:25:15.480246 Subscriber attribute 33026, length 8
Feb 27 12:25:15.480337 Received subscriber login request, subscriber-session-id:219
Feb 27 12:25:15.480554 Decoding attribute 10005 length 4
Feb 27 12:25:15.480645 Decoding attribute 10180 length 15
Feb 27 12:25:15.480826 Decoding attribute 10182 length 4
Feb 27 12:25:15.480910 Decoding attribute 33025 length 6
Feb 27 12:25:15.481100 Decoding attribute 33026 length 8
Feb 27 12:25:15.481211 Processing address request in default:default network 100.105.105.1 mac 64:D1:54:8C:F9:97
Feb 27 12:25:15.481405 readSessionEntry
Feb 27 12:25:15.481532 Processing rule Network-Match
Feb 27 12:25:15.481715 ***************** START-NetworkMatch ********************
Feb 27 12:25:15.481803 DUMP of all addressRequest fields for subscriber session-id:219 router default:default
Feb 27 12:25:15.482008 client type jdhcpd-client client type 1 mac address 64:D1:54:8C:F9:97
Feb 27 12:25:15.482111 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 100.105.105.1 null
Feb 27 12:25:15.482333 V4NA: req: yes pool: NULL address: 100.105.105.6
Feb 27 12:25:15.482541 V6NA: req: no pool: NULL address: null
Feb 27 12:25:15.482643 V6PD: req: no pool: NULL prefix: null/0
Feb 27 12:25:15.482840 V6NDRA: req: no pool: NULL ndra prefix: null/0
Feb 27 12:25:15.482925 *********************************************************
Feb 27 12:25:15.483109 IPV4 ADDRESS ALLOC begin
Feb 27 12:25:15.483209 Found a pool DHCP-POOL that matches the externally assigned address 100.105.105.6
Feb 27 12:25:15.483397 IPV6 ADDRESS ALLOC begin
Feb 27 12:25:15.483478 IPV6 PREFIX ALLOC begin
Feb 27 12:25:15.483650 ****************** END-NetworkMatch *********************
Feb 27 12:25:15.483736 DUMP of all addressRequest fields for subscriber session-id:219 router default:default
Feb 27 12:25:15.483934 client type jdhcpd-client client type 1 mac address 64:D1:54:8C:F9:97
Feb 27 12:25:15.484068 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 100.105.105.1 null
Feb 27 12:25:15.484418 V4NA: req: yes pool: DHCP-POOL address: 100.105.105.6
Feb 27 12:25:15.484518 V6NA: req: no pool: NULL address: null
Feb 27 12:25:15.484684 V6PD: req: no pool: NULL prefix: null/0
Feb 27 12:25:15.485215 V6NDRA: req: no pool: NULL ndra prefix: null/0
Feb 27 12:25:15.485368 *********************************************************
Feb 27 12:25:15.485557 Done processing rules
Feb 27 12:25:15.485678 Pool::addressAssign: pool DHCP-POOL addr 100.105.105.6 range null session-id:219
Feb 27 12:25:15.485895 Pool::addressAssign: pool DHCP-POOL addr 100.105.105.6 range null returning <Success:authd class=3, code=0> session-id:219
Feb 27 12:25:15.486032 Trying to assign address 100.105.105.6 to subscriber session-id:219
Feb 27 12:25:15.486298 Inserting address 100.105.105.6 for session-id:219 into pool DHCP-POOL
Feb 27 12:25:15.486428 Finding a client snapshot session-id:219
Feb 27 12:25:15.486737 Result have been returned with opcode=0, result=2
Feb 27 12:25:15.486827 ************* Results of Address Allocation *************
Feb 27 12:25:15.487013 DUMP of all addressRequest fields for subscriber session-id:219 router default:default
Feb 27 12:25:15.487319 client type jdhcpd-client client type 1 mac address 64:D1:54:8C:F9:97
Feb 27 12:25:15.487444 REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 100.105.105.1 null
Feb 27 12:25:15.487503 Framed-Pool-->SDB_USER_IP_POOL 'DHCP-POOL' used for V4NA
Feb 27 12:25:15.487565 V4NA: req: yes pool: DHCP-POOL address: 100.105.105.6
Feb 27 12:25:15.487611 V6NA: req: no pool: NULL address: null
Feb 27 12:25:15.487662 V6PD: req: no pool: NULL prefix: null/0
Feb 27 12:25:15.487711 V6NDRA: req: no pool: NULL ndra prefix: null/0
Feb 27 12:25:15.487749 *********************************************************
Feb 27 12:25:15.487804 authd_auth_update_local_server_address ::Searching access profile RADIUS-PROFILE for local DNS Server
Feb 27 12:25:15.487866 AuthFsm::current state=AuthStart(1) event=2 astEntry=0x301f06c aaa msg=0x25a706c session-id:219
Feb 27 12:25:15.488259 Auth-FSM: Process Auth-Response for session-id:219 and client type broadband
Feb 27 12:25:15.488485 createDynamicRequest: (2) received
Feb 27 12:25:15.488570 CoARequest CTOR 0x0x303806c
Feb 27 12:25:15.488745 createDynamicRequest: isBulkCoaRequest 0
Feb 27 12:25:15.488842 buildAndAddRequest:4719 session-id:219 activate svc-global-inet
Feb 27 12:25:15.489082 ServiceActivate: request=svc-global-inet, serviceName=svc-global-inet, serviceString=svc-global-inet
Feb 27 12:25:15.489318 buildAndAddRequest:4778 Setting sub-session-id:219 and NO serviceSessionId
Feb 27 12:25:15.489402 finishAddRequest:4569
Feb 27 12:25:15.489550 ServiceActivate::validateRequest
Feb 27 12:25:15.489797 Decoding the Dynamic-Service=svc-global-inet. Request=<svc-global-inet>
Feb 27 12:25:15.489898 finishAddRequest:4621
Feb 27 12:25:15.490092 buildAndAddRequest:4719 session-id:219 activate svc-global-inet(70m,70m)
Feb 27 12:25:15.490367 ServiceActivate: request=svc-global-inet(70m,70m), serviceName=svc-global-inet, serviceString=svc-global-inet(70m,70m)
Feb 27 12:25:15.490460 buildAndAddRequest:4778 Setting sub-session-id:219 and NO serviceSessionId
Feb 27 12:25:15.490654 finishAddRequest:4569
Feb 27 12:25:15.490735 ServiceActivate::validateRequest
Feb 27 12:25:15.490929 Decoding the Dynamic-Service=svc-global-inet. Request=<svc-global-inet(70m,70m)>
Feb 27 12:25:15.491042 finishAddRequest:4621
Feb 27 12:25:15.491401 ServiceAtLoginRequest::validateRequest
Feb 27 12:25:15.491512 Framework: auth result is 1. Performing post-auth operations
Feb 27 12:25:15.491701 Set Idle Timeout Ingress Only: FALSE
Feb 27 12:25:15.491784 Framework: result is 1.
Feb 27 12:25:15.491972 SEQ SendClientMsg:jdhcpd-client session-id:219 reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), cookie=65754, rply_len=28, num_tlv_blocks=0
Feb 27 12:25:15.492080 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x25a75e8
Feb 27 12:25:15.492314 ###################################################################
Feb 27 12:25:15.492505 ######################### AUTH REQ ACK SENT #######################
Feb 27 12:25:15.492586 ###################################################################
Feb 27 12:25:15.493164 Auth-FSM: GRES-Mirror for session-id:219 state:AuthClntRespWait(4)
Feb 27 12:25:15.493383 doPersistedDataUpdates
Feb 27 12:25:15.493471 persistOnlyPrivateData m_inFlight
Feb 27 12:25:15.761163 Process/Dispatch Client Message
Feb 27 12:25:15.761310 New Process/Dispatch Client Message
Feb 27 12:25:15.761586 authd_auth_aaa_msg_create: num_of_tlvs:1 tot_num_of_tlv:1
Feb 27 12:25:15.761673 authd_auth_aaa_msg_create: profile:()
Feb 27 12:25:15.761857 Process Request
Feb 27 12:25:15.761948 SEQ RecvClientMsg:jdhcpd-client session-id:219 Opcode:3, Subcode:15 (SESSION_LOGOUT)
Feb 27 12:25:15.762144 Setting terminate ID to 40001
Feb 27 12:25:15.762251 Decoding incoming attributes
Feb 27 12:25:15.762432 Begin to logout Subscriber
Feb 27 12:25:15.762520 Received subscriber logout request session-id:219
Feb 27 12:25:15.762703 subscriberLogout session-id:219
Feb 27 12:25:15.762804 Releasing addressEntry for address 100.105.105.6 session-id:219
Feb 27 12:25:15.763036 ###################################################################
Feb 27 12:25:15.763125 ############################ LOGOUT RCVD ##########################
Feb 27 12:25:15.763312 ###################################################################
Feb 27 12:25:15.763412 AuthFsm::current state=AuthClntRespWait(4) event=8 astEntry=0x301f06c aaa msg=0x25a75e8 session-id:219
Feb 27 12:25:15.763607 Auth-FSM: Posting a Logout-Ack to the client daemon for session-id:219
Feb 27 12:25:15.764326 clearDynamicConfigLists: numRequests 2
Feb 27 12:25:15.764381 ~CoARequest 0x0x303806c
Feb 27 12:25:15.764416 cleanServiceList: numRequests 2
Feb 27 12:25:15.764457 cleanServiceList: For service svc-global-inet session-id:0, processed No, action Service Add
Feb 27 12:25:15.764500 markAsProcessed: ServiceRequestEntry service session-id:0
Feb 27 12:25:15.764538 cleanServiceList: For service svc-global-inet session-id:0, processed No, action Service Add
Feb 27 12:25:15.764576 markAsProcessed: ServiceRequestEntry service session-id:0
Feb 27 12:25:15.764627 ~DynamicRequestEntry 0x0x303806c
Feb 27 12:25:15.764677 ****astEntry:0x301f06c aaaMsg:0x25a75e8 replyOpcode:1 replySubOpcode:16 replyStatus:1
Feb 27 12:25:15.764728 SEQ SendClientMsg:jdhcpd-client session-id:219 reply-code=1 (OK), result-subopcode=16 (SESSION_LOGOUT_ACK), cookie=65754, rply_len=28, num_tlv_blocks=0
Feb 27 12:25:15.764783 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x25a706c
Feb 27 12:25:15.764832 ###################################################################
Feb 27 12:25:15.764867 ####################### LOGOUT ACK SENT ########################
Feb 27 12:25:15.764900 ###################################################################
Feb 27 12:25:15.766207 retrieveChassisStartupTimeInUsecs from kernel call 0
Feb 27 12:25:15.766641 Only start time found for session-id:219
Feb 27 12:25:15.766812 Delete session-id:219
Feb 27 12:25:15.767009 Begin to logout Subscriber
Feb 27 12:25:15.767398 subscriberLogout session-id:219
Feb 27 12:25:15.767671 UserAccess:64d1.548c.f997 session-id:219 state:log-out ae0:2511 reason: dhcp nak
Feb 27 12:25:16.065234 Process/Dispatch Client Message
Feb 27 12:25:16.065371 New Process/Dispatch Client Message
Feb 27 12:25:16.065633 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0
Feb 27 12:25:16.065718 authd_auth_aaa_msg_create: profile:()
Feb 27 12:25:16.065900 Process Request
Feb 27 12:25:16.065995 SEQ RecvClientMsg:jdhcpd-client session-id:219 Opcode:1, Subcode:17 (CLIENT_SESSION_CLEANUP_REQ)
Feb 27 12:25:16.066180 findSession AST-Table couldn't find the session-id:219
Feb 27 12:25:16.066266 lookup_subscriber_session_entry Failed to get ASTEntry for session-id:219
Feb 27 12:25:16.066449 Pending ACCT Stop Table couldn't find session-id:219
Feb 27 12:25:16.066537 ###################################################################
Feb 27 12:25:16.066990 ################ TERMINATE-REQ RCVD AFTER CLEANUP #################
Feb 27 12:25:16.067428 ###################################################################
Feb 27 12:25:16.067536 SEQ SendClientMsg:jdhcpd-client session-id:219 reply-code=1 (OK), result-subopcode=18 (CLIENT_SESSION_CLEANUP_ACK), cookie=65754, rply_len=28, num_tlv_blocks=0
Feb 27 12:25:16.067770 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x25a75e8
Feb 27 12:25:16.067869 ###################################################################
Feb 27 12:25:16.068012 ########## TERMINATE-REQ-ACK SENT (FAKE - AFTER CLEANUP) ##########
Feb 27 12:25:16.068271 ###################################################################
% tail -f /var/log/dhcplog
Feb 27 12:27:17.806522 [MSTR][INFO] jdhcpd_smd_process_v4_pkt: **** 417 byte packet received on IFL index 328 ****
Feb 27 12:27:17.806835 [MSTR][DEBUG] jdhcpd_packet_new: PACKET - Allocated new v4 packet 0x33a8400
Feb 27 12:27:17.807114 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] 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 293
Feb 27 12:27:17.807245 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP from == 0.0.0.0, port == 68 ]--
Feb 27 12:27:17.807453 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP size == 293, op == 1 ]--
Feb 27 12:27:17.807917 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP flags == 8000 ]--
Feb 27 12:27:17.808119 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP htype == 1, hlen == 6 ]--
Feb 27 12:27:17.808213 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP hops == 0, xid == c23251d2 ]--
Feb 27 12:27:17.808408 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP secs == 45, flags == 8000 ]--
Feb 27 12:27:17.808504 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP ciaddr == 0.0.0.0 ]--
Feb 27 12:27:17.808700 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP yiaddr == 0.0.0.0 ]--
Feb 27 12:27:17.808801 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP siaddr == 0.0.0.0 ]--
Feb 27 12:27:17.809051 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP giaddr == 0.0.0.0 ]--
Feb 27 12:27:17.809270 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP chaddr == 64 d1 54 8c f9 97 00 00 00 00 00 00 00 00 00 00 ]--
Feb 27 12:27:17.809366 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP sname == ]--
Feb 27 12:27:17.809604 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ DHCP/BOOTP file == ]--
Feb 27 12:27:17.809708 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ OPTION code 53, len 1, data DHCP-DISCOVER ]--
Feb 27 12:27:17.809925 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ OPTION code 55, len 8, data 01 79 03 21 06 2a 8a 2b ]--
Feb 27 12:27:17.810027 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ OPTION code 12, len 8, data 4d 69 6b 72 6f 54 69 6b ]--
Feb 27 12:27:17.810260 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ OPTION code 61, len 7, data 01 64 d1 54 8c f9 97 ]--
Feb 27 12:27:17.810482 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] --[ OPTION code 82, len 18, data 01 06 00 04 09 cf 01 15 02 08 00 06 b8 be bf ab 02 80 ]--
Feb 27 12:27:17.810578 [MSTR][INFO] [default:default][SVR][INET][ae0.2511] --[ OPTION code 255, len 0 ]--
Feb 27 12:27:17.810813 [MSTR][DEBUG] client_key_compose: Composing key (0x33a8600) for cid_l 7, cid 64 d1 54 8c f9 97, mac 64 d1 54 8c f9 97, htype 1, subnet 100.105.105.1, ifindx 0, opt82_l 0, opt82 NULL
Feb 27 12:27:17.810914 [MSTR][DEBUG] client_key_compose: Successfully composed CK_TYPE_CLIENT_ID_ON_SUBNET (1) client key object.
Feb 27 12:27:17.811174 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_CLIENT_ID_ON_SUBNET (1): subnet 100.105.105.1, Clientid_len 7, 01 64 d1 54 8c f9 97
Feb 27 12:27:17.811380 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_CLIENT_ID_ON_SUBNET (1) other fields: subnet 100.105.105.1, ifindex 0, opt82_len 0, -
Feb 27 12:27:17.811479 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] jdhcpd_find_client_from_client_pdu: BOOTPREQUEST could not find client table ent
Feb 27 12:27:17.811684 [MSTR][NOTE] jdhcpd_packet_handle: RECEIVE DISCOVER: stats_safd 0x0 , safd 0x339dc00 ae0.2511
Feb 27 12:27:17.811788 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] jdhcpd_process_forward_only_or_drop: Returning ... forward-only flags not set (flags=0, rc_flags a40c0d) for routing context 0
Feb 27 12:27:17.812069 [MSTR][INFO] cedb_entry_new_common: New client (0x33ad800), family=INET, index=65787
Feb 27 12:27:17.812211 [MSTR][DEBUG] cedb_entry_new_common: DHCPv4 client entry ADDED, app_type 1 routing context default:default
Feb 27 12:27:17.812490 [MSTR][DEBUG] jdhcpd_name_2_const: ifl ae0.2511 fpc 0 pic 4294967295 port 4294967295 chnl 4294967295 chnl_max 4294967295 unit 2511
Feb 27 12:27:17.812591 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=0] cedb_entry_new_common: Newly created client entry is flow-based.
Feb 27 12:27:17.812917 [MSTR][DEBUG][default:default][SVR][INET][SID=0] _jdhcpd_stale_timer_add: Added stale-timer for client:0x33ad800
Feb 27 12:27:17.813136 [MSTR][DEBUG][default:default][SVR][INET][SID=0] jdhcpd_packet_handle: new client table entry created for ifindex 328
Feb 27 12:27:17.813236 [MSTR][DEBUG] jdhcpd_name_2_const: ifl ae0.2511 fpc 0 pic 4294967295 port 4294967295 chnl 4294967295 chnl_max 4294967295 unit 2511
Feb 27 12:27:17.813444 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511] jdhcpd_process_offer_advertise_delay: Returning ... offer delay not set (flags=0, rc_flags a40c0d) for routing context 0, rc(2c71000)
Feb 27 12:27:17.813558 [MSTR][DEBUG][default:default][SVR][INET][SID=0] jdhcpd_packet_handle: Set client next-hop mac addr: 00 00 10 11 a9 ad
Feb 27 12:27:17.813779 [MSTR][INFO] [default:default][SVR][INET][SID=0] JDHCPD_CLIENT_EVENT: Client(0x33ad800) got event CLIENT_EVENT_DISCOVER_PDU in state LOCAL_SERVER_STATE_INIT flags 1: 0x0 2: 0x80000 3: 0x0 nm: 0x0
Feb 27 12:27:17.813917 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_profile_get: No snapshot handle to recover SDB profile name
Feb 27 12:27:17.813971 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_profile_get: Profile_get using regular profile svc-global-inet
Feb 27 12:27:17.814556 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_decline_new_client_session: Incremented global in-flight logins - count is 1, session id 0
Feb 27 12:27:17.814612 Service_get using service name svc-global-inet
Feb 27 12:27:17.814663 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_access_profile_get: access_profile_get using access-profile name RADIUS-PROFILE
Feb 27 12:27:17.814708 [MSTR][INFO] jdhcpd_client_set_pkt: *********** Setting v4 packet 0x33a8400
Feb 27 12:27:17.815096 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: phy device name ae0
Feb 27 12:27:17.815483 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting LR name default
Feb 27 12:27:17.815585 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting RI name default
Feb 27 12:27:17.815804 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: sdb username 64d1.548c.f997
Feb 27 12:27:17.816009 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting profile name svc-global-inet
Feb 27 12:27:17.816103 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting access profile name RADIUS-PROFILE
Feb 27 12:27:17.816302 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting service profile name svc-global-inet
Feb 27 12:27:17.816456 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting inner vlan_ID 2511
Feb 27 12:27:17.816507 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting underlying interface ae0.2511
Feb 27 12:27:17.816562 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting MAC addr 64:d1:54:8c:f9:97
Feb 27 12:27:17.816951 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_session_db_create_v4_session_attributes: Setting IPv4 Addr Key 100.105.105.1
Feb 27 12:27:17.817048 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_session_db_create_v4_session_attributes: dhcp_options len 52, data 35 01 01 37 08 01 79 03 21 06 2a 8a 2b 0c 08 4d 69 6b 72 6f 54 69 6b 3d 07 01 64 d1 54 8c f9 97 52 12 01 06 00 04 09 cf 01 15 02 08 00 06 b8 be bf ab 02 80
Feb 27 12:27:17.817100 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_session_db_create_v4_session_attributes: shmlog filter setting ACI 000409cf0115
Feb 27 12:27:17.817146 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_session_db_create_v4_session_attributes: shmlog filter setting ARI 0006b8bebfab0280
Feb 27 12:27:17.817199 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting physical interface name ae0
Feb 27 12:27:17.817243 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=0] jdhcpd_sdb_create_session: setting authd phy ifd name ae0
Feb 27 12:27:17.819659 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_sdb_create_session: session DB create got INET entry id 252
Feb 27 12:27:17.820123 [MSTR][DEBUG] jdhcpd_shmlog_fill_option_filter: Setting the client-id in shmlog filter as 0164d1548cf997.
Feb 27 12:27:17.820231 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_sdb_create_session: Adding shmlog fileter success for session id 252
Feb 27 12:27:17.820446 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_persistent_is_entry_in_file_allowed: client_type=1, client->state=0
Feb 27 12:27:17.820549 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_fill_client_sdb_private_data: Mirroring disabled (ha_graceful_switchover false) ::
Feb 27 12:27:17.820787 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_get_v4_v6_protocol_attributes: get configured protocol-attributes
Feb 27 12:27:17.820862 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_fill_client_sdb_private_data: Allocated memory to store in SDB, total mirrored length 249, client length 249, dual stack peer client length 0, session-id 252
Feb 27 12:27:17.820914 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_write_private_data: Saved NON-DEMUX interface name ae0.2511 into mirroring ha_info
Feb 27 12:27:17.820960 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_get_v4_v6_protocol_attributes: get configured protocol-attributes
Feb 27 12:27:17.821011 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_write_private_data: Added TLV for DHCPv4 CLIENT ID from client key, length 7
Feb 27 12:27:17.821057 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_write_private_data: ++++Added TLV for WHOLESALE LR name default length 7
Feb 27 12:27:17.821102 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_write_private_data: ++++Added TLV for WHOLESALE RI name default length 7
Feb 27 12:27:17.821147 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_write_private_data: Added TLV for last_packet_time length 4, last_packet_time: 1709029637
Feb 27 12:27:17.821638 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_write_private_data: ++++Added TLV for access profile name length 14, profile_name: RADIUS-PROFILE
Feb 27 12:27:17.821906 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_mirrorsdb_add_client: Successfully saved private data for 0.0.0.0 in SDB, length 249
Feb 27 12:27:17.822014 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_client_correlation_id_update: setting the client correlation_id 1 in state 0.
Feb 27 12:27:17.822276 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ
Feb 27 12:27:17.822344 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_auth_request: auth-request attempt initiated: flags1:0x20020; flags2:0x84000l flags3:0
Feb 27 12:27:17.822384 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0
Feb 27 12:27:17.822420 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0
Feb 27 12:27:17.822454 Added client w/ session_id 252 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ, to authd_restart_teardown list, count authd_restart_teardown_count 1
Feb 27 12:27:17.856503 jdhcpd_authenticate_rply_proc: Got reply for auth_request, reply auth_rqst_id = 65787- (session Id 252)
Feb 27 12:27:17.856831 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 252 in state 1 from authd_restart_teardown list, count authd_restart_teardown_count 1
Feb 27 12:27:17.857259 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count
Feb 27 12:27:17.857452 jdhcpd_authenticate_rply_proc: auth login reply status for session 252: result:1; flags1:0x20020; flags2:0x84080
Feb 27 12:27:17.857709 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: got IP address 100.105.105.6
Feb 27 12:27:17.857894 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: failed to update IP Address in shmlog for 252.
Feb 27 12:27:17.858116 [MSTR][DEBUG] jdhcpd_session_db_client_rc_key_create: SDB_LOGICAL_SYSTEM_NAME = default for session-id 252
Feb 27 12:27:17.858217 [MSTR][DEBUG] jdhcpd_session_db_client_rc_key_create: SDB_ROUTING_INSTANCE_NAME = default for session-id 252
Feb 27 12:27:17.858448 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: got pool name DHCP-POOL, len 9
Feb 27 12:27:17.858945 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: got net mask 255.255.255.0
Feb 27 12:27:17.859192 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10180
Feb 27 12:27:17.859295 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10053
Feb 27 12:27:17.859500 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: got unknown auth attr from session db 10201
Feb 27 12:27:17.859601 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_v4_client_info_get: address-change-interim-update enabled
Feb 27 12:27:17.859863 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] JDHCPD_CLIENT_EVENT: Client(0x33ad800) got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ flags 1: 0x20020 2: 0x2084080 3: 0x0 nm: 0x200
Feb 27 12:27:17.860097 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_local_server_auth_request_ack_common: Auth request reply ip=100.105.105.6; pool name=DHCP-POOL; wait_auth_login_req=1
Feb 27 12:27:17.860202 jdhcpd_pool_find: cfg 2c72000, pool_name 32e7740, DHCP-POOL
Feb 27 12:27:17.860400 jdhcpd_pool_find: Pool DHCP-POOL found 0x2c79800 w/ cfg container 0x2c72000
Feb 27 12:27:17.860506 jdhcpd_pool_find: cfg 2c72000, pool_name 32e7740, DHCP-POOL
Feb 27 12:27:17.860689 jdhcpd_pool_find: Pool DHCP-POOL found 0x2c79800 w/ cfg container 0x2c72000
Feb 27 12:27:17.860799 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_check_lease_validation_violation: No configuration for lease time violation validation
Feb 27 12:27:17.860967 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_update_dynamic_variable_demux_ip: Added host address 100.105.105.6/32 to array variable junos-subscriber-demux-ip-address
Feb 27 12:27:17.861367 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_profile_request: Add Profile svc-global-inet request for client session 252 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ, flow = True
Feb 27 12:27:17.861475 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_PROF_INST --> LOCAL_SERVER_STATE_WAIT_PROF_INST
Feb 27 12:27:17.951021 [MSTR][ERROR][default:default][SVR][INET][ae0.2511][SID=252] proflib_cb_handler: Profile Addition NACK (FAILED) - res 8, Errored daemon "bbe-smgd", msg "Failed to create IFL", retry "FALSE"
Feb 27 12:27:17.951492 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] 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 27 12:27:17.951812 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] JDHCPD_CLIENT_EVENT: Client(0x33ad800) got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_INST flags 1: 0x20020 2: 0x2084080 3: 0x0 nm: 0x200
Feb 27 12:27:17.951912 Got profile instantiate reply 8, updating SDB with client session state 1
Feb 27 12:27:17.952121 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_client_session_state_set: setting session state 1
Feb 27 12:27:17.952227 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_client_session_state_set: setting action bits to 3, config-bits:0xff 0xc0 0x39 0xf2 0x2 0x14 0 0
Feb 27 12:27:17.952956 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 252
Feb 27 12:27:17.953043 profile instantiate reply failed err: 8 LOCAL_SERVER_STATE_WAIT_PROF_INST
Feb 27 12:27:17.953246 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_local_server_abort_client: In client state LOCAL_SERVER_STATE_WAIT_PROF_INST - client session Id 252 processing event CLIENT_EVENT_PROF_ACK client was aborted - transitioning to state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE
Feb 27 12:27:17.953366 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE
Feb 27 12:27:17.953595 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_auth_release: auth logout initiated for session 252 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20020; flags2:0x2084080
Feb 27 12:27:17.953705 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_auth_release_common: Release authd (request user logout): updating SDB with client session state SDB_SESSION_STATE_TERMINATING
Feb 27 12:27:17.953926 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_client_session_state_set: setting session state 3
Feb 27 12:27:17.955094 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 252
Feb 27 12:27:17.955468 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_client_correlation_id_update: setting the client correlation_id 2 in state 4.
Feb 27 12:27:17.955707 jdhcpd_auth_release_common: ISSU logout for client session id 252, decrement global in-flight logins (count is 0)
Feb 27 12:27:17.955824 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0
Feb 27 12:27:17.956010 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0
Feb 27 12:27:17.956095 Added client w/ session_id 252 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE, to authd_restart_teardown list, count authd_restart_teardown_count 1
Feb 27 12:27:17.956305 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_auth_release_common: auth logout requested for session 252 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20; flags2:0x2086080
Feb 27 12:27:18.059071 jdhcpd_user_logout_rply_proc: Got reply for user_logout, reply rqst_id = 65787 (session Id 252)
Feb 27 12:27:18.059246 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Get SDB STATE for session Id 252
Feb 27 12:27:18.059535 [MSTR][DEBUG] jdhcpd_session_db_client_session_state_get: Got SDB SESSION STATE 3 for client session Id 252
Feb 27 12:27:18.059636 jdhcpd_user_logout_rply_proc: Got authd reply for user_logout in SDB state TERMINATING, for client 100.105.105.6, client session Id 252
Feb 27 12:27:18.059845 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 252 in state 4 from authd_restart_teardown list, count authd_restart_teardown_count 1
Feb 27 12:27:18.059934 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count
Feb 27 12:27:18.060143 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] JDHCPD_CLIENT_EVENT: Client(0x33ad800) got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE flags 1: 0x20 2: 0x2086080 3: 0x0 nm: 0x200
Feb 27 12:27:18.060243 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 27 12:27:18.060453 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_CM_DELETE --> LOCAL_SERVER_STATE_WAIT_CM_DELETE
Feb 27 12:27:18.060558 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] JDHCPD_CLIENT_EVENT: Client(0x33ad800) got event CLIENT_EVENT_CLIENT_MIRROR_ACK in state LOCAL_SERVER_STATE_WAIT_CM_DELETE flags 1: 0x20 2: 0x2086080 3: 0x0 nm: 0x200
Feb 27 12:27:18.060779 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_PROF_DELETE --> LOCAL_SERVER_STATE_WAIT_PROF_DELETE
Feb 27 12:27:18.061038 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_profile_request: Delete Profile svc-global-inet request for client session 252 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, flow = True
Feb 27 12:27:18.152931 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] proflib_cb_handler: Profile ACK (SUCCESS) - res 0
Feb 27 12:27:18.153063 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] 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 27 12:27:18.153337 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] JDHCPD_CLIENT_EVENT: Client(0x33ad800) got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE flags 1: 0x20 2: 0x2086080 3: 0x0 nm: 0x200
Feb 27 12:27:18.153453 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] 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 27 12:27:18.153674 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_client_session_state_set: setting session state 4
Feb 27 12:27:18.154658 [MSTR][DEBUG] jdhcpd_shmlog_update_session_state: Updating session state to shmlog filter failed for 252
Feb 27 12:27:18.154769 In state LOCAL_SERVER_STATE_WAIT_PROF_DELETE got CLIENT_EVENT_PROF_ACK, proceed with the user-terminated handshake
Feb 27 12:27:18.155057 jdhcpd_auth_release_terminated: auth terminate initiated for session 252: flags1:0x20; flags2:0x2086080
Feb 27 12:27:18.155153 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0
Feb 27 12:27:18.155341 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0
Feb 27 12:27:18.155427 Added client w/ session_id 252 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, to authd_restart_teardown list, count authd_restart_teardown_count 1
Feb 27 12:27:18.155611 jdhcpd_auth_release_terminated_common: auth terminate request for session 252: flags1:0x20; flags2:0x2086080
Feb 27 12:27:18.155896 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_set_fsm_state: FSM state change : LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED --> LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED
Feb 27 12:27:18.262035 jdhcpd_user_terminated_rply_proc: Got user-session terminated REPLY from authd- reqId 65787, for client session Id 252
Feb 27 12:27:18.262188 [MSTR][INFO] jdhcpd_authd_restart_teardown_delete: Request to remove client w. session_id 252 in state 5 from authd_restart_teardown list, count authd_restart_teardown_count 1
Feb 27 12:27:18.262446 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count
Feb 27 12:27:18.262554 [MSTR][INFO] [default:default][SVR][INET][ae0.2511][SID=252] JDHCPD_CLIENT_EVENT: Client(0x33ad800) got event CLIENT_EVENT_AUTH_TERMINATED_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED flags 1: 0x20 2: 0x2086080 3: 0x0 nm: 0x200
Feb 27 12:27:18.262775 [MSTR][INFO] jdhcpd_request_delete_baseline_stats: ATTEMPT TO DELETE libstats; session_id = 252
Feb 27 12:27:18.263035 [MSTR][ERROR] jdhcpd_request_delete_baseline_stats: libstats delete: failed; error 3, session_id = 252
Feb 27 12:27:18.263284 [MSTR][WARN] [default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_client_delete: Failure (status 2) when deleting baseline stats for sessopm (client index 65787)
Feb 27 12:27:18.263382 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_session_db_client_delete: Logging entry delete to file
Feb 27 12:27:18.264627 [MSTR][DEBUG][default:default][SVR][INET][ae0.2511][SID=252] jdhcpd_persistent_remove_entry_from_file: Entry remove not logged as it is not presistent
Feb 27 12:27:18.266589 [MSTR][DEBUG] jdhcpd_session_db_entry_remove_common: Non-bundled SDB entry successfully deleted for session id 252: status = success (0)
Feb 27 12:27:18.266766 [MSTR][WARN] jdhcpd_offer_delay_client_fsm_retry_queue_process: offer-delay: retry operation is aleady in progress/ no entries to process
Feb 27 12:27:18.267058 [MSTR][WARN] [default:default][SVR][INET][ae0.2511][SID=252] safd_num_clients_bound_dec: NOK:decrementing safd(0x339dc00) bound clients counter for client (0x33ad800)
Feb 27 12:27:18.267192 [MSTR][INFO] jdhcpd_client_unset_pkt: *********** Unsetting v4 packet 0x33a8400
Feb 27 12:27:18.267427 [MSTR][DEBUG] jdhcpd_packet_free: PACKET - Freeing v4 packet 0x33a8400
Thanks and Best Regards,
------------------------------
DUMITRU POPOVICI
------------------------------