pppd 2.3.5-2/Debian 2.0.30-2 or .34 dials into NT RAS+callback
Hi all,
I have tried to cope with it myself for about 4 days, then posted to
linux-ppp -- and, after a week since the post, I am still nowhere :-(
I posted it on debian-user with no results either. Then I realized that it
is kind of advanced question probably related to the overall ppp package
development and thought that debian-devel would be more appropriate for
it.
I am trying to set up an outbound PPP on linux into an NT box, which is
supposed to call me back. (pppd 2.3.5-2 with mschap and cbcp compiled in,
linux 2.0.30-2/Debian, then 2.0.34 with the same problems). I am 2 years
using Linux and different PPP
dialout/dialin setups, but this is the 1st time I am trying to make it
with NT on the other end.
Before setting it up in a bulletproof way (with support for BUSY/problems
on callback/etc) I just started with the following simple trial script:
-- script --
line 1> pppd debug noauth nodetach /dev/ttyS3 callback 08-9390138
user vassilii remotename net-post
connect 'chat "" atz "OK" atd036122362 "CONNECT" "" && sleep 1'
line 2> pppd debug noauth nodetach kdebug 3 /dev/ttyS3
user vassilii remotename net-post defaultroute
connect 'chat -v RING ATA "CONNECT" "\c" && sleep 1'
--end of script --
Now, it is not that things are totally not working.
chap-secrets file is properly set up.
I tried to setup a test acct on NT that doesn't do
callback; and then ensured ppp starts OK with it (the second line in the
above script then is not needed, of course), and I have a proper
internet connection.
Now, back to the callback scenario.
The dialout completes OK, I see the LCP negotiation progress and then the
disconnect; then the remote end calls me back. The second "chat" answers,
pppd starts... and this is the point I am stuck at: the peer never sends
me an LCP packet my pppd recognizes.
I tried to answer with minicom, not pppd/chat, and see if PPP data stream
comes in -- it does. I tried all the combinations of `passive' and
`silent'. (In the passive case my pppd sends out LCP requests, but never
gets an LCP response). After a timeout (I tried to increase it to 30 LCP
packets --- no diff :-( ) it hangs up.
I had a guess that on
the callback all the options must already be negotiated (IPCP etc.), but,
after careful examination of both the dialout w/o callback and w/ callbeck
LCP sequences, I made sure that nothing except for CHAP auth. and callback
negotiation takes place on the outbound call in the callback scenario --
so some LCP *must* take place on the callback stage!!!
I tried to enable kdebug 3 to see how pppd reacts to the incoming packets
from NT; and discovered they all are recognized as having CRC problems!!!
I understand things may be out of sync at the beginning -- while the
"CONNECT ..." modem message tail can still be in effect, or, vice versa,
if pppd starts up after the peer NT begins its PPP talk and misses some
initial peer PPP babble. But why doesn't it recover??
(The log messages attached in the end of the message are the ones
generated by the second pppd/chat line in the script).
Am I missing something obvious?
What can be wrong? Anyone ever set up outbound ppp w/ callback with an NT
RAS server? Have any refs to a sample setup? Anything?
(I checked all the things like /usr/doc/ppp, HOWTOs (Serial and PPP), sag
-- and found nothing :-( I understood from some on irc #debian that the
topic is relatively new and unknown... as soon as I get the solution from
anywhere I will post it here as well with all the sample conf. files and
suggest it for the PPP-FAQ.)
Many thanks to all who can shed some light on the issue.
vassilii (a.k.a. BACbKA on #debian)
-- script --
pppd debug noauth nodetach /dev/ttyS3 callback 08-9390138 user vassilii remotename net-post connect 'chat "" atz "OK" atd036122362 "CONNECT" "" && sleep 1'
pppd debug noauth nodetach kdebug 3 /dev/ttyS3 user vassilii remotename net-post defaultroute connect 'chat -v RING ATA "CONNECT" "\c" && sleep 1'
-- messages --
Jul 13 12:38:59 Desdemona pppd[189]: pppd 2.3.5 started by root, uid 0
Jul 13 12:39:00 Desdemona chat[191]: expect (RING)
Jul 13 12:39:08 Desdemona chat[191]: ^M
Jul 13 12:39:08 Desdemona chat[191]: RING
Jul 13 12:39:08 Desdemona chat[191]: -- got it
Jul 13 12:39:08 Desdemona chat[191]: send (ATA^M)
Jul 13 12:39:08 Desdemona chat[191]: expect (CONNECT)
Jul 13 12:39:08 Desdemona chat[191]: ^M
Jul 13 12:39:08 Desdemona chat[191]: ^M
Jul 13 12:39:08 Desdemona chat[191]: NO CARRIER^M
Jul 13 12:39:23 Desdemona chat[191]: A^M^M
Jul 13 12:39:23 Desdemona chat[191]: CONNECT
Jul 13 12:39:23 Desdemona chat[191]: -- got it
Jul 13 12:39:23 Desdemona chat[191]: send ()
Jul 13 12:39:24 Desdemona pppd[189]: Serial connection established.
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set flags to 30000
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set flags to 30000
Jul 13 12:39:25 Desdemona pppd[189]: Using interface ppp0
Jul 13 12:39:25 Desdemona pppd[189]: Connect: ppp0 <--> /dev/ttyS3
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set xasyncmap
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set flags to 30000
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set mru to 5dc
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set rcv asyncmap ffffffff
Jul 13 12:39:25 Desdemona kernel: ppp_tty_ioctl: set flags to 30000
Jul 13 12:39:55 Desdemona pppd[189]: LCP: timeout sending Config-Requests
Jul 13 12:39:55 Desdemona pppd[189]: Connection terminated.
Jul 13 12:39:55 Desdemona kernel: ppp: channel ppp0 closing.
Jul 13 12:39:56 Desdemona pppd[189]: Exit.
-- debug --
Jul 13 12:39:25 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:25 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:25 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:25 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:25 Desdemona kernel: C9 43 .C
Jul 13 12:39:27 Desdemona kernel: ppp: frame with bad fcs, length = 22
Jul 13 12:39:27 Desdemona kernel: ppp: bad frame, count = 22
Jul 13 12:39:27 Desdemona kernel: FF C0 00 21 34 C2 23 80 ...!4.#.
Jul 13 12:39:27 Desdemona kernel: 75 49 4E 78 D7 8E D2 BE uINx....
Jul 13 12:39:27 Desdemona kernel: A0 C9 8D 5D 51 BD ...]Q.
Jul 13 12:39:28 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:28 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:28 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:28 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:28 Desdemona kernel: C9 43 .C
Jul 13 12:39:31 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:31 Desdemona kernel: ppp: frame with bad fcs, length = 22
Jul 13 12:39:31 Desdemona kernel: ppp: bad frame, count = 22
Jul 13 12:39:31 Desdemona kernel: FF C0 00 21 34 C2 23 80 ...!4.#.
Jul 13 12:39:31 Desdemona kernel: 75 49 4E 78 D7 8E D2 BE uINx....
Jul 13 12:39:31 Desdemona kernel: A0 C9 8D 5D 51 BD ...]Q.
Jul 13 12:39:31 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:31 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:31 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:31 Desdemona kernel: C9 43 .C
Jul 13 12:39:34 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:34 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:34 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:34 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:34 Desdemona kernel: C9 43 .C
Jul 13 12:39:35 Desdemona kernel: ppp: frame with bad fcs, length = 22
Jul 13 12:39:35 Desdemona kernel: ppp: bad frame, count = 22
Jul 13 12:39:35 Desdemona kernel: FF C0 00 21 34 C2 23 80 ...!4.#.
Jul 13 12:39:35 Desdemona kernel: 75 49 4E 78 D7 8E D2 BE uINx....
Jul 13 12:39:35 Desdemona kernel: A0 C9 8D 5D 51 BD ...]Q.
Jul 13 12:39:37 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:37 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:37 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:37 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:37 Desdemona kernel: C9 43 .C
Jul 13 12:39:39 Desdemona kernel: ppp: frame with bad fcs, length = 22
Jul 13 12:39:39 Desdemona kernel: ppp: bad frame, count = 22
Jul 13 12:39:39 Desdemona kernel: FF C0 00 21 34 C2 23 80 ...!4.#.
Jul 13 12:39:39 Desdemona kernel: 75 49 4E 78 D7 8E D2 BE uINx....
Jul 13 12:39:39 Desdemona kernel: A0 C9 8D 5D 51 BD ...]Q.
Jul 13 12:39:40 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:40 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:40 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:40 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:40 Desdemona kernel: C9 43 .C
Jul 13 12:39:43 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:43 Desdemona kernel: ppp: frame with bad fcs, length = 22
Jul 13 12:39:43 Desdemona kernel: ppp: bad frame, count = 22
Jul 13 12:39:43 Desdemona kernel: FF C0 00 21 34 C2 23 80 ...!4.#.
Jul 13 12:39:43 Desdemona kernel: 75 49 4E 78 D7 8E D2 BE uINx....
Jul 13 12:39:43 Desdemona kernel: A0 C9 8D 5D 51 BD ...]Q.
Jul 13 12:39:43 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:43 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:43 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:43 Desdemona kernel: C9 43 .C
Jul 13 12:39:46 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:46 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:46 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:46 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:46 Desdemona kernel: C9 43 .C
Jul 13 12:39:47 Desdemona kernel: ppp: frame with bad fcs, length = 22
Jul 13 12:39:47 Desdemona kernel: ppp: bad frame, count = 22
Jul 13 12:39:47 Desdemona kernel: FF C0 00 21 34 C2 23 80 ...!4.#.
Jul 13 12:39:47 Desdemona kernel: 75 49 4E 78 D7 8E D2 BE uINx....
Jul 13 12:39:47 Desdemona kernel: A0 C9 8D 5D 51 BD ...]Q.
Jul 13 12:39:49 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:49 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:49 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:49 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:49 Desdemona kernel: C9 43 .C
Jul 13 12:39:51 Desdemona kernel: ppp: frame with bad fcs, length = 22
Jul 13 12:39:51 Desdemona kernel: ppp: bad frame, count = 22
Jul 13 12:39:51 Desdemona kernel: FF C0 00 21 34 C2 23 80 ...!4.#.
Jul 13 12:39:51 Desdemona kernel: 75 49 4E 78 D7 8E D2 BE uINx....
Jul 13 12:39:51 Desdemona kernel: A0 C9 8D 5D 51 BD ...]Q.
Jul 13 12:39:52 Desdemona pppd[189]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe25e584d> <pcomp> <accomp>]
Jul 13 12:39:52 Desdemona kernel: ppp: frame with bad fcs, length = 10
Jul 13 12:39:52 Desdemona kernel: ppp: bad frame, count = 10
Jul 13 12:39:52 Desdemona kernel: FF C0 00 21 E2 5E 58 4D ...!.^XM
Jul 13 12:39:52 Desdemona kernel: C9 43 .C
Jul 13 12:39:55 Desdemona kernel: ppp0 released
Jul 13 12:39:55 Desdemona kernel: ppp0: ccp closed
--
To UNSUBSCRIBE, email to debian-devel-request@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Reply to: