Hi Paul,Gotcha.On Wed, 29 Dec 1999 16:33:17 GMT, you posted to redhat.networking.general:
>No, I don't know why this works, but I've tried the exact same ppp options
>using a chat script (pap authentication only) and it doesn't behave
>the same way. It's as if the script is having trouble connecting via
>chat, but using anything else things work fine.Look, if you want help, you have to show us what is wrong. This is best done
by posting logs. You can describe what you see all day long, and it's not
going to get worthwhile help, because you are telling us what you thought
you saw, not what actually happened. Chat is pretty dumb and hard to screw
up. Really. Call chat with the -v option and see what you are doing wrong by
looking at the resulting log data in /var/log/messages. If you can't see it,
_then_ post the log to comp.os.linux.networking.Hope this helps,
[EMAIL PROTECTED]
I've been using kdebug 7 and debug and chat -v all along.
Sorry, I'm new to this list.
Ok, here's the dirt:
The following is the verbose output of the pppd at the terminal window:
Passwords where appear (deleted in output) were
correct.
GOOD connection (output from an expect script that calls minicom
and pppd)
------------------
Using interface ppp0
Connect: ppp0 <--> /dev/ttyS0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xc99a0b28>
<pcomp> <accomp>]
rcvd [LCP ConfRej id=0x1 <magic 0xc99a0b28> <pcomp> <accomp>]
sent [LCP ConfReq id=0x2 <asyncmap 0x0>]
rcvd [LCP ConfReq id=0x8d <auth chap m$oft>]
sent [LCP ConfAck id=0x8d <auth chap m$oft>]
rcvd [LCP ConfReq id=0x8e <auth chap MD5>]
sent [LCP ConfAck id=0x8e <auth chap MD5>]
rcvd [LCP ConfReq id=0x8f <auth 0xc027 01 00 00 01>]
sent [LCP ConfNak id=0x8f <auth chap MD5>]
rcvd [LCP ConfReq id=0x90 <auth pap>]
sent [LCP ConfAck id=0x90 <auth pap>]
rcvd [LCP ConfReq id=0x91 <auth 0xc027 01 00 00 02>]
sent [LCP ConfNak id=0x91 <auth chap MD5>]
rcvd [LCP ConfReq id=0x92 <auth 0xc027 01 00 00 03 00 00 00
0f>]
sent [LCP ConfNak id=0x92 <auth chap MD5>]
sent [LCP ConfReq id=0x2 <asyncmap 0x0>]
rcvd [LCP ConfReq id=0x94 <asyncmap 0xa0000> <auth pap>]
sent [LCP ConfAck id=0x94 <asyncmap 0xa0000> <auth pap>]
rcvd [LCP ConfAck id=0x2 <asyncmap 0x0>]
sent [PAP AuthReq id=0x1 user="cv" password="[deleted in output]"]
rcvd [PAP AuthAck id=0x1 ""]
Remote message: ^F
sent [IPCP ConfReq id=0x1 <addr 192.168.1.1> <compress VJ
0f 01>]
sent [IPCP ConfReq id=0x1 <addr 192.168.1.1> <compress VJ
0f 01>]
rcvd [IPCP ConfReq id=0x1 <addr 205.133.156.3>]
sent [IPCP ConfAck id=0x1 <addr 205.133.156.3>]
rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x2 <addr 192.168.1.1>]
rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
rcvd [IPCP ConfNak id=0x2 <addr 205.133.156.26>]
sent [IPCP ConfReq id=0x3 <addr 205.133.156.26>]
rcvd [IPCP ConfAck id=0x3 <addr 205.133.156.26>]
local IP address 205.133.156.26
remote IP address 205.133.156.3
Using interface ppp0
Connect: ppp0 <--> /dev/ttyS0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x7d924f2b>
<pcomp> <accomp>]
rcvd [LCP ConfReq id=0xd0 <auth chap m$oft>]
sent [LCP ConfAck id=0xd0 <auth chap m$oft>]
rcvd [LCP ConfRej id=0x1 <magic 0x7d924f2b> <pcomp> <accomp>]
sent [LCP ConfReq id=0x2 <asyncmap 0x0>]
rcvd [LCP ConfReq id=0xd1 <auth chap MD5>]
sent [LCP ConfAck id=0xd1 <auth chap MD5>]
rcvd [LCP ConfReq id=0xd2 <auth 0xc027 01 00 00 01>]
sent [LCP ConfNak id=0xd5 <auth chap MD5>]
sent [LCP ConfReq id=0x2 <asyncmap 0x0>]
rcvd [LCP ConfReq id=0xd7 <asyncmap 0xa0000> <auth pap>]
sent [LCP ConfAck id=0xd7 <asyncmap 0xa0000> <auth pap>]
rcvd [LCP ConfAck id=0x2 <asyncmap 0x0>]
sent [PAP AuthReq id=0x1 user="cv" password="[deleted in output]"]
rcvd [PAP AuthAck id=0x1 ""]
Remote message: ^F
sent [IPCP ConfReq id=0x1 <addr 192.168.1.1> <compress VJ
0f 01>]
rcvd [IPCP ConfReq id=0x1 <addr 205.133.156.3>]
sent [IPCP ConfAck id=0x1 <addr 205.133.156.3>]
sent [IPCP ConfReq id=0x1 <addr 192.168.1.1> <compress VJ
0f 01>]
rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x2 <addr 192.168.1.1>]
rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
rcvd [IPCP ConfNak id=0x2 <addr 205.133.156.26>]
sent [IPCP ConfReq id=0x3 <addr 205.133.156.26>]
rcvd [IPCP ConfAck id=0x3 <addr 205.133.156.26>]
local IP address 205.133.156.26
remote IP address 205.133.156.3
Script /etc/ppp/ip-up started; pid = 6572
Script /etc/ppp/ip-up finished (pid 6572), status = 0x0
----------------
That's a sucessful launch and connect.
In /var/log/messages:
--------------------
Dec 29 22:34:10 vv pppd[6568]: pppd 2.3.7 started by root, uid
0
Dec 29 22:34:10 vv pppd[6568]: Using interface ppp0
Dec 29 22:34:10 vv pppd[6568]: Connect: ppp0 <--> /dev/ttyS0
Dec 29 22:34:10 vv kernel: ppp_ioctl: set dbg flags to 70000
Dec 29 22:34:10 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:34:10 vv kernel: ppp_tty_ioctl: set xasyncmap
Dec 29 22:34:10 vv kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Dec 29 22:34:10 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:34:10 vv kernel: ppp_ioctl: set mru to 5dc
Dec 29 22:34:10 vv kernel: ppp_tty_ioctl: set rcv asyncmap ffffffff
Dec 29 22:34:10 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:34:13 vv kernel: ppp_tty_ioctl: set xmit asyncmap a0000
Dec 29 22:34:13 vv kernel: ppp_ioctl: set flags to f070000
Dec 29 22:34:13 vv kernel: ppp_ioctl: set mru to 5dc
Dec 29 22:34:13 vv kernel: ppp_tty_ioctl: set rcv asyncmap 0
Dec 29 22:34:13 vv kernel: ppp_ioctl: set flags to f070010
Dec 29 22:34:13 vv pppd[6568]: Remote message: ^F
Dec 29 22:34:13 vv kernel: ppp_ioctl: set flags to f070050
Dec 29 22:34:16 vv kernel: ppp_ioctl: set flags to f070058
Dec 29 22:34:16 vv pppd[6568]: local IP address 205.133.156.26
Dec 29 22:34:16 vv pppd[6568]: remote IP address 205.133.156.3
Dec 29 22:34:44 vv pppd[6568]: Hangup (SIGHUP)
Dec 29 22:34:44 vv kernel: ppp_ioctl: set flags to f070058
Dec 29 22:34:44 vv kernel: ppp_ioctl: set flags to f070018
Dec 29 22:34:44 vv kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Dec 29 22:34:44 vv kernel: ppp_ioctl: set flags to f070018
Dec 29 22:34:44 vv kernel: ppp_ioctl: set mru to 5dc
Dec 29 22:34:44 vv kernel: ppp_tty_ioctl: set rcv asyncmap 0
Dec 29 22:34:44 vv kernel: ppp_ioctl: set flags to f070018
Dec 29 22:34:44 vv pppd[6568]: Modem hangup
Dec 29 22:34:44 vv pppd[6568]: Connection terminated.
Dec 29 22:34:44 vv pppd[6568]: Connect time 0.6 minutes.
Dec 29 22:34:44 vv pppd[6568]: Sent 409 bytes, received 2413 bytes.
Dec 29 22:34:44 vv kernel: ppp: channel ppp0 closing.
Dec 29 22:34:44 vv pppd[6568]: Exit.
-----------------------
End of GOOD connect.
Now for the one that fails.
Lets take a look at what it does with fairly stock RedHat 6.0 (almost
identical output with a home-brew script, btw, both using the chat
program).
29 22:38:59 vv ifup-ppp: pppd started for ppp0 on /dev/ttyS0 at
115200
Dec 29 22:38:59 vv pppd[6704]: pppd 2.3.7 started by root, uid
0
Dec 29 22:39:00 vv chat[6705]: abort on (BUSY)
Dec 29 22:39:00 vv chat[6705]: abort on (ERROR)
Dec 29 22:39:00 vv chat[6705]: abort on (NO CARRIER)
Dec 29 22:39:00 vv chat[6705]: abort on (NO DIALTONE)
Dec 29 22:39:00 vv chat[6705]: abort on (Invalid Login)
Dec 29 22:39:00 vv chat[6705]: abort on (Login incorrect)
Dec 29 22:39:00 vv chat[6705]: send (AT^M)
Dec 29 22:39:00 vv chat[6705]: expect (OK)
Dec 29 22:39:00 vv chat[6705]: AT^M^M
Dec 29 22:39:00 vv chat[6705]: OK
Dec 29 22:39:00 vv chat[6705]: -- got it
Dec 29 22:39:00 vv chat[6705]: send (ATD4937111^M)
Dec 29 22:39:01 vv chat[6705]: expect (CONNECT)
Dec 29 22:39:01 vv chat[6705]: ^M
Dec 29 22:39:02 vv chat[6705]: ATD4937111^M^M
Dec 29 22:39:02 vv chat[6705]: CONNECT
Dec 29 22:39:02 vv chat[6705]: -- got it
Dec 29 22:39:02 vv chat[6705]: send (^M)
Dec 29 22:39:02 vv chat[6705]: expect (~)
Dec 29 22:39:02 vv chat[6705]: 115200^M
Dec 29 22:39:02 vv chat[6705]: ~
Dec 29 22:39:02 vv chat[6705]: -- got it
Dec 29 22:39:02 vv chat[6705]: send (^M)
Dec 29 22:39:02 vv pppd[6704]: Serial connection established.
Dec 29 22:39:02 vv pppd[6704]: Using interface ppp0
Dec 29 22:39:02 vv kernel: ppp_ioctl: set dbg flags to 70000
Dec 29 22:39:02 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:39:02 vv kernel: ppp_tty_ioctl: set xasyncmap
Dec 29 22:39:02 vv pppd[6704]: Connect: ppp0 <--> /dev/ttyS0
Dec 29 22:39:02 vv kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Dec 29 22:39:02 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:39:02 vv kernel: ppp_ioctl: set mru to 5dc
Dec 29 22:39:02 vv kernel: ppp_tty_ioctl: set rcv asyncmap ffffffff
Dec 29 22:39:02 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:39:04 vv pppd[6704]: Modem hangup
Dec 29 22:39:04 vv pppd[6704]: Connection terminated.
Dec 29 22:39:04 vv kernel: ppp: channel ppp0 closing.
Dec 29 22:39:04 vv pppd[6704]: Connect time 0.1 minutes.
Dec 29 22:39:05 vv pppd[6704]: Exit.
(That's stock redhat)
Now, for a custom script (attached at the end):
--------------------------
# ./jbicpap2
Dialing jbic.com...4937111
Serial connection established.
Using interface ppp0
Connect: ppp0 <--> /dev/ttyS0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x651b2f33>
<pcomp> <accomp>]
rcvd [LCP ConfReq id=0xf3 <auth chap m$oft>]
sent [LCP ConfAck id=0xf3 <auth chap m$oft>]
rcvd [LCP ConfReq id=0xf4 <auth chap m$oft>]
sent [LCP ConfAck id=0xf4 <auth chap m$oft>]
rcvd [LCP ConfReq id=0xf5 <auth chap m$oft>]
sent [LCP ConfAck id=0xf5 <auth chap m$oft>]
rcvd [LCP ConfReq id=0xf6 <auth chap m$oft>]
sent [LCP ConfAck id=0xf6 <auth chap m$oft>]
rcvd [LCP ConfReq id=0xf7 <auth chap m$oft>]
sent [LCP ConfAck id=0xf7 <auth chap m$oft>]
rcvd [LCP ConfRej id=0x1 <magic 0x651b2f33> <pcomp> <accomp>]
sent [LCP ConfReq id=0x2 <asyncmap 0x0>]
rcvd [LCP ConfReq id=0xf8 <auth chap MD5>]
sent [LCP ConfAck id=0xf8 <auth chap MD5>]
rcvd [LCP ConfReq id=0xf9 <auth 0xc027 01 00 00 01>]
sent [LCP ConfNak id=0xf9 <auth chap MD5>]
rcvd [LCP ConfReq id=0xfa <auth pap>]
sent [LCP ConfAck id=0xfa <auth pap>]
rcvd [LCP ConfReq id=0xfb <auth 0xc027 01 00 00 02>]
sent [LCP ConfNak id=0xfb <auth chap MD5>]
rcvd [LCP ConfReq id=0xfc <auth 0xc027 01 00 00 03 00 00 00
0f>]
sent [LCP ConfNak id=0xfc <auth chap MD5>]
Modem hangup
Connection terminated.
Connect time 0.1 minutes.
This produces the following kernel messages in /var/log/messages:
(again, this one fails - compare to the kernel debug above)
Dec 29 22:42:19 vv pppd[6783]: pppd 2.3.7 started by root, uid 0
Dec 29 22:42:20 vv chat[6784]: timeout set to 3 seconds
Dec 29 22:42:20 vv chat[6784]: abort on (\nBUSY\r)
Dec 29 22:42:20 vv chat[6784]: abort on (\nNO ANSWER\r)
Dec 29 22:42:20 vv chat[6784]: abort on (\nRINGING\r\n\r\nRINGING\r)
Dec 29 22:42:20 vv chat[6784]: send (rAT^M)
Dec 29 22:42:20 vv chat[6784]: expect (OK)
Dec 29 22:42:20 vv chat[6784]: rAT^M^M
Dec 29 22:42:20 vv chat[6784]: OK
Dec 29 22:42:20 vv chat[6784]: -- got it
Dec 29 22:42:20 vv chat[6784]: send (^MAT%A4=0^M)
Dec 29 22:42:21 vv chat[6784]: timeout set to 60 seconds
Dec 29 22:42:21 vv chat[6784]: expect (OK)
Dec 29 22:42:21 vv chat[6784]: ^M
Dec 29 22:42:21 vv chat[6784]: ^MAT%A4=0^M^M
Dec 29 22:42:21 vv chat[6784]: OK
Dec 29 22:42:21 vv chat[6784]: -- got it
Dec 29 22:42:21 vv chat[6784]: send (ATD4937111^M)
Dec 29 22:42:21 vv chat[6784]: expect (CONNECT)
Dec 29 22:42:21 vv chat[6784]: ^M
Dec 29 22:42:23 vv chat[6784]: ATD4937111^M^M
Dec 29 22:42:23 vv chat[6784]: CONNECT
Dec 29 22:42:23 vv chat[6784]: -- got it
Dec 29 22:42:23 vv chat[6784]: send (\~^M)
Dec 29 22:42:23 vv pppd[6783]: Serial connection established.
Dec 29 22:42:23 vv kernel: ppp_ioctl: set dbg flags to 70000
Dec 29 22:42:23 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:42:23 vv pppd[6783]: Using interface ppp0
Dec 29 22:42:23 vv pppd[6783]: Connect: ppp0 <--> /dev/ttyS0
Dec 29 22:42:23 vv kernel: ppp_tty_ioctl: set xasyncmap
Dec 29 22:42:23 vv kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Dec 29 22:42:23 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:42:23 vv kernel: ppp_ioctl: set mru to 5dc
Dec 29 22:42:23 vv kernel: ppp_tty_ioctl: set rcv asyncmap ffffffff
Dec 29 22:42:23 vv kernel: ppp_ioctl: set flags to 70000
Dec 29 22:42:25 vv kernel: ppp: channel ppp0 closing.
Dec 29 22:42:25 vv pppd[6783]: Modem hangup
Dec 29 22:42:25 vv pppd[6783]: Connection terminated.
Dec 29 22:42:25 vv pppd[6783]: Connect time 0.1 minutes.
Dec 29 22:42:26 vv pppd[6783]: Exit.
------------------ End of BAD connect sequences
And for the connect script (that fails):
--------------------------
#!/bin/sh
# oz.net isdn
DEVICE=ttyS0 #com1
PHONE=4937111
#PHONE=4932655
USER=cv
PROVIDER=jbic.com
PROVIDER_NAME=jbic.com
LOCALNAME=cv.jbic.com
echo Dialing $PROVIDER_NAME...$PHONE
# noccp modem crtscts noipdefault
\
# remotename $PROVIDER
\
# name $LOCALNAME
\
# mtu 1500 mru 1500 \
# crtscts
/usr/sbin/pppd lock /dev/ttyS0 name cv \
modem 115200 crtscts nodetach \
ipcp-accept-local ipcp-accept-remote
\
debug kdebug 7 defaultroute asyncmap 0 noauth mtu 1500 mru
1500 \
connect "/usr/sbin/chat -v
\
TIMEOUT
3
\
ABORT
'\nBUSY\r'
\
ABORT
'\nNO ANSWER\r'
\
ABORT
'\nRINGING\r\n\r\nRINGING\r' \
''
\rAT$B0
\
'OK-+++\c-OK'
'\rAT%A4=0' \
TIMEOUT
60
\
OK
ATD$PHONE
\
CONNECT
'\~'
\
"
------------------
The script that works:
#!/usr/bin/expect -f
#
set force_conservative 0 ;# set to 1 to force conservative
mode even if
;# script wasn't run conservatively originally
if {$force_conservative} {
set send_slow {1 .1}
proc send {ignore arg} {
sleep .1
exp_send -s -- $arg
}
}
set timeout -1
match_max 100000
spawn $env(SHELL)
send -- "minicom isdn ; ./jbicpppd.sh\r"
expect "Press CTRL-A Z for help on special keys\r"
send -- "atd4937111\r"
expect "CONNECT 115200\r"
expect "~"
send -- "q"
send -- "\r"
expect "Using interface ppp0\r"
expect "Connect: ppp0 <--> /dev/ttyS0\r"
expect -exact "Terminating on signal 2.\r"
send -- "exit\r"
expect eof
exit
------------- Second part of this script is a simple pppd call:
#!/bin/bash
/usr/sbin/pppd lock /dev/ttyS0 name cv \
modem 115200 crtscts nodetach \
ipcp-accept-local ipcp-accept-remote
\
debug kdebug 7 defaultroute asyncmap 0 noauth mtu 1500 mru
1500
------------ End
-- Paul Ferris | http://linuxtoday.com | 330-875-2757 ------------------------------------------------------ Linux: Because a computer is a terrible thing to waste ------------------------------------------------------
