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