PPPoE-Server not responding to Configuration Requests

[Ted]

Hello. I am using RP-PPPoE Server to test RP-PPPoE client but I am
having some troubles. Here is my setup:

Server:
RP-PPPoE Server v3.7
pppd v2.4.4b1

/etc/ppp/pppoe-server-options
# PPP options for the PPPoE server
# LIC: GPL
#require-pap
#login
noauth
lcp-echo-interval 10
lcp-echo-failure 2

#pppoe-server -F -Ieth0 -L192.168.1.1 -R192.168.1.100

Client
RP-PPPoE Client v3.7
pppd v2.3.8

#pppd pty 'pppoe -Ieth0' noauth

*Errors*:
tethereal
0.000000 LannerEl_04:29:f7 -> Broadcast PPPoED Active Discovery
Initiation (PADI)
0.000057 AsustekC_2e:ba:e7 -> LannerEl_04:29:f7 PPPoED Active
Discovery Offer (PADO)
0.000099 AsustekC_2e:ba:e7 -> LannerEl_04:29:f7 PPPoED Active
Discovery Offer (PADO)
0.000135 AsustekC_2e:ba:e7 -> LannerEl_04:29:f7 PPPoED Active
Discovery Offer (PADO)
0.000170 AsustekC_2e:ba:e7 -> LannerEl_04:29:f7 PPPoED Active
Discovery Offer (PADO)
0.000854 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPPoED Active
Discovery Request (PADR)
0.001138 AsustekC_2e:ba:e7 -> LannerEl_04:29:f7 PPPoED Active
Discovery Session-confirmation (PADS)
1.005278 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
4.014041 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
7.023795 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
10.033574 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
13.043363 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
16.053126 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
19.062911 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
22.072677 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
25.082500 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
28.082346 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
31.094798 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPPoED Active
Discovery Terminate (PADT)
31.095109 AsustekC_2e:ba:e7 -> LannerEl_04:29:f7 PPPoED Active
Discovery Terminate (PADT)

/var/log/debug

Feb 14 12:08:37 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:40 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]
Feb 14 12:08:40 astrocomp pppd[14321]: sent [LCP ConfRej id=0x1
<asyncmap 0x0> <pcomp> <accomp>]
Feb 14 12:08:40 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:43 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:46 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]
Feb 14 12:08:46 astrocomp pppd[14321]: sent [LCP ConfRej id=0x1
<asyncmap 0x0> <pcomp> <accomp>]
Feb 14 12:08:46 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:49 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:52 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]
Feb 14 12:08:52 astrocomp pppd[14321]: sent [LCP ConfRej id=0x1
<asyncmap 0x0> <pcomp> <accomp>]
Feb 14 12:08:52 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:55 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:58 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]
Feb 14 12:08:58 astrocomp pppd[14321]: sent [LCP ConfRej id=0x1
<asyncmap 0x0> <pcomp> <accomp>]
Feb 14 12:08:58 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:09:01 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:09:04 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]
Feb 14 12:09:04 astrocomp pppd[14321]: sent [LCP ConfRej id=0x1
<asyncmap 0x0> <pcomp> <accomp>]
Feb 14 12:09:04 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:09:07 astrocomp pppd[14321]: sent [LCP TermReq id=0x2 "User
request"]
Feb 14 12:09:10 astrocomp pppd[14321]: sent [LCP TermReq id=0x3 "User
request"]
Feb 14 12:09:13 astrocomp pppd[14321]: Waiting for 1 child processes...
Feb 14 12:09:13 astrocomp pppd[14321]: script /usr/sbin/pppoe -n -I
eth0 -e 2:00:90:0b:04:29:f7 -S '', pid 14323
Feb 14 12:09:18 astrocomp pppd[14321]: sending SIGTERM to process 14323

/var/log/messages

Feb 14 12:08:36 astrocomp pppoe-server[14321]: Session 2 created for
client 00:90:0b:04:29:f7 (192.168.3.100) on eth0 using Service-Name ''
Feb 14 12:08:36 astrocomp pppd[14321]: pppd 2.4.4b1 started by root,
uid 0
Feb 14 12:08:36 astrocomp pppd[14321]: Using interface ppp0
Feb 14 12:08:36 astrocomp pppd[14321]: Connect: ppp0 <--> /dev/pts/7
Feb 14 12:09:07 astrocomp pppoe-server[14297]: Sent PADT
Feb 14 12:09:07 astrocomp pppd[14321]: Terminating on signal 15
Feb 14 12:09:13 astrocomp pppd[14321]: Connection terminated.
Feb 14 12:09:13 astrocomp pppd[14321]: Modem hangup
Feb 14 12:09:18 astrocomp pppd[14321]: Exit.
Feb 14 12:09:18 astrocomp pppoe-server[14297]: Session 2 closed for
client 00:90:0b:04:29:f7 (192.168.3.100) on eth0

I did set up eth0 to be up without a IP to start as man pppoe-server
describes. For some reason the server is not replying to the
ConfigRequests?? It certainly thinks it is from the debug logs, but
tethereal shows no responses from the server. Does anyone know if
using different versions of pppd has anything to do with it. Any help
is much appreciated!

[James Carlson]

Post by Ted
1.005278 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
4.014041 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration

Why is ethereal here showing such a radically different picture from
the pppd logs? One of these two just isn't right.

Post by Ted
Feb 14 12:08:37 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:40 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]
Feb 14 12:08:40 astrocomp pppd[14321]: sent [LCP ConfRej id=0x1
<asyncmap 0x0> <pcomp> <accomp>]
Feb 14 12:08:40 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:43 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:46 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]

This tells you that the peer cannot hear you. You're receiving
packets just fine from the peer, but the packets you're sending aren't
making it over to the peer. Look into the PPPoE software you're using
and the link from you to the peer.

Post by Ted
I did set up eth0 to be up without a IP to start as man pppoe-server
describes. For some reason the server is not replying to the
ConfigRequests??

It's not receiving them.

This isn't a PPP (or pppd configuration) problem, instead it's a
low-level communications failure: you're able to receive packets from
the peer, but the peer cannot receive what you're sending.

Post by Ted
It certainly thinks it is from the debug logs, but
tethereal shows no responses from the server.

That's strangely the exact opposite of what the pppd logs show. I'd
mistrust ethereal's report here, because the reverse (having pppd just
"imagine" that it's receiving data) is unthinkable.

Post by Ted
Does anyone know if
using different versions of pppd has anything to do with it. Any help
is much appreciated!

I don't think this is a pppd issue at all.

[Ted]

Post by James Carlson

Post by Ted
1.005278 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration
Request
4.014041 LannerEl_04:29:f7 -> AsustekC_2e:ba:e7 PPP LCP Configuration

Why is ethereal here showing such a radically different picture from
the pppd logs? One of these two just isn't right.

I assure you both are ?right?, I did not manipulate them if thats what
you are implying.

Post by James Carlson

Post by Ted
Feb 14 12:08:37 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:40 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]
Feb 14 12:08:40 astrocomp pppd[14321]: sent [LCP ConfRej id=0x1
<asyncmap 0x0> <pcomp> <accomp>]
Feb 14 12:08:40 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:43 astrocomp pppd[14321]: sent [LCP ConfReq id=0x1 <magic
0x1b60833e>]
Feb 14 12:08:46 astrocomp pppd[14321]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x457d8c7b> <pcomp> <accomp>]

This tells you that the peer cannot hear you. You're receiving
packets just fine from the peer, but the packets you're sending aren't
making it over to the peer. Look into the PPPoE software you're using
and the link from you to the peer.

I figured that as the logs clearly show the server end sending but no
info over the wire.

Post by James Carlson

Post by Ted
I did set up eth0 to be up without a IP to start as man pppoe-server
describes. For some reason the server is not replying to the
ConfigRequests??

It's not receiving them.

Yes the logs clearly show the server is recieving them. This is the
server peer that is trying to send. Note the ConfReq's.

Post by James Carlson
This isn't a PPP (or pppd configuration) problem, instead it's a
low-level communications failure: you're able to receive packets from
the peer, but the peer cannot receive what you're sending.

That is indeed the problem, but why would the server be able to listen
on the ppp link, but not send?? Do I need a special pppd option? ie
modem, local, lock????

Post by James Carlson

Post by Ted
It certainly thinks it is from the debug logs, but
tethereal shows no responses from the server.

That's strangely the exact opposite of what the pppd logs show. I'd
mistrust ethereal's report here, because the reverse (having pppd just
"imagine" that it's receiving data) is unthinkable.

What could be preventing the server from sending stuff out??

Post by James Carlson

Post by Ted
Does anyone know if
using different versions of pppd has anything to do with it. Any help
is much appreciated!

I don't think this is a pppd issue at all.

Perhaps not... but to me the pppoe PADI PADO PADR PADS and PADT's seem
to be working just fine.

Post by James Carlson
--
Sun Microsystems / 1 Network Drive 71.232W Vox [phone]
MS UBUR02-212 / Burlington MA 01803-2757 42.496N Fax [phone]

[James Carlson]

This post might be inappropriate. Click to display it.

[Ted]

This post might be inappropriate. Click to display it.

[Ted]

Victory is mine!! HAHAHAHAHA
Using pppd-2.4.1 fixes this problem. I changed nothing in my
configuration and now everything works just fantastic! There is surely
a bug somewhere, ATM I believe it is in pppd because I have no reason
to think otherwise. I suppose that RP-PPPoE could be the culprit and
that this old pppd is working around some rp-pppoe thing and it is not
doing so in the latest pppd but I do not know. What I do know is that
pppd-2.4.4 is fairly new and 2.4.1 was released in 2001 and seemed to
be good enough until about a year ago when 2.4.3 was released.
Changing topic to [SOLVED] if I can.

-Ted

[krishna]

Hello Ted,
I am also facing the same problem as you are facing.
Can you tell me exactly what pppoe server and client you are using.
I am using 2.6 kernel will that have any effect.
I tried even pppd 2.4.1 but still it didnt help
pppoe client is aceman pro on windows.

Any ideas

Thanks
Kris

[Ted]

Hey Kris,
I was using RP-PPPoE server and client version 3.7. All my version
info is in my top level post.

[krishna]

Hi Ted,
Thanks!!
2.6 kernel was causing problem.
I tried with the 2.4 kernel it is working properly now

Thanks
Kris