OpenWrt Forum Archive

Topic: pppoe: Unable to complete PPPoE Discovery

The content of this topic has been archived on 1 Apr 2018. There are no obvious gaps in this topic, but there may still be some posts missing at the end.

Post #1
schoppa
14 Aug 2005, 22:21

Hi,

after booting the pppoe needs more than 2 minutes to establish a connection. I get these error messages:

Any ideas?

Jan  1 01:00:47 (none) kern.warn pppd[402]: Timeout waiting for PADS packets
Jan  1 01:00:47 (none) kern.err pppd[402]: Unable to complete PPPoE Discovery
....
        ifconfig $IFNAME up
        /usr/sbin/pppd nodetach \
                plugin rp-pppoe.so \
                connect /bin/true \
                usepeerdns \
                defaultroute \
                noipdefault \
                persist \
                noauth \
                hide-password \
                linkname $type \
                user "$USERNAME" \
                password "$PASSWORD" \
                $MTU \
                $REDIAL \
                $IFNAME
....
Jan  1 01:00:11 (none) kern.info kernel: PPP generic driver version 2.4.2
Jan  1 01:00:12 (none) kern.info pppd[402]: Plugin rp-pppoe.so loaded.
Jan  1 01:00:12 (none) user.info : Plugin rp-pppoe.so loaded.
Jan  1 01:00:12 (none) kern.notice pppd[402]: pppd 2.4.3 started by root, uid 0
Jan  1 01:00:17 (none) kern.notice crond[614]: crond 2.3.2 dillon, started, log level 8
Jan  1 01:00:17 (none) kern.info dropbear[625]: Running in background
Jan  1 01:00:33 (none) kern.info dropbear[627]: Child connection from 192.168.1.40:34015
Jan  1 01:00:37 (none) kern.notice dropbear[627]: password auth succeeded for 'root' from 192.168.1.40:34015
Jan  1 01:00:47 (none) kern.warn pppd[402]: Timeout waiting for PADS packets
Jan  1 01:00:47 (none) kern.err pppd[402]: Unable to complete PPPoE Discovery
Jan  1 01:00:47 (none) user.info : Timeout waiting for PADS packets
Jan  1 01:00:47 (none) user.info : Unable to complete PPPoE Discovery
Jan  1 01:01:52 (none) kern.warn pppd[402]: Timeout waiting for PADS packets
Jan  1 01:01:52 (none) kern.err pppd[402]: Unable to complete PPPoE Discovery
Jan  1 01:01:52 (none) user.info : Timeout waiting for PADS packets
Jan  1 01:01:52 (none) user.info : Unable to complete PPPoE Discovery
Jan  1 01:02:23 (none) kern.info pppd[402]: PPP session is 8202
Jan  1 01:02:23 (none) user.info : PPP session is 8202
Jan  1 01:02:23 (none) kern.info pppd[402]: Using interface ppp0
Jan  1 01:02:23 (none) kern.notice pppd[402]: Connect: ppp0 <--> vlan1
Jan  1 01:02:23 (none) kern.warn pppd[402]: Couldn't increase MTU to 1500
Jan  1 01:02:23 (none) kern.warn pppd[402]: Couldn't increase MRU to 1500
Jan  1 01:02:23 (none) user.info : Using interface ppp0
Jan  1 01:02:23 (none) user.info : Connect: ppp0 <--> vlan1
Jan  1 01:02:23 (none) user.info : Couldn't increase MTU to 1500
Jan  1 01:02:23 (none) user.info : Couldn't increase MRU to 1500
Jan  1 01:02:23 (none) kern.notice pppd[402]: PAP authentication succeeded
Jan  1 01:02:23 (none) kern.notice pppd[402]: PAP authentication succeeded
Jan  1 01:02:23 (none) kern.notice pppd[402]: peer from calling number 00:90:1A:A0:15:B5 authorized
Jan  1 01:02:23 (none) user.info : PAP authentication succeeded
Jan  1 01:02:23 (none) user.info : PAP authentication succeeded
Jan  1 01:02:23 (none) user.info : peer from calling number 00:90:1A:A0:15:B5 authorized
Jan  1 01:02:23 (none) kern.notice pppd[402]: local  IP address 84.134.140.129
Jan  1 01:02:23 (none) kern.notice pppd[402]: remote IP address 217.0.116.115
Jan  1 01:02:23 (none) kern.notice pppd[402]: primary   DNS address 217.237.149.161
Jan  1 01:02:23 (none) kern.notice pppd[402]: secondary DNS address 217.237.150.97
Jan  1 01:02:23 (none) user.info : local  IP address 84.134.140.129
Jan  1 01:02:23 (none) user.info : remote IP address 217.0.116.115
Jan  1 01:02:23 (none) user.info : primary   DNS address 217.237.149.161
Jan  1 01:02:23 (none) user.info : secondary DNS address 217.237.150.97
Post #2
freezer2k
9 Sep 2005, 12:47

Hello,

Ive got the exact same errors with the same symptom, it takes 2-3minutes after boot to have an etablished ppp connection.


Maybe it has to do something with the MTU set @nvram? i set it to 1400 (AOL DSL in germany), in the log is also the error "kern.warn pppd[402]: Couldn't increase MTU to 1500", after the 2-3minutes i get connected, BUT ifconfig shows an MTU of 1454 at the ppp0 device - not the 1400 i set in the nvram settings.

This also results that clients have problems with some www-sites (as example ebay.de). I can set the MTU manually to 1400, then all sites are accessible by the clients.



Greetz,
Freezer

(Last edited by freezer2k on 9 Sep 2005, 12:50)

Post #3
roTT
10 Sep 2005, 17:15

i saw the same behaviour

modified /sbin/ifup.pppoe commenting this lines

        #IDLETIME=$(nvram get ppp_idletime)
        #IDLETIME=${IDLETIME:+lcp-echo-failure $IDLETIME}

now the "power on to ppp link" time is under a minute. reconnects are fast too

also a look in that file will help you to understand the nvram vars involved in the link creation, usefull if you have more than one (a)dsl provider.

hope this helps

Post #4
freezer2k
11 Sep 2005, 17:51

mh lol big_smile


out-commenting these lines in the config results that the "power on to ppp up" time has been increased to nearly 6 minutes big_smile


what does the ppp_idletime nvram value do? Will maybe help an other value? Also i noticed that this entry does not exist in my nvram!


Greetz,
Freezer

Post #5
Shining
12 Sep 2005, 00:54
freezer2k wrote:

what does the ppp_idletime nvram value do?

Its name is quite misleading - ppp_idletime sets the lcp-echo-failure value for pppd. Quoting from the pppd man page:

manpage wrote:

If  this  option is given, pppd will presume the peer to be dead if n LCP echo-requests are sent without receiving  a  valid  LCP
echo-reply.   If  this  happens, pppd will terminate the connection.

so values will lead to faster connection aborts.

Regarding the original problem: when the session initiation has advanced to a situation where a PADS is expected by the client, there already has been some information exchange between the client and the server. PADS packets may not arrive due to wrongly set MTU/MRU but it would be easier to tell if the "debug" option were switched on for the pppd process.

Post #6
nieslpriem
22 Sep 2005, 07:26

Hi,

im using "White Russian RC3" on a LinkSys WRT54GSv1.1.

freezer2k wrote:

Maybe it has to do something with the MTU set @nvram? i set it to 1400 (AOL DSL in germany), in the log is also the error "kern.warn pppd[402]: Couldn't increase MTU to 1500", after the 2-3minutes i get connected, BUT ifconfig shows an MTU of 1454 at the ppp0 device - not the 1400 i set in the nvram settings.

This also results that clients have problems with some www-sites (as example ebay.de). I can set the MTU manually to 1400, then all sites are accessible by the clients.

I have the same problem with ebay.de. But manually setting doesn't help.

root@OpenWrt:/etc# ifconfig ppp0 mtu 1454
root@OpenWrt:/etc# ifconfig ppp0
ppp0      Link encap:Point-Point Protocol
          inet addr:82.135.10.237  P-t-P:82.135.10.1  Mask:255.255.255.255
          UP POINTOPOINT RUNNING NOARP MULTICAST  MTU:1454  Metric:1
          RX packets:637 errors:0 dropped:0 overruns:0 frame:0
          TX packets:720 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:3
          RX bytes:682881 (666.8 KiB)  TX bytes:50584 (49.3 KiB)

Here is the debug output from logread:

Jan  1 01:00:20 (none) kern.info kernel: PPP generic driver version 2.4.2
Jan  1 01:00:21 (none) kern.info pppd[302]: Plugin rp-pppoe.so loaded.
Jan  1 01:00:21 (none) user.info : Plugin rp-pppoe.so loaded.
Jan  1 01:00:21 (none) kern.notice pppd[302]: pppd 2.4.3 started by root, uid 0
Jan  1 01:00:22 (none) kern.debug pppd[302]: PADS: Service-Name: ''
Jan  1 01:00:22 (none) user.info : PADS: Service-Name: ''
Jan  1 01:00:22 (none) kern.info pppd[302]: PPP session is 59259
Jan  1 01:00:22 (none) user.info : PPP session is 59259
Jan  1 01:00:22 (none) kern.debug pppd[302]: using channel 1
Jan  1 01:00:22 (none) user.info : using channel 1
Jan  1 01:00:22 (none) kern.info pppd[302]: Using interface ppp0
Jan  1 01:00:22 (none) user.info : Using interface ppp0
Jan  1 01:00:22 (none) kern.notice pppd[302]: Connect: ppp0 <--> vlan1
Jan  1 01:00:22 (none) user.info : Connect: ppp0 <--> vlan1
Jan  1 01:00:22 (none) kern.warn pppd[302]: Couldn't increase MTU to 1500
Jan  1 01:00:22 (none) user.info : Couldn't increase MTU to 1500
Jan  1 01:00:22 (none) kern.warn pppd[302]: Couldn't increase MRU to 1500
Jan  1 01:00:22 (none) user.info : Couldn't increase MRU to 1500
Jan  1 01:00:22 (none) kern.debug pppd[302]: sent [LCP ConfReq id=0x1 <mru 1400> <magic 0x8c7d8d60>]
Jan  1 01:00:22 (none) user.info : sent [LCP ConfReq id=0x1 <mru 1400> <magic 0x8c7d8d60>]
Jan  1 01:00:22 (none) kern.debug pppd[302]: rcvd [LCP ConfReq id=0x5a <mru 1492> <auth chap MD5> <magic 0x6846dbed>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:22 (none) user.info : rcvd [LCP ConfReq id=0x5a <mru 1492> <auth chap MD5> <magic 0x6846dbed>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:22 (none) kern.debug pppd[302]: sent [LCP ConfAck id=0x5a <mru 1492> <auth chap MD5> <magic 0x6846dbed>]
Jan  1 01:00:22 (none) user.info : sent [LCP ConfAck id=0x5a <mru 1492> <auth chap MD5> <magic 0x6846dbed>]
Jan  1 01:00:22 (none) kern.debug pppd[302]: rcvd [LCP ConfAck id=0x1 <mru 1400> <magic 0x8c7d8d60>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:22 (none) user.info : rcvd [LCP ConfAck id=0x1 <mru 1400> <magic 0x8c7d8d60>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:22 (none) kern.debug pppd[302]: rcvd [CHAP Challenge id=0x1 <97eb95a68a08a7b9930cb10398dcd164>, name = "ac1-br1-lanal052"] 00
Jan  1 01:00:22 (none) user.info : rcvd [CHAP Challenge id=0x1 <97eb95a68a08a7b9930cb10398dcd164>, name = "ac1-br1-lanal052"] 00
Jan  1 01:00:22 (none) kern.debug pppd[302]: sent [CHAP Response id=0x1 <1f46f493c4a2e53cbf95c96e47509412>, name = "X0009734@mdsl.mnet-online.de"]
Jan  1 01:00:22 (none) user.info : sent [CHAP Response id=0x1 <1f46f493c4a2e53cbf95c96e47509412>, name = "X0009734@mdsl.mnet-online.de"]
Jan  1 01:00:23 (none) kern.debug pppd[302]: rcvd [CHAP Success id=0x1 "CHAP authentication success, unit 9866"]
Jan  1 01:00:23 (none) kern.info pppd[302]: CHAP authentication succeeded: CHAP authentication success, unit 9866
Jan  1 01:00:23 (none) kern.notice pppd[302]: CHAP authentication succeeded
Jan  1 01:00:23 (none) kern.notice pppd[302]: peer from calling number 00:02:3B:02:9C:84 authorized
Jan  1 01:00:23 (none) kern.debug pppd[302]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Jan  1 01:00:23 (none) kern.debug pppd[302]: rcvd [IPCP ConfReq id=0x3c <addr 82.135.10.1>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:23 (none) kern.debug pppd[302]: sent [IPCP ConfAck id=0x3c <addr 82.135.10.1>]
Jan  1 01:00:23 (none) user.info : rcvd [CHAP Success id=0x1 "CHAP authentication success, unit 9866"]
Jan  1 01:00:23 (none) user.info : CHAP authentication succeeded: CHAP authentication success, unit 9866
Jan  1 01:00:23 (none) user.info : CHAP authentication succeeded
Jan  1 01:00:23 (none) user.info : peer from calling number 00:02:3B:02:9C:84 authorized
Jan  1 01:00:23 (none) user.info : sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Jan  1 01:00:23 (none) user.info : rcvd [IPCP ConfReq id=0x3c <addr 82.135.10.1>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:23 (none) user.info : sent [IPCP ConfAck id=0x3c <addr 82.135.10.1>]
Jan  1 01:00:23 (none) kern.debug pppd[302]: rcvd [IPCP ConfNak id=0x1 <addr 82.135.10.145> <ms-dns1 212.18.3.5> <ms-dns3 212.18.0.5>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:23 (none) kern.debug pppd[302]: sent [IPCP ConfReq id=0x2 <addr 82.135.10.145> <ms-dns1 212.18.3.5> <ms-dns3 212.18.0.5>]
Jan  1 01:00:23 (none) user.info : rcvd [IPCP ConfNak id=0x1 <addr 82.135.10.145> <ms-dns1 212.18.3.5> <ms-dns3 212.18.0.5>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:23 (none) user.info : sent [IPCP ConfReq id=0x2 <addr 82.135.10.145> <ms-dns1 212.18.3.5> <ms-dns3 212.18.0.5>]
Jan  1 01:00:23 (none) kern.debug pppd[302]: rcvd [IPCP ConfAck id=0x2 <addr 82.135.10.145> <ms-dns1 212.18.3.5> <ms-dns3 212.18.0.5>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Jan  1 01:00:23 (none) kern.notice pppd[302]: replacing old default route to br0 [192.168.0.1]
Jan  1 01:00:23 (none) kern.notice pppd[302]: local  IP address 82.135.10.145
Jan  1 01:00:23 (none) kern.notice pppd[302]: remote IP address 82.135.10.1
Jan  1 01:00:23 (none) kern.notice pppd[302]: primary   DNS address 212.18.3.5
Jan  1 01:00:23 (none) kern.notice pppd[302]: secondary DNS address 212.18.0.5
Jan  1 01:00:23 (none) user.info : rcvd [IPCP ConfAck id=0x2 <addr 82.135.10.145> <ms-dns1 212.18.3.5> <ms-dns3 212.18.0.5>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

Has someone found a solution?

TIA
Daniel

Post #7
doddel
23 Sep 2005, 11:07

addressed the problem here by a script that via telnet connects to the adsl modem and brings the adsl line down and up again. After that connect follows mostly quickly. Apparently the modems in the phone exchange and at the client can get into a situation that does not produce these PADS packets that the ppp negotiation is waiting for.
But, ...., we noticed here that the moments this problem happens often coincide with popular internet use moments.
ADSL modem capacity is in some telephone exchanges a scarce resource and requires investment by the telco.
So another possible source of the problem is your telco and the adsl capacity installed in the local exchange.

example of the script to talk with the modem, to be adapted to your needs:

#!/bin/sh
IFS=
host_attempt=0
while ((!( /bin/ping -c 1 **ipnumber_of_provider_gateway** | grep -q '1 packets received' )) && \
        [ $host_attempt -lt '3' ] )
do
        host_attempt=`expr $host_attempt + 1`
        /bin/sleep 1
done
        LOGSTRING="`date`"
if [ $host_attempt = 3 ] ; then
        echo -e $LOGSTRING >> /etc/**your_choice_of_logname**.log
        # kill pppoe and adsl link
        /usr/bin/killall -9 ifup.pppoe
        /usr/bin/killall -9 pppd
        # bring down wan
        /sbin/ifdown wan
        /etc/init.d/fixed                               # fixed is a script that sets temporary nvram for static wan IP
        /bin/sleep 1
        /sbin/ifup wan                                 # bring wan back up with modem's ip reachable
        /etc/init.d/fixed_ipt                   # script to change and open the iptables firewall; do not use masquerade
        nc -i 2 **ip_of_adsl_modem** 23 <<EOT | grep "Downstream Noise Margin" >> /etc/**your_choice_of_logname**.log
**modem's_password**
bsp line
bsp down
bsp up
@close
EOT
        /bin/sleep 10
       /etc/init.d/dynamic                             # script to restore nvram parameters to previous dynamic state
        /bin/sleep 1
        /sbin/ifup wan
        /etc/init.d/**your_firewall**    # restore iptables firewall
fi

=====================================
the commands after modem's password are specific for the OS of the modem and its Command line Interface (CLI).
This script logs the moments that this reconnect attempt is made and monitors the signal to noise ratio on the ADSL line. All of this script telnet detail is modem dependent. It starts talking to the modem after attempting three times without success to ping the Telco's gateway. NC is set to give out its command lines with two second intervals, until EOT comes along.
And this script is called by crond; we do it here every three minutes.

(Last edited by doddel on 23 Sep 2005, 11:09)

Post #8
olli
23 Sep 2005, 11:29

Please update to the new White Russian RC3 release.

There are lots of PPP bugs fixed.

The discussion might have continued from here.