Dialout fails using linuxconf/netconf - pppd dies

Hi!

I am unable to obtain a stable dialup connection using linuxconf.
The symptom is that the connection dies after a short time, often
around 1.5 minutes.

Can anyone tell me how to fix pppd and/or linuxconf so that
netconf connects ok?

An example log follows:

Aug 14 20:33:18 JandC pppd[12795]: Script /etc/ppp/ip-up finished (pid 12807), status = 0x0
Aug 14 20:33:46 JandC pppd[12795]: Terminating on signal 15.
Aug 14 20:33:46 JandC pppd[12795]: Script /etc/ppp/ip-down started (pid 12874)
Aug 14 20:33:46 JandC pppd[12795]: sent [LCP TermReq id=0x2 "User request"]
Aug 14 20:33:47 JandC pppd[12795]: rcvd [LCP TermAck id=0x2]
Aug 14 20:33:47 JandC pppd[12795]: Connection terminated.
Aug 14 20:33:47 JandC pppd[12795]: Connect time 0.6 minutes.

This connection was started with
$ netconf --connect uklinux
Netconf does not return to the console until AFTER the link
dies, and has an exit code of 255.

After much experimentation, it appears that the cause is that pppd does not
detach.
Running
$ pppd file /var/run/pppd-args.uklinux -detach
creates a stable connection but does NOT return to the console without
doing ctl-C to kill the link. pppd dump option shows that the -detach
option is being used.

Running
$ pppd file /var/run/pppd-args.uklinux updetach
works properly (returns to console once connected, with exit code
of 0) and is a workaround for the problem, but does tend to negate the
advantages of using linuxconf.

I am using Mandrake 9.1, pppd 2.4.1, linuxconf 1.29 (subrev 3). I can
provide pppd dump output if required.

Thanks
....John
--
---------------------------------------------------
(Remove digits from my email address before use ;-)

JRH <(E-Mail Removed)> wrote:

> I am unable to obtain a stable dialup connection using linuxconf.
> The symptom is that the connection dies after a short time, often
> around 1.5 minutes.

> Can anyone tell me how to fix pppd and/or linuxconf so that
> netconf connects ok?

> An example log follows:

> Aug 14 20:33:18 JandC pppd[12795]: Script /etc/ppp/ip-up finished (pid
> 12807), status = 0x0
> Aug 14 20:33:46 JandC pppd[12795]: Terminating on signal 15.

This looks like you terminated pppd. We need log messages for a
connection that died when you didn't want it to do so.

> Aug 14 20:33:46 JandC pppd[12795]: Script /etc/ppp/ip-down started
> (pid 12874)
> Aug 14 20:33:46 JandC pppd[12795]: sent [LCP TermReq id=0x2 "User request"]
> Aug 14 20:33:47 JandC pppd[12795]: rcvd [LCP TermAck id=0x2]
> Aug 14 20:33:47 JandC pppd[12795]: Connection terminated.
> Aug 14 20:33:47 JandC pppd[12795]: Connect time 0.6 minutes.

> This connection was started with
> $ netconf --connect uklinux
> Netconf does not return to the console until AFTER the link
> dies, and has an exit code of 255.

> After much experimentation, it appears that the cause is that pppd
> does not detach.

I don't see how that would cause pppd to often die "after a short
time." Running without or without the updetach option won't make any
difference in connection time as far as pppd itself is concerned.

> Running
> $ pppd file /var/run/pppd-args.uklinux -detach
> creates a stable connection but does NOT return to the console without
> doing ctl-C to kill the link. pppd dump option shows that the -detach
> option is being used.

If this really does produce a "stable connection" then the fault is
in what either the netconf or linuxconf script does. Considering that
you think the problem is solved by just switching option on the pppd
command line above, even that seems highly unlikely.

> Running
> $ pppd file /var/run/pppd-args.uklinux updetach
> works properly (returns to console once connected, with exit code
> of 0) and is a workaround for the problem, but does tend to negate
> the advantages of using linuxconf.

What advantages would those be? Is one advantage that of being unable
to easily determine the real nature of your problem?

If you use a script to configure or start a PPP connection then you are
stuck with what is written into the script. If it cannot configure/start
pppd to run the way you want then you have to dig into the script and
change it. Or find a workaround(?) as you did above.

--
Clifford Kite Email: "echo xvgr_yvahk-(E-Mail Removed)|rot13"
PPP-Q&A links, downloads: http://ckite.no-ip.net/
/* Emacs vs vi:
Sort of like a Swiss Army knife versus a rapier. */

Clifford Kite wrote:

> JRH <(E-Mail Removed)> wrote:
>
>> I am unable to obtain a stable dialup connection using linuxconf.
>> The symptom is that the connection dies after a short time, often
>> around 1.5 minutes.
>
>> Can anyone tell me how to fix pppd and/or linuxconf so that
>> netconf connects ok?
>
>> An example log follows:
>
>> Aug 14 20:33:18 JandC pppd[12795]: Script /etc/ppp/ip-up finished (pid
>> 12807), status = 0x0
>> Aug 14 20:33:46 JandC pppd[12795]: Terminating on signal 15.
>
> This looks like you terminated pppd. We need log messages for a
> connection that died when you didn't want it to do so.

This *is* a log when the link spontaneously disconnected. I did *not* do
anything to cause it to disconnect.

>> Aug 14 20:33:46 JandC pppd[12795]: Script /etc/ppp/ip-down started
>> (pid 12874)
>> Aug 14 20:33:46 JandC pppd[12795]: sent [LCP TermReq id=0x2 "User
>> request"] Aug 14 20:33:47 JandC pppd[12795]: rcvd [LCP TermAck id=0x2]
>> Aug 14 20:33:47 JandC pppd[12795]: Connection terminated.
>> Aug 14 20:33:47 JandC pppd[12795]: Connect time 0.6 minutes.
>
>> This connection was started with
>> $ netconf --connect uklinux
>> Netconf does not return to the console until AFTER the link
>> dies, and has an exit code of 255.
>
>> After much experimentation, it appears that the cause is that pppd
>> does not detach.
>
> I don't see how that would cause pppd to often die "after a short
> time." Running without or without the updetach option won't make any
> difference in connection time as far as pppd itself is concerned.

No, I'm grasping at straws really. I think perhaps netconf is killing pppd
for some reason, perhaps because it has a timeout on pppd which as I
understand it should return immediately when started with the -detach
option. This is why subsequent tests were performed running pppd directly.

>> Running
>> $ pppd file /var/run/pppd-args.uklinux -detach
>> creates a stable connection but does NOT return to the console without
>> doing ctl-C to kill the link. pppd dump option shows that the -detach
>> option is being used.
>
> If this really does produce a "stable connection" then the fault is
> in what either the netconf or linuxconf script does. Considering that
> you think the problem is solved by just switching option on the pppd
> command line above, even that seems highly unlikely.
>
>> Running
>> $ pppd file /var/run/pppd-args.uklinux updetach
>> works properly (returns to console once connected, with exit code
>> of 0) and is a workaround for the problem, but does tend to negate
>> the advantages of using linuxconf.
>
> What advantages would those be? Is one advantage that of being unable
> to easily determine the real nature of your problem?

The advantage of being able to easily select a connection name (I use
multipls ISPs) on the command line. I have since written a bash script that
runs pppd directly with the updetach option, that has the same advantage.
(Plus I know exactly what my script does ;-)

> If you use a script to configure or start a PPP connection then you are
> stuck with what is written into the script. If it cannot configure/start
> pppd to run the way you want then you have to dig into the script and
> change it. Or find a workaround(?) as you did above.

As you say, linuxconf introduces another layer of complexity that is hard to
debug, but I did not know enough about pppd, chat etc to set up
the connection unaided.

I think the knowledge I am missing is, at what point should
$ pppd file /var/run/pppd-args.uklinux -detach
return to the command prompt? Immediately or at some later time? What later
time? My reading of the man page leads me to expect it to return
more-or-less immediately, but I may be wrong.
And what might prevent it from ever returning to the command prompt (unless
kill pppd)?

....John
--
---------------------------------------------------
(Remove digits from my email address before use ;-)

On Mon, 25 Aug 2003 17:31:37 +0100, JRH wrote:

> Clifford Kite wrote:
>
>> JRH <(E-Mail Removed)> wrote:
>>
>>> I am unable to obtain a stable dialup connection using linuxconf. The
>>> symptom is that the connection dies after a short time, often around
>>> 1.5 minutes.
>>
>>> Can anyone tell me how to fix pppd and/or linuxconf so that netconf
>>> connects ok?
>>
>>> An example log follows:
>>
>>> Aug 14 20:33:18 JandC pppd[12795]: Script /etc/ppp/ip-up finished (pid
>>> 12807), status = 0x0
>>> Aug 14 20:33:46 JandC pppd[12795]: Terminating on signal 15.

I had similar problems when I first started run Linux and I used dialup
(I've upgraded to cable modem, which is so easy to use with Linux it's
ridiculous). I tracked it down to the modem initialization string... I
hate to admit it, but the way I finally figured out what the correct
initialization string was was to boot to Windows, log the initialization
string and copy it over into my startup scripts.

JRH <(E-Mail Removed)> wrote:

> The advantage of being able to easily select a connection name (I use
> multipls ISPs) on the command line. I have since written a bash script that
> runs pppd directly with the updetach option, that has the same advantage.
> (Plus I know exactly what my script does ;-)

And *exactly* the reason for avoiding distribution supplied configuration
scripts when it's possible - and reasonable - to do so.

>> If you use a script to configure or start a PPP connection then you are
>> stuck with what is written into the script. If it cannot configure/start
>> pppd to run the way you want then you have to dig into the script and
>> change it. Or find a workaround(?) as you did above.

> As you say, linuxconf introduces another layer of complexity that
> is hard to debug, but I did not know enough about pppd, chat etc
> to set up the connection unaided.

> I think the knowledge I am missing is, at what point should
> $ pppd file /var/run/pppd-args.uklinux -detach
> return to the command prompt? Immediately or at some later time? What
> later time? My reading of the man page leads me to expect it to
> return more-or-less immediately, but I may be wrong.

Here it usually takes a little less than a minute for the PPP negotiations
to reach the stage where the link comes up for IP. That includes modem
connection and negotiation as well as the PPP negotiations through IPCP
where the IP addresses for the link are agreed to by both sides.

> And what might prevent it from ever returning to the command prompt
> (unless kill pppd)?

Probably because the IPCP negotiations never complete and pppd doesn't
terminate as it should for some reason. I'd rather not try to speculate
about what could cause this.

Adding the chat -v and pppd debug option should produce log messages
that have enough detail to tell what's happened during one of the
troublesome sessions. Adding a line such as

local2.*;*.=debug;*.=notice /var/log/ppp-debug.log

to /etc/syslog.conf and SIGHUPing syslogd creates a log with all the
messages in one place.

Post an exact copy of the messages from a no-return session if you like.

--
Clifford Kite Email: "echo xvgr_yvahk-(E-Mail Removed)|rot13"
PPP-Q&A links, downloads: http://ckite.no-ip.net/
/* The generation of random numbers is too important to be left
to chance. */

Clifford Kite wrote:

[...]
>> And what might prevent pppd from ever returning to the command prompt
>> (unless kill pppd)?
>
> Probably because the IPCP negotiations never complete and pppd doesn't
> terminate as it should for some reason. I'd rather not try to speculate
> about what could cause this.
>
> Adding the chat -v and pppd debug option should produce log messages
> that have enough detail to tell what's happened during one of the
> troublesome sessions. Adding a line such as
>
> local2.*;*.=debug;*.=notice /var/log/ppp-debug.log
>
> to /etc/syslog.conf and SIGHUPing syslogd creates a log with all the
> messages in one place.
>
> Post an exact copy of the messages from a no-return session if you like.
>
OK, here is is.

/etc/ppp/pppd-args.uklinux
==========================
asyncmap 0
lock
modem crtscts
#mru 1500
:
defaultroute
-detach
remotename lnx-uklinux name yoredale
connect '/usr/sbin/chat -v -f /etc/ppp/pppd-args-chat.uklinux'
/dev/modem
115200
refuse-pap

/etc/ppp/pppd-args-chat.uklinux
===============================
# Init strings same as work for kppp
ABORT 'NO CARRIER'
ABORT BUSY
'' ATZ
OK ATM1L1
OK ATDT08456042086
CONNECT ''
SAY "\nChat script ends\n" # this displays ok on console

chap-secrets
============
# Secrets for authentication using CHAP
# client server secret IP addresses
yoredale lnx-uklinux guess *

Command line
============
pppd file /etc/ppp/pppd-args.uklinux debug -detach refuse-pap dump

Log file
========
I terminated the connection after 3 minutes by kill $(pidof pppd) from
a different console. Connection was usable, eg browse web ok.
This was with NO ip-up.local script, and therefore no firewall was
installed.

Aug 26 21:01:01 JandC pppd[3386]: pppd options in effect:
Aug 26 21:01:01 JandC pppd[3386]: debug # (from command line)
Aug 26 21:01:01 JandC pppd[3386]: -detach # (from command line)
Aug 26 21:01:01 JandC pppd[3386]: dump # (from command line)
Aug 26 21:01:01 JandC pppd[3386]: noauth # (from /etc/ppp/options)
Aug 26 21:01:01 JandC pppd[3386]: refuse-pap # (from command line)
Aug 26 21:01:01 JandC pppd[3386]: name yoredale # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: remotename lnx-uklinux # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: /dev/modem # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: 115200 # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: lock # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: connect /usr/sbin/chat -v -f /etc/ppp/pppd-args-chat.uklinux # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: crtscts # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: modem # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: asyncmap 0 # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: noipdefault # (from /etc/ppp/options)
Aug 26 21:01:01 JandC pppd[3386]: defaultroute # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: usepeerdns # (from /etc/ppp/options)
Aug 26 21:01:01 JandC pppd[3386]: : # (from /etc/ppp/pppd-args.uklinux)
Aug 26 21:01:01 JandC pppd[3386]: pppd 2.4.1 started by john, uid 0
Aug 26 21:01:02 JandC chat[3389]: abort on (NO CARRIER)
Aug 26 21:01:02 JandC chat[3389]: abort on (BUSY)
Aug 26 21:01:02 JandC chat[3389]: send (ATZ^M)
Aug 26 21:01:02 JandC chat[3389]: expect (OK)
Aug 26 21:01:02 JandC chat[3389]: ATZ^M^M
Aug 26 21:01:02 JandC chat[3389]: OK
Aug 26 21:01:02 JandC chat[3389]: -- got it
Aug 26 21:01:02 JandC chat[3389]: send (ATM1L1^M)
Aug 26 21:01:02 JandC chat[3389]: expect (OK)
Aug 26 21:01:02 JandC chat[3389]: ^M
Aug 26 21:01:02 JandC chat[3389]: ATM1L1^M^M
Aug 26 21:01:02 JandC chat[3389]: OK
Aug 26 21:01:02 JandC chat[3389]: -- got it
Aug 26 21:01:02 JandC chat[3389]: send (ATDT08456042086^M)
Aug 26 21:01:03 JandC chat[3389]: expect (CONNECT)
Aug 26 21:01:03 JandC chat[3389]: ^M
Aug 26 21:01:18 JandC chat[3389]: ATDT08456042086^M^M
Aug 26 21:01:18 JandC chat[3389]: CONNECT
Aug 26 21:01:18 JandC chat[3389]: -- got it
Aug 26 21:01:18 JandC chat[3389]: send (^M)
Aug 26 21:01:18 JandC pppd[3386]: Serial connection established.
Aug 26 21:01:18 JandC pppd[3386]: using channel 10
Aug 26 21:01:18 JandC pppd[3386]: Using interface ppp0
Aug 26 21:01:18 JandC pppd[3386]: Connect: ppp0 <--> /dev/modem
Aug 26 21:01:18 JandC /etc/hotplug/net.agent: assuming ppp0 is already up
Aug 26 21:01:19 JandC pppd[3386]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x7513da16> <pcomp> <accomp>]
Aug 26 21:01:19 JandC pppd[3386]: rcvd [LCP ConfReq id=0xa7 <asyncmap 0xa0000> <auth chap MD5> <magic 0x9ae9bffd> <pcomp> <accomp>]
Aug 26 21:01:19 JandC pppd[3386]: sent [LCP ConfAck id=0xa7 <asyncmap 0xa0000> <auth chap MD5> <magic 0x9ae9bffd> <pcomp> <accomp>]
Aug 26 21:01:19 JandC pppd[3386]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x7513da16> <pcomp> <accomp>]
Aug 26 21:01:19 JandC pppd[3386]: rcvd [CHAP Challenge id=0x17 <5c931c172c7297c9ca6de8fff5e31352>, name = "NewcAP111as3"]
Aug 26 21:01:19 JandC pppd[3386]: sent [CHAP Response id=0x17 <dde0b8e7383b35d635f805209a287567>, name = "yoredale"]
Aug 26 21:01:21 JandC pppd[3386]: rcvd [CHAP Success id=0x17 ""]
Aug 26 21:01:21 JandC pppd[3386]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Aug 26 21:01:21 JandC pppd[3386]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Aug 26 21:01:21 JandC pppd[3386]: rcvd [IPCP ConfReq id=0x5a <addr 213.121.147.12>]
Aug 26 21:01:21 JandC pppd[3386]: sent [IPCP ConfAck id=0x5a <addr 213.121.147.12>]
Aug 26 21:01:21 JandC pppd[3386]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Aug 26 21:01:21 JandC pppd[3386]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Aug 26 21:01:21 JandC pppd[3386]: rcvd [LCP ProtRej id=0x28 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Aug 26 21:01:21 JandC pppd[3386]: rcvd [IPCP ConfNak id=0x2 <addr 194.247.49.248> <ms-dns1 194.247.47.47> <ms-dns3 194.247.40.126>]
Aug 26 21:01:21 JandC pppd[3386]: sent [IPCP ConfReq id=0x3 <addr 194.247.49.248> <ms-dns1 194.247.47.47> <ms-dns3 194.247.40.126>]
Aug 26 21:01:21 JandC pppd[3386]: rcvd [IPCP ConfAck id=0x3 <addr 194.247.49.248> <ms-dns1 194.247.47.47> <ms-dns3 194.247.40.126>]
Aug 26 21:01:21 JandC pppd[3386]: local IP address 194.247.49.248
Aug 26 21:01:21 JandC pppd[3386]: remote IP address 213.121.147.12
Aug 26 21:01:21 JandC pppd[3386]: primary DNS address 194.247.47.47
Aug 26 21:01:21 JandC pppd[3386]: secondary DNS address 194.247.40.126
Aug 26 21:01:21 JandC pppd[3386]: Script /etc/ppp/ip-up started (pid 3408)
Aug 26 21:01:22 JandC pppd[3386]: Script /etc/ppp/ip-up finished (pid 3408), status = 0x0
Aug 26 21:04:18 JandC pppd[3386]: Terminating on signal 15.
Aug 26 21:04:18 JandC pppd[3386]: Script /etc/ppp/ip-down started (pid 3421)
Aug 26 21:04:18 JandC pppd[3386]: sent [LCP TermReq id=0x2 "User request"]
Aug 26 21:04:18 JandC pppd[3386]: rcvd [LCP TermAck id=0x2]
Aug 26 21:04:18 JandC pppd[3386]: Connection terminated.
Aug 26 21:04:18 JandC pppd[3386]: Connect time 3.0 minutes.
Aug 26 21:04:18 JandC pppd[3386]: Sent 292 bytes, received 343 bytes.
Aug 26 21:04:18 JandC /etc/hotplug/net.agent: NET unregister event not supported
Aug 26 21:04:19 JandC pppd[3386]: Waiting for 1 child processes...
Aug 26 21:04:19 JandC pppd[3386]: script /etc/ppp/ip-down, pid 3421
Aug 26 21:04:21 JandC pppd[3386]: Script /etc/ppp/ip-down finished (pid 3421), status = 0x0
Aug 26 21:04:21 JandC pppd[3386]: Exit.

....John
--
---------------------------------------------------
(Remove digits from my email address before use ;-)

JRH <(E-Mail Removed)> wrote:

> Command line
> ============
> pppd file /etc/ppp/pppd-args.uklinux debug -detach refuse-pap dump

> Log file
> ========
> I terminated the connection after 3 minutes by kill $(pidof pppd) from
> a different console. Connection was usable, eg browse web ok.
> This was with NO ip-up.local script, and therefore no firewall was
> installed.

> Aug 26 21:01:01 JandC pppd[3386]: pppd options in effect:
> Aug 26 21:01:01 JandC pppd[3386]: debug # (from command line)
> Aug 26 21:01:01 JandC pppd[3386]: -detach # (from command line)

Duh! It's been awhile since -detach was deprecated and I'd forgotten
that it meant "don't detach" (and is probably the default as well).
You must use "updetach" to fork pppd and have it detach from the
terminal.

Sorry about that.

(Nothing of significance in the log to comment on.)

--
Clifford Kite Email: "echo xvgr_yvahk-(E-Mail Removed)|rot13"
PPP-Q&A links, downloads: http://ckite.no-ip.net/
/* The generation of random numbers is too important to be left
to chance. */

Clifford Kite wrote:

> JRH <(E-Mail Removed)> wrote:
[...]
>> Log file
>> ========
[...]
>> Aug 26 21:01:01 JandC pppd[3386]: pppd options in effect:
>> Aug 26 21:01:01 JandC pppd[3386]: debug # (from command line)
>> Aug 26 21:01:01 JandC pppd[3386]: -detach # (from command line)
>
> Duh! It's been awhile since -detach was deprecated and I'd forgotten
> that it meant "don't detach" (and is probably the default as well).
> You must use "updetach" to fork pppd and have it detach from the
> terminal.
>
> Sorry about that.
> [...]

Don't be sorry. Thanks for solving a mystery.

In summary,
- linuxconf/netconf is broken because it wrongly supplies the -detach option
to pppd, it should probably provide updetach. (I know my linuxconf is not
quite the latest but I looked at the bug fix logs for later versions and
found no relevant reference.)
- pppd is working exactly as it should, with updetach
- the man page for pppd in RH8.0 and Mdk9.1 is out of date, because it
describes the detach option not the -detach option, but pppd itself
understands only -detach.

This misunderstanding has cost me several evenings, but on the positive side
I have learnt enough about pppd and chat to be able to set up a dialup link
without linuxconf or other crutch.

Thanks again
....John
--
---------------------------------------------------
(Remove digits from my email address before use ;-)