PPP : LCP failed to negotiate

[alshamlan]

Dears,

I have a cisco 887 router and I have tested on two different DSL line. The first line it worked fine with while the other noe is not. both line on same exchange and establishing the ppp session with same BRAS. The debug seems that there Establishing phase failed, but my question here is how our BRAS will faied the establishing from on line while from other landline is working fine.

=============================================================

CISCO ROUTER Configuration

=======================

interface ATM0/1/0
no ip address
no ip mroute-cache
no atm ilmi-keepalive
dsl operating-mode auto
pvc 8/35
encapsulation aal5mux ppp dialer
dialer pool-member
!
interface Dialer1
ip address negotiated
ip nat outside
ip virtual-reassembly
encapsulation ppp
dialer pool 1
ppp chap hostname companyx
ppp chap password abcda123
ppp pap sent-username companyx password abcda123

===========================================

when I did ppp negotiation debug the below messages i got:

============================================

Mar 16 13:19:18.103: Vi2 PPP: Phase is DOWN

Mar 16 13:19:19.103: PPP: Alloc Context [85DEC77C]

Mar 16 13:19:19.103: ppp28 PPP: Phase is ESTABLISHING

Mar 16 13:19:19.103: Vi2 PPP: Using dialer call direction

Mar 16 13:19:19.103: Vi2 PPP: Treating connection as a callout

Mar 16 13:19:19.103: Vi2 PPP: Session handle[700001C] Session id[28]

Mar 16 13:19:19.103: Vi2 LCP: Event[OPEN] State[Initial to Starting]

Mar 16 13:19:19.103: Vi2 PPP: No remote authentication for call-out

Mar 16 13:19:19.103: Vi2 LCP: O CONFREQ [Starting] id 1 len 14

Mar 16 13:19:19.103: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:19.103: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:19.103: Vi2 LCP: Event[UP] State[Starting to REQsent]

Mar 16 13:19:21.111: Vi2 LCP: O CONFREQ [REQsent] id 2 len 14

Mar 16 13:19:21.111: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:21.111: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:21.111: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:23.127: Vi2 LCP: O CONFREQ [REQsent] id 3 len 14

Mar 16 13:19:23.127: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:23.127: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:23.127: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:25.143: Vi2 LCP: O CONFREQ [REQsent] id 4 len 14

Mar 16 13:19:25.143: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:25.143: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:25.143: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:27.159: Vi2 LCP: O CONFREQ [REQsent] id 5 len 14

Mar 16 13:19:27.159: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:27.159: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:27.159: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:29.175: Vi2 LCP: O CONFREQ [REQsent] id 6 len 14

Mar 16 13:19:29.175: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:29.175: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:29.175: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:31.191: Vi2 LCP: O CONFREQ [REQsent] id 7 len 14

Mar 16 13:19:31.191: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:31.191: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:31.191: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:33.207: Vi2 LCP: O CONFREQ [REQsent] id 8 len 14

Mar 16 13:19:33.207: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:33.207: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:33.207: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:35.223: Vi2 LCP: O CONFREQ [REQsent] id 9 len 14

Mar 16 13:19:35.223: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:35.223: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:35.223: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:37.239: Vi2 LCP: O CONFREQ [REQsent] id 10 len 14

Mar 16 13:19:37.239: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:37.239: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:37.239: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:39.255: Vi2 PPP DISC: LCP failed to negotiate

Mar 16 13:19:39.255: PPP: NET STOP send to AAA.

Mar 16 13:19:39.255: Vi2 PPP: No remote authentication for call-out

Mar 16 13:19:39.255: Vi2 LCP: Event[Timeout-] State[REQsent to Stopped]

Mar 16 13:19:39.255: Vi2 LCP: Event[DOWN] State[Stopped to Starting]

Mar 16 13:19:39.255: Vi2 PPP: Phase is DOWN

Mar 16 13:19:40.255: PPP: Alloc Context [85DEC77C]

Mar 16 13:19:40.255: ppp29 PPP: Phase is ESTABLISHING

Mar 16 13:19:40.255: Vi2 PPP: Using dialer call direction

Mar 16 13:19:40.255: Vi2 PPP: Treating connection as a callout

Mar 16 13:19:40.255: Vi2 PPP: Session handle[F400001D] Session id[29]

Mar 16 13:19:40.255: Vi2 LCP: Event[OPEN] State[Initial to Starting]

Mar 16 13:19:40.255: Vi2 PPP: No remote authentication for call-out

Mar 16 13:19:40.255: Vi2 LCP: O CONFREQ [Starting] id 1 len 14

Mar 16 13:19:40.255: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:40.255: Vi2 LCP:    MagicNumber 0xF2D10CAB (0x0506F2D10CAB

interface ATM0/1/0

no ip address

no ip mroute-cache

no atm ilmi-keepalive

dsl operating-mode auto

pvc 8/35

  encapsulation aal5mux ppp dialer

  dialer pool-member 1

!

!

interface Dialer1

ip address negotiated

ip nat outside

ip virtual-reassembly

encapsulation ppp

dialer pool 1

ppp chap hostname zara3087

ppp chap password 7 031E5A19150A27

ppp pap sent-username zara3087 password 7 131F1600180902

Mar 16 13:19:18.103: Vi2 PPP: Phase is DOWN

Mar 16 13:19:19.103: PPP: Alloc Context [85DEC77C]

Mar 16 13:19:19.103: ppp28 PPP: Phase is ESTABLISHING

Mar 16 13:19:19.103: Vi2 PPP: Using dialer call direction

Mar 16 13:19:19.103: Vi2 PPP: Treating connection as a callout

Mar 16 13:19:19.103: Vi2 PPP: Session handle[700001C] Session id[28]

Mar 16 13:19:19.103: Vi2 LCP: Event[OPEN] State[Initial to Starting]

Mar 16 13:19:19.103: Vi2 PPP: No remote authentication for call-out

Mar 16 13:19:19.103: Vi2 LCP: O CONFREQ [Starting] id 1 len 14

Mar 16 13:19:19.103: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:19.103: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:19.103: Vi2 LCP: Event[UP] State[Starting to REQsent]
Mar 16 13:19:21.111: Vi2 LCP: O CONFREQ [REQsent] id 2 len 14

Mar 16 13:19:21.111: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:21.111: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:21.111: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:23.127: Vi2 LCP: O CONFREQ [REQsent] id 3 len 14
Mar 16 13:19:23.127: Vi2 LCP:    MRU 1492 (0x010405D4)
Mar 16 13:19:23.127: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)
Mar 16 13:19:23.127: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]
Mar 16 13:19:25.143: Vi2 LCP: O CONFREQ [REQsent] id 4 len 14
Mar 16 13:19:25.143: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:25.143: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:25.143: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:27.159: Vi2 LCP: O CONFREQ [REQsent] id 5 len 14

Mar 16 13:19:27.159: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:27.159: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:27.159: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:29.175: Vi2 LCP: O CONFREQ [REQsent] id 6 len 14

Mar 16 13:19:29.175: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:29.175: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:29.175: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:31.191: Vi2 LCP: O CONFREQ [REQsent] id 7 len 14

Mar 16 13:19:31.191: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:31.191: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:31.191: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:33.207: Vi2 LCP: O CONFREQ [REQsent] id 8 len 14

Mar 16 13:19:33.207: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:33.207: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:33.207: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:35.223: Vi2 LCP: O CONFREQ [REQsent] id 9 len 14

Mar 16 13:19:35.223: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:35.223: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:35.223: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:37.239: Vi2 LCP: O CONFREQ [REQsent] id 10 len 14

Mar 16 13:19:37.239: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:37.239: Vi2 LCP:    MagicNumber 0xF2D0B9FD (0x0506F2D0B9FD)

Mar 16 13:19:37.239: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Mar 16 13:19:39.255: Vi2 PPP DISC: LCP failed to negotiate

Mar 16 13:19:39.255: PPP: NET STOP send to AAA.

Mar 16 13:19:39.255: Vi2 PPP: No remote authentication for call-out

Mar 16 13:19:39.255: Vi2 LCP: Event[Timeout-] State[REQsent to Stopped]

Mar 16 13:19:39.255: Vi2 LCP: Event[DOWN] State[Stopped to Starting]

Mar 16 13:19:39.255: Vi2 PPP: Phase is DOWN

Mar 16 13:19:40.255: PPP: Alloc Context [85DEC77C]

Mar 16 13:19:40.255: ppp29 PPP: Phase is ESTABLISHING

Mar 16 13:19:40.255: Vi2 PPP: Using dialer call direction

Mar 16 13:19:40.255: Vi2 PPP: Treating connection as a callout

Mar 16 13:19:40.255: Vi2 PPP: Session handle[F400001D] Session id[29]

Mar 16 13:19:40.255: Vi2 LCP: Event[OPEN] State[Initial to Starting]

Mar 16 13:19:40.255: Vi2 PPP: No remote authentication for call-out

Mar 16 13:19:40.255: Vi2 LCP: O CONFREQ [Starting] id 1 len 14

Mar 16 13:19:40.255: Vi2 LCP:    MRU 1492 (0x010405D4)

Mar 16 13:19:40.255: Vi2 LCP:    MagicNumber 0xF2D10CAB (0x0506F2D10CAB

[Peter Paluch]

Hello,

The debugs show that you are starting the LCP negotiation by sending the LCP CONFREQ messages. However, absolutely no LCP messages are being received from the other party. This is an important indication because it shows that the other party is not responding to your PPP session establishement requests.

This looks like you have a problem in sending and receiving PPP frames with the access concentrator. I suggest verifying these details:

• Has it been verified that the DSL modem has successfully trained to the DSLAM?
• Is the VPI/VCI combination of 8/35 correct for your provider?
• Your configuration is currently of the PPPoA kind. Is your provider using PPPoA or PPPoE?
• Is the AAL5MUX encapsulation correct? Is it possible that the provider uses AAL5SNAP?

Best regards,

Peter

[alshamlan]

Thanks peter for you answer.

please see my response and comments.

• Has it been verified that the DSL modem has successfully trained to the DSLAM?
  

It was working fine with other ISP, the circuit provider changed only the VPI/VCI to be pointed to our BRAS.

• Is the VPI/VCI combination of 8/35 correct for your provider?
  

Yes it is correct, and when I tested the circuit over small linksys router the link worked fine.

• Your configuration is currently of the PPPoA kind. Is your provider using PPPoA or PPPoE?
  

This point can be the issue, beacuse I checked the PPPoE over linksys router bu not PPPoA, when I checked PPPoA

it didnt work. How we I can change my configuration on cisco to have PPPoE?

• Is the AAL5MUX encapsulation correct? Is it possible that the provider uses AAL5SNAP?
  

Encapsulation is correct, I have been tesed the same configuraiton on other circuit and it worked fine.

Can you please advice about my comments espacially point 3

[Peter Paluch]

Hello,

The correct configuration of a PPPoE on the ATM interface would look as follows:

interface ATM0/1/0
 no ip address
 no ip mroute-cache
 no atm ilmi-keepalive
 dsl operating-mode auto
 pvc 8/35
  pppoe-client dial-pool-number 1

The configuration of the Dialer interface does not change. Give this a try!

Best regards,

Peter

[alshamlan]

Thanks Peter,

I will try it and get post my feedback.

Thanks for your cooperation.

regards

[ranjit123]

Hello alshamlan,

I Hope the issue is solved by now.

I also faced the same issue as below 

LCP failed to negotiate  <-------****
 

I investigated and reloaded the Router to fix the issue.

regards,

Ranjit

[caminantedevida]

Hi all, 

I've faced the same problem, the issue was that the primary phone cable was been plugged into the incorrect socket.

Before 

pprt085070001#show atm pvc
VCD / Peak Av/Min Burst
Interface Name VPI VCI Type Encaps SC Kbps Kbps Cells St
0/0/0.1 1 0 38 PVC MUX UBR 575 UP
0/1/0.1 1 0 38 PVC MUX UBR 832 UP

show ip inte brief

Virtual-Access3            unassigned      YES unset  up                    down

pprt085070001#sh pppatm sess

Uniq ID ATM-Intf VPI/VCI Encap VT VA VA-st State
N/A AT0/0/0.1 0/38 MUX Di1 Vi3 DOWN VA_AT
N/A AT0/1/0.1 0/38 MUX Di2 Vi2 UP VA_AT

484138: Jul 25 15:26:20.411: Vi3 PPP DISC: LCP failed to negotiate
484139: Jul 25 15:26:20.411: Vi3 PPP: Sending Acct Event[Down] id[78B4]
484140: Jul 25 15:26:20.411: PPP: NET STOP send to AAA.
484141: Jul 25 15:26:20.411: Vi3 PPP: No remote authentication for call-out
484142: Jul 25 15:26:20.411: Vi3 LCP: Event[Timeout-] State[REQsent to Stopped]
484143: Jul 25 15:26:20.411: Vi3 LCP: Event[DOWN] State[Stopped to Starting]
484144: Jul 25 15:26:20.411: Vi3 PPP: Phase is DOWN
484145: Jul 25 15:26:21.411: PPP: Alloc Context [308E86CC]
484146: Jul 25 15:26:21.411: ppp815 PPP: Phase is ESTABLISHING
484147: Jul 25 15:26:21.411: Vi3 PPP: Using dialer call direction
484148: Jul 25 15:26:21.411: Vi3 PPP: Treating connection as a callout
484149: Jul 25 15:26:21.411: Vi3 PPP: Session handle[E60000FF] Session id[815]
484150: Jul 25 15:26:21.411: Vi3 LCP: Event[OPEN] State[Initial to Starting]
484151: Jul 25 15:26:21.411: Vi3 PPP: No remote authentication for call-out
484152: Jul 25 15:26:21.411: Vi3 LCP: O CONFREQ [Starting] id 1 len 10
484153: Jul 25 15:26:21.411: Vi3 LCP: MagicNumber 0x1818CE4C (0x05061818CE4C)
484154: Jul 25 15:26:21.411: Vi3 LCP: Event[UP] State[Starting to REQsent]
484155: Jul 25 15:26:23.419: Vi3 LCP: O CONFREQ [REQsent] id 2 len 10
484156: Jul 25 15:26:23.419: Vi3 LCP: MagicNumber 0x1818CE4C (0x05061818CE4C)
484157: Jul 25 15:26:23.419: Vi3 LCP: Event[Timeout+] State[REQsent to REQsent]

After:

485407: Jul 25 15:39:24.799: PPPATM: ATM0/0/0.1 0/38, Event = VC event:4, VT:None
485408: Jul 25 15:39:24.991: PPPATM: ATM0/0/0.1 0/38 [0], Event = Up Pending
485409: Jul 25 15:39:24.991: PPPATM: ATM0/0/0.1 0/38, Event = VC event:2, VT:None
485410: Jul 25 15:39:25.903: PPPATM: ATM0/0/0.1 0/38 [0], Event = Up Dequeued
485411: Jul 25 15:39:25.903: PPPATM: ATM0/0/0.1 0/38 [0], Event = Processing Up
485412: Jul 25 15:39:25.903: Event = Set Pkts to VA
485413: Jul 25 15:39:25.903: PPPATM: ATM0/0/0.1 0/38 [0], Event = Vaccess Up
485414: Jul 25 15:39:25.907: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to up
485415: Jul 25 15:39:25.907: %DIALER-6-BIND: Interface Vi3 bound to profile Di1
485416: Jul 25 15:39:25.907: Vi3 PPP: Sending cstate UP notification
485417: Jul 25 15:39:25.907: Vi3 PPP: Processing CstateUp message
485418: Jul 25 15:39:25.907: PPP: Alloc Context [308E86CC]
485419: Jul 25 15:39:25.907: ppp836 PPP: Phase is ESTABLISHING
485420: Jul 25 15:39:25.907: Vi3 PPP: Using dialer call direction
485421: Jul 25 15:39:25.907: Vi3 PPP: Treating connection as a callout
485422: Jul 25 15:39:25.907: Vi3 PPP: Session handle[56000015] Session id[836]
485423: Jul 25 15:39:25.907: Vi3 LCP: Event[OPEN] State[Initial to Starting]
485424: Jul 25 15:39:25.907: Vi3 PPP: No remote authentication for call-out
pprt085070001#
485425: Jul 25 15:39:25.907: Vi3 LCP: O CONFREQ [Starting] id 1 len 10
485426: Jul 25 15:39:25.907: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485427: Jul 25 15:39:25.907: Vi3 LCP: Event[UP] State[Starting to REQsent]
485428: Jul 25 15:39:25.991: Vi3 LCP: I CONFACK [REQsent] id 1 len 10
485429: Jul 25 15:39:25.991: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485430: Jul 25 15:39:25.991: Vi3 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
pprt085070001#
485431: Jul 25 15:39:27.895: Vi3 LCP: O CONFREQ [ACKrcvd] id 2 len 10
485432: Jul 25 15:39:27.895: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485433: Jul 25 15:39:27.895: Vi3 LCP: Event[Timeout+] State[ACKrcvd to REQsent]
485434: Jul 25 15:39:27.915: Vi3 LCP: I CONFACK [REQsent] id 2 len 10
485435: Jul 25 15:39:27.915: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485436: Jul 25 15:39:27.915: Vi3 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
pprt085070001#
485437: Jul 25 15:39:29.171: Vi3 LCP: I CONFREQ [ACKrcvd] id 203 len 19
485438: Jul 25 15:39:29.171: Vi3 LCP: MRU 1500 (0x010405DC)
485439: Jul 25 15:39:29.171: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485440: Jul 25 15:39:29.171: Vi3 LCP: MagicNumber 0x7311D89A (0x05067311D89A)
485441: Jul 25 15:39:29.171: Vi3 LCP: O CONFACK [ACKrcvd] id 203 len 19
485442: Jul 25 15:39:29.171: Vi3 LCP: MRU 1500 (0x010405DC)
485443: Jul 25 15:39:29.171: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485444: Jul 25 15:39:29.171: Vi3 LCP: MagicNumber 0x7311D89A (0x05067311D89A)
485445: Jul 25 15:39:29.171: Vi3 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
485446: Jul 25 15:39:29.175: Vi3 PPP: Phase is AUTHENTICATING, by the peer
485447: Jul 25 15:39:29.175: Vi3 LCP: State is Open
485448: Jul 25 15:39:29.195: Vi3 CHAP: I CHALLENGE id 1 len 80 from "acc-aln1.nc-nth"
485449: Jul 25 15:39:29.195: Vi3 PPP: Sent CHAP SENDAUTH Request
485450: Jul 25 15:39:29.195: Vi3 PPP: Received SENDAUTH Response FAIL
485451: Jul 25 15:39:29.195: Vi3 CHAP: Using hostname from interface CHAP
485452: Jul 25 15:39:29.195: Vi3 CHAP: Using password from interface CHAP
485453: Jul 25 15:39:29.195: Vi3 CHAP: O RESPONSE id 1 len 47 from "BBEU15059115@o2entgw.co.uk"
485454: Jul 25 15:39:29.303: Vi3 LCP: I CONFREQ [Open] id 1 len 19
485455: Jul 25 15:39:29.303: Vi3 LCP: MRU 1490 (0x010405D2)
485456: Jul 25 15:39:29.303: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485457: Jul 25 15:39:29.303: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485458: Jul 25 15:39:29.303: Vi3 PPP DISC: PPP Renegotiating
485459: Jul 25 15:39:29.303: Vi3 PPP: Sending Acct Event[Reneg] id[78CA]
485460: Jul 25 15:39:29.303: PPP: NET STOP send to AAA.
485461: Jul 25 15:39:29.303: Vi3 LCP: Event[LCP Reneg] State[Open to Open]
485462: Jul 25 15:39:29.303: Vi3 LCP: Event[DOWN] State[Open to Starting]
485463: Jul 25 15:39:29.303: Vi3 PPP: Phase is DOWN
485464: Jul 25 15:39:29.307: PPP: Alloc Context [308E8500]
485465: Jul 25 15:39:29.307: ppp836 PPP: Phase is ESTABLISHING
485466: Jul 25 15:39:29.307: Vi3 PPP: Using dialer call direction
485467: Jul 25 15:39:29.307: Vi3 PPP: Treating connection as a callout
485468: Jul 25 15:39:29.307: Vi3 PPP: Session handle[2C000017] Session id[836]
485469: Jul 25 15:39:29.307: Vi3 LCP: Event[OPEN] State[Initial to Starting]
485470: Jul 25 15:39:29.307: Vi3 PPP: No remote authentication for call-out
485471: Jul 25 15:39:29.307: Vi3 LCP: O CONFREQ [Starting] id 1 len 10
485472: Jul 25 15:39:29.307: Vi3 LCP: MagicNumber 0x1824DA74 (0x05061824DA74)
485473: Jul 25 15:39:29.307: Vi3 LCP: Event[UP] State[Starting to REQsent]
485474: Jul 25 15:39:29.307: Vi3 LCP: I CONFREQ [REQsent] id 1 len 19
485475: Jul 25 15:39:29.307: Vi3 LCP: MRU 1490 (0x010405D2)
485476: Jul 25 15:39:29.307: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485477: Jul 25 15:39:29.307: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485478: Jul 25 15:39:29.307: Vi3 LCP: O CONFNAK [REQsent] id 1 len 8
485479: Jul 25 15:39:29.307: Vi3 LCP: MRU 1500 (0x010405DC)
485480: Jul 25 15:39:29.307: Vi3 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]
485481: Jul 25 15:39:29.335: Vi3 LCP: I CONFACK [REQsent] id 1 len 10
485482: Jul 25 15:39:29.335: Vi3 LCP: MagicNumber 0x1824DA74 (0x05061824DA74)
485483: Jul 25 15:39:29.335: Vi3 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
485484: Jul 25 15:39:29.335: Vi3 LCP: I CONFREQ [ACKrcvd] id 2 len 19
485485: Jul 25 15:39:29.335: Vi3 LCP: MRU 1500 (0x010405DC)
485486: Jul 25 15:39:29.335: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485487: Jul 25 15:39:29.335: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485488: Jul 25 15:39:29.335: Vi3 LCP: O CONFACK [ACKrcvd] id 2 len 19
485489: Jul 25 15:39:29.335: Vi3 LCP: MRU 1500 (0x010405DC)
485490: Jul 25 15:39:29.335: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485491: Jul 25 15:39:29.335: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485492: Jul 25 15:39:29.335: Vi3 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
485493: Jul 25 15:39:29.367: Vi3 PPP: Phase is AUTHENTICATING, by the peer
485494: Jul 25 15:39:29.367: Vi3 LCP: State is Open
485495: Jul 25 15:39:29.391: Vi3 CHAP: I CHALLENGE id 2 len 26 from "lns-2"
485496: Jul 25 15:39:29.391: Vi3 PPP: Sent CHAP SENDAUTH Request
485497: Jul 25 15:39:29.391: Vi3 PPP: Received SENDAUTH Response FAIL
485498: Jul 25 15:39:29.391: Vi3 CHAP: Using hostname from interface CHAP
485499: Jul 25 15:39:29.391: Vi3 CHAP: Using password from interface CHAP
485500: Jul 25 15:39:29.391: Vi3 CHAP: O RESPONSE id 2 len 47 from "BBEU15059115@o2entgw.co.uk"
485501: Jul 25 15:39:29.431: Vi3 CHAP: I SUCCESS id 2 len 4
485502: Jul 25 15:39:29.431: Vi3 PPP: Phase is FORWARDING, Attempting Forward
485503: Jul 25 15:39:29.431: Vi3 PPP: Queue IPCP code[1] id[1]
485504: Jul 25 15:39:29.431: Vi3 PPP: Phase is ESTABLISHING, Finish LCP
485505: Jul 25 15:39:29.431: Vi3 PPP: Phase is UP
485506: Jul 25 15:39:29.431: Vi3 IPCP: Protocol configured, start CP. state[Initial]
485507: Jul 25 15:39:29.431: Vi3 IPCP: Event[OPEN] State[Initial to Starting]
485508: Jul 25 15:39:29.431: Vi3 IPCP: O CONFREQ [Starting] id 1 len 10
485509: Jul 25 15:39:29.431: Vi3 IPCP: Address 10.10.0.242 (0x03060A0A00F2)
485510: Jul 25 15:39:29.431: Vi3 IPCP: Event[UP] State[Starting to REQsent]
485511: Jul 25 15:39:29.431: Vi3 CDPCP: Protocol configured, start CP. state[Initial]
485512: Jul 25 15:39:29.431: Vi3 CDPCP: Event[OPEN] State[Initial to Starting]
485513: Jul 25 15:39:29.431: Vi3 CDPCP: O CONFREQ [Starting] id 1 len 4
485514: Jul 25 15:39:29.431: Vi3 CDPCP: Event[UP] State[Starting to REQsent]
485515: Jul 25 15:39:29.431: Vi3 PPP: Process pending ncp packets
485516: Jul 25 15:39:29.431: Vi3 IPCP: Redirect packet to Vi3
485517: Jul 25 15:39:29.431: Vi3 IPCP: I CONFREQ [REQsent] id 1 len 10
485518: Jul 25 15:39:29.431: Vi3 IPCP: Address 172.16.101.100 (0x0306AC106564)
485519: Jul 25 15:39:29.431: Vi3 IPCP: O CONFACK [REQsent] id 1 len 10
485520: Jul 25 15:39:29.431: Vi3 IPCP: Address 172.16.101.100 (0x0306AC106564)
485521: Jul 25 15:39:29.431: Vi3 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
485522: Jul 25 15:39:29.435: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to up
485523: Jul 25 15:39:29.459: Vi3 IPCP: I CONFACK [ACKsent] id 1 len 10
485524: Jul 25 15:39:29.459: Vi3 IPCP: Address 10.10.0.242 (0x03060A0A00F2)
485525: Jul 25 15:39:29.459: Vi3 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
485526: Jul 25 15:39:29.463: Vi3 IPCP: State is Open
485527: Jul 25 15:39:29.463: Di1 Added to neighbor route AVL tree: topoid 2, address 172.16.101.100
485528: Jul 25 15:39:29.463: Di1 IPCP: Install route to 172.16.101.100
485529: Jul 25 15:39:29.463: Vi3 LCP: I PROTREJ [Open] id 3 len 10 protocol CDPCP (0x01010004)
485530: Jul 25 15:39:29.463: Vi3 CDPCP: Event[Receive CodeRej-] State[REQsent to Stopped]

[caminantedevida]

Hi all, 

I've faced the same problem, the issue was that the primary phone cable was been plugged into the incorrect socket.

Before 

---

@ranjit123 wrote:

Hello alshamlan,

I Hope the issue is solved by now.

I also faced the same issue as below 

LCP failed to negotiate  <-------****
 

I investigated and reloaded the Router to fix the issue.

regards,

Ranjit

---

#show atm pvc
VCD / Peak Av/Min Burst
Interface Name VPI VCI Type Encaps SC Kbps Kbps Cells St
0/0/0.1 1 0 38 PVC MUX UBR 575 UP
0/1/0.1 1 0 38 PVC MUX UBR 832 UP

show ip inte brief

Virtual-Access3            unassigned      YES unset  up                    down

#sh pppatm sess

Uniq ID ATM-Intf VPI/VCI Encap VT VA VA-st State
N/A AT0/0/0.1 0/38 MUX Di1 Vi3 DOWN VA_AT
N/A AT0/1/0.1 0/38 MUX Di2 Vi2 UP VA_AT

484138: Jul 25 15:26:20.411: Vi3 PPP DISC: LCP failed to negotiate
484139: Jul 25 15:26:20.411: Vi3 PPP: Sending Acct Event[Down] id[78B4]
484140: Jul 25 15:26:20.411: PPP: NET STOP send to AAA.
484141: Jul 25 15:26:20.411: Vi3 PPP: No remote authentication for call-out
484142: Jul 25 15:26:20.411: Vi3 LCP: Event[Timeout-] State[REQsent to Stopped]
484143: Jul 25 15:26:20.411: Vi3 LCP: Event[DOWN] State[Stopped to Starting]
484144: Jul 25 15:26:20.411: Vi3 PPP: Phase is DOWN
484145: Jul 25 15:26:21.411: PPP: Alloc Context [308E86CC]
484146: Jul 25 15:26:21.411: ppp815 PPP: Phase is ESTABLISHING
484147: Jul 25 15:26:21.411: Vi3 PPP: Using dialer call direction
484148: Jul 25 15:26:21.411: Vi3 PPP: Treating connection as a callout
484149: Jul 25 15:26:21.411: Vi3 PPP: Session handle[E60000FF] Session id[815]
484150: Jul 25 15:26:21.411: Vi3 LCP: Event[OPEN] State[Initial to Starting]
484151: Jul 25 15:26:21.411: Vi3 PPP: No remote authentication for call-out
484152: Jul 25 15:26:21.411: Vi3 LCP: O CONFREQ [Starting] id 1 len 10
484153: Jul 25 15:26:21.411: Vi3 LCP: MagicNumber 0x1818CE4C (0x05061818CE4C)
484154: Jul 25 15:26:21.411: Vi3 LCP: Event[UP] State[Starting to REQsent]
484155: Jul 25 15:26:23.419: Vi3 LCP: O CONFREQ [REQsent] id 2 len 10
484156: Jul 25 15:26:23.419: Vi3 LCP: MagicNumber 0x1818CE4C (0x05061818CE4C)
484157: Jul 25 15:26:23.419: Vi3 LCP: Event[Timeout+] State[REQsent to REQsent]

After:

485407: Jul 25 15:39:24.799: PPPATM: ATM0/0/0.1 0/38, Event = VC event:4, VT:None
485408: Jul 25 15:39:24.991: PPPATM: ATM0/0/0.1 0/38 [0], Event = Up Pending
485409: Jul 25 15:39:24.991: PPPATM: ATM0/0/0.1 0/38, Event = VC event:2, VT:None
485410: Jul 25 15:39:25.903: PPPATM: ATM0/0/0.1 0/38 [0], Event = Up Dequeued
485411: Jul 25 15:39:25.903: PPPATM: ATM0/0/0.1 0/38 [0], Event = Processing Up
485412: Jul 25 15:39:25.903: Event = Set Pkts to VA
485413: Jul 25 15:39:25.903: PPPATM: ATM0/0/0.1 0/38 [0], Event = Vaccess Up
485414: Jul 25 15:39:25.907: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to up
485415: Jul 25 15:39:25.907: %DIALER-6-BIND: Interface Vi3 bound to profile Di1
485416: Jul 25 15:39:25.907: Vi3 PPP: Sending cstate UP notification
485417: Jul 25 15:39:25.907: Vi3 PPP: Processing CstateUp message
485418: Jul 25 15:39:25.907: PPP: Alloc Context [308E86CC]
485419: Jul 25 15:39:25.907: ppp836 PPP: Phase is ESTABLISHING
485420: Jul 25 15:39:25.907: Vi3 PPP: Using dialer call direction
485421: Jul 25 15:39:25.907: Vi3 PPP: Treating connection as a callout
485422: Jul 25 15:39:25.907: Vi3 PPP: Session handle[56000015] Session id[836]
485423: Jul 25 15:39:25.907: Vi3 LCP: Event[OPEN] State[Initial to Starting]
485424: Jul 25 15:39:25.907: Vi3 PPP: No remote authentication for call-out
pprt085070001#
485425: Jul 25 15:39:25.907: Vi3 LCP: O CONFREQ [Starting] id 1 len 10
485426: Jul 25 15:39:25.907: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485427: Jul 25 15:39:25.907: Vi3 LCP: Event[UP] State[Starting to REQsent]
485428: Jul 25 15:39:25.991: Vi3 LCP: I CONFACK [REQsent] id 1 len 10
485429: Jul 25 15:39:25.991: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485430: Jul 25 15:39:25.991: Vi3 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
pprt085070001#
485431: Jul 25 15:39:27.895: Vi3 LCP: O CONFREQ [ACKrcvd] id 2 len 10
485432: Jul 25 15:39:27.895: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485433: Jul 25 15:39:27.895: Vi3 LCP: Event[Timeout+] State[ACKrcvd to REQsent]
485434: Jul 25 15:39:27.915: Vi3 LCP: I CONFACK [REQsent] id 2 len 10
485435: Jul 25 15:39:27.915: Vi3 LCP: MagicNumber 0x1824CD23 (0x05061824CD23)
485436: Jul 25 15:39:27.915: Vi3 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
pprt085070001#
485437: Jul 25 15:39:29.171: Vi3 LCP: I CONFREQ [ACKrcvd] id 203 len 19
485438: Jul 25 15:39:29.171: Vi3 LCP: MRU 1500 (0x010405DC)
485439: Jul 25 15:39:29.171: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485440: Jul 25 15:39:29.171: Vi3 LCP: MagicNumber 0x7311D89A (0x05067311D89A)
485441: Jul 25 15:39:29.171: Vi3 LCP: O CONFACK [ACKrcvd] id 203 len 19
485442: Jul 25 15:39:29.171: Vi3 LCP: MRU 1500 (0x010405DC)
485443: Jul 25 15:39:29.171: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485444: Jul 25 15:39:29.171: Vi3 LCP: MagicNumber 0x7311D89A (0x05067311D89A)
485445: Jul 25 15:39:29.171: Vi3 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
485446: Jul 25 15:39:29.175: Vi3 PPP: Phase is AUTHENTICATING, by the peer
485447: Jul 25 15:39:29.175: Vi3 LCP: State is Open
485448: Jul 25 15:39:29.195: Vi3 CHAP: I CHALLENGE id 1 len 80 from "acc-aln1.nc-nth"
485449: Jul 25 15:39:29.195: Vi3 PPP: Sent CHAP SENDAUTH Request
485450: Jul 25 15:39:29.195: Vi3 PPP: Received SENDAUTH Response FAIL
485451: Jul 25 15:39:29.195: Vi3 CHAP: Using hostname from interface CHAP
485452: Jul 25 15:39:29.195: Vi3 CHAP: Using password from interface CHAP
485453: Jul 25 15:39:29.195: Vi3 CHAP: O RESPONSE id 1 len 47 from "BBEU15059115@o2entgw.co.uk"
485454: Jul 25 15:39:29.303: Vi3 LCP: I CONFREQ [Open] id 1 len 19
485455: Jul 25 15:39:29.303: Vi3 LCP: MRU 1490 (0x010405D2)
485456: Jul 25 15:39:29.303: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485457: Jul 25 15:39:29.303: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485458: Jul 25 15:39:29.303: Vi3 PPP DISC: PPP Renegotiating
485459: Jul 25 15:39:29.303: Vi3 PPP: Sending Acct Event[Reneg] id[78CA]
485460: Jul 25 15:39:29.303: PPP: NET STOP send to AAA.
485461: Jul 25 15:39:29.303: Vi3 LCP: Event[LCP Reneg] State[Open to Open]
485462: Jul 25 15:39:29.303: Vi3 LCP: Event[DOWN] State[Open to Starting]
485463: Jul 25 15:39:29.303: Vi3 PPP: Phase is DOWN
485464: Jul 25 15:39:29.307: PPP: Alloc Context [308E8500]
485465: Jul 25 15:39:29.307: ppp836 PPP: Phase is ESTABLISHING
485466: Jul 25 15:39:29.307: Vi3 PPP: Using dialer call direction
485467: Jul 25 15:39:29.307: Vi3 PPP: Treating connection as a callout
485468: Jul 25 15:39:29.307: Vi3 PPP: Session handle[2C000017] Session id[836]
485469: Jul 25 15:39:29.307: Vi3 LCP: Event[OPEN] State[Initial to Starting]
485470: Jul 25 15:39:29.307: Vi3 PPP: No remote authentication for call-out
485471: Jul 25 15:39:29.307: Vi3 LCP: O CONFREQ [Starting] id 1 len 10
485472: Jul 25 15:39:29.307: Vi3 LCP: MagicNumber 0x1824DA74 (0x05061824DA74)
485473: Jul 25 15:39:29.307: Vi3 LCP: Event[UP] State[Starting to REQsent]
485474: Jul 25 15:39:29.307: Vi3 LCP: I CONFREQ [REQsent] id 1 len 19
485475: Jul 25 15:39:29.307: Vi3 LCP: MRU 1490 (0x010405D2)
485476: Jul 25 15:39:29.307: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485477: Jul 25 15:39:29.307: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485478: Jul 25 15:39:29.307: Vi3 LCP: O CONFNAK [REQsent] id 1 len 8
485479: Jul 25 15:39:29.307: Vi3 LCP: MRU 1500 (0x010405DC)
485480: Jul 25 15:39:29.307: Vi3 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]
485481: Jul 25 15:39:29.335: Vi3 LCP: I CONFACK [REQsent] id 1 len 10
485482: Jul 25 15:39:29.335: Vi3 LCP: MagicNumber 0x1824DA74 (0x05061824DA74)
485483: Jul 25 15:39:29.335: Vi3 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
485484: Jul 25 15:39:29.335: Vi3 LCP: I CONFREQ [ACKrcvd] id 2 len 19
485485: Jul 25 15:39:29.335: Vi3 LCP: MRU 1500 (0x010405DC)
485486: Jul 25 15:39:29.335: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485487: Jul 25 15:39:29.335: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485488: Jul 25 15:39:29.335: Vi3 LCP: O CONFACK [ACKrcvd] id 2 len 19
485489: Jul 25 15:39:29.335: Vi3 LCP: MRU 1500 (0x010405DC)
485490: Jul 25 15:39:29.335: Vi3 LCP: AuthProto CHAP (0x0305C22305)
485491: Jul 25 15:39:29.335: Vi3 LCP: MagicNumber 0xE25FF9FD (0x0506E25FF9FD)
485492: Jul 25 15:39:29.335: Vi3 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
485493: Jul 25 15:39:29.367: Vi3 PPP: Phase is AUTHENTICATING, by the peer
485494: Jul 25 15:39:29.367: Vi3 LCP: State is Open
485495: Jul 25 15:39:29.391: Vi3 CHAP: I CHALLENGE id 2 len 26 from "lns-2"
485496: Jul 25 15:39:29.391: Vi3 PPP: Sent CHAP SENDAUTH Request
485497: Jul 25 15:39:29.391: Vi3 PPP: Received SENDAUTH Response FAIL
485498: Jul 25 15:39:29.391: Vi3 CHAP: Using hostname from interface CHAP
485499: Jul 25 15:39:29.391: Vi3 CHAP: Using password from interface CHAP
485500: Jul 25 15:39:29.391: Vi3 CHAP: O RESPONSE id 2 len 47 from "BBEU15059115@o2entgw.co.uk"
485501: Jul 25 15:39:29.431: Vi3 CHAP: I SUCCESS id 2 len 4
485502: Jul 25 15:39:29.431: Vi3 PPP: Phase is FORWARDING, Attempting Forward
485503: Jul 25 15:39:29.431: Vi3 PPP: Queue IPCP code[1] id[1]
485504: Jul 25 15:39:29.431: Vi3 PPP: Phase is ESTABLISHING, Finish LCP
485505: Jul 25 15:39:29.431: Vi3 PPP: Phase is UP
485506: Jul 25 15:39:29.431: Vi3 IPCP: Protocol configured, start CP. state[Initial]
485507: Jul 25 15:39:29.431: Vi3 IPCP: Event[OPEN] State[Initial to Starting]
485508: Jul 25 15:39:29.431: Vi3 IPCP: O CONFREQ [Starting] id 1 len 10
485509: Jul 25 15:39:29.431: Vi3 IPCP: Address 10.10.0.242 (0x03060A0A00F2)
485510: Jul 25 15:39:29.431: Vi3 IPCP: Event[UP] State[Starting to REQsent]
485511: Jul 25 15:39:29.431: Vi3 CDPCP: Protocol configured, start CP. state[Initial]
485512: Jul 25 15:39:29.431: Vi3 CDPCP: Event[OPEN] State[Initial to Starting]
485513: Jul 25 15:39:29.431: Vi3 CDPCP: O CONFREQ [Starting] id 1 len 4
485514: Jul 25 15:39:29.431: Vi3 CDPCP: Event[UP] State[Starting to REQsent]
485515: Jul 25 15:39:29.431: Vi3 PPP: Process pending ncp packets
485516: Jul 25 15:39:29.431: Vi3 IPCP: Redirect packet to Vi3
485517: Jul 25 15:39:29.431: Vi3 IPCP: I CONFREQ [REQsent] id 1 len 10
485518: Jul 25 15:39:29.431: Vi3 IPCP: Address 172.16.101.100 (0x0306AC106564)
485519: Jul 25 15:39:29.431: Vi3 IPCP: O CONFACK [REQsent] id 1 len 10
485520: Jul 25 15:39:29.431: Vi3 IPCP: Address 172.16.101.100 (0x0306AC106564)
485521: Jul 25 15:39:29.431: Vi3 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
485522: Jul 25 15:39:29.435: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to up
485523: Jul 25 15:39:29.459: Vi3 IPCP: I CONFACK [ACKsent] id 1 len 10
485524: Jul 25 15:39:29.459: Vi3 IPCP: Address 10.10.0.242 (0x03060A0A00F2)
485525: Jul 25 15:39:29.459: Vi3 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
485526: Jul 25 15:39:29.463: Vi3 IPCP: State is Open
485527: Jul 25 15:39:29.463: Di1 Added to neighbor route AVL tree: topoid 2, address 172.16.101.100
485528: Jul 25 15:39:29.463: Di1 IPCP: Install route to 172.16.101.100
485529: Jul 25 15:39:29.463: Vi3 LCP: I PROTREJ [Open] id 3 len 10 protocol CDPCP (0x01010004)
485530: Jul 25 15:39:29.463: Vi3 CDPCP: Event[Receive CodeRej-] State[REQsent to Stopped]