Scheduled Maintenance: We are aware of an issue with Google, AOL, and Yahoo services as email providers which are blocking new registrations. We are trying to fix the issue and we have several internal and external support tickets in process to resolve the issue. Please see: viewtopic.php?t=158230

 

 

 

ppp0 doesn't stay connected on boot

Linux Kernel, Network, and Services configuration.
Post Reply
Message
Author
troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

ppp0 doesn't stay connected on boot

#1 Post by troffasky »

Trying to troubleshoot an issue whereby ppp0 connects and then disconnects very quickly on boot:

11:04:07 westogre pppd[1445]: Plugin rp-pppoe.so loaded.
11:04:07 westogre pppd[1451]: pppd 2.4.7 started by root, uid 0
11:04:12 westogre pppd[1451]: PPP session is 5750
11:04:12 westogre pppd[1451]: Connected to a0:f3:e4:34:d6:74 via interface eth3
11:04:12 westogre pppd[1451]: Using interface ppp0
11:04:12 westogre pppd[1451]: Connect: ppp0 <--> eth3
11:04:13 westogre pppd[1451]: CHAP authentication succeeded: BBEU10217542
11:04:13 westogre pppd[1451]: CHAP authentication succeeded
11:04:13 westogre pppd[1451]: peer from calling number A0:F3:E4:34:D6:74 authorized
11:04:13 westogre pppd[1451]: local IP address 81.x.x.x
11:04:13 westogre pppd[1451]: remote IP address 81.x.x.x
11:04:13 westogre pppd[1451]: local LL address fe80::847c:5c65:8c60:33be
11:04:13 westogre pppd[1451]: remote LL address fe80::0203:97ff:fe27:c000
11:04:18 westogre pppd[1451]: Terminating on signal 15
11:04:18 westogre pppd[1451]: Connect time 0.1 minutes.
11:04:18 westogre pppd[1451]: Sent 946 bytes, received 696 bytes.
11:04:18 westogre pppd[1451]: Child process /etc/ppp/ip-up (pid 1483) terminated with signal 15
11:04:18 westogre pppd[1451]: Connection terminated.
11:04:18 westogre pppd[1451]: Connect time 0.1 minutes.
11:04:18 westogre pppd[1451]: Sent 946 bytes, received 696 bytes.
11:04:18 westogre pppd[1451]: Exit.

After boot, if I 'ifup ppp0' it connects just fine, and basically remains in this state until the next reboot. Multiple reboots show the same events for pppd - it connects and is then killed after about 5s. I couldn't say when this started happening, and I'm not sure it has ever worked on boot.

Relevant section from interfaces:

auto ppp0
iface ppp0 inet ppp
pre-up /bin/ip link set eth3 mtu 1508
pre-up /bin/ip link set eth3 up
provider provider
post-up sh /root/firewall/delayed-post-up.sh

The post-up script waits 10s and then loads my iptables rules.

All other interfaces on the system come up on boot without a problem.

Where to start troubleshooting? What could be sending signal 15? /etc/ppp/ip-up is probably 'factory' - the timestamp is 2011 which is before I started using PPPoE for internet access in 2013.


Using Debian SID.

p.H
Global Moderator
Global Moderator
Posts: 3049
Joined: 2017-09-17 07:12
Has thanked: 5 times
Been thanked: 132 times

Re: ppp0 doesn't stay connected on boot

#2 Post by p.H »

troffasky wrote:The post-up script waits 10s and then loads my iptables rules.
10 seconds is the delay between the start and termination of pppd.

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#3 Post by troffasky »

I will try varying the delay and rebooting.

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#4 Post by troffasky »

Indeed, changing the delay in my firewall script to 7s shortens the time between events accordingly. So is the script somehow telling ifupdown to terminate the connection? The other thing I noticed when manually putting ppp0 up again is this:

Code: Select all

# ifup ppp0
ifup: interface ppp0 already configured
so ifupdown doesn't actually consider ppp0 to be down.

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#5 Post by troffasky »

If I comment out the post-up action completely, it just drops the connection immediately:

Code: Select all

May 27 08:37:17 westogre pppd[2289]: Plugin rp-pppoe.so loaded.
May 27 08:37:17 westogre pppd[2300]: pppd 2.4.7 started by root, uid 0
May 27 08:37:21 westogre pppd[2300]: PPP session is 2971
May 27 08:37:21 westogre pppd[2300]: Connected to 28:8a:1c:e9:c0:52 via interface eth3
May 27 08:37:21 westogre pppd[2300]: Using interface ppp0
May 27 08:37:21 westogre pppd[2300]: Connect: ppp0 <--> eth3
May 27 08:37:21 westogre pppd[2300]: Terminating on signal 15
May 27 08:37:21 westogre pppd[2300]: Connection terminated.
May 27 08:37:21 westogre pppd[2300]: Sent PADT
May 27 08:37:21 westogre pppd[2300]: Exit
Any ideas on further troubleshooting?

User avatar
debiman
Posts: 3063
Joined: 2013-03-12 07:18

Re: ppp0 doesn't stay connected on boot

#6 Post by debiman »

so are you saying it has worked for years, and now stopped working?
what's actually happening, are you left without internet connection in the end, or does it settle eventually?
this is mobile broadband, yes?
i have been using that years ago, and i remember it never reliably worked straight from booting; in the end i did some config and ran

Code: Select all

pon
poff
when required.

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#7 Post by troffasky »

debiman wrote:so are you saying it has worked for years, and now stopped working?
I suspect it's been like this all along but I reboot infrequently enough that I can't remember.
debiman wrote:what's actually happening, are you left without internet connection in the end, or does it settle eventually?
No internet until I ifdown/ifup.
debiman wrote:this is mobile broadband, yes?
VDSL.

arzgi
Posts: 1185
Joined: 2008-02-21 17:03
Location: Finland
Been thanked: 31 times

Re: ppp0 doesn't stay connected on boot

#8 Post by arzgi »

troffasky wrote:
No internet until I ifdown/ifup.
debiman wrote:this is mobile broadband, yes?
VDSL.
You spoke about ppp0, and now VDSL and ifdown and ifup. I too have a VDSL, but it is a router thing, behind router it is just normal lan. I use static and dhcp addresses.

ppp I use when I'm on the road, this notebook has internal 3g-modem. And ppp does not live though reboots.

My sister's computer only network connection is 3g, so I put wvdial to start at boot.

p.H
Global Moderator
Global Moderator
Posts: 3049
Joined: 2017-09-17 07:12
Has thanked: 5 times
Been thanked: 132 times

Re: ppp0 doesn't stay connected on boot

#9 Post by p.H »

Sorry for the delay, I missed your replies.
troffasky wrote:If I comment out the post-up action completely, it just drops the connection immediately
Then it seems that what stops pppd is not in the script but happens after the script returns and the ppp0 stanza is completed. You can check this by appending another "post-ip sleep xx" delay. Could it be the next stanza ?
Could you post the complete contents of /etc/network/interfaces and its include files ?
Also, could you add the "debug" option in /etc/ppp/peers/provider to get more verbose pppd logs ?
troffasky wrote:so ifupdown doesn't actually consider ppp0 to be down.
The status in ifupdown is an administrative status which changes only by running ifup and ifdown.

@ arzgi : PPPoE is a commonly used protocol over xDSL links. That's what you use when the xDSL modem acts as a bridge.

arzgi
Posts: 1185
Joined: 2008-02-21 17:03
Location: Finland
Been thanked: 31 times

Re: ppp0 doesn't stay connected on boot

#10 Post by arzgi »

p.H wrote: The status in ifupdown is an administrative status which changes only by running ifup and ifdown.

@ arzgi : PPPoE is a commonly used protocol over xDSL links. That's what you use when the xDSL modem acts as a bridge.
Thanks p.H. I have newer used my router as a bridge, so I tend to think my setup is the norm :mrgreen:

User avatar
debiman
Posts: 3063
Joined: 2013-03-12 07:18

Re: ppp0 doesn't stay connected on boot

#11 Post by debiman »

well now i'm confused.
i learned that the device ppp0, ppp1 etc. denominates a mobile broadband connection, and PPPoE is something very different.
VDSL has nothing to do with mobile broadband, yet op's ouput clearly mentions ppp (NOT pppoe) several times...???

p.H
Global Moderator
Global Moderator
Posts: 3049
Joined: 2017-09-17 07:12
Has thanked: 5 times
Been thanked: 132 times

Re: ppp0 doesn't stay connected on boot

#12 Post by p.H »

The use of the PPP protocol and pppN interfaces is much more general than just mobile connections.
It was historically used for dial-up connections using POTS modems (remember, they emitted tones during dial-up), then DSL connections (encapsulated with PPPoE or PPPoA for transport over ethernet or ATM). It is also used in the Microsoft VPN protocol PPTP (over GRE encapsulation).

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#13 Post by troffasky »

pppd logs on boot:

Code: Select all

May 29 23:31:21 westogre pppd[1777]: pppd 2.4.7 started by root, uid 0
May 29 23:31:21 westogre pppd[1777]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 29 23:31:21 westogre pppd[1777]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 29 23:31:21 westogre pppd[1777]:  [service-name] [PPP-max-payload  05 dc]
May 29 23:31:24 westogre pppd[1777]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 29 23:31:24 westogre pppd[1777]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 29 23:31:24 westogre pppd[1777]:  [service-name] [PPP-max-payload  05 dc]
May 29 23:31:25 westogre pppd[1777]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
May 29 23:31:25 westogre pppd[1777]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 29 23:31:25 westogre pppd[1777]:  [AC-name nge002.bla-re0] [PPP-max-payload  05 dc] [service-name] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 29 23:31:25 westogre pppd[1777]: Send PPPOE Discovery V1T1 PADR session 0x0 length 30
May 29 23:31:25 westogre pppd[1777]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 29 23:31:25 westogre pppd[1777]:  [service-name] [PPP-max-payload  05 dc] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 29 23:31:25 westogre pppd[1777]: Recv PPPOE Discovery V1T1 PADS session 0x9c7 length 48
May 29 23:31:25 westogre pppd[1777]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 29 23:31:25 westogre pppd[1777]:  [service-name] [PPP-max-payload  05 dc] [AC-name nge002.bla-re0] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 29 23:31:25 westogre pppd[1777]: PADS: Service-Name: ''
May 29 23:31:25 westogre pppd[1777]: PPP session is 2503
May 29 23:31:25 westogre pppd[1777]: Connected to 28:8a:1c:e9:c0:52 via interface eth3
May 29 23:31:25 westogre pppd[1777]: using channel 1
May 29 23:31:25 westogre pppd[1777]: Using interface ppp0
May 29 23:31:25 westogre pppd[1777]: Connect: ppp0 <--> eth3
May 29 23:31:25 westogre pppd[1777]: sent [LCP ConfReq id=0x1 <magic 0x5d62f9cc>]
May 29 23:31:25 westogre pppd[1777]: rcvd [LCP ConfReq id=0xbd <auth chap MD5> <magic 0x17450116>]
May 29 23:31:25 westogre pppd[1777]: sent [LCP ConfAck id=0xbd <auth chap MD5> <magic 0x17450116>]
May 29 23:31:25 westogre pppd[1777]: rcvd [LCP ConfAck id=0x1 <magic 0x5d62f9cc>]
May 29 23:31:25 westogre pppd[1777]: sent [LCP EchoReq id=0x0 magic=0x5d62f9cc]
May 29 23:31:25 westogre pppd[1777]: rcvd [CHAP Challenge id=0xf0 <ebe723e7b146540b656263f1f2aa5d522dec35a2e1e2ce77d985322986f2c4cd72c072a3ab67>, name = "nge002.bla"]
May 29 23:31:25 westogre pppd[1777]: sent [CHAP Response id=0xf0 <7553183aec27b9fde0b31c3eb9839b53>, name = "user@name"]
May 29 23:31:25 westogre pppd[1777]: rcvd [LCP EchoRep id=0x0 magic=0x17450116]
May 29 23:31:25 westogre pppd[1777]: rcvd [CHAP Success id=0xf0 "FTTC2279959"]
May 29 23:31:25 westogre pppd[1777]: CHAP authentication succeeded: FTTC2279959
May 29 23:31:25 westogre pppd[1777]: CHAP authentication succeeded
May 29 23:31:25 westogre pppd[1777]: peer from calling number 28:8A:1C:E9:C0:52 authorized
May 29 23:31:25 westogre pppd[1777]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 29 23:31:25 westogre pppd[1777]: sent [IPV6CP ConfReq id=0x1 <addr fe80::0110:8524:9f47:12b2>]
May 29 23:31:26 westogre pppd[1777]: rcvd [IPCP ConfReq id=0x0 <addr 81.187.81.187>]
May 29 23:31:26 westogre pppd[1777]: sent [IPCP ConfAck id=0x0 <addr 81.187.81.187>]
May 29 23:31:27 westogre pppd[1777]: rcvd [IPCP ConfReq id=0x1 <addr 81.187.81.187>]
May 29 23:31:27 westogre pppd[1777]: sent [IPCP ConfAck id=0x1 <addr 81.187.81.187>]
May 29 23:31:28 westogre pppd[1777]: rcvd [IPCP ConfReq id=0x2 <addr 81.187.81.187>]
May 29 23:31:28 westogre pppd[1777]: sent [IPCP ConfAck id=0x2 <addr 81.187.81.187>]
May 29 23:31:28 westogre pppd[1777]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 29 23:31:28 westogre pppd[1777]: sent [IPV6CP ConfReq id=0x1 <addr fe80::0110:8524:9f47:12b2>]
May 29 23:31:28 westogre pppd[1777]: rcvd [IPCP ConfNak id=0x1 <addr 81.x.x.x>]
May 29 23:31:28 westogre pppd[1777]: sent [IPCP ConfReq id=0x2 <addr 81.x.x.x>]
May 29 23:31:28 westogre pppd[1777]: rcvd [IPV6CP ConfAck id=0x1 <addr fe80::0110:8524:9f47:12b2>]
May 29 23:31:28 westogre pppd[1777]: rcvd [IPCP ConfAck id=0x2 <addr 81.x.x.x>]
May 29 23:31:28 westogre pppd[1777]: local  IP address 81.x.x.x
May 29 23:31:28 westogre pppd[1777]: remote IP address 81.187.81.187
May 29 23:31:28 westogre pppd[1777]: Script /etc/ppp/ip-up started (pid 1991)
May 29 23:31:28 westogre pppd[1777]: rcvd [IPV6CP ConfReq id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 29 23:31:28 westogre pppd[1777]: sent [IPV6CP ConfAck id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 29 23:31:28 westogre pppd[1777]: local  LL address fe80::0110:8524:9f47:12b2
May 29 23:31:28 westogre pppd[1777]: remote LL address fe80::0203:97ff:fe42:0000
May 29 23:31:28 westogre pppd[1777]: Script /etc/ppp/ipv6-up started (pid 1992)
May 29 23:31:28 westogre pppd[1777]: Script /etc/ppp/ipv6-up finished (pid 1992), status = 0x0
May 29 23:31:29 westogre pppd[1777]: Terminating on signal 15
May 29 23:31:29 westogre pppd[1777]: Connect time 0.1 minutes.
May 29 23:31:29 westogre pppd[1777]: Sent 740 bytes, received 443 bytes.
May 29 23:31:29 westogre pppd[1777]: Script /etc/ppp/ipv6-down started (pid 2072)
May 29 23:31:29 westogre pppd[1777]: sent [LCP TermReq id=0x2 "User request"]
May 29 23:31:29 westogre pppd[1777]: Child process /etc/ppp/ip-up (pid 1991) terminated with signal 15
May 29 23:31:29 westogre pppd[1777]: Script /etc/ppp/ip-down started (pid 2073)
May 29 23:31:29 westogre pppd[1777]: rcvd [LCP TermAck id=0x2]
May 29 23:31:29 westogre pppd[1777]: Connection terminated.
May 29 23:31:29 westogre pppd[1777]: Connect time 0.1 minutes.
May 29 23:31:29 westogre pppd[1777]: Sent 740 bytes, received 443 bytes.
May 29 23:31:29 westogre pppd[1777]: Send PPPOE Discovery V1T1 PADT session 0x9c7 length 20
May 29 23:31:29 westogre pppd[1777]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 29 23:31:29 westogre pppd[1777]:  [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 29 23:31:29 westogre pppd[1777]: Sent PADT
May 29 23:31:29 westogre pppd[1777]: Script /etc/ppp/ipv6-down finished (pid 2072), status = 0x0
May 29 23:31:29 westogre pppd[1777]: Waiting for 1 child processes...
May 29 23:31:29 westogre pppd[1777]:   script /etc/ppp/ip-down, pid 2073
May 29 23:31:30 westogre pppd[1777]: Script /etc/ppp/ip-down finished (pid 2073), status = 0x1
May 29 23:31:30 westogre pppd[1777]: Exit.
Logs after ifdown ppp0 ; ifup ppp0:

Code: Select all

May 29 23:35:28 westogre pppd[6225]: Plugin rp-pppoe.so loaded.
May 29 23:35:28 westogre pppd[6226]: pppd 2.4.7 started by alex, uid 0
May 29 23:35:28 westogre pppd[6226]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 29 23:35:28 westogre pppd[6226]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 29 23:35:28 westogre pppd[6226]:  [service-name] [PPP-max-payload  05 dc]
May 29 23:35:28 westogre pppd[6226]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
May 29 23:35:28 westogre pppd[6226]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 29 23:35:28 westogre pppd[6226]:  [AC-name nge002.bla-re0] [PPP-max-payload  05 dc] [service-name] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 29 23:35:28 westogre pppd[6226]: Send PPPOE Discovery V1T1 PADR session 0x0 length 30
May 29 23:35:28 westogre pppd[6226]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 29 23:35:28 westogre pppd[6226]:  [service-name] [PPP-max-payload  05 dc] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 29 23:35:28 westogre pppd[6226]: Recv PPPOE Discovery V1T1 PADS session 0x88c length 48
May 29 23:35:28 westogre pppd[6226]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 29 23:35:28 westogre pppd[6226]:  [service-name] [PPP-max-payload  05 dc] [AC-name nge002.bla-re0] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 29 23:35:28 westogre pppd[6226]: PADS: Service-Name: ''
May 29 23:35:28 westogre pppd[6226]: PPP session is 2188
May 29 23:35:28 westogre pppd[6226]: Connected to 28:8a:1c:e9:c0:52 via interface eth3
May 29 23:35:28 westogre pppd[6226]: using channel 2
May 29 23:35:28 westogre pppd[6226]: Using interface ppp0
May 29 23:35:28 westogre pppd[6226]: Connect: ppp0 <--> eth3
May 29 23:35:28 westogre pppd[6226]: sent [LCP ConfReq id=0x1 <magic 0xf2453d1e>]
May 29 23:35:28 westogre pppd[6226]: rcvd [LCP ConfReq id=0xe2 <auth chap MD5> <magic 0x60003794>]
May 29 23:35:28 westogre pppd[6226]: sent [LCP ConfAck id=0xe2 <auth chap MD5> <magic 0x60003794>]
May 29 23:35:28 westogre pppd[6226]: rcvd [LCP ConfAck id=0x1 <magic 0xf2453d1e>]
May 29 23:35:28 westogre pppd[6226]: sent [LCP EchoReq id=0x0 magic=0xf2453d1e]
May 29 23:35:28 westogre pppd[6226]: rcvd [CHAP Challenge id=0x73 <5389eed0578c90da530b6fcf>, name = "nge002.bla"]
May 29 23:35:28 westogre pppd[6226]: sent [CHAP Response id=0x73 <11e6495b6d1e09f4313dd90a5b2be8c2>, name = "user@name"]
May 29 23:35:28 westogre pppd[6226]: rcvd [LCP EchoRep id=0x0 magic=0x60003794]
May 29 23:35:29 westogre pppd[6226]: rcvd [CHAP Success id=0x73 "FTTC2279959"]
May 29 23:35:29 westogre pppd[6226]: CHAP authentication succeeded: FTTC2279959
May 29 23:35:29 westogre pppd[6226]: CHAP authentication succeeded
May 29 23:35:29 westogre pppd[6226]: peer from calling number 28:8A:1C:E9:C0:52 authorized
May 29 23:35:29 westogre pppd[6226]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 29 23:35:29 westogre pppd[6226]: sent [IPV6CP ConfReq id=0x1 <addr fe80::ed65:effc:4118:4180>]
May 29 23:35:30 westogre pppd[6226]: rcvd [IPCP ConfReq id=0x0 <addr 81.187.81.187>]
May 29 23:35:30 westogre pppd[6226]: sent [IPCP ConfAck id=0x0 <addr 81.187.81.187>]
May 29 23:35:31 westogre pppd[6226]: rcvd [IPCP ConfReq id=0x1 <addr 81.187.81.187>]
May 29 23:35:31 westogre pppd[6226]: sent [IPCP ConfAck id=0x1 <addr 81.187.81.187>]
May 29 23:35:32 westogre pppd[6226]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 29 23:35:32 westogre pppd[6226]: sent [IPV6CP ConfReq id=0x1 <addr fe80::ed65:effc:4118:4180>]
May 29 23:35:32 westogre pppd[6226]: rcvd [IPCP ConfNak id=0x1 <addr 81.x.x.x>]
May 29 23:35:32 westogre pppd[6226]: sent [IPCP ConfReq id=0x2 <addr 81.x.x.x>]
May 29 23:35:32 westogre pppd[6226]: rcvd [IPV6CP ConfAck id=0x1 <addr fe80::ed65:effc:4118:4180>]
May 29 23:35:32 westogre pppd[6226]: rcvd [IPCP ConfAck id=0x2 <addr 81.x.x.x>]
May 29 23:35:32 westogre pppd[6226]: local  IP address 81.x.x.x
May 29 23:35:32 westogre pppd[6226]: remote IP address 81.187.81.187
May 29 23:35:32 westogre pppd[6226]: Script /etc/ppp/ip-up started (pid 6276)
May 29 23:35:32 westogre pppd[6226]: rcvd [IPV6CP ConfReq id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 29 23:35:32 westogre pppd[6226]: sent [IPV6CP ConfAck id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 29 23:35:32 westogre pppd[6226]: local  LL address fe80::ed65:effc:4118:4180
May 29 23:35:32 westogre pppd[6226]: remote LL address fe80::0203:97ff:fe42:0000
May 29 23:35:32 westogre pppd[6226]: Script /etc/ppp/ipv6-up started (pid 6277)
May 29 23:35:32 westogre pppd[6226]: Script /etc/ppp/ipv6-up finished (pid 6277), status = 0x0
May 29 23:35:35 westogre pppd[6226]: Script /etc/ppp/ip-up finished (pid 6276), status = 0x0
So it looks like /etc/ppp/ip-up is the culprit. It runs these:

Code: Select all

/etc/ppp/ip-up.d # ls -al
total 40
drwxr-xr-x 2 root root 4096 May 19 22:58 .
drwxr-xr-x 8 root dip  4096 Mar  3 10:42 ..
-rwxr-xr-x 1 root root  902 Feb  4  2011 0000usepeerdns
-rwxr-xr-x 1 root root  515 Sep  7  2012 000resolvconf
-rwxr-xr-x 1 root root  204 May  2  2013 0clampmss
-rwxr-xr-x 1 root root 4024 Nov  4  2010 0dns-up
-rwxr-xr-x 1 root root  289 Jan 17 06:06 bind9
-rwxr-xr-x 1 root root  293 Jun 18  2007 exim4
-rwxr-xr-x 1 root root  391 Aug 14  2009 fetchmail
-rwxr-xr-x 1 root root 1120 Feb 18  2010 postfix
I have created /var/log/ppp-ipupdown.log per comments in /etc/ppp/ip-up and will try again tomorrow [it's late...].



/etc/network/interfaces:

Code: Select all

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

# The loopback network interface
auto lo
iface lo inet loopback

iface eth5 inet manual
iface eth7 inet manual
# br0, LAN
auto br0
iface br0 inet static
        bridge_ports eth5 eth7 enp3s0f0 enp3s0f1 enp4s0f0 enp4s0f1
                address 192.168.1.3
                netmask 255.255.255.0
                bridge_stp on
                bridge_waitport 0
#               bridge_fd 0

iface br0 inet6 static
        address 2001:x:x:x:1
        netmask 64

auto ppp0
iface ppp0 inet ppp
        pre-up /bin/ip link set eth3 mtu 1508
        pre-up /bin/ip link set eth3 up
        provider provider
#       post-up sh /root/firewall/delayed-post-up.sh
        post-up sleep 10
delayed-post-up.sh has iptables rules in it.

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#14 Post by troffasky »

I have created /var/log/ppp-ipupdown.log per comments in /etc/ppp/ip-up and will try again tomorrow [it's late...].
Well that wasn't any use...exactly one line got logged to /var/log/ppp-ipupdown.log [my IP, peer's IP].
What I have noticed, however, is that the on-boot pppd events don't mention any of the scripts and the user when it doesn't work is root and when it does work is alex. I wonder if there's a problem with the environment on boot?
On boot:

Code: Select all

May 30 08:26:12 westogre systemd[1]: session-9.scope: Killing process 6226 (pppd) with signal SIGTERM.
May 30 08:26:12 westogre pppd[6226]: Terminating on signal 15
May 30 08:27:42 westogre pppd[1753]: Plugin rp-pppoe.so loaded.
May 30 08:27:42 westogre pppd[1762]: pppd 2.4.7 started by root, uid 0
May 30 08:27:42 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 30 08:27:42 westogre pppd[1762]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 30 08:27:42 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc]
May 30 08:27:46 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 30 08:27:46 westogre pppd[1762]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 30 08:27:46 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc]
May 30 08:27:47 westogre pppd[1762]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
May 30 08:27:47 westogre pppd[1762]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 08:27:47 westogre pppd[1762]:  [AC-name nge002.bla-re0] [PPP-max-payload  05 dc] [service-name] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:47 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADR session 0x0 length 30
May 30 08:27:47 westogre pppd[1762]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 08:27:47 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:47 westogre pppd[1762]: Recv PPPOE Discovery V1T1 PADS session 0x9a4 length 48
May 30 08:27:47 westogre pppd[1762]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 08:27:47 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc] [AC-name nge002.bla-re0] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:47 westogre pppd[1762]: PADS: Service-Name: ''
May 30 08:27:47 westogre pppd[1762]: PPP session is 2468
May 30 08:27:47 westogre pppd[1762]: Connected to 28:8a:1c:e9:c0:52 via interface eth3
May 30 08:27:47 westogre pppd[1762]: using channel 1
May 30 08:27:47 westogre pppd[1762]: Using interface ppp0
May 30 08:27:47 westogre pppd[1762]: Connect: ppp0 <--> eth3
May 30 08:27:47 westogre pppd[1762]: sent [LCP ConfReq id=0x1 <magic 0xb8b305e0>]
May 30 08:27:47 westogre pppd[1762]: rcvd [LCP ConfReq id=0xf0 <auth chap MD5> <magic 0x1bfbb9ef>]
May 30 08:27:47 westogre pppd[1762]: sent [LCP ConfAck id=0xf0 <auth chap MD5> <magic 0x1bfbb9ef>]
May 30 08:27:47 westogre pppd[1762]: rcvd [LCP ConfAck id=0x1 <magic 0xb8b305e0>]
May 30 08:27:47 westogre pppd[1762]: sent [LCP EchoReq id=0x0 magic=0xb8b305e0]
May 30 08:27:47 westogre pppd[1762]: rcvd [LCP EchoRep id=0x0 magic=0x1bfbb9ef]
May 30 08:27:47 westogre pppd[1762]: rcvd [CHAP Challenge id=0xfc <b7612c457e6a6c844084dfc21d06bc2a0feaec808bb2d85e11decce57bd6fe8e2ba3f209f48e512c78b2c65a>, name = "nge002.bla"]
May 30 08:27:47 westogre pppd[1762]: sent [CHAP Response id=0xfc <fbfc56de5d1763e3924f978a95ef5c36>, name = "user@name"]
May 30 08:27:47 westogre pppd[1762]: rcvd [CHAP Success id=0xfc "FTTC2279959"]
May 30 08:27:47 westogre pppd[1762]: CHAP authentication succeeded: FTTC2279959
May 30 08:27:47 westogre pppd[1762]: CHAP authentication succeeded
May 30 08:27:47 westogre pppd[1762]: peer from calling number 28:8A:1C:E9:C0:52 authorized
May 30 08:27:47 westogre pppd[1762]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 30 08:27:47 westogre pppd[1762]: sent [IPV6CP ConfReq id=0x1 <addr fe80::852c:e46a:d303:e0dd>]
May 30 08:27:48 westogre pppd[1762]: rcvd [IPCP ConfReq id=0x0 <addr 81.187.81.187>]
May 30 08:27:48 westogre pppd[1762]: sent [IPCP ConfAck id=0x0 <addr 81.187.81.187>]
May 30 08:27:49 westogre pppd[1762]: Terminating on signal 15
May 30 08:27:49 westogre pppd[1762]: sent [LCP TermReq id=0x2 "User request"]
May 30 08:27:50 westogre pppd[1762]: rcvd [LCP TermReq id=0x9]
May 30 08:27:50 westogre pppd[1762]: sent [LCP TermAck id=0x9]
May 30 08:27:50 westogre pppd[1762]: Modem hangup
May 30 08:27:50 westogre pppd[1762]: Connection terminated.
May 30 08:27:50 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADT session 0x9a4 length 20
May 30 08:27:50 westogre pppd[1762]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 08:27:50 westogre pppd[1762]:  [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:50 westogre pppd[1762]: Sent PADT
May 30 08:27:50 westogre pppd[1762]: Exit.
ifdown ppp0 ; ifup ppp0:

Code: Select all

May 30 08:26:12 westogre systemd[1]: session-9.scope: Killing process 6226 (pppd) with signal SIGTERM.
May 30 08:26:12 westogre pppd[6226]: Terminating on signal 15
May 30 08:27:42 westogre pppd[1753]: Plugin rp-pppoe.so loaded.
May 30 08:27:42 westogre pppd[1762]: pppd 2.4.7 started by root, uid 0
May 30 08:27:42 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 30 08:27:42 westogre pppd[1762]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 30 08:27:42 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc]
May 30 08:27:46 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 30 08:27:46 westogre pppd[1762]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 30 08:27:46 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc]
May 30 08:27:47 westogre pppd[1762]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
May 30 08:27:47 westogre pppd[1762]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 08:27:47 westogre pppd[1762]:  [AC-name nge002.bla-re0] [PPP-max-payload  05 dc] [service-name] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:47 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADR session 0x0 length 30
May 30 08:27:47 westogre pppd[1762]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 08:27:47 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:47 westogre pppd[1762]: Recv PPPOE Discovery V1T1 PADS session 0x9a4 length 48
May 30 08:27:47 westogre pppd[1762]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 08:27:47 westogre pppd[1762]:  [service-name] [PPP-max-payload  05 dc] [AC-name nge002.bla-re0] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:47 westogre pppd[1762]: PADS: Service-Name: ''
May 30 08:27:47 westogre pppd[1762]: PPP session is 2468
May 30 08:27:47 westogre pppd[1762]: Connected to 28:8a:1c:e9:c0:52 via interface eth3
May 30 08:27:47 westogre pppd[1762]: using channel 1
May 30 08:27:47 westogre pppd[1762]: Using interface ppp0
May 30 08:27:47 westogre pppd[1762]: Connect: ppp0 <--> eth3
May 30 08:27:47 westogre pppd[1762]: sent [LCP ConfReq id=0x1 <magic 0xb8b305e0>]
May 30 08:27:47 westogre pppd[1762]: rcvd [LCP ConfReq id=0xf0 <auth chap MD5> <magic 0x1bfbb9ef>]
May 30 08:27:47 westogre pppd[1762]: sent [LCP ConfAck id=0xf0 <auth chap MD5> <magic 0x1bfbb9ef>]
May 30 08:27:47 westogre pppd[1762]: rcvd [LCP ConfAck id=0x1 <magic 0xb8b305e0>]
May 30 08:27:47 westogre pppd[1762]: sent [LCP EchoReq id=0x0 magic=0xb8b305e0]
May 30 08:27:47 westogre pppd[1762]: rcvd [LCP EchoRep id=0x0 magic=0x1bfbb9ef]
May 30 08:27:47 westogre pppd[1762]: rcvd [CHAP Challenge id=0xfc <b7612c457e6a6c844084dfc21d06bc2a0feaec808bb2d85e11decce57bd6fe8e2ba3f209f48e512c78b2c65a>, name = "nge002.bla"]
May 30 08:27:47 westogre pppd[1762]: sent [CHAP Response id=0xfc <fbfc56de5d1763e3924f978a95ef5c36>, name = "user@name"]
May 30 08:27:47 westogre pppd[1762]: rcvd [CHAP Success id=0xfc "FTTC2279959"]
May 30 08:27:47 westogre pppd[1762]: CHAP authentication succeeded: FTTC2279959
May 30 08:27:47 westogre pppd[1762]: CHAP authentication succeeded
May 30 08:27:47 westogre pppd[1762]: peer from calling number 28:8A:1C:E9:C0:52 authorized
May 30 08:27:47 westogre pppd[1762]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 30 08:27:47 westogre pppd[1762]: sent [IPV6CP ConfReq id=0x1 <addr fe80::852c:e46a:d303:e0dd>]
May 30 08:27:48 westogre pppd[1762]: rcvd [IPCP ConfReq id=0x0 <addr 81.187.81.187>]
May 30 08:27:48 westogre pppd[1762]: sent [IPCP ConfAck id=0x0 <addr 81.187.81.187>]
May 30 08:27:49 westogre pppd[1762]: Terminating on signal 15
May 30 08:27:49 westogre pppd[1762]: sent [LCP TermReq id=0x2 "User request"]
May 30 08:27:50 westogre pppd[1762]: rcvd [LCP TermReq id=0x9]
May 30 08:27:50 westogre pppd[1762]: sent [LCP TermAck id=0x9]
May 30 08:27:50 westogre pppd[1762]: Modem hangup
May 30 08:27:50 westogre pppd[1762]: Connection terminated.
May 30 08:27:50 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADT session 0x9a4 length 20
May 30 08:27:50 westogre pppd[1762]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 08:27:50 westogre pppd[1762]:  [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:50 westogre pppd[1762]: Sent PADT
May 30 08:27:50 westogre pppd[1762]: Exit.

Code: Select all

# systemctl status networking
* networking.service - Raise network interfaces
   Loaded: loaded (/lib/systemd/system/networking.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Wed 2018-05-30 08:27:50 BST; 22min ago
     Docs: man:interfaces(5)
  Process: 1684 ExecStart=/sbin/ifup -a --read-environment (code=exited, status=1/FAILURE)
 Main PID: 1684 (code=exited, status=1/FAILURE)

May 30 08:27:50 westogre pppd[1762]: sent [LCP TermAck id=0x9]
May 30 08:27:50 westogre pppd[1762]: Modem hangup
May 30 08:27:50 westogre pppd[1762]: Connection terminated.
May 30 08:27:50 westogre pppd[1762]: Send PPPOE Discovery V1T1 PADT session 0x9a4 length 20
May 30 08:27:50 westogre pppd[1762]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 08:27:50 westogre pppd[1762]:  [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 08:27:50 westogre pppd[1762]: Sent PADT
May 30 08:27:50 westogre pppd[1762]: Exit.
May 30 08:27:50 westogre systemd[1]: networking.service: Failed with result 'exit-code'.
May 30 08:27:50 westogre systemd[1]: Failed to start Raise network interfaces.
I have put VERBOSE=yes in /etc/default/networking and will give it another reboot.

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#15 Post by troffasky »

ifup now logs more events.

On boot. I can see my "post-up" firewall script is called before the first PADI packet is even sent!
The problem occurs at 22:39:13 and is probably in one of:
/etc/network/if-up.d/bind9
/etc/network/if-up.d/ethtool
/etc/network/if-up.d/mountnfs
/etc/network/if-up.d/ntpdate
/etc/network/if-up.d/openssh-server
but why would they be run twice?

Code: Select all

May 30 22:39:06 westogre systemd[1]: Started Helper to synchronize boot up for ifupdown.
May 30 22:39:06 westogre ifup[1612]: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/bridge
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/ethtool
May 30 22:39:06 westogre ifup[1612]: ifup: configuring interface lo=lo (inet)
May 30 22:39:06 westogre ifup[1612]: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/bridge
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/ethtool
May 30 22:39:06 westogre ifup[1612]: /bin/ip link set dev lo up
May 30 22:39:06 westogre ifup[1612]: /bin/run-parts --exit-on-error --verbose /etc/network/if-up.d
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/bind9
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/ethtool
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/mountnfs
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/ntpdate
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/openssh-server
May 30 22:39:06 westogre ifup[1612]: ifup: configuring interface br0=br0 (inet)
May 30 22:39:06 westogre ifup[1612]: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/bridge
May 30 22:39:06 westogre ifup[1612]: interface eth5 does not exist!
May 30 22:39:06 westogre ifup[1612]: Waiting for br0 to get ready (MAXWAIT is 32 seconds).
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/ethtool
May 30 22:39:06 westogre ifup[1612]: /bin/ip addr add 192.168.1.3/255.255.255.0 broadcast 192.168.1.255 #011  dev br0 label br0
May 30 22:39:06 westogre ifup[1612]: RTNETLINK answers: File exists
May 30 22:39:06 westogre ifup[1612]: ifup: failed to bring up br0
May 30 22:39:06 westogre ifup[1612]: ifup: configuring interface ppp0=ppp0 (inet)
May 30 22:39:06 westogre ifup[1612]: /bin/ip link set eth3 mtu 1508
May 30 22:39:06 westogre ifup[1612]: /bin/ip link set eth3 up
May 30 22:39:06 westogre ifup[1612]: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/bridge
May 30 22:39:06 westogre ifup[1612]: run-parts: executing /etc/network/if-pre-up.d/ethtool
May 30 22:39:06 westogre ifup[1612]: /usr/bin/pon provider
May 30 22:39:06 westogre pppd[1676]: Plugin rp-pppoe.so loaded.
May 30 22:39:06 westogre ifup[1612]: Plugin rp-pppoe.so loaded.
May 30 22:39:06 westogre pppd[1690]: pppd 2.4.7 started by root, uid 0
May 30 22:39:06 westogre ifup[1612]: sh /root/firewall/delayed-post-up.sh
May 30 22:39:06 westogre pppd[1690]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 30 22:39:06 westogre pppd[1690]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 30 22:39:06 westogre pppd[1690]:  [service-name] [PPP-max-payload  05 dc]
May 30 22:39:10 westogre pppd[1690]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 30 22:39:10 westogre pppd[1690]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 30 22:39:10 westogre pppd[1690]:  [service-name] [PPP-max-payload  05 dc]
May 30 22:39:10 westogre pppd[1690]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
May 30 22:39:10 westogre pppd[1690]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 22:39:10 westogre pppd[1690]:  [AC-name nge002.bla-re0] [PPP-max-payload  05 dc] [service-name] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 22:39:10 westogre pppd[1690]: Send PPPOE Discovery V1T1 PADR session 0x0 length 30
May 30 22:39:10 westogre pppd[1690]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 22:39:10 westogre pppd[1690]:  [service-name] [PPP-max-payload  05 dc] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 22:39:10 westogre pppd[1690]: Recv PPPOE Discovery V1T1 PADS session 0x2ea length 48
May 30 22:39:10 westogre pppd[1690]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 22:39:10 westogre pppd[1690]:  [service-name] [PPP-max-payload  05 dc] [AC-name nge002.bla-re0] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 22:39:10 westogre pppd[1690]: PADS: Service-Name: ''
May 30 22:39:10 westogre pppd[1690]: PPP session is 746
May 30 22:39:10 westogre pppd[1690]: Connected to 28:8a:1c:e9:c0:52 via interface eth3
May 30 22:39:10 westogre pppd[1690]: using channel 1
May 30 22:39:10 westogre pppd[1690]: Using interface ppp0
May 30 22:39:10 westogre pppd[1690]: Connect: ppp0 <--> eth3
May 30 22:39:10 westogre pppd[1690]: sent [LCP ConfReq id=0x1 <magic 0x84786a1d>]
May 30 22:39:10 westogre pppd[1690]: rcvd [LCP ConfReq id=0xb5 <auth chap MD5> <magic 0x1b8e943f>]
May 30 22:39:10 westogre pppd[1690]: sent [LCP ConfAck id=0xb5 <auth chap MD5> <magic 0x1b8e943f>]
May 30 22:39:10 westogre pppd[1690]: rcvd [LCP ConfAck id=0x1 <magic 0x84786a1d>]
May 30 22:39:10 westogre pppd[1690]: sent [LCP EchoReq id=0x0 magic=0x84786a1d]
May 30 22:39:10 westogre pppd[1690]: rcvd [LCP EchoRep id=0x0 magic=0x1b8e943f]
May 30 22:39:10 westogre pppd[1690]: rcvd [CHAP Challenge id=0xaf <9a0b126e48a68dbe7887ce05>, name = "nge002.bla"]
May 30 22:39:10 westogre pppd[1690]: sent [CHAP Response id=0xaf <9d911f147911b1bdfbb5cce58d878cd5>, name = "user@name"]
May 30 22:39:11 westogre pppd[1690]: rcvd [CHAP Success id=0xaf "FTTC2279959"]
May 30 22:39:11 westogre pppd[1690]: CHAP authentication succeeded: FTTC2279959
May 30 22:39:11 westogre pppd[1690]: CHAP authentication succeeded
May 30 22:39:11 westogre pppd[1690]: peer from calling number 28:8A:1C:E9:C0:52 authorized
May 30 22:39:11 westogre pppd[1690]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 30 22:39:11 westogre pppd[1690]: sent [IPV6CP ConfReq id=0x1 <addr fe80::80a8:3ad4:d882:a0a2>]
May 30 22:39:11 westogre pppd[1690]: rcvd [IPCP ConfNak id=0x1 <addr 81.x.x.x>]
May 30 22:39:11 westogre pppd[1690]: sent [IPCP ConfReq id=0x2 <addr 81.x.x.x>]
May 30 22:39:11 westogre pppd[1690]: rcvd [IPV6CP ConfAck id=0x1 <addr fe80::80a8:3ad4:d882:a0a2>]
May 30 22:39:11 westogre pppd[1690]: rcvd [IPCP ConfAck id=0x2 <addr 81.x.x.x>]
May 30 22:39:11 westogre pppd[1690]: rcvd [IPCP ConfReq id=0x0 <addr 81.187.81.187>]
May 30 22:39:11 westogre pppd[1690]: sent [IPCP ConfAck id=0x0 <addr 81.187.81.187>]
May 30 22:39:11 westogre pppd[1690]: local  IP address 81.x.x.x
May 30 22:39:11 westogre pppd[1690]: remote IP address 81.187.81.187
May 30 22:39:11 westogre pppd[1690]: Script /etc/ppp/ip-up started (pid 1894)
May 30 22:39:11 westogre pppd[1690]: rcvd [IPV6CP ConfReq id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 30 22:39:11 westogre pppd[1690]: sent [IPV6CP ConfAck id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 30 22:39:11 westogre pppd[1690]: local  LL address fe80::80a8:3ad4:d882:a0a2
May 30 22:39:11 westogre pppd[1690]: remote LL address fe80::0203:97ff:fe42:0000
May 30 22:39:11 westogre pppd[1690]: Script /etc/ppp/ipv6-up started (pid 1896)
May 30 22:39:12 westogre pppd[1690]: Script /etc/ppp/ipv6-up finished (pid 1896), status = 0x0
May 30 22:39:13 westogre ifup[1612]: /bin/run-parts --exit-on-error --verbose /etc/network/if-up.d
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/bind9
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/ethtool
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/mountnfs
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/ntpdate
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/openssh-server
May 30 22:39:13 westogre ifup[1612]: /bin/run-parts --exit-on-error --verbose /etc/network/if-up.d
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/bind9
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/ethtool
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/mountnfs
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/ntpdate
May 30 22:39:13 westogre ifup[1612]: run-parts: executing /etc/network/if-up.d/openssh-server
May 30 22:39:13 westogre pppd[1690]: Terminating on signal 15
May 30 22:39:13 westogre pppd[1690]: Connect time 0.1 minutes.
May 30 22:39:13 westogre pppd[1690]: Sent 318 bytes, received 14 bytes.
May 30 22:39:13 westogre pppd[1690]: Script /etc/ppp/ipv6-down started (pid 2048)
May 30 22:39:13 westogre pppd[1690]: sent [LCP TermReq id=0x2 "User request"]
May 30 22:39:13 westogre pppd[1690]: Child process /etc/ppp/ip-up (pid 1894) terminated with signal 15
May 30 22:39:13 westogre pppd[1690]: Script /etc/ppp/ip-down started (pid 2049)
May 30 22:39:13 westogre pppd[1690]: rcvd [LCP TermAck id=0x2]
May 30 22:39:13 westogre pppd[1690]: Connection terminated.
May 30 22:39:13 westogre pppd[1690]: Connect time 0.1 minutes.
May 30 22:39:13 westogre pppd[1690]: Sent 318 bytes, received 14 bytes.
May 30 22:39:13 westogre pppd[1690]: Send PPPOE Discovery V1T1 PADT session 0x2ea length 20
May 30 22:39:13 westogre pppd[1690]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 22:39:13 westogre pppd[1690]:  [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 22:39:13 westogre pppd[1690]: Sent PADT
May 30 22:39:13 westogre pppd[1690]: Script /etc/ppp/ipv6-down finished (pid 2048), status = 0x0
May 30 22:39:13 westogre pppd[1690]: Waiting for 1 child processes...
May 30 22:39:13 westogre pppd[1690]:   script /etc/ppp/ip-down, pid 2049
May 30 22:39:13 westogre pppd[1690]: Script /etc/ppp/ip-down finished (pid 2049), status = 0x1
May 30 22:39:13 westogre pppd[1690]: Exit.

Manually, after boot. ifup doesn't log any debug events when I do ifdown/ifup?

Code: Select all

May 30 22:45:12 westogre pppd[8902]: Plugin rp-pppoe.so loaded.
May 30 22:45:12 westogre pppd[8907]: pppd 2.4.7 started by alex, uid 0
May 30 22:45:12 westogre pppd[8907]: Send PPPOE Discovery V1T1 PADI session 0x0 length 10
May 30 22:45:12 westogre pppd[8907]:  dst ff:ff:ff:ff:ff:ff  src 00:19:99:ed:01:9a
May 30 22:45:12 westogre pppd[8907]:  [service-name] [PPP-max-payload  05 dc]
May 30 22:45:12 westogre pppd[8907]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
May 30 22:45:12 westogre pppd[8907]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 22:45:12 westogre pppd[8907]:  [AC-name nge002.bla-re0] [PPP-max-payload  05 dc] [service-name] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 22:45:12 westogre pppd[8907]: Send PPPOE Discovery V1T1 PADR session 0x0 length 30
May 30 22:45:12 westogre pppd[8907]:  dst 28:8a:1c:e9:c0:52  src 00:19:99:ed:01:9a
May 30 22:45:12 westogre pppd[8907]:  [service-name] [PPP-max-payload  05 dc] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 22:45:12 westogre pppd[8907]: Recv PPPOE Discovery V1T1 PADS session 0x9c7 length 48
May 30 22:45:12 westogre pppd[8907]:  dst 00:19:99:ed:01:9a  src 28:8a:1c:e9:c0:52
May 30 22:45:12 westogre pppd[8907]:  [service-name] [PPP-max-payload  05 dc] [AC-name nge002.bla-re0] [AC-cookie  33 58 9a 5b 57 42 46 f7 fc e5 5e 6f d0 b3 47 8c]
May 30 22:45:12 westogre pppd[8907]: PADS: Service-Name: ''
May 30 22:45:12 westogre pppd[8907]: PPP session is 2503
May 30 22:45:12 westogre pppd[8907]: Connected to 28:8a:1c:e9:c0:52 via interface eth3
May 30 22:45:12 westogre pppd[8907]: using channel 2
May 30 22:45:12 westogre pppd[8907]: Using interface ppp0
May 30 22:45:12 westogre pppd[8907]: Connect: ppp0 <--> eth3
May 30 22:45:12 westogre pppd[8907]: sent [LCP ConfReq id=0x1 <magic 0x738906af>]
May 30 22:45:13 westogre pppd[8907]: rcvd [LCP ConfReq id=0xef <auth chap MD5> <magic 0x106e9070>]
May 30 22:45:13 westogre pppd[8907]: sent [LCP ConfAck id=0xef <auth chap MD5> <magic 0x106e9070>]
May 30 22:45:13 westogre pppd[8907]: rcvd [LCP ConfAck id=0x1 <magic 0x738906af>]
May 30 22:45:13 westogre pppd[8907]: sent [LCP EchoReq id=0x0 magic=0x738906af]
May 30 22:45:13 westogre pppd[8907]: rcvd [CHAP Challenge id=0xb3 <466c7504f0fdf8ba>, name = "nge002.bla"]
May 30 22:45:13 westogre pppd[8907]: sent [CHAP Response id=0xb3 <eb257ae481bacc82747774032b6bee61>, name = "user@name"]
May 30 22:45:13 westogre pppd[8907]: rcvd [LCP EchoRep id=0x0 magic=0x106e9070]
May 30 22:45:13 westogre pppd[8907]: rcvd [CHAP Success id=0xb3 "FTTC2279959"]
May 30 22:45:13 westogre pppd[8907]: CHAP authentication succeeded: FTTC2279959
May 30 22:45:13 westogre pppd[8907]: CHAP authentication succeeded
May 30 22:45:13 westogre pppd[8907]: peer from calling number 28:8A:1C:E9:C0:52 authorized
May 30 22:45:13 westogre pppd[8907]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 30 22:45:13 westogre pppd[8907]: sent [IPV6CP ConfReq id=0x1 <addr fe80::a87e:907d:ba6e:4eb5>]
May 30 22:45:14 westogre pppd[8907]: rcvd [IPCP ConfReq id=0x0 <addr 81.187.81.187>]
May 30 22:45:14 westogre pppd[8907]: sent [IPCP ConfAck id=0x0 <addr 81.187.81.187>]
May 30 22:45:15 westogre pppd[8907]: rcvd [IPCP ConfReq id=0x1 <addr 81.187.81.187>]
May 30 22:45:15 westogre pppd[8907]: sent [IPCP ConfAck id=0x1 <addr 81.187.81.187>]
May 30 22:45:16 westogre pppd[8907]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 30 22:45:16 westogre pppd[8907]: sent [IPV6CP ConfReq id=0x1 <addr fe80::a87e:907d:ba6e:4eb5>]
May 30 22:45:16 westogre pppd[8907]: rcvd [IPCP ConfNak id=0x1 <addr 81.x.x.x>]
May 30 22:45:16 westogre pppd[8907]: sent [IPCP ConfReq id=0x2 <addr 81.x.x.x>]
May 30 22:45:16 westogre pppd[8907]: rcvd [IPV6CP ConfAck id=0x1 <addr fe80::a87e:907d:ba6e:4eb5>]
May 30 22:45:16 westogre pppd[8907]: rcvd [IPCP ConfAck id=0x2 <addr 81.x.x.x>]
May 30 22:45:16 westogre pppd[8907]: local  IP address 81.x.x.x
May 30 22:45:16 westogre pppd[8907]: remote IP address 81.187.81.187
May 30 22:45:16 westogre pppd[8907]: Script /etc/ppp/ip-up started (pid 10273)
May 30 22:45:16 westogre pppd[8907]: rcvd [IPV6CP ConfReq id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 30 22:45:16 westogre pppd[8907]: sent [IPV6CP ConfAck id=0x0 <addr fe80::0203:97ff:fe42:0000>]
May 30 22:45:16 westogre pppd[8907]: local  LL address fe80::a87e:907d:ba6e:4eb5
May 30 22:45:16 westogre pppd[8907]: remote LL address fe80::0203:97ff:fe42:0000
May 30 22:45:16 westogre pppd[8907]: Script /etc/ppp/ipv6-up started (pid 10281)
May 30 22:45:16 westogre pppd[8907]: Script /etc/ppp/ipv6-up finished (pid 10281), status = 0x0
May 30 22:45:18 westogre pppd[8907]: Script /etc/ppp/ip-up finished (pid 10273), status = 0x0


troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#16 Post by troffasky »

It seems like the sequence of events is different when it works to when it doesn't. When it doesn't work, "pon provider" appears. When it does work, it doesn't. So ifup ppp0 doesn't seem to bring up the PPP interface in the same way that the boot sequence does. How can I replicate what the boot sequence does without rebooting the whole system? Would "pon provider" be enough?

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#17 Post by troffasky »

networking.service runs "ifup -a --read-environment". So I've tried stopping networking, deleting the bridge then running this. I get the output

Waiting for DAD... Timed out
ifup: failed to bring up br0
Plugin rp-pppoe.so loaded.

But everything is actually working. The exit state of ifup is 1, so systemd is being "clever" and assuming things are broken, so tries to undo everything and kills pppd even though it's br0 that has the "problem"? Totally guessing here...

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#18 Post by troffasky »

Added -v to ifup command, and I can see the last thing that happens before br0 "failed" is that it runs /lib/ifupdown/settle-dad.sh. I have tried commenting out that whole script and guess what? ppp0 NOW STAYS UP ON BOOT!

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#19 Post by troffasky »

Here's the real fix for this: "dad-attempts 0" in the inet6 stanza for br0. Watching the boot sequence I can see that the DAD attempt is sent before the port has transitioned to forwarding so the whole thing is pointless as the neighbour discovery would never leave the interface.

troffasky
Posts: 37
Joined: 2017-11-05 11:00
Has thanked: 1 time
Been thanked: 1 time

Re: ppp0 doesn't stay connected on boot

#20 Post by troffasky »

And again...
This time, it was because I had uninstalled wireguard-tools but left the interface definition for wg0 in place. I don't understand why ppp0 is always the "victim" here. Perhaps the answer is to not use ifupdown to manage it.

Post Reply