1

I have the issue while establishing pppoe connection on De(b)vuan based distribution. My ISP allows me to establish link via tagged vlan 300. Previosly the connection worked just fine, before i slightly recompiled kernel (made it more generic), but I don't believe it should be a problem.

All modules are (should) be properly loaded already.

Here is the log:

Nov 11 01:08:02  pppd[2863]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Nov 11 01:08:02  pppd[2863]:  dst ff:ff:ff:ff:ff:ff  src b8:27:eb:62:e6:80
Nov 11 01:08:02  pppd[2863]:  [service-name] [host-uniq  2f 0b 00 00]
Nov 11 01:08:02  pppd[2863]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 53
Nov 11 01:08:02  pppd[2863]:  dst b8:27:eb:62:e6:80  src e4:81:84:26:2e:6c
Nov 11 01:08:02  pppd[2863]:  [service-name] [AC-name BNG_NS_SATELIT1_2] [host-uniq  2f 0b 00 00] [AC-cookie  06 40 99 9b 50 e9 b3 90 be 93 bb 10 9f e6 16 db]
Nov 11 01:08:02  pppd[2863]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Nov 11 01:08:02  pppd[2863]:  dst e4:81:84:26:2e:6c  src b8:27:eb:62:e6:80
Nov 11 01:08:02  pppd[2863]:  [service-name] [host-uniq  2f 0b 00 00] [AC-cookie  06 40 99 9b 50 e9 b3 90 be 93 bb 10 9f e6 16 db]
Nov 11 01:08:02  pppd[2863]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 57
Nov 11 01:08:02  pppd[2863]:  dst b8:27:eb:62:e6:80  src e4:81:84:25:df:d6
Nov 11 01:08:02  pppd[2863]:  [service-name] [AC-name BNG_XXXX] [host-uniq  2f 0b 00 00] [AC-cookie  5e 0c 8b 60 fb 75 10 fd 83 4f 68 ce fa 5a f3 d9]
Nov 11 01:08:02  pppd[2863]: Recv PPPOE Discovery V1T1 PADS session 0x642 length 12
Nov 11 01:08:02  pppd[2863]:  dst b8:27:eb:62:e6:80  src e4:81:84:26:2e:6c
Nov 11 01:08:02  pppd[2863]:  [service-name] [host-uniq  2f 0b 00 00]
Nov 11 01:08:02  pppd[2863]: PADS: Service-Name: ''
Nov 11 01:08:02  pppd[2863]: PPP session is 1602
Nov 11 01:08:02  pppd[2863]: Connected to e4:81:xx:xx:xx via interface eth0.300
Nov 11 01:08:02  pppd[2863]: using channel 71
Nov 11 01:08:02  pppd[2863]: Using interface ppp0
Nov 11 01:08:02  pppd[2863]: Connect: ppp0 <--> eth0.300
Nov 11 01:08:02  pppd[2863]: sent [LCP ConfReq id=0xa <mru 1492> <magic 0x6bd07e40>]
Nov 11 01:08:02  pppd[2863]: rcvd [LCP ConfAck id=0xa <mru 1492> <magic 0x6bd07e40>]
Nov 11 01:08:05  pppd[2863]: rcvd [LCP ConfReq id=0x28 <mru 1492> <auth pap> <magic 0x6e7eeffa>]
Nov 11 01:08:05  pppd[2863]: sent [LCP ConfAck id=0x28 <mru 1492> <auth pap> <magic 0x6e7eeffa>]
Nov 11 01:08:05  pppd[2863]: sent [LCP EchoReq id=0x0 magic=0x6bd07e40]
Nov 11 01:08:05  pppd[2863]: sent [PAP AuthReq id=0x9 user="username@isp.com" password=<hidden>]
Nov 11 01:08:05  pppd[2863]: rcvd [LCP EchoRep id=0x0 magic=0x6e7eeffa]
Nov 11 01:08:06  pppd[2863]: rcvd [PAP AuthAck id=0x9 "Login ok"]
Nov 11 01:08:06  pppd[2863]: Remote message: Login ok
Nov 11 01:08:06  pppd[2863]: PAP authentication succeeded
Nov 11 01:08:06  pppd[2863]: peer from calling number E4:81:xx:xx:xx:xx authorized
Nov 11 01:08:06  pppd[2863]: sent [IPCP ConfReq id=0x19 <addr 0.0.0.0>]
Nov 11 01:08:06  pppd[2863]: rcvd [IPCP ConfReq id=0xe <addr xxx.xxx.xxx.xxx>]
Nov 11 01:08:06  pppd[2863]: sent [IPCP ConfAck id=0xe <addr xxx.xxx.xxx.xxx>] # <- GW
Nov 11 01:08:06  pppd[2863]: rcvd [IPCP ConfNak id=0x19 <addr xxx.xxx.xxx.xxx>]
Nov 11 01:08:06  pppd[2863]: sent [IPCP ConfReq id=0x1a <addr xxx.xxx.xxx.xxx>]
Nov 11 01:08:06  pppd[2863]: rcvd [IPCP ConfAck id=0x1a <addr xxx.xxx.xxx.xxx>]
Nov 11 01:08:06  pppd[2863]: ioctl(SIOCADDRT) device route: Network is down (line 2501)
Nov 11 01:08:06  pppd[2863]: Interface configuration failed
Nov 11 01:08:06  pppd[2863]: Connect time 0.1 minutes.
Nov 11 01:08:06  pppd[2863]: Sent 30 bytes, received 30 bytes.
Nov 11 01:08:06  pppd[2863]: sent [IPCP TermReq id=0x1b "Interface configuration failed"]
Nov 11 01:08:06  pppd[2863]: rcvd [LCP TermReq id=0x29]
Nov 11 01:08:06  pppd[2863]: LCP terminated by peer
Nov 11 01:08:06  pppd[2863]: sent [LCP TermAck id=0x29]
Nov 11 01:08:06  pppd[2863]: rcvd [IPCP TermAck id=0x1b]
Nov 11 01:08:06  pppd[2863]: Discarded non-LCP packet when LCP not open
Nov 11 01:08:06  pppd[2863]: Modem hangup
Nov 11 01:08:06  pppd[2863]: Connection terminated.
Nov 11 01:08:06  pppd[2863]: Failed to disconnect PPPoE socket: 114 Operation already in progress


 # cat /etc/ppp/peers/dsl-provider 
# Minimalistic default options file for DSL/PPPoE connections

noipdefault
defaultroute
replacedefaultroute
hide-password
#lcp-echo-interval 0 
#lcp-echo-failure 0
noauth
persist
mtu 1412
persist
#maxfail 0
holdoff 20
plugin rp-pppoe.so
eth0.300
user "username@isp.com"

EDIT: As it is on my modified router, here is the link status :

# ip  a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,PROMISC,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether b8:27:eb:62:e6:80 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::ba27:ebff:fe62:e680/64 scope link 
       valid_lft forever preferred_lft forever
3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 00:0e:c6:c7:3e:1c brd ff:ff:ff:ff:ff:ff
    inet 192.168.1.1/24 brd 192.168.1.255 scope global eth1
       valid_lft forever preferred_lft forever
    inet6 fe80::20e:c6ff:fec7:3e1c/64 scope link 
       valid_lft forever preferred_lft forever
4: eth3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast master br0 state UP group default qlen 1000
    link/ether 00:e0:4c:36:02:76 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::2e0:4cff:fe36:276/64 scope link 
       valid_lft forever preferred_lft forever
32: eth0.200@eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue master br0 state UP group default qlen 1000
    link/ether b8:27:eb:62:e6:80 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::ba27:ebff:fe62:e680/64 scope link 
       valid_lft forever preferred_lft forever
33: br0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 00:e0:4c:36:02:76 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::2e0:4cff:fe36:276/64 scope link 
       valid_lft forever preferred_lft forever
63: eth0.300@eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether b8:27:eb:62:e6:80 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::ba27:ebff:fe62:e680/64 scope link 
       valid_lft forever preferred_lft forever

Modules:

# lsmod | grep 'ppp\|802\|garp':

ppp_mppe                6951  0 
pppoe                  11779  0 
pppox                   2913  1 pppoe
ppp_generic            29613  3 pppox,pppoe,ppp_mppe
slhc                    5959  1 ppp_generic
8021q                  22998  0 
garp                    7049  1 8021q
mrp                     8903  1 8021q
stp                     2430  2 garp,bridge
llc                     5903  3 garp,bridge,stp

Can anyone point me what is causing:

Nov 11 01:08:29  pppd[2863]: ioctl(SIOCADDRT) device route: Network is down (line 2501)
Nov 11 01:08:29  pppd[2863]: Interface configuration failed
Nov 11 01:08:29  pppd[2863]: Connect time 0.1 minutes.
Nov 11 01:08:29  pppd[2863]: Sent 30 bytes, received 30 bytes.
Nov 11 01:08:29  pppd[2863]: sent [IPCP TermReq id=0x1e "Interface configuration failed"]
Nov 11 01:08:29  pppd[2863]: rcvd [LCP TermReq id=0x34]
Nov 11 01:08:29  pppd[2863]: LCP terminated by peer

Edit interfaces file:

 # cat /etc/network/interfaces

# This file describes the network interfaces available on your system
# and how to activate them. For more information, see interfaces(5).

source /etc/network/interfaces.d/*

# The loopback network interface
auto lo
iface lo inet loopback

# The primary network interface

auto eth0
auto eth1
auto eth3

#LAN
iface eth1 inet static
    address 192.168.1.1
    netmask 255.255.255.0

#IPTV
auto eth0.200
iface eth0.200 inet manual


#WAN
auto eth0.300
iface eth0.300 inet manual

auto dsl-provider
iface dsl-provider inet ppp
    pre-up /bin/ip link set eth0.300 up # line maintained by pppoeconf
    provider dsl-provider

iface br0 inet manual
    bridge_ports eth3 eth0.200

IP route:

 # ip r
192.168.1.0/24 dev eth1  proto kernel  scope link  src 192.168.1.1 

Generated by pppoeconf:

:/~ # grep -v '^$\|^#' /etc/ppp/peers/dsl-provider 
noipdefault
defaultroute
hide-password
lcp-echo-interval 20
lcp-echo-failure 3
connect /bin/true
noauth
persist
mtu 1492
noaccomp
default-asyncmap
logfile /var/log/ppp.log
plugin rp-pppoe.so eth0.300
user "myusername@isp.com"

Edit 2:

Attached strace output:

strace pppd file /etc/ppp/peers/dsl-provider debug

http://paste.debian.net/995356/

strace -p PID

http://paste.debian.net/995357/

Appreciated!

1

The line

ioctl(SIOCADDRT) device route: Network is down

means that pppd tried to set a route for an address range on a device which is down. The same happens if you set the route manually with ip route.

Debug by doing ip addr, looking at the addresses on the network interfaces and which ones are up or down, and looking at the addresses pppd received. This may involve some guessing what pppd was doing during the execution, as the state after it shuts down may not be the same state as during the execution. If you can't guess anything, use strace and be prepared for a large output.

You didn't show the other network interfaces or the addresses, so I can't do that for you.

  • thanks for response! I updated my question. I guessed that is the problem and meaning of the message, but all ifaces are up, except ppp0 . Shouldn't this device be configured automatically when connection is going to be started? Default route, and related routing should be set with defaultroute && noipdefault in ppp.conf, right? – fugitive Nov 11 '17 at 17:33
  • Hm. Possibly pppd is not setting ppp0 up before trying to set the route, and that worked with older kernels? Can you upgrade pppd to the newest version (if this is a bug for newer kernels, I'm sure someone has noticed it already ...)? – dirkt Nov 11 '17 at 18:16
  • Not sure, I haven't changed the kernel it self, only added couple of modules, it is 4.9.59 for raspberry 3. But yea, I believe this is the case. Reinstalled everything related to ppp already - but no luck. When I do a reboot, i notice ppp0 link but it is in down state. When I try to start ppp - it just get lost. Not sure how to troubleshoot this – fugitive Nov 11 '17 at 18:27
  • Next step is either strace, or using a debugger on pppd, I suppose. – dirkt Nov 11 '17 at 20:52
  • Well, strace doesn't ring a bell for me.. I am not very comfortable with low-level debug except something is obvious. If anyone can help, I'll be very thankful! – fugitive Nov 12 '17 at 19:54

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.