Pppd killed on signal 15 after reconnect, repeatedly

Software SW help
1

Hello. I’m connected via FTTH using pppoe. My ISP disconnects me after 24 hours. After trying to reconnect pppd gets repeatedly being killed via SIGTERM. Today, it took ~5 minutes and 50 attempts to connect again.
Anyone’s got an idea what is happening and/or how can I get pppd or netifd to display more verbose messages to see it?

May 24 08:42:25 gw pppd[24888]: LCP terminated by peer
May 24 08:42:25 gw pppd[24888]: Connect time 1440.0 minutes.
May 24 08:42:25 gw pppd[24888]: Sent 257119211 bytes, received 4161234584 bytes.
May 24 08:42:25 gw netifd: Network device 'pppoe-wan' link is down
May 24 08:42:25 gw pppd[24888]: Modem hangup
May 24 08:42:25 gw pppd[24888]: Connection terminated.
May 24 08:42:25 gw netifd: Interface 'wan' has lost the connection
May 24 10:42:25 gw dnsmasq[25076]: no servers found in /tmp/resolv.conf.auto, will retry
May 24 08:42:25 gw pppd[24888]: Sent PADT
May 24 08:42:25 gw pppd[24888]: Exit.
May 24 08:42:25 gw netifd: Interface 'wan' is now down
May 24 10:42:25 gw kernel: [173354.562216] mvneta f1034000.ethernet eth2: Link is Down
May 24 08:42:25 gw netifd: Interface 'wan' is disabled
May 24 10:42:25 gw kernel: [173354.578680] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
May 24 10:42:25 gw kernel: [173354.680719] mvneta f1034000.ethernet eth2: PHY [f1072004.mdio-mii:01] driver [Marvell 88E1510]
May 24 10:42:25 gw kernel: [173354.699263] mvneta f1034000.ethernet eth2: configuring for phy/sgmii link mode
May 24 10:42:25 gw kernel: [173354.707072] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
May 24 08:42:25 gw netifd: Interface 'wan' is enabled
May 24 08:42:25 gw netifd: Interface 'wan' is setting up now
May 24 08:42:25 gw insmod: module is already loaded - slhc
May 24 08:42:25 gw insmod: module is already loaded - ppp_generic
May 24 08:42:25 gw insmod: module is already loaded - pppox
May 24 08:42:25 gw insmod: module is already loaded - pppoe
May 24 08:42:25 gw pppd[12507]: Plugin rp-pppoe.so loaded.
May 24 08:42:25 gw pppd[12507]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
May 24 08:42:25 gw pppd[12507]: pppd 2.4.7 started by root, uid 0
May 24 10:42:26 gw kernel: [173355.842793] mvneta f1034000.ethernet eth2: Link is Down
May 24 08:42:26 gw netifd: Network device 'eth2' link is down
May 24 08:42:26 gw netifd: Interface 'wan' has link connectivity loss
May 24 10:42:28 gw kernel: [173357.919518] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
May 24 08:42:28 gw netifd: Network device 'eth2' link is up
May 24 08:42:28 gw netifd: Interface 'wan' has link connectivity 
May 24 08:42:28 gw netifd: Interface 'wan' is setting up now
May 24 08:42:30 gw pppd[12507]: PPP session is 24380
May 24 08:42:30 gw pppd[12507]: Connected to 7c:ad:74:f2:2f:30 via interface eth2
May 24 10:42:30 gw kernel: [173359.901002] pppoe-wan: renamed from ppp0
May 24 08:42:31 gw pppd[12507]: Using interface pppoe-wan
May 24 08:42:31 gw pppd[12507]: Connect: pppoe-wan <--> eth2
May 24 08:42:31 gw pppd[12507]: Terminating on signal 15
May 24 08:42:31 gw pppd[12507]: Connection terminated.
May 24 08:42:31 gw pppd[12507]: Sent PADT
May 24 08:42:31 gw pppd[12507]: Exit.
May 24 08:42:31 gw netifd: Interface 'wan' is now down
May 24 10:42:31 gw kernel: [173360.015131] mvneta f1034000.ethernet eth2: Link is Down
May 24 10:42:31 gw kernel: [173360.032713] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
May 24 08:42:31 gw netifd: Interface 'wan' is disabled
May 24 10:42:31 gw kernel: [173360.149691] mvneta f1034000.ethernet eth2: PHY [f1072004.mdio-mii:01] driver [Marvell 88E1510]
May 24 10:42:31 gw kernel: [173360.160900] mvneta f1034000.ethernet eth2: configuring for phy/sgmii link mode
May 24 10:42:31 gw kernel: [173360.168420] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
May 24 08:42:31 gw netifd: Interface 'wan' is enabled
May 24 08:42:31 gw netifd: Interface 'wan' is setting up now
May 24 08:42:31 gw insmod: module is already loaded - slhc
May 24 08:42:31 gw insmod: module is already loaded - ppp_generic
May 24 08:42:31 gw insmod: module is already loaded - pppox
May 24 08:42:31 gw insmod: module is already loaded - pppoe
May 24 08:42:31 gw pppd[12927]: Plugin rp-pppoe.so loaded.
May 24 08:42:31 gw pppd[12927]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
May 24 08:42:31 gw pppd[12927]: pppd 2.4.7 started by root, uid 0
May 24 10:42:32 gw kernel: [173361.282451] mvneta f1034000.ethernet eth2: Link is Down
May 24 08:42:32 gw netifd: Network device 'eth2' link is down
May 24 08:42:32 gw netifd: Interface 'wan' has link connectivity loss
May 24 08:42:34 gw netifd: Network device 'eth2' link is up
May 24 08:42:34 gw netifd: Interface 'wan' has link connectivity 
May 24 08:42:34 gw netifd: Interface 'wan' is setting up now
May 24 10:42:34 gw kernel: [173363.359125] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
May 24 08:42:35 gw kresd[12481]: [priming] cannot resolve address 'g.root-servers.net.', type: 1
May 24 08:42:35 gw kresd[12481]: [priming] cannot resolve address 'f.root-servers.net.', type: 1
May 24 08:42:35 gw kresd[12481]: [priming] cannot resolve address 'e.root-servers.net.', type: 28
May 24 08:42:36 gw pppd[12927]: PPP session is 24411
May 24 08:42:36 gw pppd[12927]: Connected to 7c:ad:74:f2:2f:30 via interface eth2
May 24 10:42:36 gw kernel: [173365.374699] pppoe-wan: renamed from ppp0
May 24 08:42:36 gw pppd[12927]: Using interface pppoe-wan
May 24 08:42:36 gw pppd[12927]: Connect: pppoe-wan <--> eth2
May 24 08:42:36 gw pppd[12927]: Terminating on signal 15
May 24 08:42:36 gw pppd[12927]: Connection terminated.
May 24 08:42:36 gw pppd[12927]: Sent PADT
May 24 08:42:36 gw pppd[12927]: Exit.
May 24 08:42:36 gw netifd: Interface 'wan' is now down
2

There are some known issues atm:

1 Like
3

For pppd in /etc/config/network

config interface 'wan'
	option pppd_options 'debug kdebug 7'

For netifd modify /etc/init.d/network

procd_set_param command /sbin/netifd -l 5
procd_set_param stderr 1

There is a report about such Unreliable DSL (PPP) connection (#107) · Issues · Turris / Turris OS / Turris Build · GitLab but that pertains to xDSL connectivity and happening during boot time, hence could be unrelated.

There is also a linux kernel bug pertinent to ISP backend misconfiguration PPPoE disconnects every few hours - Network and Wireless Configuration - OpenWrt Forum

4

I have seen this one but looks unrelated. And even if it’d help, 10 seconds seems too much for me.

Thank you, applied. First I tred to modify /etc/ppp/options but this should have the same effect.

I have noticed this, but postes new topic just because I think is shouldn’t be related.
The workaround might work. but I hate when my ssh sessions timeout adter 10 seconds. Maybe 1-second sleep would be fine. But I prefer the debug output for now.

Thank you both for now

5

suggest to try/test also with pppd options maxfail 0 and passive

7

I don’t think they would help - pppd is getting killed and netifd restart the connection itself

8

Perhaps the debug logs will shed some light what triggers the SIGTERM. Worst case it might be caused by an

9

Hello

Reconnect issues

If you experience pppd crash loop after reboot or reconnect, it sounds really similar to linked PPP problem (topic, issue).

The problem is (probably) in some timing issues in OpenWrt, which Turris OS is based on. We were not able to track the cause of this problem down yet, however mentioned workaround with sleep 10 seems to work (and was applied in Turris OS 3.x as well).

BTW, sleep 10 is probably better than

This workaround is coming to Turris OS 5.0 (currently in HBT and soon to be released) and you would be able to configure the length of this sleep workaround in Turris OS 5.0.1.

If you decide to debug this problem more, we would appreciate any relevant findings. Feel free to add comments to the issue.

Disconnect issue

This sounds like an ISP problem but cannot tell without more details. Does this happens periodically after 24 hours?

I heard about some PPPD disconnecting issue once, but it happens irregularly in that case.

10

It might even be a feature. This is the default behavior of Deutsche Telekom residential lines in Germany, for example.

11

I haven’t explicitly asked the ISP but I only find this as a problem when it happens anytime and my sessions fail for so long. I don’t think it’s an ISP problem.
I didn’t have this problem with my former router and openwrt, neither 18.06 nor 19.07.

I had similar problem over a year ago, connection was correctly set up but no data went through.
That problem disappeared somehow a year ago and everything was okay.

looking at logs, around the time I’ve had this problem (2019/03/22) I have installed OpenWRT 18.06.02 (probably beta, I see release came on 2019/06/25).

12

Not since a long time. DT will reconnect every 180 days. Many resellers like O2/Telefonica however will reconnect the PPPoE session every 24 hours. But I agree PPPoE reconnections are not an abnormality per se, but should just work :wink:

1 Like
13

Oh… how it should be handled? Does a reconnection should happen without an outage?

14

After a PPPoE reconnect the user gets often/always a new IPv4 address and a new IPv6-prefix IIRC, so there certainly will be a short outage and all existing connections will be lost.
I guess the question is more how long does this outage need to be and should the PPP deamon shut itself down in the process ;). On stock OpenWrt master, the pppoe application stays up and running, querying the ppp-server periodically until a new connection can be made.
In an only slightly related matter, I note that there was a bugfix in the Linux kernel and OpenWrt master, so that PADTs for other MAC addresses than the PPPoE-terminating device’s will be ignored. These should, in theory, never be sent in the first place, but some users reported seen these and had their connection terminated erroneously.

1 Like
15

Thanks, I have missed this update. I know it was of an issue years ago, due to IPv6 prefixes changing (and therefore often renumbering events happening).

As for the outage, it definitely happens, but should last no more than the duration of reconnect_interval+connecting_time (time to connect from the first PADI packet to the moment IPCP/IPv6CP is up and traffic is routed) seconds. So something like one minute?

16

Which is not uncommon with

  • ISP not providing static IPv4|6 addresses but dynamic ones
  • ISP back-end utilising IPCP/IPv6CP instead of DHCPv4|6 for IPv4|6 provisioning

If the ISP deploys IPCP/IPv6CP instead of of DHCPv4|6 the outage does not constitute an actual signal outage on the line but a termination of the the current ppp session. In OpenWrt rp-ppppoe is plugged into pppd and with IPCP/IPv6CP on the ISP’s back-end the ppp daemon on the router requires to stay alive/active in order to receive the new IPv4|6 addresses through IPCP/IPv6CP in a new ppp session.

More like ~ 10 - 30 seconds, depending on:

  • line signal processing speed
  • ISP back-end processing speed
  • router processing speed

On xDSL connectivity, which is not applicable in this use case, it may take longer than fibre, taking the ATM sync process into account.

17

The patch is not scheduled to be backported to source kernel 4.14, only 4.19 | 5.4 | 5.6. Is there any indication that it will be backported into OpenWrt 19.x? Master is already based on kernel 5.4 and when 5.4.42 arrives it does include the patch already.

With rp-pppoe being plugged into ppp it is not distinguishable whether ppp or rp-pppoe is causing the SIGTERM. It is also noticeable that OpenWrt’s rp-pppoe version 3.1.2 is not in sync with the source development version 3.1.3.

Having looked into the source code of rp-pppoe there is no indication that

is printed/generated by rp-pppoe but rather by ppp ppp/pppd/main.c at master · ppp-project/ppp · GitHub

18

I have static IP asigned (ssh user). The reconnection should happen (semi-)immediately.
Unless something breaks and it takes few minutes to connect, which is this case I have reported.

19

hello there, maybe this helps…i also have ftth with pppoe. What works with me is to activate Force link in advanced network> WAN interface

"Force link X

Set interface properties regardless of the link carrier (If set, carrier sense events do not invoke hotplug handlers). "

20

OK, finally some debug results. I had i typo in config so no debug happened yesterday
This is disconnect message:

May 26 18:40:34 gw pppd[4914]: rcvd [LCP TermReq id=0x2]
May 26 18:40:34 gw pppd[4914]: LCP terminated by peer
May 26 18:40:34 gw pppd[4914]: Connect time 1440.0 minutes.
May 26 18:40:34 gw pppd[4914]: Sent 622325281 bytes, received 2367081982 bytes.
May 26 18:40:34 gw netifd: wan (4914): rcvd [LCP TermReq id=0x2]
May 26 18:40:34 gw netifd: wan (4914): LCP terminated by peer
May 26 18:40:34 gw netifd: wan (4914): Connect time 1440.0 minutes.
May 26 18:40:34 gw netifd: wan (4914): Sent 622325281 bytes, received 2367081982 bytes.
May 26 18:40:34 gw netifd: Network device ‘pppoe-wan’ link is down
May 26 18:40:34 gw pppd[4914]: Script /lib/netifd/ppp-down started (pid 12565)
May 26 18:40:34 gw pppd[4914]: sent [LCP TermAck id=0x2]
May 26 18:40:34 gw netifd: wan (4914): Script /lib/netifd/ppp-down started (pid 12565)
May 26 18:40:34 gw netifd: wan (4914): sent [LCP TermAck id=0x2]
May 26 18:40:34 gw pppd[4914]: Modem hangup
May 26 18:40:34 gw pppd[4914]: Connection terminated.
May 26 18:40:34 gw netifd: wan (4914): Modem hangup
May 26 18:40:34 gw netifd: wan (4914): Connection terminated.
May 26 18:40:34 gw netifd: Interface ‘wan’ has lost the connection
May 26 18:40:34 gw pppd[4914]: Send PPPOE Discovery V1T1 PADT session 0xaa16 length 20
May 26 18:40:34 gw pppd[4914]: dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:40:34 gw pppd[4914]: [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:34 gw pppd[4914]: Sent PADT
May 26 18:40:34 gw netifd: wan (4914): Send PPPOE Discovery V1T1 PADT session 0xaa16 length 20
May 26 18:40:34 gw netifd: wan (4914): dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:40:34 gw netifd: wan (4914): [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:34 gw netifd: wan (4914): Sent PADT
May 26 18:40:34 gw pppd[4914]: Script /lib/netifd/ppp-down finished (pid 12565), status = 0x1
May 26 18:40:34 gw pppd[4914]: Exit.
May 26 18:40:34 gw netifd: wan (4914): Script /lib/netifd/ppp-down finished (pid 12565), status = 0x1
May 26 18:40:35 gw netifd: Interface ‘wan’ is now down
May 26 20:40:35 gw kernel: [86418.002437] mvneta f1034000.ethernet eth2: Link is Down
May 26 18:40:35 gw netifd: Interface ‘wan’ is disabled
May 26 20:40:35 gw kernel: [86418.016309] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
May 26 18:40:35 gw netifd[2854]: syntax error. Last token seen: +
May 26 18:40:35 gw netifd[2854]: Garbled time

… this is the first attempt and at least next two, no visible differences, even file sizes look the same.

May 26 20:40:35 gw kernel: [86418.118694] mvneta f1034000.ethernet eth2: PHY [f1072004.mdio-mii:01] driver [Marvell 88E1510]
May 26 20:40:35 gw kernel: [86418.131402] mvneta f1034000.ethernet eth2: configuring for phy/sgmii link mode
May 26 20:40:35 gw kernel: [86418.139027] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
May 26 18:40:35 gw netifd: Interface ‘wan’ is enabled
May 26 18:40:35 gw netifd: Interface ‘wan’ is setting up now
May 26 18:40:35 gw insmod: module is already loaded - slhc
May 26 18:40:35 gw insmod: module is already loaded - ppp_generic
May 26 18:40:35 gw insmod: module is already loaded - pppox
May 26 18:40:35 gw insmod: module is already loaded - pppoe
May 26 18:40:35 gw pppd[12692]: Plugin rp-pppoe.so loaded.
May 26 18:40:35 gw pppd[12692]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
May 26 18:40:35 gw netifd: wan (12692): Plugin rp-pppoe.so loaded.
May 26 18:40:35 gw netifd: wan (12692): RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
May 26 18:40:35 gw pppd[12692]: pppd 2.4.7 started by root, uid 0
May 26 18:40:35 gw pppd[12692]: Send PPPOE Discovery V1T1 PADI session 0x0 length 4
May 26 18:40:35 gw pppd[12692]: dst ff:ff:ff:ff:ff:ff src d8:58:d7:00:xx:xx
May 26 18:40:35 gw pppd[12692]: [service-name]
May 26 18:40:35 gw netifd: wan (12692): Send PPPOE Discovery V1T1 PADI session 0x0 length 4
May 26 18:40:35 gw netifd: wan (12692): dst ff:ff:ff:ff:ff:ff src d8:58:d7:00:xx:xx
May 26 18:40:35 gw netifd: wan (12692): [service-name]
May 26 20:40:36 gw kernel: [86419.281442] mvneta f1034000.ethernet eth2: Link is Down
May 26 18:40:36 gw netifd: Network device ‘eth2’ link is down
May 26 18:40:36 gw netifd: Interface ‘wan’ has link connectivity loss
May 26 20:40:38 gw kernel: [86421.358125] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
May 26 18:40:38 gw netifd: Network device ‘eth2’ link is up
May 26 18:40:38 gw netifd: Interface ‘wan’ has link connectivity
May 26 18:40:38 gw netifd: Interface ‘wan’ is setting up now
May 26 18:40:40 gw pppd[12692]: Send PPPOE Discovery V1T1 PADI session 0x0 length 4
May 26 18:40:40 gw pppd[12692]: dst ff:ff:ff:ff:ff:ff src d8:58:d7:00:xx:xx
May 26 18:40:40 gw pppd[12692]: [service-name]
May 26 18:40:40 gw netifd: wan (12692): Send PPPOE Discovery V1T1 PADI session 0x0 length 4
May 26 18:40:40 gw netifd: wan (12692): dst ff:ff:ff:ff:ff:ff src d8:58:d7:00:xx:xx
May 26 18:40:40 gw netifd: wan (12692): [service-name]
May 26 18:40:40 gw pppd[12692]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 38
May 26 18:40:40 gw pppd[12692]: dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:40:40 gw pppd[12692]: [service-name] [AC-name BB-LNS-STL] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw netifd: wan (12692): Recv PPPOE Discovery V1T1 PADO session 0x0 length 38
May 26 18:40:40 gw pppd[12692]: Send PPPOE Discovery V1T1 PADR session 0x0 length 24
May 26 18:40:40 gw netifd: wan (12692): dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:40:40 gw pppd[12692]: dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:40:40 gw netifd: wan (12692): [service-name] [AC-name BB-LNS-STL] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw pppd[12692]: [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw netifd: wan (12692): Send PPPOE Discovery V1T1 PADR session 0x0 length 24
May 26 18:40:40 gw netifd: wan (12692): dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:40:40 gw netifd: wan (12692): [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw pppd[12692]: Recv PPPOE Discovery V1T1 PADS session 0x7d57 length 24
May 26 18:40:40 gw pppd[12692]: dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:40:40 gw pppd[12692]: [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw netifd: wan (12692): Recv PPPOE Discovery V1T1 PADS session 0x7d57 length 24
May 26 18:40:40 gw pppd[12692]: PADS: Service-Name: ‘’
May 26 18:40:40 gw netifd: wan (12692): dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:40:40 gw pppd[12692]: PPP session is 32087
May 26 18:40:40 gw netifd: wan (12692): [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw pppd[12692]: Connected to 7c:ad:74:f2:2f:30 via interface eth2
May 26 18:40:40 gw netifd: wan (12692): PADS: Service-Name: ‘’
May 26 18:40:40 gw netifd: wan (12692): PPP session is 32087
May 26 18:40:40 gw netifd: wan (12692): Connected to 7c:ad:74:f2:2f:30 via interface eth2
May 26 18:40:40 gw pppd[12692]: using channel 2
May 26 18:40:40 gw netifd: wan (12692): using channel 2
May 26 20:40:40 gw kernel: [86423.345918] pppoe-wan: renamed from ppp0
May 26 18:40:40 gw pppd[12692]: Using interface pppoe-wan
May 26 18:40:40 gw pppd[12692]: Connect: pppoe-wan <–> eth2
May 26 18:40:40 gw pppd[12692]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x333ee213>]
May 26 18:40:40 gw pppd[12692]: Terminating on signal 15
May 26 18:40:40 gw pppd[12692]: sent [LCP TermReq id=0x2 “User request”]
May 26 18:40:40 gw pppd[12692]: rcvd [LCP ConfReq id=0x1 <mru 1492> <magic 0xacf54fd0>]
May 26 18:40:40 gw pppd[12692]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x333ee213>]
May 26 18:40:40 gw pppd[12692]: rcvd [LCP TermAck id=0x2]
May 26 18:40:40 gw pppd[12692]: Connection terminated.
May 26 18:40:40 gw netifd: wan (12692): Using interface pppoe-wan
May 26 18:40:40 gw netifd: wan (12692): Connect: pppoe-wan <–> eth2
May 26 18:40:40 gw netifd: wan (12692): sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x333ee213>]
May 26 18:40:40 gw netifd: wan (12692): Terminating on signal 15
May 26 18:40:40 gw netifd: wan (12692): sent [LCP TermReq id=0x2 “User request”]
May 26 18:40:40 gw netifd: wan (12692): rcvd [LCP ConfReq id=0x1 <mru 1492> <magic 0xacf54fd0>]
May 26 18:40:40 gw netifd: wan (12692): rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x333ee213>]
May 26 18:40:40 gw netifd: wan (12692): rcvd [LCP TermAck id=0x2]
May 26 18:40:40 gw netifd: wan (12692): Connection terminated.
May 26 18:40:40 gw netifd: wan (12692): Using interface pppoe-wan
May 26 18:40:40 gw netifd: wan (12692): Connect: pppoe-wan <–> eth2
May 26 18:40:40 gw netifd: wan (12692): sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x333ee213>]
May 26 18:40:40 gw netifd: wan (12692): Terminating on signal 15
May 26 18:40:40 gw netifd: wan (12692): sent [LCP TermReq id=0x2 “User request”]
May 26 18:40:40 gw netifd: wan (12692): rcvd [LCP ConfReq id=0x1 <mru 1492> <magic 0xacf54fd0>]
May 26 18:40:40 gw netifd: wan (12692): rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x333ee213>]
May 26 18:40:40 gw netifd: wan (12692): rcvd [LCP TermAck id=0x2]
May 26 18:40:40 gw netifd: wan (12692): Connection terminated.
May 26 18:40:40 gw pppd[12692]: Send PPPOE Discovery V1T1 PADT session 0x7d57 length 20
May 26 18:40:40 gw pppd[12692]: dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:40:40 gw pppd[12692]: [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw pppd[12692]: Sent PADT
May 26 18:40:40 gw netifd: wan (12692): Send PPPOE Discovery V1T1 PADT session 0x7d57 length 20
May 26 18:40:40 gw netifd: wan (12692): dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:40:40 gw netifd: wan (12692): [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:40:40 gw netifd: wan (12692): Sent PADT
May 26 18:40:40 gw pppd[12692]: Exit.
May 26 18:40:40 gw netifd: Interface ‘wan’ is now down
May 26 20:40:40 gw kernel: [86423.453095] mvneta f1034000.ethernet eth2: Link is Down
May 26 20:40:40 gw kernel: [86423.470998] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
May 26 18:40:40 gw netifd: Interface ‘wan’ is disabled

… and finally the successful connect:

May 26 20:53:17 gw kernel: [87180.844628] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
May 26 20:53:18 gw kernel: [87180.948324] mvneta f1034000.ethernet eth2: PHY [f1072004.mdio-mii:01] driver [Marvell 88E1510]
May 26 20:53:18 gw kernel: [87180.962792] mvneta f1034000.ethernet eth2: configuring for phy/sgmii link mode
May 26 18:53:18 gw netifd: Interface ‘wan’ is enabled
May 26 18:53:18 gw netifd: Interface ‘wan’ is setting up now
May 26 18:53:18 gw netifd: Network device ‘eth2’ link is down
May 26 18:53:18 gw netifd: Interface ‘wan’ has link connectivity loss
May 26 18:53:18 gw insmod: module is already loaded - slhc
May 26 18:53:18 gw insmod: module is already loaded - ppp_generic
May 26 18:53:18 gw insmod: module is already loaded - pppox
May 26 18:53:18 gw insmod: module is already loaded - pppoe
May 26 18:53:18 gw netifd: wan (8561): Command failed: Permission denied
May 26 18:53:21 gw netifd: Network device ‘eth2’ link is up
May 26 18:53:21 gw netifd: Interface ‘wan’ has link connectivity
May 26 18:53:21 gw netifd: Interface ‘wan’ is setting up now
May 26 20:53:21 gw kernel: [87184.187540] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
May 26 18:53:21 gw insmod: module is already loaded - slhc
May 26 18:53:21 gw insmod: module is already loaded - ppp_generic
May 26 18:53:21 gw insmod: module is already loaded - pppox
May 26 18:53:21 gw insmod: module is already loaded - pppoe
May 26 18:53:21 gw pppd[8730]: Plugin rp-pppoe.so loaded.
May 26 18:53:21 gw netifd: wan (8730): Plugin rp-pppoe.so loaded.
May 26 18:53:21 gw pppd[8730]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
May 26 18:53:21 gw netifd: wan (8730): RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
May 26 18:53:21 gw pppd[8730]: pppd 2.4.7 started by root, uid 0
May 26 18:53:21 gw pppd[8730]: Send PPPOE Discovery V1T1 PADI session 0x0 length 4
May 26 18:53:21 gw netifd: wan (8730): Send PPPOE Discovery V1T1 PADI session 0x0 length 4
May 26 18:53:21 gw pppd[8730]: dst ff:ff:ff:ff:ff:ff src d8:58:d7:00:xx:xx
May 26 18:53:21 gw netifd: wan (8730): dst ff:ff:ff:ff:ff:ff src d8:58:d7:00:xx:xx
May 26 18:53:21 gw pppd[8730]: [service-name]
May 26 18:53:21 gw netifd: wan (8730): [service-name]
May 26 18:53:21 gw pppd[8730]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 38
May 26 18:53:21 gw netifd: wan (8730): Recv PPPOE Discovery V1T1 PADO session 0x0 length 38
May 26 18:53:21 gw pppd[8730]: dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:53:21 gw netifd: wan (8730): dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:53:21 gw pppd[8730]: [service-name] [AC-name BB-LNS-STL] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:53:21 gw netifd: wan (8730): [service-name] [AC-name BB-LNS-STL] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:53:21 gw pppd[8730]: Send PPPOE Discovery V1T1 PADR session 0x0 length 24
May 26 18:53:21 gw netifd: wan (8730): Send PPPOE Discovery V1T1 PADR session 0x0 length 24
May 26 18:53:21 gw pppd[8730]: dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:53:21 gw netifd: wan (8730): dst 7c:ad:74:f2:2f:30 src d8:58:d7:00:xx:xx
May 26 18:53:21 gw pppd[8730]: [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:53:21 gw netifd: wan (8730): [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:53:21 gw pppd[8730]: Recv PPPOE Discovery V1T1 PADS session 0x96b2 length 24
May 26 18:53:21 gw netifd: wan (8730): Recv PPPOE Discovery V1T1 PADS session 0x96b2 length 24
May 26 18:53:21 gw pppd[8730]: dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:53:21 gw netifd: wan (8730): dst d8:58:d7:00:xx:xx src 7c:ad:74:f2:2f:30
May 26 18:53:21 gw pppd[8730]: [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:53:21 gw netifd: wan (8730): [service-name] [AC-cookie aa f7 b9 0e 15 29 fc f2 c6 3e a6 6e 29 ef 58 80]
May 26 18:53:21 gw pppd[8730]: PADS: Service-Name: ‘’
May 26 18:53:21 gw netifd: wan (8730): PADS: Service-Name: ‘’
May 26 18:53:21 gw pppd[8730]: PPP session is 38578
May 26 18:53:21 gw netifd: wan (8730): PPP session is 38578
May 26 18:53:21 gw pppd[8730]: Connected to 7c:ad:74:f2:2f:30 via interface eth2
May 26 18:53:21 gw netifd: wan (8730): Connected to 7c:ad:74:f2:2f:30 via interface eth2
May 26 18:53:21 gw pppd[8730]: using channel 141
May 26 18:53:21 gw netifd: wan (8730): using channel 141
May 26 20:53:21 gw kernel: [87184.378042] pppoe-wan: renamed from ppp0
May 26 18:53:21 gw pppd[8730]: Using interface pppoe-wan
May 26 18:53:21 gw pppd[8730]: Connect: pppoe-wan <–> eth2
May 26 18:53:21 gw pppd[8730]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x14de1afa>]
May 26 18:53:21 gw netifd: wan (8730): Using interface pppoe-wan
May 26 18:53:21 gw netifd: wan (8730): Connect: pppoe-wan <–> eth2
May 26 18:53:21 gw netifd: wan (8730): sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x14de1afa>]
May 26 18:53:21 gw pppd[8730]: rcvd [LCP ConfReq id=0x1 <mru 1492> <magic 0xad012a11>]
May 26 18:53:21 gw pppd[8730]: sent [LCP ConfAck id=0x1 <mru 1492> <magic 0xad012a11>]
May 26 18:53:21 gw pppd[8730]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x14de1afa>]
May 26 18:53:21 gw pppd[8730]: sent [LCP EchoReq id=0x0 magic=0x14de1afa]
May 26 18:53:21 gw pppd[8730]: sent [PAP AuthReq id=0x1 user=“xxx” password=]
May 26 18:53:21 gw netifd: wan (8730): rcvd [LCP ConfReq id=0x1 <mru 1492> <magic 0xad012a11>]
May 26 18:53:21 gw pppd[8730]: rcvd [LCP EchoRep id=0x0 magic=0xad012a11]
May 26 18:53:21 gw netifd: wan (8730): sent [LCP ConfAck id=0x1 <mru 1492> <magic 0xad012a11>]
May 26 18:53:21 gw netifd: wan (8730): rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x14de1afa>]
May 26 18:53:21 gw netifd: wan (8730): sent [LCP EchoReq id=0x0 magic=0x14de1afa]
May 26 18:53:21 gw netifd: wan (8730): sent [PAP AuthReq id=0x1 user=“xxx” password=]
May 26 18:53:21 gw netifd: wan (8730): rcvd [LCP EchoRep id=0x0 magic=0xad012a11]
May 26 18:53:21 gw pppd[8730]: rcvd [PAP AuthAck id=0x1 “”]
May 26 18:53:21 gw pppd[8730]: PAP authentication succeeded
May 26 18:53:21 gw netifd: wan (8730): peer from calling number 7C:AD:74:F2:2F:30 authorized
May 26 18:53:21 gw pppd[8730]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 26 18:53:21 gw netifd: wan (8730): sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 26 18:53:21 gw pppd[8730]: rcvd [IPCP ConfReq id=0x1 <addr 84.16.59.40>]
May 26 18:53:21 gw pppd[8730]: sent [IPCP ConfAck id=0x1 <addr 84.16.59.40>]
May 26 18:53:21 gw netifd: wan (8730): rcvd [IPCP ConfReq id=0x1 <addr 84.16.59.40>]
May 26 18:53:21 gw netifd: wan (8730): sent [IPCP ConfAck id=0x1 <addr 84.16.59.40>]
May 26 18:53:21 gw pppd[8730]: rcvd [IPCP ConfNak id=0x1 <addr 212.55.yy.yy> <ms-dns1 195.28.64.99> <ms-dns2 195.80.171.4>]
May 26 18:53:21 gw pppd[8730]: sent [IPCP ConfReq id=0x2 <addr 212.55.yy.yy> <ms-dns1 195.28.64.99> <ms-dns2 195.80.171.4>]
May 26 18:53:21 gw netifd: wan (8730): rcvd [IPCP ConfNak id=0x1 <addr 212.55.yy.yy> <ms-dns1 195.28.64.99> <ms-dns2 195.80.171.4>]
May 26 18:53:21 gw netifd: wan (8730): sent [IPCP ConfReq id=0x2 <addr 212.55.yy.yy> <ms-dns1 195.28.64.99> <ms-dns2 195.80.171.4>]
May 26 18:53:21 gw pppd[8730]: rcvd [IPCP ConfAck id=0x2 <addr 212.55.yy.yy> <ms-dns1 195.28.64.99> <ms-dns2 195.80.171.4>]
May 26 18:53:21 gw netifd: wan (8730): rcvd [IPCP ConfAck id=0x2 <addr 212.55.yy.yy> <ms-dns1 195.28.64.99> <ms-dns2 195.80.171.4>]
May 26 18:53:21 gw pppd[8730]: local IP address 212.55.yy.yy
May 26 18:53:21 gw pppd[8730]: remote IP address 84.16.59.40
May 26 18:53:21 gw pppd[8730]: primary DNS address 195.28.64.99
May 26 18:53:21 gw pppd[8730]: secondary DNS address 195.80.171.4
May 26 18:53:21 gw netifd: wan (8730): local IP address 212.55.yy.yy
May 26 18:53:21 gw netifd: wan (8730): remote IP address 84.16.59.40
May 26 18:53:21 gw netifd: wan (8730): primary DNS address 195.28.64.99
May 26 18:53:21 gw netifd: wan (8730): secondary DNS address 195.80.171.4
May 26 18:53:21 gw pppd[8730]: Script /lib/netifd/ppp-up started (pid 8818)
May 26 18:53:21 gw netifd: wan (8730): Script /lib/netifd/ppp-up started (pid 8818)
May 26 18:53:21 gw netifd: Network device ‘pppoe-wan’ link is up
May 26 18:53:21 gw netifd: Interface ‘wan’ is now up
May 26 18:53:21 gw pppd[8730]: Script /lib/netifd/ppp-up finished (pid 8818), status = 0x1
May 26 18:53:21 gw netifd: wan (8730): Script /lib/netifd/ppp-up finished (pid 8818), status = 0x1
May 26 18:53:21 gw netifd[2854]: syntax error. Last token seen: +
May 26 18:53:21 gw netifd[2854]: Garbled time

I got more if needed.

21 
netifd: syntax error. Last token seen: +
netifd: Garbled time

does not look healthy and is probably unrelated as being caused by a kresd script and should been fixed already in TOS5.x resolver-conf: Fix syntax error when run resolver init script (#360) · Issues · Turris / Turris OS / Turris OS packages · GitLab

apparent differences seems to be in the numeric values of

  • LCP ConfReq id=0x1 [...] <magic 0x14de1afa>
  • using channel 2

The magic number is probably unrelated but jumping from channel 2 to 141 seems somewhat conspicuous. Can you check in the logs which channel been used:

  • prior the ISP started a new session?
  • channels showing in the logs with the subsequent failed attempts, e.g. is it always channel 2 or is the number changing/increasing with each new attempt?

What is the output of ps -aux | grep pppd ? - :warning: you may want to obfuscate potentially private data such as username | password