some problem

some problem

[Murali K. Vemuri]

[-- Attachment #1: Type: text/plain, Size: 706 bytes --]

Hi There,
I am using ppp version 2.4.4 and I am using the /etc/ppp/options file
for configuration parameters. I am also using the CHAT program for
automating the MODEM stuff.

I attached the /etc/ppp/options file and /etc/ppp/chat-sk file in this
mail. (chat-sk is the file I use for 'chat' program)

When I run the PPP, I am getting some kind of "Failed" message from Chat
program and after few seconds, PPP sends out LCP Conf req and I am not
getting any response.

BTW, this is a wireless modem so, one side its connected to my board on
USB and on the other side I cannot do any packet dump.

please check the logs below and let me know if you have any clue:

Thanks & regards
Murali

[-- Attachment #2: options --]
[-- Type: text/plain, Size: 162 bytes --]

debug
/dev/modem
115200
modem
defaultroute
crtscts
connect '/sbin/chat -v -f /etc/ppp/chat-sk'
ipcp-accept-local
ipcp-accept-remote
usepeerdns
persist

[-- Attachment #3: chat-sk --]
[-- Type: text/plain, Size: 132 bytes --]

ABORT "NO DIALTONE"
ABORT "ERROR"
ABORT "NO ANSWER"
ABORT "BUSY"
AT+CGDCONT=1,"ip","web.sktelecom.com",,,
ATDT*98#
CONNECT


[-- Attachment #4: ppp-logs --]
[-- Type: text/plain, Size: 2842 bytes --]

Jan  1 00:01:36 (none) daemon.notice pppd[88]: pppd 2.4.4 started by root, uid 0
Jan  1 00:01:37 (none) local2.info chat[91]: abort on (NO DIALTONE)
Jan  1 00:01:37 (none) local2.info chat[91]: abort on (ERROR)
Jan  1 00:01:37 (none) local2.info chat[91]: abort on (NO ANSWER)
Jan  1 00:01:37 (none) local2.info chat[91]: abort on (BUSY)
Jan  1 00:01:37 (none) local2.info chat[91]: expect (AT+CGDCONT=1,"ip","web.sktelecom.com",,,)
Jan  1 00:02:22 (none) local2.info chat[91]: alarm
Jan  1 00:02:22 (none) local2.info chat[91]: Failed
Jan  1 00:02:22 (none) daemon.debug pppd[88]: device script returned: 768
Jan  1 00:02:22 (none) daemon.info pppd[88]: Serial connection established.
Jan  1 00:02:22 (none) daemon.debug pppd[88]: using channel 1
Jan  1 00:02:22 (none) daemon.info pppd[88]: Using interface ppp0
Jan  1 00:02:22 (none) daemon.notice pppd[88]: Connect: ppp0 <--> /dev/modem
Jan  1 00:02:23 (none) daemon.warn pppd[88]: Warning - secret file /etc/ppp/pap-secrets has world and/or group access
Jan  1 00:02:23 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:26 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:29 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:32 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:35 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:38 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:41 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:44 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:47 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:50 (none) daemon.debug pppd[88]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x109561d8> <pcomp> <accomp>]
Jan  1 00:02:53 (none) daemon.warn pppd[88]: LCP: timeout sending Config-Requests
Jan  1 00:02:53 (none) daemon.notice pppd[88]: Connection terminated.
Jan  1 00:02:54 (none) daemon.notice pppd[88]: Modem hangup
Jan  1 00:03:25 (none) local2.info chat[125]: abort on (NO DIALTONE)
Jan  1 00:03:25 (none) local2.info chat[125]: abort on (ERROR)
Jan  1 00:03:25 (none) local2.info chat[125]: abort on (NO ANSWER)
Jan  1 00:03:25 (none) local2.info chat[125]: abort on (BUSY)
Jan  1 00:03:25 (none) local2.info chat[125]: expect (AT+CGDCONT=1,"ip","web.sktelecom.com",,,)

Re: some problem

[Eugene Paskevich]

On Wed, 03 Mar 2010 09:55:54 +0200, Murali K. Vemuri <murali@uczen.co.kr>  
wrote:

> When I run the PPP, I am getting some kind of "Failed" message from Chat
> program and after few seconds, PPP sends out LCP Conf req and I am not
> getting any response.

You should definitely take a closer look at chat manual page.
Currently your script is malformed.

-- 
Eugene Paskevich             |   *=)-----------   |     Plug me into
eugene@raptor.kiev.ua        |   -----------(=*   |      The Matrix

Re: some problem

[James Carlson]

Murali K. Vemuri wrote:
> When I run the PPP, I am getting some kind of "Failed" message from Chat
> program and after few seconds, PPP sends out LCP Conf req and I am not
> getting any response.

Your chat script is malformed.  You have this:

AT+CGDCONT=1,"ip","web.sktelecom.com",,,
ATDT*98#
CONNECT

But the syntax for chat is pairs of strings in "expect send" format.
This means that each one of those strings above is something we're
expecting to see from the modem, and we send nothing at all.

What you should have is something more like this:

"" AT+CGDCONT=1,"ip","web.sktelecom.com",,,
OK 'ATDT*98#'
CONNECT

That says:

  - expect nothing at first; just send
  - send the "AT+..." string
  - expect "OK" as a response
  - then send the "ATD..." string
  - finally expect "CONNECT" as a response before exiting to PPP

See the chat man page and your modem's documentation for details.  I
don't know off-hand if the AT commands you're using are necessarily the
right ones, so there's some guesswork involved.

The log file shows this failure:

Jan  1 00:01:37 (none) local2.info chat[91]: abort on (BUSY)
Jan  1 00:01:37 (none) local2.info chat[91]: expect
(AT+CGDCONT=1,"ip","web.sktelecom.com",,,)
Jan  1 00:02:22 (none) local2.info chat[91]: alarm
Jan  1 00:02:22 (none) local2.info chat[91]: Failed

Note that we were expecting to receive a string that we should have been
sending, and that the "alarm" (time-out) went off, resulting in failure.
 That's symptomatic of a malformed chat script.

This next part is strange, and I can't explain it.  It looks like pppd
plows ahead even though the script obviously failed.  I don't know if
this is a platform bug (is this UNIX or something else?), or if it's
some sort of obscure problem in pppd.

Jan  1 00:02:22 (none) daemon.debug pppd[88]: device script returned: 768
Jan  1 00:02:22 (none) daemon.info pppd[88]: Serial connection established.

In any event, pppd should have aborted without attempting to run LCP.
LCP is unlikely to be useful at all if the chat script fails.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>

Re: some problem

[Charlie Brady]

On Wed, 3 Mar 2010, James Carlson wrote:

> This next part is strange, and I can't explain it.  It looks like pppd
> plows ahead even though the script obviously failed.  I don't know if
> this is a platform bug (is this UNIX or something else?), or if it's
> some sort of obscure problem in pppd.

I suspect a bug in pppd. I am using pppd over pppoe, using:

pty '/usr/sbin/pppoe -I eth1 -T 120 -U -m 1412 '

pppd ploughs ahead with LCP even when the pppoe command fails when it 
cannot find its peer:

pppoe: Timeout waiting for PADO packets

>
> Jan  1 00:02:22 (none) daemon.debug pppd[88]: device script returned: 768
> Jan  1 00:02:22 (none) daemon.info pppd[88]: Serial connection established.
>
> In any event, pppd should have aborted without attempting to run LCP.
> LCP is unlikely to be useful at all if the chat script fails.
>
>

Re: some problem

[Murali K. Vemuri]

Hi James et al.,

Thanks for the response.

I think I made some progress in the right direction.....

anyway,with your suggestions, I made changes in the CHAT script and then
I reverted one change in the pppd/main.c file (that was by mistake).

after that, I re ran the pppd, and these are the messages I got:

Jan  1 00:02:36 (none) daemon.notice pppd[106]: pppd 2.4.4 started by
root, uid 0
Jan  1 00:02:37 (none) local2.info chat[109]: abort on (NO DIALTONE)
Jan  1 00:02:37 (none) local2.info chat[109]: abort on (ERROR)
Jan  1 00:02:37 (none) local2.info chat[109]: abort on (NO ANSWER)
Jan  1 00:02:37 (none) local2.info chat[109]: abort on (BUSY)
Jan  1 00:02:37 (none) local2.info chat[109]: send (AT^M)
Jan  1 00:02:37 (none) local2.info chat[109]: send (AT
+CGDCONT=1,"ip","web.sktelecom.com",,,^M)
Jan  1 00:02:38 (none) local2.info chat[109]: send (ATDT*98#^M)
Jan  1 00:02:38 (none) local2.info chat[109]: expect (CONNECT)
Jan  1 00:03:23 (none) local2.info chat[109]: alarm
Jan  1 00:03:23 (none) local2.info chat[109]: Failed
Jan  1 00:03:23 (none) daemon.err pppd[106]: Connect script failed


Again, the PPPD connection failed. But I believe, may be valid reasons?

BTW, The modem I am using is a 3G Modem (WCDMA) and this modem was
supplied to us by the vendor with some installable software for WINDOWS.

So, my current effort is to create the dialer mechanism for Linux. 
My board uses 2.6.19 kernel and uses "busybox" for most of the general
linux utilities. 

given this background, would it be fair enough to talk to the TELCO &
Modem vendor to fix up the issue or I would need to dig little further
with CHAT script ?

any suggestions plz?

Thanks in advance
Murali

On Wed, 2010-03-03 at 08:37 -0500, James Carlson wrote:
> Murali K. Vemuri wrote:
> > When I run the PPP, I am getting some kind of "Failed" message from Chat
> > program and after few seconds, PPP sends out LCP Conf req and I am not
> > getting any response.
> 
> Your chat script is malformed.  You have this:
> 
> AT+CGDCONT=1,"ip","web.sktelecom.com",,,
> ATDT*98#
> CONNECT
> 
> But the syntax for chat is pairs of strings in "expect send" format.
> This means that each one of those strings above is something we're
> expecting to see from the modem, and we send nothing at all.
> 
> What you should have is something more like this:
> 
> "" AT+CGDCONT=1,"ip","web.sktelecom.com",,,
> OK 'ATDT*98#'
> CONNECT
> 
> That says:
> 
>   - expect nothing at first; just send
>   - send the "AT+..." string
>   - expect "OK" as a response
>   - then send the "ATD..." string
>   - finally expect "CONNECT" as a response before exiting to PPP
> 
> See the chat man page and your modem's documentation for details.  I
> don't know off-hand if the AT commands you're using are necessarily the
> right ones, so there's some guesswork involved.
> 
> The log file shows this failure:
> 
> Jan  1 00:01:37 (none) local2.info chat[91]: abort on (BUSY)
> Jan  1 00:01:37 (none) local2.info chat[91]: expect
> (AT+CGDCONT=1,"ip","web.sktelecom.com",,,)
> Jan  1 00:02:22 (none) local2.info chat[91]: alarm
> Jan  1 00:02:22 (none) local2.info chat[91]: Failed
> 
> Note that we were expecting to receive a string that we should have been
> sending, and that the "alarm" (time-out) went off, resulting in failure.
>  That's symptomatic of a malformed chat script.
> 
> This next part is strange, and I can't explain it.  It looks like pppd
> plows ahead even though the script obviously failed.  I don't know if
> this is a platform bug (is this UNIX or something else?), or if it's
> some sort of obscure problem in pppd.
> 
> Jan  1 00:02:22 (none) daemon.debug pppd[88]: device script returned: 768
> Jan  1 00:02:22 (none) daemon.info pppd[88]: Serial connection established.
> 
> In any event, pppd should have aborted without attempting to run LCP.
> LCP is unlikely to be useful at all if the chat script fails.
> 

Re: some problem

[James Cameron]

On Wed, Mar 03, 2010 at 11:41:15PM +0900, Murali K. Vemuri wrote:
> Jan  1 00:02:37 (none) local2.info chat[109]: send (AT^M)
> Jan  1 00:02:37 (none) local2.info chat[109]: send (AT
> +CGDCONT=1,"ip","web.sktelecom.com",,,^M)
> Jan  1 00:02:38 (none) local2.info chat[109]: send (ATDT*98#^M)
> Jan  1 00:02:38 (none) local2.info chat[109]: expect (CONNECT)
> Jan  1 00:03:23 (none) local2.info chat[109]: alarm

There's no evidence in that chat log that you are receiving anything
back from the modem.  You should receive OK in response to AT and
AT+CGDCONT.  Can you confirm that with a manual connection between
keyboard and modem?

A common cause of this is modems that provide two USB endpoints; one for
firmware update, one for communications.  The firmware update endpoint
may not respond.  For one modem, I fixed this by using the next device
name; /dev/ttyUSB1 instead of /dev/ttyUSB0.

Otherwise, the sequence looks acceptable.  For a sequence that I've
tested with a different modem, but which works with every other modem
I've tried, see:

http://quozl.linux.org.au/darcs/eee-bpw/etc/chatscripts/bpw

In this particular instance, an additional check AT+CGATT? is done to
verify that the modem has attached to the network ... before attempting
a connection.

-- 
James Cameron
http://quozl.linux.org.au/

Re: some problem

[James Carlson]

James Cameron wrote:
> On Wed, Mar 03, 2010 at 11:41:15PM +0900, Murali K. Vemuri wrote:
>> Jan  1 00:02:37 (none) local2.info chat[109]: send (AT^M)
>> Jan  1 00:02:37 (none) local2.info chat[109]: send (AT
>> +CGDCONT=1,"ip","web.sktelecom.com",,,^M)
>> Jan  1 00:02:38 (none) local2.info chat[109]: send (ATDT*98#^M)
>> Jan  1 00:02:38 (none) local2.info chat[109]: expect (CONNECT)
>> Jan  1 00:03:23 (none) local2.info chat[109]: alarm
> 
> There's no evidence in that chat log that you are receiving anything
> back from the modem.  You should receive OK in response to AT and
> AT+CGDCONT.  Can you confirm that with a manual connection between
> keyboard and modem?

More to the point, it looks like he removed the "OK" that I had in my
sample chat script, so even if it happens, he's not waiting for it.

It's important to note that most modem-like devices will balk if you
send back-to-back AT commands.  Internally, they don't design using the
usual sorts of UARTs that ordinary computers use.  Instead, for
autobauding, they use bit-bashing techniques.  One of the consequences
of this is that if you send a new character (particularly "A") right as
the modem is attempting to respond, it will treat that as a request to
abort the previous command.

Thus, you have to stop and wait for each "OK" response, or it'll fail
miserably, and that's not what he's doing.

Miniterm, kermit, cu or equivalent sounds like the right debugging tool
at this point.  And the programmer's reference manual and tech support
line for the manufacturer might be handy.  I don't think the device
works, at least here.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>

Re: some problem

[Murali K. Vemuri]

Hi James et al,
That was perfect. I changed the device to /dev/ttyUSB0
from /dev/ttyUSB1, and our entire lab was on cloud nine.
Thanks a ton for the extraordinary help.
Regards
Murali


On Thu, 2010-03-04 at 07:30 +1100, James Cameron wrote:
> On Wed, Mar 03, 2010 at 11:41:15PM +0900, Murali K. Vemuri wrote:
> > Jan  1 00:02:37 (none) local2.info chat[109]: send (AT^M)
> > Jan  1 00:02:37 (none) local2.info chat[109]: send (AT
> > +CGDCONT=1,"ip","web.sktelecom.com",,,^M)
> > Jan  1 00:02:38 (none) local2.info chat[109]: send (ATDT*98#^M)
> > Jan  1 00:02:38 (none) local2.info chat[109]: expect (CONNECT)
> > Jan  1 00:03:23 (none) local2.info chat[109]: alarm
> 
> There's no evidence in that chat log that you are receiving anything
> back from the modem.  You should receive OK in response to AT and
> AT+CGDCONT.  Can you confirm that with a manual connection between
> keyboard and modem?
> 
> A common cause of this is modems that provide two USB endpoints; one for
> firmware update, one for communications.  The firmware update endpoint
> may not respond.  For one modem, I fixed this by using the next device
> name; /dev/ttyUSB1 instead of /dev/ttyUSB0.
> 
> Otherwise, the sequence looks acceptable.  For a sequence that I've
> tested with a different modem, but which works with every other modem
> I've tried, see:
> 
> http://quozl.linux.org.au/darcs/eee-bpw/etc/chatscripts/bpw
> 
> In this particular instance, an additional check AT+CGATT? is done to
> verify that the modem has attached to the network ... before attempting
> a connection.
> 

Re: some problem

[James Cameron]

On Thu, Mar 04, 2010 at 11:31:16AM +0900, Murali K. Vemuri wrote:
> That was perfect. I changed the device to /dev/ttyUSB0
> from /dev/ttyUSB1, and our entire lab was on cloud nine.
> Thanks a ton for the extraordinary help.

What others were saying is still important ... you must make sure that
the chatscript checks for an OK answer back from the modem, because that
is the way it is supposed to work.

You cannot rely on the AT+CGDCONT command always completing before you
send the ATDT*98# command.  The OK back from the modem is an
acknowledgement of completion of the command.

Doing this properly will make what you build more resilient to unusual
environmental conditions or events.  It may work fine now, but will it
work forever?

A 3G modem is an embedded system.  It may have other more important
things to do like answering a radio beacon than processing your command.
The interface definition for that embedded system may require that you
not send commands until OK is seen.

I'm not trying to frighten you.

-- 
James Cameron
http://quozl.linux.org.au/