search

NetworkConfiguration / dhcpcd

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

Failing to re-acquire ipv6 prefix via DHCP-PD after pppd restart #76

Closed corvus1 closed 2 years ago

corvus1 commented 2 years ago

I have dhcpcd getting ipv6 prefix over pppoe, and if pppd loses and regains the connection, dhcpcd is not getting a new v6 prefix until I manually restart it.

So I tried to add dhcpcd --rebind $1 to ip-up script and here's what happens.

ec  4 20:14:30 localhost dhcpcd[2868]: ppp0: libudev: add
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: interface added
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: waiting for carrier
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: carrier acquired
Dec  4 20:14:30 localhost pppd[3875]: CHAP authentication succeeded: (balance=0) Ok, M-PM-=M-PM-8M-QM-^GM-PM-5M-PM-3M-PM-> M-QM-^A M-PM-=M-PM-8M-PM-< M-PM-4M-PM-5M-PM-;M-PM-0M-QM-^BM-QM-^L M-PM-=M-PM-5 M-PM-=M-PM-0M-PM-4M-PM->.
Dec  4 20:14:30 localhost pppd[3875]: CHAP authentication succeeded
Dec  4 20:14:30 localhost pppd[3875]: peer from calling number 00:00:5E:00:01:82 authorized
Dec  4 20:14:30 localhost pppd[3875]: local  LL address fe80::a17a:7891:69a9:95e1
Dec  4 20:14:30 localhost pppd[3875]: remote LL address fe80::0ea4:02ff:fe16:cc01
Dec  4 20:14:30 localhost pppd[3875]: local  IP address 188.235.130.24
Dec  4 20:14:30 localhost pppd[3875]: remote IP address 31.131.203.254
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: IAID 70:70:70:30
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: IA type 25 IAID 00:00:00:01
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: delaying DHCPv6 for LL address
Dec  4 20:14:30 localhost dhcpcd[4455]: sending commands to dhcpcd process
Dec  4 20:14:30 localhost dhcpcd[2868]: control command: dhcpcd --rebind ppp0
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  4 20:14:30 localhost dhcpcd[4455]: send OK
Dec  4 20:14:30 localhost root[4458]: ip-up.d executed 123
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: soliciting a DHCPv6 lease
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: delaying SOLICIT6 (xid 0x5e57c8), next in 2.1 seconds
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: IAID 70:70:70:30
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: IA type 25 IAID 00:00:00:01
Dec  4 20:14:30 localhost dhcpcd[2868]: ppp0: delaying DHCPv6 for LL address
Dec  4 20:14:30 localhost dhcpcd[2868]: control_free: No such file or directory
Dec  4 20:14:31 localhost dhcpcd[4693]: sending commands to dhcpcd process
Dec  4 20:14:31 localhost dhcpcd[4693]: send OK
Dec  4 20:14:31 localhost dhcpcd[2868]: control command: dhcpcd --rebind ppp0
Dec  4 20:14:31 localhost dhcpcd[2868]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  4 20:14:31 localhost root[4695]: ip-up.d executed 123
Dec  4 20:14:31 localhost dhcpcd[2868]: ppp0: soliciting a DHCPv6 lease
Dec  4 20:14:31 localhost dhcpcd[2868]: ppp0: delaying SOLICIT6 (xid 0xa2a215), next in 2.2 seconds
Dec  4 20:14:31 localhost dhcpcd[2868]: ppp0: IAID 70:70:70:30
Dec  4 20:14:31 localhost dhcpcd[2868]: ppp0: IA type 25 IAID 00:00:00:01
Dec  4 20:14:31 localhost dhcpcd[2868]: ppp0: delaying DHCPv6 for LL address
Dec  4 20:14:31 localhost dhcpcd[2868]: control_free: No such file or directory
Dec  4 20:14:32 localhost ntpd[4775]: Listen normally on 44 ppp0 ..........
Dec  4 20:14:32 localhost ntpd[4775]: Listen normally on 45 ppp0 [fe80::a17a:7891:69a9:95e1%36]:123
Dec  4 20:14:33 localhost dhcpcd[2868]: ppp0: broadcasting SOLICIT6 (xid 0xa2a215), next in 1.1 seconds
Dec  4 20:14:33 localhost dhcpcd[2868]: ppp0: invalid state for DHCP6 type ADVERTISE6 (2)
Dec  4 20:14:34 localhost dhcpcd[2868]: ppp0: broadcasting SOLICIT6 (xid 0xa2a215), next in 2.1 seconds
Dec  4 20:14:34 localhost dhcpcd[2868]: ppp0: invalid state for DHCP6 type ADVERTISE6 (2)
Dec  4 20:14:36 localhost dhcpcd[2868]: ppp0: broadcasting SOLICIT6 (xid 0xa2a215), next in 3.9 seconds
Dec  4 20:14:36 localhost dhcpcd[2868]: ppp0: invalid state for DHCP6 type ADVERTISE6 (2)
Dec  4 20:14:40 localhost dhcpcd[2868]: ppp0: broadcasting SOLICIT6 (xid 0xa2a215), next in 8.0 seconds
Dec  4 20:14:40 localhost dhcpcd[2868]: ppp0: invalid state for DHCP6 type ADVERTISE6 (2)
Dec  4 20:14:48 localhost dhcpcd[2868]: ppp0: broadcasting SOLICIT6 (xid 0xa2a215), next in 16.2 seconds
Dec  4 20:14:48 localhost dhcpcd[2868]: ppp0: invalid state for DHCP6 type ADVERTISE6 (2)
Dec  4 20:15:04 localhost dhcpcd[2868]: ppp0: broadcasting SOLICIT6 (xid 0xa2a215), next in 30.7 seconds
Dec  4 20:15:04 localhost dhcpcd[2868]: ppp0: invalid state for DHCP6 type ADVERTISE6 (2)

Without dhcpcd --rebind in ip-up even that doesn't happen.

Then I do /etc/init.d/dhcpcd restart and it's all good again:

Dec  4 20:17:33 localhost dhcpcd[6082]: ppp0: delaying SOLICIT6 (xid 0xf48cfb), next in 2.1 seconds
Dec  4 20:17:35 localhost dhcpcd[6082]: ppp0: broadcasting SOLICIT6 (xid 0xf48cfb), next in 1.0 seconds
Dec  4 20:17:35 localhost dhcpcd[6082]: ppp0: ADV 2a02:2698:7006:edc::/64 from fe80::ea4:2ff:fe16:cc01
Dec  4 20:17:35 localhost dhcpcd[6082]: ppp0: broadcasting REQUEST6 (xid 0x3f927e), next in 1.0 seconds
Dec  4 20:17:35 localhost dhcpcd[6082]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec  4 20:17:35 localhost dhcpcd[6082]: ppp0: renew in 300, rebind in 400, expire in 600 seconds
rsmarples commented 2 years ago

I've looked through the code and I don't see how this can be possible. Can you add this patch please so dhcpcd reports what state it thinks it's in?

diff --git a/src/dhcp6.c b/src/dhcp6.c
index 72c37ec8..d24cbb71 100644
--- a/src/dhcp6.c
+++ b/src/dhcp6.c
@@ -3531,8 +3531,8 @@ dhcp6_recvif(struct interface *ifp, const char *sfrom,
                return;
        }
        if (!valid_op) {
-               logwarnx("%s: invalid state for DHCP6 type %s (%d)",
-                   ifp->name, op, r->type);
+               logwarnx("%s: invalid state (%d) for DHCP6 type %s (%d)",
+                   ifp->name, state->state, op, r->type);
                return;
        }
corvus1 commented 2 years ago

Certainly. Here's what I'm getting now:

Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: libudev: add
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: interface added
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: waiting for carrier
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: carrier acquired
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec  5 14:46:10 localhost pppd[18182]: CHAP authentication succeeded: (balance=0) Ok, M-PM-=M-PM-8M-QM-^GM-PM-5M-PM-3M-PM-> M-QM-^A M-PM-=M-PM-8M-PM-< M-PM-4M-PM-5M-PM-;M-PM-0M-QM-^BM-QM-^L M-PM-=M-PM-5 M-PM-=M-PM-0M-PM-4M-PM->.
Dec  5 14:46:10 localhost pppd[18182]: CHAP authentication succeeded
Dec  5 14:46:10 localhost pppd[18182]: peer from calling number 00:00:5E:00:01:82 authorized
Dec  5 14:46:10 localhost pppd[18182]: local  LL address fe80::9cf4:628f:481b:67c5
Dec  5 14:46:10 localhost pppd[18182]: remote LL address fe80::0ea4:02ff:fe16:cc01
Dec  5 14:46:10 localhost pppd[18182]: local  IP address .......
Dec  5 14:46:10 localhost pppd[18182]: remote IP address 31.131.203.254
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: IAID 70:70:70:30
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: delaying DHCPv6 for LL address
Dec  5 14:46:10 localhost dhcpcd[18585]: sending commands to dhcpcd process
Dec  5 14:46:10 localhost dhcpcd[18494]: control command: dhcpcd --rebind ppp0
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  5 14:46:10 localhost dhcpcd[18585]: send OK
Dec  5 14:46:10 localhost root[18590]: ip-up.d executed 123
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: soliciting a DHCPv6 lease
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: delaying SOLICIT6 (xid 0x2d7694), next in 2.2 seconds
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: IAID 70:70:70:30
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 14:46:10 localhost dhcpcd[18494]: ppp0: delaying DHCPv6 for LL address
Dec  5 14:46:11 localhost ntpd[4775]: Listen normally on 52 ppp0 .........:123
Dec  5 14:46:11 localhost ntpd[4775]: Listen normally on 53 ppp0 [fe80::9cf4:628f:481b:67c5%42]:123
Dec  5 14:46:12 localhost dhcpcd[19036]: sending commands to dhcpcd process
Dec  5 14:46:12 localhost dhcpcd[18494]: control command: dhcpcd --rebind ppp0
Dec  5 14:46:12 localhost dhcpcd[19036]: send OK
Dec  5 14:46:12 localhost dhcpcd[18494]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  5 14:46:12 localhost root[19038]: ip-up.d executed 123
Dec  5 14:46:12 localhost dhcpcd[18494]: ppp0: soliciting a DHCPv6 lease
Dec  5 14:46:12 localhost dhcpcd[18494]: ppp0: delaying SOLICIT6 (xid 0x72ea17), next in 2.1 seconds
Dec  5 14:46:12 localhost dhcpcd[18494]: ppp0: IAID 70:70:70:30
Dec  5 14:46:12 localhost dhcpcd[18494]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 14:46:12 localhost dhcpcd[18494]: ppp0: delaying DHCPv6 for LL address
Dec  5 14:46:14 localhost dhcpcd[18494]: ppp0: broadcasting SOLICIT6 (xid 0x72ea17), next in 1.0 seconds
Dec  5 14:46:14 localhost dhcpcd[18494]: dhcp6_sendmessage: ppp0: sendmsg: Bad file descriptor
Dec  5 14:46:15 localhost dhcpcd[18494]: ppp0: broadcasting SOLICIT6 (xid 0x72ea17), next in 2.2 seconds
Dec  5 14:46:15 localhost dhcpcd[18494]: dhcp6_sendmessage: ppp0: sendmsg: Bad file descriptor
Dec  5 14:46:17 localhost dhcpcd[18494]: ppp0: broadcasting SOLICIT6 (xid 0x72ea17), next in 4.6 seconds
Dec  5 14:46:17 localhost dhcpcd[18494]: dhcp6_sendmessage: ppp0: sendmsg: Bad file descriptor
Dec  5 14:46:22 localhost dhcpcd[18494]: ppp0: broadcasting SOLICIT6 (xid 0x72ea17), next in 8.9 seconds
Dec  5 14:46:22 localhost dhcpcd[18494]: dhcp6_sendmessage: ppp0: sendmsg: Bad file descriptor
Dec  5 14:46:23 localhost dhcpcd[18494]: timed out
Dec  5 14:46:31 localhost dhcpcd[18494]: ppp0: broadcasting SOLICIT6 (xid 0x72ea17), next in 17.3 seconds
Dec  5 14:46:31 localhost dhcpcd[18494]: dhcp6_sendmessage: ppp0: sendmsg: Bad file descriptor
corvus1 commented 2 years ago

By the way, what version of dhcpcd is this patch aimed at? It failed to apply, I opened the file by hand and sorta finagled it in. Tried 9.4.1 and 9999 live from github.

rsmarples commented 2 years ago

dhcp6_sendmessage: ppp0: sendmsg: Bad file descriptor

That imples something else holds the DHCP6 port open. Are there any stale dhcpcd processes? Lets stick with 9.4.1 (specifically the dhcpcd-9 branch here) for now here's a patch for that:

diff --git a/src/dhcp6.c b/src/dhcp6.c
index 21198c42..3bf2d9d5 100644
--- a/src/dhcp6.c
+++ b/src/dhcp6.c
@@ -3531,8 +3531,8 @@ dhcp6_recvif(struct interface *ifp, const char *sfrom,
                return;
        }
        if (!valid_op) {
-               logwarnx("%s: invalid state for DHCP6 type %s (%d)",
-                   ifp->name, op, r->type);
+               logwarnx("%s: invalid state (%d) for DHCP6 type %s (%d)",
+                   ifp->name, state->state, op, r->type);
                return;
        }

Looks the same as the above? How is dhcpcd compiled please? show output of dhcpcd --version.

corvus1 commented 2 years ago

Hang on, it's exactly the same patch. It also fails to apply.

In dhcp6.c I have:

<------>default:
<------><------>logerrx("%s: invalid DHCP6 type %s (%d)",
<------><------>    ifp->name, op, r->type);
<------><------>return;
<------>}
<------>if (!valid_op) {
<------><------>logwarnx("%s: invalid state for DHCP6 type %s (%d)",
<------><------>    ifp->name, op, r->type);
<------><------>return;
<------>}

I can edit it by hand, although it's a bit annoying.

There's no stale processes. ps ax | grep dhcpcd shows only one 23299 ? S 0:00 dhcpcd: [manager] [ip6]

dhcpcd --version
dhcpcd 9.4.1
Copyright (c) 2006-2021 Roy Marples
Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH
rsmarples commented 2 years ago

Ok, so you're not using privsep but you are running in manager mode. The patch might be failing due to whitespace due to me pasting the patch? You might need the -l option to the patch command. I'd also like to see logs of when dhcpcd starts as there could be an error opening the DHCP6 port which is implied by your 2nd log.

corvus1 commented 2 years ago

Logs at starting dhcpcd:

Dec  5 15:30:08 localhost dhcpcd[23926]: received SIGTERM, stopping
Dec  5 15:30:08 localhost dhcpcd[23926]: ppp0: removing interface
Dec  5 15:30:08 localhost dhcpcd[23926]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED
Dec  5 15:30:08 localhost dhcpcd[23926]: lan5: removing interface
Dec  5 15:30:08 localhost dhcpcd[23926]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED
Dec  5 15:30:08 localhost dhcpcd[23926]: dev: unloaded udev
Dec  5 15:30:08 localhost dhcpcd[23926]: dhcpcd exited
Dec  5 15:30:09 localhost dhcpcd[24605]: dhcpcd-9.4.1 starting
Dec  5 15:30:09 localhost dhcpcd[24607]: spawned manager process on PID 24607
Dec  5 15:30:09 localhost dhcpcd[24607]: udev: starting
Dec  5 15:30:09 localhost dhcpcd[24607]: dev: loaded udev
Dec  5 15:30:09 localhost dhcpcd[24607]: DUID 00:01:00:01:1a:91:fd:69:64:66:b3:05:74:70
Dec  5 15:30:09 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec  5 15:30:09 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec  5 15:30:09 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec  5 15:30:09 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec  5 15:30:09 localhost dhcpcd[24607]: lan5: IAID 4d:82:b5:af
Dec  5 15:30:09 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec  5 15:30:09 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 15:30:09 localhost dhcpcd[24607]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:30:09 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:30:09 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0x3575ee), next in 2.1 seconds
Dec  5 15:30:11 localhost dhcpcd[24607]: ppp0: broadcasting REBIND6 (xid 0x3575ee), next in 1.1 seconds
Dec  5 15:30:11 localhost dhcpcd[24607]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec  5 15:30:11 localhost dhcpcd[24607]: ppp0: renew in 1800, rebind in 2880, expire in 86400 seconds
Dec  5 15:30:11 localhost dhcpcd[24607]: lo: adding reject route to 2a02:2698:7006:e11::/64
Dec  5 15:30:11 localhost dhcpcd[24607]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:30:11 localhost dhcpcd[24607]: ppp0: delegated prefix 2a02:2698:7006:e11::/64
Dec  5 15:30:11 localhost dhcpcd[24607]: lan5: adding address 2a02:2698:7006:e11::1/64
Dec  5 15:30:11 localhost dhcpcd[24607]: lan5: pltime 3600 seconds, vltime 86400 seconds
Dec  5 15:30:11 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Dec  5 15:30:11 localhost dhcpcd[24607]: lan5: adding route to 2a02:2698:7006:e11::/64
Dec  5 15:30:11 localhost dhcpcd[24607]: lo: deleting reject route to 2a02:2698:7006:e11::/64
Dec  5 15:30:11 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6

and:

 * Starting DHCP Client Daemon ...
dhcpcd-9.4.1 starting
spawned manager process on PID 24607
udev: starting
dev: loaded udev
DUID 00:01:00:01:1a:91:fd:69:64:66:b3:05:74:70
lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
++ case "$reason" in
lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
++ case "$reason" in
ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
++ case "$reason" in
ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
++ case "$reason" in
lan5: IAID 4d:82:b5:af
ppp0: IAID 70:70:70:30
ppp0: IA type 25 IAID 00:00:00:01
ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
ppp0: rebinding prior DHCPv6 lease
ppp0: delaying REBIND6 (xid 0x3575ee), next in 2.1 seconds
ppp0: broadcasting REBIND6 (xid 0x3575ee), next in 1.1 seconds
ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
ppp0: renew in 1800, rebind in 2880, expire in 86400 seconds
lo: adding reject route to 2a02:2698:7006:e11::/64
ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
ppp0: delegated prefix 2a02:2698:7006:e11::/64
lan5: adding address 2a02:2698:7006:e11::1/64
lan5: pltime 3600 seconds, vltime 86400 seconds
lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
++ case "$reason" in
lan5: adding route to 2a02:2698:7006:e11::/64
lo: deleting reject route to 2a02:2698:7006:e11::/64
ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
++ case "$reason" in

Seems good to me.

rsmarples commented 2 years ago

Yes, looks good. Now issue a few rebinds in a row dhcpcd --rebind ppp0 and see what happens.

corvus1 commented 2 years ago 
Dec  5 15:35:34 localhost dhcpcd[24646]: sending commands to dhcpcd process
Dec  5 15:35:34 localhost dhcpcd[24646]: send OK
Dec  5 15:35:34 localhost dhcpcd[24607]: control command: dhcpcd --rebind ppp0
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0xd11351), next in 2.1 seconds
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:35:34 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0x678f08), next in 2.0 seconds
Dec  5 15:35:34 localhost dhcpcd[24607]: control_free: No such file or directory
Dec  5 15:35:36 localhost dhcpcd[24607]: ppp0: broadcasting REBIND6 (xid 0x678f08), next in 1.1 seconds
Dec  5 15:35:36 localhost dhcpcd[24607]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec  5 15:35:36 localhost dhcpcd[24607]: ppp0: renew in 1800, rebind in 2880, expire in 86400 seconds
Dec  5 15:35:36 localhost dhcpcd[24607]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:35:36 localhost dhcpcd[24607]: ppp0: delegated prefix 2a02:2698:7006:e11::/64
Dec  5 15:35:36 localhost dhcpcd[24607]: lan5: adding address 2a02:2698:7006:e11::1/64
Dec  5 15:35:36 localhost dhcpcd[24607]: lan5: pltime 3600 seconds, vltime 86400 seconds
Dec  5 15:35:36 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Dec  5 15:35:36 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
Dec  5 15:35:46 localhost dhcpcd[24677]: sending commands to dhcpcd process
Dec  5 15:35:46 localhost dhcpcd[24677]: send OK
Dec  5 15:35:46 localhost dhcpcd[24607]: control command: dhcpcd --rebind ppp0
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0x909c36), next in 2.1 seconds
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:35:46 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0xa4b80d), next in 2.1 seconds
Dec  5 15:35:46 localhost dhcpcd[24607]: control_free: No such file or directory
Dec  5 15:35:48 localhost dhcpcd[24607]: ppp0: broadcasting REBIND6 (xid 0xa4b80d), next in 1.0 seconds
Dec  5 15:35:48 localhost dhcpcd[24607]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec  5 15:35:48 localhost dhcpcd[24607]: ppp0: renew in 1800, rebind in 2880, expire in 86400 seconds
Dec  5 15:35:48 localhost dhcpcd[24607]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:35:48 localhost dhcpcd[24607]: ppp0: delegated prefix 2a02:2698:7006:e11::/64
Dec  5 15:35:48 localhost dhcpcd[24607]: lan5: adding address 2a02:2698:7006:e11::1/64
Dec  5 15:35:48 localhost dhcpcd[24607]: lan5: pltime 3600 seconds, vltime 86400 seconds
Dec  5 15:35:48 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Dec  5 15:35:48 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
Dec  5 15:35:52 localhost dhcpcd[24710]: sending commands to dhcpcd process
Dec  5 15:35:52 localhost dhcpcd[24607]: control command: dhcpcd --rebind ppp0
Dec  5 15:35:52 localhost dhcpcd[24710]: send OK
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0x867243), next in 2.2 seconds
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:35:52 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0xe7f6ba), next in 2.0 seconds
Dec  5 15:35:52 localhost dhcpcd[24607]: control_free: No such file or directory
Dec  5 15:35:54 localhost dhcpcd[24607]: ppp0: broadcasting REBIND6 (xid 0xe7f6ba), next in 1.1 seconds
Dec  5 15:35:54 localhost dhcpcd[24607]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec  5 15:35:54 localhost dhcpcd[24607]: ppp0: renew in 1800, rebind in 2880, expire in 86400 seconds
Dec  5 15:35:54 localhost dhcpcd[24607]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:35:54 localhost dhcpcd[24607]: ppp0: delegated prefix 2a02:2698:7006:e11::/64
Dec  5 15:35:54 localhost dhcpcd[24607]: lan5: adding address 2a02:2698:7006:e11::1/64
Dec  5 15:35:54 localhost dhcpcd[24607]: lan5: pltime 3600 seconds, vltime 86400 seconds
Dec  5 15:35:54 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Dec  5 15:35:54 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
Dec  5 15:36:03 localhost dhcpcd[24739]: sending commands to dhcpcd process
Dec  5 15:36:03 localhost dhcpcd[24607]: control command: dhcpcd --rebind ppp0
Dec  5 15:36:03 localhost dhcpcd[24739]: send OK
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0xbcf277), next in 2.1 seconds
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:36:03 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0xf8ab56), next in 2.2 seconds
Dec  5 15:36:03 localhost dhcpcd[24607]: control_free: No such file or directory
Dec  5 15:36:04 localhost dhcpcd[24749]: sending commands to dhcpcd process
Dec  5 15:36:04 localhost dhcpcd[24607]: control command: dhcpcd --rebind ppp0
Dec  5 15:36:04 localhost dhcpcd[24749]: send OK
Dec  5 15:36:04 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
Dec  5 15:36:05 localhost dhcpcd[24607]: lan5: deleting address 2a02:2698:7006:e11::1/64
Dec  5 15:36:05 localhost dhcpcd[24607]: lan5: deleting route to 2a02:2698:7006:e11::/64
Dec  5 15:36:05 localhost dhcpcd[24607]: ppp0: soliciting a DHCPv6 lease
Dec  5 15:36:05 localhost dhcpcd[24607]: ppp0: delaying SOLICIT6 (xid 0x6d66c0), next in 2.1 seconds
Dec  5 15:36:05 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec  5 15:36:05 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec  5 15:36:05 localhost dhcpcd[24607]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:36:05 localhost dhcpcd[24607]: ppp0: rebinding prior DHCPv6 lease
Dec  5 15:36:05 localhost dhcpcd[24607]: ppp0: delaying REBIND6 (xid 0xea1cea), next in 2.1 seconds
Dec  5 15:36:05 localhost dhcpcd[24607]: control_free: No such file or directory
Dec  5 15:36:06 localhost ntpd[4775]: Deleting interface #57 lan5, 2a02:2698:7006:e11::1#123, interface stats: received=0, sent=0, dropped=0, active_time=892 secs
Dec  5 15:36:07 localhost dhcpcd[24607]: ppp0: broadcasting REBIND6 (xid 0xea1cea), next in 1.1 seconds
Dec  5 15:36:07 localhost dhcpcd[24607]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec  5 15:36:07 localhost dhcpcd[24607]: ppp0: renew in 1800, rebind in 2880, expire in 86400 seconds
Dec  5 15:36:07 localhost dhcpcd[24607]: lo: adding reject route to 2a02:2698:7006:e11::/64
Dec  5 15:36:07 localhost dhcpcd[24607]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Dec  5 15:36:07 localhost dhcpcd[24607]: ppp0: delegated prefix 2a02:2698:7006:e11::/64
Dec  5 15:36:07 localhost dhcpcd[24607]: lan5: adding address 2a02:2698:7006:e11::1/64
Dec  5 15:36:07 localhost dhcpcd[24607]: lan5: pltime 3600 seconds, vltime 86400 seconds
Dec  5 15:36:07 localhost dhcpcd[24607]: lan5: waiting for DHCPv6 DAD to complete
Dec  5 15:36:07 localhost dhcpcd[24607]: lan5: adding route to 2a02:2698:7006:e11::/64
Dec  5 15:36:07 localhost dhcpcd[24607]: lo: deleting reject route to 2a02:2698:7006:e11::/64
Dec  5 15:36:07 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
Dec  5 15:36:08 localhost dhcpcd[24607]: lan5: DHCPv6 DAD completed
Dec  5 15:36:08 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6

I'm not sure what control_free: No such file or directory is, but otherwise it's rebinding just fine. The issue appears if I restart ppp0, then it doesn't want to rebind.

rsmarples commented 2 years ago

The control_free is a nonsenence error which won't be reported in future versions.

What happens if you restart ppp0 without rebinding dhcpcd? Hopefully ppp0 will be remove and then be re-added which dhcpcd will spot and do the right thing. I can't seem to replicate this at my end using ppp on a linux image.

corvus1 commented 2 years ago 
Dec 19 16:38:06 localhost start-stop-daemon[17975]: Will stop /usr/sbin/pppd
Dec 19 16:38:06 localhost start-stop-daemon[17975]: Will stop PID 23048
Dec 19 16:38:06 localhost start-stop-daemon[17975]: Sending signal 15 to PID 23048
Dec 19 16:38:06 localhost pppd[23048]: Terminating on signal 15
Dec 19 16:38:06 localhost pppd[23048]: Connect time 20240.2 minutes.
Dec 19 16:38:06 localhost pppd[23048]: Sent 1296579790 bytes, received 1154121180 bytes.
Dec 19 16:38:06 localhost dhcpcd[24607]: ppp0: carrier lost
Dec 19 16:38:06 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Dec 19 16:38:07 localhost kernel: device ppp0 left promiscuous mode
Dec 19 16:38:07 localhost pppd[23048]: Connection terminated.
Dec 19 16:38:07 localhost pppd[23048]: Connect time 20240.2 minutes.
Dec 19 16:38:07 localhost pppd[23048]: Sent 1296579790 bytes, received 1154121180 bytes.
Dec 19 16:38:07 localhost dhcpcd[24607]: lan5: deleting address 2a02:2698:7006:e11::1/64
Dec 19 16:38:07 localhost dhcpcd[24607]: lo: adding reject route to 2a02:2698:7006:e11::/64
Dec 19 16:38:07 localhost dhcpcd[24607]: lan5: deleting route to 2a02:2698:7006:e11::/64
Dec 19 16:38:07 localhost dhcpcd[24607]: lo: deleting reject route to 2a02:2698:7006:e11::/64
Dec 19 16:38:07 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6
Dec 19 16:38:07 localhost pppd[23048]: Exit.
Dec 19 16:38:07 localhost dhcpcd[24607]: ppp0: libudev: remove
Dec 19 16:38:07 localhost dhcpcd[24607]: ppp0: interface departed
Dec 19 16:38:07 localhost dhcpcd[24607]: ppp0: removing interface
Dec 19 16:38:07 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks DEPARTED
Dec 19 16:38:08 localhost pppd[18322]: Plugin pppoe.so loaded.
Dec 19 16:38:08 localhost pppd[18322]: PPPoE plugin from pppd 2.4.9
Dec 19 16:38:08 localhost pppd[18322]: Plugin passwordfd.so loaded.
Dec 19 16:38:08 localhost pppd[18323]: pppd 2.4.9 started by corvus, uid 0
Dec 19 16:38:08 localhost ntpd[4775]: Deleting interface #55 ppp0, 188.235.130.24#123, interface stats: received=5394, sent=4746, dropped=0, active_time=1214406 secs
Dec 19 16:38:08 localhost ntpd[4775]: 193.192.36.3 local addr 188.235.130.24 -> <null>
Dec 19 16:38:08 localhost ntpd[4775]: 194.58.205.20 local addr 188.235.130.24 -> <null>
Dec 19 16:38:08 localhost ntpd[4775]: 217.180.209.214 local addr 188.235.130.24 -> <null>
Dec 19 16:38:08 localhost ntpd[4775]: 94.154.96.7 local addr 188.235.130.24 -> <null>
Dec 19 16:38:08 localhost ntpd[4775]: Deleting interface #56 ppp0, fe80::d188:3404:d9d3:a664%44#123, interface stats: received=0, sent=0, dropped=0, active_time=1214406 secs
Dec 19 16:38:08 localhost ntpd[4775]: Deleting interface #58 lan5, 2a02:2698:7006:e11::1#123, interface stats: received=0, sent=0, dropped=0, active_time=1213319 secs
Dec 19 16:38:08 localhost pppd[18323]: PPP session is 2
Dec 19 16:38:08 localhost pppd[18323]: Connected to 00:00:5e:00:01:82 via interface lan4
Dec 19 16:38:08 localhost pppd[18323]: Using interface ppp0
Dec 19 16:38:08 localhost pppd[18323]: Connect: ppp0 <--> lan4
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: libudev: add
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: interface added
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Dec 19 16:38:08 localhost pppd[18323]: CHAP authentication succeeded: (balance=0) Ok, M-PM-=M-PM-8M-QM-^GM-PM-5M-PM-3M-PM-> M-QM-^A M-PM-=M-PM-8M-PM-< M-PM-4M-PM-5M-PM-;M-PM-0M-QM-^BM-QM-^L M-PM-=M-PM-5 M-PM-=M-PM-0M-PM-4M-PM->.
Dec 19 16:38:08 localhost pppd[18323]: CHAP authentication succeeded
Dec 19 16:38:08 localhost pppd[18323]: peer from calling number 00:00:5E:00:01:82 authorized
Dec 19 16:38:08 localhost pppd[18323]: local  LL address fe80::8c26:f06d:cec2:0f7d
Dec 19 16:38:08 localhost pppd[18323]: remote LL address fe80::0ea4:02ff:fe16:cc01
Dec 19 16:38:08 localhost pppd[18323]: LCP terminated by peer
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: waiting for carrier
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: carrier acquired
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: delaying DHCPv6 for LL address
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: carrier lost
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: carrier acquired
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec 19 16:38:08 localhost dhcpcd[24607]: ppp0: delaying DHCPv6 for LL address
Dec 19 16:38:09 localhost root[18583]: ip-up.d executed 123
Dec 19 16:38:11 localhost pppd[18323]: Modem hangup
Dec 19 16:38:11 localhost pppd[18323]: Connection terminated.
Dec 19 16:38:11 localhost pppd[18323]: Connect time 0.0 minutes.
Dec 19 16:38:11 localhost pppd[18323]: Sent 210 bytes, received 58 bytes.
Dec 19 16:38:11 localhost dhcpcd[24607]: ppp0: carrier lost
Dec 19 16:38:11 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Dec 19 16:38:11 localhost dhcpcd[24607]: ppp0: libudev: remove
Dec 19 16:38:11 localhost dhcpcd[24607]: ppp0: interface departed
Dec 19 16:38:11 localhost dhcpcd[24607]: ppp0: removing interface
Dec 19 16:38:11 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks DEPARTED
Dec 19 16:38:21 localhost pppd[18323]: PPP session is 1
Dec 19 16:38:21 localhost pppd[18323]: Connected to 00:00:5e:00:01:82 via interface lan4
Dec 19 16:38:21 localhost pppd[18323]: Using interface ppp0
Dec 19 16:38:21 localhost pppd[18323]: Connect: ppp0 <--> lan4
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: libudev: add
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: interface added
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: waiting for carrier
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: carrier acquired
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec 19 16:38:21 localhost pppd[18323]: CHAP authentication succeeded: (balance=0) Ok, M-PM-=M-PM-8M-QM-^GM-PM-5M-PM-3M-PM-> M-QM-^A M-PM-=M-PM-8M-PM-< M-PM-4M-PM-5M-PM-;M-PM-0M-QM-^BM-QM-^L M-PM-=M-PM-5 M-PM-=M-PM-0M-PM-4M-PM->.
Dec 19 16:38:21 localhost pppd[18323]: CHAP authentication succeeded
Dec 19 16:38:21 localhost pppd[18323]: peer from calling number 00:00:5E:00:01:82 authorized
Dec 19 16:38:21 localhost pppd[18323]: local  LL address fe80::ecbe:2a8b:32ec:d518
Dec 19 16:38:21 localhost pppd[18323]: remote LL address fe80::0ea4:02ff:fe16:cc01
Dec 19 16:38:21 localhost pppd[18323]: local  IP address 188.235.130.24
Dec 19 16:38:21 localhost pppd[18323]: remote IP address 31.131.203.254
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: IAID 70:70:70:30
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: IA type 25 IAID 00:00:00:01
Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: delaying DHCPv6 for LL address
Dec 19 16:38:21 localhost root[18891]: ip-up.d executed 123
Dec 19 16:38:22 localhost root[19110]: ip-up.d executed 123
Dec 19 16:38:23 localhost ntpd[4775]: Listen normally on 59 ppp0 188.235.130.24:123
Dec 19 16:38:23 localhost ntpd[4775]: Listen normally on 60 ppp0 [fe80::ecbe:2a8b:32ec:d518%46]:123

And it seems to just sit there doing nothing. No ipv6 addresses assigned. Then, if I restart dhcpcd, then it does the right thing:

Dec 19 16:40:01 localhost CROND[19113]: (root) CMD (test -x /usr/sbin/run-crons && /usr/sbin/run-crons )
Dec 19 16:40:01 localhost CROND[19112]: (root) CMDEND (test -x /usr/sbin/run-crons && /usr/sbin/run-crons )
Dec 19 16:40:24 localhost start-stop-daemon[19150]: Will stop /sbin/dhcpcd
Dec 19 16:40:24 localhost start-stop-daemon[19150]: Will stop PID 24607
Dec 19 16:40:24 localhost start-stop-daemon[19150]: Sending signal 15 to PID 24607
Dec 19 16:40:24 localhost dhcpcd[24607]: received SIGTERM, stopping
Dec 19 16:40:24 localhost dhcpcd[24607]: ppp0: removing interface
Dec 19 16:40:24 localhost dhcpcd[24607]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED
Dec 19 16:40:24 localhost dhcpcd[24607]: lan5: removing interface
Dec 19 16:40:24 localhost dhcpcd[24607]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks STOPPED
Dec 19 16:40:24 localhost dhcpcd[24607]: dev: unloaded udev
Dec 19 16:40:24 localhost dhcpcd[24607]: dhcpcd exited
Dec 19 16:40:25 localhost dhcpcd[19185]: dhcpcd-9.4.1 starting
Dec 19 16:40:25 localhost dhcpcd[19187]: spawned manager process on PID 19187
Dec 19 16:40:25 localhost dhcpcd[19187]: udev: starting
Dec 19 16:40:25 localhost dhcpcd[19187]: dev: loaded udev
Dec 19 16:40:25 localhost dhcpcd[19187]: DUID 00:01:00:01:1a:91:fd:69:64:66:b3:05:74:70
Dec 19 16:40:25 localhost dhcpcd[19187]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec 19 16:40:25 localhost dhcpcd[19187]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec 19 16:40:25 localhost dhcpcd[19187]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Dec 19 16:40:25 localhost dhcpcd[19187]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Dec 19 16:40:25 localhost dhcpcd[19187]: lan5: IAID 4d:82:b5:af
Dec 19 16:40:25 localhost dhcpcd[19187]: ppp0: IAID 70:70:70:30
Dec 19 16:40:25 localhost dhcpcd[19187]: ppp0: IA type 25 IAID 00:00:00:01
Dec 19 16:40:25 localhost dhcpcd[19187]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Dec 19 16:40:25 localhost dhcpcd[19187]: ppp0: rebinding prior DHCPv6 lease
Dec 19 16:40:25 localhost dhcpcd[19187]: ppp0: delaying REBIND6 (xid 0x4fe4a7), next in 2.1 seconds
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: broadcasting REBIND6 (xid 0x4fe4a7), next in 1.1 seconds
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: 2a02:2698:7006:e11::/64: no valid lifetime
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: will expire
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: DHCPv6 lease expired
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: soliciting a DHCPv6 lease
Dec 19 16:40:27 localhost dhcpcd[19187]: ppp0: delaying SOLICIT6 (xid 0xd5319a), next in 2.2 seconds
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: broadcasting SOLICIT6 (xid 0xd5319a), next in 1.0 seconds
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: ADV 2a02:2698:7006:a3f::/64 from fe80::ea4:2ff:fe16:cc01
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: broadcasting REQUEST6 (xid 0x242355), next in 1.1 seconds
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: REPLY6 received from fe80::ea4:2ff:fe16:cc01
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: renew in 300, rebind in 400, expire in 600 seconds
Dec 19 16:40:29 localhost dhcpcd[19187]: lo: adding reject route to 2a02:2698:7006:a3f::/64
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: delegated prefix 2a02:2698:7006:a3f::/64
Dec 19 16:40:29 localhost dhcpcd[19187]: lan5: adding address 2a02:2698:7006:a3f::1/64
Dec 19 16:40:29 localhost dhcpcd[19187]: lan5: pltime 600 seconds, vltime 600 seconds
Dec 19 16:40:29 localhost dhcpcd[19187]: lan5: waiting for DHCPv6 DAD to complete
Dec 19 16:40:29 localhost dhcpcd[19187]: lan5: adding route to 2a02:2698:7006:a3f::/64
Dec 19 16:40:29 localhost dhcpcd[19187]: lo: deleting reject route to 2a02:2698:7006:a3f::/64
Dec 19 16:40:29 localhost dhcpcd[19187]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks BOUND6
Dec 19 16:40:29 localhost start-stop-daemon[19242]: Will stop /usr/sbin/radvd
Dec 19 16:40:29 localhost start-stop-daemon[19242]: Will stop PID 24020
Dec 19 16:40:29 localhost start-stop-daemon[19242]: Sending signal 15 to PID 24020
Dec 19 16:40:29 localhost radvd[24020]: exiting, 1 sigterm(s) received
Dec 19 16:40:29 localhost radvd[24020]: sending stop adverts
Dec 19 16:40:29 localhost radvd[24020]: removing /run/radvd/radvd.pid
Dec 19 16:40:29 localhost radvd[24020]: returning from radvd main
Dec 19 16:40:29 localhost radvd[24021]: Exiting, privsep_read_loop had readn return 0 bytes
Dec 19 16:40:29 localhost radvd[24021]: Exiting, privsep_read_loop is complete.
Dec 19 16:40:29 localhost radvd[19280]: version 2.19 started
Dec 19 16:40:32 localhost ntpd[4775]: Listen normally on 61 lan5 [2a02:2698:7006:a3f::1]:123
Dec 19 16:40:32 localhost start-stop-daemon[19581]: Will stop PID 24351
Dec 19 16:40:32 localhost /etc/init.d/darkstat[19581]: start-stop-daemon: no matching processes found
Dec 19 16:40:32 localhost kernel: device ppp0 entered promiscuous mode
Dec 19 16:40:34 localhost dhcpcd[19187]: lan5: DHCPv6 DAD completed
Dec 19 16:40:34 localhost dhcpcd[19187]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
rsmarples commented 2 years ago

Dec 19 16:38:21 localhost dhcpcd[24607]: ppp0: delaying DHCPv6 for LL address That is the last line from dhcpcd. But we had this earlier Dec 19 16:38:21 localhost pppd[18323]: local LL address fe80::ecbe:2a8b:32ec:d518

This means the address was added and likely had the TENTATIVE marker or another flag dhcpcd didn't like. So dhcpcd is waiting for this to clear. Let us see what another program thinks is happening. Can you run ip monitor in another terminal and then restart ppp0 please? We're just interested in ALL address messages on ppp0.

corvus1 commented 2 years ago 
router2 /home/corvus # ip monitor
2a02:2698:7006:a3f:1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 PROBE
2a02:2698:7006:a3f:1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 REACHABLE
Deleted default dev ppp0 scope link metric 4007 
Deleted 46: ppp0    inet 188.235.130.24 peer 31.131.203.254/32 scope global ppp0
       valid_lft forever preferred_lft forever
Deleted 31.131.203.254 dev ppp0 proto kernel scope link src 188.235.130.24 
Deleted local 188.235.130.24 dev ppp0 table local proto kernel scope host src 188.235.130.24 
Deleted 0.0.0.0 dev ppp0 lladdr 08 NOARP
Deleted 46: ppp0    inet6 fe80::ecbe:2a8b:32ec:d518 peer fe80::ea4:2ff:fe16:cc01/128 scope link 
       valid_lft forever preferred_lft forever
Deleted fe80::ea4:2ff:fe16:cc01 dev ppp0 proto kernel metric 256 pref medium
Deleted local fe80::ecbe:2a8b:32ec:d518 dev ppp0 table local proto kernel metric 0 pref medium
Deleted fe80::ecbe:2a8b:32ec:d518 dev ppp0 proto kernel metric 256 pref medium
46: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc pfifo_fast state DOWN group default 
    link/ppp 
Deleted default dev ppp0 metric 1024 pref medium
Deleted multicast ff00::/8 dev ppp0 table local proto kernel metric 256 pref medium
Deleted 2001:41d0:c:5ac:5::1 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0f::71 dev ppp0 lladdr 08 NOARP
Deleted 2a02:752:0:18::128 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4001:5d::a dev ppp0 lladdr 08 NOARP
Deleted 2001:b011:2003:df22:79:90ac:8aae:8bf8 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c02::13 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c05::77 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4011:55::1b dev ppp0 lladdr 08 NOARP
Deleted 2401:4900:30c7:30cd:5926:c15a:a55d:638d dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c1e::5e dev ppp0 lladdr 08 NOARP
Deleted 2400:2653:8d80:4000:8805:8aa:fe22:6b9d dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c08::5f dev ppp0 lladdr 08 NOARP
Deleted 2409:4052:4e92:e226:bc4e:66db:dc91:6ceb dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4011:19::19 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c1e::66 dev ppp0 lladdr 08 NOARP
Deleted 2409:4072:6e09:5599::f34a:6d00 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c1e::5f dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c1e::84 dev ppp0 lladdr 08 NOARP
Deleted 2409:8a28:a39:9270:265e:beff:fe58:f9df dev ppp0 lladdr 08 NOARP
Deleted 2408:8210:c50:fde0:265e:beff:fe58:5664 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c07::5f dev ppp0 lladdr 08 NOARP
Deleted 2606:50c0:8002::154 dev ppp0 lladdr 08 NOARP
Deleted 2405:204:1486:89c9::1689:60ac dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0f::8a dev ppp0 lladdr 08 NOARP
Deleted 2a02:2f00:210f:8e00:5880:dac5:f018:468d dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0b::5f dev ppp0 lladdr 08 NOARP
Deleted 2a03:aa00::136:50 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4001:1b::8 dev ppp0 lladdr 08 NOARP
Deleted 2600:9000:2118:6c00:6:5a75:25c0:93a1 dev ppp0 lladdr 08 NOARP
Deleted 2409:4054:208f:13ff::b17:f8ac dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0b::c6 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c02::c6 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c09::64 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c08::71 dev ppp0 lladdr 08 NOARP
Deleted 2409:4051:102:f201::2227:e8b1 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0f::84 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0e::5e dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c05::8a dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0a::5f dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c01::5f dev ppp0 lladdr 08 NOARP
Deleted 2a02:2698:7000:1::e dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0b::77 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0e::5f dev ppp0 lladdr 08 NOARP
Deleted ff02::1:2 dev ppp0 lladdr 08 NOARP
Deleted 2a02:2698:a100:3::10 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1370:8135:87cc:357e:bfd1:71ba:22c3 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c06::77 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c05::67 dev ppp0 lladdr 08 NOARP
Deleted 2409:4072:8e83:4ebb:4d27:58bd:58bd:7dc7 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c03::64 dev ppp0 lladdr 08 NOARP
Deleted 2401:4900:5856:937:0:25:9382:7301 dev ppp0 lladdr 08 NOARP
Deleted 240b:11:9780:8f00:39e2:c85c:5675:fb5 dev ppp0 lladdr 08 NOARP
Deleted 2001:d08:1b86:d70e:137f:5293:6f1d:5c47 dev ppp0 lladdr 08 NOARP
Deleted 2a02:2698:a100:3::11 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c1c::77 dev ppp0 lladdr 08 NOARP
Deleted 2409:4051:393:f475::16d3:10a1 dev ppp0 lladdr 08 NOARP
Deleted 2409:8a28:6621:ac70:265e:beff:fe51:cad4 dev ppp0 lladdr 08 NOARP
Deleted 2409:4062:1f:f726::8ad:98a5 dev ppp0 lladdr 08 NOARP
Deleted 2a00:1450:4010:c0d::5f dev ppp0 lladdr 08 NOARP
Deleted inet ppp0 
Deleted inet6 ppp0 
Deleted mpls ppp0 
Deleted 46: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc noop state DOWN group default 
    link/ppp 
Deleted 2: lan5    inet6 2a02:2698:7006:a3f::1/64 scope global dynamic noprefixroute 
       valid_lft 85685sec preferred_lft 2885sec
Deleted anycast 2a02:2698:7006:a3f:: dev lan5 table local proto kernel metric 0 pref medium
Deleted local 2a02:2698:7006:a3f::1 dev lan5 table local proto kernel metric 0 pref medium
unreachable 2a02:2698:7006:a3f::/64 dev lo proto dhcp metric 1001 pref medium
Deleted 2a02:2698:7006:a3f::/64 dev lan5 proto dhcp metric 1002 pref medium
Deleted unreachable 2a02:2698:7006:a3f::/64 dev lo proto dhcp metric 1001 pref medium
inet ppp0 forwarding on rp_filter strict mc_forwarding off proxy_neigh off ignore_routes_with_linkdown off 
inet6 ppp0 forwarding on mc_forwarding off proxy_neigh off ignore_routes_with_linkdown off 
mpls ppp0 input off 
47: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN group default 
    link/ppp 
47: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc noop state DOWN group default 
    link/ppp 
47: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp 
multicast ff00::/8 dev ppp0 table local proto kernel metric 256 pref medium
fe80::30cd:c44a:c841:a8aa dev ppp0 proto kernel metric 256 pref medium
47: ppp0    inet6 fe80::30cd:c44a:c841:a8aa/128 scope link tentative 
       valid_lft forever preferred_lft forever
fe80::ea4:2ff:fe16:cc01 dev ppp0 proto kernel metric 256 pref medium
47: ppp0    inet6 fe80::30cd:c44a:c841:a8aa peer fe80::ea4:2ff:fe16:cc01/128 scope link 
       valid_lft forever preferred_lft forever
local fe80::30cd:c44a:c841:a8aa dev ppp0 table local proto kernel metric 0 pref medium
Deleted 47: ppp0    inet6 fe80::30cd:c44a:c841:a8aa peer fe80::ea4:2ff:fe16:cc01/128 scope link 
       valid_lft forever preferred_lft forever
Deleted fe80::ea4:2ff:fe16:cc01 dev ppp0 proto kernel metric 256 pref medium
Deleted local fe80::30cd:c44a:c841:a8aa dev ppp0 table local proto kernel metric 0 pref medium
Deleted fe80::30cd:c44a:c841:a8aa dev ppp0 proto kernel metric 256 pref medium
47: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc pfifo_fast state DOWN group default 
    link/ppp 
Deleted multicast ff00::/8 dev ppp0 table local proto kernel metric 256 pref medium
Deleted ff02::16 dev ppp0 lladdr 08 NOARP
47: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp 
47: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp 
47: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp 
default dev ppp0 metric 1024 pref medium
47: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc pfifo_fast state DOWN group default 
    link/ppp 
Deleted default dev ppp0 metric 1024 pref medium
Deleted ff02::16 dev ppp0 lladdr 08 NOARP
Deleted inet ppp0 
Deleted inet6 ppp0 
Deleted mpls ppp0 
Deleted 47: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc noop state DOWN group default 
    link/ppp 
inet ppp0 forwarding on rp_filter strict mc_forwarding off proxy_neigh off ignore_routes_with_linkdown off 
inet6 ppp0 forwarding on mc_forwarding off proxy_neigh off ignore_routes_with_linkdown off 
mpls ppp0 input off 
48: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN group default 
    link/ppp 
48: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc noop state DOWN group default 
    link/ppp 
48: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp 
48: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp 
multicast ff00::/8 dev ppp0 table local proto kernel metric 256 pref medium
fe80::7897:6c99:f41a:a39e dev ppp0 proto kernel metric 256 pref medium
48: ppp0    inet6 fe80::7897:6c99:f41a:a39e/128 scope link tentative 
       valid_lft forever preferred_lft forever
fe80::ea4:2ff:fe16:cc01 dev ppp0 proto kernel metric 256 pref medium
48: ppp0    inet 188.235.130.24/32 scope global ppp0
       valid_lft forever preferred_lft forever
local 188.235.130.24 dev ppp0 table local proto kernel scope host src 188.235.130.24 
Deleted 48: ppp0    inet 188.235.130.24/32 scope global ppp0
       valid_lft forever preferred_lft forever
Deleted local 188.235.130.24 dev ppp0 table local proto kernel scope host src 188.235.130.24 
48: ppp0    inet 188.235.130.24 peer 31.131.203.254/32 scope global ppp0
       valid_lft forever preferred_lft forever
local 188.235.130.24 dev ppp0 table local proto kernel scope host src 188.235.130.24 
31.131.203.254 dev ppp0 proto kernel scope link src 188.235.130.24 
default dev ppp0 scope link metric 4007 
48: ppp0    inet6 fe80::7897:6c99:f41a:a39e peer fe80::ea4:2ff:fe16:cc01/128 scope link 
       valid_lft forever preferred_lft forever
local fe80::7897:6c99:f41a:a39e dev ppp0 table local proto kernel metric 0 pref medium
default dev ppp0 metric 1024 pref medium
2a02:2698:7006:a3f:1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 STALE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 PROBE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 REACHABLE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 STALE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 PROBE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 REACHABLE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 STALE

Looks like it's STALE, although I'm not sure what exactly that means. But the tentative flag clears. Then after restarting dhcpcd:

fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 PROBE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 REACHABLE
fe80::1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 STALE
2: lan5: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default 
    link/ether 00:22:4d:82:b5:af brd ff:ff:ff:ff:ff:ff
48: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp 
unreachable 2a02:2698:7006:10f6::/64 dev lo proto dhcp metric 1001 pref medium
2: lan5    inet6 2a02:2698:7006:10f6::1/64 scope global tentative dynamic noprefixroute 
       valid_lft 600sec preferred_lft 600sec
2a02:2698:7006:10f6::/64 dev lan5 proto dhcp metric 1002 pref medium
Deleted unreachable 2a02:2698:7006:10f6::/64 dev lo proto dhcp metric 1001 pref medium
inet6 default forwarding off 
inet6 lo forwarding off 
Deleted anycast fe80:: dev lan5 table local proto kernel metric 0 pref medium
inet6 lan5 forwarding off 
Deleted anycast fe80:: dev lan4 table local proto kernel metric 0 pref medium
inet6 lan4 forwarding off 
inet6 ip6_vti0 forwarding off 
inet6 sit0 forwarding off 
inet6 ip6tnl0 forwarding off 
inet6 ppp0 forwarding off 
inet6 all forwarding off 
inet6 default forwarding on 
inet6 lo forwarding on 
anycast fe80:: dev lan5 table local proto kernel metric 0 pref medium
inet6 lan5 forwarding on 
anycast fe80:: dev lan4 table local proto kernel metric 0 pref medium
inet6 lan4 forwarding on 
inet6 ip6_vti0 forwarding on 
inet6 sit0 forwarding on 
inet6 ip6tnl0 forwarding on 
inet6 ppp0 forwarding on 
inet6 all forwarding on 
2a02:2698:7006:10f6:1e1b:dff:feea:24a7 dev lan5 lladdr 1c:1b:0d:ea:24:a7 REACHABLE
2: lan5    inet6 2a02:2698:7006:10f6::1/64 scope global dynamic noprefixroute 
       valid_lft 599sec preferred_lft 599sec
local 2a02:2698:7006:10f6::1 dev lan5 table local proto kernel metric 0 pref medium
anycast 2a02:2698:7006:10f6:: dev lan5 table local proto kernel metric 0 pref medium
48: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc pfifo_fast state UNKNOWN group default 
    link/ppp
corvus1 commented 2 years ago

Note that my ISP is delegating me a new /64 subnet every time I reconnect to ppp. For example: before: 2a02:2698:7006:a3f:... after: 2a02:2698:7006:10f6:....

WRMSRwasTaken commented 2 years ago

I came across the same issue after moving back to fetch a delegated prefix via dhcpcd from ppp0 instead of routing one via IPsec.

Having the same issue for dhcpcd waiting for an IP6LL on ppp0 despite systemd-networkd detecting a new IP6LL on ppp0 that has been added via IPv6CP. Running dhcpcd --rebind in a hook scipt in pppd was not needed for me back then, dhcpcd did the rebind automatically, and it seems that this continues to not being needed when the root cause of this issue has been found and fixed.

corvus1 commented 2 years ago

@WRMSRwasTaken thanks for confirming. At least it means, it's not something crazy in my setup or my ISP.

dhcpcd --rebind doesn't actually do anything, for me at least.

WRMSRwasTaken commented 2 years ago

Running the rebind option also makes dhcpcd on my box spew out those errors as seen above without successfully rebinding or getting a new lease, so I am getting the same behavior as you.

corvus1 commented 2 years ago

Ping. Anything else I can try/test/help with?

mhanor commented 2 years ago

I've managed to debug this issue, although I don't know of a proper fix for it. I was having the same issue, dhcpcd was getting stuck in the flow to acquire the prefixes, right after the message for delay on DHCPv6 for LL address on ppp interface. This issue appeared after upgrading dhcpcd5 package on my Debian Testing machine, from version 7.1.0-2 to 9.4.1-0.1 The issue occurs because dhcp6_start1 callback never gets called, while the callback remains assigned to the callback queue of the interface. This happens because we never call ipv6_handleifa for the 2nd netlink message (or whatever it's called), during link_addr function execution.

ppp0: delaying DHCPv6 for LL address ppp0: cmd 20 addr fe80::4f76:556b addrflags 192 <-- the last message processed by ipv6_handleifa ppp0: cmd 20 addr fe80::1 addrflags 128 <-- we never get here

Commenting the else branch in link_addr function - branch case AF_INET6 - on the logic for checking address exists, not to execute the break, allows the flow to continue and dhcpcd manages to acquire and delegate the prefixes, though I'm not sure what a proper fix would be. Also I don't know if the new maintainer has taken over the dhcpcd project and if this is the correct repository to comment on the issue. https://github.com/NetworkConfiguration/dhcpcd/blob/3fc025392dc9a8a3c8abd8568941bad07cecbd85/src/if-linux.c#L868

corvus1 commented 2 years ago

@mhanor thank you for your work, it's greatly appreciated.

corvus1 commented 2 years ago

I tested the fix proposed by @mhanor and it works for me.

rsmarples commented 2 years ago

The problem with the fix from @mhanor is that if we cannot find the address flags we assume the address does not exist. This is needed as there can be a delay from dhcpcd processing the message to something else deleting the address. I have added a different way of gettting the address by using netlink rather than parsing /proc.

Can someone test to see if this works please?

corvus1 commented 2 years ago

@rsmarples I tested your fix, and it does work. Although here's something strange: After ppp0 restart, my old prefix is no good anymore, and the ISP gives me a new one and we have:

Apr 20 16:46:11 localhost dhcpcd[32029]: ppp0: 2a02:2698:7007:1fdb::/64: no valid lifetime
Apr 20 16:46:11 localhost dhcpcd[32029]: ppp0: will expire
Apr 20 16:46:11 localhost dhcpcd[32029]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Apr 20 16:46:11 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
Apr 20 16:46:11 localhost dhcpcd[32029]: ppp0: DHCPv6 lease expired
Apr 20 16:46:11 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6

but the address doesn't get removed:

ip addr show lan5
2: lan5: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 00:22:4d:82:b5:af brd ff:ff:ff:ff:ff:ff
    inet 192.168.1.200/24 brd 192.168.1.255 scope global lan5
       valid_lft forever preferred_lft forever
    inet6 2a02:2698:7007:215a::1/64 scope global dynamic noprefixroute 
       valid_lft 85932sec preferred_lft 3132sec
    inet6 2a02:2698:7007:1fdb::1/64 scope global dynamic noprefixroute 
       valid_lft 84275sec preferred_lft 1475sec
    inet6 fe80::222:4dff:fe82:b5af/64 scope link 
       valid_lft forever preferred_lft forever

The new one gets assigned, and I do have connectivity, but the old address 2a02:2698:7007:1fdb::1/64 is hanging there.

rsmarples commented 2 years ago

@corvus1 are you still restarting dhcpcd when pppd restarts? If so, this is expected, if not then it's a bug. Can I get a full log of dhcpcd running without restarting and pppd is restarted please?

corvus1 commented 2 years ago

No, I don't. I restarted dhcpcd once, because I rebuilt it applying the patch. Only then I restarted ppp0. 

Apr 20 17:39:54 localhost start-stop-daemon[2568]: Will stop /usr/sbin/pppd
Apr 20 17:39:54 localhost start-stop-daemon[2568]: Will stop PID 2027
Apr 20 17:39:54 localhost start-stop-daemon[2568]: Sending signal 15 to PID 2027
Apr 20 17:39:54 localhost pppd[2027]: Terminating on signal 15
Apr 20 17:39:54 localhost kernel: device ppp0 left promiscuous mode
Apr 20 17:39:54 localhost dhcpcd[32029]: ppp0: carrier lost
Apr 20 17:39:54 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Apr 20 17:39:54 localhost pppd[2027]: Connection terminated.
Apr 20 17:39:54 localhost pppd[2027]: Connect time 0.7 minutes.
Apr 20 17:39:54 localhost pppd[2027]: Sent 7786 bytes, received 475 bytes.
Apr 20 17:39:54 localhost dhcpcd[32029]: lan5: deleting address 2a02:2698:7007:21bd::1/64
Apr 20 17:39:54 localhost dhcpcd[32029]: lo: adding reject route to 2a02:2698:7007:21bd::/64
Apr 20 17:39:54 localhost dhcpcd[32029]: lan5: deleting route to 2a02:2698:7007:21bd::/64
Apr 20 17:39:54 localhost dhcpcd[32029]: lo: deleting reject route to 2a02:2698:7007:21bd::/64
Apr 20 17:39:54 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6
Apr 20 17:39:54 localhost dhcpcd[32029]: ppp0: libudev: remove
Apr 20 17:39:54 localhost dhcpcd[32029]: ppp0: interface departed
Apr 20 17:39:54 localhost dhcpcd[32029]: ppp0: removing interface
Apr 20 17:39:54 localhost pppd[2027]: Exit.
Apr 20 17:39:54 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks DEPARTED
Apr 20 17:39:55 localhost pppd[2903]: Plugin pppoe.so loaded.
Apr 20 17:39:55 localhost pppd[2903]: PPPoE plugin from pppd 2.4.9
Apr 20 17:39:55 localhost pppd[2903]: Plugin passwordfd.so loaded.
Apr 20 17:39:55 localhost pppd[2904]: pppd 2.4.9 started by corvus, uid 0
Apr 20 17:39:56 localhost pppd[2904]: PPP session is 11
Apr 20 17:39:56 localhost pppd[2904]: Connected to 00:00:5e:00:01:82 via interface lan4
Apr 20 17:39:56 localhost pppd[2904]: Using interface ppp0
Apr 20 17:39:56 localhost pppd[2904]: Connect: ppp0 <--> lan4
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: libudev: add
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: interface added
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks PREINIT
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Apr 20 17:39:56 localhost pppd[2904]: CHAP authentication succeeded: (balance=0) Ok, M-PM-=M-PM-8M-QM-^GM-PM-5M-PM-3M-PM-> M-QM-^A M-PM-=M-PM-8M-PM-< M-PM-4M-PM-5M-PM-;M-PM-0M-QM-^BM-QM-^L M-PM-=M-PM-5 M-PM-=M-PM-0M-PM-4M-PM->.
Apr 20 17:39:56 localhost pppd[2904]: CHAP authentication succeeded
Apr 20 17:39:56 localhost pppd[2904]: peer from calling number 00:00:5E:00:01:82 authorized
Apr 20 17:39:56 localhost pppd[2904]: local  LL address fe80::652e:5527:3310:2d9c
Apr 20 17:39:56 localhost pppd[2904]: remote LL address fe80::0ea4:02ff:fe8a:cc01
Apr 20 17:39:56 localhost pppd[2904]: local  IP address 188.235.165.17
Apr 20 17:39:56 localhost pppd[2904]: remote IP address 31.131.207.254
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: waiting for carrier
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: carrier acquired
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks CARRIER
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: IAID 70:70:70:30
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: IA type 25 IAID 00:00:00:01
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: delaying DHCPv6 for LL address
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: rebinding prior DHCPv6 lease
Apr 20 17:39:56 localhost dhcpcd[32029]: ppp0: delaying REBIND6 (xid 0xe03254), next in 2.1 seconds
Apr 20 17:39:56 localhost root[2954]: ip-up.d executed 123
Apr 20 17:39:57 localhost root[3175]: ip-up.d executed 123
Apr 20 17:39:58 localhost ntpd[3400]: Listen normally on 33 ppp0 188.235.165.17:123
Apr 20 17:39:58 localhost ntpd[3400]: Listen normally on 34 ppp0 [fe80::652e:5527:3310:2d9c%17]:123
Apr 20 17:39:58 localhost ntpd[3400]: Deleting interface #31 ppp0, fe80::f0af:3929:621a:ffac%16#123, interface stats: received=0, sent=0, dropped=0, active_time=43 secs
Apr 20 17:39:58 localhost ntpd[3400]: Deleting interface #32 lan5, 2a02:2698:7007:21bd::1#123, interface stats: received=0, sent=0, dropped=0, active_time=38 secs
Apr 20 17:39:58 localhost dhcpcd[32029]: ppp0: broadcasting REBIND6 (xid 0xe03254), next in 1.0 seconds
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: broadcasting REBIND6 (xid 0xe03254), next in 2.0 seconds
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: REPLY6 received from fe80::ea4:2ff:fe8a:cc01
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: 2a02:2698:7007:21bd::/64: no valid lifetime
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: will expire
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks REBIND6
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: DHCPv6 lease expired
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks EXPIRE6
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: soliciting a DHCPv6 lease
Apr 20 17:39:59 localhost dhcpcd[32029]: ppp0: delaying SOLICIT6 (xid 0x6b417d), next in 2.1 seconds
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: broadcasting SOLICIT6 (xid 0x6b417d), next in 1.1 seconds
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: ADV 2a02:2698:7007:21bd::/64 from fe80::ea4:2ff:fe8a:cc01
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: broadcasting REQUEST6 (xid 0x44ec94), next in 1.0 seconds
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: REPLY6 received from fe80::ea4:2ff:fe8a:cc01
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: renew in 300, rebind in 400, expire in 600 seconds
Apr 20 17:40:01 localhost dhcpcd[32029]: lo: adding reject route to 2a02:2698:7007:21bd::/64
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: delegated prefix 2a02:2698:7007:21bd::/64
Apr 20 17:40:01 localhost dhcpcd[32029]: lan5: adding address 2a02:2698:7007:21bd::1/64
Apr 20 17:40:01 localhost dhcpcd[32029]: lan5: pltime 600 seconds, vltime 600 seconds
Apr 20 17:40:01 localhost dhcpcd[32029]: lan5: waiting for DHCPv6 DAD to complete
Apr 20 17:40:01 localhost dhcpcd[32029]: lan5: adding route to 2a02:2698:7007:21bd::/64
Apr 20 17:40:01 localhost dhcpcd[32029]: lo: deleting reject route to 2a02:2698:7007:21bd::/64
Apr 20 17:40:01 localhost dhcpcd[32029]: ppp0: executing: /lib/dhcpcd/dhcpcd-run-hooks BOUND6
Apr 20 17:40:01 localhost start-stop-daemon[3229]: Will stop /usr/sbin/radvd
Apr 20 17:40:01 localhost start-stop-daemon[3229]: Will stop PID 2370
Apr 20 17:40:01 localhost start-stop-daemon[3229]: Sending signal 15 to PID 2370
Apr 20 17:40:01 localhost radvd[2370]: exiting, 1 sigterm(s) received
Apr 20 17:40:01 localhost radvd[2370]: sending stop adverts
Apr 20 17:40:01 localhost radvd[2370]: removing /run/radvd/radvd.pid
Apr 20 17:40:01 localhost radvd[2370]: returning from radvd main
Apr 20 17:40:01 localhost radvd[2371]: Exiting, privsep_read_loop had readn return 0 bytes
Apr 20 17:40:01 localhost radvd[2371]: Exiting, privsep_read_loop is complete.
Apr 20 17:40:01 localhost CROND[3242]: (root) CMD (test -x /usr/sbin/run-crons && /usr/sbin/run-crons )
Apr 20 17:40:01 localhost CROND[3241]: (root) CMDEND (test -x /usr/sbin/run-crons && /usr/sbin/run-crons )
Apr 20 17:40:01 localhost radvd[3284]: version 2.19 started
Apr 20 17:40:02 localhost start-stop-daemon[3315]: Will stop PID 2430
Apr 20 17:40:02 localhost /etc/init.d/darkstat[3315]: start-stop-daemon: no matching processes found
Apr 20 17:40:03 localhost kernel: device ppp0 entered promiscuous mode
Apr 20 17:40:04 localhost ntpd[3400]: Listen normally on 35 lan5 [2a02:2698:7007:21bd::1]:123
Apr 20 17:40:04 localhost dhcpcd[32029]: lan5: DHCPv6 DAD completed
Apr 20 17:40:04 localhost dhcpcd[32029]: lan5: executing: /lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
# ip -6 addr show lan5 
2: lan5: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    inet6 2a02:2698:7007:21bd::1/64 scope global dynamic noprefixroute 
       valid_lft 554sec preferred_lft 554sec
    inet6 2a02:2698:7007:1fdb::1/64 scope global deprecated dynamic noprefixroute 
       valid_lft 81814sec preferred_lft 0sec
    inet6 fe80::222:4dff:fe82:b5af/64 scope link 
       valid_lft forever preferred_lft forever

idk, what's going on here, but seems like I don't get all prefixes ever delegated to me assigned to lan5. Only that one 2a02:2698:7007:1fdb::1/64 is stuck. :-)

I guess I'll just ip addr del it and chalk it off as a fluke. Thanks Roy, great job fixing it.

PS Or did I just randomly get the same prefix assigned to me twice?

corvus1 commented 2 years ago

Yeah, no, it was false alarm. dhcpcd removing the old prefixes. I tried it a couple of times. :-) All is good now.

corvus1 commented 2 years ago

@rsmarples I just want to say thank you for working on this. It was an annoying bug to deal with.

rsmarples commented 2 years ago

@corvus1 no problem! My appologies over taking so long to address it.