search

NetworkConfiguration / dhcpcd

DHCP / IPv4LL / IPv6RA / DHCPv6 client.
https://roy.marples.name/projects/dhcpcd
BSD 2-Clause "Simplified" License
326 stars 104 forks source link

DHCP(v6) rebind fails after carrier loss #314

Open zogtogus opened 3 months ago

zogtogus commented 3 months ago

Hi,

I am running dhcpcd (10.0.6-r2) on gentoo linux router connected to a DSL link (dsl modem as a bridge), WAN v6 prefix provided using SLAAC, (static) LAN v6 prefix delegated using DHCP-PD. Once the DSL links loses carrier, dhcpcd does not recover once carrier up again, please see the logs below. dhcpcd rebind fails, it needs 'dhcpcd -k' prior dhcpcd rebind works.

Cheers, Ales

Apr 10 07:59:11 ns dhcpcd[23619]: ppp0: carrier lost Apr 10 07:59:11 ns dhcpcd[23619]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Apr 10 07:59:11 ns dhcpcd[23619]: enp2s0: deleting address 2a00:xxxx:xxxx:xxxx::1/64 Apr 10 07:59:11 ns dhcpcd[23619]: enp2s0: deleting route to 2a00:xxxx:xxxx:xxxx::/64 Apr 10 07:59:11 ns dhcpcd[23619]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6 Apr 10 07:59:11 ns dhcpcd[23619]: ppp0: deleting address 2a00:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx/64 Apr 10 07:59:11 ns dhcpcd[23619]: ppp0: deleting route to 2a00:xxxx:xxxx:xxxx::/64 Apr 10 07:59:11 ns dhcpcd[23619]: ppp0: deleting default route via fe80::xxxx:xxxx:xxxx:xxxx Apr 10 07:59:11 ns dhcpcd[23619]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT Apr 10 07:59:17 ns dhcpcd[23619]: ppp0: libudev: remove Apr 10 07:59:17 ns dhcpcd[23619]: ppp0: interface departed Apr 10 07:59:17 ns dhcpcd[23619]: ppp0: removing interface Apr 10 07:59:17 ns dhcpcd[23619]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks DEPARTED Apr 10 08:05:02 ns dhcpcd[23619]: ppp0: libudev: add Apr 10 08:05:02 ns dhcpcd[23619]: ppp0: interface added Apr 10 08:05:02 ns dhcpcd[23619]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Apr 10 08:05:02 ns dhcpcd[23619]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Apr 10 08:05:02 ns dhcpcd[23619]: ppp0: waiting for carrier Apr 10 08:05:02 ns dhcpcd[23619]: ppp0: carrier acquired Apr 10 08:05:02 ns dhcpcd[23619]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Apr 10 08:05:03 ns dhcpcd[23619]: ppp0: IAID 70:70:70:30 Apr 10 08:05:03 ns dhcpcd[23619]: ppp0: IA type 25 IAID 00:00:00:02 Apr 10 08:05:03 ns dhcpcd[23619]: ppp0: delaying IPv6 router solicitation for 0.6 seconds Apr 10 08:05:03 ns dhcpcd[23619]: ppp0: delaying DHCPv6 for LL address Apr 10 08:05:03 ns dhcpcd[23619]: ppp0: soliciting an IPv6 router Apr 10 08:05:03 ns dhcpcd[23619]: ppp0: delaying Router Solicitation for LL address ... => no v6 prefix obtained/delegated, needs dhcpcd -k or dhcpcd restart to restore IPv6 connectivity

rsmarples commented 3 months ago

So it looks like IPv6 is not started due to the LL address being absent. From the logs, dhcpcd didn't delete it, so what happened to it? If you restart dhcpcd at this point does dhcpcd put it back or does something else? You haven't posted logs for that part.

perkelix commented 2 months ago

@zogtogus ping

smlanger commented 3 weeks ago

I guess I'll chip in and provide some logs in place of @zogtogus because this appears to be the exact same issue I've had for years. I did some tests with dhcpcd 10.0.6 yesterday, did an update on the router including dhcpcd 10.0.8 and redid the tests. I'll add the logs to each test.

Sending SIGHUP to pppd to reconnect the pppoe connection will cause what OP showed in their log:

Jun 23 00:23:46 porto dhcpcd[21818]: ppp0: carrier lost Jun 23 00:23:46 porto dhcpcd[21818]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 00:23:48 porto dhcpcd[21818]: ppp0: interface departed Jun 23 00:23:48 porto dhcpcd[21818]: ppp0: removing interface Jun 23 00:23:48 porto dhcpcd[21818]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks DEPARTED Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: interface added Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: waiting for carrier Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: carrier acquired Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: IAID 70:70:70:30 Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: IA type 25 IAID 00:00:00:01 Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: delaying IPv6 router solicitation for 0.8 seconds Jun 23 00:23:52 porto dhcpcd[21818]: ppp0: delaying DHCPv6 for LL address Jun 23 00:23:53 porto dhcpcd[21818]: ppp0: soliciting an IPv6 router Jun 23 00:23:53 porto dhcpcd[21818]: ppp0: delaying Router Solicitation for LL address

Jun 23 00:23:46 porto pppd[2221]: Hangup (SIGHUP) Jun 23 00:23:46 porto pppd[2221]: Connection terminated. Jun 23 00:23:51 porto pppd[2221]: PPP session is 53325 Jun 23 00:23:52 porto pppd[2221]: Connected to 88:40:33:52:EA:1B via interface eth1 Jun 23 00:23:52 porto pppd[2221]: Using interface ppp0 Jun 23 00:23:52 porto pppd[2221]: Connect: ppp0 <--> eth1 Jun 23 00:23:55 porto pppd[2221]: Remote message: [UI-SBR:105401,37000;UI-LINEID:1UND1.DEU.DTAG.31NEU;] Jun 23 00:23:55 porto pppd[2221]: PAP authentication succeeded Jun 23 00:23:55 porto pppd[2221]: peer from calling number 88:40:33:52:EA:1B authorized Jun 23 00:23:55 porto pppd[2221]: local LL address fe80::0097:4714:1750:50bc Jun 23 00:23:55 porto pppd[2221]: remote LL address fe80::8a40:33ff:fe52:ea1b Jun 23 00:23:55 porto pppd[2221]: local IP address 92.116.243.44 Jun 23 00:23:55 porto pppd[2221]: remote IP address 94.134.199.140 Jun 23 00:23:55 porto pppd[2221]: primary DNS address 82.144.41.8 Jun 23 00:23:55 porto pppd[2221]: secondary DNS address 82.145.9.8

After that dhcpcd will wait indefinitely even though as you can see pppd received the LL addresses just a few seconds later and ip a does show the configured local and remote LL addresses on the ppp interface.

Terminating dhcpcd with dhcpcd -k and restarting the services will cause a proper prefix delegation again:

Jun 23 00:26:54 porto dhcpcd[419]: sending signal ALRM to pid 21818 Jun 23 00:26:54 porto dhcpcd[21818]: received SIGALRM, releasing Jun 23 00:26:54 porto dhcpcd[21818]: ppp0: removing interface Jun 23 00:26:54 porto dhcpcd[21818]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 00:26:54 porto dhcpcd[419]: waiting for pid 21818 to exit Jun 23 00:26:54 porto dhcpcd[21818]: tap0: removing interface Jun 23 00:26:54 porto dhcpcd[21818]: tap0: deleting address fe80::8071:31ff:fed9:d523 Jun 23 00:26:54 porto dhcpcd[21818]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 00:26:55 porto dhcpcd[21818]: wlan0: removing interface Jun 23 00:26:55 porto dhcpcd[21818]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 00:26:55 porto dhcpcd[21818]: bond0: removing interface Jun 23 00:26:55 porto dhcpcd[21818]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 00:26:55 porto dhcpcd[21818]: dhcpcd exited Jun 23 00:28:09 porto /etc/init.d/dhcpcd[519]: WARNING: dhcpcd has already been started Jun 23 00:28:13 porto /etc/init.d/dhcpcd[523]: WARNING: you are stopping a boot service Jun 23 00:28:15 porto start-stop-daemon[707]: Will stop /sbin/dhcpcd Jun 23 00:28:15 porto /etc/init.d/dhcpcd[707]: start-stop-daemon: no matching processes found Jun 23 00:28:15 porto dhcpcd[736]: dhcpcd-10.0.6 starting Jun 23 00:28:15 porto dhcpcd[738]: spawned manager process on PID 738 Jun 23 00:28:15 porto dhcpcd[738]: DUID 00:01:00:01:28:a5:8a:24:3c:ec:ef:75:64:58 Jun 23 00:28:15 porto dhcpcd[738]: lo: ignoring due to interface type and no config Jun 23 00:28:15 porto dhcpcd[738]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 00:28:15 porto dhcpcd[738]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 00:28:15 porto dhcpcd[738]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 00:28:15 porto dhcpcd[738]: wlan0: connected to Access Point: Jun 23 00:28:15 porto dhcpcd[738]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 00:28:15 porto dhcpcd[738]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 00:28:15 porto dhcpcd[738]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 00:28:15 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 00:28:15 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 00:28:15 porto dhcpcd[738]: bond0: IAID ef:75:64:58 Jun 23 00:28:15 porto dhcpcd[738]: wlan0: IAID 87:00:c6:42 Jun 23 00:28:15 porto dhcpcd[738]: tap0: waiting for carrier Jun 23 00:28:15 porto dhcpcd[738]: ppp0: IAID 70:70:70:30 Jun 23 00:28:15 porto dhcpcd[738]: ppp0: IA type 25 IAID 00:00:00:01 Jun 23 00:28:15 porto dhcpcd[738]: ppp0: delaying IPv6 router solicitation for 0.1 seconds Jun 23 00:28:15 porto dhcpcd[738]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6 Jun 23 00:28:15 porto dhcpcd[738]: ppp0: rebinding prior DHCPv6 lease Jun 23 00:28:15 porto dhcpcd[738]: ppp0: delaying REBIND6 (xid 0xe63982), next in 2.1 seconds Jun 23 00:28:15 porto dhcpcd[738]: ppp0: soliciting an IPv6 router Jun 23 00:28:15 porto dhcpcd[738]: ppp0: sending Router Solicitation Jun 23 00:28:15 porto dhcpcd[738]: ppp0: Router Advertisement from fe80::8a40:33ff:fe52:ea1b Jun 23 00:28:15 porto dhcpcd[738]: ppp0: adding address 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:28:15 porto dhcpcd[738]: ppp0: pltime 172800 seconds, vltime 259200 seconds Jun 23 00:28:15 porto dhcpcd[738]: ppp0: adding route to 2001:9e8:3b:a789::/64 Jun 23 00:28:15 porto dhcpcd[738]: ppp0: adding default route via fe80::8a40:33ff:fe52:ea1b Jun 23 00:28:15 porto dhcpcd[738]: ppp0: waiting for Router Advertisement DAD to complete Jun 23 00:28:15 porto dhcpcd[738]: ppp0: Router Advertisement DAD completed Jun 23 00:28:15 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT Jun 23 00:28:15 porto dhcpcd[738]: ppp0: sending NA for 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:28:16 porto dhcpcd[738]: ppp0: sending NA for 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:28:17 porto dhcpcd[738]: ppp0: multicasting REBIND6 (xid 0xe63982), next in 1.0 seconds Jun 23 00:28:17 porto dhcpcd[738]: ppp0: sending NA for 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:28:18 porto dhcpcd[738]: ppp0: multicasting REBIND6 (xid 0xe63982), next in 2.1 seconds Jun 23 00:28:20 porto dhcpcd[738]: ppp0: multicasting REBIND6 (xid 0xe63982), next in 4.4 seconds Jun 23 00:28:25 porto dhcpcd[738]: ppp0: multicasting REBIND6 (xid 0xe63982), next in 4.0 seconds Jun 23 00:28:25 porto dhcpcd[738]: ppp0: failed to rebind prior DHCPv6 delegation Jun 23 00:28:25 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6 Jun 23 00:28:25 porto dhcpcd[738]: ppp0: soliciting a DHCPv6 lease Jun 23 00:28:25 porto dhcpcd[738]: ppp0: delaying SOLICIT6 (xid 0x3c795f), next in 2.1 seconds Jun 23 00:28:27 porto dhcpcd[738]: ppp0: multicasting SOLICIT6 (xid 0x3c795f), next in 1.1 seconds Jun 23 00:28:27 porto dhcpcd[738]: ppp0: ADV 2001:9e8:1bdf:7300::/56 from fe80::8a40:33ff:fe52:ea1b Jun 23 00:28:27 porto dhcpcd[738]: ppp0: multicasting REQUEST6 (xid 0xcf9a9a), next in 1.1 seconds Jun 23 00:28:27 porto dhcpcd[738]: ppp0: REPLY6 received from fe80::8a40:33ff:fe52:ea1b Jun 23 00:28:27 porto dhcpcd[738]: ppp0: renew in 86400, rebind in 138240, expire in 259200 seconds Jun 23 00:28:27 porto dhcpcd[738]: lo: adding reject route to 2001:9e8:1bdf:7300::/56 Jun 23 00:28:27 porto dhcpcd[738]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6 Jun 23 00:28:27 porto dhcpcd[738]: ppp0: delegated prefix 2001:9e8:1bdf:7300::/56 Jun 23 00:28:27 porto dhcpcd[738]: bond0: adding address 2001:9e8:1bdf:7301::1/64 Jun 23 00:28:27 porto dhcpcd[738]: bond0: pltime 172800 seconds, vltime 259200 seconds Jun 23 00:28:27 porto dhcpcd[738]: bond0: waiting for DHCPv6 DAD to complete Jun 23 00:28:27 porto dhcpcd[738]: wlan0: adding address 2001:9e8:1bdf:7302::1/64 Jun 23 00:28:27 porto dhcpcd[738]: wlan0: pltime 172800 seconds, vltime 259200 seconds Jun 23 00:28:27 porto dhcpcd[738]: wlan0: waiting for DHCPv6 DAD to complete Jun 23 00:28:27 porto dhcpcd[738]: tap0: has no carrier, cannot delegate addresses Jun 23 00:28:27 porto dhcpcd[738]: bond0: adding route to 2001:9e8:1bdf:7301::/64 Jun 23 00:28:27 porto dhcpcd[738]: wlan0: adding route to 2001:9e8:1bdf:7302::/64 Jun 23 00:28:27 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks BOUND6 Jun 23 00:28:28 porto dhcpcd[736]: forked to background Jun 23 00:28:28 porto dhcpcd[738]: tap0: carrier acquired Jun 23 00:28:28 porto dhcpcd[738]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 00:28:28 porto dhcpcd[738]: tap0: IAID 31:d9:d5:23 Jun 23 00:28:28 porto dhcpcd[738]: tap0: adding address fe80::8071:31ff:fed9:d523 Jun 23 00:28:28 porto dhcpcd[738]: tap0: pltime infinity, vltime infinity Jun 23 00:28:28 porto dhcpcd[738]: tap0: delaying adding delegated addresses for LL address Jun 23 00:28:29 porto dhcpcd[738]: bond0: DHCPv6 DAD completed Jun 23 00:28:29 porto dhcpcd[738]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6 Jun 23 00:28:29 porto dhcpcd[738]: wlan0: DHCPv6 DAD completed Jun 23 00:28:29 porto dhcpcd[738]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6 Jun 23 00:28:30 porto dhcpcd[738]: tap0: adding delegated prefixes Jun 23 00:28:30 porto dhcpcd[738]: tap0: adding address 2001:9e8:1bdf:7303::1/64 Jun 23 00:28:30 porto dhcpcd[738]: tap0: pltime 172798 seconds, vltime 259198 seconds Jun 23 00:28:30 porto dhcpcd[738]: tap0: adding route to 2001:9e8:1bdf:7303::/64 Jun 23 00:28:30 porto dhcpcd[738]: tap0: waiting for DHCPv6 DAD to complete Jun 23 00:28:31 porto dhcpcd[738]: tap0: DHCPv6 DAD completed Jun 23 00:28:31 porto dhcpcd[738]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6 Jun 23 00:30:24 porto dhcpcd[738]: ppp0: Router Advertisement from fe80::8a40:33ff:fe52:ea1b Jun 23 00:30:24 porto dhcpcd[738]: ppp0: adding address 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:30:24 porto dhcpcd[738]: ppp0: pltime 172800 seconds, vltime 259200 seconds Jun 23 00:30:24 porto dhcpcd[738]: ppp0: sending NA for 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:30:24 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT Jun 23 00:30:25 porto dhcpcd[738]: ppp0: sending NA for 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:30:26 porto dhcpcd[738]: ppp0: sending NA for 2001:9e8:3b:a789:97:4714:1750:50bc/64

This had no effect on pppd. The pppd log didn't show any activity in that time frame.

Because dhcpcd does get a proper prefix delegation when the reconnect is cause by the modem losing the DSL sync I tried causing a reconnect by turning the LAN interface eth1 which pppd is running on down and up again but this did not cause any meaningful difference:

Jun 23 00:34:14 porto dhcpcd[738]: ppp0: carrier lost Jun 23 00:34:14 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 00:34:16 porto dhcpcd[738]: bond0: deleting address 2001:9e8:1bdf:7301::1/64 Jun 23 00:34:16 porto dhcpcd[738]: bond0: deleting route to 2001:9e8:1bdf:7301::/64 Jun 23 00:34:16 porto dhcpcd[738]: wlan0: deleting address 2001:9e8:1bdf:7302::1/64 Jun 23 00:34:16 porto dhcpcd[738]: wlan0: deleting route to 2001:9e8:1bdf:7302::/64 Jun 23 00:34:16 porto dhcpcd[738]: tap0: deleting address 2001:9e8:1bdf:7303::1/64 Jun 23 00:34:16 porto dhcpcd[738]: tap0: deleting route to 2001:9e8:1bdf:7303::/64 Jun 23 00:34:16 porto dhcpcd[738]: lo: deleting reject route to 2001:9e8:1bdf:7300::/56 Jun 23 00:34:16 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6 Jun 23 00:34:16 porto dhcpcd[738]: ppp0: deleting address 2001:9e8:3b:a789:97:4714:1750:50bc/64 Jun 23 00:34:16 porto dhcpcd[738]: ppp0: deleting route to 2001:9e8:3b:a789::/64 Jun 23 00:34:16 porto dhcpcd[738]: ppp0: deleting default route via fe80::8a40:33ff:fe52:ea1b Jun 23 00:34:16 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT Jun 23 00:34:16 porto dhcpcd[738]: ppp0: interface departed Jun 23 00:34:16 porto dhcpcd[738]: ppp0: removing interface Jun 23 00:34:16 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks DEPARTED Jun 23 00:35:55 porto dhcpcd[738]: ppp0: interface added Jun 23 00:35:55 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 00:35:55 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 00:35:55 porto dhcpcd[738]: ppp0: waiting for carrier Jun 23 00:35:55 porto dhcpcd[738]: ppp0: carrier acquired Jun 23 00:35:55 porto dhcpcd[738]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 00:35:55 porto dhcpcd[738]: ppp0: IAID 70:70:70:30 Jun 23 00:35:55 porto dhcpcd[738]: ppp0: IA type 25 IAID 00:00:00:01 Jun 23 00:35:55 porto dhcpcd[738]: ppp0: delaying IPv6 router solicitation for 0.8 seconds Jun 23 00:35:55 porto dhcpcd[738]: ppp0: delaying DHCPv6 for LL address Jun 23 00:35:55 porto dhcpcd[738]: ppp0: soliciting an IPv6 router Jun 23 00:35:55 porto dhcpcd[738]: ppp0: delaying Router Solicitation for LL address

Jun 23 00:34:14 porto pppd[2221]: Modem hangup Jun 23 00:34:14 porto pppd[2221]: Connection terminated. Jun 23 00:34:19 porto pppd[2221]: error sending pppoe packet: Network is down Jun 23 00:34:19 porto pppd[2221]: error receiving pppoe packet: Network is down Jun 23 00:34:24 porto pppd[2221]: error sending pppoe packet: Network is down Jun 23 00:34:34 porto pppd[2221]: error sending pppoe packet: Network is down Jun 23 00:34:54 porto pppd[2221]: Timeout waiting for PADO packets Jun 23 00:34:54 porto pppd[2221]: Unable to complete PPPoE Discovery phase 1 Jun 23 00:34:59 porto pppd[2221]: error sending pppoe packet: Network is down Jun 23 00:34:59 porto pppd[2221]: error receiving pppoe packet: Network is down Jun 23 00:35:04 porto pppd[2221]: error sending pppoe packet: Network is down Jun 23 00:35:14 porto pppd[2221]: error sending pppoe packet: Network is down Jun 23 00:35:34 porto pppd[2221]: Timeout waiting for PADO packets Jun 23 00:35:34 porto pppd[2221]: Unable to complete PPPoE Discovery phase 1 Jun 23 00:35:39 porto pppd[2221]: error sending pppoe packet: Network is down Jun 23 00:35:39 porto pppd[2221]: error receiving pppoe packet: Network is down Jun 23 00:35:54 porto pppd[2221]: PPP session is 38310 Jun 23 00:35:55 porto pppd[2221]: Connected to 88:40:33:52:EA:1B via interface eth1 Jun 23 00:35:55 porto pppd[2221]: Using interface ppp0 Jun 23 00:35:55 porto pppd[2221]: Connect: ppp0 <--> eth1 Jun 23 00:35:58 porto pppd[2221]: Remote message: [UI-SBR:105401,37000;UI-LINEID:1UND1.DEU.DTAG.31NEU;] Jun 23 00:35:58 porto pppd[2221]: PAP authentication succeeded Jun 23 00:35:58 porto pppd[2221]: peer from calling number 88:40:33:52:EA:1B authorized Jun 23 00:35:58 porto pppd[2221]: local LL address fe80::a474:f809:75d1:568d Jun 23 00:35:58 porto pppd[2221]: remote LL address fe80::8a40:33ff:fe52:ea1b Jun 23 00:35:58 porto pppd[2221]: local IP address 92.116.243.103 Jun 23 00:35:58 porto pppd[2221]: remote IP address 94.134.199.140 Jun 23 00:35:58 porto pppd[2221]: primary DNS address 82.144.41.8 Jun 23 00:35:58 porto pppd[2221]: secondary DNS address 82.145.9.8

There were no other entries from pppd or dhcpcd in between these 3 log snippets. Redoing the tests with 10.0.8 showed mostly identical log output.

To better recreate a modem sync loss I tried causing a reconnect by replugging the phoneline:

Jun 23 15:01:02 porto dhcpcd[4339]: ppp0: carrier lost Jun 23 15:01:02 porto dhcpcd[4339]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 15:01:03 porto dhcpcd[4339]: tap0: carrier lost Jun 23 15:01:03 porto dhcpcd[4339]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 15:01:03 porto dhcpcd[4339]: tap0: deleting address fe80::f0fe:35ff:fea5:e75f Jun 23 15:01:04 porto start-stop-daemon[6148]: Will stop /sbin/dhcpcd Jun 23 15:01:04 porto dhcpcd[4339]: received SIGTERM, stopping Jun 23 15:01:04 porto dhcpcd[4339]: ppp0: removing interface Jun 23 15:01:04 porto dhcpcd[4339]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 15:01:04 porto dhcpcd[4339]: tap0: removing interface Jun 23 15:01:04 porto dhcpcd[4339]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 15:01:04 porto dhcpcd[4339]: wlan0: removing interface Jun 23 15:01:04 porto dhcpcd[4339]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 15:01:04 porto dhcpcd[4339]: bond0: removing interface Jun 23 15:01:04 porto dhcpcd[4339]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED Jun 23 15:01:04 porto dhcpcd[4339]: dhcpcd exited Jun 23 15:01:58 porto dhcpcd[6806]: dhcpcd-10.0.8 starting Jun 23 15:01:58 porto dhcpcd[6810]: spawned manager process on PID 6810 Jun 23 15:01:58 porto dhcpcd[6810]: DUID 00:01:00:01:28:a5:8a:24:3c:ec:ef:75:64:58 Jun 23 15:01:58 porto dhcpcd[6810]: lo: ignoring due to interface type and no config Jun 23 15:01:58 porto dhcpcd[6810]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 15:01:58 porto dhcpcd[6810]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 15:01:58 porto dhcpcd[6810]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 15:01:58 porto dhcpcd[6810]: wlan0: connected to Access Point: Jun 23 15:01:58 porto dhcpcd[6810]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 15:01:58 porto dhcpcd[6810]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 15:01:58 porto dhcpcd[6810]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 15:01:58 porto dhcpcd[6810]: bond0: IAID ef:75:64:58 Jun 23 15:01:58 porto dhcpcd[6810]: wlan0: IAID 87:00:c6:42 Jun 23 15:01:58 porto dhcpcd[6810]: tap0: waiting for carrier Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: IAID 70:70:70:30 Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: IA type 25 IAID 00:00:00:01 Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: delaying IPv6 router solicitation for 0.4 seconds Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6 Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: rebinding prior DHCPv6 lease Jun 23 15:01:58 porto dhcpcd[6810]: ppp0: delaying REBIND6 (xid 0x89e175), next in 2.1 seconds Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: soliciting an IPv6 router Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: sending Router Solicitation Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: Router Advertisement from fe80::8a40:33ff:fe52:ea1b Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: adding address 2001:9e8:3b:b643:e499:2699:15ac:31a0/64 Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: pltime 172800 seconds, vltime 259200 seconds Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: adding route to 2001:9e8:3b:b643::/64 Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: adding default route via fe80::8a40:33ff:fe52:ea1b Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: waiting for Router Advertisement DAD to complete Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: Router Advertisement DAD completed Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT Jun 23 15:01:59 porto dhcpcd[6810]: ppp0: sending NA for 2001:9e8:3b:b643:e499:2699:15ac:31a0/64 Jun 23 15:02:00 porto dhcpcd[6810]: ppp0: sending NA for 2001:9e8:3b:b643:e499:2699:15ac:31a0/64 Jun 23 15:02:01 porto dhcpcd[6810]: ppp0: multicasting REBIND6 (xid 0x89e175), next in 1.1 seconds Jun 23 15:02:01 porto dhcpcd[6810]: ppp0: sending NA for 2001:9e8:3b:b643:e499:2699:15ac:31a0/64 Jun 23 15:02:02 porto dhcpcd[6810]: ppp0: multicasting REBIND6 (xid 0x89e175), next in 2.2 seconds Jun 23 15:02:04 porto dhcpcd[6810]: ppp0: multicasting REBIND6 (xid 0x89e175), next in 4.2 seconds Jun 23 15:02:08 porto dhcpcd[6810]: ppp0: multicasting REBIND6 (xid 0x89e175), next in 4.4 seconds Jun 23 15:02:08 porto dhcpcd[6810]: ppp0: failed to rebind prior DHCPv6 delegation Jun 23 15:02:08 porto dhcpcd[6810]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6 Jun 23 15:02:09 porto dhcpcd[6810]: ppp0: soliciting a DHCPv6 lease Jun 23 15:02:09 porto dhcpcd[6810]: ppp0: delaying SOLICIT6 (xid 0x28bf7e), next in 2.1 seconds Jun 23 15:02:11 porto dhcpcd[6810]: ppp0: multicasting SOLICIT6 (xid 0x28bf7e), next in 1.1 seconds Jun 23 15:02:11 porto dhcpcd[6810]: ppp0: ADV 2001:9e8:1be9:4d00::/56 from fe80::8a40:33ff:fe52:ea1b Jun 23 15:02:12 porto dhcpcd[6810]: ppp0: multicasting REQUEST6 (xid 0xb017b7), next in 1.0 seconds Jun 23 15:02:12 porto dhcpcd[6810]: ppp0: REPLY6 received from fe80::8a40:33ff:fe52:ea1b Jun 23 15:02:12 porto dhcpcd[6810]: ppp0: renew in 86400, rebind in 138240, expire in 259200 seconds Jun 23 15:02:12 porto dhcpcd[6810]: lo: adding reject route to 2001:9e8:1be9:4d00::/56 Jun 23 15:02:12 porto dhcpcd[6810]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6 Jun 23 15:02:12 porto dhcpcd[6810]: ppp0: delegated prefix 2001:9e8:1be9:4d00::/56 Jun 23 15:02:12 porto dhcpcd[6810]: bond0: adding address 2001:9e8:1be9:4d01::1/64 Jun 23 15:02:12 porto dhcpcd[6810]: bond0: pltime 172800 seconds, vltime 259200 seconds Jun 23 15:02:12 porto dhcpcd[6810]: bond0: waiting for DHCPv6 DAD to complete Jun 23 15:02:12 porto dhcpcd[6810]: wlan0: adding address 2001:9e8:1be9:4d02::1/64 Jun 23 15:02:12 porto dhcpcd[6810]: wlan0: pltime 172800 seconds, vltime 259200 seconds Jun 23 15:02:12 porto dhcpcd[6810]: wlan0: waiting for DHCPv6 DAD to complete Jun 23 15:02:12 porto dhcpcd[6810]: tap0: has no carrier, cannot delegate addresses Jun 23 15:02:12 porto dhcpcd[6810]: bond0: adding route to 2001:9e8:1be9:4d01::/64 Jun 23 15:02:12 porto dhcpcd[6810]: wlan0: adding route to 2001:9e8:1be9:4d02::/64 Jun 23 15:02:12 porto dhcpcd[6810]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks BOUND6 Jun 23 15:02:12 porto dhcpcd[6806]: forked to background Jun 23 15:02:13 porto dhcpcd[6810]: tap0: carrier acquired Jun 23 15:02:13 porto dhcpcd[6810]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 23 15:02:13 porto dhcpcd[6810]: tap0: IAID 35:a5:e7:5f Jun 23 15:02:13 porto dhcpcd[6810]: tap0: adding address fe80::f0fe:35ff:fea5:e75f Jun 23 15:02:13 porto dhcpcd[6810]: tap0: pltime infinity, vltime infinity Jun 23 15:02:13 porto dhcpcd[6810]: tap0: delaying adding delegated addresses for LL address Jun 23 15:02:13 porto dhcpcd[6810]: wlan0: DHCPv6 DAD completed Jun 23 15:02:13 porto dhcpcd[6810]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6 Jun 23 15:02:14 porto dhcpcd[6810]: bond0: DHCPv6 DAD completed Jun 23 15:02:14 porto dhcpcd[6810]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6 Jun 23 15:02:14 porto dhcpcd[6810]: tap0: adding delegated prefixes Jun 23 15:02:14 porto dhcpcd[6810]: tap0: adding address 2001:9e8:1be9:4d03::1/64 Jun 23 15:02:14 porto dhcpcd[6810]: tap0: pltime 172798 seconds, vltime 259198 seconds Jun 23 15:02:14 porto dhcpcd[6810]: tap0: adding route to 2001:9e8:1be9:4d03::/64 Jun 23 15:02:14 porto dhcpcd[6810]: tap0: waiting for DHCPv6 DAD to complete Jun 23 15:02:16 porto dhcpcd[6810]: tap0: DHCPv6 DAD completed Jun 23 15:02:16 porto dhcpcd[6810]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6

Jun 23 15:01:02 porto pppd[2220]: No response to 3 echo-requests Jun 23 15:01:02 porto pppd[2220]: Serial link appears to be disconnected. Jun 23 15:01:08 porto pppd[2220]: Connection terminated. Jun 23 15:01:08 porto pppd[2220]: Modem hangup Jun 23 15:01:48 porto pppd[2220]: Timeout waiting for PADO packets Jun 23 15:01:48 porto pppd[2220]: Unable to complete PPPoE Discovery phase 1 Jun 23 15:01:54 porto pppd[2220]: PPP session is 32885 Jun 23 15:01:54 porto pppd[2220]: Connected to 88:40:33:52:EA:1B via interface eth1 Jun 23 15:01:54 porto pppd[2220]: Using interface ppp0 Jun 23 15:01:54 porto pppd[2220]: Connect: ppp0 <--> eth1 Jun 23 15:01:56 porto pppd[2220]: Remote message: [UI-SBR:105401,37000;UI-LINEID:1UND1.DEU.DTAG.31NEU;] Jun 23 15:01:56 porto pppd[2220]: PAP authentication succeeded Jun 23 15:01:56 porto pppd[2220]: peer from calling number 88:40:33:52:EA:1B authorized Jun 23 15:01:56 porto pppd[2220]: local LL address fe80::e499:2699:15ac:31a0 Jun 23 15:01:56 porto pppd[2220]: remote LL address fe80::8a40:33ff:fe52:ea1b Jun 23 15:01:56 porto pppd[2220]: local IP address 92.116.242.208 Jun 23 15:01:56 porto pppd[2220]: remote IP address 94.134.199.140 Jun 23 15:01:56 porto pppd[2220]: primary DNS address 82.144.41.8 Jun 23 15:01:56 porto pppd[2220]: secondary DNS address 82.145.9.8

As it turns out in this case for whatever reason openrc will stop and restart dhdpcd and all dependent services. Which is why the prefix delegation works in this scenario. I guess this makes it more of an openrc issue and not directly related to the rebind problem.

rsmarples commented 3 weeks ago

@zogtogus @smlanger this might be fixed now in the latest master! Seems related to #333. Can you test the master branch please and let me know?

smlanger commented 3 weeks ago

@rsmarples took me a while to build a new image for my router but after building dhcpcd from latest master reconnecting ppp through SIGHUP appears to be working now:

Jun 24 23:14:03 porto dhcpcd[4310]: ppp0: carrier lost Jun 24 23:14:03 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 24 23:14:05 porto dhcpcd[4310]: bond0: deleting address 2001:9e8:1bf3:c401::1/64 Jun 24 23:14:05 porto dhcpcd[4310]: bond0: deleting route to 2001:9e8:1bf3:c401::/64 Jun 24 23:14:05 porto dhcpcd[4310]: wlan0: deleting address 2001:9e8:1bf3:c402::1/64 Jun 24 23:14:05 porto dhcpcd[4310]: wlan0: deleting route to 2001:9e8:1bf3:c402::/64 Jun 24 23:14:05 porto dhcpcd[4310]: tap0: deleting address 2001:9e8:1bf3:c403::1/64 Jun 24 23:14:05 porto dhcpcd[4310]: tap0: deleting route to 2001:9e8:1bf3:c403::/64 Jun 24 23:14:05 porto dhcpcd[4310]: lo: deleting reject route to 2001:9e8:1bf3:c400::/56 Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6 Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: deleting address 2001:9e8:3b:c718:40ba:1ef1:f666:f53e/64 Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: deleting route to 2001:9e8:3b:c718::/64 Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: deleting default route via fe80::8a40:33ff:fe52:ea1b Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: interface departed Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: removing interface Jun 24 23:14:05 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks DEPARTED Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: interface added Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: waiting for carrier Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: carrier acquired Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: IAID 70:70:70:30 Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: IA type 25 IAID 00:00:00:01 Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: delaying IPv6 Router Solicitation for LL address Jun 24 23:14:08 porto dhcpcd[4310]: ppp0: delaying DHCPv6 for LL address Jun 24 23:14:11 porto dhcpcd[4310]: ppp0: delaying IPv6 router solicitation for 0.9 seconds Jun 24 23:14:11 porto dhcpcd[4310]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6 Jun 24 23:14:11 porto dhcpcd[4310]: ppp0: rebinding prior DHCPv6 lease Jun 24 23:14:11 porto dhcpcd[4310]: ppp0: delaying REBIND6 (xid 0x8da407), next in 2.1 seconds Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: soliciting an IPv6 router Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: sending Router Solicitation Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: Router Advertisement from fe80::8a40:33ff:fe52:ea1b Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: adding address 2001:9e8:3b:c71d:79b0:eb2a:ac5a:e80c/64 Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: pltime 172800 seconds, vltime 259200 seconds Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: adding route to 2001:9e8:3b:c71d::/64 Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: adding default route via fe80::8a40:33ff:fe52:ea1b Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: waiting for Router Advertisement DAD to complete Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: Router Advertisement DAD completed Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT Jun 24 23:14:12 porto dhcpcd[4310]: ppp0: sending NA for 2001:9e8:3b:c71d:79b0:eb2a:ac5a:e80c/64 Jun 24 23:14:13 porto dhcpcd[4310]: ppp0: sending NA for 2001:9e8:3b:c71d:79b0:eb2a:ac5a:e80c/64 Jun 24 23:14:13 porto dhcpcd[4310]: ppp0: multicasting REBIND6 (xid 0x8da407), next in 1.1 seconds Jun 24 23:14:14 porto dhcpcd[4310]: ppp0: sending NA for 2001:9e8:3b:c71d:79b0:eb2a:ac5a:e80c/64 Jun 24 23:14:14 porto dhcpcd[4310]: ppp0: multicasting REBIND6 (xid 0x8da407), next in 2.1 seconds Jun 24 23:14:16 porto dhcpcd[4310]: ppp0: multicasting REBIND6 (xid 0x8da407), next in 4.3 seconds Jun 24 23:14:21 porto dhcpcd[4310]: ppp0: multicasting REBIND6 (xid 0x8da407), next in 4.0 seconds Jun 24 23:14:21 porto dhcpcd[4310]: ppp0: failed to rebind prior DHCPv6 delegation Jun 24 23:14:21 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6 Jun 24 23:14:21 porto dhcpcd[4310]: ppp0: soliciting a DHCPv6 lease Jun 24 23:14:21 porto dhcpcd[4310]: ppp0: delaying SOLICIT6 (xid 0x9d4411), next in 2.1 seconds Jun 24 23:14:23 porto dhcpcd[4310]: ppp0: multicasting SOLICIT6 (xid 0x9d4411), next in 1.0 seconds Jun 24 23:14:23 porto dhcpcd[4310]: ppp0: ADV 2001:9e8:1bf3:c600::/56 from fe80::8a40:33ff:fe52:ea1b Jun 24 23:14:24 porto dhcpcd[4310]: ppp0: multicasting REQUEST6 (xid 0x7ed903), next in 1.1 seconds Jun 24 23:14:24 porto dhcpcd[4310]: ppp0: REPLY6 received from fe80::8a40:33ff:fe52:ea1b Jun 24 23:14:24 porto dhcpcd[4310]: ppp0: renew in 86400, rebind in 138240, expire in 259200 seconds Jun 24 23:14:24 porto dhcpcd[4310]: lo: adding reject route to 2001:9e8:1bf3:c600::/56 Jun 24 23:14:24 porto dhcpcd[4310]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6 Jun 24 23:14:24 porto dhcpcd[4310]: ppp0: delegated prefix 2001:9e8:1bf3:c600::/56 Jun 24 23:14:24 porto dhcpcd[4310]: bond0: adding address 2001:9e8:1bf3:c601::1/64 Jun 24 23:14:24 porto dhcpcd[4310]: bond0: pltime 172800 seconds, vltime 259200 seconds Jun 24 23:14:24 porto dhcpcd[4310]: bond0: waiting for DHCPv6 DAD to complete Jun 24 23:14:24 porto dhcpcd[4310]: wlan0: adding address 2001:9e8:1bf3:c602::1/64 Jun 24 23:14:24 porto dhcpcd[4310]: wlan0: pltime 172800 seconds, vltime 259200 seconds Jun 24 23:14:24 porto dhcpcd[4310]: wlan0: waiting for DHCPv6 DAD to complete Jun 24 23:14:24 porto dhcpcd[4310]: tap0: adding address 2001:9e8:1bf3:c603::1/64 Jun 24 23:14:24 porto dhcpcd[4310]: tap0: pltime 172800 seconds, vltime 259200 seconds Jun 24 23:14:24 porto dhcpcd[4310]: tap0: waiting for DHCPv6 DAD to complete Jun 24 23:14:24 porto dhcpcd[4310]: bond0: adding route to 2001:9e8:1bf3:c601::/64 Jun 24 23:14:24 porto dhcpcd[4310]: tap0: adding route to 2001:9e8:1bf3:c603::/64 Jun 24 23:14:24 porto dhcpcd[4310]: wlan0: adding route to 2001:9e8:1bf3:c602::/64 Jun 24 23:14:24 porto dhcpcd[4310]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks BOUND6 Jun 24 23:14:26 porto dhcpcd[4310]: bond0: DHCPv6 DAD completed Jun 24 23:14:26 porto dhcpcd[4310]: bond0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6 Jun 24 23:14:26 porto dhcpcd[4310]: wlan0: DHCPv6 DAD completed Jun 24 23:14:26 porto dhcpcd[4310]: wlan0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6 Jun 24 23:14:26 porto dhcpcd[4310]: tap0: DHCPv6 DAD completed Jun 24 23:14:26 porto dhcpcd[4310]: tap0: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6

Jun 24 23:14:03 porto pppd[2221]: Hangup (SIGHUP) Jun 24 23:14:03 porto pppd[2221]: Connection terminated. Jun 24 23:14:08 porto pppd[2221]: PPP session is 4992 Jun 24 23:14:08 porto pppd[2221]: Connected to 88:40:33:52:EA:1B via interface eth1 Jun 24 23:14:08 porto pppd[2221]: Using interface ppp0 Jun 24 23:14:08 porto pppd[2221]: Connect: ppp0 <--> eth1 Jun 24 23:14:11 porto pppd[2221]: Remote message: [UI-SBR:105401,37000;UI-LINEID:1UND1.DEU.DTAG.31NEU;] Jun 24 23:14:11 porto pppd[2221]: PAP authentication succeeded Jun 24 23:14:11 porto pppd[2221]: peer from calling number 88:40:33:52:EA:1B authorized Jun 24 23:14:11 porto pppd[2221]: local LL address fe80::79b0:eb2a:ac5a:e80c Jun 24 23:14:11 porto pppd[2221]: remote LL address fe80::8a40:33ff:fe52:ea1b Jun 24 23:14:11 porto pppd[2221]: local IP address 92.116.242.9 Jun 24 23:14:11 porto pppd[2221]: remote IP address 94.134.199.140 Jun 24 23:14:11 porto pppd[2221]: primary DNS address 82.144.41.8 Jun 24 23:14:11 porto pppd[2221]: secondary DNS address 82.145.9.8

The only slightly annoying thing is the rebind failing and it getting a new lease but this might just be a problem with my ISP.

rsmarples commented 1 week ago

This should now be fixed in the master branch which has had numerous fixes for both PPP and Prefix Delegation.