Guest

Virtual Private Dialup Network (VPDN)

L2TP Load Balancing and Failover with Multilink PPP

Hierarchical Navigation

Document ID: 23982

Updated: Feb 04, 2010

   Download PDF
   Print

Introduction

This document describes the functionality of using load balancing and failover with multilink Point-to-Point Protocol (PPP) on Layer 2 Tunneling Protocol (L2TP).

Prerequisites

Requirements

Readers of this document should have knowledge of these topics:

  • virtual private dial-up network (VPDN)

  • L2TP

  • PPP

  • PPP Multilink

Components Used

This document is not restricted to specific software and hardware versions.

The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, make sure that you understand the potential impact of any command.

Conventions

For more information on document conventions, refer to the Cisco Technical Tips Conventions.

Background

Multilink PPP allows the splitting, recombining and sequencing of datagrams when running across multiple simultaneous PPP links. On the transmit end, Multilink PPP provides for the fragmentation of a single packet into multiple packets to be transmitted across multiple PPP links. On the receive end, Multilink PPP provides packet reassemble from multiple PPP links back into its original packet. To negotiate Multilink, both peers must agree that they are Multilink-capable, that is, able to combine multiple physical links into a single logical link (often referred to as a 'bundle'). The link control protocol (LCP) option used to indicate that the peer is Multilink enabled is the Max-Receive-Reconstructed-Unit (MRRU).

The table below shows Cisco IOS® software debug output from two Multilink-enabled devices during the final stages of LCP negotiation. As you can see, both send CONFACKS containing the MRRU option indicating that Multilink will be used during this PPP session. The endpoint discriminator is also included, although it is not necessary to do so.

Note: The Endpoint discriminator can be used in the naming of the Multilink Bundle, although the default Cisco IOS software behavior is to use the authenticated username only.

23982a.bmp

If you encounter the situation where the L2TP access concentrator (LAC) has used load balancing and tunnelled the Multilink peer's B channels to multiple tunnel end-points, you see per-LNS instances of the Multilink bundle master interface. The peer starts to fragment packets and send these simultaneously over the member links. Each LNS receives fragments and attempts to recombine, sequencing fails and lost fragments are reported. As a result, no data can be passed. In these circumstances, there is a requirement to notify other LNSs involved in the load balancing about the status of Multilink users who are connected. To do this, the LNS needs to be placed into a Multichassis Multilink PPP (MMP) 'Stack Group'. The MMP capability is based on the Stack Group Bidding Protocol (SGBP) and Level 2 Forwarding (L2F) protocols to offer and bid for ownership of Multilink calls prior to the call being accepted. The vpdn multihop command is required to allow the packets generated from the remote host to traverse more than one tunnel.

When the LNS receives a Multilink call prior to completing authentication, the username of the remote (that is the Cisco IOS software default naming for the Multilink bundle name) is passed on to SGBP. SGBP provides a mechanism for querying for existing ownership of a call within the stack group. If the stack group member who accepts the call is not the existing owner, SGBP uses a bidding process to resolve ownership with the other members of the stack. Bidding is for a particular user, not the individual connection. By default, the stack group member that receives the first call always wins the bidding process and controls ownership of all subsequent calls from that user. This is regardless of the terminating LNS (by configuration, it is possible to change the behavior of the SGBP bidding process, to influence who will win the bidding process and own the call). When all calls from the user are disconnected, the master ownership is relinquished. A new call from the same user starts the bidding process again with the resolution of a new master.

Load Balancing with Multilink PPP Connection Sequence

  1. A remote SoHo user '2500-1' places a Multilink call, single channel, into the LAC. A PPP link is established.

  2. LCP is negotiated (MRRUs are included in the CONFACKS) and tunnel information downloaded from RADIUS with the tunnel endpoints to be used in the load balancing.

    Tunnel endpoint '10.51.6.59' is selected as the first non-active address and the connection is forwarded. The tunnel and session are established.

  3. LNS creates virtual-access interface 2 to terminate the L2TP tunnel. ·

    Only the commands starting with ppp, keepalive, mtu, logging and default are copied from the virtual-template. Virtual-template 1 has ppp multilink configured. The LCP configuration information delivered in the ICCN is forced onto the Virtual-Access interface PPP stack (this includes the LAC negotiated MRRU).

  4. The LNS uses the proxy authentication response AVP - 33, delivered in the ICCN, to start the SGBP bidding process for any existing multilink bundles with the name '2500-1'.

    A mastership query open bid is sent for the bundle '2500-1' with the default seed bid of 50. ·

    SGBP member '10.51.6.61' replies with a mastership bid of 0 (mastership is declined) as there is not an existing bundle for '2500-1'. ·

    '10.51.6.59' (local) is now master for '2500-1'. A mastership query close is sent, with the mastership bid claim value of 10000 once resolution of ownership is complete.

  5. AAA/PPP authentication and authorization then takes place. A RADIUS access-request is sent.

  6. Virtual-access interface 1 is created for the multilink bundle master and is cloned from the virtual-template 1.

  7. PPP IPCP negotiation completes and is declared OPEN, a host route is installed. The remote user is now connected, and traffic flow can commence.

  8. Due to bandwidth requirements, the remote SoHo user '2500-1' places a second multilink call to the LAC.

  9. RADIUS is again queried for tunnel information. As per load balancing logic, the next non-active tunnel endpoint '10.51.6.61' is selected. The tunnel and session are established.

  10. LNS creates virtual-access interface 1 to terminate the L2TP tunnel. ·

    Virtual-template 1 is used to clone (has 'ppp multilink' configured), the LCP configuration information delivered in the ICCN is forced onto the virtual-access interface PPP stack (this includes the LAC negotiated MRRU).

  11. SGBP bidding is started for any existing Multilink Bundles with the name '2500-1' by sending a mastership query bid for the bundle '2500-1' with the default seed bid of 50.

  12. As'10.51.6.59' is already master for '2500-1' the membership bid has a claim value of 10000. ·

    '10.51.6.61' now forwards the PPP connection to '10.51.6.59'.

    An L2F tunnel is opened from '10.51.6.61' to '10.51.6.59' (the default tunneling protocol for Multichassis Multilink PPP is L2F).

    The tunnel is authenticated using the SGBP group username 'MULTIHOP'. The L2F tunnel and session are opened.

  13. The PPP session is L2F forwarded to '10.51.6.59'. Virtual-access interface 3 is created to terminate the L2F tunnel and is cloned from virtual-template 1.

  14. The LAC negotiated LCP state is replayed onto the virtual-access PPP stack, and includes the agreed MRRU option.

  15. AAA/PPP authentication and authorization then takes place. A RADIUS access-request is sent.

  16. Authentication is completed and virtual-access interface 3 is added to the Multilink bundle master.

23982b.bmp

Lab Testing - LNS Load Balancing with Multilink PPP

RADIUS Profile

This document uses this RADIUS user and tunnel profile on Merit RADIUS Server 3.6B:

2500-1 Password = "cisco" 
Service-Type = Framed,
Framed-Protocol = PPP,
Framed-IP-Address = 255.255.255.255
dnis:614629 Password = "cisco"
Service-Type = Outbound,
Cisco:Avpair = "vpdn:tunnel-type=l2tp",
Cisco:Avpair = "vpdn:tunnel-id=hgw",
Cisco:Avpair = "vpdn:ip-addresses=10.51.6.61,10.51.6.59",
Cisco:Avpair = "vpdn:l2tp-tunnel-password=hello"

LAC Configuration

LAC configuration same as the previous configuration.

LNS - Configuration for Stackgroup MULTIHOP (10.51.6.59 and 10.51.6.61) 

hostname nsa-7200-2 (10.51.6.61)
username MULTIHOP password 0 cisco

!--- The stack name/password is used to authenticate the SGBP connections between 
!--- all member routers. As RADIUS has no concept of SendAuth , the stack name 
!--- password needs to be defined locally.

sgbp group MULTIHOP

!--- The stack group is given a unique username, the name 'MULTIHOP' must be 
!--- unique within a domain and only one stack group is allowed per router.

sgbp member nsa-7200-3 10.51.6.59

!--- The stack member '10.51.6.59' is defined.

vpdn multihop

!--- Enables the LNS to forward Multilink PPP links to Stack Group members that 
!--- already own existing bundle Masters for that session.

multilink virtual-template 1

!--- The Multilink Bundle Interface will clone from the Virtual Template 1.

interface Virtual-Template1
ip unnumbered Ethernet3/0
peer default ip address pool default
ppp authentication chap vpdn
ppp authorization vpdn
ppp chap hostname nsa-7200-2
ppp multilink
hostname nsa-7200-3 (10.51.6.59)
!
username MULTIHOP password 0 cisco
!
sgbp group MULTIHOP
sgbp member nsa-7200-2 10.51.6.61
vpdn multihop
!
multilink virtual-template 1
!
interface Virtual-Template1
ip unnumbered Ethernet3/0
peer default ip address pool default
ppp authentication chap vpdn
ppp authorization vpdn
ppp chap hostname nsa-7200-3
ppp multilink

Debug Taken from LAC 

Jan 1 00:01:01.039: %LINK-3-UPDOWN: Interface Serial0:0, 
changed state to up
Jan 1 00:01:01.235: Se0:0 PPP: Treating connection as a callin
Jan 1 00:01:01.235: Se0:0 PPP: Phase is ESTABLISHING, Passive Open
Jan 1 00:01:01.239: Se0:0 CHAP: Using alternate hostname 5300-1
Jan 1 00:01:01.239: Se0:0 LCP: State is Listen
Jan 1 00:01:01.239: Se0:0 LCP: I CONFREQ [Listen] id 22 len 23
Jan 1 00:01:01.239: Se0:0 LCP: MagicNumber 0x31BFC605 (0x050631BFC605)
Jan 1 00:01:01.239: Se0:0 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:01.239: Se0:0 LCP: EndpointDisc 1 Local (0x130901323530302D31)
Jan 1 00:01:01.239: Se0:0 LCP: O CONFREQ [Listen] id 27 len 28
Jan 1 00:01:01.239: Se0:0 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:01.239: Se0:0 LCP: MagicNumber 0x15C13318 (0x050615C13318)
Jan 1 00:01:01.239: Se0:0 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:01.239: Se0:0 LCP: EndpointDisc 1 Local (0x130901353330302D31)
Jan 1 00:01:01.239: Se0:0 LCP: O CONFACK [Listen] id 22 len 23
Jan 1 00:01:01.239: Se0:0 LCP: MagicNumber 0x31BFC605 (0x050631BFC605)
Jan 1 00:01:01.239: Se0:0 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:01.239: Se0:0 LCP: EndpointDisc 1 Local (0x130901323530302D31)
Jan 1 00:01:01.287: Se0:0 LCP: I CONFACK [ACKsent] id 27 len 28
Jan 1 00:01:01.287: Se0:0 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:01.287: Se0:0 LCP: MagicNumber 0x15C13318 (0x050615C13318)
Jan 1 00:01:01.287: Se0:0 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:01.287: Se0:0 LCP: EndpointDisc 1 Local (0x130901353330302D31)
Jan 1 00:01:01.287: Se0:0 LCP: State is Open
Jan 1 00:01:01.287: Se0:0 PPP: Phase is AUTHENTICATING, by this end
Jan 1 00:01:01.287: Se0:0 CHAP: Using alternate hostname 5300-1
Jan 1 00:01:01.287: Se0:0 CHAP: O CHALLENGE id 17 len 27 from "5300-1"
Jan 1 00:01:01.315: Se0:0 CHAP: I RESPONSE id 17 len 27 from "2500-1"
Jan 1 00:01:01.315: Se0:0 PPP: Phase is FORWARDING
Jan 1 00:01:01.315: Se0:0 VPDN: Got DNIS string 614629
Jan 1 00:01:01.315: Se0:0 VPDN: Looking for tunnel -- dnis:614629 --
Jan 1 00:01:01.315: Serial0:0 AAA/AUTHOR/VPDN (552916761): Port='Serial0:0' 
list='default' service=NET
Jan 1 00:01:01.315: AAA/AUTHOR/VPDN: Serial0:0 (552916761) user='dnis:614629'
Jan 1 00:01:01.315: Serial0:0 AAA/AUTHOR/VPDN (552916761): send AV service=ppp
Jan 1 00:01:01.315: Serial0:0 AAA/AUTHOR/VPDN (552916761): send AV protocol=vpdn
Jan 1 00:01:01.315: Serial0:0 AAA/AUTHOR/VPDN (552916761): found list "default"
Jan 1 00:01:01.315: Serial0:0 AAA/AUTHOR/VPDN (552916761): Method=NSA_LAB (radius)
Jan 1 00:01:01.319: RADIUS: Initial Transmit Serial0:0 id 34 10.51.6.3:1645, 
Access-Request, len 112
Jan 1 00:01:01.319: Attribute 4 6 0A330644
Jan 1 00:01:01.319: Attribute 5 6 00000000
Jan 1 00:01:01.319: Attribute 26 17 00000009020B5365
Jan 1 00:01:01.319: Attribute 61 6 00000002
Jan 1 00:01:01.319: Attribute 1 13 646E6973
Jan 1 00:01:01.319: Attribute 30 8 36313436
Jan 1 00:01:01.319: Attribute 31 12 32303835
Jan 1 00:01:01.319: Attribute 2 18 B8DE6FA3
Jan 1 00:01:01.319: Attribute 6 6 00000005
Jan 1 00:01:01.323: RADIUS: Received from id 34 10.51.6.3:1645, 
Access-Accept, len 167
Jan 1 00:01:01.323: Attribute 6 6 00000005
Jan 1 00:01:01.323: Attribute 26 29 0000000901177670
Jan 1 00:01:01.323: Attribute 26 26 0000000901147670
Jan 1 00:01:01.323: Attribute 26 47 0000000901297670
Jan 1 00:01:01.327: Attribute 26 39 0000000901217670
Jan 1 00:01:01.327: RADIUS: saved authorization data for user 620DAD68 
at 619E9BC0
Jan 1 00:01:01.327: RADIUS: cisco AVPair "vpdn:tunnel-type=l2tp"
Jan 1 00:01:01.327: RADIUS: cisco AVPair "vpdn:tunnel-id=hgw"
Jan 1 00:01:01.327: RADIUS: cisco AVPair "vpdn:ip-addresses=
10.51.6.61,10.51.6.59"
Jan 1 00:01:01.327: RADIUS: cisco AVPair "vpdn:l2tp-tunnel-password=hello"
Jan 1 00:01:01.327: AAA/AUTHOR (552916761): Post authorization status 
= PASS_ADD
Jan 1 00:01:01.327: AAA/AUTHOR/VPDN: Processing AV service=ppp
Jan 1 00:01:01.327: AAA/AUTHOR/VPDN: Processing AV protocol=vpdn
Jan 1 00:01:01.327: AAA/AUTHOR/VPDN: Processing AV tunnel-type=l2tp
Jan 1 00:01:01.327: AAA/AUTHOR/VPDN: Processing AV tunnel-id=hgw
Jan 1 00:01:01.327: AAA/AUTHOR/VPDN: Processing AV ip-addresses=
10.51.6.61,10.51.6.59
Jan 1 00:01:01.327: AAA/AUTHOR/VPDN: Processing AV l2tp-tunnel-password=hello
Jan 1 00:01:01.327: Se0:0 VPDN/RPMS/: Got tunnel info for dnis:614629
Jan 1 00:01:01.327: Se0:0 VPDN/RPMS/: LAC hgw
Jan 1 00:01:01.327: Se0:0 VPDN/RPMS/: l2tp-busy-disconnect yes
Jan 1 00:01:01.327: Se0:0 VPDN/RPMS/: l2tp-tunnel-password xxxxxx
Jan 1 00:01:01.327: Se0:0 VPDN/RPMS/: 2 IP addresses
Jan 1 00:01:01.327: Se0:0 VPDN/RPMS/: IP 10.51.6.61 Priority 1
Jan 1 00:01:01.327: Se0:0 VPDN/RPMS/: IP 10.51.6.59 Priority 1
Jan 1 00:01:01.331: Se0:0 VPDN/: curlvl 1 Address 1: 10.51.6.59, priority 1 
Jan 1 00:01:01.331: Se0:0 VPDN/: Select non-active address 10.51.6.59, 
priority 1
Jan 1 00:01:01.331: Se0:0 VPDN: Find LNS process created
Jan 1 00:01:01.331: Tnl 5105 L2TP: SM State idle
Jan 1 00:01:01.331: Tnl 5105 L2TP: O SCCRQ 
Jan 1 00:01:01.331: Tnl 5105 L2TP: Tunnel state change from idle to 
wait-ctl-reply
Jan 1 00:01:01.331: Tnl 5105 L2TP: SM State wait-ctl-reply
Jan 1 00:01:01.331: Se0:0 VPDN: Forward to address 10.51.6.59
Jan 1 00:01:01.331: Se0:0 VPDN: Pending
Jan 1 00:01:01.331: Se0:0 VPDN: Process created
Jan 1 00:01:01.335: Tnl 5105 L2TP: I SCCRP from l2tp-gw
Jan 1 00:01:01.335: Tnl 5105 L2TP: Got a challenge from remote peer, 
l2tp-gw
Jan 1 00:01:01.335: Tnl 5105 L2TP: Got a response from remote peer, 
l2tp-gw
Jan 1 00:01:01.335: Tnl 5105 L2TP: Tunnel Authentication success
Jan 1 00:01:01.339: Tnl 5105 L2TP: Tunnel state change from 
wait-ctl-reply to established
Jan 1 00:01:01.339: Tnl 5105 L2TP: O SCCCN to l2tp-gw tnlid 24230
Jan 1 00:01:01.339: Tnl 5105 L2TP: SM State established
Jan 1 00:01:01.339: Se0:0 VPDN: Forwarding...
Jan 1 00:01:01.339: Tnl/Cl 5105/18 L2TP: Session FS enabled
Jan 1 00:01:01.339: Tnl/Cl 5105/18 L2TP: Session state change from idle 
to wait-for-tunnel
Jan 1 00:01:01.339: Se0:0 Tnl/Cl 5105/18 L2TP: Create session
Jan 1 00:01:01.339: Tnl 5105 L2TP: SM State established
Jan 1 00:01:01.339: Se0:0 Tnl/Cl 5105/18 L2TP: O ICRQ to l2tp-gw 24230/0
Jan 1 00:01:01.339: Se0:0 Tnl/Cl 5105/18 L2TP: Session state change from 
wait-for-tunnel to wait-reply
Jan 1 00:01:01.339: Se0:0 VPDN: 2500-1 is forwarded
Jan 1 00:01:01.343: Se0:0 Tnl/Cl 5105/18 L2TP: O ICCN to l2tp-gw 24230/41
Jan 1 00:01:01.347: Se0:0 Tnl/Cl 5105/18 L2TP: Session state change from 
wait-reply to established
Jan 1 00:01:02.343: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0:0, 
changed state to up

!--- Second Multilink Call is placed by the remote user.

Jan 1 00:01:03.123: %LINK-3-UPDOWN: Interface Serial0:1, 
changed state to up
Jan 1 00:01:03.127: %ISDN-6-CONNECT: Interface Serial0:0 
is now connected to 2085730592 2500-1
Jan 1 00:01:03.351: Se0:1 PPP: Treating connection as a callin
Jan 1 00:01:03.351: Se0:1 PPP: Phase is ESTABLISHING, Passive Open
Jan 1 00:01:03.351: Se0:1 CHAP: Using alternate hostname 5300-1
Jan 1 00:01:03.351: Se0:1 LCP: State is Listen
Jan 1 00:01:03.351: Se0:1 LCP: I CONFREQ [Listen] id 3 len 23
Jan 1 00:01:03.351: Se0:1 LCP: MagicNumber 0x31BFCE57 (0x050631BFCE57)
Jan 1 00:01:03.351: Se0:1 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:03.351: Se0:1 LCP: EndpointDisc 1 Local (0x130901323530302D31)
Jan 1 00:01:03.351: Se0:1 LCP: O CONFREQ [Listen] id 3 len 28
Jan 1 00:01:03.351: Se0:1 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:03.351: Se0:1 LCP: MagicNumber 0x15C13B5D (0x050615C13B5D)
Jan 1 00:01:03.351: Se0:1 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:03.351: Se0:1 LCP: EndpointDisc 1 Local (0x130901353330302D31)
Jan 1 00:01:03.355: Se0:1 LCP: O CONFACK [Listen] id 3 len 23
Jan 1 00:01:03.355: Se0:1 LCP: MagicNumber 0x31BFCE57 (0x050631BFCE57)
Jan 1 00:01:03.355: Se0:1 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:03.355: Se0:1 LCP: EndpointDisc 1 Local (0x130901323530302D31)
Jan 1 00:01:03.403: Se0:1 LCP: I CONFACK [ACKsent] id 3 len 28
Jan 1 00:01:03.403: Se0:1 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:03.403: Se0:1 LCP: MagicNumber 0x15C13B5D (0x050615C13B5D)
Jan 1 00:01:03.403: Se0:1 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:03.403: Se0:1 LCP: EndpointDisc 1 Local (0x130901353330302D31)
Jan 1 00:01:03.403: Se0:1 LCP: State is Open
Jan 1 00:01:03.403: Se0:1 PPP: Phase is AUTHENTICATING, by this end
Jan 1 00:01:03.403: Se0:1 CHAP: Using alternate hostname 5300-1
Jan 1 00:01:03.407: Se0:1 CHAP: O CHALLENGE id 3 len 27 from "5300-1"
Jan 1 00:01:03.435: Se0:1 CHAP: I RESPONSE id 3 len 27 from "2500-1"
Jan 1 00:01:03.435: Se0:1 PPP: Phase is FORWARDING
Jan 1 00:01:03.435: Se0:1 VPDN: Got DNIS string 614629
Jan 1 00:01:03.435: Se0:1 VPDN: Looking for tunnel -- dnis:614629 --
Jan 1 00:01:03.435: Serial0:1 AAA/AUTHOR/VPDN (4201608973): Port='Serial0:1' 
list='default' service=NET
Jan 1 00:01:03.435: AAA/AUTHOR/VPDN: Serial0:1 (4201608973) user='dnis:614629'
Jan 1 00:01:03.435: Serial0:1 AAA/AUTHOR/VPDN (4201608973): send AV service=ppp
Jan 1 00:01:03.435: Serial0:1 AAA/AUTHOR/VPDN (4201608973): send AV protocol=vpdn
Jan 1 00:01:03.435: Serial0:1 AAA/AUTHOR/VPDN (4201608973): found list "default"
Jan 1 00:01:03.435: Serial0:1 AAA/AUTHOR/VPDN (4201608973): Method=NSA_LAB (radius)
Jan 1 00:01:03.439: RADIUS: Initial Transmit Serial0:1 id 35 10.51.6.3:1645, 
Access-Request, len 112
Jan 1 00:01:03.439: Attribute 4 6 0A330644
Jan 1 00:01:03.439: Attribute 5 6 00000001
Jan 1 00:01:03.439: Attribute 26 17 00000009020B5365
Jan 1 00:01:03.439: Attribute 61 6 00000002
Jan 1 00:01:03.439: Attribute 1 13 646E6973
Jan 1 00:01:03.439: Attribute 30 8 36313436
Jan 1 00:01:03.439: Attribute 31 12 32303835
Jan 1 00:01:03.439: Attribute 2 18 0FC856FB
Jan 1 00:01:03.439: Attribute 6 6 00000005
Jan 1 00:01:03.443: RADIUS: Received from id 35 10.51.6.3:1645, 
Access-Accept, len 167
Jan 1 00:01:03.443: Attribute 6 6 00000005
Jan 1 00:01:03.443: Attribute 26 29 0000000901177670
Jan 1 00:01:03.443: Attribute 26 26 0000000901147670
Jan 1 00:01:03.443: Attribute 26 47 0000000901297670
Jan 1 00:01:03.443: Attribute 26 39 0000000901217670
Jan 1 00:01:03.443: RADIUS: saved authorization data for user 
62127900 at 61CD10A0
Jan 1 00:01:03.443: RADIUS: cisco AVPair "vpdn:tunnel-type=l2tp"
Jan 1 00:01:03.443: RADIUS: cisco AVPair "vpdn:tunnel-id=hgw"
Jan 1 00:01:03.443: RADIUS: cisco AVPair "vpdn:ip-addresses=
10.51.6.61,10.51.6.59"
Jan 1 00:01:03.443: RADIUS: cisco AVPair "vpdn:l2tp-tunnel-password=hello"
Jan 1 00:01:03.443: AAA/AUTHOR (4201608973): Post authorization status 
= PASS_ADD
Jan 1 00:01:03.443: AAA/AUTHOR/VPDN: Processing AV service=ppp
Jan 1 00:01:03.443: AAA/AUTHOR/VPDN: Processing AV protocol=vpdn
Jan 1 00:01:03.443: AAA/AUTHOR/VPDN: Processing AV tunnel-type=l2tp
Jan 1 00:01:03.443: AAA/AUTHOR/VPDN: Processing AV tunnel-id=hgw
Jan 1 00:01:03.443: AAA/AUTHOR/VPDN: Processing AV ip-addresses=
10.51.6.61,10.51.6.59
Jan 1 00:01:03.443: AAA/AUTHOR/VPDN: Processing AV l2tp-tunnel-password=hello
Jan 1 00:01:03.443: Se0:1 VPDN/RPMS/: Got tunnel info for dnis:614629
Jan 1 00:01:03.443: Se0:1 VPDN/RPMS/: LAC hgw
Jan 1 00:01:03.443: Se0:1 VPDN/RPMS/: l2tp-busy-disconnect yes
Jan 1 00:01:03.443: Se0:1 VPDN/RPMS/: l2tp-tunnel-password xxxxxx
Jan 1 00:01:03.443: Se0:1 VPDN/RPMS/: 2 IP addresses
Jan 1 00:01:03.443: Se0:1 VPDN/RPMS/: IP 10.51.6.61 Priority 1
Jan 1 00:01:03.447: Se0:1 VPDN/RPMS/: IP 10.51.6.59 Priority 1
Jan 1 00:01:03.447: Se0:1 VPDN/: curlvl 1 Address 1: 10.51.6.59, priority 1 
Jan 1 00:01:03.447: Se0:1 VPDN/: curlvl 1 Address 0: 10.51.6.61, priority 1 
Jan 1 00:01:03.447: Se0:1 VPDN/: Select non-active address 10.51.6.61, 
priority 1
Jan 1 00:01:03.447: Se0:1 VPDN: Find LNS process created
Jan 1 00:01:03.447: Tnl 49388 L2TP: SM State idle
Jan 1 00:01:03.447: Tnl 49388 L2TP: O SCCRQ 
Jan 1 00:01:03.447: Tnl 49388 L2TP: Tunnel state change from idle to 
wait-ctl-reply
Jan 1 00:01:03.447: Tnl 49388 L2TP: SM State wait-ctl-reply
Jan 1 00:01:03.447: Se0:1 VPDN: Forward to address 10.51.6.61
Jan 1 00:01:03.447: Se0:1 VPDN: Pending
Jan 1 00:01:03.447: Se0:1 VPDN: Process created
Jan 1 00:01:03.451: Tnl 49388 L2TP: I SCCRP from l2tp-gw
Jan 1 00:01:03.451: Tnl 49388 L2TP: Got a challenge from remote peer, 
l2tp-gw
Jan 1 00:01:03.451: Tnl 49388 L2TP: Got a response from remote peer, 
l2tp-gw
Jan 1 00:01:03.451: Tnl 49388 L2TP: Tunnel Authentication success
Jan 1 00:01:03.451: Tnl 49388 L2TP: Tunnel state change from 
wait-ctl-reply to established
Jan 1 00:01:03.451: Tnl 49388 L2TP: O SCCCN to l2tp-gw tnlid 43591
Jan 1 00:01:03.455: Tnl 49388 L2TP: SM State established
Jan 1 00:01:03.455: Se0:1 VPDN: Forwarding...
Jan 1 00:01:03.455: Tnl/Cl 49388/19 L2TP: Session FS enabled
Jan 1 00:01:03.455: Tnl/Cl 49388/19 L2TP: Session state change from 
idle to wait-for-tunnel
Jan 1 00:01:03.455: Se0:1 Tnl/Cl 49388/19 L2TP: Create session
Jan 1 00:01:03.455: Tnl 49388 L2TP: SM State established
Jan 1 00:01:03.455: Se0:1 Tnl/Cl 49388/19 L2TP: O ICRQ to l2tp-gw 43591/0
Jan 1 00:01:03.455: Se0:1 Tnl/Cl 49388/19 L2TP: Session state change from 
wait-for-tunnel to wait-reply
Jan 1 00:01:03.455: Se0:1 VPDN: 2500-1 is forwarded
Jan 1 00:01:03.459: Se0:1 Tnl/Cl 49388/19 L2TP: O ICCN to l2tp-gw 43591/19
Jan 1 00:01:03.463: Se0:1 Tnl/Cl 49388/19 L2TP: Session state change from 
wait-reply to established
Jan 1 00:01:04.455: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0:1, 
changed state to up
Jan 1 00:01:09.127: %ISDN-6-CONNECT: Interface Serial0:1 is now connected to 
2085730592 2500-1

23982c.bmp

Debugs Taken from LNS - 10.51.6.59 

Jan 1 00:01:01.783: L2TP: I SCCRQ from hgw tnl 5105
Jan 1 00:01:01.783: Tnl 24230 L2TP: Got a challenge in SCCRQ, hgw
Jan 1 00:01:01.783: Tnl 24230 L2TP: New tunnel created for remote hgw, 
address10.51.6.68
Jan 1 00:01:01.783: Tnl 24230 L2TP: O SCCRP to hgw tnlid 5105
Jan 1 00:01:01.783: Tnl 24230 L2TP: Tunnel state change from idle 
to wait-ctl-reply
Jan 1 00:01:01.787: Tnl 24230 L2TP: I SCCCN from hgw tnl 5105
Jan 1 00:01:01.787: Tnl 24230 L2TP: Got a Challenge Response in SCCCN from hgw
Jan 1 00:01:01.787: Tnl 24230 L2TP: Tunnel Authentication success
Jan 1 00:01:01.787: Tnl 24230 L2TP: Tunnel state change from wait-ctl-reply 
to established
Jan 1 00:01:01.787: Tnl 24230 L2TP: SM State established
Jan 1 00:01:01.791: Tnl 24230 L2TP: I ICRQ from hgw tnl 5105
Jan 1 00:01:01.791: Tnl/Cl 24230/41 L2TP: Session FS enabled
Jan 1 00:01:01.791: Tnl/Cl 24230/41 L2TP: Session state change from idle 
to wait-connect
Jan 1 00:01:01.791: Tnl/Cl 24230/41 L2TP: New session created
Jan 1 00:01:01.791: Tnl/Cl 24230/41 L2TP: O ICRP to hgw 5105/18
Jan 1 00:01:01.795: Tnl/Cl 24230/41 L2TP: I ICCN from hgw tnl 5105, cl 18
Jan 1 00:01:01.795: Tnl/Cl 24230/41 L2TP: Session state change from wait-connect 
to established
Jan 1 00:01:01.795: Vi2 VPDN: Virtual interface created for 2500-1
Jan 1 00:01:01.795: Vi2 PPP: Phase is DOWN, Setup
Jan 1 00:01:01.799: Vi2 VTEMPLATE: Has a new cloneblk vtemplate, 
now it has vtemplate
Jan 1 00:01:01.799: Vi2 VTEMPLATE: 
************* CLONE VACCESS2 *****************
Jan 1 00:01:01.799: Vi2 VTEMPLATE: Clone from Virtual-Template1
interface Virtual-Access2
default ip address
ppp authentication chap vpdn
ppp authorization vpdn
ppp multilink
pp chap hostname nsa-7200-3
end
Jan 1 00:01:01.835: %LINK-3-UPDOWN: Interface Virtual-Access2, 
changed state to up
Jan 1 00:01:01.835: Vi2 PPP: Using set call direction
Jan 1 00:01:01.835: Vi2 PPP: Treating connection as a callin
Jan 1 00:01:01.835: Vi2 PPP: Phase is ESTABLISHING, Passive Open
Jan 1 00:01:01.835: Vi2 CHAP: Using alternate hostname nsa-7200-3
Jan 1 00:01:01.835: Vi2 LCP: State is Listen
Jan 1 00:01:01.835: Vi2 LCP: I FORCED CONFREQ len 24
Jan 1 00:01:01.835: Vi2 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:01.835: Vi2 LCP: MagicNumber 0x15C13318 (0x050615C13318)
Jan 1 00:01:01.835: Vi2 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:01.835: Vi2 LCP: EndpointDisc 1 Local (0x130901353330302D31)
Jan 1 00:01:01.835: Vi2 VPDN: PPP LCP accepted rcv CONFACK
Jan 1 00:01:01.835: Vi2 LCP: I FORCED CONFACK len 19
Jan 1 00:01:01.835: Vi2 LCP: MagicNumber 0x31BFC605 (0x050631BFC605)
Jan 1 00:01:01.835: Vi2 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:01.835: Vi2 LCP: EndpointDisc 1 Local (0x130901323530302D31)
Jan 1 00:01:01.835: Vi2 VPDN: PPP LCP accepted sent CONFACK
Jan 1 00:01:01.835: Vi2 PPP: Phase is AUTHENTICATING, by this end
Jan 1 00:01:01.835: Vi2 CHAP: Using alternate hostname nsa-7200-3
Jan 1 00:01:01.835: Vi2 CHAP: O CHALLENGE id 3 len 31 from "nsa-7200-3"
Jan 1 00:01:01.835: Vi2 CHAP: I RESPONSE id 17 len 27 from "2500-1"
Jan 1 00:01:01.835: Vi2 PPP: Phase is FORWARDING
Jan 1 00:01:01.835: Vi2 VPDN: Looking for tunnel -- --
Jan 1 00:01:01.839: Vi2 VPDN: Looking for tunnel -- --
Jan 1 00:01:01.839: %SGBP-7-NEWL: Local query #53 for 2500-1, count 1, 
ourbid 50
Jan 1 00:01:01.839: Vi2 VPDN: Continue using SGBP for 2500-1
Jan 1 00:01:01.839: Vi2 VPDN: Pending
Jan 1 00:01:01.839: Vi2 VPDN: Process created
Jan 1 00:01:02.091: %SGBP-7-DONE: Query #53 for bundle 2500-1, count 1, 
master is local
Jan 1 00:01:02.091: %SGBP-7-MQB: Bundle: 2500-1 State: Done OurBid: 10000
Jan 1 00:01:02.091: %SGBP-7-PB: 10.51.6.61 State: Rcvd Bid: 000 Retry: 0
Jan 1 00:01:02.091: Vi2 VPDN: Not forwarded
Jan 1 00:01:02.091: Vi2 PPP: Phase is AUTHENTICATING
Jan 1 00:01:02.091: Vi2 CHAP: I RESPONSE id 17 len 27 from "2500-1"
Jan 1 00:01:02.091: AAA/AUTHEN/START (3376880111): port='Virtual-Access2' 
list='vpdn' action=LOGI service=PPP
Jan 1 00:01:02.091: AAA/AUTHEN/START (3376880111): found list vpdn
Jan 1 00:01:02.091: AAA/AUTHEN/START (3376880111): Method=radius (radius)
Jan 1 00:01:02.091: RADIUS: Initial Transmit Virtual-Access2 
id 15 10.51.6.3:1645, Access-Request, len 97
Jan 1 00:01:02.091: Attribute 4 6 0A33063B
Jan 1 00:01:02.091: Attribute 5 6 00000002
Jan 1 00:01:02.091: Attribute 61 6 00000005
Jan 1 00:01:02.091: Attribute 1 8 32353030
Jan 1 00:01:02.091: Attribute 30 8 36313436
Jan 1 00:01:02.091: Attribute 31 12 32303835
Jan 1 00:01:02.091: Attribute 3 19 110F710D
Jan 1 00:01:02.091: Attribute 6 6 00000002
Jan 1 00:01:02.091: Attribute 7 6 00000001
Jan 1 00:01:02.095: RADIUS: Received from id 15 10.51.6.3:1645, 
Access-Accept, len 38
Jan 1 00:01:02.095: Attribute 6 6 00000002
Jan 1 00:01:02.095: Attribute 7 6 00000001
Jan 1 00:01:02.095: Attribute 8 6 FFFFFFFF
Jan 1 00:01:02.095: AAA/AUTHEN (3376880111): status = PASS
Jan 1 00:01:02.095: Vi2 AAA/AUTHOR/LCP: Authorize LCP
Jan 1 00:01:02.095: Vi2 AAA/AUTHOR/LCP (2242497288): Port='Virtual-Access2' 
list='vpdn' service=NET
Jan 1 00:01:02.099: AAA/AUTHOR/LCP: Vi2 (2242497288) user='2500-1'
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/LCP (2242497288): send AV service=ppp
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/LCP (2242497288): send AV protocol=lcp
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/LCP (2242497288): found list "vpdn"
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/LCP (2242497288): Method=radius (radius)
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR (2242497288): Post authorization status 
= PASS_REPL
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/LCP: Processing AV service=ppp
Jan 1 00:01:02.099: Vi2 CHAP: O SUCCESS id 17 len 4
Jan 1 00:01:02.099: Vi2 PPP: Phase is VIRTUALIZED
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/MLP (2616761311): Port='Virtual-Access2' 
list='vpdn' service=NET
Jan 1 00:01:02.099: AAA/AUTHOR/MLP: Vi2 (2616761311) user='2500-1'
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/MLP (2616761311): send AV service=ppp
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/MLP (2616761311): send AV protocol=multilink
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/MLP (2616761311): found list "vpdn"
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR/MLP (2616761311): Method=radius (radius)
Jan 1 00:01:02.099: Vi2 AAA/AUTHOR (2616761311): Post authorization status 
= PASS_REPL
Jan 1 00:01:02.099: Vi1 VTEMPLATE: Set default settings with ip unnumbered
Jan 1 00:01:02.115: Vi1 VTEMPLATE: Hardware address 0010.0ba5.f800
Jan 1 00:01:02.115: Vi1 PPP: Phase is DOWN, Setup
Jan 1 00:01:02.119: Vi1 VTEMPLATE: Has a new cloneblk vtemplate, 
now it has vtemplate
Jan 1 00:01:02.119: Vi1 VTEMPLATE: 
************* CLONE VACCESS1 *****************
Jan 1 00:01:02.119: Vi1 VTEMPLATE: Clone from Virtual-Template1
interface Virtual-Access1
default ip address
no ip address
encap ppp
ip unnumbered Ethernet5/0
peer default ip address pool default
ppp authentication chap vpdn
ppp authorization vpdn
ppp multilink
pp chap hostname nsa-7200-3
end

Jan 1 00:01:02.179: Vi2 IPCP: Packet buffered while building 
MLP bundle interface
Jan 1 00:01:02.179: %LINK-3-UPDOWN: Interface Virtual-Access1, 
changed state to up
Jan 1 00:01:02.179: Vi1 PPP: Treating connection as a dedicated line
Jan 1 00:01:02.179: Vi1 PPP: Phase is ESTABLISHING, Active Open
Jan 1 00:01:02.179: Vi1 CHAP: Using alternate hostname nsa-7200-3
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM: (0): LCP succeeds trivially
Jan 1 00:01:02.179: Vi1 LCP: O CONFREQ [Closed] id 1 len 32
Jan 1 00:01:02.179: Vi1 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:02.179: Vi1 LCP: MagicNumber 0x1F5A340B (0x05061F5A340B)
Jan 1 00:01:02.179: Vi1 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:02.179: Vi1 LCP: EndpointDisc 1 Local 
(0x130D016E73612D373230302D33)
Jan 1 00:01:02.179: AAA/AUTHOR/MLP Vi1: Processing AV service=ppp
Jan 1 00:01:02.179: Vi1 VPDN: Virtual interface iteration
Jan 1 00:01:02.179: Vi1 PPP: Phase is UP
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM: (0): Can we start IPCP?
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM (2530889481): Port='Virtual-Access2' 
list='vpdn' service=NET
Jan 1 00:01:02.179: AAA/AUTHOR/FSM: Vi1 (2530889481) user='2500-1'
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM (2530889481): send AV service=ppp
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM (2530889481): send AV protocol=ip
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM (2530889481): found list "vpdn"
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM (2530889481): Method=radius (radius)
Jan 1 00:01:02.179: RADIUS: allowing negotiated framed address
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR (2530889481): Post authorization status 
= PASS_REPL
Jan 1 00:01:02.179: Vi1 AAA/AUTHOR/FSM: We can start IPCP
Jan 1 00:01:02.183: Vi1 IPCP: O CONFREQ [Closed] id 1 len 10
Jan 1 00:01:02.183: Vi1 IPCP: Address 10.51.6.59 (0x03060A33063B)
Jan 1 00:01:02.183: Vi1 MLP: Added first link Vi2 to bundle 2500-1
Jan 1 00:01:02.183: Vi2 IPCP: Redirect packet to Vi1
Jan 1 00:01:02.183: Vi1 IPCP: I CONFREQ [REQsent] id 1 len 10
Jan 1 00:01:02.183: Vi1 IPCP: Address 10.10.53.2 (0x03060A0A3502)
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP: Start. Her address 10.10.53.2, 
we want 0.0.0.0
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP (2777739044): Port='Virtual-Access2' 
list='vpdn' service=NET
Jan 1 00:01:02.183: AAA/AUTHOR/IPCP: Vi1 (2777739044) user='2500-1'
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP (2777739044): send AV service=ppp
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP (2777739044): send AV protocol=ip
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP (2777739044): send AV addr*10.10.53.2
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP (2777739044): found list "vpdn"
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP (2777739044): Method=radius (radius)
Jan 1 00:01:02.183: RADIUS: allowing negotiated framed address 10.10.53.2
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR (2777739044): Post authorization status 
= PASS_REPL
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP: Processing AV service=ppp
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP: Processing AV addr=10.10.53.2
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP: Authorization succeeded
Jan 1 00:01:02.183: Vi1 AAA/AUTHOR/IPCP: Done. Her address 10.10.53.2, 
we want 10.10.53.2
Jan 1 00:01:02.183: Vi1 IPCP: O CONFACK [REQsent] id 1 len 10
Jan 1 00:01:02.183: Vi1 IPCP: Address 10.10.53.2 (0x03060A0A3502)
Jan 1 00:01:02.211: Vi1 IPCP: I CONFACK [ACKsent] id 1 len 10
Jan 1 00:01:02.211: Vi1 IPCP: Address 10.51.6.59 (0x03060A33063B)
Jan 1 00:01:02.211: Vi1 IPCP: State is Open
Jan 1 00:01:02.211: Vi1 AAA/AUTHOR/PER-USER: Event IP_UP
Jan 1 00:01:02.211: Vi1 AAA/AUTHOR: IP_UP
Jan 1 00:01:02.211: Vi1 AAA/PER-USER: processing author params.
Jan 1 00:01:02.215: Vi1 IPCP: Install route to 10.10.53.2
Jan 1 00:01:03.099: %LINEPROTO-5-UPDOWN: 
Line protocol on Interface Virtual-Access2, changed state to up
Jan 1 00:01:03.179: %LINEPROTO-5-UPDOWN: 
Line protocol on Interface Virtual-Access1, changed state to up
Jan 1 00:01:04.163: %SGBP-7-NEWP: 
Peer query #54 for 2500-1, count 1, peerbid 50, ourbid 10000
Jan 1 00:01:04.363: %SGBP-7-DONE: 
Query #54 for bundle 2500-1, count 0, master is local
Jan 1 00:01:04.367: L2X: L2F_CONF received
Jan 1 00:01:04.367: Tnl 46 L2F: Received L2F-CONF from MULTIHOP
Jan 1 00:01:04.367: AAA/AUTHEN/START (1546583827): 
port='' list='default' action=SENDAUTH service=PPP
Jan 1 00:01:04.367: AAA/AUTHEN/START (1546583827): found list default
Jan 1 00:01:04.367: AAA/AUTHEN/START (1546583827): Method=LOCAL
Jan 1 00:01:04.367: AAA/AUTHEN (1546583827): status = PASS
Jan 1 00:01:04.367: AAA/AUTHEN/START (3291965384): 
port='' list='default' action=SENDAUTH service=PPP
Jan 1 00:01:04.367: AAA/AUTHEN/START (3291965384): found list default
Jan 1 00:01:04.367: AAA/AUTHEN/START (3291965384): Method=LOCAL
Jan 1 00:01:04.367: AAA/AUTHEN (3291965384): status = PASS
Jan 1 00:01:04.367: Tnl 46 L2F: 
Opened UDP socket to 10.51.6.61 using source 10.51.6.59
Jan 1 00:01:04.367: Tnl 46 L2F: 
Tunnel MULTIHOP state change from closed state opening
Jan 1 00:01:04.367: Tnl 46 L2F: Sending L2F-CONF to peer
Jan 1 00:01:04.375: Tnl 46 L2F: L2F_OPEN received
Jan 1 00:01:04.375: Tnl 46 L2F: 
OPEN from MULTIHOP received for tunnel in state opening
Jan 1 00:01:04.375: AAA/AUTHEN/START (3210024667): 
port='' list='default' action=LOGIN service=PPP
Jan 1 00:01:04.375: AAA/AUTHEN/START (3210024667): found list default
Jan 1 00:01:04.375: AAA/AUTHEN/START (3210024667): Method=LOCAL
Jan 1 00:01:04.375: AAA/AUTHEN (3210024667): status = PASS
Jan 1 00:01:04.375: VPDN: Chap authentication succeeded for MULTIHOP
Jan 1 00:01:04.375: Tnl 46 L2F: 
Tunnel MULTIHOP state change from opening state open
Jan 1 00:01:04.375: Tnl 46 L2F: Replying to MULTIHOP with L2F-OPEN
Jan 1 00:01:04.379: Tnl 46 L2F: L2F_OPEN received
Jan 1 00:01:04.379: Tnl 46 L2F: New OPEN received for Session 12
Jan 1 00:01:04.379: 2500-1Tnl/Cl 46/12 L2F: 
Session state change from closed to opening
Jan 1 00:01:04.379: Vi3 VTEMPLATE: Hardware address 0010.0ba5.f800
Jan 1 00:01:04.379: Vi3 VPDN: 
Virtual interface created for 2500-1 bandwidth 64 Kbps
Jan 1 00:01:04.379: Vi3 PPP: Phase is DOWN, Setup
Jan 1 00:01:04.379: Vi3 VTEMPLATE: 
Has a new cloneblk vtemplate, now it has vtemplate
Jan 1 00:01:04.379: Vi3 VTEMPLATE: 
************* CLONE VACCESS3 *****************
Jan 1 00:01:04.379: Vi3 VTEMPLATE: Clone from Virtual-Template1
interface Virtual-Access3
default ip address
ppp authentication chap vpdn
ppp authorization vpdn
ppp multilink
pp chap hostname nsa-7200-3
end

Jan 1 00:01:04.419: %LINK-3-UPDOWN: Interface Virtual-Access3, 
changed state to up
Jan 1 00:01:04.419: Vi3 PPP: Using set call direction
Jan 1 00:01:04.419: Vi3 PPP: Treating connection as a callin
Jan 1 00:01:04.419: Vi3 PPP: Phase is ESTABLISHING, Passive Open
Jan 1 00:01:04.419: Vi3 CHAP: Using alternate hostname nsa-7200-3
Jan 1 00:01:04.419: Vi3 LCP: State is Listen
Jan 1 00:01:04.419: Vi3 LCP: I FORCED CONFREQ len 24
Jan 1 00:01:04.419: Vi3 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:04.419: Vi3 LCP: MagicNumber 0x15C13B5D (0x050615C13B5D)
Jan 1 00:01:04.419: Vi3 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:04.419: Vi3 LCP: EndpointDisc 1 Local (0x130901353330302D31)
Jan 1 00:01:04.419: Vi3 VPDN: PPP LCP accepted rcv CONFACK
Jan 1 00:01:04.419: Vi3 LCP: I FORCED CONFACK len 19
Jan 1 00:01:04.419: Vi3 LCP: MagicNumber 0x31BFCE57 (0x050631BFCE57)
Jan 1 00:01:04.419: Vi3 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:04.419: Vi3 LCP: EndpointDisc 1 Local (0x130901323530302D31)
Jan 1 00:01:04.419: Vi3 VPDN: PPP LCP accepted sent CONFACK
Jan 1 00:01:04.419: Vi3 PPP: Phase is AUTHENTICATING, by this end
Jan 1 00:01:04.419: Vi3 CHAP: Using alternate hostname nsa-7200-3
Jan 1 00:01:04.419: Vi3 CHAP: O CHALLENGE id 3 len 31 from "nsa-7200-3"
Jan 1 00:01:04.419: Vi3 Tnl/Cl 46/12 L2F: 
Transfer NAS-Rate L2F/64000/64000 to LCP
Jan 1 00:01:04.419: Vi3 CHAP: I RESPONSE id 3 len 27 from "2500-1"
Jan 1 00:01:04.419: Vi3 PPP: Phase is FORWARDING
Jan 1 00:01:04.423: Vi3 VPDN: Looking for tunnel -- --
Jan 1 00:01:04.423: Vi3 VPDN: Looking for tunnel -- --
Jan 1 00:01:04.423: Vi3 VPDN: Multihop illegal for Multichassis Multilink

!--- This debug message is generated as the Cisco IOS software checks to see 
!--- if the second and first hops are already an existing Multichassis tunnel.
!--- If so, the tunnel is disallowed.

Jan 1 00:01:04.423: Vi3 VPDN: Continue PPP authentication for 2500-1
Jan 1 00:01:04.423: Vi3 PPP: Phase is AUTHENTICATING
Jan 1 00:01:04.423: Vi3 Tnl/Cl 46/12 L2F: Created VA for Mid, 
Replying with OPEN
Jan 1 00:01:04.423: Vi3 Tnl/Cl 46/12 L2F: 
Session state change from opening to open
Jan 1 00:01:04.423: AAA/AUTHEN/START (578160697): 
port='Virtual-Access3' list='vpdn' action=LOGIN service=PPP
Jan 1 00:01:04.423: AAA/AUTHEN/START (578160697): found list vpdn
Jan 1 00:01:04.423: AAA/AUTHEN/START (578160697): Method=radius (radius)
Jan 1 00:01:04.423: RADIUS: Initial Transmit Virtual-Access3
 id 16 10.51.6.3:1645, Access-Request, len 97
Jan 1 00:01:04.423: Attribute 4 6 0A33063B
Jan 1 00:01:04.423: Attribute 5 6 00000003
Jan 1 00:01:04.423: Attribute 61 6 00000005
Jan 1 00:01:04.423: Attribute 1 8 32353030
Jan 1 00:01:04.423: Attribute 30 8 36313436
Jan 1 00:01:04.423: Attribute 31 12 32303835
Jan 1 00:01:04.423: Attribute 3 19 03A99FFB
Jan 1 00:01:04.423: Attribute 6 6 00000002
Jan 1 00:01:04.423: Attribute 7 6 00000001
Jan 1 00:01:04.427: RADIUS: Received from id 16 10.51.6.3:1645, 
Access-Accept,len 38
Jan 1 00:01:04.427: Attribute 6 6 00000002
Jan 1 00:01:04.427: Attribute 7 6 00000001
Jan 1 00:01:04.427: Attribute 8 6 FFFFFFFF
Jan 1 00:01:04.427: AAA/AUTHEN (578160697): status = PASS
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR/LCP: Authorize LCP
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR/LCP (2032781798): Port='Virtual-Access3' 
list='vpdn' service=NET
Jan 1 00:01:04.427: AAA/AUTHOR/LCP: Vi3 (2032781798) user='2500-1'
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR/LCP (2032781798): send AV service=ppp
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR/LCP (2032781798): send AV protocol=lcp
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR/LCP (2032781798): found list "vpdn"
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR/LCP (2032781798): Method=radius (radius)
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR (2032781798): 
Post authorization status = PASS_REPL
Jan 1 00:01:04.427: Vi3 AAA/AUTHOR/LCP: Processing AV service=ppp
Jan 1 00:01:04.427: Vi3 CHAP: O SUCCESS id 3 len 4
Jan 1 00:01:04.427: Vi3 PPP: Phase is VIRTUALIZED
Jan 1 00:01:04.427: Vi1 MLP: Added link Vi3 to bundle 2500-1
Jan 1 00:01:04.491: %SGBP-7-MQB: Bundle: 2500-1 State: Done OurBid:10000
Jan 1 00:01:04.491: %SGBP-7-PB: 10.51.6.61 State: Closed Bid: 050 Retry: 1
Jan 1 00:01:05.427: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, 
changed state to up

23982d.bmp

Debugs Taken from LNS - 10.51.6.61 

Jan 1 00:01:02.399: %SGBP-7-NEWP: Peer query #53 for 2500-1, 
count 1, peerbid 5 0, ourbid 0
Jan 1 00:01:04.411: L2TP: I SCCRQ from hgw tnl 49388
Jan 1 00:01:04.411: Tnl 43591 L2TP: Got a challenge in SCCRQ, hgw
Jan 1 00:01:04.411: Tnl 43591 L2TP: New tunnel created for remote hgw, 
address 10.51.6.68
Jan 1 00:01:04.411: Tnl 43591 L2TP: O SCCRP to hgw tnlid 49388
Jan 1 00:01:04.411: Tnl 43591 L2TP: Tunnel state change from idle to 
wait-ctl-reply
Jan 1 00:01:04.415: Tnl 43591 L2TP: I SCCCN from hgw tnl 49388
Jan 1 00:01:04.415: Tnl 43591 L2TP: Got a Challenge Response in SCCCN from hgw
Jan 1 00:01:04.415: Tnl 43591 L2TP: Tunnel Authentication success
Jan 1 00:01:04.415: Tnl 43591 L2TP: Tunnel state change from wait-ctl-reply 
to established
Jan 1 00:01:04.415: Tnl 43591 L2TP: SM State established
Jan 1 00:01:04.419: Tnl 43591 L2TP: I ICRQ from hgw tnl 49388
Jan 1 00:01:04.419: Tnl/Cl 43591/19 L2TP: Session FS enabled
Jan 1 00:01:04.419: Tnl/Cl 43591/19 L2TP: Session state change from idle 
to wait-connect
Jan 1 00:01:04.419: Tnl/Cl 43591/19 L2TP: New session created
Jan 1 00:01:04.419: Tnl/Cl 43591/19 L2TP: O ICRP to hgw 49388/19
Jan 1 00:01:04.423: Tnl/Cl 43591/19 L2TP: I ICCN from hgw tnl 49388, cl 19
Jan 1 00:01:04.423: Tnl/Cl 43591/19 L2TP: Session state change from 
wait-connect to established
Jan 1 00:01:04.423: Vi1 VTEMPLATE: Hardware address 0090.b121.0c00
Jan 1 00:01:04.423: Vi1 VPDN: Virtual interface created for 2500-1
Jan 1 00:01:04.423: Vi1 PPP: Phase is DOWN, Setup
Jan 1 00:01:04.423: Vi1 VTEMPLATE: Has a new cloneblk vtemplate, 
now it has vtemplate
Jan 1 00:01:04.423: Vi1 VTEMPLATE: 
************* CLONE VACCESS1 *****************
Jan 1 00:01:04.423: Vi1 VTEMPLATE: Clone from Virtual-Template1
interface Virtual-Access1
default ip address
ppp authentication chap vpdn
ppp authorization vpdn
ppp multilink
pp chap hostname nsa-7200-2
end

Jan 1 00:01:04.479: %LINK-3-UPDOWN: Interface Virtual-Access1, 
changed state to up
Jan 1 00:01:04.479: Vi1 PPP: Using set call direction
Jan 1 00:01:04.479: Vi1 PPP: Treating connection as a callin
Jan 1 00:01:04.479: Vi1 PPP: Phase is ESTABLISHING, Passive Open
Jan 1 00:01:04.479: Vi1 CHAP: Using alternate hostname nsa-7200-2
Jan 1 00:01:04.479: Vi1 LCP: State is Listen
Jan 1 00:01:04.479: Vi1 VPDN: Bind interface direction=2
Jan 1 00:01:04.479: Vi1 LCP: I FORCED CONFREQ len 24
Jan 1 00:01:04.479: Vi1 LCP: AuthProto CHAP (0x0305C22305)
Jan 1 00:01:04.479: Vi1 LCP: MagicNumber 0x15C13B5D (0x050615C13B5D)
Jan 1 00:01:04.479: Vi1 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:04.479: Vi1 LCP: EndpointDisc 1 Local (0x130901353330302D31)
Jan 1 00:01:04.479: Vi1 VPDN: PPP LCP accepted rcv CONFACK
Jan 1 00:01:04.479: Vi1 LCP: I FORCED CONFACK len 19
Jan 1 00:01:04.479: Vi1 LCP: MagicNumber 0x31BFCE57 (0x050631BFCE57)
Jan 1 00:01:04.479: Vi1 LCP: MRRU 1524 (0x110405F4)
Jan 1 00:01:04.479: Vi1 LCP: EndpointDisc 1 Local (0x130901323530302D31)
Jan 1 00:01:04.479: Vi1 VPDN: PPP LCP accepted sent CONFACK
Jan 1 00:01:04.479: Vi1 PPP: Phase is AUTHENTICATING, by this end
Jan 1 00:01:04.483: Vi1 CHAP: O CHALLENGE id 3 len 31 from "nsa-7200-2"
Jan 1 00:01:04.483: Vi1 CHAP: I RESPONSE id 3 len 27 from "2500-1"
Jan 1 00:01:04.483: Vi1 PPP: Phase is FORWARDING
Jan 1 00:01:04.483: Vi1 VPDN: Looking for tunnel -- --
Jan 1 00:01:04.483: Vi1 VPDN: Looking for tunnel -- --
Jan 1 00:01:04.483: %SGBP-7-NEWL: Local query #54 for 2500-1, count 1,
 ourbid 50
Jan 1 00:01:04.483: Vi1 VPDN: Continue using SGBP for 2500-1
Jan 1 00:01:04.483: Vi1 VPDN: Pending
Jan 1 00:01:04.483: Vi1 VPDN: Process created
Jan 1 00:01:04.875: %SGBP-7-DONE: Query #54 for bundle 2500-1, count 1, 
master is 10.51.6.59
Jan 1 00:01:04.875: %SGBP-7-MQB: Bundle: 2500-1 State: Done OurBid: 050
Jan 1 00:01:04.875: %SGBP-7-PB: 10.51.6.59 State: Closed Bid: 10000 Retry: 0
Jan 1 00:01:04.875: Vi1 VPDN: Forwarding...
Jan 1 00:01:04.875: Vi1 Tnl/Cl 46/12 L2F: 
Session_create: Tunnel in closed state
Jan 1 00:01:04.875: Tnl 46 L2F: 
UDP socket opened to 10.51.6.59 using source 10.51.6.61
Jan 1 00:01:04.875: Tnl 46 L2F: 
Tunnel MULTIHOP state change from closed stateopening
Jan 1 00:01:04.875: Vi1 Tnl/Cl 46/12 L2F: 
Session state change from closed to waiting_for_tunnel
Jan 1 00:01:04.875: Vi1 Tnl/Cl 46/12 L2F: 
Session_create: Closed Tunnel being Re-Opened
Jan 1 00:01:04.875: Vi1 VPDN: 2500-1 is forwarded
Jan 1 00:01:04.879: Tnl 46 L2F: L2F_CONF received
Jan 1 00:01:04.879: Tnl 46 L2F: Received L2F-CONF from MULTIHOP
Jan 1 00:01:04.879: AAA/AUTHEN/START (3039224583): 
port='' list='default' action=SENDAUTH service=PPP
Jan 1 00:01:04.883: AAA/AUTHEN/START (3039224583): found list default
Jan 1 00:01:04.883: AAA/AUTHEN/START (3039224583): Method=LOCAL
Jan 1 00:01:04.883: AAA/AUTHEN (3039224583): status = PASS
Jan 1 00:01:04.883: AAA/AUTHEN/START (3797117540): 
port='' list='default' action=SENDAUTH service=PPP
Jan 1 00:01:04.883: AAA/AUTHEN/START (3797117540): found list default
Jan 1 00:01:04.883: AAA/AUTHEN/START (3797117540): Method=LOCAL
Jan 1 00:01:04.883: AAA/AUTHEN (3797117540): status = PASS
Jan 1 00:01:04.883: Tnl 46 L2F: 
Tunnel MULTIHOP state change from opening state open
Jan 1 00:01:04.883: Tnl 46 L2F: 
Replying with L2F-OPEN, Tunnel in Open-Wait
Jan 1 00:01:04.887: Tnl 46 L2F: L2F_OPEN received
Jan 1 00:01:04.887: Tnl 46 L2F: OPEN from MULTIHOP 
received for tunnel in state open
Jan 1 00:01:04.887: AAA/AUTHEN/START (228147723): 
port='' list='default' action=LOGIN service=PPP
Jan 1 00:01:04.887: AAA/AUTHEN/START (228147723): found list default
Jan 1 00:01:04.887: AAA/AUTHEN/START (228147723): Method=LOCAL
Jan 1 00:01:04.887: AAA/AUTHEN (228147723): status = PASS
Jan 1 00:01:04.887: VPDN: Chap authentication succeeded for MULTIHOP
Jan 1 00:01:04.887: Tnl 46 L2F: 
Tunnel MULTIHOP state change from open state open
Jan 1 00:01:04.887: Vi1 Tnl/Cl 46/12 L2F: 
Session state change from waiting_for_tunnel to opening
Jan 1 00:01:04.887: Vi1 Tnl/Cl 46/12 L2F: 
Sending OPEN for Open-Waiting Session
Jan 1 00:01:04.935: Vi1 Tnl/Cl 46/12 L2F: L2F_OPEN received
Jan 1 00:01:04.935: Vi1 Tnl/Cl 46/12 L2F: 
OPEN received for existing session in state opening
Jan 1 00:01:04.935: Vi1 Tnl/Cl 46/12 L2F: 
Session state change from opening to open
Jan 1 00:01:04.935: Vi1 Tnl/Cl 46/12 L2F: 
MID synced NAS/HG Clid=46/46 Mid=12
Jan 1 00:01:04.935: Vi1 PPP: Phase is FORWARDED
Jan 1 00:01:05.875: %LINEPROTO-5-UPDOWN: Line protocol on Interface 
Virtual-Access1, changed state to up

23982e.bmp

Related Information

Updated: Feb 04, 2010
Document ID: 23982