Subject: ppp gets busy
To: None <netbsd-users@netbsd.org>
From: Hanspeter Roth <hampi@rootshell.be>
List: netbsd-users
Date: 02/03/2005 22:23:13
Hello,

I'm trying to run ppp via a PCMCIA modem. In dmesg.boot it is listed
as:

com3 at pcmcia0 function 0: serial device
com3: ns16550a, working fifo

It seems to be located at /dev/tty03. At least cu can reach it
there.

The problem is ppp always gets BUSY while pppd does work and ppp on
FreeBSD works as well.


NetBSD ppp.log:

Feb  3 21:17:47 goofy ppp[1631]: tun0: Phase: PPP Started (auto mode). 
Feb  3 21:18:09 goofy ppp[1631]: tun0: Phase: Connected to local client. 
Feb  3 21:18:26 goofy ppp[1631]: tun0: Command: /var/run/pppctl: dial 
Feb  3 21:18:26 goofy ppp[1631]: tun0: Phase: bundle: Establish 
Feb  3 21:18:26 goofy ppp[1631]: tun0: Phase: deflink: closed -> opening 
Feb  3 21:18:27 goofy ppp[1631]: tun0: Phase: deflink: Connected! 
Feb  3 21:18:27 goofy ppp[1631]: tun0: Phase: deflink: opening -> dial 
Feb  3 21:18:27 goofy ppp[1631]: tun0: Chat: Phone: 0840777700 
Feb  3 21:18:27 goofy ppp[1631]: tun0: Chat: deflink: Dial attempt 1 of 1 
Feb  3 21:18:27 goofy ppp[1631]: tun0: Chat: Send: AT^M 
Feb  3 21:18:27 goofy ppp[1631]: tun0: Chat: Expect(5): OK 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Expect timeout 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Send: AT^M 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Expect(5): OK 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Received: AT^M^M 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Received: OK^M 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Send: ATE1Q0^M 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Expect(5): OK 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Received: ATE1Q0^M^M 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Received: OK^M 
Feb  3 21:18:31 goofy ppp[1631]: tun0: Chat: Send: ATDT0840777700^M 
Feb  3 21:18:33 goofy ppp[1631]: tun0: Chat: Expect(40): CONNECT 
Feb  3 21:18:36 goofy ppp[1631]: tun0: Chat: Received: ATDT0840777700^M^M 
Feb  3 21:18:36 goofy ppp[1631]: tun0: Chat: Received: BUSY^M 
Feb  3 21:18:36 goofy ppp[1631]: tun0: Warning: Chat script failed 
Feb  3 21:18:36 goofy ppp[1631]: tun0: Phase: deflink: dial -> hangup 


pppd.log:

Feb  3 21:24:41 goofy pppd[1526]: pppd 2.4.1 started by user, uid 0
Feb  3 21:24:42 goofy chat[1821]: abort on (BUSY)
Feb  3 21:24:42 goofy chat[1821]: abort on (NO CARRIER)
Feb  3 21:24:42 goofy chat[1821]: abort on (NO DIALTONE)
Feb  3 21:24:42 goofy chat[1821]: send (ATDT0840777700^M)
Feb  3 21:24:42 goofy chat[1821]: expect (CONNECT)
Feb  3 21:25:10 goofy chat[1821]: ATDT0840777700^M^M
Feb  3 21:25:10 goofy chat[1821]: CONNECT
Feb  3 21:25:10 goofy chat[1821]:  -- got it 
Feb  3 21:25:10 goofy chat[1821]: send (^M)
Feb  3 21:25:10 goofy pppd[1526]: Serial connection established.
Feb  3 21:25:10 goofy pppd[1526]: Using interface ppp0
Feb  3 21:25:10 goofy pppd[1526]: Connect: ppp0 <--> /dev/tty03
Feb  3 21:25:18 goofy pppd[1526]: Remote message: Login Succeeded


FreeBSD ppp.log:

Feb  3 20:51:15 goofy ppp[1084]: tun0: Command: /var/run/pppctl: dial
Feb  3 20:51:15 goofy ppp[1084]: tun0: Phase: bundle: Establish
Feb  3 20:51:15 goofy ppp[1084]: tun0: Phase: deflink: closed -> opening
Feb  3 20:51:15 goofy ppp[1084]: tun0: Phase: deflink: Connected!
Feb  3 20:51:15 goofy ppp[1084]: tun0: Phase: deflink: opening -> dial
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Phone: 0840777700
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: deflink: Dial attempt 1 of 1
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Send: AT^M
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Expect(5): OK
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Received: OK^M
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Send: ATE1Q0^M
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Expect(5): OK
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Received: ATE1Q0^M^M
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Received: OK^M
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Send: ATL0^M
Feb  3 20:51:15 goofy ppp[1084]: tun0: Chat: Expect(5): OK
Feb  3 20:51:16 goofy ppp[1084]: tun0: Chat: Received: ATL0^M^M
Feb  3 20:51:16 goofy ppp[1084]: tun0: Chat: Received: OK^M
Feb  3 20:51:16 goofy ppp[1084]: tun0: Chat: Send: ATM0^M
Feb  3 20:51:16 goofy ppp[1084]: tun0: Chat: Expect(5): OK
Feb  3 20:51:16 goofy ppp[1084]: tun0: Chat: Received: ATM0^M^M
Feb  3 20:51:16 goofy ppp[1084]: tun0: Chat: Received: OK^M
Feb  3 20:51:16 goofy ppp[1084]: tun0: Chat: Send: ATDT0840777700^M
Feb  3 20:51:18 goofy ppp[1084]: tun0: Chat: Expect(40): CONNECT
Feb  3 20:51:51 goofy ppp[1084]: tun0: Chat: Received: ATDT0840777700^M^M
Feb  3 20:51:51 goofy ppp[1084]: tun0: Chat: Received: CONNECT 115200^M
Feb  3 20:51:51 goofy ppp[1084]: tun0: Phase: deflink: dial -> carrier
Feb  3 20:51:52 goofy ppp[1084]: tun0: Phase: deflink: /dev/cuaa4: CD detected


The chat part of ppp looks like:

 set dial "ABORT BUSY ABORT NO\\sCARRIER ABORT NO\\sDIALTONE TIMEOUT 5 \
           \"\" AT OK-AT-OK ATE1Q0 OK \\dATDT\\T TIMEOUT 40 CONNECT"


So why does ppp get BUSY immediately while pppd does work?

-Hanspeter