Configuring the Point-to-Point Protocol (PPP)

Troubleshooting PPP negotiation

This section assumes host-to-host connectivity between the local and remote hosts. If this is not the case, see the appropriate following section first.

PPP negotiation involves at most four stages as described in ``PPP negotiation''. A failure may occur at any of these stages, causing the connection establishment to fail.

``Sample logfile of PPP negotiation'', shows the log entries of an example PPP negotiation session.

Sample logfile of PPP negotiation

  1 Feb 22 17:13:48 127.0.0.1 pppd[207]: Assigned link id for incoming link
  2 (login:nppp pid:327) is 14
  3 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):ICP:administrative
  4 open,Initial->Starting
  5 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):ICP:low layer up,Star
  6 ting->Req_sent
  7 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):ICP:Send config_req
  8 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):ICP:Receive config_req+
  9 ,Req_sent->Ack_Sent
 10 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):ICP:Send config_ack
 11 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):ICP:Receive config_ack
 12 ,Ack_Sent->Opened
 13 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:low layer up,
 14 Initial->Closed
 15 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:administrative open
 16 ,Closed->Req_sent
 17 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Send config_req
 18 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Send option MRU 1500
 19 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Send option ACCM
 20 ffffffff
 21 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Send option auth
 22 PAP
 23 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Send option magic
 24 number 46c6
 25 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive config_ack
 26 ,Req_sent->Ack_Rcvd
 27 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive option MRU
 28 1500 (Ack)
 29 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive option ACCM
 30 ffffffff (Ack)
 31 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive option auth
 32 PAP (Ack)
 33 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive option
 34 magic number:f2381e1f(Ack)
 35 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive option
 36 protocol compression (Ack)
 37 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive option
 38 addr&ctl compression (Ack)
 39 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Receive config_req+
 40 ,Ack_Rcvd->Opened
 41 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP:Send config_ack
 42 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):LCP negotiated options:
 43 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  local MRU:1500
 44 remote MRU:1500
 45 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  local ACCM:ffffffff
 46 remote ACCM:ffffffff
 47 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  local requires PAP
 48 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  remote requires PAP
 49 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  local disable
 50 protocol compression
 51 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  remote do
 52 protocol compression
 53 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  local disable
 54 addr&ctl compression
 55 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  remote do addr&ctl
 56 compression
 57 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):send a PAP_REQ packet:
 58 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  PID:mugwump.i88.
 59 isc.com
 60 Feb 22 17:13:48 127.0.0.1 pppd[206]: Link id(14):  PWD:Bull
 61 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):receive a PAP_REQ
 62 packet:
 63 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):  PID:krusty.i88.
 64 isc.com
 65 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):  PWD:Blazer
 66 Feb 22 17:13:49 127.0.0.1 pppd[207]: received PPCID_PAP
 67 Feb 22 17:13:49 127.0.0.1 pppd[207]: PPCID_PAP auth success
 68 Feb 22 17:13:49 127.0.0.1 pppd[207]: sent PPCID_PAP
 69 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):send a PAP_ACK packet
 70 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):receive a PAP_ACK packet
 71 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):IPCP:low layer up,
 72 Initial->Closed
 73 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):IPCP:administrative
 74 open,Closed->Req_sent
 75 Feb 22 17:13:49 127.0.0.1 pppd[206]: Link id(14):IPCP:Send config_req
 76 Feb 22 17:13:52 127.0.0.1 pppd[207]: received PPCID_PAP
 77 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):receive a PAP_REQ packet:
 78 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):  PID:krusty.i88.isc.com
 79 Feb 22 17:13:52 127.0.0.1 pppd[207]: PPCID_PAP auth success
 80 Feb 22 17:13:52 127.0.0.1 pppd[207]: sent PPCID_PAP
 81 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):  PWD:Blazer
 82 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):send a PAP_ACK packet
 83 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Timeout+,
 84 Req_sent->Req_sent
 85 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Send config_req
 86 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Receive option
 87 ip addresses,local:10.0.118.1
 88 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Receive option
 89 ip addresses,remote:10.0.246.8
 90 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Ack received
 91 option ip addresses
 92 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Receive option
 93 vj compression MSI:15 CSI:1 (Ack)
 94 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Receive config_
 95 req+,Req_sent->Ack_Sent
 96 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Send config_ack
 97 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP:Receive config_
 98 ack,Ack_Sent->Opened
 99 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):IPCP negotiated options:
100 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):  local address:132.
101 147.55.44
102 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):  remote address:132.
103 147.55.90
104 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):  local disable
105 vj compression
106 Feb 22 17:13:52 127.0.0.1 pppd[206]: Link id(14):  remote do vj
107 compression MSI:16 CSI:1
108 Feb 22 17:14:32 127.0.0.1 pppd[206]: Link id(14):IPCP:Receive
109 terminate_req,Opened->Stopping
110 Feb 22 17:14:32 127.0.0.1 pppd[206]: Link id(14):IPCP:Send terminate_ack
111 Feb 22 17:14:32 127.0.0.1 pppd[206]: Link id(14):LCP:Receive
112 terminate_req,Opened->Stopping
113 Feb 22 17:14:32 127.0.0.1 pppd[206]: Link id(14):LCP:Send terminate_ack
114 Feb 22 17:14:32 127.0.0.1 pppd[206]: Link id(14):IPCP:low layer down,
115 Stopping->Starting
116 Feb 22 17:14:33 127.0.0.1 pppd[206]: Link id(14):Received frame
117 abort with bad fcs=0x4751 msglen=0x10f
118 Feb 22 17:14:33 127.0.0.1 pppd[207]: received PPCID_CLOSE: muxid=14
119 Feb 22 17:14:33 127.0.0.1 pppd[206]: Link id(14):LCP:Timeout-,
120 Stopping->Stopped
121 Feb 22 17:14:33 127.0.0.1 pppd[206]: Link id(14):ICP:administrative
122 close,Opened->Closing
123 Feb 22 17:14:33 127.0.0.1 pppd[206]: Link id(14):ICP:Send terminate_req
124 Feb 22 17:14:33 127.0.0.1 pppd[206]: Link id(14):LCP:low layer down,
125 Stopped->Starting
126 Feb 22 17:14:33 127.0.0.1 pppd[207]: ppp_rm_conn: I_UNLINK muxid=14
127 Feb 22 17:14:33 127.0.0.1 pppd[206]: Link id(14):ICP:Receive
128 terminate_ack,Closing->Closed
129 Feb 22 17:14:33 127.0.0.1 pppd[206]: Link id(14):ICP:low layer down,
130 Closed->Initial
131 Feb 22 17:14:33 127.0.0.1 pppd[207]: ppp_rm_conn sending pid 327 SIGUSR1
132 Feb 22 17:14:33 127.0.0.1 pppd[207]: Incoming call on '/dev/tty1A'
133 disconnected
134 Feb 22 17:14:37 127.0.0.1 -ppp[327]: sig_hup sig=1

The logfile may contain information from many sources within a host. Using the log to troubleshoot PPP negotiation problems requires a recognition of PPP entries. All log entries contain a date and time stamp followed by the name or IP address of the host from which the log message originated. The next field in a log entry is the process that inserted the entry and its pid. All PPP entries are inserted by either the PPP daemon (shown as ``pppd'') or a PPP shell (shown as ``-ppp'').

Once host-to-host connectivity is established, the PPP daemon assigns a link ID to the connection. The following three lines show a link ID being assigned to an incoming link, an outgoing link, and a dedicated link, respectively.

Feb 22 17:13:48 127.0.0.1 pppd[207]: Assigned link id for incoming link
(login:nppp pid:327) is 14

Feb 22 19:13:48 127.0.0.1 pppd[207]: Assigned link id for outgoing link
(remote:10.0.118.6) is 17

Feb 22 21:13:48 127.0.0.1 pppd[207]: Assigned link id for dedicated link
(remote:10.0.118.10) is 14

To identify entries for the link you are troubleshooting, you need to know the login name for incoming links and the IP address of the remote system for dedicated or outgoing links.

The stage of negotiation is identified in each entry by the presence of ICP, LCP or IPCP. Log entries about the authentication stage do not have an identifier as ICP, LCP, and IPCP do. They do, however, include either the string ``PAP'' or ``CHAP'', which refer to the two authentication protocols that SCO OpenServer supports.

Examination of the log should progress from ICP, through LCP and authentication, to IPCP. If a failure occurs at an earlier stage, the later stages will never occur. For example, if a failure occurs at the LCP stage, no authentication or IPCP negotiation will occur. Following is a description of the key information to look for at each stage.

ICP stage

This stage is implementation specific to SCO PPP. (The other three stages are RFC standards.) This stage is for the exchange of information between the PPP driver and the asyhdlc module on the local system. A failure at this stage is very rare. Lines 11 and 12 of ``Sample logfile of PPP negotiation'', show the line that reflects ICP success. The key element in this entry is the PPP state change: Ack_Sent->Opened.

LCP stage

The LCP stage is negotiated according to the PPP Link Control Protocol. The following parameters are negotiated at this stage: maximum receive units value, asynchronous control character map, magic number, authentication protocol, protocol field compression, and address-control field compression. Lines 13-56 in ``Sample logfile of PPP negotiation'', show a typical LCP negotiation.

If authentication or IPCP entries appear for the link ID you are troubleshooting, then the LCP stage was successful. If successful, the value/state of the parameters negotiated will be listed in the logfile as shown in lines 43-56 of the example. This list may be repeated in the logfile.

If no authentication or IPCP entries appear, then a problem might exist with LCP negotiation. Typical problems at this stage are:

The local host does not receive any good packets from the remote host. If this occurs, you will see many LCP entries that say Send, but none that say Receive. Reasons that this might occur include: a bad checksum in response packets from the remote host, badly formatted packets from the remote host, or no packets received from the remote host.
The local and remote hosts disagree about parameters. If this occurs, you will see NAK and Reject entries. A NAK or Reject will be present for a particular parameter. Try changing the value/state of the parameter causing the NAK or rejection.

Authentication stage

As mentioned above, this stage is optional and only occurs if either the local or remote system requires authentication for this connection. Lines 57-70 in ``Sample logfile of PPP negotiation'' show a typical authentication negotiation.

If IPCP entries appear for your interface, then the authentication stage was successful. If no IPCP entries appear and LCP appears to have completed successfully (no NAKs or Rejects on LCP stage packets), then a problem is likely with authentication. Look for an authentication entry with a PAP or CHAP failure indicated. Typical problems here are the sending of an incorrect password or incorrect packet ID. See the pppauth(SFF) manual page for more information on authentication entries and exchanges.

IPCP stage

If all of the preceding stages appear successful but the connection still fails, the problem is in the IPCP negotiation stage. The following parameters are negotiated at this stage: IP addresses and Van Jacobson TCP/IP header compression. The typical problem at this stage is a disagreement about these parameters between the local and remote systems. If this occurs, you will see a NAK or Reject entry for a particular parameter. Try changing the value/state of the parameter causing the NAK or rejection.