Discussion:
Can't get modem connection to work between two Linux systems
(too old to reply)
Chris Nelson
2006-04-21 18:31:44 UTC
Permalink
I'm trying to get PPP working between two Linux systems. I got a
direct, serial, null-modem connection working without too much trouble
but a modem connection is making me crazy.

My server -- the one that'll answer the phone -- is running pppd 2.4.2
and mgetty: interim release 1.1.33-Apr10. The client is running pppd
2.4.2b3.

On the server, I have an inittab entry like:

D1:234:respawn:/usr/sbin/mgetty ttyAM1

And mgetty.config includes
port ttyAM1
init-chat "" ATZ OK AT OK
answer-chat "" ATA CONNECT \c \r

login.config includes

/AutoPPP/ - a_ppp /etc/ppp/ppplogin

and ppplogin looks like:

#!/bin/sh
stty -echo
/usr/sbin/pppd

(Though I've tried it with the more conventional:

#!/bin/sh
stty -echo
/usr/sbin/pppd silent auth -chap +pap login

and it didn't make any difference.)

On the client side, I've got /etc/ppp/ppp.cli0 which says:

/usr/sbin/pppd file /etc/ppp/options.cli0

/etc/ppp/options.cli0 says:

connect '/usr/sbin/chat -v -t 60 -f /etc/ppp/chat.cli0'
noipdefault
/dev/ttyS0
38400
name PPPClient
defaultroute

/etc/options says:

lock
crtscts
asyncmap 0
modem

and chat.cli0 says:

ABORT BUSY
ABORT "NO CARRIER"
"" "at&f s0=0 &c1 &d2 s38=255 dt101"
CONNECT ""

When I log into the client and invoke `/etc/ppp/ppp.cli0', the modem is
dialed, the remote answers, and /var/log/messages on the server shows
LCP sends and receives:

Jan 1 22:05:21 ET-5MS-MDM-1 daemon.debug pppd[579]: using channel 18
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.info pppd[579]: Using interface
ppp0
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.info pppd[579]: Connect: ppp0 ->
/dev/ttyAM1
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: Warning - secret
file /etc/ppp/pap-secrets has world and/or group access
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:24 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
...

but the ppp connection never comes up. I finally get:

Jan 1 22:05:51 ET-5MS-MDM-1 daemon.warn pppd[579]: LCP: timeout
sending Config-Requests
Jan 1 22:05:51 ET-5MS-MDM-1 daemon.notice pppd[579]: Connection
terminated.
Jan 1 22:05:51 ET-5MS-MDM-1 daemon.info pppd[579]: Exit.

So, if the modem connection is there and the pppd's are sending LCP at
each other, why doesn't the negotiation succeed?
Unruh
2006-04-22 03:17:22 UTC
Permalink
"Chris Nelson" <***@nycap.rr.com> writes:

See below interleaved.
Post by Chris Nelson
I'm trying to get PPP working between two Linux systems. I got a
direct, serial, null-modem connection working without too much trouble
but a modem connection is making me crazy.
My server -- the one that'll answer the phone -- is running pppd 2.4.2
and mgetty: interim release 1.1.33-Apr10. The client is running pppd
2.4.2b3.
D1:234:respawn:/usr/sbin/mgetty ttyAM1
And mgetty.config includes
port ttyAM1
init-chat "" ATZ OK AT OK
answer-chat "" ATA CONNECT \c \r
login.config includes
/AutoPPP/ - a_ppp /etc/ppp/ppplogin
#!/bin/sh
stty -echo
/usr/sbin/pppd
#!/bin/sh
stty -echo
/usr/sbin/pppd silent auth -chap +pap login
and it didn't make any difference.)
/usr/sbin/pppd file /etc/ppp/options.cli0
connect '/usr/sbin/chat -v -t 60 -f /etc/ppp/chat.cli0'
noipdefault
/dev/ttyS0
38400
name PPPClient
defaultroute
lock
crtscts
asyncmap 0
modem
ABORT BUSY
ABORT "NO CARRIER"
"" "at&f s0=0 &c1 &d2 s38=255 dt101"
CONNECT ""
When I log into the client and invoke `/etc/ppp/ppp.cli0', the modem is
dialed, the remote answers, and /var/log/messages on the server shows
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.debug pppd[579]: using channel 18
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.info pppd[579]: Using interface
ppp0
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.info pppd[579]: Connect: ppp0 ->
/dev/ttyAM1
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: Warning - secret
file /etc/ppp/pap-secrets has world and/or group access
So why don't you fix this?
chmod go-r /etc/ppp/pap-secrets
Post by Chris Nelson
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Something is weirdly wrong somewhee. All the < and first letters are
stripped from each command.

You eitehr have a pppd which someone has butchered or something it weird in
your syslog.
Post by Chris Nelson
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:24 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Why did you stop giving us the log? You do not know what is wrong, but
think you know when you should cut off the log for us to look at
Also the other side is not listening. I think maybe you should get
the real pppd from ftp.samba.org compile it and try again.

Also do you have the log from that side?
Post by Chris Nelson
...
Jan 1 22:05:51 ET-5MS-MDM-1 daemon.warn pppd[579]: LCP: timeout
sending Config-Requests
Jan 1 22:05:51 ET-5MS-MDM-1 daemon.notice pppd[579]: Connection
terminated.
Jan 1 22:05:51 ET-5MS-MDM-1 daemon.info pppd[579]: Exit.
So, if the modem connection is there and the pppd's are sending LCP at
each other, why doesn't the negotiation succeed?
One side does not seem to be listening. Unfortunately you do not include
enough of the log. In particular you should put
daemon.*;local2.* /var/log/ppplog
into /etc/syslog.conf and then do
killall -1 syslogd
(Do not forget the -1)
Also include the log from teh other side.
Chris Nelson
2006-04-24 14:39:45 UTC
Permalink
Post by Unruh
See below interleaved.
Thanks for the feedback.
Post by Unruh
Post by Chris Nelson
...
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: Warning - secret
file /etc/ppp/pap-secrets has world and/or group access
So why don't you fix this?
chmod go-r /etc/ppp/pap-secrets
Because I have a configuration tool on my system which does NOT run as
root and need to be able to rewrite pap-secrets so I need at least
write access by that tool.
Post by Unruh
Post by Chris Nelson
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Something is weirdly wrong somewhee. All the < and first letters are
stripped from each command.
You eitehr have a pppd which someone has butchered or something it weird in
your syslog.
Yes, I've noticed that and I don't understand it. My pppd is 2.4.2
built from distributed source with no changes. Maybe there's something
wrong with my syslogd?
Post by Unruh
Post by Chris Nelson
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:24 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Why did you stop giving us the log? You do not know what is wrong, but
think you know when you should cut off the log for us to look at
It repeats the same thing over and over.
Post by Unruh
Also the other side is not listening. I think maybe you should get
the real pppd from ftp.samba.org compile it and try again.
Also do you have the log from that side?
...
One side does not seem to be listening. Unfortunately you do not include
enough of the log. In particular you should put
daemon.*;local2.* /var/log/ppplog
into /etc/syslog.conf and then do
killall -1 syslogd
(Do not forget the -1)
Also include the log from teh other side.
I'll work on that.

After I posted last week, I got the two sides to authenticate but then
they keep exchanging LCPs and never create the ppp0 interface. I'll
post new logs shortly (hopefully ones that aren't missing so many
characters).
Unruh
2006-04-24 23:53:55 UTC
Permalink
Post by Chris Nelson
Post by Unruh
See below interleaved.
Thanks for the feedback.
Post by Unruh
Post by Chris Nelson
...
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: Warning - secret
file /etc/ppp/pap-secrets has world and/or group access
So why don't you fix this?
chmod go-r /etc/ppp/pap-secrets
Because I have a configuration tool on my system which does NOT run as
root and need to be able to rewrite pap-secrets so I need at least
write access by that tool.
That is very insecure. Certainly giving it world read access means that
anyone who happens to ever get onto your system can see all passwords. That
is not a good idea.
Post by Chris Nelson
Post by Unruh
Post by Chris Nelson
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Something is weirdly wrong somewhee. All the < and first letters are
stripped from each command.
You eitehr have a pppd which someone has butchered or something it weird in
your syslog.
Yes, I've noticed that and I don't understand it. My pppd is 2.4.2
built from distributed source with no changes. Maybe there's something
wrong with my syslogd?
Post by Unruh
Post by Chris Nelson
Jan 1 22:05:23 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:24 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfReq
id=0x1 syncmap 0x0> uth pap> agic 0x616185a7> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: rcvd [LCP ConfReq
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Why did you stop giving us the log? You do not know what is wrong, but
think you know when you should cut off the log for us to look at
It repeats the same thing over and over.
Post by Unruh
Also the other side is not listening. I think maybe you should get
the real pppd from ftp.samba.org compile it and try again.
Also do you have the log from that side?
...
One side does not seem to be listening. Unfortunately you do not include
enough of the log. In particular you should put
daemon.*;local2.* /var/log/ppplog
into /etc/syslog.conf and then do
killall -1 syslogd
(Do not forget the -1)
Also include the log from teh other side.
I'll work on that.
After I posted last week, I got the two sides to authenticate but then
they keep exchanging LCPs and never create the ppp0 interface. I'll
post new logs shortly (hopefully ones that aren't missing so many
characters).
It really sounds like they do not hear each other. This indicates something
wrong with the modems, or with the way you originally logged on.
Chris Nelson
2006-04-25 12:21:05 UTC
Permalink
Post by Unruh
Post by Chris Nelson
Post by Unruh
Post by Chris Nelson
Jan 1 22:05:21 ET-5MS-MDM-1 daemon.warn pppd[579]: Warning - secret
file /etc/ppp/pap-secrets has world and/or group access
So why don't you fix this?
chmod go-r /etc/ppp/pap-secrets
Because I have a configuration tool on my system which does NOT run as
root and need to be able to rewrite pap-secrets so I need at least
write access by that tool.
That is very insecure. Certainly giving it world read access means that
anyone who happens to ever get onto your system can see all passwords. That
is not a good idea.
It's an embedde system with no interactive logons that don't lead to a
configuration tool. I changed it to 640 (so the configuration user's
group has only write permission to overwrite the existing pap-secrets).
I get the same warning but I guess that's a bit more secure.
Post by Unruh
...
It really sounds like they do not hear each other. This indicates something
wrong with the modems, or with the way you originally logged on.
As noted elsewhere on this topic, I appear to have been missing some
options. It's working now. Thanks.
James Carlson
2006-04-25 12:01:29 UTC
Permalink
Post by Chris Nelson
Post by Unruh
You eitehr have a pppd which someone has butchered or something it weird in
your syslog.
Yes, I've noticed that and I don't understand it. My pppd is 2.4.2
built from distributed source with no changes. Maybe there's something
wrong with my syslogd?
That seems likely. It's hard to imagine what else would do this. It
deserves a bit of debug.
Post by Chris Nelson
Post by Unruh
Post by Chris Nelson
Jan 1 22:05:26 ET-5MS-MDM-1 daemon.warn pppd[579]: sent [LCP ConfAck
id=0x1 syncmap 0x0> agic 0xd6a4137> comp> ccomp>]
Why did you stop giving us the log? You do not know what is wrong, but
think you know when you should cut off the log for us to look at
It repeats the same thing over and over.
In that case, what's in the log on the other side? I suspect that
this is a low-level communications problem. One side isn't receiving
any data.
--
James Carlson, KISS Network <***@sun.com>
Sun Microsystems / 1 Network Drive 71.232W Vox +1 781 442 2084
MS UBUR02-212 / Burlington MA 01803-2757 42.496N Fax +1 781 442 1677
Chris Nelson
2006-04-25 12:18:24 UTC
Permalink
Post by Unruh
...
One side does not seem to be listening. Unfortunately you do not include
enough of the log. In particular you should put
daemon.*;local2.* /var/log/ppplog
into /etc/syslog.conf and then do
killall -1 syslogd
(Do not forget the -1)
Also include the log from teh other side.
In crossing Ts and dotting Is to make sure I had a very clear case and
clean logs to present, I found that the client was missing options that
were present in another, working client. When I added

crtscts
asyncmap 0

to my options file, my client works. I don't know why but someone
Googling this problem in the future will now be prompted to verify
their options.

Thanks for the feedback.
Chris Nelson
2006-04-26 17:51:08 UTC
Permalink
Post by Chris Nelson
...
In crossing Ts and dotting Is to make sure I had a very clear case and
clean logs to present, I found that the client was missing options that
were present in another, working client. When I added
crtscts
asyncmap 0
to my options file, my client works. I don't know why but someone
Googling this problem in the future will now be prompted to verify
their options.
Well, it was better for a while. I'm back to an infinite negotiation
and no actual PPP interface being created.

(My mangled log problem came from running BusyBox as syslogd on my
embedded system. I put a real syslogd in and the logs below look OK to
me.)

On my PPP dial-up server, the log starts out OK:

02:23:38 myhost pppd[528]: pppd options in effect:
02:23:38 myhost pppd[528]: debug^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: dump^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: +pap^I^I# (from command line)
02:23:38 myhost pppd[528]: -chap^I^I# (from command line)
02:23:38 myhost pppd[528]: login^I^I# (from command line)
02:23:38 myhost pppd[528]: lock^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: crtscts^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: modem^I^I# (from /etc/ppp/options.ttyS01)
02:23:38 myhost pppd[528]: asyncmap 0^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: silent^I^I# (from command line)
02:23:38 myhost pppd[528]: :10.192.8.18^I^I# (from
/etc/ppp/options.ttyS01)
02:23:38 myhost pppd[528]: nodeflate^I^I# (from
/etc/ppp/options.ttyS01)
02:23:38 myhost pppd[528]: pppd 2.4.2 started by root, uid 0
02:23:38 myhost pppd[528]: using channel 8
02:23:39 myhost pppd[528]: Using interface ppp0
02:23:39 myhost pppd[528]: Connect: ppp0 <--> /dev/ttyS01
02:23:40 myhost pppd[528]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0>
<magic 0xa922fa93> <pcomp> <accomp>]
02:23:41 myhost pppd[528]: sent [LCP ConfReq id=0x1 <asyncmap 0x0>
<auth pap> <magic 0x215d836f> <pcomp> <accomp>]
02:23:42 myhost pppd[528]: sent [LCP ConfAck id=0x1 <asyncmap 0x0>
<magic 0xa922fa93> <pcomp> <accomp>]
02:23:42 myhost pppd[528]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0>
<auth pap> <magic 0x215d836f> <pcomp> <accomp>]
02:23:42 myhost pppd[528]: rcvd [PAP AuthReq id=0x1 user="PPPTest"
password=<hidden>]
02:23:43 myhost pppd[528]: user PPPTest logged in
02:23:43 myhost pppd[528]: sent [PAP AuthAck id=0x1 "Login ok"]
02:23:44 myhost pppd[528]: PAP peer authentication succeeded for
PPPTest
02:23:44 myhost pppd[528]: sent [CCP ConfReq id=0x1 <bsd v1 15>]
02:23:44 myhost pppd[528]: sent [IPCP ConfReq id=0x1 <compress VJ 0f
01> <addr 0.0.0.0>]
02:23:44 myhost pppd[528]: rcvd [CCP ConfReq id=0x1 <bsd v1 15>]
02:23:45 myhost pppd[528]: sent [CCP ConfAck id=0x1 <bsd v1 15>]
02:23:45 myhost pppd[528]: rcvd [IPCP ConfReq id=0x1 <compress VJ 0f
01> <addr 0.0.0.0>]
02:23:45 myhost pppd[528]: sent [IPCP ConfNak id=0x1 <addr
10.192.8.18>]
02:23:46 myhost pppd[528]: rcvd [CCP ConfAck id=0x1 <bsd v1 15>]
02:23:46 myhost pppd[528]: BSD-Compress (15) compression enabled
02:23:46 myhost pppd[528]: rcvd [IPCP ConfRej id=0x1 <addr 0.0.0.0>]

Then I seem to run into problems trying to negotiate the address for
the PPP0 interface:

02:23:46 myhost pppd[528]: sent [IPCP ConfReq id=0x2 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:47 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:47 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:47 myhost pppd[528]: rcvd [IPCP ConfRej id=0x2 <addrs 0.0.0.0
10.192.8.18>]
02:23:47 myhost pppd[528]: sent [IPCP ConfReq id=0x3 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:48 myhost pppd[528]: rcvd [IPCP ConfRej id=0x3 <addrs 0.0.0.0
10.192.8.18>]
02:23:49 myhost pppd[528]: sent [IPCP ConfReq id=0x4 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:50 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:50 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:51 myhost pppd[528]: rcvd [IPCP ConfRej id=0x4 <addrs 0.0.0.0
10.192.8.18>]
02:23:52 myhost pppd[528]: sent [IPCP ConfReq id=0x5 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:52 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:53 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:54 myhost pppd[528]: rcvd [IPCP ConfRej id=0x5 <addrs 0.0.0.0
10.192.8.18>]
02:23:54 myhost pppd[528]: sent [IPCP ConfReq id=0x6 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:54 myhost pppd[528]: rcvd [IPCP ConfRej id=0x6 <addrs 0.0.0.0
10.192.8.18>]
02:23:55 myhost pppd[528]: sent [IPCP ConfReq id=0x7 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:55 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:55 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:55 myhost pppd[528]: rcvd [IPCP ConfRej id=0x7 <addrs 0.0.0.0
10.192.8.18>]
02:23:56 myhost pppd[528]: sent [IPCP ConfReq id=0x8 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:56 myhost pppd[528]: rcvd [IPCP ConfRej id=0x8 <addrs 0.0.0.0
10.192.8.18>]
02:23:56 myhost pppd[528]: sent [IPCP ConfReq id=0x9 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:57 myhost pppd[528]: rcvd [IPCP ConfRej id=0x9 <addrs 0.0.0.0
10.192.8.18>]
02:23:57 myhost pppd[528]: sent [IPCP ConfReq id=0xa <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:57 myhost pppd[528]: rcvd [IPCP ConfRej id=0xa <addrs 0.0.0.0
10.192.8.18>]
02:23:58 myhost pppd[528]: sent [IPCP ConfReq id=0xb <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:59 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:00 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:00 myhost pppd[528]: rcvd [IPCP ConfRej id=0xb <addrs 0.0.0.0
10.192.8.18>]
02:24:01 myhost pppd[528]: sent [IPCP ConfReq id=0xc <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:24:01 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:01 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:02 myhost pppd[528]: rcvd [IPCP ConfRej id=0xc <addrs 0.0.0.0
10.192.8.18>]

and much the same thing repeated over and over until I kill pppd and I
get:

02:25:31 myhost pppd[528]: rcvd [LCP TermReq id=0x2 "User request"]
02:25:32 myhost pppd[528]: LCP terminated by peer (User request)
02:25:33 myhost pppd[528]: sent [LCP TermAck id=0x2]
02:25:36 myhost pppd[528]: Connection terminated.
02:25:36 myhost pppd[528]: Connect time 1.9 minutes.
02:25:36 myhost pppd[528]: Sent 1740 bytes, received 1384 bytes.
02:25:36 myhost pppd[528]: Connect time 1.9 minutes.
02:25:36 myhost pppd[528]: Sent 1740 bytes, received 1384 bytes.
02:25:36 myhost pppd[528]: Exit.

I imagine there's a conflict between the address being proposed and
what the remote can to. My server's options are:

lock
crtscts
asyncmap 0
debug
dump
modem
:10.192.8.18
require-pap
nodeflate

and the client has:

lock
crtscts
asyncmap 0
modem
nodeflate
connect '/usr/sbin/chat -v -t 60 -f /etc/ppp/chat.cli0'
noipdefault
/dev/ttyS0
38400
name PPPTest
defaultroute

As I said, I imagine an address conflict. The client has these
physical interfaces:

eth0 Link encap:Ethernet HWaddr 00:A0:1D:35:24:1A
inet addr:10.93.0.18 Bcast:10.255.255.255 Mask:255.0.0.0
...

eth1 Link encap:Ethernet HWaddr 00:A0:1D:29:2A:1A
inet addr:192.168.0.18 Bcast:192.168.255.255
Mask:255.255.0.0
...

and the server has:

eth0 Link encap:Ethernet HWaddr 00:A0:1D:32:A4:17
inet addr:10.93.0.54 Bcast:10.93.255.255 Mask:255.255.0.0
....

Can someone help me cut through the fog? What's a good remote IP
address for the server's option file?

A more general question, shouldn't pppd detected that it's going around
and around and give up eventually? It's not like it's going to get a
new address out of the blue; once in this mode this will fail forever,
right?

Thanks again for any insight.

Chris
James Carlson
2006-04-26 21:53:13 UTC
Permalink
Post by Chris Nelson
02:23:46 myhost pppd[528]: rcvd [IPCP ConfRej id=0x1 <addr 0.0.0.0>]
Then I seem to run into problems trying to negotiate the address for
Not "then." The problem is above with the Configure-Reject you
received.

You've asked your peer to supply you with an IP address. He is
refusing, probably because he doesn't know what address you should
have.

You need to configure this IP address somewhere; either on this system
or the remote one.
Post by Chris Nelson
I imagine there's a conflict between the address being proposed and
lock
crtscts
asyncmap 0
debug
dump
modem
:10.192.8.18
require-pap
nodeflate
That looks fairly good. But I'd imagine that the problem is that
there's no local address on the link.

By default, if no local address is supplied, pppd looks up the host
name (gethostname; /usr/bin/hostname) via name services to find out
the local address to use for the system. I assume that this is going
awry because of some local misconfiguration in name services.

If you can't fix that by making sure the system host name and
/etc/hosts are correct, then you may want to change that
second-to-last line to:

10.192.8.1:10.192.8.18

... so that you're not asking your client for an address.
Post by Chris Nelson
eth0 Link encap:Ethernet HWaddr 00:A0:1D:35:24:1A
inet addr:10.93.0.18 Bcast:10.255.255.255 Mask:255.0.0.0
[...]
Post by Chris Nelson
eth0 Link encap:Ethernet HWaddr 00:A0:1D:32:A4:17
inet addr:10.93.0.54 Bcast:10.93.255.255 Mask:255.255.0.0
....
Ooh, that's a bad idea. You've got overlapping subnets there.

That won't hurt the PPP link, but you're have a heck of a time getting
any sort of routing to work between those machines for nodes on those
networks. You probably don't want to do that.
Post by Chris Nelson
A more general question, shouldn't pppd detected that it's going around
and around and give up eventually? It's not like it's going to get a
new address out of the blue; once in this mode this will fail forever,
right?
It should. If it doesn't, then that's a bug.
--
James Carlson, KISS Network <***@sun.com>
Sun Microsystems / 1 Network Drive 71.232W Vox +1 781 442 2084
MS UBUR02-212 / Burlington MA 01803-2757 42.496N Fax +1 781 442 1677
Chris Nelson
2006-04-27 11:59:30 UTC
Permalink
Post by James Carlson
Post by Chris Nelson
02:23:46 myhost pppd[528]: rcvd [IPCP ConfRej id=0x1 <addr 0.0.0.0>]
Then I seem to run into problems trying to negotiate the address for
Not "then." The problem is above with the Configure-Reject you
received.
You've asked your peer to supply you with an IP address. He is
refusing, probably because he doesn't know what address you should
have.
You need to configure this IP address somewhere; either on this system
or the remote one.
...
Post by Chris Nelson
:10.192.8.18
...
That looks fairly good. But I'd imagine that the problem is that
there's no local address on the link.
By default, if no local address is supplied, pppd looks up the host
name (gethostname; /usr/bin/hostname) via name services to find out
the local address to use for the system. I assume that this is going
awry because of some local misconfiguration in name services.
A good clue. Thanks. ...

Adding my host to /etc/hosts fixes the problem. Thanks. That's easy
to do statically but I'm not sure how I'll do that if my host is
getting it's address via DHCP. That's a detail I can work out...
Post by James Carlson
If you can't fix that by making sure the system host name and
/etc/hosts are correct, then you may want to change that
10.192.8.1:10.192.8.18
... so that you're not asking your client for an address.
Yes, of course I don't want my client to give me an address.

What I don't understand it how this has worked some time. I haven't
changed how I configure name resolution and I haven't had a local
address in my options file any time.
Post by James Carlson
Post by Chris Nelson
eth0 Link encap:Ethernet HWaddr 00:A0:1D:35:24:1A
inet addr:10.93.0.18 Bcast:10.255.255.255 Mask:255.0.0.0
[...]
Post by Chris Nelson
eth0 Link encap:Ethernet HWaddr 00:A0:1D:32:A4:17
inet addr:10.93.0.54 Bcast:10.93.255.255 Mask:255.255.0.0
....
Ooh, that's a bad idea. You've got overlapping subnets there.
Yeah, one thing at a time.
Post by James Carlson
...
Post by Chris Nelson
A more general question, shouldn't pppd detected that it's going around
and around and give up eventually? It's not like it's going to get a
new address out of the blue; once in this mode this will fail forever,
right?
It should. If it doesn't, then that's a bug.
I'm using 2.4.2 so it may be fixed in a later release (but 2.4.3 is all
kinds of broken on my system so I can't move forward). I'll look to
see if there's a bug report and file one if the isn't. Thanks.
Unruh
2006-04-27 00:40:16 UTC
Permalink
Post by Chris Nelson
Post by Chris Nelson
...
In crossing Ts and dotting Is to make sure I had a very clear case and
clean logs to present, I found that the client was missing options that
were present in another, working client. When I added
crtscts
asyncmap 0
to my options file, my client works. I don't know why but someone
Googling this problem in the future will now be prompted to verify
their options.
Well, it was better for a while. I'm back to an infinite negotiation
and no actual PPP interface being created.
(My mangled log problem came from running BusyBox as syslogd on my
embedded system. I put a real syslogd in and the logs below look OK to
me.)
Well, no. No stock pppd lists all these options.
Post by Chris Nelson
02:23:38 myhost pppd[528]: debug^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: dump^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: +pap^I^I# (from command line)
02:23:38 myhost pppd[528]: -chap^I^I# (from command line)
02:23:38 myhost pppd[528]: login^I^I# (from command line)
02:23:38 myhost pppd[528]: lock^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: crtscts^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: modem^I^I# (from /etc/ppp/options.ttyS01)
02:23:38 myhost pppd[528]: asyncmap 0^I^I# (from /etc/ppp/options)
02:23:38 myhost pppd[528]: silent^I^I# (from command line)
02:23:38 myhost pppd[528]: :10.192.8.18^I^I# (from
/etc/ppp/options.ttyS01)
02:23:38 myhost pppd[528]: nodeflate^I^I# (from
/etc/ppp/options.ttyS01)
02:23:38 myhost pppd[528]: pppd 2.4.2 started by root, uid 0
02:23:38 myhost pppd[528]: using channel 8
02:23:39 myhost pppd[528]: Using interface ppp0
02:23:39 myhost pppd[528]: Connect: ppp0 <--> /dev/ttyS01
02:23:40 myhost pppd[528]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0>
<magic 0xa922fa93> <pcomp> <accomp>]
02:23:41 myhost pppd[528]: sent [LCP ConfReq id=0x1 <asyncmap 0x0>
<auth pap> <magic 0x215d836f> <pcomp> <accomp>]
02:23:42 myhost pppd[528]: sent [LCP ConfAck id=0x1 <asyncmap 0x0>
<magic 0xa922fa93> <pcomp> <accomp>]
02:23:42 myhost pppd[528]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0>
<auth pap> <magic 0x215d836f> <pcomp> <accomp>]
02:23:42 myhost pppd[528]: rcvd [PAP AuthReq id=0x1 user="PPPTest"
password=<hidden>]
02:23:43 myhost pppd[528]: user PPPTest logged in
02:23:43 myhost pppd[528]: sent [PAP AuthAck id=0x1 "Login ok"]
02:23:44 myhost pppd[528]: PAP peer authentication succeeded for
PPPTest
02:23:44 myhost pppd[528]: sent [CCP ConfReq id=0x1 <bsd v1 15>]
02:23:44 myhost pppd[528]: sent [IPCP ConfReq id=0x1 <compress VJ 0f
01> <addr 0.0.0.0>]
You ask him that your address be 0.0.0.0, which is that he supply you with
your IP address. But you8 are the server. You should be telling him what IP
address you want.
I have no idea what IP addesses you want your system and the remote to
have, but put something like
10.192.8.1:10.192.8.18
into /etc/ppp/options
(local address:remote address)
Post by Chris Nelson
02:23:44 myhost pppd[528]: rcvd [CCP ConfReq id=0x1 <bsd v1 15>]
02:23:45 myhost pppd[528]: sent [CCP ConfAck id=0x1 <bsd v1 15>]
02:23:45 myhost pppd[528]: rcvd [IPCP ConfReq id=0x1 <compress VJ 0f
01> <addr 0.0.0.0>]
He asks you for an address.
Post by Chris Nelson
02:23:45 myhost pppd[528]: sent [IPCP ConfNak id=0x1 <addr
10.192.8.18>]
You suggest 10.192.8.18
Post by Chris Nelson
02:23:46 myhost pppd[528]: rcvd [CCP ConfAck id=0x1 <bsd v1 15>]
02:23:46 myhost pppd[528]: BSD-Compress (15) compression enabled
02:23:46 myhost pppd[528]: rcvd [IPCP ConfRej id=0x1 <addr 0.0.0.0>]
He says-- I cannot supply you with an IP address.
And at that point negotiations break down.
Post by Chris Nelson
Then I seem to run into problems trying to negotiate the address for
02:23:46 myhost pppd[528]: sent [IPCP ConfReq id=0x2 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:47 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
He asks for the address you requested.

You have your address defaults set up badly.
Post by Chris Nelson
02:23:47 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
You say fine.
Post by Chris Nelson
02:23:47 myhost pppd[528]: rcvd [IPCP ConfRej id=0x2 <addrs 0.0.0.0
10.192.8.18>]
He rejects your not having told him your address.
Post by Chris Nelson
02:23:47 myhost pppd[528]: sent [IPCP ConfReq id=0x3 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
You again demand that he supply you with an address.
Post by Chris Nelson
02:23:48 myhost pppd[528]: rcvd [IPCP ConfRej id=0x3 <addrs 0.0.0.0
10.192.8.18>]
He refuses.
Post by Chris Nelson
02:23:49 myhost pppd[528]: sent [IPCP ConfReq id=0x4 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
\
YOu insist.
Post by Chris Nelson
02:23:50 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
He says "lets at least agree on my address"
Post by Chris Nelson
02:23:50 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
You say Sure.
Post by Chris Nelson
02:23:51 myhost pppd[528]: rcvd [IPCP ConfRej id=0x4 <addrs 0.0.0.0
10.192.8.18>]
He says, But I still cannot accept that you are asking me for your IP
addrss.

etc, etc.
Post by Chris Nelson
02:23:52 myhost pppd[528]: sent [IPCP ConfReq id=0x5 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:52 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:53 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:54 myhost pppd[528]: rcvd [IPCP ConfRej id=0x5 <addrs 0.0.0.0
10.192.8.18>]
02:23:54 myhost pppd[528]: sent [IPCP ConfReq id=0x6 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:54 myhost pppd[528]: rcvd [IPCP ConfRej id=0x6 <addrs 0.0.0.0
10.192.8.18>]
02:23:55 myhost pppd[528]: sent [IPCP ConfReq id=0x7 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:55 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:55 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:23:55 myhost pppd[528]: rcvd [IPCP ConfRej id=0x7 <addrs 0.0.0.0
10.192.8.18>]
02:23:56 myhost pppd[528]: sent [IPCP ConfReq id=0x8 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:56 myhost pppd[528]: rcvd [IPCP ConfRej id=0x8 <addrs 0.0.0.0
10.192.8.18>]
02:23:56 myhost pppd[528]: sent [IPCP ConfReq id=0x9 <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:57 myhost pppd[528]: rcvd [IPCP ConfRej id=0x9 <addrs 0.0.0.0
10.192.8.18>]
02:23:57 myhost pppd[528]: sent [IPCP ConfReq id=0xa <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:57 myhost pppd[528]: rcvd [IPCP ConfRej id=0xa <addrs 0.0.0.0
10.192.8.18>]
02:23:58 myhost pppd[528]: sent [IPCP ConfReq id=0xb <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:23:59 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:00 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:00 myhost pppd[528]: rcvd [IPCP ConfRej id=0xb <addrs 0.0.0.0
10.192.8.18>]
02:24:01 myhost pppd[528]: sent [IPCP ConfReq id=0xc <addrs 0.0.0.0
10.192.8.18> <compress VJ 0f 01>]
02:24:01 myhost pppd[528]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:01 myhost pppd[528]: sent [IPCP ConfAck id=0x2 <compress VJ 0f
01> <addr 10.192.8.18>]
02:24:02 myhost pppd[528]: rcvd [IPCP ConfRej id=0xc <addrs 0.0.0.0
10.192.8.18>]
and much the same thing repeated over and over until I kill pppd and I
02:25:31 myhost pppd[528]: rcvd [LCP TermReq id=0x2 "User request"]
02:25:32 myhost pppd[528]: LCP terminated by peer (User request)
02:25:33 myhost pppd[528]: sent [LCP TermAck id=0x2]
02:25:36 myhost pppd[528]: Connection terminated.
02:25:36 myhost pppd[528]: Connect time 1.9 minutes.
02:25:36 myhost pppd[528]: Sent 1740 bytes, received 1384 bytes.
02:25:36 myhost pppd[528]: Connect time 1.9 minutes.
02:25:36 myhost pppd[528]: Sent 1740 bytes, received 1384 bytes.
02:25:36 myhost pppd[528]: Exit.
I imagine there's a conflict between the address being proposed and
Yes, your server wants him to give the server and IP address. He cannot.
Post by Chris Nelson
lock
crtscts
asyncmap 0
debug
dump
modem
:10.192.8.18
Change this to
10.192.8.1:10.192.8.18
Post by Chris Nelson
require-pap
nodeflate
lock
crtscts
asyncmap 0
modem
nodeflate
connect '/usr/sbin/chat -v -t 60 -f /etc/ppp/chat.cli0'
noipdefault
/dev/ttyS0
38400
name PPPTest
defaultroute
He has no idea what address to give to you. YOu never told it what address
to give.
Post by Chris Nelson
As I said, I imagine an address conflict. The client has these
Nope no conflict.
"Tell me my name" "I do not know your name." "Tell me my name" .....
Post by Chris Nelson
eth0 Link encap:Ethernet HWaddr 00:A0:1D:35:24:1A
inet addr:10.93.0.18 Bcast:10.255.255.255 Mask:255.0.0.0
...
eth1 Link encap:Ethernet HWaddr 00:A0:1D:29:2A:1A
inet addr:192.168.0.18 Bcast:192.168.255.255
Mask:255.255.0.0
...
eth0 Link encap:Ethernet HWaddr 00:A0:1D:32:A4:17
inet addr:10.93.0.54 Bcast:10.93.255.255 Mask:255.255.0.0
....
Can someone help me cut through the fog? What's a good remote IP
address for the server's option file?
The remote is not the problem, It is the local that is the problem. Any wy
when the server is on 10.92.0.54 do you say the client should be on
10.192.8.18? Are you making these up ?
Post by Chris Nelson
A more general question, shouldn't pppd detected that it's going around
and around and give up eventually? It's not like it's going to get a
new address out of the blue; once in this mode this will fail forever,
right?
No, sometimes something changes and a bit of persistance works. But after
20 times it probably will not, I agree.\
Post by Chris Nelson
Thanks again for any insight.
Chris
James Carlson
2006-04-27 12:02:04 UTC
Permalink
Post by Unruh
Well, no. No stock pppd lists all these options.
That's untrue. The "dump" option was added to the CVS sources back in
2001.
--
James Carlson, KISS Network <***@sun.com>
Sun Microsystems / 1 Network Drive 71.232W Vox +1 781 442 2084
MS UBUR02-212 / Burlington MA 01803-2757 42.496N Fax +1 781 442 1677
Chris Nelson
2006-04-27 12:05:18 UTC
Permalink
Post by Unruh
...
Post by Chris Nelson
Well, it was better for a while. I'm back to an infinite negotiation
and no actual PPP interface being created.
(My mangled log problem came from running BusyBox as syslogd on my
embedded system. I put a real syslogd in and the logs below look OK to
me.)
Well, no. No stock pppd lists all these options.
I don't understand. When I say, "the log starts out OK" I mean it
lists the options that I specified.
Post by Unruh
Post by Chris Nelson
...
02:23:44 myhost pppd[528]: sent [CCP ConfReq id=0x1 <bsd v1 15>]
02:23:44 myhost pppd[528]: sent [IPCP ConfReq id=0x1 <compress VJ 0f
01> <addr 0.0.0.0>]
You ask him that your address be 0.0.0.0, which is that he supply you with
your IP address. But you are the server. You should be telling him what IP
address you want.
I have no idea what IP addesses you want your system and the remote to
have, but put something like
10.192.8.1:10.192.8.18
into /etc/ppp/options
(local address:remote address)
Someone else pointed out that I appeared to have a misconfigured name
service so pppd wasn't getting back a valid IP from gethostbyname() or
whatever. When I added my hosts to /etc/hosts, it works.
Post by Unruh
Post by Chris Nelson
02:23:44 myhost pppd[528]: rcvd [CCP ConfReq id=0x1 <bsd v1 15>]
02:23:45 myhost pppd[528]: sent [CCP ConfAck id=0x1 <bsd v1 15>]
02:23:45 myhost pppd[528]: rcvd [IPCP ConfReq id=0x1 <compress VJ 0f
01> <addr 0.0.0.0>]
He asks you for an address.
Post by Chris Nelson
02:23:45 myhost pppd[528]: sent [IPCP ConfNak id=0x1 <addr
10.192.8.18>]
You suggest 10.192.8.18
...
Thank you very much for the detailed analysis of the log. I will read
it closely so I understand it better next time.
Post by Unruh
Post by Chris Nelson
...
Chris

Loading...