search

NetworkConfiguration / dhcpcd

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

Route for delegated prefix removed and not restored upon carrier loss on local interface #333

Closed gadall closed 5 months ago

gadall commented 5 months ago

dhcpcd 10.0.8 on Debian. Upstream is ppp0, local interface is enp2s0. After carrier is lost and regained on enp2s0, then following the next Router Advertisement on the ppp0 uplink, the route for the delegated prefix is removed and not restored. dhcpcd -n enp2s0 does temporarily help, until the next Router Advertisement.

2024-06-16T14:40:38.175420+00:00 rt0 dhcpcd[11177]: enp2s0: carrier lost
2024-06-16T14:40:06.466973+00:00 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Down
2024-06-16T14:40:38.175444+00:00 rt0 dhcpcd[11177]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
2024-06-16T14:40:38.180974+00:00 rt0 dhcpcd[11177]: enp2s0: deleting address 2001:xxxx:xxxx:9626::1/64
2024-06-16T14:40:38.181489+00:00 rt0 dhcpcd[11177]: enp2s0: deleting route to 2001:xxxx:xxxx:9626::/64
2024-06-16T14:40:10.851101+00:00 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
2024-06-16T14:40:42.666910+00:00 rt0 dhcpcd[11177]: enp2s0: carrier acquired
2024-06-16T14:40:42.668260+00:00 rt0 dhcpcd[11177]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
2024-06-16T14:40:42.672162+00:00 rt0 dhcpcd[11177]: enp2s0: IAID xx:xx:xx:xx
2024-06-16T14:40:42.672288+00:00 rt0 dhcpcd[11177]: enp2s0: adding delegated prefixes
2024-06-16T14:40:42.672302+00:00 rt0 dhcpcd[11177]: enp2s0: adding address 2001:xxxx:xxxx:9626::1/64
2024-06-16T14:40:42.672314+00:00 rt0 dhcpcd[11177]: enp2s0: pltime 85546 seconds, vltime 85546 seconds
2024-06-16T14:40:42.672804+00:00 rt0 dhcpcd[11177]: enp2s0: adding route to 2001:xxxx:xxxx:9626::/64
2024-06-16T14:40:42.672970+00:00 rt0 dhcpcd[11177]: enp2s0: waiting for DHCPv6 DAD to complete
2024-06-16T14:40:42.672981+00:00 rt0 dhcpcd[11177]: enp2s0: reading lease: /var/lib/dhcpcd/enp2s0.lease6
2024-06-16T14:41:31.145208+00:00 rt0 dhcpcd[11177]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
2024-06-16T14:41:31.146015+00:00 rt0 dhcpcd[11177]: ppp0: adding address 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64
2024-06-16T14:41:31.146150+00:00 rt0 dhcpcd[11177]: ppp0: pltime 3600 seconds, vltime 86400 seconds
2024-06-16T14:41:31.146513+00:00 rt0 dhcpcd[11177]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64
2024-06-16T14:41:31.146871+00:00 rt0 dhcpcd[11177]: enp2s0: deleting route to 2001:xxxx:xxxx:9626::/64
2024-06-16T14:41:31.147135+00:00 rt0 dhcpcd[11177]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
2024-06-16T14:41:32.147836+00:00 rt0 dhcpcd[11177]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64
2024-06-16T14:41:33.149104+00:00 rt0 dhcpcd[11177]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64

# ip a
2: enp2s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000
    link/ether 00:d0:4c:xx:xx:xx brd ff:ff:ff:ff:ff:ff
    altname enx00d04cxxxxxx
    inet 192.168.9.1/24 brd 192.168.9.255 scope global enp2s0
       valid_lft forever preferred_lft forever
    inet6 2001:xxxx:xxxx:9626::1/64 scope global dynamic noprefixroute 
       valid_lft 84823sec preferred_lft 84823sec
    inet6 fe80::xxxx:xxxx:xxxx:xxxx/64 scope link 
       valid_lft forever preferred_lft forever

# ip -6 ro
2001:xxxx:xxxx:xxxx::/64 dev ppp0 proto ra metric 1018 mtu 1492 pref medium
fe80::xxxx:xxxx:xxxx:c801 dev ppp0 proto kernel metric 256 pref medium
fe80::a863:18fc:e022:f0b dev ppp0 proto kernel metric 256 pref medium
fe80::/64 dev enp2s0 proto kernel metric 256 pref medium
fe80::/64 dev enp5s0 proto kernel metric 256 pref medium
default via fe80::xxxx:xxxx:xxxx:c801 dev ppp0 proto ra metric 1018 mtu 1492 pref medium

2024-06-16T14:59:06.752658+00:00 rt0 dhcpcd[11177]: control command: dhcpcd -n enp2s0
2024-06-16T14:59:06.753318+00:00 rt0 dhcpcd[11177]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks RECONFIGURE
2024-06-16T14:59:06.756778+00:00 rt0 dhcpcd[11177]: enp2s0: IAID xx:xx:xx:xx
2024-06-16T14:59:06.756791+00:00 rt0 dhcpcd[11177]: enp2s0: adding delegated prefixes
2024-06-16T14:59:06.756833+00:00 rt0 dhcpcd[11177]: enp2s0: adding address 2001:xxxx:xxxx:9626::1/64
2024-06-16T14:59:06.756842+00:00 rt0 dhcpcd[11177]: enp2s0: pltime 84442 seconds, vltime 84442 seconds
2024-06-16T14:59:06.757054+00:00 rt0 dhcpcd[11177]: enp2s0: adding route to 2001:xxxx:xxxx:9626::/64
2024-06-16T14:59:06.757209+00:00 rt0 dhcpcd[11177]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
2024-06-16T14:59:06.760328+00:00 rt0 dhcpcd[11177]: enp2s0: reading lease: /var/lib/dhcpcd/enp2s0.lease6

# ip -6 ro
2001:xxxx:xxxx:9626::/64 dev enp2s0 proto dhcp metric 1002 pref medium
.. etc ..
gadall commented 5 months ago

Well, the route is deleted again upon the next RA arriving from upstream:

2024-06-16T15:11:37.148993+00:00 rt0 dhcpcd[11177]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
2024-06-16T15:11:37.149747+00:00 rt0 dhcpcd[11177]: ppp0: adding address 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64
2024-06-16T15:11:37.149766+00:00 rt0 dhcpcd[11177]: ppp0: pltime 3600 seconds, vltime 86400 seconds
2024-06-16T15:11:37.149986+00:00 rt0 dhcpcd[11177]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64
2024-06-16T15:11:37.150405+00:00 rt0 dhcpcd[11177]: enp2s0: deleting route to 2001:xxxx:xxxx:9626::/64
2024-06-16T15:11:37.150723+00:00 rt0 dhcpcd[11177]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
2024-06-16T15:11:38.151277+00:00 rt0 dhcpcd[11177]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64
2024-06-16T15:11:39.152563+00:00 rt0 dhcpcd[11177]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:xxxx:ea51:c857:94d1/64
borkra commented 5 months ago

I am curious after carrier restored do you observe RA request? Is it not replied to? Technically after carrier loss dhcpcd does not know if you are connected to the same network, so ip negotiations need to start over.

gadall commented 5 months ago

@borkra The issue occurs after all the following:

  1. Carrier is lost on the LOCAL interface
  2. Carrier is restored on the LOCAL interface
  3. An unsolicited RA is received from the ISP on the uplink interface

At this point, dhcpcd deletes the route for the delegated prefix on the local interface.

The issue is triggered by the RA, any number of minutes after the link on the local interface is already up. In fact, the route for the delegated prefix can be restored with dhcpcd -n but it will be deleted again upon the next RA received on the uplink. The only way to permanently fix the issue is to restart dhcpcd.

rsmarples commented 5 months ago

@gadall I can't replicate this just using ethernet and I don't see how it could be PPP specific either. If it is, it's not obvious. If you restart dhcpcd, delegate from ppp to eth and then force a carrier change on eth does the next RA still cause the route to be deleted? If you look at the tcpdump for the RA, is the deleted prefix advertised with a zero vltime?

And I don't suppose the recently fixed #332 helps with this at all?

gadall commented 5 months ago

@rsmarples

If you restart dhcpcd, delegate from ppp to eth and then force a carrier change on eth does the next RA still cause the route to be deleted?

Yes, that's what I've been doing to reproduce the problem reliably. This issue too has been going on for a long time until I reported it now.

If you look at the tcpdump for the RA, is the deleted prefix advertised with a zero vltime?

hop limit 64, Flags [other stateful], pref medium, router lifetime 4500s, reachable time 0ms, retrans timer 0ms
      mtu option (5), length 8 (1):  1492
prefix info option (3), length 32 (4): 2001:xxxx:xxxx:e993::/64, Flags [onlink, auto], valid time 86400s, pref. time 3600s

And I don't suppose the recently fixed #332 helps with this at all?

No.

gadall commented 5 months ago

@rsmarples The delegated prefix is not mentioned in the RA. Only the /64 prefix within which the NA on ppp0 resides is mentioned.

My current address on ppp0 is 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64 LAN has 2001:xxxx:xxxx:3e30::1/64

Log:

Jun 18 15:40:13 rt0 dhcpcd[13175]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 18 15:40:13 rt0 dhcpcd[13175]: ppp0: adding address 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 15:40:13 rt0 dhcpcd[13175]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 18 15:40:13 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 15:40:13 rt0 dhcpcd[13175]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 18 15:40:14 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 15:40:15 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 15:55:16 rt0 dhcpcd[13175]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 18 15:55:16 rt0 dhcpcd[13175]: ppp0: adding address 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 15:55:16 rt0 dhcpcd[13175]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 18 15:55:16 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 15:55:16 rt0 dhcpcd[13175]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 18 15:55:17 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 15:55:18 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 16:01:09 rt0 dhcpcd[13175]: enp2s0: carrier lost
Jun 18 16:00:30 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Down
Jun 18 16:01:09 rt0 dhcpcd[13175]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Jun 18 16:01:09 rt0 dhcpcd[13175]: enp2s0: deleting address 2001:xxxx:xxxx:3e30::1/64
Jun 18 16:01:09 rt0 dhcpcd[13175]: enp2s0: deleting route to 2001:xxxx:xxxx:3e30::/64
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: carrier acquired
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 18 16:00:40 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: IAID 4c:10:00:38
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: adding delegated prefixes
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: adding address 2001:xxxx:xxxx:3e30::1/64
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: pltime 71442 seconds, vltime 71442 seconds
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: adding route to 2001:xxxx:xxxx:3e30::/64
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: waiting for DHCPv6 DAD to complete
Jun 18 16:01:19 rt0 dhcpcd[13175]: enp2s0: reading lease: /var/lib/dhcpcd/enp2s0.lease6
Jun 18 16:10:19 rt0 dhcpcd[13175]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 18 16:10:19 rt0 dhcpcd[13175]: ppp0: adding address 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 16:10:19 rt0 dhcpcd[13175]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 18 16:10:19 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 16:10:19 rt0 dhcpcd[13175]: enp2s0: deleting route to 2001:xxxx:xxxx:3e30::/64
Jun 18 16:10:19 rt0 dhcpcd[13175]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 18 16:10:20 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
Jun 18 16:10:21 rt0 dhcpcd[13175]: ppp0: sending NA for 2001:xxxx:xxxx:e993:e9e1:e581:e1c2:3784/64
gadall commented 5 months ago

@rsmarples Starting dhcpcd, here is the combined ICMPv6 and DHCPv6 traffic

16:33:37.219318 IP6 (flowlabel 0xdeef0, hlim 255, next-header ICMPv6 (58) payload length: 8) fe80::788e:d3ca:4a0a:d1ce > ff02::2: [icmp6 sum ok] ICMP6, router solicitation, length 8
16:33:37.219459 IP6 (flowlabel 0x06cbe, hlim 1, next-header UDP (17) payload length: 111) fe80::788e:d3ca:4a0a:d1ce.546 > ff02::1:2.547: [udp sum ok] dhcp6 rebind (xid=1b5255 (client-ID hwaddr/time type 1 time 742505335 00d04c100038) (IA_NA IAID:1 T1:0 T2:0) (IA_PD IAID:2 T1:0 T2:0 (IA_PD-prefix 2001:xxxx:xxxx:be85::/64 pltime:0 vltime:0)) (option-request DNS-server DNS-search-list Client-FQDN opt_82 opt_83) (elapsed-time 0))
16:33:37.222877 IP6 (class 0xc0, hlim 255, next-header UDP (17) payload length: 125) fe80::xxxx:xxxx:xxxx:c801.547 > fe80::788e:d3ca:4a0a:d1ce.546: [udp sum ok] dhcp6 reply (xid=1b5255 (server-ID hwaddr type 1 xxxxxxxxc801) (client-ID hwaddr/time type 1 time 742505335 00d04c100038) (IA_PD IAID:2 T1:0 T2:0 (IA_PD-prefix 2001:xxxx:xxxx:be85::/64 pltime:0 vltime:0)) (DNS-server 2001:xxxx:xxxx::2 2001:xxxx:xxxx::1))
16:33:37.242687 IP6 (flowlabel 0x06cbe, hlim 1, next-header UDP (17) payload length: 86) fe80::788e:d3ca:4a0a:d1ce.546 > ff02::1:2.547: [udp sum ok] dhcp6 solicit (xid=5d0491 (client-ID hwaddr/time type 1 time 742505335 00d04c100038) (IA_NA IAID:1 T1:0 T2:0) (IA_PD IAID:2 T1:0 T2:0) (option-request DNS-server DNS-search-list Client-FQDN opt_82 opt_83) (elapsed-time 0) (rapid-commit))
16:33:37.246563 IP6 (class 0xc0, hlim 255, next-header UDP (17) payload length: 129) fe80::xxxx:xxxx:xxxx:c801.547 > fe80::788e:d3ca:4a0a:d1ce.546: [udp sum ok] dhcp6 reply (xid=5d0491 (server-ID hwaddr type 1 xxxxxxxxc801) (client-ID hwaddr/time type 1 time 742505335 00d04c100038) (rapid-commit) (IA_PD IAID:2 T1:43200 T2:69120 (IA_PD-prefix 2001:xxxx:xxxx:be8d::/64 pltime:86400 vltime:86400)) (DNS-server 2001:xxxx:xxxx::2 2001:xxxx:xxxx::1))
16:33:37.314163 IP6 (class 0xc0, hlim 255, next-header ICMPv6 (58) payload length: 96) fe80::xxxx:xxxx:xxxx:c801 > fe80::788e:d3ca:4a0a:d1ce: [icmp6 sum ok] ICMP6, router advertisement, length 96
    hop limit 64, Flags [other stateful], pref medium, router lifetime 4500s, reachable time 0ms, retrans timer 0ms
      mtu option (5), length 8 (1):  1492
      prefix info option (3), length 32 (4): 2001:xxxx:xxxx:323::/64, Flags [onlink, auto], valid time 86400s, pref. time 3600s
      rdnss option (25), length 40 (5):  lifetime 3600s, addr: 2001:xxxx:xxxx::2 addr: 2001:xxxx:xxxx::1

Log:

Jun 18 16:33:37 rt0 dhcpcd[15429]: dhcpcd-10.0.8 starting
Jun 18 16:33:37 rt0 dhcpcd[15429]: dhcpcd-10.0.8 starting
Jun 18 16:33:37 rt0 dhcpcd[15429]: chrooting as dhcpcd to /usr/lib/dhcpcd
Jun 18 16:33:37 rt0 dhcpcd[15429]: chrooting as dhcpcd to /usr/lib/dhcpcd
Jun 18 16:33:37 rt0 dhcpcd[15429]: sandbox: seccomp
Jun 18 16:33:37 rt0 dhcpcd[15431]: spawned manager process on PID 15431
Jun 18 16:33:37 rt0 dhcpcd[15431]: spawned manager process on PID 15431
Jun 18 16:33:37 rt0 dhcpcd[15432]: udev: starting
Jun 18 16:33:37 rt0 dhcpcd[15432]: udev: starting
Jun 18 16:33:37 rt0 dhcpcd[15432]: dev: loaded udev
Jun 18 16:33:37 rt0 dhcpcd[15432]: spawned privileged proxy on PID 15432
Jun 18 16:33:37 rt0 dhcpcd[15432]: spawned network proxy on PID 15433
Jun 18 16:33:37 rt0 dhcpcd[15432]: spawned controller proxy on PID 15434
Jun 18 16:33:37 rt0 dhcpcd[15432]: DUID 00:01:00:01:2c:41:bb:77:00:d0:4c:10:00:38
Jun 18 16:33:37 rt0 dhcpcd[15432]: dev: loaded udev
Jun 18 16:33:37 rt0 dhcpcd[15432]: spawned privileged proxy on PID 15432
Jun 18 16:33:37 rt0 dhcpcd[15432]: spawned network proxy on PID 15433
Jun 18 16:33:37 rt0 dhcpcd[15432]: spawned controller proxy on PID 15434
Jun 18 16:33:37 rt0 dhcpcd[15432]: DUID 00:01:00:01:2c:41:bb:77:00:d0:4c:10:00:38
Jun 18 16:33:37 rt0 dhcpcd[15429]: forked to background
Jun 18 16:33:37 rt0 dhcpcd[15432]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks PREINIT
Jun 18 16:33:37 rt0 dhcpcd[15432]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks PREINIT
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 18 16:33:37 rt0 dhcpcd[15432]: enp2s0: IAID 4c:10:00:38
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: IAID 00:00:00:01
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: IA type 25 IAID 00:00:00:02
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: soliciting an IPv6 router
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: sending Router Solicitation
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: rebinding prior DHCPv6 lease
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: multicasting REBIND6 (xid 0x1b5255), next in 1.1 seconds
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: REPLY6 received from fe80::xxxx:xxxx:xxxx:c801
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: 2001:xxxx:xxxx:be85::/64: no valid lifetime
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: will expire
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks REBIND6
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: DHCPv6 lease expired
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks EXPIRE6
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: soliciting a DHCPv6 lease
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: multicasting SOLICIT6 (xid 0x5d0491), next in 1.0 seconds
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: REPLY6 received from fe80::xxxx:xxxx:xxxx:c801
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: renew in 43200, rebind in 69120, expire in 86400 seconds
Jun 18 16:33:37 rt0 dhcpcd[15432]: lo: adding reject route to 2001:xxxx:xxxx:be8d::/64
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: delegated prefix 2001:xxxx:xxxx:be8d::/64
Jun 18 16:33:37 rt0 dhcpcd[15432]: enp2s0: adding address 2001:xxxx:xxxx:be8d::1/64
Jun 18 16:33:37 rt0 dhcpcd[15432]: enp2s0: pltime 86400 seconds, vltime 86400 seconds
Jun 18 16:33:37 rt0 dhcpcd[15432]: enp2s0: waiting for DHCPv6 DAD to complete
Jun 18 16:33:37 rt0 dhcpcd[15432]: enp2s0: adding route to 2001:xxxx:xxxx:be8d::/64
Jun 18 16:33:37 rt0 dhcpcd[15432]: lo: deleting reject route to 2001:xxxx:xxxx:be8d::/64
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks BOUND6
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: adding address 2001:xxxx:xxxx:323:f9d9:e805:fa97:e09f/64
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: adding route to 2001:xxxx:xxxx:323::/64
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: adding default route via fe80::xxxx:xxxx:xxxx:c801
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: waiting for Router Advertisement DAD to complete
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: Router Advertisement DAD completed
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 18 16:33:37 rt0 dhcpcd[15432]: ppp0: sending NA for 2001:xxxx:xxxx:323:f9d9:e805:fa97:e09f/64
Jun 18 16:33:38 rt0 dhcpcd[15432]: ppp0: sending NA for 2001:xxxx:xxxx:323:f9d9:e805:fa97:e09f/64
Jun 18 16:33:38 rt0 dhcpcd[15432]: enp2s0: DHCPv6 DAD completed
Jun 18 16:33:38 rt0 dhcpcd[15432]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Jun 18 16:33:39 rt0 dhcpcd[15432]: ppp0: sending NA for 2001:xxxx:xxxx:323:f9d9:e805:fa97:e09f/64
rsmarples commented 5 months ago

OK. It will take some time to setup a PPPoE server somewhere to connect to the Debian VM as I couldn't get it working on my host OS which is DragonflyBSD.

rsmarples commented 5 months ago

Eek, didn't mean to close this by commit! Anyway, I've added a few commits to master which improves the debug experience here AND I think I've fixed the issue.

Sorry for the delay, took longer than I wanted to setup a PPPoE server for my VM's as the host OS required some kernel patching for it.

rsmarples commented 5 months ago

@gadall can you test the master branch please to see if it works for you now?

gadall commented 5 months ago

@rsmarples Looks the same to me

Jun 24 11:44:25 rt0 dhcpcd[24598]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 24 11:44:25 rt0 dhcpcd[24598]: ppp0: adding address 2001:xxxx:xxxx:xxxx:e4bd:6bf4:245a:4c3c/64
Jun 24 11:44:25 rt0 dhcpcd[24598]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 24 11:44:25 rt0 dhcpcd[24598]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:e4bd:6bf4:245a:4c3c/64
Jun 24 11:44:25 rt0 dhcpcd[24598]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 24 11:44:25 rt0 dhcpcd[24598]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 24 11:44:26 rt0 dhcpcd[24598]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:e4bd:6bf4:245a:4c3c/64
Jun 24 11:44:27 rt0 dhcpcd[24598]: ppp0: sending NA for 2001:xxxx:xxxx:xxxx:e4bd:6bf4:245a:4c3c/64
rsmarples commented 5 months ago

@gadall I just cannot replicate this :( I could when my VM host was accidentally causing DAD failures on my VM's, hence some patches, but now I have both sides playing nicely I just cannot replicate the PD route being deleted.

I've created a new branch called pd_debug. Please check that out, and post some new logs - I only need the output from CONSIDERING DHCP ROUTES just before you get the log message that the route has been deleted, but please include output upto and including that line also please.

gadall commented 5 months ago

@rsmarples Here:

Jun 24 15:56:28 rt0 systemd[1]: Stopped dhcpcd.service - DHCP Client Daemon on all interfaces.
Jun 24 15:56:28 rt0 systemd[1]: Starting dhcpcd.service - DHCP Client Daemon on all interfaces...
Jun 24 15:56:28 rt0 dhcpcd[24959]: dhcpcd-10.0.8 starting
Jun 24 15:56:28 rt0 dhcpcd[24959]: dhcpcd-10.0.8 starting
Jun 24 15:56:28 rt0 dhcpcd[24959]: chrooting as dhcpcd to /usr/lib/dhcpcd
Jun 24 15:56:28 rt0 dhcpcd[24959]: chrooting as dhcpcd to /usr/lib/dhcpcd
Jun 24 15:56:28 rt0 dhcpcd[24959]: sandbox: seccomp
Jun 24 15:56:28 rt0 dhcpcd[24962]: spawned manager process on PID 24962
Jun 24 15:56:28 rt0 dhcpcd[24962]: spawned manager process on PID 24962
Jun 24 15:56:28 rt0 dhcpcd[24963]: udev: starting
Jun 24 15:56:28 rt0 dhcpcd[24963]: dev: loaded udev
Jun 24 15:56:28 rt0 dhcpcd[24963]: spawned privileged proxy on PID 24963
Jun 24 15:56:28 rt0 dhcpcd[24963]: spawned network proxy on PID 24964
Jun 24 15:56:28 rt0 dhcpcd[24963]: spawned controller proxy on PID 24965
Jun 24 15:56:28 rt0 dhcpcd[24963]: udev: starting
Jun 24 15:56:28 rt0 dhcpcd[24963]: DUID 00:01:00:01:2c:41:bb:77:00:d0:4c:10:00:38
Jun 24 15:56:28 rt0 dhcpcd[24963]: dev: loaded udev
Jun 24 15:56:28 rt0 dhcpcd[24963]: spawned privileged proxy on PID 24963
Jun 24 15:56:28 rt0 dhcpcd[24963]: spawned network proxy on PID 24964
Jun 24 15:56:28 rt0 dhcpcd[24963]: spawned controller proxy on PID 24965
Jun 24 15:56:28 rt0 dhcpcd[24963]: DUID 00:01:00:01:2c:41:bb:77:00:d0:4c:10:00:38
Jun 24 15:56:28 rt0 dhcpcd[24959]: forked to background
Jun 24 15:56:28 rt0 dhcpcd[24963]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks PREINIT
Jun 24 15:56:28 rt0 systemd[1]: Started dhcpcd.service - DHCP Client Daemon on all interfaces.
Jun 24 15:56:28 rt0 dhcpcd[24963]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks PREINIT
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 24 15:56:28 rt0 dhcpcd[24963]: enp2s0: IAID 4c:10:00:38
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: IAID 00:00:00:01
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: IA type 25 IAID 00:00:00:02
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: soliciting an IPv6 router
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: sending Router Solicitation
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: rebinding prior DHCPv6 lease
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: multicasting REBIND6 (xid 0xa45223), next in 1.1 seconds
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: REPLY6 received from fe80::xxxx:xxxx:xxxx:c801
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: renew in 43200, rebind in 69120, expire in 86400 seconds
Jun 24 15:56:28 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT 0x55a6f83e70a0
Jun 24 15:56:28 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: lo: adding reject route to 2001:xxxx:xxxx:32a0::/64
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: delegated prefix 2001:xxxx:xxxx:32a0::/64
Jun 24 15:56:28 rt0 dhcpcd[24963]: enp2s0: adding address 2001:xxxx:xxxx:32a0::1/64
Jun 24 15:56:28 rt0 dhcpcd[24963]: enp2s0: pltime 86400 seconds, vltime 86400 seconds
Jun 24 15:56:28 rt0 dhcpcd[24963]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Jun 24 15:56:28 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT (nil)
Jun 24 15:56:28 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: IFP enp2s0 ADDR 2001:xxxx:xxxx:32a0::1/64 RT 0x55a6f83e8050
Jun 24 15:56:28 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 15:56:28 rt0 dhcpcd[24963]: enp2s0: adding route to 2001:xxxx:xxxx:32a0::/64
Jun 24 15:56:28 rt0 dhcpcd[24963]: lo: deleting reject route to 2001:xxxx:xxxx:32a0::/64
Jun 24 15:56:28 rt0 dhcpcd[24963]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks REBIND6
Jun 24 15:56:29 rt0 dhcpcd[24963]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 24 15:56:29 rt0 dhcpcd[24963]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 24 15:56:29 rt0 dhcpcd[24963]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 24 15:56:29 rt0 dhcpcd[24963]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 24 15:56:29 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 15:56:29 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT (nil)
Jun 24 15:56:29 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 15:56:29 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 15:56:29 rt0 dhcpcd[24963]: IFP enp2s0 ADDR 2001:xxxx:xxxx:32a0::1/64 RT 0x55a6f83c1bc0
Jun 24 15:56:29 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 15:56:29 rt0 dhcpcd[24963]: ppp0: adding route to 2001:xxxx:xxxx:83df::/64
Jun 24 15:56:29 rt0 dhcpcd[24963]: ppp0: adding default route via fe80::xxxx:xxxx:xxxx:c801
Jun 24 15:56:29 rt0 dhcpcd[24963]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 24 15:56:30 rt0 dhcpcd[24963]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 24 15:56:31 rt0 dhcpcd[24963]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 24 15:57:15 rt0 dhcpcd[24963]: enp2s0: carrier lost
Jun 24 15:57:15 rt0 dhcpcd[24963]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Jun 24 15:56:16 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Down
Jun 24 15:57:15 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT (nil)
Jun 24 15:57:15 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: IFP enp2s0 ADDR 2001:xxxx:xxxx:32a0::1/64 RT 0x55a6f83c20b0
Jun 24 15:57:15 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: enp2s0: deleting address 2001:xxxx:xxxx:32a0::1/64
Jun 24 15:57:15 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT (nil)
Jun 24 15:57:15 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 24 15:57:15 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT (nil)
Jun 24 15:57:15 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:15 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: carrier acquired
Jun 24 15:56:25 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: IAID 4c:10:00:38
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: adding delegated prefixes
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: adding address 2001:xxxx:xxxx:32a0::1/64
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: pltime 86344 seconds, vltime 86344 seconds
Jun 24 15:57:24 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:24 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT (nil)
Jun 24 15:57:24 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 15:57:24 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:24 rt0 dhcpcd[24963]: IFP enp2s0 ADDR 2001:xxxx:xxxx:32a0::1/64 RT 0x55a6f83ea2b0
Jun 24 15:57:24 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: adding route to 2001:xxxx:xxxx:32a0::/64
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: waiting for DHCPv6 DAD to complete
Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: reading lease: /var/lib/dhcpcd/enp2s0.lease6
Jun 24 16:11:32 rt0 dhcpcd[24963]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 24 16:11:32 rt0 dhcpcd[24963]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 24 16:11:32 rt0 dhcpcd[24963]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 24 16:11:32 rt0 dhcpcd[24963]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 24 16:11:32 rt0 dhcpcd[24963]: CONSIDERING DHCP 3 ROUTES
Jun 24 16:11:32 rt0 dhcpcd[24963]: IFP ppp0 ADDR 2001:xxxx:xxxx:32a0::/64 RT (nil)
Jun 24 16:11:32 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 3 ROUTES
Jun 24 16:11:32 rt0 dhcpcd[24963]: CONSIDERING DHCP 12 ROUTES
Jun 24 16:11:32 rt0 dhcpcd[24963]: DONE CONSIDERING DHCP 12 ROUTES
Jun 24 16:11:32 rt0 dhcpcd[24963]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 24 16:11:32 rt0 dhcpcd[24963]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 24 16:11:33 rt0 dhcpcd[24963]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 24 16:11:34 rt0 dhcpcd[24963]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
rsmarples commented 5 months ago

Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: waiting for DHCPv6 DAD to complete Jun 24 15:57:24 rt0 dhcpcd[24963]: enp2s0: reading lease: /var/lib/dhcpcd/enp2s0.lease6

Aha! Why is it reading the lease? I suspect that is the issue. Can you post your /etc/dhcpcd.conf please?

gadall commented 5 months ago

@rsmarples 

duid
persistent
vendorclassid
option domain_name_servers, domain_name, domain_search
option classless_static_routes
option interface_mtu
option host_name
option rapid_commit
require dhcp_server_identifier
slaac private
background
debug
noipv6rs
ipv6only
nohook resolv.conf, yp, hostname, ntp
allowinterfaces enp2s0 ppp0
interface ppp0
    nodelay
    ipv6rs
    iaid 1
    ia_na 1
    ia_pd 2 enp2s0/0
rsmarples commented 5 months ago

@gadall ok, I think I understand the issue now. Can you test the above branch please?

gadall commented 5 months ago

@rsmarples will test now. in your commit message s/rouies/routes

rsmarples commented 5 months ago

@rsmarples in your commit message s/rouies/routes

fixed, thanks

gadall commented 5 months ago

It just did it again, unfortunately :-(

Jun 25 11:20:22 rt0 dhcpcd[27297]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 25 11:20:22 rt0 dhcpcd[27297]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 11:20:22 rt0 dhcpcd[27297]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 25 11:20:22 rt0 dhcpcd[27297]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 11:20:22 rt0 dhcpcd[27297]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 25 11:20:22 rt0 dhcpcd[27297]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 25 11:20:23 rt0 dhcpcd[27297]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 11:20:24 rt0 dhcpcd[27297]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
gadall commented 5 months ago

I've been triggering the problem by actually unplugging the ethernet cable. Now I tried ip link set enp2s0 down; ip link set enp2s0 up and the problem didn't occur (I would expect it at 12:08):

Jun 25 11:53:15 rt0 dhcpcd[27346]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 25 11:53:15 rt0 dhcpcd[27346]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 11:53:15 rt0 dhcpcd[27346]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 25 11:53:15 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 11:53:15 rt0 dhcpcd[27346]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 25 11:53:16 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 11:53:17 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 11:54:41 rt0 dhcpcd[27346]: enp2s0: carrier lost
Jun 25 11:54:41 rt0 dhcpcd[27346]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Jun 25 11:54:41 rt0 dhcpcd[27346]: enp2s0: deleting address 2001:xxxx:xxxx:32a0::1/64
Jun 25 11:54:41 rt0 dhcpcd[27346]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 25 11:54:44 rt0 dhcpcd[27346]: enp2s0: carrier acquired
Jun 25 11:54:44 rt0 dhcpcd[27346]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 25 11:53:42 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Jun 25 11:54:44 rt0 dhcpcd[27346]: enp2s0: IAID 4c:10:00:38
Jun 25 11:54:44 rt0 dhcpcd[27346]: enp2s0: adding address fe80::6524:f340:1119:ec45
Jun 25 11:54:44 rt0 dhcpcd[27346]: enp2s0: pltime infinity, vltime infinity
Jun 25 11:54:44 rt0 dhcpcd[27346]: enp2s0: delaying adding delegated addresses for LL address
Jun 25 11:54:45 rt0 dhcpcd[27346]: enp2s0: adding delegated prefixes
Jun 25 11:54:45 rt0 dhcpcd[27346]: enp2s0: adding address 2001:xxxx:xxxx:32a0::1/64
Jun 25 11:54:45 rt0 dhcpcd[27346]: enp2s0: pltime 84503 seconds, vltime 84503 seconds
Jun 25 11:54:45 rt0 dhcpcd[27346]: enp2s0: adding route to 2001:xxxx:xxxx:32a0::/64
Jun 25 11:54:45 rt0 dhcpcd[27346]: enp2s0: waiting for DHCPv6 DAD to complete
Jun 25 11:54:47 rt0 dhcpcd[27346]: enp2s0: DHCPv6 DAD completed
Jun 25 11:54:47 rt0 dhcpcd[27346]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Jun 25 12:08:18 rt0 dhcpcd[27346]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 25 12:08:18 rt0 dhcpcd[27346]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 12:08:18 rt0 dhcpcd[27346]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 25 12:08:18 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 12:08:18 rt0 dhcpcd[27346]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 25 12:08:19 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 12:08:20 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
rsmarples commented 5 months ago

That's how I do it too. It's all in a VM, no physical cable to unplug. Can you post a similar log segment for the unplug please? Your prior one lacked the context of this one. Maybe it will reveal another clue.

I don't know why carrier should be different from admin state - dhcpcd joins them together internally.

gadall commented 5 months ago

Very strange. Now I unplugged it and when a RA arrived the route was not deleted. After restarting dhcpcd, the issue can be reproduced again. Looks like ip link somehow immunizes the system? Here is the log showing both unplugging attempts

Jun 25 12:53:27 rt0 dhcpcd[27346]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 25 12:53:27 rt0 dhcpcd[27346]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 12:53:27 rt0 dhcpcd[27346]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 25 12:53:27 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 12:53:27 rt0 dhcpcd[27346]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 25 12:53:28 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 12:53:29 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 12:56:39 rt0 dhcpcd[27346]: enp2s0: carrier lost
Jun 25 12:56:39 rt0 dhcpcd[27346]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Jun 25 12:55:38 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Down
Jun 25 12:56:39 rt0 dhcpcd[27346]: enp2s0: deleting address 2001:xxxx:xxxx:32a0::1/64
Jun 25 12:56:39 rt0 dhcpcd[27346]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 25 12:56:39 rt0 dhcpcd[27346]: enp2s0: deleting address fe80::6524:f340:1119:ec45
Jun 25 12:56:47 rt0 dhcpcd[27346]: enp2s0: carrier acquired
Jun 25 12:56:47 rt0 dhcpcd[27346]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 25 12:55:45 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Jun 25 12:56:47 rt0 dhcpcd[27346]: enp2s0: IAID 4c:10:00:38
Jun 25 12:56:47 rt0 dhcpcd[27346]: enp2s0: adding address fe80::6524:f340:1119:ec45
Jun 25 12:56:47 rt0 dhcpcd[27346]: enp2s0: pltime infinity, vltime infinity
Jun 25 12:56:47 rt0 dhcpcd[27346]: enp2s0: delaying adding delegated addresses for LL address
Jun 25 12:56:48 rt0 dhcpcd[27346]: enp2s0: adding delegated prefixes
Jun 25 12:56:48 rt0 dhcpcd[27346]: enp2s0: adding address 2001:xxxx:xxxx:32a0::1/64
Jun 25 12:56:48 rt0 dhcpcd[27346]: enp2s0: pltime 80780 seconds, vltime 80780 seconds
Jun 25 12:56:48 rt0 dhcpcd[27346]: enp2s0: adding route to 2001:xxxx:xxxx:32a0::/64
Jun 25 12:56:48 rt0 dhcpcd[27346]: enp2s0: waiting for DHCPv6 DAD to complete
Jun 25 12:56:50 rt0 dhcpcd[27346]: enp2s0: DHCPv6 DAD completed
Jun 25 12:56:50 rt0 dhcpcd[27346]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Jun 25 13:08:30 rt0 dhcpcd[27346]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 25 13:08:30 rt0 dhcpcd[27346]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:08:30 rt0 dhcpcd[27346]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 25 13:08:30 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:08:30 rt0 dhcpcd[27346]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 25 13:08:31 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:08:32 rt0 dhcpcd[27346]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:10:22 rt0 systemd[1]: Stopping dhcpcd.service - DHCP Client Daemon on all interfaces...
Jun 25 13:10:22 rt0 dhcpcd[28114]: sending signal TERM to pid 27345
Jun 25 13:10:22 rt0 dhcpcd[28114]: waiting for pid 27345 to exit
Jun 25 13:10:22 rt0 dhcpcd[28114]: sending signal TERM to pid 27345
Jun 25 13:10:22 rt0 dhcpcd[28114]: waiting for pid 27345 to exit
Jun 25 13:10:22 rt0 dhcpcd[27346]: received SIGTERM, stopping
Jun 25 13:10:22 rt0 dhcpcd[27346]: ppp0: removing interface
Jun 25 13:10:22 rt0 dhcpcd[27346]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks STOPPED
Jun 25 13:10:22 rt0 dhcpcd[27346]: enp2s0: removing interface
Jun 25 13:10:22 rt0 dhcpcd[27346]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks STOPPED
Jun 25 13:10:22 rt0 dhcpcd[27346]: network proxy exited from PID 27347
Jun 25 13:10:22 rt0 systemd[1]: dhcpcd.service: Deactivated successfully.
Jun 25 13:10:22 rt0 systemd[1]: Stopped dhcpcd.service - DHCP Client Daemon on all interfaces.
Jun 25 13:10:22 rt0 systemd[1]: Starting dhcpcd.service - DHCP Client Daemon on all interfaces...
Jun 25 13:10:22 rt0 dhcpcd[28118]: dhcpcd-10.0.8 starting
Jun 25 13:10:22 rt0 dhcpcd[28118]: dhcpcd-10.0.8 starting
Jun 25 13:10:22 rt0 dhcpcd[28118]: chrooting as dhcpcd to /usr/lib/dhcpcd
Jun 25 13:10:22 rt0 dhcpcd[28118]: chrooting as dhcpcd to /usr/lib/dhcpcd
Jun 25 13:10:22 rt0 dhcpcd[28118]: sandbox: seccomp
Jun 25 13:10:22 rt0 dhcpcd[28121]: spawned manager process on PID 28121
Jun 25 13:10:22 rt0 dhcpcd[28121]: spawned manager process on PID 28121
Jun 25 13:10:22 rt0 dhcpcd[28122]: udev: starting
Jun 25 13:10:22 rt0 dhcpcd[28122]: dev: loaded udev
Jun 25 13:10:22 rt0 dhcpcd[28122]: spawned privileged proxy on PID 28122
Jun 25 13:10:22 rt0 dhcpcd[28122]: spawned network proxy on PID 28123
Jun 25 13:10:22 rt0 dhcpcd[28122]: spawned controller proxy on PID 28124
Jun 25 13:10:22 rt0 dhcpcd[28122]: udev: starting
Jun 25 13:10:22 rt0 dhcpcd[28122]: DUID 00:01:00:01:2c:41:bb:77:00:d0:4c:10:00:38
Jun 25 13:10:22 rt0 dhcpcd[28122]: dev: loaded udev
Jun 25 13:10:22 rt0 dhcpcd[28122]: spawned privileged proxy on PID 28122
Jun 25 13:10:22 rt0 dhcpcd[28122]: spawned network proxy on PID 28123
Jun 25 13:10:22 rt0 dhcpcd[28122]: spawned controller proxy on PID 28124
Jun 25 13:10:22 rt0 dhcpcd[28122]: DUID 00:01:00:01:2c:41:bb:77:00:d0:4c:10:00:38
Jun 25 13:10:22 rt0 dhcpcd[28118]: forked to background
Jun 25 13:10:22 rt0 dhcpcd[28122]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks PREINIT
Jun 25 13:10:22 rt0 systemd[1]: Started dhcpcd.service - DHCP Client Daemon on all interfaces.
Jun 25 13:10:22 rt0 dhcpcd[28122]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks PREINIT
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 25 13:10:22 rt0 dhcpcd[28122]: enp2s0: IAID 4c:10:00:38
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: IAID 00:00:00:01
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: IA type 25 IAID 00:00:00:02
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: soliciting an IPv6 router
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: sending Router Solicitation
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: reading lease: /var/lib/dhcpcd/ppp0.lease6
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: rebinding prior DHCPv6 lease
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: multicasting REBIND6 (xid 0xd85f28), next in 1.0 seconds
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: REPLY6 received from fe80::xxxx:xxxx:xxxx:c801
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: renew in 43200, rebind in 69120, expire in 86400 seconds
Jun 25 13:10:22 rt0 dhcpcd[28122]: lo: adding reject route to 2001:xxxx:xxxx:32a0::/64
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: writing lease: /var/lib/dhcpcd/ppp0.lease6
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: delegated prefix 2001:xxxx:xxxx:32a0::/64
Jun 25 13:10:22 rt0 dhcpcd[28122]: enp2s0: adding address 2001:xxxx:xxxx:32a0::1/64
Jun 25 13:10:22 rt0 dhcpcd[28122]: enp2s0: pltime 86400 seconds, vltime 86400 seconds
Jun 25 13:10:22 rt0 dhcpcd[28122]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks DELEGATED6
Jun 25 13:10:22 rt0 dhcpcd[28122]: enp2s0: adding route to 2001:xxxx:xxxx:32a0::/64
Jun 25 13:10:22 rt0 dhcpcd[28122]: lo: deleting reject route to 2001:xxxx:xxxx:32a0::/64
Jun 25 13:10:22 rt0 dhcpcd[28122]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks REBIND6
Jun 25 13:10:23 rt0 dhcpcd[28122]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 25 13:10:23 rt0 dhcpcd[28122]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:10:23 rt0 dhcpcd[28122]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 25 13:10:23 rt0 dhcpcd[28122]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:10:23 rt0 dhcpcd[28122]: ppp0: adding route to 2001:xxxx:xxxx:83df::/64
Jun 25 13:10:23 rt0 dhcpcd[28122]: ppp0: adding default route via fe80::xxxx:xxxx:xxxx:c801
Jun 25 13:10:23 rt0 dhcpcd[28122]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 25 13:10:24 rt0 dhcpcd[28122]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:10:25 rt0 dhcpcd[28122]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:11:07 rt0 dhcpcd[28122]: enp2s0: carrier lost
Jun 25 13:11:07 rt0 dhcpcd[28122]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks NOCARRIER
Jun 25 13:10:05 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Down
Jun 25 13:11:07 rt0 dhcpcd[28122]: enp2s0: deleting address 2001:xxxx:xxxx:32a0::1/64
Jun 25 13:11:07 rt0 dhcpcd[28122]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: carrier acquired
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks CARRIER
Jun 25 13:10:09 rt0 kernel: igc 0000:02:00.0 enp2s0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: IAID 4c:10:00:38
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: adding delegated prefixes
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: adding address 2001:xxxx:xxxx:32a0::1/64
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: pltime 86351 seconds, vltime 86351 seconds
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: adding route to 2001:xxxx:xxxx:32a0::/64
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: waiting for DHCPv6 DAD to complete
Jun 25 13:11:11 rt0 dhcpcd[28122]: enp2s0: reading lease: /var/lib/dhcpcd/enp2s0.lease6
Jun 25 13:25:26 rt0 dhcpcd[28122]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 25 13:25:26 rt0 dhcpcd[28122]: ppp0: adding address 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:25:26 rt0 dhcpcd[28122]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 25 13:25:26 rt0 dhcpcd[28122]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:25:26 rt0 dhcpcd[28122]: enp2s0: deleting route to 2001:xxxx:xxxx:32a0::/64
Jun 25 13:25:26 rt0 dhcpcd[28122]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 25 13:25:27 rt0 dhcpcd[28122]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
Jun 25 13:25:28 rt0 dhcpcd[28122]: ppp0: sending NA for 2001:xxxx:xxxx:83df:e4bd:6bf4:245a:4c3c/64
rsmarples commented 5 months ago

@gadall I think it's a few factors, but the root cause is that I mix DHCP6 and delegated addresses into the same state which was probably a bad idea. To avoid a refactor, I've added another patch to the mix which will hopefully address your problem.

Sorry about all of this, but I just can't replicate the issue at my end :/ Anyway, please pull and test the same branch as it has a new commit on it. Thanks.

gadall commented 5 months ago

I tested it, it's still deleting the route :-( I wonder what else I can do to help with this? Is the trouble you have reproducing this rooted mainly in you using a VM? Perhaps I could try to reproduce this with ethernet/ethernet rather than PPPoE/ethernet? Any more debugging?

rsmarples commented 5 months ago

I tested it, it's still deleting the route :-( I wonder what else I can do to help with this? Is the trouble you have reproducing this rooted mainly in you using a VM? Perhaps I could try to reproduce this with ethernet/ethernet rather than PPPoE/ethernet? Any more debugging?

OK, this was my bad - I didn't fully test my patch. I was finally able to reproduce it by forcing DHCP6 to start on the delegated interface. I still don't understand why it's starting on your delegated interface though as you have nothing in your config to say it should start. I also fixed a long standing bug with privsep where the reject route was not restored if it was removed when the delegation was activated.

I couldn't replicate it either with ethernet/ethernet and I spent the best part of a week as a result setting up a PPPoE server and having to debug DragonflyBSD kernel to work out why it didn't work over a bridge to my VM's and fixed a few unrelated bugs as a result, so it's not a wasted effort here.

I forced a new patch in, please test - and cross fingers!

gadall commented 5 months ago

I still don't understand why it's starting on your delegated interface

This part? allowinterfaces enp2s0 ppp0 I guess I thought that since dhcpcd is meant to perform actions on enp2s0, it should be "allowed". Now I took that out and I see the delegation works nonetheless. Maybe the meaning of allowinterfaces could be further clarified in the docs. But it fails in such an exotic way that I thought it's just working and never gave it a second thought :-)

I forced a new patch in, please test - and cross fingers!

OK, I'll re-add enp2s0 to allowinterfaces and test right away! :-)

rsmarples commented 5 months ago

allowinterfaces just means start dhcpcd on that interface automatically. denyinterfaces means don't use dhcpcd at all on that interface by default.

Regardless, starting DHCP6 requires either a forced ia request (na or pd) or a RA with either the O or M flags set on that interface. You have neither, hence my confusion as to why it's starting. But it clearly is as it tries to read the leasefile for the interface. If you have the time and patience, I'd like to solve that too if you open another issue for it. If not, that's also fine.

gadall commented 5 months ago

This is my router, I have dnsmasq doing DHCP(v4), DHCPv6 and RA on enp2s0. I've been filtering that from the logs posted here since I ... thought it was irrelevant :D Are you saying that my dnsmasq sending out RA on this interface is confusing dhcpcd?

Meanwhile, it does seem to be fixed now:

Jun 26 09:52:07 rt0 dhcpcd[29910]: enp2s0: waiting for DHCPv6 DAD to complete
Jun 26 09:52:07 rt0 dhcpcd[29910]: enp2s0: reading lease: /var/lib/dhcpcd/enp2s0.lease6
Jun 26 10:06:37 rt0 dhcpcd[29910]: ppp0: Router Advertisement from fe80::xxxx:xxxx:xxxx:c801
Jun 26 10:06:37 rt0 dhcpcd[29910]: ppp0: adding address 2001:xxxx:xxxx:2277:9fce:2bf5:945c:974f/64
Jun 26 10:06:37 rt0 dhcpcd[29910]: ppp0: pltime 3600 seconds, vltime 86400 seconds
Jun 26 10:06:37 rt0 dhcpcd[29910]: ppp0: sending NA for 2001:xxxx:xxxx:2277:9fce:2bf5:945c:974f/64
Jun 26 10:06:37 rt0 dhcpcd[29910]: ppp0: executing: /usr/lib/dhcpcd/dhcpcd-run-hooks ROUTERADVERT
Jun 26 10:06:38 rt0 dhcpcd[29910]: ppp0: sending NA for 2001:xxxx:xxxx:2277:9fce:2bf5:945c:974f/64
Jun 26 10:06:39 rt0 dhcpcd[29910]: ppp0: sending NA for 2001:xxxx:xxxx:2277:9fce:2bf5:945c:974f/64

relevant dnsmasq bits:

enable-ra
quiet-ra
ra-param=enp2s0,mtu:1492,600,9000
dhcp-range=tag:enp2s0,::200,::600,constructor:enp2s0,slaac,64
dhcp-option=tag:enp2s0,option6:dns-server,[::]
dhcp-option=tag:enp2s0,option6:ntp-server,[::]
gadall commented 5 months ago

Actually I think I already tested earlier and reproduced the issue with dnsmasq not running

rsmarples commented 5 months ago

Actually I think I already tested earlier and reproduced the issue with dnsmasq not running

Yeah, it would be a RA coming in on enp0s3, not going out. But that isn't being logged, hence my confusion. If we want to work out why, open a new ticket please and we'll add some debug and follow it through.

But I think this particular issue re routes not coming back is now resolved then! Thanks for your patience.