Automated PPPoE bouncing - proper way

Hi there,

I've been using OpenWRT 15.x & 18.x on a few 4/32 routers with PPPoE over WAN (my ISP works this way) and managed to bounce the PPPoE connection daily with the help of an UCI script. The reason behind this is to renew my public IP, and, because I can, also randomizing my WAN MAC address.
The ISP I'm connecting to does check if the MAC (OUI) is valid and therefore I need to generate a valid MAC address with the help of the oui.txt - collection of valid MAC prefixes. That file is pretty large (200-300kB) and didn't fit in the limited space of the 4/32 routers. This is why I was connecting (ssh - dropbear) from a remote Linux system (using expect) and only instructing OpenWRT with UCI commands.
Meanwhile I managed to buy a second hand D-Link DIR-860L and loaded OpenWRT 19.07.4 on it, experiencing issues with bouncing the PPPoE connection.

On OpenWRT 15.x & 18.x I was successfully using the following expect embedded UCI sequence ($MAC contains the already prepared(randomized) MAC string):

send -- "uci set network.wan_eth0_2_dev.macaddr=$MAC\r"
expect *
send -- "uci commit network\r"
expect *
send -- "ifdown wan\r"
expect *
send -- "ifup wan\r"
expect *

The pppd daemon was disconnecting gracefully, that's sending the PADT packet before quitting and then reconnecting automatically when the wan interface was brought back up.
Unfortunately, this sequence of UCI commands doesn't work properly on OpenWRT 19.07.4. This is what happens when I run it:

Sat Oct 24 17:39:28 2020 authpriv.notice dropbear[10139]: Password auth succeeded for 'root' from xxx.xxx.xxx.xxx:123
Sat Oct 24 17:39:28 2020 daemon.notice pppd[9969]: Modem hangup
Sat Oct 24 17:39:28 2020 daemon.info pppd[9969]: Connect time 9.7 minutes.
Sat Oct 24 17:39:28 2020 daemon.info pppd[9969]: Sent 787953 bytes, received 4580452 bytes.
Sat Oct 24 17:39:28 2020 daemon.notice pppd[9969]: Connection terminated.
Sat Oct 24 17:39:28 2020 daemon.warn dnsmasq[2547]: no servers found in /tmp/resolv.conf.auto, will retry
Sat Oct 24 17:39:28 2020 daemon.notice netifd: Network device 'pppoe-wan' link is down
Sat Oct 24 17:39:28 2020 daemon.err pppd[9969]: error sending pppoe packet: No such device or address
Sat Oct 24 17:39:28 2020 daemon.info pppd[9969]: Sent PADT
Sat Oct 24 17:39:28 2020 authpriv.info dropbear[10139]: Exit (root): Disconnect received
Sat Oct 24 17:39:28 2020 daemon.info pppd[9969]: Exit.
Sat Oct 24 17:39:28 2020 daemon.notice netifd: Interface 'wan' is now down
Sat Oct 24 17:39:28 2020 daemon.notice netifd: Interface 'wan' is disabled
Sat Oct 24 17:39:28 2020 daemon.notice netifd: Interface 'wan' is enabled
Sat Oct 24 17:39:28 2020 daemon.notice netifd: Interface 'wan' is setting up now
Sat Oct 24 17:39:28 2020 daemon.err insmod: module is already loaded - slhc
Sat Oct 24 17:39:28 2020 daemon.err insmod: module is already loaded - ppp_generic
Sat Oct 24 17:39:28 2020 daemon.err insmod: module is already loaded - pppox
Sat Oct 24 17:39:28 2020 daemon.err insmod: module is already loaded - pppoe
Sat Oct 24 17:39:28 2020 daemon.info pppd[10317]: Plugin rp-pppoe.so loaded.
Sat Oct 24 17:39:28 2020 daemon.info pppd[10317]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sat Oct 24 17:39:29 2020 daemon.notice pppd[10317]: pppd 2.4.7 started by root, uid 0
Sat Oct 24 17:39:30 2020 daemon.info pppd[10317]: PPP session is 5758
Sat Oct 24 17:39:30 2020 daemon.warn pppd[10317]: Connected to xx:xx:xx:xx:xx:xx via interface eth0.2
Sat Oct 24 17:39:30 2020 kern.info kernel: [42086.429162] pppoe-wan: renamed from ppp0
Sat Oct 24 17:39:30 2020 daemon.info pppd[10317]: Renamed interface ppp0 to pppoe-wan
Sat Oct 24 17:39:30 2020 daemon.info pppd[10317]: Using interface pppoe-wan
Sat Oct 24 17:39:30 2020 daemon.notice pppd[10317]: Connect: pppoe-wan <--> eth0.2
**Sat Oct 24 17:39:33 2020 daemon.info pppd[10317]: Remote message: ^M^JAccess denied (already active).^J**
Sat Oct 24 17:39:33 2020 daemon.err pppd[10317]: PAP authentication failed
Sat Oct 24 17:39:38 2020 daemon.notice pppd[10317]: Connection terminated.
Sat Oct 24 17:39:38 2020 daemon.info pppd[10317]: Sent PADT
Sat Oct 24 17:39:38 2020 daemon.info pppd[10317]: Exit.

Note that my ISP denies me access, notifying in the error message that I'm already connected, meaning, pppd hasn't got a chance to send the PADT packet. It will allow me access after a while, presumably noticing (PPPoE echo packets) that the previous session is dead.

Playing around a little I managed to find a workaroud by killing pppd:

send -- "killall pppd\r"
expect *
send -- "sleep 1\r"
expect *
send -- "uci set network.wan_eth0_2_dev.macaddr=$MAC\r"
expect *
send -- "uci commit network\r"
expect *
send -- "ifdown wan\r"
expect *
send -- "ifup wan\r"
expect *

Result:

Sat Oct 24 19:31:42 2020 authpriv.info dropbear[15095]: Child connection from xxx.xxx.xxx.xxx:123
Sat Oct 24 19:31:42 2020 authpriv.notice dropbear[15095]: Password auth succeeded for 'root' from xxx.xxx.xxx.xxx:123
Sat Oct 24 19:31:42 2020 daemon.info pppd[14751]: Terminating on signal 15
Sat Oct 24 19:31:42 2020 daemon.info pppd[14751]: Connect time 50.7 minutes.
Sat Oct 24 19:31:42 2020 daemon.info pppd[14751]: Sent 4164973 bytes, received 62384193 bytes.
Sat Oct 24 19:31:42 2020 daemon.notice netifd: Network device 'pppoe-wan' link is down
Sat Oct 24 19:31:42 2020 daemon.notice netifd: Interface 'wan' has lost the connection
Sat Oct 24 19:31:42 2020 daemon.warn dnsmasq[2547]: no servers found in /tmp/resolv.conf.auto, will retry
Sat Oct 24 19:31:42 2020 daemon.notice pppd[14751]: Connection terminated.
Sat Oct 24 19:31:43 2020 daemon.info pppd[14751]: Sent PADT
Sat Oct 24 19:31:43 2020 daemon.info pppd[14751]: Exit.
Sat Oct 24 19:31:43 2020 daemon.notice netifd: Interface 'wan' is now down
Sat Oct 24 19:31:43 2020 daemon.notice netifd: Interface 'wan' is disabled
Sat Oct 24 19:31:43 2020 daemon.notice netifd: Interface 'wan' is enabled
Sat Oct 24 19:31:43 2020 daemon.notice netifd: Interface 'wan' is setting up now
Sat Oct 24 19:31:43 2020 daemon.err insmod: module is already loaded - slhc
Sat Oct 24 19:31:43 2020 daemon.err insmod: module is already loaded - ppp_generic
Sat Oct 24 19:31:43 2020 daemon.err insmod: module is already loaded - pppox
Sat Oct 24 19:31:43 2020 daemon.err insmod: module is already loaded - pppoe
Sat Oct 24 19:31:43 2020 daemon.info pppd[15195]: Plugin rp-pppoe.so loaded.
Sat Oct 24 19:31:43 2020 daemon.info pppd[15195]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sat Oct 24 19:31:43 2020 daemon.notice pppd[15195]: pppd 2.4.7 started by root, uid 0
**Sat Oct 24 19:31:43 2020 daemon.err pppd[15195]: error receiving pppoe packet: Network is down**
Sat Oct 24 19:31:44 2020 authpriv.info dropbear[15095]: Exit (root): Disconnect received
**Sat Oct 24 19:31:48 2020 daemon.err pppd[15195]: error sending pppoe packet: No such device or address**
Sat Oct 24 19:31:48 2020 daemon.notice netifd: Interface 'wan' is now down
Sat Oct 24 19:31:48 2020 daemon.notice netifd: Interface 'wan' is disabled
Sat Oct 24 19:31:48 2020 daemon.notice netifd: Interface 'wan' is enabled
Sat Oct 24 19:31:48 2020 daemon.notice netifd: Interface 'wan' is setting up now
Sat Oct 24 19:31:48 2020 daemon.err insmod: module is already loaded - slhc
Sat Oct 24 19:31:48 2020 daemon.err insmod: module is already loaded - ppp_generic
Sat Oct 24 19:31:48 2020 daemon.err insmod: module is already loaded - pppox
Sat Oct 24 19:31:49 2020 daemon.err insmod: module is already loaded - pppoe
Sat Oct 24 19:31:49 2020 daemon.info pppd[15410]: Plugin rp-pppoe.so loaded.
Sat Oct 24 19:31:49 2020 daemon.info pppd[15410]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sat Oct 24 19:31:49 2020 daemon.notice pppd[15410]: pppd 2.4.7 started by root, uid 0
Sat Oct 24 19:31:50 2020 daemon.info pppd[15410]: PPP session is 1763
Sat Oct 24 19:31:50 2020 daemon.warn pppd[15410]: Connected to xx:xx:xx:xx:xx:xx via interface eth0.2
Sat Oct 24 19:31:50 2020 kern.info kernel: [48826.555334] pppoe-wan: renamed from ppp0
Sat Oct 24 19:31:50 2020 daemon.info pppd[15410]: Renamed interface ppp0 to pppoe-wan
Sat Oct 24 19:31:50 2020 daemon.info pppd[15410]: Using interface pppoe-wan
Sat Oct 24 19:31:50 2020 daemon.notice pppd[15410]: Connect: pppoe-wan <--> eth0.2
Sat Oct 24 19:31:53 2020 daemon.notice pppd[15410]: PAP authentication succeeded
Sat Oct 24 19:31:53 2020 daemon.notice pppd[15410]: peer from calling number xx:xx:xx:xx:xx:xx authorized
Sat Oct 24 19:31:53 2020 daemon.notice pppd[15410]: local  IP address xxx.xxx.xxx.xxx
Sat Oct 24 19:31:53 2020 daemon.notice pppd[15410]: remote IP address xxx.xxx.xxx.xxx
Sat Oct 24 19:31:53 2020 daemon.notice pppd[15410]: primary   DNS address xxx.xxx.xxx.xxx
Sat Oct 24 19:31:53 2020 daemon.notice pppd[15410]: secondary DNS address xxx.xxx.xxx.xxx
Sat Oct 24 19:31:53 2020 daemon.notice netifd: Network device 'pppoe-wan' link is up
Sat Oct 24 19:31:53 2020 daemon.notice netifd: Interface 'wan' is now up
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: reading /tmp/resolv.conf.auto
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using local addresses only for domain test
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using local addresses only for domain onion
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using local addresses only for domain localhost
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using local addresses only for domain local
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using local addresses only for domain invalid
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using local addresses only for domain bind
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using local addresses only for domain lan
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using nameserver xxx.xxx.xxx.xxx#53
Sat Oct 24 19:31:53 2020 daemon.info dnsmasq[2547]: using nameserver xxx.xxx.xxx.xxx#53
Sat Oct 24 19:31:53 2020 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)

I presume the two pppd errors: error receiving pppoe packet & error sending pppoe packet are due to pppd restarting and not having the wan interface available (yet).
Interestingly, if I omit the expect - send -- "sleep 1\r", then the error comes up before sending the PADT packet. Looks like pppd doesn't get a chance to send the PADT packet before I bring the wan down. However, it still works, I'm not getting access denied by my ISP on reconnecting. Maybe it's only a logging delay and pppd actually manages to send the PADT. Anyways, it's dirty. Here's the log snippet without sleep:

Sat Oct 24 19:35:20 2020 daemon.notice pppd[15410]: Modem hangup
Sat Oct 24 19:35:20 2020 daemon.notice pppd[15410]: Connection terminated.
Sat Oct 24 19:35:20 2020 daemon.err pppd[15410]: error sending pppoe packet: No such device or address
Sat Oct 24 19:35:20 2020 daemon.info pppd[15410]: Sent PADT
Sat Oct 24 19:35:20 2020 daemon.info pppd[15410]: Exit.

Finally, if I go in LuCI and manually stop the WAN interface, I don't get any pppd error messages:

Sat Oct 24 18:16:44 2020 daemon.info pppd[13400]: Terminating on signal 15
Sat Oct 24 18:16:44 2020 daemon.info pppd[13400]: Connect time 2.5 minutes.
Sat Oct 24 18:16:44 2020 daemon.info pppd[13400]: Sent 206023 bytes, received 306499 bytes.
Sat Oct 24 18:16:44 2020 daemon.notice netifd: Network device 'pppoe-wan' link is down
Sat Oct 24 18:16:44 2020 daemon.notice pppd[13400]: Connection terminated.
Sat Oct 24 18:16:44 2020 daemon.info pppd[13400]: Sent PADT
Sat Oct 24 18:16:44 2020 daemon.info pppd[13400]: Exit.
Sat Oct 24 18:16:44 2020 daemon.notice netifd: Interface 'wan' is now down
Sat Oct 24 18:16:44 2020 daemon.notice netifd: Interface 'wan' is disabled
Sat Oct 24 18:16:44 2020 daemon.warn dnsmasq[2547]: no servers found in /tmp/resolv.conf.auto, will retry
Sat Oct 24 18:16:44 2020 daemon.notice netifd: VLAN 'eth0.2' link is down
Sat Oct 24 18:16:44 2020 daemon.notice netifd: Interface 'wan' has link connectivity loss
Sat Oct 24 18:17:14 2020 daemon.notice netifd: Interface 'wan' is enabled
Sat Oct 24 18:17:14 2020 daemon.notice netifd: VLAN 'eth0.2' link is up
Sat Oct 24 18:17:14 2020 daemon.notice netifd: Interface 'wan' has link connectivity
Sat Oct 24 18:17:14 2020 daemon.notice netifd: Interface 'wan' is setting up now
Sat Oct 24 18:17:14 2020 daemon.err insmod: module is already loaded - slhc
Sat Oct 24 18:17:14 2020 daemon.err insmod: module is already loaded - ppp_generic
Sat Oct 24 18:17:14 2020 daemon.err insmod: module is already loaded - pppox
Sat Oct 24 18:17:14 2020 daemon.err insmod: module is already loaded - pppoe
Sat Oct 24 18:17:14 2020 daemon.info pppd[13771]: Plugin rp-pppoe.so loaded.
Sat Oct 24 18:17:14 2020 daemon.info pppd[13771]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sat Oct 24 18:17:14 2020 daemon.notice pppd[13771]: pppd 2.4.7 started by root, uid 0
Sat Oct 24 18:17:15 2020 daemon.info pppd[13771]: PPP session is 2263
Sat Oct 24 18:17:15 2020 daemon.warn pppd[13771]: Connected to xx:xx:xx:xx:xx:xx via interface eth0.2
Sat Oct 24 18:17:16 2020 kern.info kernel: [44352.157622] pppoe-wan: renamed from ppp0
Sat Oct 24 18:17:16 2020 daemon.info pppd[13771]: Renamed interface ppp0 to pppoe-wan
Sat Oct 24 18:17:16 2020 daemon.info pppd[13771]: Using interface pppoe-wan
Sat Oct 24 18:17:16 2020 daemon.notice pppd[13771]: Connect: pppoe-wan <--> eth0.2
Sat Oct 24 18:17:19 2020 daemon.notice pppd[13771]: PAP authentication succeeded
Sat Oct 24 18:17:19 2020 daemon.notice pppd[13771]: peer from calling number xx:xx:xx:xx:xx:xx authorized
Sat Oct 24 18:17:19 2020 daemon.notice pppd[13771]: local  IP address xxx.xxx.xxx.xxx
Sat Oct 24 18:17:19 2020 daemon.notice pppd[13771]: remote IP address xxx.xxx.xxx.xxx
Sat Oct 24 18:17:19 2020 daemon.notice pppd[13771]: primary   DNS address xxx.xxx.xxx.xxx
Sat Oct 24 18:17:19 2020 daemon.notice pppd[13771]: secondary DNS address xxx.xxx.xxx.xxx
Sat Oct 24 18:17:19 2020 daemon.notice netifd: Network device 'pppoe-wan' link is up
Sat Oct 24 18:17:19 2020 daemon.notice netifd: Interface 'wan' is now up
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: reading /tmp/resolv.conf.auto
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using local addresses only for domain test
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using local addresses only for domain onion
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using local addresses only for domain localhost
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using local addresses only for domain local
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using local addresses only for domain invalid
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using local addresses only for domain bind
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using local addresses only for domain lan
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using nameserver xxx.xxx.xxx.xxx#53
Sat Oct 24 18:17:19 2020 daemon.info dnsmasq[2547]: using nameserver xxx.xxx.xxx.xxx#53
Sat Oct 24 18:17:19 2020 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)

Some extra details - router: D-Link DIR-860L, running:

# cat /etc/openwrt_release
DISTRIB_ID='OpenWrt'
DISTRIB_RELEASE='19.07.4'
DISTRIB_REVISION='r11208-ce6496d796'
DISTRIB_TARGET='ramips/mt7621'
DISTRIB_ARCH='mipsel_24kc'
DISTRIB_DESCRIPTION='OpenWrt 19.07.4 r11208-ce6496d796'
DISTRIB_TAINTS=''

I'd be thankful if anyone can guide me with a potentially better/cleaner automated approach. I'm also planning to do this bouncing directly on the new OpenWRT, plenty of space to accomodate the oui.txt now.

Many thanks in advance!