test

System Administration Guide, Volume 3

Analyzing Diagnostic Output

When a PPP link runs correctly, the asppp.log file includes diagnostic information in addition to its normal output. This section explains what the diagnostic messages mean. If your output is different, refer to RFC 1331.

Host and Modem Setup

This section contains messages that occur as the local host sends configuration information to the modem, and then as the modem tries to dial the remote host. These initial activities are actually handled by the UUCP daemon. You might think of them as the UUCP portion of asynchronous PPP communications. (Refer to Chapter 25, Overview of UUCP for complete details on UUCP.)

The following two messages should always appear at the beginning of the session. They indicate that the aspppd daemon has started successfully.


11:53:33 Link manager (1057) started 04/14/94
11:53:33 parse_config_file: Successful configuration

The next line indicates that a packet was routed to the ipdptp0 interface on the local host. It helps you to determine if a dial-out is occurring correctly. For example, if you tried to ping the remote machine and this message isn't in asppp.log, the packet was lost, probably due to a routing problem.

Next, UUCP checks for an entry that matches Ppac7 in a chat script in the /etc/uucp/Systems file. It then reports that it found an entry that had a device type ACUTEC. (For more information on the Systems file, refer to "UUCP /etc/uucp/Systems File".) 


11:53:46 process_ipd_msg: ipdptp0 needs connection
conn(Ppac7)
Trying entry from '/etc/uucp/Systems' - device type ACUTEC.

UUCP then finds the dialing information for an ACUTEC dialer in the /etc/uucp/Devices file. When it finds the information, it opens the appropriate serial port on the local host and sets it with a speed of 9600. (For more information on /etc/uucp/Devices, see "UUCP /etc/uucp/Devices File".) 


Device Type ACUTEC wanted
Trying device entry 'cua/a' from '/etc/uucp/Devices'.
processdev: calling setdevcfg(ppp, ACUTEC)
fd_mklock: ok
fixline(8, 9600)
gdial(tb9600-ec) calle

UUCP checks for the entry tb9600 in the /etc/uucp/Dialers file and then sends out these messages. 


Trying caller script 'tb9600-ec' from '/etc/uucp/Dialers'
expect: ("")

The host waits a couple of seconds and then sets the registers on the modem. The information shown in the following log is modem specific. It comes from the /etc/uucp/Dialers file.


got it
sendthem (DELAY)
APAUSE
APAUSE
APAUSE
T&D2E1V1X1Q0S2=255S12=255S50=6S58=2^M<NO CR>)

The next lines are the dialog between the modem and the host machine. expect (OK^M) means that the host expects the modem to send an "okay." The words got it at the end of the second line indicate that the host got the "okay" message from the modem.


expect: (OK^M)
AAAT&D2E1V1X1Q0S2=255S12=255S50=6S58=2^M^M^JOK^Mgot it

Next, the host sends the following string to the modem, which does the actual dialing. The phone number in the second line is retrieved from the entry for the remote host in the /etc/uucp/Systems file.


sendthem (ECHO CHECK ON
A^JATTDDTT99003300887744^M^M<NO CR>)

The line beginning with expect indicates that the local host expects to get a response from the modem at a speed of 9600 bps. The next line indicates that the modem responded.


expect: (CONNECT 9600)
^M^JCONNECT 9600got it

This line indicates that hardware flow control has started on the link. The host obtains flow control information from the /etc/uucp/Dialers file.


STTY crtscts

In the next series of messages, the local host waits for the remote host to send it a standard UNIX login prompt.


getty ret 8
expect: ("")
got it
sandiest (^J^M)
expect: (login:)

The next messages indicate that the local host has received the login prompt from the remote. It then retrieves the appropriate login sequence from the chat script in the /etc/uucp/Systems entry for the remote host. This sequence is Ppong^M, which is required for login by the remote host.


^M^J^M^Jlogin:got it
sendthem (Ppong^M)

In these messages, the local host waits for the ssword prompt from the remote host. On receipt of the prompt, the local host sends the password retrieved from the chat script in the /etc/uucp/Systems entry for the remote host.


expect: (ssword:)
login: Ppong^M^JPassword:got it

The following messages indicate that dialing and modem connection completed successfully.


sendthem (ppptest1^M)
call cleanup(0)^M

Communications Between the Local and Remote Hosts

At this point, PPP communications start, as the link between local and remote hosts is now established.

The first lines in this part of the session constitute a configuration request (Config-Req). This is the first PPP packet sent to the remote host. The configuration request is one example of a Link Control Protocol (LCP) packet. It requests that configuration be set up and then sets up the PPP link between endpoint machines. The following example shows a sample configuration request.

Example 24-3 Configuration Request


11:54:20 004298 ipdptp0 SEND PPP ASYNC 29 Octets LCP Config-Req 
ID=4c LEN=24 MRU=1500 ACCM=00000000 MAG#=69f4f5b2 ProtFCOMP
AddrCCOMP

Here is a description of the configuration request.

The remaining items are a list of options to be negotiated between hosts.

The next lines are reporting invalid PPP packets. They come from the remote host, which is sending out UNIX text. This does not indicate a problem with PPP.


11:54:20 004299 ipdptp0 RECEIVE {Invalid ppp packet}PPP ASYNC 7
Octets [BAD FCS] {Unrecognized protocol:    1}

11:54:20 004299 ipdptp0 RECEIVE PPP ASYNC 73 Octets [BAD FCS]
{Unrecognized protocol:    880a}

In these packets, the local host receives the remote host's request for configuration, then sends out another configuration request. The packets are identical except for their ID fields. The ID field helps to distinguish between the two packets.


11:54:21 004301 ipdptp0 RECEIVE PPP ASYNC 29 Octets LCP Config-
Req  ID=35 LEN=24 MRU=1500 ACCM=00000000 MAG#=a8562e5f ProtFCOMP
AddrCCOMP

11:54:21 004302 ipdptp0 SEND PPP ASYNC 29 Octets LCP Config-Req 
ID=4d LEN=24 MRU=1500 ACCM=00000000 MAG#=69f4f5b2 ProtFCOMP
AddrCCOMP

In this packet, the local host acknowledges the remote request by sending it a configuration acknowledgment (Config-ACK).


11:54:21 004303 ipdptp0 SEND PPP ASYNC 29 Octets LCP Config-ACK 
ID=35 LEN=24 MRU=1500 ACCM=00000000 MAG#=a8562e5f ProtFCOMP
AddrCCOMP

The local host receives a configuration request (Config-Req) from the remote host.


11:54:21 004304 ipdptp0 RECEIVE PPP ASYNC 29 Octets LCP Config-
Req  ID=36 LEN=24 MRU=1500 ACCM=00000000 MAG#=a8562e5f ProtFCOMP
AddrCCOMP

In these packets, the local host acknowledges the second packet sent by the remote host and receives the remote host's acknowledgment. 


11:54:21 004305 ipdptp0 SEND PPP ASYNC 29 Octets LCP Config-ACK 
ID=36 LEN=24 MRU=1500 ACCM=00000000 MAG#=a8562e5f ProtFCOMP
AddrCCOMP

11:54:21 004306 ipdptp0 RECEIVE PPP ASYNC 29 Octets LCP Config-
ACK  ID=4d LEN=24 MRU=1500 ACCM=00000000 MAG#=69f4f5b2 ProtFCOMP
AddrCCOMP

Here the local host negotiates parameters about IP transmission. LEN=16 gives the packet size. VJCOMP indicates Van Jacobsen header compression. IPADDR is followed by the calling host's IP address.


11:54:21 004307 ipdptp0 SEND PPP ASYNC 21 Octets IP_NCP Config-
Req  ID=4e LEN=16 VJCOMP MAXSID=15 Sid-comp-OK IPADDR=192.9.68.70

This packet indicates that the local host has received IP configuration from the remote host, including its IP address. 


11:54:22 004308 ipdptp0 RECEIVE PPP ASYNC 21 Octets IP_NCP
Config-Req  ID=37 LEN=16 VJCOMP MAXSID=15 Sid-comp-OK
IPADDR=192.9.68.71

The local host sends this ACK to the remote host and receives an ACK from the remote host.


11:54:22 004309 ipdptp0 SEND PPP ASYNC 21 Octets IP_NCP Config-
ACK  ID=37 LEN=16 VJCOMP MAXSID=15 Sid-comp-OK IPADDR=192.9.68.71

11:54:22 004310 ipdptp0 RECEIVE PPP ASYNC 21 Octets IP_NCP
Config-ACK  ID=4e LEN=16 VJCOMP MAXSID=15 Sid-comp-OK
IPADDR=192.9.68.70

The first message that follows indicates that IP has started on the link. The next message indicates that the local host is sending IP traffic over the link. 


11:54:22 start_ip: IP up on interface ipdptp0, timeout set for
120 seconds

11:54:24 004311 ipdptp0 SEND PPP ASYNC 89 Octets IP_PROTO

In the first message that follows, the local host receives IP traffic from the remote host. The subsequent messages indicate that the interface was disconnected because of an idle timeout.


11:54:25 004312 ipdptp0 RECEIVE PPP ASYNC 89 Octets IP_PROTO
11:56:25 process_ipd_msg: interface ipdptp0 has disconnected
11:56:25 disconnect: disconnected connection from  ipdptp0

The next messages begin the termination sequence. The first message indicates that the remote host has sent a packet to terminate the IP layer. The second is the local host's acknowledgment of the request to terminate.


11:56:25 004313 ipdptp0 RECEIVE PPP ASYNC 9 Octets IP_NCP Term-
REQ  ID=38 LEN=4

11:56:25 004314 ipdptp0 SEND PPP ASYNC 9 Octets IP_NCP Term-ACK 
ID=38 LEN=4

The local host receives a request to terminate the LCP layer. The second message is an acknowledgment of the request, causing a graceful shutdown.


11:56:25 004315 ipdptp0 RECEIVE PPP ASYNC 9 Octets LCP Term-REQ 
ID=39 LEN=4

11:56:25 004316 ipdptp0 SEND PPP ASYNC 9 Octets LCP Term-ACK 
ID=39 LEN=4

This message indicates that the link has closed.


11:56:29 004317 ipdptp0 PPP DIAG CLOSE