My original Subject: of this email was
"Having some problems with pppd 2.4.0b2 and ac12 patch"
But, since the problem was solved, the new title is more appropriate.
This email is in two parts, one highlights the problem, the 2nd highlights
the solution (such as it was..)
PLEASE - this is an invitation to brainstorm and kibitz.
The problem description..
Snippet of /var/log/messages
Jun 9 23:56:11 hoho0 pppd[1268]: pppd 2.4.0b1 started by root, uid 0
Jun 9 23:57:29 hoho0 chat[1274]: Password:
Jun 9 23:57:29 hoho0 chat[1274]: -- got it
Jun 9 23:57:29 hoho0 chat[1274]: send (??????)
Jun 9 23:57:30 hoho0 pppd[1268]: Serial connection established.
Jun 9 23:57:30 hoho0 pppd[1268]: Connect: ppp0 <--> /dev/pts/2
Jun 9 23:57:35 hoho0 pppd[1268]: Hangup (SIGHUP)
Jun 9 23:57:35 hoho0 pppd[1268]: Modem hangup
Jun 9 23:57:35 hoho0 pppd[1268]: Connection terminated.
Jun 9 23:57:39 hoho0 pppd[1268]: Starting link
A bit later
Jun 9 23:59:14 hoho0 chat[1278]: Password:
Jun 9 23:59:14 hoho0 chat[1278]: -- got it
Jun 9 23:59:14 hoho0 chat[1278]: send (??????)
Jun 9 23:59:15 hoho0 pppd[1268]: Serial connection established.
Jun 9 23:59:15 hoho0 pppd[1268]: Connect: ppp0 <--> /dev/pts/2
Jun 9 23:59:20 hoho0 pppd[1268]: Hangup (SIGHUP)
Jun 9 23:59:20 hoho0 pppd[1268]: Modem hangup
Jun 9 23:59:20 hoho0 pppd[1268]: Connection terminated.
Somehow, something is hitting pppd with a SIGHUP.
I have massive debug/logging turned on (see script below)
[root@hoho0 ppp]# more /etc/ppp/peers/isp.dump
/dev/ttyS1 115200 crtscts
connect '/usr/sbin/chat -v -f /etc/ppp/chat-isp'
noauth
hide-password
record /tmp/pppd1.out
kdebug 25
ktune
lock
debug
# defaultroute
199.3.36.36:205.164.53.120
demand
holdoff 2
idle 120
With debug set, syslog.conf directs daemon messages to /tmp/pppk1.log
This file contains:
Jun 9 23:57:29 hoho0 chat[1274]: Password:
Jun 9 23:57:29 hoho0 chat[1274]: -- got it
Jun 9 23:57:29 hoho0 chat[1274]: send (??????)
Jun 9 23:57:30 hoho0 pppd[1268]: Serial connection established.
Jun 9 23:57:30 hoho0 pppd[1268]: using channel 4
Jun 9 23:57:30 hoho0 pppd[1268]: Connect: ppp0 <--> /dev/pts/2
Jun 9 23:57:31 hoho0 pppd[1268]: sent [LCP ConfReq id=0x1 <asyncmap 0x0>
<magic
0x5e4d3887> <pcomp> <accomp>]
Jun 9 23:57:34 hoho0 pppd[1268]: sent [LCP ConfReq id=0x1 <asyncmap 0x0>
<magic
0x5e4d3887> <pcomp> <accomp>]
Jun 9 23:57:34 hoho0 pppd[1268]: rcvd [LCP ConfReq id=0x1 < 00 04 00 00>
<mru 1
524> <asyncmap 0x0> <auth pap> <pcomp> <accomp> <mrru 1524> <endpoint
[MAC:00:c0
:7b:8f:f1:bc]>]
Jun 9 23:57:34 hoho0 pppd[1268]: sent [LCP ConfRej id=0x1 < 00 04 00 00> <auth
pap> <mrru 1524> <endpoint [MAC:00:c0:7b:8f:f1:bc]>]
Jun 9 23:57:34 hoho0 pppd[1268]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0>
<magic
0x5e4d3887> <pcomp> <accomp>]
Jun 9 23:57:34 hoho0 pppd[1268]: rcvd [LCP TermReq id=0x2]
Jun 9 23:57:34 hoho0 pppd[1268]: sent [LCP TermAck id=0x2]
Jun 9 23:57:35 hoho0 pppd[1268]: Hangup (SIGHUP)
Jun 9 23:57:35 hoho0 pppd[1268]: sent [LCP TermReq id=0x2 "User request"]
Jun 9 23:57:35 hoho0 pppd[1268]: Script pppd (charshunt) finished (pid
1273), s
tatus = 0x0
Jun 9 23:57:35 hoho0 pppd[1268]: Modem hangup
Jun 9 23:57:35 hoho0 pppd[1268]: Connection terminated
Not a lot of help from the above series of messages.
After the problem was solved (see further below), I did look at the record
(dump) file and would have noticed the ASCII text 'Request Denied' coming
from my ISP, but I was still hung up (.. pun? ..) on the Hangup (SIGHUP)
messages in the log files I did look at.
For that same time period, the record file contains:
( /usr/sbin/pppdump -p /tmp/pppd1.out )
start Fri Jun 9 23:56:39 2000
time 1.3s
time 0.1s
time 0.1s
time 0.1s
time 42.8s
time 0.1s
time 5.3s
time 0.1s
time 0.1s
time 0.1s
time 0.1s
time 0.1s
time 1.0s
time 1.0s
sent 61 74 7a 0d 61 74 64 74 36 38 37 34 32 30 33 0d atz.atdt6874203.
....
BAD FCS: (residue = ca93)
sent ff 03 c0 21 01 01 00 14 02 06 00 00 00 00 05 06 ...!............
5e 4d 38 87 07 02 08 02 ^M8.....
time 0.1s
rcvd 61 74 7a 0d 0d 0a 4f 4b 0d 0a 61 74 64 74 36 38 atz...OK..atdt68
37 34 32 30 33 0d 0d 0a 43 4f 4e 4e 45 43 54 20 74203...CONNECT
31 31 35 32 30 30 0d 0a 54 6f 20 65 6e 74 65 72 115200..To enter
20 73 68 65 6c 6c 20 74 79 70 65 20 22 6d 63 73 shell type "mcs
22 20 61 74 20 62 6f 74 68 20 70 72 6f 6d 70 74 " at both prompt
73 0d 0a 0d 0a 0d 0a 6c 6f 67 69 6e 3a 20 62 6f s......login: bo
62 67 75 73 0d 0a 50 61 73 73 77 6f 72 64 3a 20 bgus..Password:
0d 0a 52 65 71 75 65 73 74 20 44 65 6e 69 65 64 ..Request Denied
0d 0a 0d 0a 0d 0a 6c 6f 67 69 6e 3a 20 0d 0a 0d ......login: ...
0a 6c 6f 67 69 6e .login
BAD FCS: (residue = 4e86)
time 2.9s
sent ff 03 c0 21 01 01 00 14 02 06 00 00 00 00 05 06 ...!............
5e 4d 38 87 07 02 08 02 ^M8.....
time 0.1s
rcvd ff 03 c0 21 01 01 00 27 00 04 00 00 01 04 05 f4 ...!...'........
02 06 00 00 00 00 03 04 c0 23 07 02 08 02 11 04 .........#......
05 f4 13 09 03 00 c0 7b 8f f1 bc .......{...
sent ff 03 c0 21 04 01 00 19 00 04 00 00 03 04 c0 23 ...!...........#
11 04 05 f4 13 09 03 00 c0 7b 8f f1 bc .........{...
rcvd ff 03 c0 21 02 01 00 14 02 06 00 00 00 00 05 06 ...!............
5e 4d 38 87 07 02 08 02 ^M8.....
time 0.1s
rcvd ff 03 c0 21 05 02 00 04 ...!....
sent ff 03 c0 21 06 02 00 04 ...!....
time 0.6s
end recv
sent ff 03 c0 21 05 02 00 10 55 73 65 72 20 72 65 71 ...!....User req
75 65 73 74 uest
start Fri Jun 9 23:57:39 2000
^^^^^^^ This is the start of the next login attempt
.....
My system is a PII 400Mhz, 120MB, 9+GB
The 2.4.0 kernel code I'm using is from
http://www.kernel.org/pub/linux/kernel/v2.4/linux-2.4.0-test1.tar.bz2
There is a patch 'ac11' which is available from
http://www.kernel.org/pub/linux/kernel/people/alan/2.4.0test/patch-2.4.0test1-ac
12.bz2
My PPP worked fine with patch-2.4.0test1-ac11.bz2 - (I did not check with
dump logging then).
Should I go back to patch ac11? Any clues on what could be happening?
-- OK, this was the problem, now for the solution ('out of the box..')----
Since I needed my periodic email fix, I connected the modem directly to my
old Macintosh 840av and configured PPP to work as my TCP connection to the
outside world. (MacOS 8.1 - not Linux)
It didn't work, but looking at the 'Activity Log' of the Mac PPP
application gave me a clue:
06/10/00 00:16 CCL write: "AT\13"
06/10/00 00:16 CCL match: "OK\13\10"
06/10/00 00:16 CCL write: "AT&F1E0W2S95=45S0=0&D3S7=60\13"
06/10/00 00:16 CCL match: "OK\13\10"
06/10/00 00:16 Dialing 687-4203
06/10/00 00:16 CCL write: "ATDT687-4203\13"
06/10/00 00:16 CCL match: "CARRIER"
06/10/00 00:16 CCL match: "PROTOCOL: LAP"
06/10/00 00:16 CCL match: "COMPRESSION: V"
06/10/00 00:16 CCL match: "CONNECT "
06/10/00 00:16 CCL match: "\10"
06/10/00 00:16 LCP: Sending Configuration Request.
06/10/00 00:16 LCP: >> Async Map = 0x00000000.
06/10/00 00:16 LCP: >> Magic Number = 0x00880F27.
06/10/00 00:16 LCP: >> Protocol Compression On
06/10/00 00:16 LCP: >> Address/Control Compression On
06/10/00 00:16 LCP: Sending Configuration Request.
06/10/00 00:16 LCP: >> Async Map = 0x00000000.
06/10/00 00:16 LCP: >> Magic Number = 0x00880F27.
06/10/00 00:16 LCP: >> Protocol Compression On
06/10/00 00:16 LCP: >> Address/Control Compression On
06/10/00 00:16 LCP: Received Configuration Request.
06/10/00 00:16 LCP: >> Unknown type: 0x00000000.
06/10/00 00:16 LCP: >> MRU = 1524.
06/10/00 00:16 LCP: >> Async Map = 0x00000000.
06/10/00 00:16 LCP: >> Auth Protocol = 0x0000C023.
06/10/00 00:16 LCP: >> Protocol Compression On
06/10/00 00:16 LCP: >> Address/Control Compression On
06/10/00 00:16 LCP: >> Unknown type: 0x00000011.
06/10/00 00:16 LCP: >> Unknown type: 0x00000013.
06/10/00 00:16 LCP: >> Unknown Option Rejected.
06/10/00 00:16 LCP: Sending Configuration Reject.
06/10/00 00:16 LCP: Received Configuration Ack.
06/10/00 00:16 LCP: Received Configuration Request.
06/10/00 00:16 LCP: >> MRU = 1524.
06/10/00 00:16 LCP: >> Async Map = 0x00000000.
06/10/00 00:16 LCP: >> Auth Protocol = 0x0000C023.
06/10/00 00:16 LCP: >> Protocol Compression On
06/10/00 00:16 LCP: >> Address/Control Compression On
06/10/00 00:16 LCP: Sending Configuration Ack.
06/10/00 00:16 Authentication failed.
06/10/00 00:16 Request Denied
06/10/00 00:16 Termination request received from the remote side.
06/10/00 00:16 CCL write: "+++"
06/10/00 00:16 CCL write: "AT\13"
06/10/00 00:16 CCL match: "OK\13\10"
06/10/00 00:17 CCL write: "ATH\13"
06/10/00 00:17 CCL match: "OK\13\10"
06/10/00 00:17 CCL write: "AT&F1S0=0\13"
06/10/00 00:17 CCL match: "OK\13\10"
06/10/00 00:17 Connection failed.
The problem was not in the Linux PPP code, but it was a problem at my ISP's
side - perhaps the authentication server was down.
The message "Termination request received from the remote side." was a very
clear (to me anyway) indication that the problem was not on my side. It
would be great if Linux pppd could give similar direct problem indications.
(Yes, I know - find the spots, insert code, submit patches... I thought I
would just share my thoughts at this preliminary level - you folks on the
list can do a much better job of figuring out the best changes than I)
------
I logged in this morning, and all was fine, both with the Macintosh PPP
connection and the Linux PPP connection.
-
To unsubscribe from this list: send the line "unsubscribe linux-ppp" in
the body of a message to [EMAIL PROTECTED]
