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
ppp0 doesn't stay connected on boot
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: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.
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: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.
Re: ppp0 doesn't stay connected on boot
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:
so ifupdown doesn't actually consider ppp0 to be down.
Code: Select all
# ifup ppp0
ifup: interface ppp0 already configured
Re: ppp0 doesn't stay connected on boot
If I comment out the post-up action completely, it just drops the connection immediately:
Any ideas on further troubleshooting?
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
Re: ppp0 doesn't stay connected on boot
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 ranwhen required.
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
Re: ppp0 doesn't stay connected on boot
I suspect it's been like this all along but I reboot infrequently enough that I can't remember.debiman wrote:so are you saying it has worked for years, and now stopped working?
No internet until I ifdown/ifup.debiman wrote:what's actually happening, are you left without internet connection in the end, or does it settle eventually?
VDSL.debiman wrote:this is mobile broadband, yes?
Re: ppp0 doesn't stay connected on boot
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.troffasky wrote:
No internet until I ifdown/ifup.
VDSL.debiman wrote:this is mobile broadband, yes?
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.
-
- 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
Sorry for the delay, I missed your replies.
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 ?
@ arzgi : PPPoE is a commonly used protocol over xDSL links. That's what you use when the xDSL modem acts as a bridge.
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 ?troffasky wrote:If I comment out the post-up action completely, it just drops the connection immediately
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 ?
The status in ifupdown is an administrative status which changes only by running ifup and ifdown.troffasky wrote:so ifupdown doesn't actually consider ppp0 to be down.
@ arzgi : PPPoE is a commonly used protocol over xDSL links. That's what you use when the xDSL modem acts as a bridge.
Re: ppp0 doesn't stay connected on boot
Thanks p.H. I have newer used my router as a bridge, so I tend to think my setup is the normp.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.
Re: ppp0 doesn't stay connected on boot
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...???
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...???
-
- 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
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).
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).
Re: ppp0 doesn't stay connected on boot
pppd logs on boot:
Logs after ifdown ppp0 ; ifup ppp0:
So it looks like /etc/ppp/ip-up is the culprit. It runs these:
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:
delayed-post-up.sh has iptables rules in it.
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.
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
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
/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
Re: ppp0 doesn't stay connected on boot
Well that wasn't any use...exactly one line got logged to /var/log/ppp-ipupdown.log [my IP, peer's IP].I have created /var/log/ppp-ipupdown.log per comments in /etc/ppp/ip-up and will try again tomorrow [it's late...].
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.
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.
Re: ppp0 doesn't stay connected on boot
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?
Manually, after boot. ifup doesn't log any debug events when I do ifdown/ifup?
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
Re: ppp0 doesn't stay connected on boot
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?
Re: ppp0 doesn't stay connected on boot
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...
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...
Re: ppp0 doesn't stay connected on boot
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!
Re: ppp0 doesn't stay connected on boot
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.
Re: ppp0 doesn't stay connected on boot
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.
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.