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.
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 12, UUCP Databases and Programs, for complete details on UUCP.)
The two messages below 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 looks 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 "/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 "/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 looks 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 log below 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 string below 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. Upon 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 |
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. Example 10-4 shows a sample 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 shown in Example 10-4.
11:54:20 - Time stamp field, indicating the time when the packet was sent
004298 - Number of the packet
ipdptp0 - Network interface used
SEND PPP ASYNC - Indicates that the modem is sending asynchronous PPP
29 Octets - Amount of data the host sent
LCP - Packet type to send
ID=4c - Identifier associated with the packet; it is actually part of the packet
LEN=24 - Length of the LCP part of the packet
The remaining items are a list of options to be negotiated between hosts.
MRU=1500 - Maximum Receive Unit (MRU), the largest packet size the calling host can receive from the remote host
ACCM=00000000 - Asynchronous Character Map (ACCM), the mask sent to the remote host that tells what control characters to escape on transmission
MAG#=69f4f5b2 - Magic number field; used for loopback detection mechanism
ProtFCOMP AddrCCOMP - Asks for the remote host to compress certain parts of the frame header (protocol field, address field).
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 below 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 below the local host receives IP traffic from the remote host. The subsequent messages indicate that the interface was disconnected because of an idle time-out.
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 |