The broken PPP saga continues!
Okay... for those who offered to look at my scripts and such, here's
everything you'd ever need to know about what's going on, I hope.
I put a lot of time into organizing the information into something easy to
read, so, even though it's long, I'd appreciate it if you'd take the time
to give it a look.... but only if you know a thing or two about PPP.
First, I'll give you how things look on the *SERVER* side... the Debain
box I'm dialing into. Keep in mind that this is the machine that runs our
modem pool of four modems and we've never had any complaints of people
not being able to connect or getting dropped.
Now, among other entries, "ifconfig" returns the following. "ppp1" is a
win95 connection that I just connected with for comparison. "ppp3" is the one
from the Debian machine that can't get pings back. The "ppp2" is another
user... probably Win95.... included here in case it helps. In the logs posted
below, the the interface is ppp0, so don't go telling me that I'm looking
at the wrong thing. The logs that are posted and the "ifconfig" output,
albeit from different "sessions", represent sessions that were identical
in respect to their "brokenness".
##############
ppp1 Link encap:Point-Point Protocol
inet addr:207.114.134.1 P-t-P:207.114.134.200 Mask:255.255.255.0
UP POINTOPOINT RUNNING MTU:1500 Metric:1
RX packets:156 errors:0 dropped:0 overruns:0
TX packets:102 errors:0 dropped:0 overruns:0
ppp2 Link encap:Point-Point Protocol
inet addr:207.114.134.1 P-t-P:207.114.134.201 Mask:255.255.255.0
UP POINTOPOINT RUNNING MTU:1500 Metric:1
RX packets:740 errors:0 dropped:0 overruns:0
TX packets:682 errors:0 dropped:0 overruns:0
ppp3 Link encap:Point-Point Protocol
inet addr:207.114.134.1 P-t-P:207.114.134.202 Mask:255.255.255.0
UP POINTOPOINT RUNNING MTU:1500 Metric:1
RX packets:314 errors:2 dropped:2 overruns:0
TX packets:175 errors:0 dropped:0 overruns:0
Next, "route" returns:
#############
Kernel IP routing table
Destination Gateway Genmask Flags Metric Ref Use Iface
modem2.genesisc * 255.255.255.255 UH 0 0 20 ppp2
modem1.genesisc * 255.255.255.255 UH 0 0 4 ppp1
modem3.genesisc * 255.255.255.255 UH 0 0 6 ppp3
localnet * 255.255.255.0 U 0 0 3448 eth0
127.0.0.0 * 255.0.0.0 U 0 0 596 lo
default 207.114.134.250 0.0.0.0 UG 1 0 39322 eth0
Here's a section from ppp.log of the Win95 machine logging in with CHAP:
###########
Feb 28 18:01:56 debian1 pppd[17294]: pppd 2.2.0 started by root, uid 0
Feb 28 18:01:56 debian1 pppd[17294]: Using interface ppp1
Feb 28 18:01:56 debian1 pppd[17294]: Connect: ppp1 <--> /dev/ttyR0
Feb 28 18:01:58 debian1 pppd[17294]: user jemenake logged in
Feb 28 18:01:59 debian1 pppd[17294]: local IP address 207.114.134.1
Feb 28 18:01:59 debian1 pppd[17294]: remote IP address 207.114.134.200
Feb 28 18:01:59 debian1 pppd[17294]: found interface eth0 for proxy arp
Feb 28 18:01:59 debian1 pppd[17294]: CCP terminated at peer's request
Feb 28 18:01:59 debian1 pppd[17294]: Compression disabled by peer.
Here's a section from ppp.log of the Debian machine logging in with debug
activated on the server side:
###########
Feb 28 18:14:29 debian1 pppd[18084]: pppd 2.2.0 started by jemenake, uid 1000
Feb 28 18:14:29 debian1 pppd[18084]: Using interface ppp0
Feb 28 18:14:29 debian1 pppd[18084]: Connect: ppp0 <--> /dev/ttyR3
Feb 28 18:14:29 debian1 pppd[18084]: sent [LCP ConfReq id=0x1 <mru 1500>
<asyncmap 0x0> <magic 0xdae82342> <pcomp> <accomp>]
Feb 28 18:14:32 debian1 pppd[18084]: sent [LCP ConfReq id=0x1 <mru 1500>
<asyncmap 0x0> <magic 0xdae82342> <pcomp> <accomp>]
Feb 28 18:14:32 debian1 pppd[18084]: rcvd [LCP ConfReq id=0x27 <mru 1500>
<asyncmap 0x0> <magic 0xa03210f4> <pcomp> <accomp>]
Feb 28 18:14:32 debian1 pppd[18084]: sent [LCP ConfAck id=0x27 <mru 1500>
<asyncmap 0x0> <magic 0xa03210f4> <pcomp> <accomp>]
Feb 28 18:14:32 debian1 pppd[18084]: rcvd [LCP ConfAck id=0x1 <mru 1500>
<asyncmap 0x0> <magic 0xdae82342> <pcomp> <accomp>]
Feb 28 18:14:32 debian1 pppd[18084]: sent [IPCP ConfReq id=0x1
<addr 207.114.134.1> <compress VJ 0f 01>]
Feb 28 18:14:32 debian1 pppd[18084]: sent [CCP ConfReq id=0x1 <bsd v1 12>]
Feb 28 18:14:33 debian1 pppd[18084]: rcvd [IPCP ConfReq id=0x1a
<addr 0.0.0.0> <compress VJ 0f 01>]
Feb 28 18:14:33 debian1 pppd[18084]: sent [IPCP ConfNak id=0x1a
<addr 207.114.134.203>]
Feb 28 18:14:33 debian1 pppd[18084]: rcvd [IPCP ConfAck id=0x1
<addr 207.114.134.1> <compress VJ 0f 01>]
Feb 28 18:14:33 debian1 pppd[18084]: rcvd [CCP ConfReq id=0xf]
Feb 28 18:14:33 debian1 pppd[18084]: sent [CCP ConfAck id=0xf]
Feb 28 18:14:33 debian1 pppd[18084]: rcvd [CCP ConfRej id=0x1 <bsd v1 12>]
Feb 28 18:14:33 debian1 pppd[18084]: sent [CCP ConfReq id=0x2]
Feb 28 18:14:33 debian1 pppd[18084]: rcvd [IPCP ConfReq id=0x1b
<addr 207.114.134.203> <compress VJ 0f 01>]
Feb 28 18:14:33 debian1 pppd[18084]: sent [IPCP ConfAck id=0x1b
<addr 207.114.134.203> <compress VJ 0f 01>]
Feb 28 18:14:33 debian1 pppd[18084]: local IP address 207.114.134.1
Feb 28 18:14:33 debian1 pppd[18084]: remote IP address 207.114.134.203
Feb 28 18:14:33 debian1 pppd[18084]: found interface eth0 for proxy arp
Feb 28 18:14:33 debian1 pppd[18084]: rcvd [CCP ConfAck id=0x2]
Feb 28 18:15:04 debian1 pppd[18084]: sent [LCP EchoReq id=0x0 da e8 23 42]
Feb 28 18:15:08 debian1 pppd[18084]: Hangup (SIGHUP)
Feb 28 18:15:08 debian1 pppd[18084]: Modem hangup
Feb 28 18:15:08 debian1 pppd[18084]: Connection terminated.
Feb 28 18:15:08 debian1 pppd[18084]: Exit.
Here's the non-commented contents of /etc/ppp/options.ttyR3
##########
:207.114.134.202
file /etc/ppp/options.std.dialin
Here's the non-commented contents of /etc/ppp/options.std.dialin:
##########
dns-addr 207.114.134.1
dns-addr 207.114.134.2
wins-addr 207.114.134.2
wins-addr 207.114.134.1
asyncmap 0
crtscts
modem
proxyarp
lcp-echo-interval 30
lcp-echo-failure 4
#####################################################
#####################################################
Now, that was the server end. Here's the end that's having the problem:
Here's the line in /etc/init.d/ppp that starts everything:
###########
start-stop-daemon --start --verbose --exec /usr/sbin/pppd -- \
connect "/usr/sbin/chat -v -f /etc/ppp.chatscript" `cat /etc/ppp.options_out`
Here's /etc/chatscript:
(An explanation might be necessary... in my .profile, I've got a little
program that I wrote that asks me if I'm using "vt-100" if so, it
autodetects the screen size and I "eval" an "stty rows # cols #" line that
it spits out. That's where the "100 n" line comes from below.)
###########
ABORT BUSY
ABORT "NO CARRIER"
ABORT VOICE
ABORT "NO DIALTONE"
"" ATDT<number removed>
ogin <loginid removed>
word \q<password removed>\q
100 n
$ "/usr/sbin/pppd debug"
Here's the /etc/ppp.options_out:
(I put the "-proxyarp debug" there)
###########
defaultroute /dev/modem 38400 persist -proxyarp debug
Here's the /etc/ppp/options (without comments):
###########
asyncmap 0
crtscts
lock
modem
proxyarp
lcp-echo-interval 30
lcp-echo-failure 4
And, finally, the /var/log/ppp.log (but only the part that relates to the
failed connection that shows in the server log above):
##########
Feb 28 09:58:21 debian chat[1313]: abort on (BUSY)
Feb 28 09:58:21 debian chat[1313]: abort on (NO CARRIER)
Feb 28 09:58:21 debian chat[1313]: abort on (VOICE)
Feb 28 09:58:21 debian chat[1313]: abort on (NO DIALTONE)
Feb 28 09:58:21 debian chat[1313]: send (ATDT<removed>^M)
Feb 28 09:58:21 debian chat[1313]: expect (ogin)
Feb 28 09:58:44 debian chat[1313]: ATDT<removed>^M^M
Feb 28 09:58:44 debian chat[1313]: CONNECT 38400^M
Feb 28 09:58:44 debian chat[1313]: ^MDebian GNU/Linux 1.2
Feb 28 09:58:45 debian chat[1313]: ^MCopyright (C) 1993-1996 Software in the
Public Interest, Inc. and others
Feb 28 09:58:45 debian chat[1313]: ^M**EMSI_REQA77E^M ^M^M
Feb 28 09:58:45 debian chat[1313]: debian1!login -- got it
Feb 28 09:58:45 debian chat[1313]: send (<removed>^M)
Feb 28 09:58:45 debian chat[1313]: expect (word)
Feb 28 09:58:45 debian chat[1313]: : <removed>^M
Feb 28 09:58:45 debian chat[1313]: Password -- got it
Feb 28 09:58:45 debian chat[1313]: send (<removed>^M)
Feb 28 09:58:45 debian chat[1313]: expect (100)
Feb 28 09:58:45 debian chat[1313]: : ^M^M
Feb 28 09:58:45 debian chat[1313]: Last login: Fri Feb 28 18:13:12 on ttyR3^M
Feb 28 09:58:45 debian chat[1313]: Linux debian1 2.0.25 #16 Sun Feb 9
05:26:20Using a vt-100 -- got it
Feb 28 09:58:45 debian chat[1313]: send (n^M)
Feb 28 09:58:45 debian chat[1313]: expect ($)
Feb 28 09:58:45 debian chat[1313]: ?^M
Feb 28 09:58:46 debian chat[1313]: n^M
Feb 28 09:58:46 debian chat[1313]: $ -- got it
Feb 28 09:58:46 debian chat[1313]: send (/usr/sbin/pppd debug^M)
Feb 28 09:58:46 debian pppd[834]: Serial connection established.
Feb 28 09:58:47 debian pppd[834]: Using interface ppp0
Feb 28 09:58:47 debian pppd[834]: Connect: ppp0 <--> /dev/modem
Feb 28 09:58:49 debian pppd[834]: rcvd [LCP ConfReq id=0x1 <mru 1500>
<asyncmap 0x0> <magic 0xdae82342> <pcomp> <accomp>]
Feb 28 09:58:49 debian pppd[834]: sent [LCP ConfReq id=0x27 <mru 1500>
<asyncmap 0x0> <magic 0xa03210f4> <pcomp> <accomp>]
Feb 28 09:58:49 debian pppd[834]: sent [LCP ConfAck id=0x1 <mru 1500>
<asyncmap 0x0> <magic 0xdae82342> <pcomp> <accomp>]
Feb 28 09:58:50 debian pppd[834]: rcvd [LCP ConfAck id=0x27 <mru 1500>
<asyncmap 0x0> <magic 0xa03210f4> <pcomp> <accomp>]
Feb 28 09:58:50 debian pppd[834]: sent [IPCP ConfReq id=0x1a <addr 0.0.0.0>
<compress VJ 0f 01>]
Feb 28 09:58:50 debian pppd[834]: rcvd [IPCP ConfReq id=0x1
<addr 207.114.134.1> <compress VJ 0f 01>]
Feb 28 09:58:50 debian pppd[834]: sent [IPCP ConfAck id=0x1
<addr 207.114.134.1> <compress VJ 0f 01>]
Feb 28 09:58:50 debian pppd[834]: rcvd [CCP ConfReq id=0x1 <bsd v1 12>]
Feb 28 09:58:50 debian pppd[834]: sent [CCP ConfReq id=0xf]
Feb 28 09:58:50 debian pppd[834]: sent [CCP ConfRej id=0x1 <bsd v1 12>]
Feb 28 09:58:50 debian pppd[834]: rcvd [IPCP ConfNak id=0x1a
<addr 207.114.134.203>]
Feb 28 09:58:50 debian pppd[834]: sent [IPCP ConfReq id=0x1b
<addr 207.114.134.203> <compress VJ 0f 01>]
Feb 28 09:58:50 debian pppd[834]: rcvd [CCP ConfAck id=0xf]
Feb 28 09:58:50 debian pppd[834]: rcvd [CCP ConfReq id=0x2]
Feb 28 09:58:50 debian pppd[834]: sent [CCP ConfAck id=0x2]
Feb 28 09:58:50 debian pppd[834]: rcvd [IPCP ConfAck id=0x1b
<addr 207.114.134.203> <compress VJ 0f 01>]
Feb 28 09:58:50 debian pppd[834]: local IP address 207.114.134.203
Feb 28 09:58:50 debian pppd[834]: remote IP address 207.114.134.1
Feb 28 09:59:18 debian pppd[834]: sent [LCP EchoReq id=0x0 a0 32 10 f4]
Feb 28 09:59:18 debian pppd[834]: sent [LCP EchoReq id=0x1 a0 32 10 f4]
Feb 28 09:59:18 debian pppd[834]: sent [LCP EchoReq id=0x2 a0 32 10 f4]
Feb 28 09:59:18 debian pppd[834]: sent [LCP EchoReq id=0x3 a0 32 10 f4]
Feb 28 09:59:18 debian pppd[834]: Excessive lack of response to LCP echo
frames.
Feb 28 09:59:18 debian pppd[834]: sent [LCP TermReq id=0x28]
Feb 28 09:59:21 debian pppd[834]: sent [LCP TermReq id=0x29]
Feb 28 09:59:21 debian pppd[834]: rcvd [LCP EchoReq id=0x0 da e8 23 42]
Feb 28 09:59:24 debian pppd[834]: Connection terminated.
Now, here's what I figure is happening judging from the logs on either side
(and for clarity, I'll label the messages sequentially according to which
side initiated the original message. The first request from the client side
will be "C1", then "C2", etc.)
The server sees things like this:
###############
Sends LCP request S1
Sends LCP request S1 again
Gets LCP request C1
Sends LCP ACK of C1
Gets LCP ACK of S1
Sends IPCP request S2 (to use 207.114.134.1 as server IP and VJ header comp.)
Sends CCP request S3 (to use bsd compression?)
Gets IPCP request C2 (to use 0.0.0.0 as client IP)
Sends IPCP NAK of C2 (and suggests client IP: 207.114.134.203)
Gets IPCP ACK of S2 (acknowledging server IP of 207.114.134.1 and VJ comp.)
Gets CCP request C3
Sends CCP ACK of C3
Gets CCP REJ of S3 (client rejects offer of bsd compression)
Sends CCP request S4
Gets IPCP request C4 (for client IP of 207.114.134.203)
Sends IPCP ACK of C4 (acknowldeging client IP: 207.114.134.203)
<At this point, the logs show the agreed-upon IP's>
Gets CCP ACK of S4
Sends LCP echo-request S5
-=<Connection terminates>=-
The client sees things like this:
#################
Gets LCP request S1
Sends LCP request C1
Sends LCP ACK of S1
Gets LCP ACK of C1
Sends IPCP request C2 (to use client IP:0.0.0.0)
Gets IPCP request S2 (to use server IP:207.114.134.1)
Sends IPCP ACK of S2 (to use server IP:207.114.134.1)
Gets CCP request S3 (to use bsd header comp)
Sends CCP request C3
Sends CCP REJ of S3 (client rejects offer of bsd compression)
Gets IPCP NAK of C2 (Server refuses client IP:0.0.0.0, offers 207.114.134.203)
Sends IPCP request C4 (requesting client IP:207.114.134.1)
Gets CCP ACK of C3
Gets CCP request S4
Sends CCP ACK of S4
Gets IPCP ACK of C4 (Server agrees on client IP:207.114.134.203)
<At this point, the logs show the agreed-upon IP's>
Sends LCP echo-request C5
Sends LCP echo-request C6
Sends LCP echo-request C7
Sends LCP echo-request C8
<Client gives up>
Sends LCP TerminateRequest C9
Sends LCP TerminateRequest C10
Gets LCP echo-request S5
So, looking at it all like this, it appears that the conversation goes fine
until they agree on IP addresses. After that, the server doesn't see any
of the client's echo requests. However, the client DOES see the single
on that comes from the server.
Now, I *DON'T* think this is an problem with LCP timing settings. The LCP
echoes are only to preserve the connection. If I played with those, that
would only make the connection stay up longer before quitting.... but I
still wouldn't get any IP packets through... no matter HOW long the modems
stay connected.
The only things different between this connection and the Win95 conenection
are the following:
1 - The Win95 connection disabled CCP
2 - The Win95 disabled compression (of any kind?)
3 - The Debian connection disabled bsd compression.
Any ideas?
- Joe
Reply to: