Junos
Highlighted
Junos

JunOS 17.4R2-S1.2 PPPoE PWHT Issues

‎01-02-2019 05:19 PM

I am trying to get subs online using PWHT on an MX204 running 17.4R2-S1.2.  The subs authenticate via RADIUS successfully and begin to get an IP from the MX, but then something goes wrong and the sessions tears down.  I cannot identify what is breaking.

 

# show dynamic-profiles
pppoe-profile {
    interfaces {
        pp0 {
            unit "$junos-interface-unit" {
                ppp-options {
                    chap;
                    pap;
                    ipcp-suggest-dns-option;
                }
                pppoe-options {
                    underlying-interface "$junos-underlying-interface";
                    server;
                }
                keepalives interval 30;
                family inet {
                    rpf-check;
                    tcp-mss 1460;
                    filter {
                        input "$junos-input-filter";
                    }
                    unnumbered-address lo0.0;
                }
            }
        }
    }
    class-of-service {
        traffic-control-profiles {
            tcp-dynamic {
                shaping-rate "$junos-cos-shaping-rate" burst-size "$junos-cos-shaping-rate-burst";
                excess-rate proportion 0;
            }
        }
        interfaces {
            pp0 {
                unit "$junos-interface-unit" {
                    output-traffic-control-profile tcp-dynamic;
                }
            }
        }
    }
    routing-options {
        access {
            route $junos-framed-route-ip-address-prefix {
                qualified-next-hop "$junos-interface-name";
            }
        }
    }
}
dual-vlan-prof {
    interfaces {
        "$junos-interface-ifd-name" {
            unit "$junos-interface-unit" {
                no-traps;
                vlan-tags outer "$junos-stacked-vlan-id" inner "$junos-vlan-id";
                family pppoe {
                    duplicate-protection;
                    dynamic-profile pppoe-profile;
                    short-cycle-protection {
                        lockout-time-max 60;
                    }
                }
            }
        }
    }
}
single-vlan-prof {
    interfaces {
        "$junos-interface-ifd-name" {
            unit "$junos-interface-unit" {
                vlan-id "$junos-vlan-id";
                family pppoe {
                    duplicate-protection;
                    dynamic-profile pppoe-profile;
                    short-cycle-protection {
                        lockout-time-max 60;
                    }
                }
            }
        }
    }
}

# show interfaces ps0
apply-groups PWHT-PPPOE;
description TRNGTNWY-SHORT;
anchor-point {
    lt-0/1/0;
}

 

# show groups
PWHT-PPPOE {
    interfaces {
        <ps*> {
            flexible-vlan-tagging;
            auto-configure {
                vlan-ranges {
                    dynamic-profile single-vlan-prof {
                        accept pppoe;
                        ranges {
                            2-4094;
                        }
                    }
                    access-profile aaa-profile;
                }
                remove-when-no-subscribers;
            }
            mtu 9100;
            no-gratuitous-arp-request;
            unit 0 {
                encapsulation ethernet-ccc;
            }
        }
    }
}

 

This is the log from the general-auth daemon:

 

Jan  3 09:13:17.027898 IPV4 ADDRESS ALLOC begin
Jan  3 09:13:17.027905 Just get the first pool with addresses
Jan  3 09:13:17.027913 NetworkMatch: Found a pool DNVR-POOL1
Jan  3 09:13:17.027920 NetworkMatch: calling getAddress for pool 'DNVR-POOL1'
Jan  3 09:13:17.027927 No host is found
Jan  3 09:13:17.027942 Searching for available address in range 1, low=72.55.210.0, high=72.55.211.255, next=72.55.210.205 session-id:1186
Jan  3 09:13:17.027953 IPV6 ADDRESS ALLOC begin
Jan  3 09:13:17.027959 IPV6 PREFIX ALLOC begin
Jan  3 09:13:17.027964  ****************** END-NetworkMatch *********************
Jan  3 09:13:17.027970 DUMP of all addressRequest fields for subscriber session-id:1186 router default:default
Jan  3 09:13:17.027979       client type jpppd-client client type 64 mac address C0:FF:D4:A2:72:C0
Jan  3 09:13:17.027988       REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null
Jan  3 09:13:17.027998       V4NA: req: yes pool: DNVR-POOL1 address: 72.55.210.205
Jan  3 09:13:17.028005       V6NA: req: no pool: NULL address: null
Jan  3 09:13:17.028013       V6PD: req: no pool: NULL prefix: null/0
Jan  3 09:13:17.028024       V6NDRA: req: no pool: NULL ndra prefix: null/0
Jan  3 09:13:17.028030  *********************************************************
Jan  3 09:13:17.028036 Done processing rules
Jan  3 09:13:17.028047 Pool::addressAssign: pool DNVR-POOL1 addr 72.55.210.205 range 72.55.210.0 session-id:1186
Jan  3 09:13:17.028061 Pool::addressAssign: pool DNVR-POOL1 addr 72.55.210.205 range 72.55.210.0 returning <Success:authd class=3, code=0> session-id:1186
Jan  3 09:13:17.028077 Trying to assign address 72.55.210.205 to subscriber session-id:1186
Jan  3 09:13:17.028116 Inserting address 72.55.210.205 for session-id:1186 into pool DNVR-POOL1
Jan  3 09:13:17.028134 Finding a client snapshot session-id:1186
Jan  3 09:13:17.028164 Result have been returned with opcode=0, result=2
Jan  3 09:13:17.028170  ************* Results of Address Allocation *************
Jan  3 09:13:17.028177 DUMP of all addressRequest fields for subscriber session-id:1186 router default:default
Jan  3 09:13:17.028186       client type jpppd-client client type 64 mac address C0:FF:D4:A2:72:C0
Jan  3 09:13:17.028196       REQUESTING: OldStyle 0 OldStyleFilled 1 hint null null network 255.255.255.254 null
Jan  3 09:13:17.028204       Framed-Pool-->SDB_USER_IP_POOL 'DNVR-POOL1' used for V4NA
Jan  3 09:13:17.028213       V4NA: req: yes pool: DNVR-POOL1 address: 72.55.210.205
Jan  3 09:13:17.028220       V6NA: req: no pool: NULL address: null
Jan  3 09:13:17.028229       V6PD: req: no pool: NULL prefix: null/0
Jan  3 09:13:17.028237       V6NDRA: req: no pool: NULL ndra prefix: null/0
Jan  3 09:13:17.028243  *********************************************************
Jan  3 09:13:17.028257 AuthFsm::current state=AuthStart(1) event=2 astEntry=0xf41889c aaa msg=0x9a0d76c session-id:1186
Jan  3 09:13:17.028264 Auth-FSM: Process Auth-Response for session-id:1186 and client type broadband
Jan  3 09:13:17.028271 createDynamicRequest: (2) received
Jan  3 09:13:17.028282 CoARequest CTOR 0x0x9bdcb74
Jan  3 09:13:17.028289 createDynamicRequest: isBulkCoaRequest 0
Jan  3 09:13:17.028300 ServiceAtLoginRequest::validateRequest
Jan  3 09:13:17.028310 Framework: auth result is 1. Performing post-auth operations
Jan  3 09:13:17.028317 Found a Session Timeout value: 43200  passing it into the Accounting Module
Jan  3 09:13:17.028323 Found a Idle Timeout value: 1800  passing it into the Accounting Module
Jan  3 09:13:17.028329 Set Idle Timeout Ingress Only: FALSE
Jan  3 09:13:17.028336 Framework: result is 1.
Jan  3 09:13:17.028344 SEQ SendClientMsg:jpppd-client session-id:1186 reply-code=1 (OK), result-subopcode=1 (ACCESS_OK), cookie=653, rply_len=28, num_tlv_blocks=0
Jan  3 09:13:17.028355 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x9a118ac
Jan  3 09:13:17.028363 ###################################################################
Jan  3 09:13:17.028369 ######################### AUTH REQ ACK SENT #######################
Jan  3 09:13:17.028374 ###################################################################
Jan  3 09:13:17.028384 Auth-FSM: GRES-Mirror for session-id:1186 state:AuthClntRespWait(4)
Jan  3 09:13:17.028390 doPersistedDataUpdates
Jan  3 09:13:17.028396 persistOnlyPrivateData m_inFlight
Jan  3 09:13:17.308448 Process/Dispatch Client Message
Jan  3 09:13:17.308475 New Process/Dispatch Client Message
Jan  3 09:13:17.308489 authd_auth_aaa_msg_create: num_of_tlvs:2 tot_num_of_tlv:2
Jan  3 09:13:17.308497 authd_auth_aaa_msg_create username:() profile:()
Jan  3 09:13:17.308504 Process Request
Jan  3 09:13:17.308511 SEQ RecvClientMsg:jpppd-client session-id:1186 Opcode:3, Subcode:15 (SESSION_LOGOUT)
Jan  3 09:13:17.308521 Setting terminate ID to 100c2
Jan  3 09:13:17.308540 Decoding incoming attributes
Jan  3 09:13:17.308547 Begin to logout Subscriber
Jan  3 09:13:17.308560 Received subscriber logout request session-id:1186
Jan  3 09:13:17.308568 subscriberLogout session-id:1186
Jan  3 09:13:17.308579 Releasing addressEntry for address 72.55.210.205 session-id:1186
Jan  3 09:13:17.308597 ###################################################################
Jan  3 09:13:17.308613 ############################ LOGOUT RCVD ##########################
Jan  3 09:13:17.308619 ###################################################################
Jan  3 09:13:17.308628 AuthFsm::current state=AuthClntRespWait(4) event=8 astEntry=0xf41889c aaa msg=0x9a118ac session-id:1186
Jan  3 09:13:17.308635 Auth-FSM: Posting a Logout-Ack to the client daemon for session-id:1186
Jan  3 09:13:17.308652 clearDynamicConfigLists: numRequests 0
Jan  3 09:13:17.308659 ~CoARequest 0x0x9bdcb74
Jan  3 09:13:17.308665 cleanServiceList: numRequests 0
Jan  3 09:13:17.308672 ~DynamicRequestEntry 0x0x9bdcb74
Jan  3 09:13:17.308681 ****astEntry:0xf41889c aaaMsg:0x9a118ac replyOpcode:1 replySubOpcode:16 replyStatus:1
Jan  3 09:13:17.308691 SEQ SendClientMsg:jpppd-client session-id:1186 reply-code=1 (OK), result-subopcode=16 (SESSION_LOGOUT_ACK), cookie=654, rply_len=28, num_tlv_blocks=0
Jan  3 09:13:17.308704 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x9a0d76c
Jan  3 09:13:17.308712 ###################################################################
Jan  3 09:13:17.308718 ####################### LOGOUT ACK SENT ########################
Jan  3 09:13:17.308723 ###################################################################
Jan  3 09:13:17.308750 Only start time found for session-id:1186
Jan  3 09:13:17.308760 Delete session-id:1186
Jan  3 09:13:17.308767 Begin to logout Subscriber
Jan  3 09:13:17.308773 subscriberLogout session-id:1186
Jan  3 09:13:17.308787 UserAccess:user123@domain.com session-id:1186 state:log-out ps8.3221225809:100 reason: ppp subscriber-mgr-activation-failed
Jan  3 09:13:17.609770 Process/Dispatch Client Message
Jan  3 09:13:17.609794 New Process/Dispatch Client Message
Jan  3 09:13:17.609804 authd_auth_aaa_msg_create: num_of_tlvs:0 tot_num_of_tlv:0
Jan  3 09:13:17.609811 authd_auth_aaa_msg_create username:() profile:()
Jan  3 09:13:17.609818 Process Request
Jan  3 09:13:17.609825 SEQ RecvClientMsg:jpppd-client session-id:1186 Opcode:1, Subcode:17 (CLIENT_SESSION_CLEANUP_REQ)
Jan  3 09:13:17.609833 findSession AST-Table couldn't find the session-id:1186
Jan  3 09:13:17.609839 lookup_subscriber_session_entry Failed to get ASTEntry for session-id:1186
Jan  3 09:13:17.609846 Pending ACCT Stop Table couldn't find session-id:1186
Jan  3 09:13:17.609852 ###################################################################
Jan  3 09:13:17.609858 ################ TERMINATE-REQ RCVD AFTER CLEANUP #################
Jan  3 09:13:17.609863 ###################################################################
Jan  3 09:13:17.609870 SEQ SendClientMsg:jpppd-client session-id:1186 reply-code=1 (OK), result-subopcode=18 (CLIENT_SESSION_CLEANUP_ACK), cookie=655, rply_len=28, num_tlv_blocks=0
Jan  3 09:13:17.609882 authd_auth_aaa_msg_destruct auth_aaa_msg: 0x9a118ac
Jan  3 09:13:17.609890 ###################################################################
Jan  3 09:13:17.609896 ########## TERMINATE-REQ-ACK SENT (FAKE - AFTER CLEANUP) ##########
Jan  3 09:13:17.609901 ###################################################################

 

Most interesting being " UserAccess:user123@domain.com session-id:1186 state:log-out ps8.3221225809:100 reason: ppp subscriber-mgr-activation-failed"

 

 

 

In the SMG log, I am getting the following type of output over and over:

 

Jan  3 09:14:52 bbe_if_arp_pkt_handler:1769 IFF for interface ae1.3221225472 not found
Jan  3 09:14:52  2 PppoeBbePlugin::IFL ps8.3221225861 key = 864576206 , id = 1483
Jan  3 09:14:52 1 PppoeBbePlugin::IFL pp0.3221225862 key = 3184548676 , id = 1485 lower_id = 0 update_Result = 1483
Jan  3 09:14:52 bbe_if_arp_pkt_handler:1769 IFF for interface ps8.3221225861 not found
Jan  3 09:14:52 bbe_route_add_framed_config:1108 framed_dprof db entry pppoe-profile, af 2
Jan  3 09:14:52 ERR: bbe_route_dprof_create_framed_full_config: dprof_get_string FAILED for IPV4 route prefix pppoe-profile error 17
Jan  3 09:14:52 bbe_route_add_framed_config:1247 Not found framed_config structure for ifl pp0.3221225862:509 af 2
Jan  3 09:14:52 dprof_get_service_flag: No SDB_SERVICE_INFO_FLAGS for service session_id=1485, err=-7
Jan  3 09:14:52 dprof_response_handler: Required service flag session_id=1485
Jan  3 09:14:52 ERR: dprof_respond_to_client: Sending NACK profile response for: "pppoe-profile" to plugin: Central, req id: 10954, result 0, err=0x06010001
Jan  3 09:14:52 bbe_route_framed_cleanup: Failed to find framed_config structure for ifl pp0.3221225862:509
Jan  3 09:14:52 PppoeBbePlugin::processIflNotification: Unknown notification notifyAction = 7
Jan  3 09:14:53  2 PppoeBbePlugin::IFL ps8.3221225863 key = 864576208 , id = 1486

 

 

Most interesting being the "ERR: bbe_route_dprof_create_framed_full_config: dprof_get_string FAILED for IPV4 route prefix pppoe-profile error 17"

 

 

My RADIUS server is returning these extra VSAs:

 

           Jnpr-CoS-Parameter-Type:0 = "T02 100m",
           Jnpr-CoS-Parameter-Type:0 = "T12 64k",
           Unisphere-Ingress-Policy-Name = "5M_IN",

 

 

This is working fine on several other MX BNGs....

 

What can I do to properly idenitfy what the actual issue is?

6 REPLIES 6
Highlighted
Junos

Re: JunOS 17.4R2-S1.2 PPPoE PWHT Issues

‎01-02-2019 06:18 PM

HI,

 

Have you enabled inline tunnel service ?

can you get #show configuration chassis

 

 

/Karan Dhanak
Highlighted
Junos

Re: JunOS 17.4R2-S1.2 PPPoE PWHT Issues

‎01-02-2019 06:43 PM

# show chassis
aggregated-devices {
    ethernet {
        device-count 4;
    }
}
pseudowire-service {
    device-count 1024;
}
fpc 0 {
    pic 1 {
        tunnel-services {
            bandwidth 20g;
        }
    }
}
alarm {
    management-ethernet {
        link-down ignore;
    }
}
network-services enhanced-ip;

Highlighted
Junos

Re: JunOS 17.4R2-S1.2 PPPoE PWHT Issues

‎01-02-2019 06:49 PM

I also have PPPoE configured on a physical interface and there are about 60 customers that are using it:

 

# show interfaces ae1
description QFX-SOUTH-LAG;
hierarchical-scheduler;
flexible-vlan-tagging;
auto-configure {
    vlan-ranges {
        dynamic-profile single-vlan-prof {
            accept pppoe;
            ranges {
                300-305;
            }
        }
        access-profile aaa-profile;
    }
}

 

This works perfectly fine and it uses the same profiles as the PWHT-PPPOE is.  So it seems just the PWHT PPPoEs are not working...I see the subs in "show subscribers" for a second, then they disappear.  Something isn't checking out during session initiaization and I just can't figure out how to identify what that is...

Highlighted
Junos

Re: JunOS 17.4R2-S1.2 PPPoE PWHT Issues

‎01-02-2019 07:44 PM

I believe I found the issue.  I was missing "hierarchical-scheduler implicit-hierarchy" under lt-0/1/0.

Highlighted
Junos

Re: JunOS 17.4R2-S1.2 PPPoE PWHT Issues

‎01-02-2019 08:12 PM

 

Thats great; I was about to load your configuration onto my box. I think i dont have to now, cheers.

 

 

 

 

 

/Karan Dhanak
Highlighted
Junos

Re: JunOS 17.4R2-S1.2 PPPoE PWHT Issues

‎01-02-2019 08:49 PM
Well thank you for your dedication!
Feedback