Solaris Resources at Kempston

Analysing the asppp log file on Solaris 7 and Solaris 8

Perhaps you've configured your system as described in Configuring PPP on Solaris to connect to an ISP and it doesn't work. The reason for failure will be recorded in aspppd's log file /var/adm/log/asppp.log, but interpreting this log file is difficult without an understanding of the dial-up and PPP negotiation process. There's an excellent book on the subject entitled "Using and Managing PPP" by Andrew Sun, published by O'Reilly, ISBN 1-56592-321-9, and this is highly recommended if you're interested in learning more than is covered on this Web page.

This page offers a brief guide to understanding the log file by presenting the results of several dial-up connections and explaining each line in the log file. To display the contents of the log file while it is being written during the dial-up process, type:

	# tail -f /var/adm/log/asppp.log

in another window before running the dial-up script.

To display the log file after a connection attempt has failed, type:

	# more /var/adm/log/asppp.log

The dial-up process

The first two lines written to the log file are:

	17:34:01 Link manager (1196) started 02/03/00
	17:34:02 parse_config_file: Successful configuration

Each line is prefixed with a time stamp and these two lines record that the Link manager (the aspppd daemon) was started at 17:34:01 on February 3rd as process number 1196 and that it read and understood its configuration file in /etc/asppp.cf. If you see an error message here in place of "Successful configuration", there's a syntax error in the configuration file.

Each line in the log file is now described in turn.

	17:34:02 process_ipd_msg: ipdptp0 needs connection

"ipdptp0 needs connection" indicates that Solaris has detected that the destination of an outgoing TCP/IP packet is an address at the remote end of a dial-up link. ipdptp0 is the network device at the Solaris end of this link.

	conn(zulu-ppp)

This shows that a connection is about to be made to the remote system ("zulu-ppp") identified by the peer_system_name keyword in the "path" section associated with the ipdptp0 device in the /etc/asppp.cf file.

	Trying entry from '/etc/uucp/Systems' - device type ACU.
	Device Type ACU wanted

aspppd has looked up the entry for "zulu-ppp" in /etc/uucp/Systems and has found that it needs device type "ACU" in order to make a connection to the remote system. ACU is an abbreviation for "Automatic Call Unit" which is a fancy way of describing a modem.

	Trying device entry 'cua/b' from '/etc/uucp/Devices'.

aspppd has now looked up the entry for "ACU" in /etc/uucp/Devices and has found that device type ACU is associated with the modem attached to /dev/cua/b. It also notes from the same entry in /etc/uucp/Devices that this modem is of type "hayes".

	processdev: calling setdevcfg(ppp, ACU)
	fd_mklock: ok
	fixline(9, 115200)
	gdial(hayes) called

PPP is associated with device type ACU, the device is locked to prevent any other process from using it, the line speed is set to 115200 and a process called "gdial" is started to dial-up the remote number.

	Trying caller script 'hayes' from '/etc/uucp/Dialers'.

The entry for "hayes" in /etc/uucp/Dialers defines what should be sent to the modem to cause it to dial-out and make a connection to the remote system. The chat script in the hayes entry reads

"" P_ZERO "" \d "" ATZ\r OK ATDT\T\r\c CONNECT

and this consists of a series of expect/send pairs described in Configuring PPP on Solaris to connect to an ISP

	expect: ("")
	got it
	expect: ("")
	got it
	sendthem (DELAY
	^M)
	expect: ("")
	got it
	sendthem (ATZ^M^M)
	expect: (OK)
	^MATZ^MM^M^JOKgot it
	sendthem (ATDT1234567^M<NO CR>)
	expect: (CONNECT)
	^M^JATDT1234567^M^M^JCONNECTgot it
	getto ret 9

The log file shows what is expected from the modem at each point, what is sent by the modem to the local system and what is sent by aspppd to the modem.

Lines starting "expect:" show what the chat script is waiting for from the modem; "got it" is confirmation that the expected string has been found in the sequence of characters sent by the modem to the local system; "sendthem" shows what the local system is sending to the modem; and the other lines record the characters received from the modem.

It's worth examining this part of the log file carefully to check that the expect/send sequence corresponds to what is expected. In particular, if the log shows that a certain string is expected followed by an indication that the dial-out attempt has timed out, it's likely that the chat script is waiting for a response that never comes. The end of the chat script defined in the entry in /etc/uucp/Dialers normally ends with "CONNECT" showing that the next expected response from the modem is the notification that a connection to the remote system has been achieved.

When the local system receives the characters "CONNECT" from the modem, a connection has been established with the modem at the remote end of the link. "CONNECT" is the last expected string in the chat script from etc/uucp/Dialers and aspppd then looks in /etc/uucp/Systems to see what it should do next. If there's a further chat script in /etc/uucp/Systems designed to respond to Login and Password prompts from the remote system, this will be executed before aspppd switches into PPP. If there's no chat script in /etc/uucp/Systems, aspppd switches into PPP at this point and it will be necessary to authenticate using either PAP or CHAP. Examples of each type of authentication are provided below.

Login / Password authentication using a chat script

The next part of the log file shows what happens when /etc/uucp/Systems contains an authentication chat script such as:

	ogin: kempston word: secret "" STTY=crtscts

This chat script waits for a prompt from the remote end ending ogin:, responds to that prompt with the user name kempston, waits for a prompt ending word: and responds to that prompt with the password secret. Finally, it waits for nothing ("") and STTY=crtscts sets hardware flow control. The chat script then exits and aspppd switches into PPP mode. The log file records this dialogue:

	expect: (ogin:)
	 49333/ARQ/V90/LAPM/V42BIS^M^JWelcome to Zulu Internet^M^J^M^J^M^Jlogin:got it
	sendthem (kempston^M)
	expect: (word:)
	 kempston^M^JPassword:got it
	sendthem (secret^M)
	STTY crtscts
	call cleanup(0)

After this point, the log file contains a record of each PPP datagram sent and received over the link. The first few datagrams are concerned with negotiating a PPP connection and these will be covered next.

PPP negotiation

As soon as aspppd switches to PPP, it starts to negotiate a set of compatible PPP options with the remote end of the link. The first few datagrams are Link Control Protocol (LCP) packets and this protocol is concerned with establishing, maintaining and ending PPP. Before the link can be used to carry TCP/IP protocols, LCP is used to reach agreement about PPP options. Essentially, this part of the dialogue discovers whether the two ends of the link can talk the same language.

Immediately after the "call cleanup(0)" entry in the log file are the following records:

	17:34:49 000001 ipdptp0 ppp_diag: [ID 272263 kern.debug] SEND PPP
	ASYNC 23 Octets LCP Config-Req  ID=00 LEN=18 MRU=1500 MAG#=4a6eb851
	ProtFCOMP AddrCCOMP 

	17:34:49 000002 ipdptp0 ppp_diag: [ID 724474 kern.debug] RECEIVE PPP
	ASYNC 28 Octets NB LCP Config-Req  ID=01 LEN=23 ACCM=000a0000
	ProtFCOMP AddrCCOMP {Unknown OPTION=13 l=9} 13 09 03 00 c0 7b 6c db a7 

	17:34:49 000003 ipdptp0 ppp_diag: [ID 864262 kern.debug] RECEIVE PPP
	ASYNC 23 Octets LCP Config-ACK  ID=00 LEN=18 MRU=1500 MAG#=4a6eb851
	ProtFCOMP AddrCCOMP 

	17:34:49 000004 ipdptp0 ppp_diag: [ID 573792 kern.debug] SEND PPP
	ASYNC 18 Octets NB LCP Config-REJ  ID=01 LEN=13 {Unknown OPTION=13 l=9}
	13 09 03 00 c0 7b 6c db a7 

	17:34:50 000005 ipdptp0 ppp_diag: [ID 297503 kern.debug] RECEIVE PPP
	ASYNC 19 Octets NB LCP Config-Req  ID=02 LEN=14 ACCM=000a0000
	ProtFCOMP AddrCCOMP 

	17:34:50 000006 ipdptp0 ppp_diag: [ID 901460 kern.debug] SEND PPP
	ASYNC 19 Octets NB LCP Config-ACK  ID=02 LEN=14 ACCM=000a0000
	ProtFCOMP AddrCCOMP 

These log records are wrapped on the Web page for readability but each record is written as one line in the log. There are minor differences in the format of the PPP log records between Solaris 7 and Solaris 8 and the examples here are from Solaris 8. This is an example only: the precise nature and order of the dialogue will vary from one ISP to another and even between connections to the same ISP. If you follow the description of this sample log sequence, you should be able to make at least an intelligent guess about the meaning of any variations that you see when connecting to your own ISP.

The first packet sent by aspppd and recorded in the log is the opening suggestion in a negotiation process:

	17:34:49 000001 ipdptp0 ppp_diag: [ID 272263 kern.debug] SEND PPP
	ASYNC 23 Octets LCP Config-Req  ID=00 LEN=18 MRU=1500 MAG#=4a6eb851
	ProtFCOMP AddrCCOMP 

Each entry starts with a timestamp, a log serial number and the name of the network interface in use, ipdptp0. Each of the significant parts of this log file record are described separately:

	SEND PPP ASYNC 23 Octets LCP Config-Req

records that your local system is SENDing an ASYNChronous PPP packet to the remote end of the link. The packet is 23 octets (bytes) in length, it's an LCP (Link Control Protocol) packet and it's REQuesting a CONFIGuration.

There are several types of LCP packet and I'll describe these briefly at this point.

Config-Req is a configuration request, a suggestion that particular PPP options should be used on the link. The remote end is free to accept the suggestion or reject it and make an alternative proposal. This is very much a negotiation process between peers. If the two ends of the link reach agreement about the PPP options to be used, the link is established successfully. If they can't agree, the link fails.

Config-ACK is an acknowledgement, saying that the suggested options are acceptable.

Config-REJ is a rejection, saying that the suggested options are unacceptable.

Config-NACK is a counter-offer, saying that the suggested options are unsuitable and suggesting alternative options instead.

At any time, one end or the other can decide that it's not possible to reach agreement, and terminate the connection.

The rest of this first packet reads:

	ID=00 LEN=18 MRU=1500 MAG#=4a6eb851 ProtFCOMP AddrCCOMP

and this means that the local system is proposing an MRU (maximum transmission unit) size of 1500 bytes; a "magic number", essentially a random number that identifies this end of the link; protocol field compression, a compressed format for the protocol field in a PPP frame; and address and control field compression.

The next record in the log reads:

	17:34:49 000002 ipdptp0 ppp_diag: [ID 724474 kern.debug] RECEIVE PPP
	ASYNC 28 Octets NB LCP Config-Req  ID=01 LEN=23 ACCM=000a0000
	ProtFCOMP AddrCCOMP {Unknown OPTION=13 l=9} 13 09 03 00 c0 7b 6c db a7 

This is a datagram received from the remote end of the link. It's not a reply to the datagram just sent from our end but is the remote end's opening request (Config-Req) in the negotiation process. This is suggesting an Async Character Map (ACCM), which identifies characters in the ASCII set that the remote end wants escaping when sent across the link, and is also suggesting protocol field compression and address and control field compression. Finally, the log records that this LCP packet from the remote end is suggesting a particular PPP option (option 13) that is not understood by aspppd. Incidentally, asking for unknown options is perfectly acceptable: it's not necessary for a PPP implementation to support all possible PPP options and that fact allows development of the PPP protocol without rendering existing implementations obsolete. All that is necessary is that both ends of the link reach agreement on a mutually-acceptable set of options.

The next record:

	17:34:49 000003 ipdptp0 ppp_diag: [ID 864262 kern.debug] RECEIVE PPP
	ASYNC 23 Octets LCP Config-ACK  ID=00 LEN=18 MRU=1500 MAG#=4a6eb851
	ProtFCOMP AddrCCOMP 

shows a datagram received from the remote end which acknowledges and accepts (Config-ACK) the options suggested by our system in our first packet.

The next datagram sent by our system is a reply to the first datagram from the remote system:

	17:34:49 000004 ipdptp0 ppp_diag: [ID 573792 kern.debug] SEND PPP ASYNC
	18 Octets NB LCP Config-REJ  ID=01 LEN=13 
	{Unknown OPTION=13 l=9} 13 09 03 00 c0 7b 6c db a7 

It rejects the unknown option suggested by the remote system and the response:

	17:34:50 000005 ipdptp0 ppp_diag: [ID 297503 kern.debug] RECEIVE PPP
	ASYNC 19 Octets NB LCP Config-Req  ID=02 LEN=14 ACCM=000a0000
	ProtFCOMP AddrCCOMP 

shows that the remote end doesn't mind about our rejection of the unknown option; it repeats its initial suggestion less the unknown option. We then confirm that this revised set of options is acceptable (Config-ACK):

	17:34:50 000006 ipdptp0 ppp_diag: [ID 901460 kern.debug] SEND PPP
	ASYNC 19 Octets NB LCP Config-ACK  ID=02 LEN=14 ACCM=000a0000
	ProtFCOMP AddrCCOMP 

and that completes the LCP configuration of the PPP link: both ends have reached agreement on the PPP options to be used.

The PPP connection now moves to the network state which is concerned with configuring the network layer protocols carried by the link. This is done by means of a similar negotiation technique using a Network Control Protocol (NCP). One difference between the LCP and NCP negotiation processes is that, with NCP, options can be set differently for each direction on the link. Each end of the link must send a configure-request to the other end and seek agreement on the options to be used in that direction.

NCP is actually a family of protocols, one for each network layer protocol supported by PPP, and the only NCP protocol of concern here is the Internet Protocol Control Protocol (IPCP) for TCP/IP.

The IPCP datagrams recorded in the log are:

	17:34:50 000007 ipdptp0 ppp_diag: [ID 515506 kern.debug] SEND PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-Req  ID=01 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=0.0.0.0 

	17:34:50 000008 ipdptp0 ppp_diag: [ID 941403 kern.debug] RECEIVE PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-Req  ID=01 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.159.160.161 

	17:34:50 000009 ipdptp0 ppp_diag: [ID 858220 kern.debug] RECEIVE PPP
	ASYNC 15 Octets (A) IP_NCP Config-NACK  ID=01 LEN=10
	IPADDR=158.157.156.155 

	17:34:50 000010 ipdptp0 ppp_diag: [ID 272424 kern.debug] SEND PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-ACK  ID=01 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.159.160.161 

	17:34:50 000011 ipdptp0 ppp_diag: [ID 997898 kern.debug] SEND PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-Req  ID=02 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.157.156.155 

	17:34:50 000012 ipdptp0 ppp_diag: [ID 499739 kern.debug] RECEIVE PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-ACK  ID=02 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.157.156.155 

	17:34:50 start_ip: IP up on interface ipdptp0, timeout set for 300 seconds

The first of these requests (Config-Req) TCP/IP options that we'd like to have:

	17:34:50 000007 ipdptp0 ppp_diag: [ID 515506 kern.debug] SEND PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-Req  ID=01 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=0.0.0.0 

These suggest Van Jacobsen compression (VJCOMP), with the VJ compression parameter max-slot-id set to a value of 15 and comp-slot-id switched on, and an IP address for our end of the link of 0.0.0.0. An IP address of 0.0.0.0 is invalid but asking for this address is a means of asking the other end of the link to set our IP address. We expect the other end to reject the suggested address and provide a real IP address for our use.

The next datagram shows the IPCP options suggested by the remote end:

	17:34:50 000008 ipdptp0 ppp_diag: [ID 941403 kern.debug] RECEIVE PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-Req  ID=01 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.159.160.161

This happens to be almost identical to our suggestion with the addition that it's suggesting an IP address for the remote end of the PPP link of 158.159.160.161. Before we can reply to this, we receive a response to our opening suggestion:

	17:34:50 000009 ipdptp0 ppp_diag: [ID 858220 kern.debug] RECEIVE PPP
	ASYNC 15 Octets (A) IP_NCP Config-NACK  ID=01 LEN=10
	IPADDR=158.157.156.155

saying that we can't have an IP address for our end of the link of 0.0.0.0 and asking whether 158.157.156.155 would be acceptable instead. Before replying to this, we reply to datagram number 8, saying that we're happy with the suggested options and with the suggested remote IP address of 158.159.160.161.

	17:34:50 000010 ipdptp0 ppp_diag: [ID 272424 kern.debug] SEND PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-ACK  ID=01 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.159.160.161 

We then reply to datagram number 9, saying that we're happy to have a local IP address of 158.157.156.155:

	17:34:50 000011 ipdptp0 ppp_diag: [ID 997898 kern.debug] SEND PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-Req  ID=02 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.157.156.155

The remote end confirms that it's now happy:

	17:34:50 000012 ipdptp0 ppp_diag: [ID 499739 kern.debug] RECEIVE PPP
	ASYNC 21 Octets NB (A) IP_NCP Config-ACK  ID=02 LEN=16 VJCOMP
	MAXSID=15 Sid-comp-OK IPADDR=158.157.156.155 

and that ends the IPCP negotiation since both ends have sent a Config-ACK agreeing to the proposal from the other end of the link

aspppd now records in the log file that the PPP link is fully established and ready to pass IP traffic:

	17:34:50 start_ip: IP up on interface ipdptp0, timeout set for 300 seconds

That "IP up on interface ipdptp0" message is crucial. If that's not present in the log file, the link has failed and you'll need to analyse the PPP negotiation in detail to determine why it failed.

PAP authentication

When authenticaating using PAP (Password Authentication Protocol), authentication is part of the PPP negotiation. The chat script in /etc/uucp/Systems typically contains just:

	"" STTY=crtscts

and the aspppd log contains, after the dial-up process has established a connection:

	expect: ("")
	got it
	STTY crtscts
	call cleanup(0)

At this point, the PPP negotiation starts with LCP:

	17:40:26 000026 ipdptp0 ppp_diag: [ID 566553 kern.debug] SEND PPP 
	ASYNC 23 Octets LCP Config-Req  ID=05 LEN=18 MRU=1500 MAG#=33d44a42 
	ProtFCOMP AddrCCOMP 

	17:40:27 000027 ipdptp0 ppp_diag: [ID 786563 kern.debug] RECEIVE PPP 
	ASYNC 36 Octets NB LCP Config-Req  ID=01 LEN=31 MRU=1524 ACCM=000a0000 
	Auth=PAP ProtFCOMP AddrCCOMP {Unknown OPTION=13 l=9} 13 09 03 00 c0 7b 72 a8 12 

	17:40:27 000028 ipdptp0 ppp_diag: [ID 258571 kern.debug] RECEIVE PPP 
	ASYNC 23 Octets LCP Config-ACK  ID=05 LEN=18 MRU=1500 MAG#=33d44a42 
	ProtFCOMP AddrCCOMP 

	17:40:27 000029 ipdptp0 ppp_diag: [ID 163049 kern.debug] SEND PPP 
	ASYNC 18 Octets NB LCP Config-REJ  ID=01 LEN=13 
	{Unknown OPTION=13 l=9} 13 09 03 00 c0 7b 72 a8 12 

	17:40:27 000030 ipdptp0 ppp_diag: [ID 986753 kern.debug] RECEIVE PPP 
	ASYNC 27 Octets NB LCP Config-Req  ID=02 LEN=22 MRU=1524 ACCM=000a0000 
	Auth=PAP ProtFCOMP AddrCCOMP
 
	17:40:27 000031 ipdptp0 ppp_diag: [ID 814726 kern.debug] SEND PPP 
	ASYNC 27 Octets NB LCP Config-ACK  ID=02 LEN=22 MRU=1524 ACCM=000a0000 
	Auth=PAP ProtFCOMP AddrCCOMP 

This negotiation is very similar to the case already considered when authentication is performed with a Login/Password script before PPP starts. For this reason, I won't provide quite as much detail. Please read all the preceding discussion even if you aren't using Login/Password authentication. The first packet sent by our system:

	17:40:26 000026 ipdptp0 ppp_diag: [ID 566553 kern.debug] SEND PPP 
	ASYNC 23 Octets LCP Config-Req  ID=05 LEN=18 MRU=1500 MAG#=33d44a42 
	ProtFCOMP AddrCCOMP

suggests an MRU of 1500, provides a magic number and requests protocol field compression and address and control field compression.

The next packet:

	17:40:27 000027 ipdptp0 ppp_diag: [ID 786563 kern.debug] RECEIVE PPP 
	ASYNC 36 Octets NB LCP Config-Req  ID=01 LEN=31 MRU=1524 ACCM=000a0000 
	Auth=PAP ProtFCOMP AddrCCOMP {Unknown OPTION=13 l=9} 13 09 03 00 c0 7b 72 a8 12 

is identical to the opening packet received when authentication has already been completed, except that, because the remote end of the link knows that we haven't yet authenticated ourselves, it contains a request (Auth=PAP) to authenticate using PAP. The final LCP packet sent from our system:

	17:40:27 000031 ipdptp0 ppp_diag: [ID 814726 kern.debug] SEND PPP 
	ASYNC 27 Octets NB LCP Config-ACK  ID=02 LEN=22 MRU=1524 ACCM=000a0000 
	Auth=PAP ProtFCOMP AddrCCOMP 

agrees to the requests made by the remote system to use an MRU of 1524 and PAP authentication.

Before proceeding with the Network Control Protocol (NCP) phase of the negotiation, we have to authenticate ourselves using PAP:

	17:40:27 000032 ipdptp0 ppp_diag: [ID 338425 kern.debug] SEND PPP 
	ASYNC 35 Octets NB (A) AuthPAP Authenticate  ID=01 LEN=19 
	Peer-ID-Length= 8 Peer-ID: 6b 65 6d 70 73 74 6f 6e Passwd-Length= 5 
	Passwd: 73 65 63 72 65 74 

	17:40:27 000033 ipdptp0 ppp_diag: [ID 497307 kern.debug] RECEIVE PPP 
	ASYNC 205 Octets NB (A) AuthPAP Auth ACK  ID=01 LEN=12 Msg-Length= 7 
	Welcome

Our system sends an AuthPAP packet containing the length in bytes of the user name (Peer-ID-Length), the user name itself (Peer-ID), the length of the password (Passwd-Length) and the password (Passwd). The user name and the password are displayed in the log as ASCII characters. In case you can't easily translate hex ASCII characters into their character equivalents, here's a handy translation table:

	30  0      42  B      4d  M      58  X      69  i      74  t
	31  1      43  C      4e  N      59  Y      6a  j      75  u
	32  2      44  D      4f  O      5a  Z      6b  k      76  v
	33  3      45  E      50  P      61  a      6c  l      77  w
	34  4      46  F      51  Q      62  b      6d  m      78  x
	35  5      47  G      52  R      63  c      6e  n      79  y
	36  6      48  H      53  S      64  d      6f  o      7a  z
	37  7      49  I      54  T      65  e      70  p
	38  8      4a  J      55  U      66  f      71  q
	39  9      4b  K      56  V      67  g      72  r
	41  A      4c  L      57  W      68  h      73  s

Using this table, we can translate the Peer-ID value into "kempston" and the Passwd value into "secret".

The remote end checks the user name and password and sends an ACK, meaning that authentication was successful:

	17:40:27 000033 ipdptp0 ppp_diag: [ID 497307 kern.debug] RECEIVE PPP 
	ASYNC 205 Octets NB (A) AuthPAP Auth ACK  ID=01 LEN=12 Msg-Length= 7 
	Welcome

Negotiation then continues with NCP packets, in exactly the same way as described in the section which covers Login/Password authentication. When this is complete, the log records:

	17:40:28 start_ip: IP up on interface ipdptp0, timeout set for 300 seconds

and the link is ready to carry traffic.

CHAP authentication

CHAP authentication is much more secure than PAP. PAP transmits the password across the link as plain text and theoretically is subject to interception but CHAP doesn't send the password over the link at all. With CHAP authentication, the ISP sends your system a random string as a challenge. Your system encrypts this challenge using your password as the key and sends the result back. The ISP performs the same encryption and compares the two results. Authentication succeeds if the results match. The encryption algorithm is one-way so that, even if both the challenge and the encrypted result are intercepted, the algorithm cannot be reversed to derive the password.

This is a typical LCP negotiation when CHAP is used:

	21:21:08 000015 ipdptp0 ppp_diag: [ID 455822 kern.debug] RECEIVE PPP 
	ASYNC 30 Octets NB LCP Config-Req  ID=08 LEN=25 ACCM=000a0000 
	Auth=CHAP Alg=MD5 MAG#=dcda36f1 ProtFCOMP AddrCCOMP 

	21:21:08 000016 ipdptp0 ppp_diag: [ID 977013 kern.debug] SEND PPP 
	ASYNC 23 Octets NB LCP Config-Req  ID=04 LEN=18 MRU=1500 
	MAG#=b405f072 ProtFCOMP AddrCCOMP 

	21:21:08 000017 ipdptp0 ppp_diag: [ID 159798 kern.debug] SEND PPP 
	ASYNC 30 Octets NB LCP Config-ACK  ID=08 LEN=25 ACCM=000a0000 
	Auth=CHAP Alg=MD5 MAG#=dcda36f1 ProtFCOMP AddrCCOMP 

	21:21:08 000018 ipdptp0 ppp_diag: [ID 437702 kern.debug] RECEIVE PPP 
	ASYNC 23 Octets NB LCP Config-ACK  ID=03 LEN=18 MRU=1500 
	MAG#=b405f072 ProtFCOMP AddrCCOMP 

	21:21:08 000019 ipdptp0 ppp_diag: [ID 437704 kern.debug] RECEIVE PPP 
	ASYNC 23 Octets NB LCP Config-ACK  ID=04 LEN=18 MRU=1500 
	MAG#=b405f072 ProtFCOMP AddrCCOMP 

Points to note here are that the ISP asks us in packet number 15 to authenticate using the CHAP protocol with the MD5 encryption algorithm and that we agree to do so in packet number 17.

The CHAP authentication then proceeds:

	21:21:08 000020 ipdptp0 ppp_diag: [ID 151773 kern.debug] RECEIVE PPP 
	ASYNC 38 Octets NB CHAP Challenge  ID=05 LEN=33 Value-size= 16 
	Value: 22 43 f4 2d 48 2f 76 bc f3 21 e2 a4 fb 08 23 63 
	Name: MiltAP112as6

	21:21:08 000021 ipdptp0 ppp_diag: [ID 830045 kern.debug] SEND PPP 
	ASYNC 44 Octets NB (A) CHAP Response  ID=05 LEN=29 Value-size= 16 
	Value: d5 38 0b ec a1 fb 3c 96 2f b3 18 7e 8d b3 60 fc 
	Name: kempston

	21:21:09 000022 ipdptp0 ppp_diag: [ID 611023 kern.debug] RECEIVE PPP 
	ASYNC 9 Octets NB CHAP Success  ID=05 LEN=4 Message: 

The ISP sends us a CHAP challenge string in packet number 20, we encrypt this using the CHAP_secret (password) defined in /etc/asppp.cf and send the result back in packet number 21 with our login username. The ISP computes the same value, finds that their result matches ours and confirms that authentication has succeeded by sending us a "CHAP Success" in packet number 22.

IP_NCP negotiation then proceeds in much the same way as illustrated earlier and the log records:

	21:21:09 start_ip: IP up on interface ipdptp0, timeout set for 300 seconds

showing that the link is now fully up.

And finally ...

This is by no means an exhaustive treatment of the negotiation and authentication phases of a PPP connection. If you're interesting in learning more, Andrew Sun's book mentioned at the top of this page is the definitive text.

When I have time, I'll add some typical examples of PPP negotiation and authentication failures but I hope that what is presented here is sufficient to enable you to diagnose most failures to establish the PPP link. Almost all failures are caused by making typos in the configuration files, by specifying an incorrect user name or password or by using the wrong authentication method. If you're completely stuck, I'll be happy to help via email but please give me some evidence that you've tried to diagnose the problem yourself. Indicating that you've read and understood this page would be a good start!

Has this guide been useful?

I hope these instructions prove useful. If you have any comments or suggestions for improvement, or have found any technical errors, please email me at mike@kempston.net

This page is copyright © mike@kempston.net 2000. Reproduction is forbidden without the author's permission. You are welcome to link to these pages if you wish but please point to the pages at www.kempston.net: Solaris Resources at Kempston

This page is maintained by the Kempston Webmaster
Last updated 11 February 2000