Routing
Highlighted
Routing

SVLAN Dynamic subscriber management using local DHCP

‎11-21-2013 03:40 AM

H all

I'm trouble setting up dynamic subscribers on an MX80. I'm using the singe tagged SVLAN model with a local  DHCP server configured on the MX. I'm seeing the VLAN interface, but no demux0 interface,  I'm also not seeing any DHCP IP address - Mac address bindings (I;m using MAC address for username. Any ideas what I'm doing wrong? I've followed the dayone guide to the letter, but being dynamic this is proving tricky to troubleshoot. Please see config & output below.  Any advice or comments would be greatly appreciated.

 

admin@lab-siteA-pe01> show subscribers
Interface           IP Address/VLAN ID                      User Name                      LS:RI
ge-1/0/4.1073741834  100                                                              default:default     

admin@lab-siteA-pe01> show dhcp server binding

admin@lab-siteA-pe01> show dhcp server statistics
Packets dropped:
    Total                      29
    Authentication             29

Messages received:
    BOOTREQUEST                29
    DHCPDECLINE                0
    DHCPDISCOVER               29
    DHCPINFORM                 0
    DHCPRELEASE                0
    DHCPREQUEST                0

Messages sent:
    BOOTREPLY                  0
    DHCPOFFER                  0
    DHCPACK                    0
    DHCPNAK                    0
    DHCPFORCERENEW             0

admin@lab-siteA-pe01>

 

 

Interface auto-configuration:

admin@lab-siteA-pe01> show configuration interfaces ge-1/0/4
description To_SiteA_CE1_fe-0/0/5;
flexible-vlan-tagging;
speed 100m;
auto-configure {
    vlan-ranges {
        dynamic-profile DYNINTF-SVLAN-DHCP-INT {
            accept any;
            ranges {
                any;
            }
        }
    }
}

admin@lab-siteA-pe01> show configuration interfaces lo0
unit 0 {
    family inet {
        address 127.0.0.1/32;
        address 10.150.0.2/32 {
            primary;
            preferred;
        }
        address 10.18.133.1/32;
    }
}





Dynamic VLAN profile config:

admin@lab-siteA-pe01> show configuration dynamic-profiles DYNINTF-SVLAN-DHCP-INT
interfaces {
    "$junos-interface-ifd-name" {
        unit "$junos-interface-unit" {
            demux-source inet;
            proxy-arp restricted;
            vlan-id "$junos-vlan-id";
            family inet {
                unnumbered-address lo0.0 preferred-source-address 10.18.133.1;
            }
        }
    }
}


Dynamic IP profile:

 admin@lab-siteA-pe01> show configuration dynamic-profiles DYNSUB-SVLAN-IPDEMUX
interfaces {
    demux0 {
        unit "$junos-interface-unit" {
            demux-options {
                underlying-interface "$junos-underlying-interface";
            }
            family inet {
                demux-source {
                    $junos-subscriber-ip-address;
                }
            }
        }
    }
}


Bind Dynamic IP Profile via DHCP Group:

admin@lab-siteA-pe01> show configuration system services dhcp-local-server
pool-match-order {
    ip-address-first;
}
authentication {
    username-include {
        mac-address;
    }
}

group local {
    dynamic-profile DYNSUB-SVLAN-IPDEMUX;
    interface ge-1/0/4.0;
}

 

 

 

 

8 REPLIES 8
Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎11-21-2013 06:19 AM

You have authentication enabled for dhcp. Do you have AAA config - I mean radius access profile etc.

Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎11-26-2013 05:35 AM

I have configured access controls as follows, I'm not using Radius.

 

admin@lab-siteA-pe01> show configuration access
profile local {
    authentication-order none;
}
##
## Warning: requires 'subscriber-address-assignment' license
##
address-assignment {
    pool DHCP-subs {
        family inet {
            network 10.18.133.0/24;
            range 1 {
                low 10.18.133.2;
                high 10.18.133.254;
            }
            dhcp-attributes {
                maximum-lease-time 172800;
                router {
                    10.18.133.1;
                }
            }
        }
    }
}


admin@lab-siteA-pe01> show configuration system services dhcp-local-server
traceoptions { ## Warning: 'traceoptions' is deprecated
    file DHCP-logs;
    flag all;
}
pool-match-order {
    ip-address-first;
}
duplicate-clients-on-interface;
authentication {
    username-include {
        mac-address;
    }
}
group local {
    dynamic-profile DYNSUB-SVLAN-IPDEMUX;
    interface ge-1/0/4.0;

 

The DHCP-DISCOVER is being received, but no OFFER is being returned & DHCP fails to complete. We have multiple sessions from the same mac address so "duplicate-clients-on-interface" has been configured. DHCP logs report the following:

 

admin@lab-siteA-pe01> show log DHCP-logs | find "Nov 26 11:11"
Nov 26 11:11:10 ifl-event ge-1/0/4.1073741862, oper add, state up, ifl_index 360, dev_index 146, under_ifl_ifindx 0, link_type 13
Nov 26 11:11:10 ifl ge-1/0/4.1073741862 has vlan tags inner:100 outer:0
Nov 26 11:11:10 ifd-event ge-1/0/4, oper change, state up, dev_index 146
Nov 26 11:11:10 iff-event ge-1/0/4.1073741862, oper add, state up, ifl_index 360, dev_index 146, af 2(INET)
Nov 26 11:11:10 jdhcpd_iffm_handler_idl: RtrCtx: LS:default, RI:default, BD:, AF:INET; IS configured
Nov 26 11:11:10 change_sus_if_addr - Changing if_addr to 10.18.133.1: intf ge-1/0/4.1073741862 (stack 0x2180200); INET safd(0x1f8e700); dhcp_type 0; LSRI default:default
Nov 26 11:11:10 change_sus_if_addr - Cannot change subunit safd's AVL: ge-1/0/4.1073741862 INET safd not in configured list for LSRI default:default; dhcp_type 0; if_addr 10.18.133.1 (new ip_addr 10.18.133.1)
Nov 26 11:11:10 jdhcpd_iffm_first_time_add_unnum_ifa: unnumbered INET iff with pref src addr; iff name ge-1/0/4, sub 1073741862, addr 10.18.133.1
Nov 26 11:11:10 jdhcpd_iffm_handler_idl: (Status=2) Could not find bd index tlv - wait for IFBD iff(ge-1/0/4) msg for ifl(ge-1/0/4)
Nov 26 11:11:10 Composing intf name: full_ifname = ge-1/0/4.0, sizeof(full_ifname) = 60, underlying_ifd->dev_name = no underlying dev_name, su_stack->ifd_ptr->dev_name = ge-1/0/4, found AUTOCONF
Nov 26 11:11:10 jdhcpd_interface_config_find_in_rc: if_name ge-1/0/4.0, rc default:default (0x1f55000), flags 0x4200d
Nov 26 11:11:10 jdhcpd_interface_config_find_in_rc: grp_name local
Nov 26 11:11:10 Interface 'ge-1/0/4.0' found
Nov 26 11:11:10 jdhcpd_interface_config_find_in_rc: FOUND config for ge-1/0/4.0, app 1, rc default:default
Nov 26 11:11:10 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862] safd_if_cfg_set: Set safd(0x1f8e700) if_cfg to 0x1f4d84c (was 0) if_name_cfg to 2120400 (was 0) dhcp_type(1)
Nov 26 11:11:10 rc_entry_sus_add - Adding IFL ge-1/0/4.1073741862 INET safd to LSRI default:default: RC 0x1f55000; dhcp_type 1; su_ifl 0x2180200; subunit flags 0x3
Nov 26 11:11:10 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862] safd_rc_owner_list_insert: Added safd to routing context's configured safd list.
Nov 26 11:11:10 rc_entry_sus_add - Adding IFL ge-1/0/4.1073741862 INET safd to LSRI default:default RC 0x1f55000: safd 0x1f8e700 has if_addr 10.18.133.1
Nov 26 11:11:10 sus_by_ip_addr_add - Added 'subunit by ip-addr' entry 0x2167880, safd 0x1f8e700 for IP ADDR 10.18.133.1 type 1 in routing context LR default/RI default (ref_count 1)
Nov 26 11:11:10 interface ge-1/0/4.0 found cfg, app_type 1- SET CFG
Nov 26 11:11:10 Attempt to restore AUTOCONF intf ge-1/0/4.1073741862
Nov 26 11:11:10 jdhcpd_iffm_handler_idl (check_mirror): about to call mirror_restore_if(full_ifname ge-1/0/4.1073741862) for su_stack session id 0, interface IFl index 360, unit stack 0x2180200
Nov 26 11:11:10 Client restoration STARTING on IF ge-1/0/4.1073741862
Nov 26 11:11:10 NOT found ha_avl_entry_ptr on IF ge-1/0/4.1073741862
Nov 26 11:11:14 [DEBUG] jdhcpd_io_pfe_reader: Entered
Nov 26 11:11:14 [INFO]  jdhcpd_io_pfe_reader: jdhcpd_pfe_pkt_hdr_t: pfe packet 328 bytes: L3ifindex = 360, L2ifindex = 0, dpi_rtbl=0
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] jdhcpd_io_pfe_packet: LOCAL : recv sa 255.255.255.255 da 255.255.255.255, src_port 68, dst_port 67 if name ge-1/0/4.1073741862 len 300
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   from == 0.0.0.0, port == 68 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   size == 300, op == 1 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  flags == 8000 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  htype == 1, hlen == 6 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   hops == 0, xid == 3804823e ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   secs == 0, flags == 8000 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP ciaddr == 0.0.0.0 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP yiaddr == 0.0.0.0 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP siaddr == 0.0.0.0 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP giaddr == 0.0.0.0 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP chaddr == 80 71 1f b9 1a 05 00 00 00 00 00 00 00 00 00 00 ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  sname ==  ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   file ==  ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code  53, len   1, data DHCP-DISCOVER ]--
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code 255, len   0 ]--
Nov 26 11:11:14 cid_l 0 cidp 2 mac 0x80 71 1f b9 1a 5 htype 1 subnet a128501 ifindx 360 key_type 5
Nov 26 11:11:14 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862] jdhcpd_find_client_from_client_pdu: BOOTPREQUEST could not find client table ent
Nov 26 11:11:14 DHCPv4 client entry ADDED, app_type 1 routing context default:default
Nov 26 11:11:14 [DEBUG][default:default][SVR][INET][SID=0] jdhcpd_packet_handle: new client table entry created for ifindex 360
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][SID=0] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_DISCOVER_PDU in state LOCAL_SERVER_STATE_INIT
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=0] jdhcpd_profile_get: Profile_get using regular profile DYNSUB-SVLAN-IPDEMUX
Nov 26 11:11:14 Service_get NO service name
Nov 26 11:11:14 Performance time start for SDB client add
Nov 26 11:11:14 jdhcpd_sdb_create_session: phy device name ge-1/0/4
Nov 26 11:11:14 jdhcpd_sdb_create_session: INET, setting LR name  default
Nov 26 11:11:14 jdhcpd_sdb_create_session: INET, setting RI name  default
Nov 26 11:11:14 jdhcpd_sdb_create_session: INET, sdb username 8071.1fb9.1a05
Nov 26 11:11:14 jdhcpd_sdb_create_session: INET, setting profile name  DYNSUB-SVLAN-IPDEMUX
Nov 26 11:11:14 jdhcpd_sdb_create_session: INET, setting inner vlan_ID 100
Nov 26 11:11:14 jdhcpd_sdb_create_session: INET, setting underlying interface ge-1/0/4.1073741862
Nov 26 11:11:14 jdhcpd_sdb_create_session: INET, setting MAC addr 80:71:1f:b9:1a:05
Nov 26 11:11:14 jdhcpd_session_db_create_v4_session_attributes: INET, setting IP addr Key 10.18.133.1
Nov 26 11:11:14 jdhcpd_session_db_create_v4_session_attributes: INET, dhcp_options len   3, data 35 01 01
Nov 26 11:11:14 jdhcpd_sdb_create_session: session DB create got INET entry id 73
Nov 26 11:11:14 Mirroring disabled (ha_graceful_switchover false) 0.0.0.0
Nov 26 11:11:14 Allocated memory to store in SDB, sizeof(jdhcpd_ha_client_header_t) 88 + total_tlvs_len 70 (sizeof(client->session_id) is 73)
Nov 26 11:11:14 Saved NON-DEMUX interface name ge-1/0/4.1073741862 into mirroring ha_info
Nov 26 11:11:14 Added TLV for DHCPv6 LinkLocal Address, length 16
Nov 26 11:11:14 Successfully saved private data for 0.0.0.0 in SDB, length 158
Nov 26 11:11:14 PERF time for SDB client add add is 0 sec, 18723972 nsec
Nov 26 11:11:14 Performance time start for AUTHD request
Nov 26 11:11:14 jdhcpd_auth_request: auth-request attempt initiated for session 73: flags1:0x20020; flags2:0
Nov 26 11:11:14 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0
Nov 26 11:11:14 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0
Nov 26 11:11:14 Added client w/ session_id 73 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ, to authd_restart_teardown list, count authd_restart_teardown_count 1
Nov 26 11:11:14 using Service-Profile-Name <NULL>
Nov 26 11:11:14 jdhcpd_authenticate_rply_proc: Got reply for auth_request, reply auth_rqst_id = 65585- (session Id 73)
Nov 26 11:11:14 Request to remove client w. session_id 73 in state 1 from authd_restart_teardown list, count authd_restart_teardown_count 1
Nov 26 11:11:14 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count
Nov 26 11:11:14 jdhcpd_authenticate_rply_proc: auth login reply status for session 73: result:1; flags1:0x20020; flags2:0x10
Nov 26 11:11:14 got IP address jdhcpd_session_db_client_info_get 10.18.133.18
Nov 26 11:11:14 got net mask jdhcpd_session_db_client_info_get 255.255.255.0
Nov 26 11:11:14 got ls name jdhcpd_session_db_client_info_get default
Nov 26 11:11:14 got ri name jdhcpd_session_db_client_info_get default
Nov 26 11:11:14 got pool name DHCP-subs, len 9
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ
Nov 26 11:11:14 PERF time for AUTHD request add is 0 sec, 20125134 nsec
Nov 26 11:11:14 Auth request reply ip 10.18.133.18, pool name DHCP-subs
Nov 26 11:11:14 jdhcpd_pool_find: cfg 1f4d400, pool_name 215ec10, DHCP-subs
Nov 26 11:11:14 jdhcpd_pool_find: Pool DHCP-subs  found 0x2184000 w/ cfg container 0x1f4d400
Nov 26 11:11:14 Performance time start for Profile Instantiation
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_profile_request: Add Profile DYNSUB-SVLAN-IPDEMUX request for client in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ
Nov 26 11:11:14 ifl-event demux0.1073741863, oper add, state up, ifl_index 365, dev_index 130, under_ifl_ifindx 360, link_type 3
Nov 26 11:11:14 Demux IFL has session ID 73
Nov 26 11:11:14 jdhcpd_iflm_handler -  demux0.1073741863 (ifindx 365) has underlying interface of ge-1/0/4.1073741862 (ifindx 360)
Nov 26 11:11:14 iff-event demux0.1073741863, oper add, state up, ifl_index 365, dev_index 130, af 2(INET)
Nov 26 11:11:14 jdhcpd_iffm_handler_idl: RtrCtx: LS:default, RI:default, BD:, AF:INET; IS configured
Nov 26 11:11:14 [DEBUG][default:default][SVR][INET][demux0.1073741863] safd_if_cfg_copy: Set safd(0x2183200) if_cfg to 0x1f4d84c (was 0) & dhcp_type(1)
Nov 26 11:11:14 jdhcpd_ip_demux_get_cfg: demux0.1073741863 successfully inherited its INET dhcp_type(1) from its underlying ge-1/0/4.1073741862 INET safd in LSRI default:default
Nov 26 11:11:14 jdhcpd_iffm_handler_idl: (Status=2) Could not find bd index tlv - wait for IFBD iff(demux0) msg for ifl(demux0)
Nov 26 11:11:14 Composing intf name: full_ifname = demux0.0, sizeof(full_ifname) = 60, underlying_ifd->dev_name = ge-1/0/4, su_stack->ifd_ptr->dev_name = demux0, found AUTOCONF
Nov 26 11:11:14 jdhcpd_interface_config_find_in_rc: if_name demux0.0, rc default:default (0x1f55000), flags 0x4200d
Nov 26 11:11:14 jdhcpd_interface_config_find_in_rc: grp_name local
Nov 26 11:11:14 Interface 'demux0.0' not found
Nov 26 11:11:14 inteface demux0.0 DID NOT find cfg
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] proflib_cb_handler: Profile ACK (SUCCESS) - res 0
Nov 26 11:11:14 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] proflib_cb_handler: Config bits from profile:0x3 0 0 0 0 , copied:0x3 0 0 0 0
Nov 26 11:11:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_INST
Nov 26 11:11:14 PERF time for Profile Instantiation add is 0 sec, 116452565 nsec
Nov 26 11:11:14 Got profile instantiate reply 0, updating SDB with client session state 1
Nov 26 11:11:14 jdhcpd_session_db_client_session_state_set: setting session state 1
Nov 26 11:11:14 jdhcpd_session_db_client_session_state_set: setting action bits to 3, config-bits:0x3 0 0 0 0
Nov 26 11:11:14 profile instantiate reply SUCCESS
Nov 26 11:11:14 jdhcpd_session_db_client_interface_get: Got interface name demux0.1073741863 for session 73
Nov 26 11:11:14 Client got new interface demux0.1073741863, unit stack 0x2182400, INET safd 0x2183200
Nov 26 11:11:14 Client gonna go wait for the interface
Nov 26 11:11:14 Performance time start for Interface Create
Nov 26 11:11:14 ifl-event ge-1/0/4.1073741862, oper change, state up, ifl_index 360, dev_index 146, under_ifl_ifindx 0, link_type 13
Nov 26 11:11:14 ifl-event demux0.1073741863, oper change, state up, ifl_index 365, dev_index 130, under_ifl_ifindx 360, link_type 3
Nov 26 11:11:22 [DEBUG] jdhcpd_io_pfe_reader: Entered
Nov 26 11:11:22 [INFO]  jdhcpd_io_pfe_reader: jdhcpd_pfe_pkt_hdr_t: pfe packet 328 bytes: L3ifindex = 360, L2ifindex = 0, dpi_rtbl=0
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] jdhcpd_io_pfe_packet: LOCAL : recv sa 255.255.255.255 da 255.255.255.255, src_port 68, dst_port 67 if name ge-1/0/4.1073741862 len 300
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   from == 0.0.0.0, port == 68 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   size == 300, op == 1 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  flags == 8000 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  htype == 1, hlen == 6 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   hops == 0, xid == 3804823e ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   secs == 0, flags == 8000 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP ciaddr == 0.0.0.0 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP yiaddr == 0.0.0.0 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP siaddr == 0.0.0.0 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP giaddr == 0.0.0.0 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP chaddr == 80 71 1f b9 1a 05 00 00 00 00 00 00 00 00 00 00 ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  sname ==  ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   file ==  ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code  53, len   1, data DHCP-DISCOVER ]--
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code 255, len   0 ]--
Nov 26 11:11:22 cid_l 0 cidp 2 mac 0x80 71 1f b9 1a 5 htype 1 subnet a128501 ifindx 360 key_type 5
Nov 26 11:11:22 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_find_client_from_client_pdu: BOOTPREQUEST found client table entry
Nov 26 11:11:22 [NOTE] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_packet_handle: RECEIVE DISCOVER: incomming_safd 0x1f8e700, demux 0x0, safd 0x1f8e700
Nov 26 11:11:22 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_DISCOVER_PDU in state LOCAL_SERVER_STATE_WAIT_INTERFACE
Nov 26 11:11:24 mgmt command: show dhcp server statistics
Nov 26 11:11:24 Performance details for Server in logical-system default, routing-instance default
Nov 26 11:11:24 Processing details for DISCOVER to OFFER (0 pkts)
Nov 26 11:11:24   SDB client add: Min: 1.127 ms, Max: 20.579 ms, Avg: 2.999 ms
Nov 26 11:11:24   AUTHD request: Min: 1.030 ms, Max: 77.915 ms, Avg: 5.041 ms
Nov 26 11:11:24   Profile Instantiation: Min: 76.047 ms, Max: 234.337 ms, Avg: 29.388 ms
Nov 26 11:11:24   Interface Create: None
Nov 26 11:11:24   Total: None
Nov 26 11:11:24 Processing details for REQUEST to ACK (0 pkts)
Nov 26 11:11:24   AUTHD Profile Activate: None
Nov 26 11:11:24   SDB Active: None
Nov 26 11:11:24   Total: None
Nov 26 11:11:24 mgmt command: show dhcp server statistics [done]
Nov 26 11:11:38 [DEBUG] jdhcpd_io_pfe_reader: Entered
Nov 26 11:11:38 [INFO]  jdhcpd_io_pfe_reader: jdhcpd_pfe_pkt_hdr_t: pfe packet 328 bytes: L3ifindex = 360, L2ifindex = 0, dpi_rtbl=0
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] jdhcpd_io_pfe_packet: LOCAL : recv sa 255.255.255.255 da 255.255.255.255, src_port 68, dst_port 67 if name ge-1/0/4.1073741862 len 300
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   from == 0.0.0.0, port == 68 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   size == 300, op == 1 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  flags == 8000 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  htype == 1, hlen == 6 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   hops == 0, xid == 3804823e ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   secs == 0, flags == 8000 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP ciaddr == 0.0.0.0 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP yiaddr == 0.0.0.0 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP siaddr == 0.0.0.0 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP giaddr == 0.0.0.0 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP chaddr == 80 71 1f b9 1a 05 00 00 00 00 00 00 00 00 00 00 ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  sname ==  ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   file ==  ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code  53, len   1, data DHCP-DISCOVER ]--
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code 255, len   0 ]--
Nov 26 11:11:38 cid_l 0 cidp 2 mac 0x80 71 1f b9 1a 5 htype 1 subnet a128501 ifindx 360 key_type 5
Nov 26 11:11:38 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_find_client_from_client_pdu: BOOTPREQUEST found client table entry
Nov 26 11:11:38 [NOTE] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_packet_handle: RECEIVE DISCOVER: incomming_safd 0x1f8e700, demux 0x0, safd 0x1f8e700
Nov 26 11:11:38 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_DISCOVER_PDU in state LOCAL_SERVER_STATE_WAIT_INTERFACE
Nov 26 11:12:11 [DEBUG] jdhcpd_io_pfe_reader: Entered
Nov 26 11:12:11 [INFO]  jdhcpd_io_pfe_reader: jdhcpd_pfe_pkt_hdr_t: pfe packet 328 bytes: L3ifindex = 360, L2ifindex = 0, dpi_rtbl=0
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] jdhcpd_io_pfe_packet: LOCAL : recv sa 255.255.255.255 da 255.255.255.255, src_port 68, dst_port 67 if name ge-1/0/4.1073741862 len 300
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   from == 0.0.0.0, port == 68 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   size == 300, op == 1 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  flags == 8000 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  htype == 1, hlen == 6 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   hops == 0, xid == 3804823e ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   secs == 0, flags == 8000 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP ciaddr == 0.0.0.0 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP yiaddr == 0.0.0.0 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP siaddr == 0.0.0.0 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP giaddr == 0.0.0.0 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP chaddr == 80 71 1f b9 1a 05 00 00 00 00 00 00 00 00 00 00 ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP  sname ==  ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ DHCP/BOOTP   file ==  ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code  53, len   1, data DHCP-DISCOVER ]--
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862] --[ OPTION code 255, len   0 ]--
Nov 26 11:12:11 cid_l 0 cidp 2 mac 0x80 71 1f b9 1a 5 htype 1 subnet a128501 ifindx 360 key_type 5
Nov 26 11:12:11 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_find_client_from_client_pdu: BOOTPREQUEST found client table entry
Nov 26 11:12:11 [NOTE] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_packet_handle: RECEIVE DISCOVER: incomming_safd 0x1f8e700, demux 0x0, safd 0x1f8e700
Nov 26 11:12:11 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_DISCOVER_PDU in state LOCAL_SERVER_STATE_WAIT_INTERFACE
Nov 26 11:14:14 Client 80-71-1f-b9-1a-05 stale timer expired
Nov 26 11:14:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_DELETE in state LOCAL_SERVER_STATE_WAIT_INTERFACE
Nov 26 11:14:14 jdhcpd_auth_release: auth logout initiated for session 73 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20020; flags2:0x10
Nov 26 11:14:14 jdhcpd_auth_release_common: Release authd (request user logout): updating SDB with client session state SDB_SESSION_STATE_TERMINATING
Nov 26 11:14:14 jdhcpd_session_db_client_session_state_set: setting session state 3
Nov 26 11:14:14 jdhcpd_auth_release_common: ISSU logout for client session id 73, decrement global in-flight logins (count is 0)
Nov 26 11:14:14 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0
Nov 26 11:14:14 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0
Nov 26 11:14:14 Added client w/ session_id 73 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE, to authd_restart_teardown list, count authd_restart_teardown_count 1
Nov 26 11:14:14 jdhcpd_auth_release_common: auth logout requested for session 73 in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE: flags1:0x20; flags2:0x10
Nov 26 11:14:14 jdhcpd_user_logout_rply_proc: Got reply for user_logout, reply rqst_id = 65585 (session Id 73)
Nov 26 11:14:14 Get SDB STATE for session Id 73
Nov 26 11:14:14 Got SDB SESSION STATE 3 for client session Id 73
Nov 26 11:14:14 jdhcpd_user_logout_rply_proc: Got authd reply for user_logout in SDB state TERMINATING, for client 10.18.133.18, client session Id 73
Nov 26 11:14:14 Request to remove client w. session_id 73 in state 4 from authd_restart_teardown list, count authd_restart_teardown_count 1
Nov 26 11:14:14 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count
Nov 26 11:14:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_AUTH_REQ_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE
Nov 26 11:14:14 In state LOCAL_SERVER_STATE_WAIT_SDB_TERMINATED_MIRROR_REQ: starting updating SDB with client session state SDB_SESSION_STATE_TERMINATED
Nov 26 11:14:14 In client state LOCAL_SERVER_STATE_WAIT_SDB_TERMINATED_MIRROR_REQ: updating SDB with client session state SDB_SESSION_STATE_TERMINATED
Nov 26 11:14:14 jdhcpd_session_db_client_session_state_set: setting session state 4
Nov 26 11:14:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_CLIENT_MIRROR_ACK in state LOCAL_SERVER_STATE_WAIT_CM_DELETE
Nov 26 11:14:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] jdhcpd_profile_request: Delete Profile DYNSUB-SVLAN-IPDEMUX request for client in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE
Nov 26 11:14:14 iff-event demux0.1073741863, oper delete, state up, ifl_index 365, dev_index 130, af 2(INET)
Nov 26 11:14:14 jdhcpd_safd_deconfigure_start: remove su_stack 0x2182400 INET safd 0x2183200 from rc 0x1f55000
Nov 26 11:14:14 rc_entry_sus_remove: Warning - subunit demux0.1073741863 INET safd not in list:  if_addr 0.0.0.0, dhcp_type 0
Nov 26 11:14:14 jdhcpd_safd_deconfigure_start: Subunit 0x2182400 INET safd 0x2183200 deconfigure start for rc_ptr 0x1f55000, intf demux0, unit 1073741863, ifindex 365, cfg FALSE, flags 0x10
Nov 26 11:14:14 jdhcpd_safd_deconfigure_event: Subunit 0x2182400 INET safd 0x2183200 deconfigure event for intf demux0 unit 1073741863, ifindex 365, rc_ptr 0x1f55000
Nov 26 11:14:14 jdhcpd_safd_deconfigure_event: INET safd 0x2183200 deconfigure done, safd being deleted
Nov 26 11:14:14 jdhcpd_sus_deconfigure_cleanup: Subunit 0x2182400 for intf demux0 unit 1073741863 ifindex 365: stack still present
Nov 26 11:14:14 ifl-event demux0.1073741863, oper delete, state up, ifl_index 365, dev_index 130, under_ifl_ifindx 0, link_type 0
Nov 26 11:14:14 jdhcpd_sus_deconfigure_start: Subunit 0x2182400 deconfigure start for intf demux0 unit 1073741863, ifindex 0, flags 0x4
Nov 26 11:14:14 jdhcpd_sus_deconfigure_event: Subunit 0x2182400 deconfigure event for intf demux0 unit 1073741863 ifindex 0
Nov 26 11:14:14 jdhcpd_sus_deconfigure_cleanup: Deleting subunit 0x2182400 for intf demux0 unit 1073741863 ifindex 0
Nov 26 11:14:14 sus_entry_delete: demux0.1073741863 su_stack 0, index 0 flags 0x1f3e000 is being deleted
Nov 26 11:14:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] proflib_cb_handler: Profile ACK (SUCCESS) - res 0
Nov 26 11:14:14 [DEBUG][default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] proflib_cb_handler: Config bits from profile:0x3 0 0 0 0 , copied:0x3 0 0 0 0
Nov 26 11:14:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_PROF_ACK in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE
Nov 26 11:14:14 In state LOCAL_SERVER_STATE_WAIT_PROF_DELETE got CLIENT_EVENT_PROF_ACK, proceed with the user-terminated handshake
Nov 26 11:14:14 jdhcpd_auth_release_terminated: auth terminate initiated for session 73: flags1:0x20; flags2:0x10
Nov 26 11:14:14 Before adding to teardown list, jdhcpd_inst.authd_restart_teardown_count 0
Nov 26 11:14:14 LIST IS EMPTY, jdhcpd_inst.authd_restart_teardown_count 0
Nov 26 11:14:14 Added client w/ session_id 73 in state LOCAL_SERVER_STATE_WAIT_PROF_DELETE, to authd_restart_teardown list, count authd_restart_teardown_count 1
Nov 26 11:14:14 jdhcpd_auth_release_terminated_common: auth terminate request for session 73: flags1:0x20; flags2:0x10
Nov 26 11:14:14 jdhcpd_user_terminated_rply_proc: Got user-session terminated REPLY from authd- reqId 65585, for client session Id 73
Nov 26 11:14:14 Request to remove client w. session_id 73 in state 5 from authd_restart_teardown list, count authd_restart_teardown_count 1
Nov 26 11:14:14 Removed LAST client from authd_restart teardown list, zero out COUNT authd_restart_teardown_count
Nov 26 11:14:14 [INFO] [default:default][SVR][INET][ge-1/0/4.1073741862][SID=73] JDHCPD_CLIENT_EVENT: Client got event CLIENT_EVENT_AUTH_TERMINATED_ACK in state LOCAL_SERVER_STATE_WAIT_AUTH_REQ_RELEASE_TERMINATED
Nov 26 11:14:14 ATTEMPT TO DELETE libstats; session_id = 73

Nov 26 11:14:14 libstats delete stats: passed session_id 73

Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎11-26-2013 06:21 AM

Hi,

 

maybe:

 

"

admin@lab-siteA-pe01> show configuration access
profile local {
    authentication-order none;
}
...

"

 

and

 

"

admin@lab-siteA-pe01> show configuration system services dhcp-local-server ...

authentication {    

  username-include {        

    mac-address;

  }

}

"

 

don´t work well together. Have you tried removing auth from the dhcp-LS config?

 

Best Regards

 

Ulf

--
If this worked for you please flag my post as an 'Accepted Solution' so others can benefit. A kudo would be cool if you think I earned it.
Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎11-26-2013 08:35 AM

Hi Ulf

Thanks for your fast response. I tried this but still not progressing beyond state "selecting". I've been using the following a a giuide for configuration

 

http://forums.juniper.net/jnet/attachments/jnet/Day1Books/155/1/DO_DynamicSubscriberMgmt.pdf

 

Any suggestions would be welcome.

 

Thanks

 

 

Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎11-26-2013 08:54 AM

Hi,

 

hm, I´m nearly stuck. Two things:

 

- have you done:

 

"

[edit]

admin@lab-siteA-pe01# set access-profile local

"

 

- can you please enable traceoptions as suggested on pages 26/27 of the day one guide and share all files generated?

 

 

--
If this worked for you please flag my post as an 'Accepted Solution' so others can benefit. A kudo would be cool if you think I earned it.
Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎12-02-2013 04:27 AM

Hi. Yes I have enabled access profile local.

 

I have attached the logs generated wth DHCP traceoptions enabled. An authentication request seems to be intitated by the server & it is waiting a reponse despite the fact that auth order none is configured. Could this be the problm? Please see DHCP logs attached.

 

This is a lab router rather than a production box & we are currently using the 30 day trial license to test config and we are within the 30 day test period. Should full funstionality be allowed on the trial license or could this be what is stopping DHCP from completing?

 

admin@lab-siteA-pe01> show system license
License usage:
                                 Licenses     Licenses    Licenses    Expiry
  Feature name                       used    installed      needed
  subscriber-authentication             1            0           1    10 days
  subscriber-address-assignment         1            0           1    19 days
  scale-subscriber                      0         1000           0    permanent
  scale-l2tp                            0         1000           0    permanent
  scale-mobile-ip                       0         1000           0    permanent

Licenses installed: none

No OFFER being made by the server

 

admin@lab-siteA-pe01> show dhcp server statistics
Packets dropped:
    Total                      33
    Authentication             33

Messages received:
    BOOTREQUEST                162
    DHCPDECLINE                0
    DHCPDISCOVER               162
    DHCPINFORM                 0
    DHCPRELEASE                0
    DHCPREQUEST                0

Messages sent:
    BOOTREPLY                  0
    DHCPOFFER                  0
    DHCPACK                    0
    DHCPNAK                    0
    DHCPFORCERENEW             0

 

DHCP server allocates an IP address byt state doesn't complete and stays "selecting" state & demox interface gets torn down.

 

admin@lab-siteA-pe01> show subscribers
Interface           IP Address/VLAN ID                      User Name                      LS:RI
ge-1/0/4.1073741868  100                                                              default:default
demux0.1073741869   10.18.133.22                            8071.1fb9.1a05            default:default

admin@lab-siteA-pe01> show dhcp server binding

IP address        Session Id  Hardware address   Expires     State      Interface
10.18.133.22      79          80:71:1f:b9:1a:05  172695      SELECTING  ge-1/0/4.1073741868

 

Attachments

Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎12-02-2013 07:00 AM

Hello again

On researching this issue I came across a known problem  resolved in 12.1 (PR 93267]) where the DHCP offer contains the incorrect MAC address. We are running 11.4. Could this be the issue causing DHCP to stay in select state or would we expect to see a DHCP OFFER message in the DHCP log file?

 

Thanks

 

 

Highlighted
Routing

Re: SVLAN Dynamic subscriber management using local DHCP

‎12-05-2013 04:41 AM

Hi,

 

- trial-license shouldn´t interfere here

 

- you´ve only attached the dhcp-logs, but not the (general)auth-logs

 

- the PR (number has a typo) seems to suggest that an OFFER is at least being prepared which is not happening in your case, so I´d say it´s unrelated

 

- which 11.4 are you using? Latest 11.4X27 from http://kb.juniper.net/InfoCenter/index?page=content&id=TSB16098

 

- did you already try to remove auth from the dhcp-LS config? (Yes, that´s not what the day-one-books says, but it´s still somewhat odd)

 

Best Regards

 

Ulf

--
If this worked for you please flag my post as an 'Accepted Solution' so others can benefit. A kudo would be cool if you think I earned it.