wvdial problems

In news:5imhc6F3pnm8gU1@mid.individual.net,
Gretch <gretchen@invalid.corn> wrote:

>>> Aug 15 22:29:43 linux0 chat[4034]: send (\dc^M^M)
>>
>> Hmmm...
>>
>> Aug 11 11:46:59 apraphoe chat[13969]: CONNECT
>> Aug 11 11:46:59 apraphoe chat[13969]: -- got it
>> Aug 11 11:46:59 apraphoe chat[13969]: send (\d)
>>
>>> $ cat /etc/ppp/dialscript
>>> ABORT BUSY ABORT 'NO CARRIER' "" AT&F0S11=50 OK ATDTxxxxxxx CONNECT
>>> \d\c
>>
>> Not exactly sure why the '\dc' got sent - the '\c' is supposed to
>> exit without sending a carriage return. Try quoting the '\d\c' at
>> the end of the dial-script (change the end of the line to be CONNECT
'\d\c').
>
> After quoting, the same result is achieved; indeed, the same result
> even if the \d\c is omitted.

Sorry, I meant to say that quoting suppresses the error of "\dc" getting
sent; the "same result" was meant to refer to the failure to establish a
working connection. My apologies for any confusion I created.

On Fri, 17 Aug 2007, in the Usenet newsgroup comp.os.linux.misc, in article
<5imhc6F3pnm8gU1@mid.individual.net>, Gretch wrote:

>Moe Trin <ibuprofin@painkiller.example.tld> wrote:

>> Is this the same box, or a different one?
>
>The M$ dialup is performed from w2k on a laptop, the Linux is a
>router/firewall dialup on a different box -- different
>modems/drivers/dialup-clients etc.

OK. Was hoping a bit that they were the same.

>Yes, just recording the connection then a voluntary disconnect yielded
>~17KB of "stuff".

What can I say?

>> I don't _think_ it's a factor here, but check the output of the command
>> 'rpm -q ppp' and see which package you have.
>
>$ rpm -q ppp
>ppp-2.4.1-3

OK - that's the good version.

>> Not exactly sure why the '\dc' got sent - the '\c' is supposed to exit
>> without sending a carriage return. Try quoting the '\d\c' at the end
>> of the dial-script (change the end of the line to be CONNECT '\d\c').
>
>After quoting, the same result is achieved; indeed, the same result even
>if the \d\c is omitted.

The rational - assume an mgetty is running with 'autoppp' mode. If you
start slinging ppp frames at it (which are 8 bit binary), mgetty says
"Oh - wants to talk ppp - let's do that'. If you send ANYTHING with the
eighth bit set to zero (ASCII - even a LF or CR), mgetty says "OK,
they want to talk text" - and that needs a whole bunch of configuration
that isn't done by default. This is no problem for windoze, as it starts
slinging ppp frames as soon as the modems are connected, but without
that '\c', chat will look at the chat-script and see "expect CONNECT"
and then there is the end of the script - I'll send a Carriage Return
(you see this in the logs as the ^M) and the peer _may_ think you are
going to the text mode. We also have the 'mystique' problem, with
people thinking "I'm using UNIX - I _MUST_ find some Login: prompt"
forgetting that they don't do this in windoze. A lot of the application
authors fall into this trap, which drive the ppp maintainers nuts.
The idiots who created WvDial find this astounding, which is why they
finally added the "Stupid Mode", as if their creation is the true way.

>A curious thing though, is that if I dial a long-distance PoP for the
>same ISP, the connection will cycle through all 10 default "sent [LCP
>ConfReq ..." without receiving a response before the "Modem
>hangup\nConnection terminated.", rather than having a hangup after a
>few seconds as occurs when dialing the local PoP number.

I'd feel a hell of a lot better if the other PoP responded properly. The
fact that they aren't hanging up the phone is slightly better, but it's
not getting us connected.

>This suggests to me that there may be a local Telco issue coincidentally
>complicating the problem, but the fact remains that the local w2k dialup
>connection is successful. The authentication seems to be hexadecimal
>plain text and won't be included here, but the protocol and
>authentication negotiations start as:

Before we get to an authentication exchange, we've got to get the darn
thing talking. They're not doing that. From a "normal" logfile:

-------------------------
Jul 3 09:55:23 gtech pppd[924]: Connect: ppp0 <--> /dev/ttyS1
Jul 3 09:55:24 gtech pppd[924]: sent [LCP ConfReq id=0x1 <asyncmap
0x0> <magic 0x8bab12d4> <pcomp> <accomp>]
Jul 3 09:55:27 gtech pppd[924]: sent [LCP ConfReq id=0x1 <asyncmap
0x0> <magic 0x8bab12d4> <pcomp> <accomp>]
Jul 3 09:55:27 gtech pppd[924]: rcvd [LCP ConfReq id=0x1 < 00 04 00
00> <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> < 11 04
05 f4> < 13 09 03 00 c0 7b 90 17 04>]

Here, this box said hello, twice, before hearing from the peer. The peer
wants to have this system authenticate with PAP ( <auth pap> ), and is
offering three services this box never heard of.

Jul 3 09:55:27 gtech pppd[924]: sent [LCP ConfRej id=0x1 < 00 04 00
00> < 11 04 05 f4> < 13 09 03 00 c0 7b 90 17 04>]

So, this box rejects the unknown stuff.

Jul 3 09:55:27 gtech pppd[924]: rcvd [LCP ConfAck id=0x1 <asyncmap
0x0> <magic 0x8bab12d4> <pcomp> <accomp>]
Jul 3 09:55:27 gtech pppd[924]: rcvd [LCP ConfReq id=0x2 <mru 1524>
<asyncmap 0xa0000> <auth pap> <pcomp> <accomp>]
Jul 3 09:55:27 gtech pppd[924]: sent [LCP ConfAck id=0x2 <mru 1524>
<asyncmap 0xa0000> <auth pap> <pcomp> <accomp>]

The peer comes back and acknowledges the original 'hello', and says hello
itself, but this time without the unknown services. This box acknowledges
the peer.

Jul 3 09:55:27 gtech pppd[924]: sent [PAP AuthReq id=0x1 user=<hidden>
password=<hidden>]
Jul 3 09:55:28 gtech pppd[924]: rcvd [PAP AuthAck id=0x1 ""]

This box sends in the username and password (here edited out), and the peer
comes back and approves the login.
-------------------------

Notice, we're not seeing this. The peer is just ignoring us. What may
be good news is that pppd isn't complaining about the line looped back,
or all characters having bit 7 (start from zero - this is the high order
bit) set to zero (or one) - symptoms that generally indicate we're not
talking to a ppp server. Instead, we're getting nothing. THAT is the
problem.

>[1280] 15:36:59:754: <PPP packet sent at 08/16/2007 22:36:59:754
>[1280] 15:36:59:754: <Protocol = LCP, Type = Configure-Req, Length = 0x34,
>Id = 0x0, Port = 5

This is the "you said hello"

>[1520] 15:37:00:235: Packet received (41 bytes) for hPort 5
>[1280] 15:37:00:235: >PPP packet received at 08/16/2007 22:37:00:235
>[1280] 15:37:00:235: >Protocol = LCP, Type = Configure-Req, Length = 0x29,
>Id = 0x1, Port = 5

and that's the peer saying hello. Notice the ID and length are different
so we're reasonably assured this isn't a loopback of what we sent.

>1280] 15:37:00:235: <PPP packet sent at 08/16/2007 22:37:00:235
>[1280] 15:37:00:235: <Protocol = LCP, Type = Configure-Reject, Length =
> 0xa, Id = 0x1, Port = 5
>[1280] 15:37:00:235: <C0 21 04 01 00 08 00 04 00 00 00 00 00 00 00 00

c021 Link Control Protocol
4 Configure-Reject
01 Identifier
00 08 Length 8 bytes

and I loose it there - but not to be out-done, the peer comes back

>[1520] 15:37:00:235: Packet received (9 bytes) for hPort 5
>[1280] 15:37:00:235: >PPP packet received at 08/16/2007 22:37:00:235
>[1280] 15:37:00:235: >Protocol = LCP, Type = Configure-Reject, Length =
> 0x9, Id = 0x0, Port = 5
>[1280] 15:37:00:235: >C0 21 04 00 00 07 0D 03 06 00 00 00 00 00 00 00

and rejects something that was proposed here. This stuff comes from
RFC1661, and a ppp numbers web page from IANA (or close enough to
RFC1700 which is obsolete).

The big point here is that the peer is actually talking. We're not even
getting that far. THAT is what is frustrating.

http://www.modemsite.com/56k/modemlog2k.asp w2k & XP modem log howto

A possibility is that you are trying to talk to a windoze server (I can't
tell from the windoze ppp log). I think it's W2K that can be configured
as a "RAS Server" that expects a text exchange - you say "CLIENT" and
the peer comes back with "CLIENT/SERVER" or some such rot. I really
wouldn't expect this, but we're running out of possibilities. My
understanding is that the 'modem.log' (which is somewhat less bloated
by the way) would show this exchange if it existed. If we needed to
go this way, that would simply involve changing the chat script ending
from 'CONNECT \d\c' to (I'm guessing here) 'CONNECT CLIENT CLIENT/SERVER
\d\c' - but I'd like to see the modem log before trying that trick.

Old guy

In news:slrnfccrvk.d5q.ibuprofin@compton.phx.az.us,
Moe Trin <ibuprofin@painkiller.example.tld> wrote:

> Before we get to an authentication exchange, we've got to get the darn
> thing talking. They're not doing that.

I may have discovered the reason prior to reading your very informative and
corroborative response, as a result of downloading and installing
ftp://ftp.samba.org/pub/ppp/ppp-2.4.4.tar.gz and the encryption tools
necessary to support MSCHAP-{80,81} from
http://www2.psy.uq.edu.au/~ftp/Crypt...es-4.01.tar.gz

From the ${ppp.2.4.4}/README.MSCHAP80 file: "Another thing that might cause
problems is that some RAS servers won't respond at all to LCP config
requests without seeing the word "CLIENT" from the other end. If you see
pppd sending out LCP config requests without getting any reply, try putting
something in your chat script to send the word CLIENT after the modem has
connected."

> A possibility is that you are trying to talk to a windoze server (I
> can't tell from the windoze ppp log). I think it's W2K that can be
> configured as a "RAS Server" that expects a text exchange - you say
> "CLIENT" and the peer comes back with "CLIENT/SERVER" or some
> such rot. I really wouldn't expect this, but we're running out of
possibilities. My
> understanding is that the 'modem.log' (which is somewhat less bloated
> by the way) would show this exchange if it existed. If we needed to
> go this way, that would simply involve changing the chat script ending
> from 'CONNECT \d\c' to (I'm guessing here) 'CONNECT CLIENT
> CLIENT/SERVER \d\c' - but I'd like to see the modem log before
> trying that trick.

I simply can't find any information in the M$ ppp.log to see what sort of
conversation is happening before the M$ box starts slinging PPP packets:
[480] 16:19:29:399: PPPEMSG_Start recvd, d=,
hPort=5,callback=0,mask=83074a,IfType=-1
[1560] 16:19:29:449: Line up event occurred on port 5
[1560] 16:19:29:449: Local identification = MSRAS-0-W2K
[1560] 16:19:29:449: PortName: COM7
[1560] 16:19:29:449: Starting PPP on link with
IfType=0xffffffff,IPIf=0xffffffff,IPXIf=0xffffffff
[1560] 16:19:29:449: RasGetBuffer returned 100060 for SendBuf
[1560] 16:19:29:449: FsmInit called for protocol = c021, port = 5
[1560] 16:19:29:449: ConfigInfo = 83074a
[1560] 16:19:29:449: APs available = 5e
[1560] 16:19:29:459: FsmReset called for protocol = c021, port = 5
[1560] 16:19:29:459: Inserting port in bucket # 5
[1560] 16:19:29:459: Inserting bundle in bucket # 1
[1560] 16:19:29:459: FsmOpen event received for protocol c021 on port 5
[1560] 16:19:29:459: FsmThisLayerStarted called for protocol = c021, port =
5
[1560] 16:19:29:489: FsmUp event received for protocol c021 on port 5
[1560] 16:19:29:529: <PPP packet sent at 08/18/2007 23:19:29:489
[1560] 16:19:29:529: <Protocol = LCP, Type = Configure-Req, Length = 0x34,
Id = 0x0, Port = 5
[1560] 16:19:29:529: <C0 21 01 00 00 32 02 06 00 00 00 00 05 06 53 51
|.!...2........SQ|
[1560] 16:19:29:529: <03 4F 07 02 08 02 0D 03 06 11 04 06 4E 13 17 01
|.O..........N...|
[1560] 16:19:29:529: <FD C3 D0 86 A1 48 4D 4B BF 2A D8 B3 31 32 5F C9
|.....HMK.*..12_.|
[1560] 16:19:29:529: <00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
|................|
[1560] 16:19:29:529:
[1560] 16:19:29:529: InsertInTimerQ called
portid=0,Id=0,Protocol=c021,EventType=0,fAuth=0
[1560] 16:19:29:529: InsertInTimerQ called
portid=0,Id=0,Protocol=0,EventType=3,fAuth=0
[1472] 16:19:29:980: Packet received (41 bytes) for hPort 5
[1560] 16:19:29:980: >PPP packet received at 08/18/2007 23:19:29:980
....

The Linux ppp-debug.log shows (using the new pppd/chat and the long-distance
PoP that doesn't hangup prematurely):

Aug 18 16:33:59 linux0 pppd[13525]: pppd 2.4.4 started by gretch, uid 0
Aug 18 16:34:00 linux0 chat[13526]: abort on (BUSY)
Aug 18 16:34:00 linux0 chat[13526]: abort on (NO CARRIER)
Aug 18 16:34:00 linux0 chat[13526]: send (ATS11=50^M)
Aug 18 16:34:00 linux0 chat[13526]: expect (OK)
Aug 18 16:34:00 linux0 chat[13526]: ATS11=50^M^M
Aug 18 16:34:00 linux0 chat[13526]: OK
Aug 18 16:34:00 linux0 chat[13526]: -- got it
Aug 18 16:34:00 linux0 chat[13526]: send (ATDT18005431462,,,,,xxxxxxxxxx^M)
Aug 18 16:34:01 linux0 chat[13526]: expect (CONNECT)
Aug 18 16:34:01 linux0 chat[13526]: ^M
Aug 18 16:34:41 linux0 chat[13526]: ATDT18005431462,,,,,xxxxxxxxxx^M^M
Aug 18 16:34:41 linux0 chat[13526]: CONNECT
Aug 18 16:34:41 linux0 chat[13526]: -- got it
Aug 18 16:34:41 linux0 chat[13526]: send (CLIENT^M)
Aug 18 16:34:41 linux0 chat[13526]: expect (CLIENT/SERVER)
Aug 18 16:34:41 linux0 chat[13526]: 24000/ARQ^M
Aug 18 16:35:26 linux0 chat[13526]: alarm
Aug 18 16:35:26 linux0 chat[13526]: Failed

Instead of CLIENT I tried sending MSRAS-0-W2K from the other log, but the
expected response seems to be the problem? ... CLIENT ' ' '\d\c' seems to
receive the expected blank response and continue on to repeated LCP
ConfReq's as before:

Aug 18 17:22:13 linux0 chat[13676]: send (CLIENT^M)
Aug 18 17:22:13 linux0 chat[13676]: expect ( )
Aug 18 17:22:13 linux0 chat[13676]:
Aug 18 17:22:13 linux0 chat[13676]: -- got it
Aug 18 17:22:13 linux0 chat[13676]: send (\d)
Aug 18 17:22:14 linux0 chat[13676]: expect (^M)
Aug 18 17:22:14 linux0 chat[13676]: 26400/ARQ^M
Aug 18 17:22:14 linux0 chat[13676]: -- got it
Aug 18 17:22:14 linux0 chat[13676]: send (^M^M)
Aug 18 17:22:14 linux0 pppd[13675]: using channel 34
Aug 18 17:22:14 linux0 pppd[13675]: Connect: ppp0 <--> /dev/ttyS1
Aug 18 17:22:15 linux0 pppd[13675]: sent [LCP ConfReq id=0x1 <asyncmap 0x0>
<magic 0xc9373a71> <pcomp> <accomp>]
Aug 18 17:22:43 linux0 last message repeated 9 times
Aug 18 17:22:46 linux0 pppd[13675]: Connection terminated.
Aug 18 17:22:47 linux0 pppd[13675]: Modem hangup

The PoP list in .csv format can be found at
http://dialup.ispnetbilling.com/exce...ISPWholesale-8 , but I'm
unable to discern the M$ connection conversation from the few dialup numbers
I've tried, as they don't differ from the portion I posted earlier in
news:<5imhc6F3pnm8gU1@mid.individual.net> or above. As you say, the
possibilities are seemingly almost exhausted, but perhaps you might see
something useful at the PoP that's local to you, if you would be so kind and
can spare some minutes from your busy schedule. I really learn a great deal
from your responses, thank you.

On Sat, 18 Aug 2007, in the Usenet newsgroup comp.os.linux.misc, in article
<5ipjeaF3q5jrhU1@mid.individual.net>, Gretch wrote:

>Moe Trin <ibuprofin@painkiller.example.tld> wrote:

>> Before we get to an authentication exchange, we've got to get the
>> darn thing talking. They're not doing that.

>I may have discovered the reason prior to reading your very informative
>and corroborative response, as a result of downloading and installing
>ftp://ftp.samba.org/pub/ppp/ppp-2.4.4.tar.gz and the encryption tools
>necessary to support MSCHAP-{80,81} from
>http://www2.psy.uq.edu.au/~ftp/Crypt...es-4.01.tar.gz

MSCHAP-80 has been supported since ppp-2.3.2. MSCHAP-81 was
supported from ppp-2.4.2.

>>From the ${ppp.2.4.4}/README.MSCHAP80 file: "Another thing that might
>cause problems is that some RAS servers won't respond at all to LCP
>config requests without seeing the word "CLIENT" from the other end.
>If you see pppd sending out LCP config requests without getting any
>reply, try putting something in your chat script to send the word
>CLIENT after the modem has connected."

Yup. Thing is, these are not very common for regular ISPs (and PoPs
run for them). I think I may gave seen the "CLIENT" stanza needed less
than a dozen times in ten years. MSCHAP-81 was something invented for
W2K, and was pretty much a bust, mainly because it is totally
incompatible with MSCHAP-80. ISPs want compatibility, because having
win95 lusers calling in about the Internet being b0rken is wasting
their hell-desk staff time. In fact the number of ISPs using MSCHAP
of any kind is tiny. PAP, which was supposedly superseded by CHAP-MD5
in August 1996, is still the most common authentication algorithm.

>I simply can't find any information in the M$ ppp.log to see what
>sort of conversation is happening before the M$ box starts slinging
>PPP packets:
>[480] 16:19:29:399: PPPEMSG_Start recvd, d=,
>hPort=5,callback=0,mask=83074a,IfType=-1

No, that looks to long in the connection. What you should be seeing
is the modem initiation, dialing, and the modem connect string.

>The Linux ppp-debug.log shows (using the new pppd/chat and the
>long-distance PoP that doesn't hangup prematurely):

>Aug 18 16:34:00 linux0 chat[13526]: abort on (NO CARRIER)
>Aug 18 16:34:00 linux0 chat[13526]: send (ATS11=50^M)
>Aug 18 16:34:00 linux0 chat[13526]: expect (OK)
>Aug 18 16:34:00 linux0 chat[13526]: ATS11=50^M^M
>Aug 18 16:34:00 linux0 chat[13526]: OK
>Aug 18 16:34:00 linux0 chat[13526]: -- got it

You're not initializing the modem

>Aug 18 16:34:41 linux0 chat[13526]: send (CLIENT^M)
>Aug 18 16:34:41 linux0 chat[13526]: expect (CLIENT/SERVER)
>Aug 18 16:34:41 linux0 chat[13526]: 24000/ARQ^M
>Aug 18 16:35:26 linux0 chat[13526]: alarm
>Aug 18 16:35:26 linux0 chat[13526]: Failed

The " 24000/ARQ" is the rest of the modem connect stanza (pppd is like
a little kid - you tell it to look for something, and as soon as it
finds that, it's screaming "I FOUND IT - I FOUND IT!!!" without waiting
for the modem to finish the statement). Obviously nothing came back.

>Instead of CLIENT I tried sending MSRAS-0-W2K from the other log, but the
>expected response seems to be the problem? ... CLIENT ' ' '\d\c' seems to
>receive the expected blank response

The 'MSRAS-0-W2K' _appears_ to be a local variable, but I've never seen
it reported as being used over the wire.

>Aug 18 17:22:13 linux0 chat[13676]: send (CLIENT^M)
>Aug 18 17:22:13 linux0 chat[13676]: expect ( )
>Aug 18 17:22:13 linux0 chat[13676]:
>Aug 18 17:22:13 linux0 chat[13676]: -- got it

OK, what happened there is that 'chat' found the space between the
word CONNECT and 24000/ARQ.

>Aug 18 17:22:14 linux0 chat[13676]: expect (^M)
>Aug 18 17:22:14 linux0 chat[13676]: 26400/ARQ^M
>Aug 18 17:22:14 linux0 chat[13676]: -- got it
>Aug 18 17:22:14 linux0 chat[13676]: send (^M^M)

then you are expecting a CR, and finding that at the end of the modem
CONNECT stanza. You could try 'CONNECT CLIENT' (expect CONNECT, send
CLIENT) and see it that does anything, but I'm not holding much hope.

>The PoP list in .csv format can be found at
>http://dialup.ispnetbilling.com/exce...ISPWholesale-8

I have no means of reading that web page.

>but I'm unable to discern the M$ connection conversation from the few
>dialup numbers I've tried, as they don't differ from the portion I
>posted earlier

What we are looking for occurs before the ppp log stuff.

>As you say, the possibilities are seemingly almost exhausted, but
>perhaps you might see something useful at the PoP that's local to you,
>if you would be so kind and can spare some minutes from your busy
>schedule. I really learn a great deal from your responses, thank you.

Do you have a number in the Phoenix (Arizona) metro area? That would
be area codes 480, 602, or 623?

Old guy

In news:slrnfcff9r.3l6.ibuprofin@compton.phx.az.us,
Moe Trin <ibuprofin@painkiller.example.tld> wrote:

> In fact the number of ISPs using MSCHAP
> of any kind is tiny. PAP, which was supposedly superseded by CHAP-MD5
> in August 1996, is still the most common authentication algorithm.

That is apparently what's being offered here, from a previous post:
[1280] 15:37:00:445: Authenticating phase started
[1280] 15:37:00:445: <PPP packet sent at 08/16/2007 22:37:00:445
[1280] 15:37:00:445: <Protocol = PAP, Type = Protocol specific, Length =
0x22, Id = 0x5, Port = 5

>> I simply can't find any information in the M$ ppp.log to see what
>> sort of conversation is happening before the M$ box starts slinging
>> PPP packets:
>> [480] 16:19:29:399: PPPEMSG_Start recvd, d=,
>> hPort=5,callback=0,mask=83074a,IfType=-1
>
> No, that looks to long in the connection. What you should be seeing
> is the modem initiation, dialing, and the modem connect string.

Yes, that makes sense, but it doesn't appear in any of the logs: the [480]
is the earliest line logged in every call.

>> The Linux ppp-debug.log shows (using the new pppd/chat and the
>> long-distance PoP that doesn't hangup prematurely):
>
>> Aug 18 16:34:00 linux0 chat[13526]: abort on (NO CARRIER)
>> Aug 18 16:34:00 linux0 chat[13526]: send (ATS11=50^M)
>> Aug 18 16:34:00 linux0 chat[13526]: expect (OK)
>> Aug 18 16:34:00 linux0 chat[13526]: ATS11=50^M^M
>> Aug 18 16:34:00 linux0 chat[13526]: OK
>> Aug 18 16:34:00 linux0 chat[13526]: -- got it
>
> You're not initializing the modem

Sorry, I didn't repost the earlier part, only what led to the next section
to show the send()/expect() as hinted.

>> Aug 18 16:34:41 linux0 chat[13526]: send (CLIENT^M)
>> Aug 18 16:34:41 linux0 chat[13526]: expect (CLIENT/SERVER)
>> Aug 18 16:34:41 linux0 chat[13526]: 24000/ARQ^M
>> Aug 18 16:35:26 linux0 chat[13526]: alarm
>> Aug 18 16:35:26 linux0 chat[13526]: Failed
>
> The " 24000/ARQ" is the rest of the modem connect stanza (pppd is like
> a little kid - you tell it to look for something, and as soon as it
> finds that, it's screaming "I FOUND IT - I FOUND IT!!!" without
> waiting for the modem to finish the statement). Obviously nothing
> came back.
>
>> Instead of CLIENT I tried sending MSRAS-0-W2K from the other log,
>> but the expected response seems to be the problem? ... CLIENT ' '
>> '\d\c' seems to receive the expected blank response
>
> The 'MSRAS-0-W2K' _appears_ to be a local variable, but I've never
> seen
> it reported as being used over the wire.
>
>> Aug 18 17:22:13 linux0 chat[13676]: send (CLIENT^M)
>> Aug 18 17:22:13 linux0 chat[13676]: expect ( )
>> Aug 18 17:22:13 linux0 chat[13676]:
>> Aug 18 17:22:13 linux0 chat[13676]: -- got it
>
> OK, what happened there is that 'chat' found the space between the
> word CONNECT and 24000/ARQ.
>
>> Aug 18 17:22:14 linux0 chat[13676]: expect (^M)
>> Aug 18 17:22:14 linux0 chat[13676]: 26400/ARQ^M
>> Aug 18 17:22:14 linux0 chat[13676]: -- got it
>> Aug 18 17:22:14 linux0 chat[13676]: send (^M^M)
>
> then you are expecting a CR, and finding that at the end of the modem
> CONNECT stanza. You could try 'CONNECT CLIENT' (expect CONNECT, send
> CLIENT) and see it that does anything, but I'm not holding much hope.

Results:
....
Aug 18 18:35:35 linux0 chat[13864]: CONNECT
Aug 18 18:35:35 linux0 chat[13864]: -- got it
Aug 18 18:35:35 linux0 chat[13864]: send (CLIENT^M)
Aug 18 18:35:36 linux0 chat[13864]: expect (^M)
Aug 18 18:35:36 linux0 chat[13864]: 26400/ARQ^M
Aug 18 18:35:36 linux0 chat[13864]: -- got it
Aug 18 18:35:36 linux0 chat[13864]: send (^M^M)
Aug 18 18:35:36 linux0 pppd[13863]: using channel 36
Aug 18 18:35:36 linux0 pppd[13863]: Connect: ppp0 <--> /dev/ttyS1
Aug 18 18:35:37 linux0 pppd[13863]: sent [LCP ConfReq id=0x1 <asyncmap 0x0>
<magic 0x1f660864> <pcomp> <accomp>]
Aug 18 18:36:04 linux0 last message repeated 9 times
Aug 18 18:36:07 linux0 pppd[13863]: Connection terminated.
Aug 18 18:36:08 linux0 pppd[13863]: Modem hangup

>> but I'm unable to discern the M$ connection conversation from the few
>> dialup numbers I've tried, as they don't differ from the portion I
>> posted earlier
>
> What we are looking for occurs before the ppp log stuff.

Yes; I wish I knew how to capture it. wireshark can't help as the interface
isn't yet up.

> Do you have a number in the Phoenix (Arizona) metro area? That would
> be area codes 480, 602, or 623?

wget -O- \
http://dialup.ispnetbilling.com/exce...ISPWholesale-8 \
2>/dev/null | egrep '^\"480|^\"602|^\"623'

yields:

"480","889-0114","USA","AZ ","Gilbert ","v.92","True","True",

All other AZ PoPs (44 of them) are area codes 520 and 928.

On Sat, 18 Aug 2007, in the Usenet newsgroup comp.os.linux.misc, in article
<5iq4dkF3q9dalU1@mid.individual.net>, Gretch wrote:

>Moe Trin <ibuprofin@painkiller.example.tld> wrote:

>> In fact the number of ISPs using MSCHAP of any kind is tiny. PAP,
>> which was supposedly superseded by CHAP-MD5 in August 1996, is still
>> the most common authentication algorithm.
>
>That is apparently what's being offered here

Yeah - it's insecure as can be (everything is plain text), but it's
been working since PPP became a common service in the early 1990s.

>> No, that looks to long in the connection. What you should be seeing
>> is the modem initiation, dialing, and the modem connect string.
>
>Yes, that makes sense, but it doesn't appear in any of the logs: the
>[480] is the earliest line logged in every call.

Recheck your modem log setup. It should be going to a different log
file.

>> You could try 'CONNECT CLIENT' (expect CONNECT, send CLIENT) and
>> see it that does anything, but I'm not holding much hope.

>Results:
>...
>Aug 18 18:35:35 linux0 chat[13864]: CONNECT
>Aug 18 18:35:35 linux0 chat[13864]: -- got it
>Aug 18 18:35:35 linux0 chat[13864]: send (CLIENT^M)
>Aug 18 18:35:36 linux0 chat[13864]: expect (^M)
>Aug 18 18:35:36 linux0 chat[13864]: 26400/ARQ^M
>Aug 18 18:35:36 linux0 chat[13864]: -- got it
>Aug 18 18:35:36 linux0 chat[13864]: send (^M^M)
>Aug 18 18:35:36 linux0 pppd[13863]: using channel 36
>Aug 18 18:35:36 linux0 pppd[13863]: Connect: ppp0 <--> /dev/ttyS1
>Aug 18 18:35:37 linux0 pppd[13863]: sent [LCP ConfReq id=0x1 <asyncmap
0x0> <magic 0x1f660864> <pcomp> <accomp>]
>Aug 18 18:36:04 linux0 last message repeated 9 times
>Aug 18 18:36:07 linux0 pppd[13863]: Connection terminated.
>Aug 18 18:36:08 linux0 pppd[13863]: Modem hangup

Darn!

>> What we are looking for occurs before the ppp log stuff.
>
>Yes; I wish I knew how to capture it. wireshark can't help as the
>interface isn't yet up.

I can't say because I don't use windoze, but the modem log instructions
should do the job.

>> Do you have a number in the Phoenix (Arizona) metro area? That would
>> be area codes 480, 602, or 623?
>
>wget -O- \
>http://dialup.ispnetbilling.com/exce...ISPWholesale-8 \
>2>/dev/null | egrep '^\"480|^\"602|^\"623'

Hmmm, didn't think to try wget.

>yields:
>
>"480","889-0114","USA","AZ ","Gilbert ","v.92","True","True",

================================================== ===================
Aug 19 11:22:23 galileo chat[8459]: abort on (BUSY)
Aug 19 11:22:23 galileo chat[8459]: abort on (NO CARRIER)
Aug 19 11:22:23 galileo chat[8459]: send (AT&F1^M)
Aug 19 11:22:23 galileo chat[8459]: expect (OK)
Aug 19 11:22:23 galileo chat[8459]: AT&F1^M^M
Aug 19 11:22:23 galileo chat[8459]: OK
Aug 19 11:22:23 galileo chat[8459]: -- got it
Aug 19 11:22:23 galileo chat[8459]: send (ATDT8890114^M)
Aug 19 11:22:23 galileo chat[8459]: expect (CONNECT)
Aug 19 11:22:23 galileo chat[8459]: ^M
Aug 19 11:22:43 galileo chat[8459]: ATDT8890114^M^M
Aug 19 11:22:43 galileo chat[8459]: CONNECT
Aug 19 11:22:43 galileo chat[8459]: -- got it
Aug 19 11:22:43 galileo chat[8459]: send (\d)
Aug 19 11:22:45 galileo pppd[8454]: sent [LCP ConfReq id=0x1 <magic
0x3f9363b9> <pcomp> <accomp>]
Aug 19 11:22:45 galileo pppd[8454]: rcvd [LCP ConfReq id=0x1 < 00 04 00
00> <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> < 11 04
05 f4> < 13 0e 01 6c 6f 73 61 6e 67 65 6c 65 73 31> < 17 04 66 05>]
Aug 19 11:22:45 galileo pppd[8454]: sent [LCP ConfRej id=0x1 < 00 04 00
00> <auth pap> < 11 04 05 f4> < 13 0e 01 6c 6f 73 61 6e 67 65 6c 65 73
31> < 17 04 66 05 >]
Aug 19 11:22:45 galileo pppd[8454]: rcvd [LCP ConfAck id=0x1 <magic
0x3f9363b9> <pcomp> <accomp>]
Aug 19 11:22:45 galileo pppd[8454]: rcvd [LCP TermReq id=0x2]
Aug 19 11:22:45 galileo pppd[8454]: sent [LCP TermAck id=0x2]
================================================== ===================

Works like a champ. I'm using exactly

[galileo ~]$ cat /usr/local/bin/dialinA
#!/bin/bash
exec /usr/sbin/pppd connect "/usr/sbin/chat -vf /etc/ppp/dialscriptA" \
lock defaultroute noipdefault nodetach /dev/modem 115200 crtscts user \
nobody.
[galileo ~]$ cat /etc/ppp/dialscriptA
ABORT BUSY ABORT 'NO CARRIER' "" AT&F1 OK ATDT8890114 CONNECT \d\c
[galileo ~]$

and the user 'nobody' is intentionally not in /etc/ppp/pap-secrets,
which is why pppd declined <auth pap>. Point is, I have no trouble
initiating the ppp negotiations. (I normally have most of the options
in /etc/ppp/options, but moved that out of the way and created an
empty options file for this attempt.)

What else can I see... It's offering MRRU, which is fine - interestingly
it's suggesting an Asyncmap of 0xa0000 (escaping XON/XOFF) which is
often the sign of a less clued configuration - your system defaults to
the normal 0x0. You could try setting your asyncmap option to 0xa0000
but it wasn't needed here. What else can I try?

I tried intentionally changing the expected modem stanza.

======================================
Aug 19 11:27:47 galileo chat[8565]: expect (CONNECTED)
Aug 19 11:27:47 galileo chat[8565]: ^M
Aug 19 11:28:07 galileo chat[8565]: ATDT8890114^M^M
Aug 19 11:28:07 galileo chat[8565]: CONNECT 28800/ARQ/V34/LAPM/V42BIS^M
Aug 19 11:28:12 galileo chat[8565]: ^M
Aug 19 11:28:12 galileo chat[8565]:
Aug 19 11:28:12 galileo last message repeated 23 times
Aug 19 11:28:12 galileo chat[8565]: *****Authorized use only-Unauthorized
use is Prohibited.**UQKT2^M
======================================

and they hung up. Tried changing to 'CONNECT CLIENT' and this had no
effect - they ignored the ASCII, and responded immediately to my LCP
frames. Unfortunately, that blows a hole in the idea that this peer
is sensitive to ASCII.

======================================
Aug 19 11:30:04 galileo chat[8578]: CONNECT
Aug 19 11:30:04 galileo chat[8578]: -- got it
Aug 19 11:30:04 galileo chat[8578]: send (CLIENT^M)
Aug 19 11:30:05 galileo pppd[8573]: sent [LCP ConfReq id=0x1 <magic
0xf7aaa560> <pcomp> <accomp>]
Aug 19 11:30:08 galileo pppd[8573]: sent [LCP ConfReq id=0x1 <magic
0xf7aaa560> <pcomp> <accomp>]
Aug 19 11:30:09 galileo pppd[8573]: rcvd [LCP ConfReq id=0x1 < 00 04 00
00> <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> < 11 04
05 f4> < 13 0e 01 6c 6f 73 61 6e 67 65 6c 65 73 31> < 17 04 b8 19>]
======================================

I'm not seeing anything strange. It _looks_ as if I had a valid user
name and password, this connection would work for me. I don't know if
it's a function of this PoP verses others, but this looks pretty much
like a standard terminal server - possibly an Ascend, and they're
relatively common and tolerant of mis-configured chat scripts. Of
minor interest, the ascii string in option 0x13 translates to
'losangles1' for an endpoint discriminator.

Old guy