Date created: Friday, April 17, 2015 4:17:52 PM. Last modified: Friday, May 10, 2024 5:54:49 PM

PPP Session Establishment

PPP session establishment with LCP, NCP and IPCP.

References:
https://www.ietf.org/rfc/rfc1661.txt
http://www.ciscopress.com/articles/article.asp?p=2202412&seqNum=5

PPP Stages (from https://www.ietf.org/rfc/rfc1661.txt)

Link Dead
This phase occurs when the link fails, or one side has been told to disconnect (e.g. a user has finished his or her dialup connection.)

Link Establishment Phase
This phase is where Link Control Protocol negotiation is attempted. If successful, control goes either to the authentication phase or the Network-Layer Protocol phase, depending on whether authentication is desired.

Authentication Phase
This phase is optional. It allows the sides to authenticate each other before a connection is established. If successful, control goes to the network-layer protocol phase.

Network-Layer Protocol Phase
This phase is where each desired protocols' Network Control Protocols are invoked. For example, IPCP is used in establishing IP service over the line. Data transport for all protocols which are successfully started with their network control protocols also occurs in this phase. Closing down of network protocols also occur in this phase.

Link Termination Phase
This phase closes down this connection. This can happen if there is an authentication failure, if there are so many checksum errors that the two parties decide to tear down the link automatically, if the link suddenly fails, or if the user decides to hang up his connection.

PPP – Link Control Protocol (LCP)

The LCP functions within the data link layer and has a role in establishing, configuring, and testing the data-link connection. The LCP establishes the point-to-point link. The LCP also negotiates and sets up control options on the WAN data link, which are handled by the NCPs.

LCP inside PPP packet:

The LCP provides automatic configuration of the interfaces at each end, including

  • Handling varying limits on packet size
  • Detecting common misconfiguration errors
  • Terminating the link
  • Determining when a link is functioning properly or when it is failing

After the link is established, PPP also uses the LCP to agree automatically on encapsulation formats such as authentication, compression, and error detection.

 

LCP Stages


Initial
In the Initial state, the lower layer is unavailable (Down), and no Open has occurred. The Restart timer is not running in the Initial state.

Starting
The Starting state is the Open counterpart to the Initial state. An administrative Open has been initiated, but the lower layer is still unavailable (Down). The Restart timer is not running in the Starting state. When the lower layer becomes available (Up), a Configure-Request is sent.
 
Closed
In the Closed state, the link is available (Up), but no Open has occurred. The Restart timer is not running in the Closed state. Upon reception of Configure-Request packets, a Terminate-Ack is sent.  Terminate-Acks are silently discarded to avoid creating a loop.
 
Stopped
The Stopped state is the Open counterpart to the Closed state. It is entered when the automaton is waiting for a Down event after the This-Layer-Finished action, or after sending a Terminate-Ack. The Restart timer is not running in the Stopped state. Upon reception of Configure-Request packets, an appropriate response is sent. Upon reception of other packets, a Terminate- Ack is sent. Terminate-Acks are silently discarded to avoid creating a loop.
 
Rationale:
The Stopped state is a junction state for link termination, link configuration failure, and other automaton failure modes. These potentially separate states have been combined. There is a race condition between the Down event response (from the This-Layer-Finished action) and the Receive-Configure-Request event. When a Configure-Request arrives before the Down event, the Down event will supercede by returning the automaton to the Starting state. This prevents attack by repetition.
 
Implementation Option:
After the peer fails to respond to Configure-Requests, an implementation MAY wait passively for the peer to send Configure-Requests. In this case, the This-Layer-Finished action is not used for the TO- event in states Req-Sent, Ack-Rcvd and Ack-Sent. This option is useful for dedicated circuits, or circuits which have no status signals available, but SHOULD NOT be used for switched circuits.
 
Closing
In the Closing state, an attempt is made to terminate the connection. A Terminate-Request has been sent and the Restart timer is running, but a Terminate-Ack has not yet been received. Upon reception of a Terminate-Ack, the Closed state is entered. Upon the expiration of the Restart timer, a new Terminate-Request is transmitted, and the Restart timer is restarted. After the Restart timer has expired Max-Terminate times, the Closed state is entered.
 
Stopping
The Stopping state is the Open counterpart to the Closing state. A Terminate-Request has been sent and the Restart timer is running, but a Terminate-Ack has not yet been received.
 
Rationale:
The Stopping state provides a well defined opportunity to terminate a link before allowing new traffic. After the link has terminated, a new configuration may occur via the Stopped or Starting states.
 
Request-Sent
In the Request-Sent state an attempt is made to configure the connection. A Configure-Request has been sent and the Restart timer is running, but a Configure-Ack has not yet been received nor has one been sent.
 
Ack-Received
In the Ack-Received state, a Configure-Request has been sent and a Configure-Ack has been received. The Restart timer is still running, since a Configure-Ack has not yet been sent.
 
Ack-Sent
In the Ack-Sent state, a Configure-Request and a Configure-Ack have both been sent, but a Configure-Ack has not yet been received. The Restart timer is running, since a Configure-Ack has not yet been received.
 
Opened
In the Opened state, a Configure-Ack has been both sent and received. The Restart timer is not running. When entering the Opened state, the implementation SHOULD signal the upper layers that it is now Up. Conversely, when leaving the Opened state, the implementation SHOULD signal the upper layers that it is now Down.
 
 

PPP – Network Control Protocol (NCP)

PPP permits multiple network layer protocols to operate on the same communications link. For every network layer protocol used, PPP uses a separate NCP. For example, IPv4 uses the IP Control Protocol (IPCP) and IPv6 uses IPv6 Control Protocol (IPv6CP).

NCPs include functional fields containing standardized codes to indicate the network layer protocol that PPP encapsulates.

Establishing a PPP Session. There are three phases of establishing a PPP session:

Phase 1: Link establishment and configuration negotiation: Before PPP exchanges any network layer datagrams, such as IP, the LCP must first open the connection and negotiate configuration options. This phase is complete when the receiving router sends a configuration-acknowledgment frame back to the router initiating the connection.

Phase 2: Link quality determination (optional): The LCP tests the link to determine whether the link quality is sufficient to bring up network layer protocols. The LCP can delay transmission of network layer protocol information until this phase is complete.

Phase 3: Network layer protocol configuration negotiation: After the LCP has finished the link quality determination phase, the appropriate NCP can separately configure the network layer protocols, and bring them up and take them down at any time. If the LCP closes the link, it informs the network layer protocols so that they can take appropriate action.
 

The link remains configured for communications until explicit LCP or NCP frames close the link, or until some external event occurs such as an inactivity timer expiring, or an administrator intervening. The LCP can terminate the link at any time. This is usually done when one of the routers requests termination, but can happen because of a physical event, such as the loss of a carrier or the expiration of an idle-period timer.

LCP Operation

LCP operation includes provisions for link establishment, link maintenance, and link termination. LCP operation uses three classes of LCP frames to accomplish the work of each of the LCP phases:

  • Link-establishment frames establish and configure a link (Configure-Request, Configure-Ack, Configure-Nak, and Configure-Reject).
  • Link-maintenance frames manage and debug a link (Code-Reject, Protocol-Reject, Echo-Request, Echo-Reply, and Discard-Request).
  • Link-termination frames terminate a link (Terminate-Request and Terminate-Ack).

 

LCP Packet Fields

LCP Code

LCP Packet Type

Description

1

Configure-Request

Sent to open or reset a PPP connection. Configure-Request contains a list of LCP options with changes to default option values.

2

Configure-Ack

Sent when all of the values of all of the LCP options in the last Configure-Request received are recognized and acceptable. When both PPP peers send and receive Configure-Acks, the LCP negotiation is complete.

3

Configure-Nak

Sent when all the LCP options are recognized, but the values of some options are not acceptable. Configure-Nak includes the mismatching options and their acceptable values.

4

Configure-Reject

Set when LCP options are not recognized or not acceptable for negotiation. Configure-Reject includes the unrecognized or non-negotiable options.

5

Terminate-Request

Optionally sent to close the PPP connection.

6

Terminate-Ack

Sent in response to a Terminate-Request.

7

Code-Reject

Sent when the LCP code is unknown. The Code-Request message includes the rejected LCP packet.

8

Protocol-Reject

Sent when the PPP frame contains an unknown Protocol ID. The Protocol-Reject message includes the rejected LCP packet. Protocol-Reject is typically sent by a PPP peer in response to PPP NCP for a LAN protocol not enabled on the PPP peer.

9

Echo-Request

Optionally sent to test PPP connection.

10

Echo-Reply

Sent in response to an Echo-Request. The PPP Echo-Request and Echo-Reply are not related to the ICMP Echo Request and Echo Reply messages.

11

Discard-Request

Optionally sent to exercise the link in the outbound direction.

Link establishment is the first phase of LCP operation. This phase must complete successfully, before any network layer packets can be exchanged. During link establishment, the LCP opens the connection and negotiates the configuration parameters. The link establishment process starts with the initiating device sending a Configure-Request frame to the responder. The Configure-Request frame includes a variable number of configuration options needed to set up on the link.

The initiator includes the options for how it wants the link created, including protocol or authentication parameters. The responder processes the request:

  • If the options are not acceptable or not recognized, the responder sends a Configure-Nak or Configure-Reject message. If this occurs and the negotiation fails, the initiator must restart the process with new options.
  • If the options are acceptable, the responder responds with a Configure-Ack message and the process moves on to the authentication stage. The operation of the link is handed over to the NCP.

When NCP has completed all necessary configurations, including validating authentication if configured, the line is available for data transfer. During the exchange of data, LCP transitions into link maintenance.

 

Link Maintenance, LCP can use messages to provide feedback and test the link.

  • Echo-Request, Echo-Reply, and Discard-Request: These frames can be used for testing the link.

  • Code-Reject and Protocol-Reject: These frame types provide feedback when one device receives an invalid frame due to either an unrecognized LCP code (LCP frame type) or a bad protocol identifier. For example, if an uninterpretable packet is received from the peer, a Code-Reject packet is sent in response. The sending device will resend the packet.

Link Termination, After the transfer of data at the network layer completes, the LCP terminates the link. NCP only terminates the network layer and NCP link. The link remains open until the LCP terminates it. If the LCP terminates the link before NCP, the NCP session is also terminated. PPP can terminate the link at any time. This might happen because of the loss of the carrier, authentication failure, link quality failure, the expiration of an idle-period timer, or the administrative closing of the link. The LCP closes the link by exchanging Terminate packets. The device initiating the shutdown sends a Terminate-Request message. The other device replies with a Terminate-Ack. A termination request indicates that the device sending it needs to close the link. When the link is closing, PPP informs the network layer protocols so that they may take appropriate action.

LCP establishment, NCP establishment, ongoing LCP maintenance, then LCP termination when the connection is finished with:

 

LCP Negotiation Parameters

LCP can negotiate many PPP options, as follows:

  • MRU size—Maximum receive unit size (always accepted).

  • Magic number—Randomly generated number used to identify one end of a point-to-point connection. Each side negotiates its magic number, taking note of each other’s magic number. If both sides discover that the magic numbers they are negotiating are the same, each side attempts to change its magic number. If they are not successful, and the magic numbers remain the same, the session terminates because of the loopback that is detected. Magic numbers are always accepted.

  • Authentication—Requested if configured.

  • Protocol-Field-Compression (PFC) and Address-and-Control-Field-Compression (ACFC)—Accepted, but never requested.

  • Multilink PPP—Additional options can be negotiated when Multilink PPP is configured. See MLPPP Overview.

  • Async-Control-Character-Map (ACCM—Supported by PPP when used with an L2TP Network Server (LNS). ACCM allows PPP to indirectly support asynchronous PPP connections tunneled via a third-party L2TP Access Concentrator (LAC). PPP on the router uses the ACCM configuration data as supplied by the LAC via proxy LCP. The router does not directly support asynchronous PPP connections and will not negotiate an ACCM option unless directed to do so by a third-party LAC.

 

 

NCP Explained

After the link has been initiated, the LCP passes control to the appropriate NCP.

Although initially designed for IP packets, PPP can carry data from multiple network layer protocols by using a modular approach in its implementation. PPP’s modular model allows LCP to set up the link and then transfer the details of a network protocol to a specific NCP. Each network protocol has a corresponding NCP and each NCP has a corresponding RFC.

There are NCPs for IPv4, IPv6, IPX, AppleTalk, and many others. NCPs use the same packet format as the LCPs.

After the LCP has configured and authenticated the basic link, the appropriate NCP is invoked to complete the specific configuration of the network layer protocol being used. When the NCP has successfully configured the network layer protocol, the network protocol is in the open state on the established LCP link. At this point, PPP can carry the corresponding network layer protocol packets.

IPCP Example
After LCP has established the link, the routers exchange IPCP messages, negotiating options specific to the IPv4 protocol. IPCP is responsible for configuring, enabling, and disabling the IPv4 modules on both ends of the link. IPv6CP is an NCP with the same responsibilities for IPv6.

IPCP negotiates two options:

  • Compression: Allows devices to negotiate an algorithm to compress TCP and IP headers and save bandwidth. The Van Jacobson TCP/IP header compression reduces the size of the TCP/IP headers to as few as 3 bytes. This can be a significant improvement on slow serial lines, particularly for interactive traffic.
  • IPv4-Address: Allows the initiating device to specify an IPv4 address to use for routing IP over the PPP link, or to request an IPv4 address for the responder. Prior to the advent of broadband technologies such as DSL and cable modem services, dialup network links commonly used the IPv4 address option.

After the NCP process is complete, the link goes into the open state, and LCP takes over again in a link maintenance phase. Link traffic consists of any possible combination of LCP, NCP, and network layer protocol packets. When data transfer is complete, NCP terminates the protocol link; LCP terminates the PPP connection.

 

Example 1:

 

Example 2:

Apr 17 15:47:05: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
Apr 17 15:47:05: %DIALER-6-BIND: Interface Vi2 bound to profile Di0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP: Sending cstate UP notification
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP: Processing CstateUp message
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP: Change SIP state from Down to SSS Setup
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP: old[Down] event[CstateUp] state[SSS Setup]
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment: Provisioned
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     if_number     19
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     sub_if_number 19
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     ppp_vencap    0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     access id     1600000E
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     switch hdl    0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     sss circuit   0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     lcp magic     0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     local term    0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     lcp up        0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     punt to RP    0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     cond debug    1
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     vp_bound      0
Apr 17 2015 15:47:05.693 GMT: Vi2 PPP SIP segment:     fwded         0
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Received SSS-Mgr Need-More-Keys from SSS
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Change SIP state from SSS Setup to Binding
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: old[SSS Setup] event[MoreKeys] state[Binding]
Apr 17 2015 15:47:05.697 GMT: PPP: Alloc Context [8606B71C]
Apr 17 2015 15:47:05.697 GMT: ppp14 PPP: Initialized Context 8606B71C
Apr 17 2015 15:47:05.697 GMT: ppp14 PPP: Phase is ESTABLISHING
Apr 17 2015 15:47:05.697 GMT: PPP: Bind ppp14 to Virtual-Access2
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Static Bind peer_type[0]
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Send Message[Static Bind Response]
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Using dialer call direction
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Treating connection as a callout
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Session handle[A700000E] Session id[14]
Apr 17 2015 15:47:05.697 GMT: Vi2 LCP: Event[OPEN] State[Initial to Starting]
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: No remote authentication for call-out
Apr 17 2015 15:47:05.697 GMT: Vi2 LCP: O CONFREQ [Starting] id 1 len 10
Apr 17 2015 15:47:05.697 GMT: Vi2 LCP:    MagicNumber 0xA5301E2A (0x0506A5301E2A)
Apr 17 2015 15:47:05.697 GMT: Vi2 LCP: Event[UP] State[Starting to REQsent]
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Received Static Bind Response from PPP
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: Change SIP state from Binding to Up
Apr 17 2015 15:47:05.697 GMT: Vi2 PPP: old[Binding] event[PPPBindResp] state[Up]
Apr 17 2015 15:47:07.705 GMT: Vi2 LCP: O CONFREQ [REQsent] id 2 len 10
Apr 17 2015 15:47:07.705 GMT: Vi2 LCP:    MagicNumber 0xA5301E2A (0x0506A5301E2A)
Apr 17 2015 15:47:07.705 GMT: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP: I CONFREQ [REQsent] id 1 len 38
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    MagicNumber 0xECE52BEC (0x0506ECE52BEC)
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    MRRU 1524 (0x110405F4)
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    EndpointDisc 1 CP-LNS-NAME
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    (0x1313016C6E73312D74686E6C6F6E2E63)
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    (0x6F7265)
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP: O CONFREJ [REQsent] id 1 len 8
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    MRRU 1524 (0x110405F4)
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP: I CONFACK [REQsent] id 2 len 10
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP:    MagicNumber 0xA5301E2A (0x0506A5301E2A)
Apr 17 2015 15:47:07.729 GMT: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP: I CONFREQ [ACKrcvd] id 2 len 34
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    MagicNumber 0xECE52BEC (0x0506ECE52BEC)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    EndpointDisc 1 CP-LNS-NAME
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    (0x1313016C6E73312D74686E6C6F6E2E63)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    (0x6F7265)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP: O CONFACK [ACKrcvd] id 2 len 34
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    MagicNumber 0xECE52BEC (0x0506ECE52BEC)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    EndpointDisc 1 CP-LNS-NAME
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    (0x1313016C6E73312D74686E6C6F6E2E63)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP:    (0x6F7265)
Apr 17 2015 15:47:07.757 GMT: Vi2 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
Apr 17 2015 15:47:07.769 GMT: Vi2 PPP: Phase is AUTHENTICATING, by the peer
Apr 17 2015 15:47:07.769 GMT: Vi2 LCP: State is Open
Apr 17 2015 15:47:07.805 GMT: Vi2 CHAP: I CHALLENGE id 1 len 37 from "CP-LNS-NAME"
Apr 17 2015 15:47:07.805 GMT: Vi2 PPP: Sent CHAP SENDAUTH Request
Apr 17 2015 15:47:07.805 GMT: Vi2 PPP: Received SENDAUTH Response FAIL
Apr 17 2015 15:47:07.805 GMT: Vi2 CHAP: Using hostname from interface CHAP
Apr 17 2015 15:47:07.805 GMT: Vi2 CHAP: Using password from interface CHAP
Apr 17 2015 15:47:07.805 GMT: Vi2 CHAP: O RESPONSE id 1 len 45 from "username@realm.net"
Apr 17 2015 15:47:07.845 GMT: Vi2 CHAP: I SUCCESS id 1 len 4
Apr 17 2015 15:47:07.845 GMT: Vi2 PPP SSS: Forwarding request
Apr 17 2015 15:47:07.845 GMT: Vi2 PPP: Phase is FORWARDING, Attempting Forward
Apr 17 2015 15:47:07.845 GMT: Vi2 PPP: Queue IPCP code[1] id[1]
Apr 17 2015 15:47:07.849 GMT: Vi2 PPP: Received SSS-Mgr Connect-Local from SSS
Apr 17 2015 15:47:07.849 GMT: Vi2 PPP: Phase is ESTABLISHING, Finish LCP
Apr 17 2015 15:47:07.849 GMT: Vi2 PPP: Phase is UP
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: Protocol configured, start CP. state[Initial]
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: Event[OPEN] State[Initial to Starting]
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: O CONFREQ [Starting] id 1 len 10
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP:    Address 0.0.0.0 (0x030600000000)
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: Event[UP] State[Starting to REQsent]
Apr 17 2015 15:47:07.849 GMT: Vi2 CDPCP: Protocol configured, start CP. state[Initial]
Apr 17 2015 15:47:07.849 GMT: Vi2 CDPCP: Event[OPEN] State[Initial to Starting]
Apr 17 2015 15:47:07.849 GMT: Vi2 CDPCP: O CONFREQ [Starting] id 1 len 4
Apr 17 2015 15:47:07.849 GMT: Vi2 CDPCP: Event[UP] State[Starting to REQsent]
Apr 17 2015 15:47:07.849 GMT: Vi2 PPP: Process pending ncp packets
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: Redirect packet to Vi2
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: I CONFREQ [REQsent] id 1 len 10
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP:    Address 10.254.253.41 (0x03060AFEFD29)
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: O CONFACK [REQsent] id 1 len 10
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP:    Address 10.254.253.41 (0x03060AFEFD29)
Apr 17 2015 15:47:07.849 GMT: Vi2 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Apr 17 2015 15:47:07.849 GMT: Vi2 PPP: old[Up] event[LocalTerm] state[Up]
Apr 17 2015 15:47:07.849 GMT: Vi2 PPP SIP segment: Bind
Apr 17 15:47:07: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment: Update
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     if_number     19
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     sub_if_number 19
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     ppp_vencap    80489D80
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     access id     1600000E
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     switch hdl    0
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     sss circuit   0
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     lcp magic     A5301E2A
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     local term    1
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     lcp up        1
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     punt to RP    0
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     cond debug    1
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     vp_bound      0
Apr 17 2015 15:47:07.853 GMT: Vi2 PPP SIP segment:     fwded         0
Apr 17 2015 15:47:07.877 GMT: Vi2 IPCP: I CONFNAK [ACKsent] id 1 len 10
Apr 17 2015 15:47:07.877 GMT: Vi2 IPCP:    Address 100.65.16.16 (0x030664411010)
Apr 17 2015 15:47:07.877 GMT: Vi2 IPCP: O CONFREQ [ACKsent] id 2 len 10
Apr 17 2015 15:47:07.877 GMT: Vi2 IPCP:    Address 100.65.16.16 (0x030664411010)
Apr 17 2015 15:47:07.877 GMT: Vi2 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
Apr 17 2015 15:47:07.877 GMT: Vi2 LCP: I PROTREJ [Open] id 3 len 10 protocol CDPCP (0x01010006)
Apr 17 2015 15:47:07.877 GMT: Vi2 CDPCP: Event[Receive CodeRej-] State[REQsent to Stopped]
Apr 17 2015 15:47:07.953 GMT: Vi2 IPCP: I CONFACK [ACKsent] id 2 len 10
Apr 17 2015 15:47:07.953 GMT: Vi2 IPCP:    Address 100.65.16.16 (0x030664411010)
Apr 17 2015 15:47:07.953 GMT: Vi2 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
Apr 17 2015 15:47:07.961 GMT: Vi2 IPCP: State is Open
Apr 17 2015 15:47:07.961 GMT: Di0 IPCP: Install negotiated IP interface address 100.65.16.16
Apr 17 2015 15:47:07.961 GMT: Di0 Added to neighbor route AVL tree: topoid 0, address 10.254.253.41
Apr 17 2015 15:47:07.961 GMT: Di0 IPCP: Install route to 10.254.253.41

Example 3:

1941(config)#int atm0/1/0
1941(config-if)#no shut
*Jul 14 2015 14:35:39.283 BST: %LINK-3-UPDOWN: Interface Dialer1, changed state to up
*Jul 14 2015 14:35:39.283 BST: Event = Set Pkts to VA
*Jul 14 2015 14:35:39.283 BST: PPPATM: ATM0/1/0 0/38 [0], Event = Vaccess Up
*Jul 14 2015 14:35:39.287 BST: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
*Jul 14 2015 14:35:39.287 BST: %DIALER-6-BIND: Interface Vi2 bound to profile Di1
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Sending cstate UP notification
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Processing CstateUp message
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Change SIP state from Down to SSS Setup
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: old[Down] event[CstateUp] state[SSS Setup]
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment: Provisioned
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     if_number     20
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     sub_if_number 20
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     ppp_vencap    0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     access id     5000000B
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     switch hdl    0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     sss circuit   0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     lcp magic     0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     local term    0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     lcp up        0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     punt to RP    0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     cond debug    1
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     vp_bound      0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP SIP segment:     fwded         0
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Received SSS-Mgr Need-More-Keys from SSS
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Change SIP state from SSS Setup to Binding
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: old[SSS Setup] event[MoreKeys] state[Binding]
*Jul 14 2015 14:35:39.287 BST: PPP: Alloc Context [2AA6194C]
*Jul 14 2015 14:35:39.287 BST: ppp11 PPP: Initialized Context 2AA6194C
*Jul 14 2015 14:35:39.287 BST: ppp11 PPP: Phase is ESTABLISHING
*Jul 14 2015 14:35:39.287 BST: PPP: Bind ppp11 to Virtual-Access2
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Static Bind peer_type[0]
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Send Message[Static Bind Response]
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Using dialer call direction
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Treating connection as a callout
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Session handle[4500000B] Session id[11]
*Jul 14 2015 14:35:39.287 BST: Vi2 LCP: Event[OPEN] State[Initial to Starting]
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: No remote authentication for call-out
*Jul 14 2015 14:35:39.287 BST: Vi2 LCP: O CONFREQ [Starting] id 1 len 10
*Jul 14 2015 14:35:39.287 BST: Vi2 LCP:    MagicNumber 0x584FC994 (0x0506584FC994)
*Jul 14 2015 14:35:39.287 BST: Vi2 LCP: Event[UP] State[Starting to REQsent]
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Received Static Bind Response from PPP
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: Change SIP state from Binding to Up
*Jul 14 2015 14:35:39.287 BST: Vi2 PPP: old[Binding] event[PPPBindResp] state[Up]
*Jul 14 2015 14:35:39.471 BST: Vi2 LCP: I CONFACK [REQsent] id 1 len 10
*Jul 14 2015 14:35:39.471 BST: Vi2 LCP:    MagicNumber 0x584FC994 (0x0506584FC994)
*Jul 14 2015 14:35:39.471 BST: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
*Jul 14 2015 14:35:41.303 BST: Vi2 LCP: O CONFREQ [ACKrcvd] id 2 len 10
*Jul 14 2015 14:35:41.303 BST: Vi2 LCP:    MagicNumber 0x584FC994 (0x0506584FC994)
*Jul 14 2015 14:35:41.303 BST: Vi2 LCP: Event[Timeout+] State[ACKrcvd to REQsent]
*Jul 14 2015 14:35:41.311 BST: Vi2 LCP: I CONFACK [REQsent] id 2 len 10
*Jul 14 2015 14:35:41.311 BST: Vi2 LCP:    MagicNumber 0x584FC994 (0x0506584FC994)
*Jul 14 2015 14:35:41.311 BST: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP: I CONFREQ [ACKrcvd] id 183 len 19
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP:    MRU 1500 (0x010405DC)
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP:    MagicNumber 0x3F290377 (0x05063F290377)
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP: O CONFACK [ACKrcvd] id 183 len 19
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP:    MRU 1500 (0x010405DC)
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP:    MagicNumber 0x3F290377 (0x05063F290377)
*Jul 14 2015 14:35:42.403 BST: Vi2 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
*Jul 14 2015 14:35:42.411 BST: Vi2 PPP: Queue CHAP code[1] id[1]
*Jul 14 2015 14:35:42.423 BST: Vi2 PPP: No authorization without authentication
*Jul 14 2015 14:35:42.423 BST: Vi2 PPP: Phase is AUTHENTICATING, by the peer
*Jul 14 2015 14:35:42.423 BST: Vi2 CHAP: Redirect packet to Vi2
*Jul 14 2015 14:35:42.423 BST: Vi2 CHAP: I CHALLENGE id 1 len 57 from "acc-aln12.so-ex"
*Jul 14 2015 14:35:42.423 BST: Vi2 PPP: Sent CHAP SENDAUTH Request
*Jul 14 2015 14:35:42.423 BST: Vi2 LCP: State is Open
*Jul 14 2015 14:35:42.423 BST: Vi2 PPP: Received SENDAUTH Response FAIL
*Jul 14 2015 14:35:42.423 BST: Vi2 CHAP: Using hostname from interface CHAP
*Jul 14 2015 14:35:42.423 BST: Vi2 CHAP: Using password from interface CHAP
*Jul 14 2015 14:35:42.423 BST: Vi2 CHAP: O RESPONSE id 1 len 28 from "jb687@a"
*Jul 14 2015 14:35:42.607 BST: Vi2 CHAP: I SUCCESS id 1 len 16 msg is "BBEU18293443"
*Jul 14 2015 14:35:42.607 BST: Vi2 PPP SSS: Forwarding request
*Jul 14 2015 14:35:42.607 BST: Vi2 PPP: Phase is FORWARDING, Attempting Forward
*Jul 14 2015 14:35:42.607 BST: Vi2 PPP: Queue IPCP code[1] id[0]
*Jul 14 2015 14:35:42.607 BST: Vi2 PPP: Received SSS-Mgr Connect-Local from SSS
*Jul 14 2015 14:35:42.607 BST: Vi2 PPP: Phase is ESTABLISHING, Finish LCP
*Jul 14 2015 14:35:42.607 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
*Jul 14 2015 14:35:42.607 BST: Vi2 PPP: Phase is UP
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP: Protocol configured, start CP. state[Initial]
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP: Event[OPEN] State[Initial to Starting]
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP: O CONFREQ [Starting] id 1 len 10
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP:    Address 0.0.0.0 (0x030600000000)
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP: Event[UP] State[Starting to REQsent]
*Jul 14 2015 14:35:42.607 BST: Vi2 PPP: Process pending ncp packets
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP: Redirect packet to Vi2
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP: I CONFREQ [REQsent] id 0 len 10
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP:    Address 81.187.81.187 (0x030651BB51BB)
*Jul 14 2015 14:35:42.607 BST: Vi2 IPCP: O CONFACK [REQsent] id 0 len 10
*Jul 14 2015 14:35:42.611 BST: Vi2 IPCP:    Address 81.187.81.187 (0x030651BB51BB)
*Jul 14 2015 14:35:42.611 BST: Vi2 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP: old[Up] event[LocalTerm] state[Up]
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment: Bind
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment: Update
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     if_number     20
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     sub_if_number 20
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     ppp_vencap    21C97458
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     access id     5000000B
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     switch hdl    0
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     sss circuit   0
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     lcp magic     584FC994
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     local term    1
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     lcp up        1
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     punt to RP    0
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     cond debug    1
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     vp_bound      0
*Jul 14 2015 14:35:42.611 BST: Vi2 PPP SIP segment:     fwded         0
*Jul 14 2015 14:35:42.627 BST: Vi2 IPCP: I CONFNAK [ACKsent] id 1 len 10
*Jul 14 2015 14:35:42.627 BST: Vi2 IPCP:    Address 81.187.160.97 (0x030651BBA061)
*Jul 14 2015 14:35:42.627 BST: Vi2 IPCP: O CONFREQ [ACKsent] id 2 len 10
*Jul 14 2015 14:35:42.627 BST: Vi2 IPCP:    Address 81.187.160.97 (0x030651BBA061)
*Jul 14 2015 14:35:42.627 BST: Vi2 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
*Jul 14 2015 14:35:42.647 BST: Vi2 IPCP: I CONFACK [ACKsent] id 2 len 10
*Jul 14 2015 14:35:42.647 BST: Vi2 IPCP:    Address 81.187.160.97 (0x030651BBA061)
*Jul 14 2015 14:35:42.647 BST: Vi2 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
*Jul 14 2015 14:35:42.647 BST: Vi2 IPV6CP: I CONFREQ [UNKNOWN] id 0 len 14
*Jul 14 2015 14:35:42.647 BST: Vi2 IPV6CP:    Interface-Id 0203:97FF:FE19:8000 (0x010A020397FFFE198000)
*Jul 14 2015 14:35:42.647 BST: Vi2 LCP: O PROTREJ [Open] id 3 len 20 protocol IPV6CP (0x0100000E010A020397FFFE198000)
*Jul 14 2015 14:35:42.679 BST: Vi2 IPCP: State is Open
*Jul 14 2015 14:35:42.679 BST: Di1 IPCP: Install negotiated IP interface address 81.187.160.97
*Jul 14 2015 14:35:42.679 BST: Di1 IPCP: Install default route thru 81.187.81.187
*Jul 14 2015 14:35:42.679 BST: Di1 Added to neighbor route AVL tree: topoid 0, address 81.187.81.187
*Jul 14 2015 14:35:42.679 BST: Di1 IPCP: Install route to 81.187.81.187

1941#show ip route
S*    0.0.0.0/0 [1/0] via 81.187.81.187
      81.0.0.0/32 is subnetted, 2 subnets
C        81.187.81.187 is directly connected, Dialer1
C        81.187.160.97 is directly connected, Dialer1

In this example below one can see that IPCP is not being negotiated so the PPP session is establishing and the user is connecting, but they aren't being assigned an IP address. This is shown by "IPCP: I CONFREQ [Not negotiated] id 12 len 22" and "Vi46 LCP: O PROTREJ [Open] id 1 len 46 protocol IPCP". This error is informing that IP routing is not active/possible on this connection which is why the IPCP protocol cannot negotiate an IP address.

Looking in the RADIUS debug info the reason for this is that the two AV pairs are in the wrong order, the LNS is processing them in the order they are being received and the RADIUS server is sending them in the order they are stored in the RADIUS database. The LNS is trying to attach the user session to the Loopback interface which is in a VRF then attach the user session to the VRF, so this is the wrong order. Reversing the AV pair order in RADIUS fixes this issue here.

! This is the RADIUS debug output showing the AV pairs are back to front
.Dec 16 09:17:10.112 GMT: RADIUS/ENCODE(0004A84F):Orig. component type = VPDN
.Dec 16 09:17:10.112 GMT: RADIUS:  AAA Unsupported Attr: interface         [153] 15
.Dec 16 09:17:10.112 GMT: RADIUS:   55 6E 69 71 2D 53 65 73 73 2D 49 44 37           [Uniq-Sess-ID7]
.Dec 16 09:17:10.112 GMT: RADIUS(0004A84F): Storing nasport 768 in rad_db
.Dec 16 09:17:10.112 GMT: RADIUS(0004A84F): Config NAS IP: 172.31.253.101
.Dec 16 09:17:10.112 GMT: RADIUS/ENCODE(0004A84F): acct_session_id: 364061
.Dec 16 09:17:10.112 GMT: RADIUS(0004A84F): sending
.Dec 16 09:17:10.112 GMT: RADIUS(0004A84F): Send Access-Request to 10.0.0.1:1812 id 1645/165, len 183
.Dec 16 09:17:10.112 GMT: RADIUS:  authenticator CA 0A F2 17 57 2D 48 88 - 1C 30 F8 81 E3 52 01 48
.Dec 16 09:17:10.112 GMT: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
.Dec 16 09:17:10.112 GMT: RADIUS:  User-Name           [1]   36  "username@realm.net"
.Dec 16 09:17:10.112 GMT: RADIUS:  CHAP-Password       [3]   19  *
.Dec 16 09:17:10.112 GMT: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]
.Dec 16 09:17:10.112 GMT: RADIUS:  NAS-Port            [5]   6   768
.Dec 16 09:17:10.112 GMT: RADIUS:  Calling-Station-Id  [31]  36  "LWSHAR-C5#SC-06-048-LWSHAR-7 atm 0"
.Dec 16 09:17:10.112 GMT: RADIUS:  Called-Station-Id   [30]  42  "1/0/31:0.38@Remote-Agent-Id Not Present/"
.Dec 16 09:17:10.112 GMT: RADIUS:  Service-Type        [6]   6   Framed                    [2]
.Dec 16 09:17:10.112 GMT: RADIUS:  NAS-IP-Address      [4]   6   172.31.253.101
.Dec 16 09:17:10.116 GMT: RADIUS: Received from id 1645/165 10.0.0.1:1812, Access-Accept, len 195
.Dec 16 09:17:10.116 GMT: RADIUS:  authenticator 49 52 42 B8 51 09 08 A8 - 69 02 F4 FA 06 11 57 C7
.Dec 16 09:17:10.116 GMT: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
.Dec 16 09:17:10.116 GMT: RADIUS:  Framed-IP-Address   [8]   6   172.29.112.15
.Dec 16 09:17:10.116 GMT: RADIUS:  Framed-Route        [22]  48  "172.17.2.224 255.255.255.224 172.29.112.15 220"
.Dec 16 09:17:10.116 GMT: RADIUS:  Service-Type        [6]   6   Framed                    [2]
.Dec 16 09:17:10.116 GMT: RADIUS:  Vendor, Cisco       [26]  47
.Dec 16 09:17:10.116 GMT: RADIUS:   Cisco AVpair       [1]   41  "lcp:interface-config=ip unnumbered lo58"
.Dec 16 09:17:10.116 GMT: RADIUS:  Vendor, Cisco       [26]  62
.Dec 16 09:17:10.116 GMT: RADIUS:   Cisco AVpair       [1]   56  "lcp:interface-config=ip vrf forwarding usergroup1"
.Dec 16 09:17:10.116 GMT: RADIUS(0004A84F): Received from id 1645/165
.Dec 16 09:17:10.124 GMT: %LINK-3-UPDOWN: Interface Virtual-Access27, changed state to up
.Dec 16 09:17:10.124 GMT: RADIUS/ENCODE(0004A84F):Orig. component type = VPDN
.Dec 16 09:17:10.124 GMT: RADIUS(0004A84F): Using existing nas_port 768
.Dec 16 09:17:10.124 GMT: RADIUS(0004A84F): Config NAS IP: 172.31.253.101
.Dec 16 09:17:11.124 GMT: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access27, changed state to up


! This is the PPP debug output for a different user but with the exact same problem
.Dec 16 09:21:55.519 GMT:  EVT: Dynamic Bind 0 0x64E0EF08
.Dec 16 09:21:55.519 GMT: ppp94 PPP: Authorization required
.Dec 16 09:21:55.519 GMT: ppp94 PPP: Phase is ESTABLISHING
.Dec 16 09:21:55.519 GMT: ppp94 PPP: Send Message[Dynamic Bind Response]
.Dec 16 09:21:55.519 GMT: ppp94 EVT: Set LCP Open 2 0x00000000
.Dec 16 09:21:55.519 GMT: ppp94 LCP: I FORCED rcvd CONFACK len 11
.Dec 16 09:21:55.519 GMT: ppp94 LCP:    AuthProto CHAP (0x0305C22305)
.Dec 16 09:21:55.519 GMT: ppp94 LCP:    MagicNumber 0x4E659835 (0x05064E659835)
.Dec 16 09:21:55.519 GMT: ppp94 LCP: I FORCED sent CONFACK len 10
.Dec 16 09:21:55.519 GMT: ppp94 LCP:    MRU 1506 (0x010405E2)
.Dec 16 09:21:55.519 GMT: ppp94 LCP:    MagicNumber 0xACF3AFE8 (0x0506ACF3AFE8)
.Dec 16 09:21:55.519 GMT: ppp94 PPP: Phase is FORWARDING, Attempting Forward
.Dec 16 09:21:55.519 GMT: ppp94 EVT: Hook 1 0x00000000
.Dec 16 09:21:55.519 GMT: ppp94 PPP SSS: Receive SSS-Mgr Need-More-Keys
.Dec 16 09:21:55.519 GMT: ppp94 EVT: Hook 1 0x00000000
.Dec 16 09:21:55.519 GMT: ppp94 EVT: Forwarded 0 0x00000000
.Dec 16 09:21:55.519 GMT: ppp94 PPP: Phase is AUTHENTICATING, Unauthenticated User
.Dec 16 09:21:55.523 GMT: ppp94 PPP: Sent CHAP LOGIN Request
.Dec 16 09:21:55.527 GMT: ppp94 EVT: AAA Response 0 0x650BADF0
.Dec 16 09:21:55.527 GMT: ppp94 PPP: Received LOGIN Response PASS
.Dec 16 09:21:55.527 GMT: ppp94 PPP: Phase is FORWARDING, Attempting Forward
.Dec 16 09:21:55.527 GMT: ppp94 EVT: Hook 1 0x00000000
.Dec 16 09:21:55.527 GMT: ppp94 PPP SSS: Receive SSS-Mgr Connect-Local
.Dec 16 09:21:55.527 GMT: ppp94 PPP: Send Message[Connect Local]
.Dec 16 09:21:55.527 GMT: Vi134 EVT: Setup 0 0x00000000
.Dec 16 09:21:55.527 GMT: Vi134 PPP: Phase is DOWN, Setup
.Dec 16 09:21:55.527 GMT:  EVT: Static Bind 0 0x64E0EF08
.Dec 16 09:21:55.527 GMT: Vi134 PPP: Attempt to free context twice
.Dec 16 09:21:55.531 GMT: -Traceback= 60AE3B80 60B06ED0 60AFB608 60AFB7B8
.Dec 16 09:21:55.531 GMT: ppp94 PPP: Bind to [Virtual-Access134]
.Dec 16 09:21:55.531 GMT: Vi134 PPP: Send Message[Static Bind Response]
.Dec 16 09:21:55.535 GMT: %LINK-3-UPDOWN: Interface Virtual-Access134, changed state to up
.Dec 16 09:21:55.535 GMT: Vi134 EVT: Hook 1 0x00000000
.Dec 16 09:21:55.535 GMT: Vi134 EVT: Forwarded 0 0x00000000
.Dec 16 09:21:55.535 GMT: Vi134 PPP: Phase is AUTHENTICATING, Authenticated User
.Dec 16 09:21:55.535 GMT: Vi134 CHAP: O SUCCESS id 2 len 4
.Dec 16 09:21:55.535 GMT: Vi134 PPP: Phase is FORWARDING
.Dec 16 09:21:55.539 GMT: Vi134 EVT: Virtual Profile 0 0x651DB040
.Dec 16 09:21:55.539 GMT: Vi134 EVT: Virtualize 0 0x00000000
.Dec 16 09:21:55.539 GMT: Vi134 PPP: Phase is UP
.Dec 16 09:21:55.539 GMT: Vi134 PPP: Process pending ncp packets
.Dec 16 09:21:55.571 GMT: Vi134 EVT: IPCP Packet 0 0x6373CA9C
.Dec 16 09:21:55.575 GMT: Vi134 IPCP: I CONFREQ [Not negotiated] id 16 len 22
.Dec 16 09:21:55.575 GMT: Vi134 IPCP:    Address 0.0.0.0 (0x030600000000)
.Dec 16 09:21:55.575 GMT: Vi134 IPCP:    PrimaryDNS 0.0.0.0 (0x810600000000)
.Dec 16 09:21:55.575 GMT: Vi134 IPCP:    SecondaryDNS 0.0.0.0 (0x830600000000)
.Dec 16 09:21:55.575 GMT: Vi134 LCP: O PROTREJ [Open] id 1 len 46 protocol IPCP
.Dec 16 09:21:55.575 GMT: Vi134 LCP:  (0x80210110001603060000000081060000)
.Dec 16 09:21:55.575 GMT: Vi134 LCP:  (0x00008306000000000000000000000000)
.Dec 16 09:21:55.575 GMT: Vi134 LCP:  (0x00000000000000000000)
.Dec 16 09:21:56.535 GMT: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access134, changed state to up

 


^ Top

Previous page: PPP over L2TP Process Cycle
Next page: Pseudowires (PWE3)