Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

10.2.0 - IPv6 default route being deleted #465

Open
jlsnt opened this issue Feb 16, 2025 · 10 comments
Open

10.2.0 - IPv6 default route being deleted #465

jlsnt opened this issue Feb 16, 2025 · 10 comments

Comments

@jlsnt
Copy link

jlsnt commented Feb 16, 2025

Hello,

I upgraded from 10.1.0 to 10.2.0.
Since then, I noticed the IPv6 default route being deleted for no apparent (or understandable, to me at least) reason.
Mind the "pid 0 deleted default route via fe80::ba0:bab" log messages.

Falling back to 10.1.0 solves the issue.

I'm running Debian 12.

Please let me know if you need any kind of test/config change.

Configuration below :

noipv4ll
nohook hostname resolv.conf timesyncd.conf
allowinterfaces eno1.832
debug
logfile /var/log/dhcpcd.log
noauthrequired
noarp
noipv6rs

interface eno1.832
	iaid	37091470
	ipv6rs
	ia_pd	37091470 br0//64
	clientid
	userclass FSVDSL_livebox.Internet.softathome.Livebox5
	vendclass 1038 sagem
	vendorclassid sagem
	broadcast
	option subnet_mask routers domain_name_servers domain_name broadcast_address dhcp_lease_time dhcp_renewal_time dhcp_rebinding_time domain_search sip_server 125 auth
	option dhcp6_vivso dhcp6_name_servers dhcp6_domain_search dhcp6_auth
	nooption 33 57
	authprotocol token 0x123/0x456
	authtoken 0x456 "" forever 64:68:63:70:6c:69:76:65:62:6f:78:66:72:32:35:30
	authtoken 0x123 "" forever 1a:09:00:00:xxx

interface br0
	nolink

Relevant logs (debug enabled) :

Feb 16 18:38:05 [1548101]: no such user dhcpcd
Feb 16 18:38:05 [1548101]: dhcpcd-10.2.0 starting
Feb 16 18:38:05 [1548103]: spawned manager process on PID 1548103
Feb 16 18:38:05 [1548103]: DUID 00:03:00:01:xxx
Feb 16 18:38:05 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks PREINIT
Feb 16 18:38:05 [1548101]: forked to background
Feb 16 18:38:05 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks CARRIER
Feb 16 18:38:05 [1548103]: eno1.832: IAID 02:35:f8:8e
Feb 16 18:38:05 [1548103]: eno1.832: delaying IPv6 router solicitation for 0.6 seconds
Feb 16 18:38:05 [1548103]: eno1.832: reading lease: /var/db/dhcpcd/eno1.832.lease6
Feb 16 18:38:05 [1548103]: eno1.832: soliciting a DHCPv6 lease
Feb 16 18:38:05 [1548103]: eno1.832: delaying SOLICIT6 (xid 0x4431e2), next in 1.1 seconds
Feb 16 18:38:05 [1548103]: br0: activating for delegation
Feb 16 18:38:05 [1548103]: br0: executing: /usr/local/libexec/dhcpcd-run-hooks PREINIT
Feb 16 18:38:05 [1548103]: br0: IAID a4:ae:c9:22
Feb 16 18:38:05 [1548103]: eno1.832: delaying IPv4 for 0.5 seconds
Feb 16 18:38:05 [1548103]: eno1.832: using ClientID xxx
Feb 16 18:38:05 [1548103]: eno1.832: reading lease: /var/db/dhcpcd/eno1.832.lease
Feb 16 18:38:05 [1548103]: eno1.832: soliciting a DHCP lease
Feb 16 18:38:05 [1548103]: eno1.832: sending DISCOVER (xid 0xba9e29f2), next in 4.4 seconds
Feb 16 18:38:06 [1548103]: eno1.832: soliciting an IPv6 router
Feb 16 18:38:06 [1548103]: eno1.832: sending Router Solicitation
Feb 16 18:38:06 [1548103]: eno1.832: validated using 0x00001110
Feb 16 18:38:06 [1548103]: eno1.832: offered xxx from xxx
Feb 16 18:38:06 [1548103]: eno1.832: sending REQUEST (xid 0xba9e29f2), next in 3.8 seconds
Feb 16 18:38:06 [1548103]: eno1.832: validated using 0x00001110
Feb 16 18:38:06 [1548103]: eno1.832: acknowledged xxx from xxx
Feb 16 18:38:06 [1548103]: eno1.832: leased 86.247.132.3 for 259200 seconds
Feb 16 18:38:06 [1548103]: eno1.832: renew in 77910 seconds, rebind in 207360 seconds
Feb 16 18:38:06 [1548103]: eno1.832: writing lease: /var/db/dhcpcd/eno1.832.lease
Feb 16 18:38:06 [1548103]: eno1.832: adding IP address xxx/21 broadcast xxx
Feb 16 18:38:06 [1548103]: eno1.832: adding route to xxx/21
Feb 16 18:38:06 [1548103]: eno1.832: adding default route via xxx
Feb 16 18:38:06 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks BOUND
Feb 16 18:38:06 [1548103]: eno1.832: multicasting SOLICIT6 (xid 0x4431e2), next in 1.0 seconds
Feb 16 18:38:06 [1548103]: eno1.832: validated using 0x00001110
Feb 16 18:38:06 [1548103]: eno1.832: ADV 2a01:xxx::/56 from fe80::ba0:bab (0)
Feb 16 18:38:07 [1548103]: eno1.832: multicasting REQUEST6 (xid 0xf0a9b0), next in 1.0 seconds
Feb 16 18:38:07 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 18:38:07 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 18:38:07 [1548103]: lo: adding reject route to 2a01:xxx::/56
Feb 16 18:38:07 [1548103]: eno1.832: adding default route via fe80::ba0:bab
Feb 16 18:38:07 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 18:38:07 [1548103]: eno1.832: No DHCPv6 instruction in RA
Feb 16 18:38:07 [1548103]: eno1.832: validated using 0x00001110
Feb 16 18:38:07 [1548103]: eno1.832: REPLY6 received from fe80::ba0:bab
Feb 16 18:38:07 [1548103]: eno1.832: renew in 77910, rebind in 207360, expire in 259200 seconds
Feb 16 18:38:07 [1548103]: eno1.832: writing lease: /var/db/dhcpcd/eno1.832.lease6
Feb 16 18:38:07 [1548103]: eno1.832: delegated prefix 2a01:xxx::/56
Feb 16 18:38:07 [1548103]: br0: adding address 2a01:xxx::1/64
Feb 16 18:38:07 [1548103]: br0: pltime 259200 seconds, vltime 259200 seconds
Feb 16 18:38:07 [1548103]: br0: waiting for DHCPv6 DAD to complete
Feb 16 18:38:07 [1548103]: br0: adding route to 2a01:xxx::/64
Feb 16 18:38:07 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks BOUND6
Feb 16 18:38:09 [1548103]: br0: DHCPv6 DAD completed
Feb 16 18:38:09 [1548103]: br0: executing: /usr/local/libexec/dhcpcd-run-hooks DELEGATED6
Feb 16 19:01:37 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 19:01:37 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 19:01:37 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 19:21:46 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 19:21:46 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 19:21:46 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 19:42:53 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 19:42:53 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 19:42:53 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 19:53:36 [1548103]: eno1.832: pid 0 deleted default route via fe80::ba0:bab
Feb 16 20:06:59 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 20:06:59 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 20:06:59 [1548103]: eno1.832: adding default route via fe80::ba0:bab
Feb 16 20:06:59 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 20:26:38 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 20:26:38 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 20:26:38 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 20:45:55 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 20:45:55 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 20:45:55 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 21:06:45 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 21:06:45 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 21:06:45 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 21:22:02 [1548103]: eno1.832: pid 0 deleted default route via fe80::ba0:bab
Feb 16 21:24:28 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 21:24:28 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 21:24:28 [1548103]: eno1.832: adding default route via fe80::ba0:bab
Feb 16 21:24:28 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 21:50:18 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 21:50:18 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 21:50:18 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 22:14:32 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 22:14:32 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 22:14:32 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
Feb 16 22:39:39 [1548103]: eno1.832: pid 0 deleted default route via fe80::ba0:bab
Feb 16 22:43:21 [1548103]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 16 22:43:21 [1548103]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 16 22:43:21 [1548103]: eno1.832: adding default route via fe80::ba0:bab
Feb 16 22:43:21 [1548103]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT
@rsmarples
Copy link
Member

That log shows that dhcpcd just noted that the route was deleted, dhcpcd didn't delete it itself.

@rsmarples
Copy link
Member

What is the lifetime of the default route? Is it hitting zero at these times maybe?

@jlsnt
Copy link
Author

jlsnt commented Feb 18, 2025

With dhcpcd 10.1.0, no lifetime is set :

default via fe80::ba0:bab dev eno1.832 proto ra metric 1033 mtu 1500 pref medium

With dhcpcd 10.2.0, a lifetime is set :

default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires 4447sec mtu 1500 pref medium

What seems to happen is that the lifetime is not reset to the value advertised by the router (4500 seconds) when a RA is received. Lifetime decreases until it gets negative and the route is deleted.

default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires 3sec mtu 1500 pref medium
Tue 18 Feb 18:38:50 CET 2025
default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires -1sec mtu 1500 pref medium
Tue 18 Feb 18:38:55 CET 2025
default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires -6sec mtu 1500 pref medium
Tue 18 Feb 18:39:00 CET 2025
default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires -11sec mtu 1500 pref medium
Tue 18 Feb 18:39:05 CET 2025
Tue 18 Feb 18:39:10 CET 2025

2025-02-18T18:39:05.380538+01:00 gateway dhcpcd[1565393]: eno1.832: pid 0 deleted default route via fe80::ba0:bab

Typical RA from my ISP :

18:14:13.535990 18:5b:00:a5:36:8d > 18:86:xxxx, ethertype IPv6 (0x86dd), length 86: (class 0xc0, hlim 255, next-header ICMPv6 (58) payload length: 32) fe80::ba0:bab > fe80::1a86:xxxxx: [icmp6 sum ok] ICMP6, router advertisement, length 32
	hop limit 255, Flags [none], pref medium, router lifetime 4500s, reachable time 1800000ms, retrans timer 0ms
	  mtu option (5), length 8 (1):  1540
	  source link-address option (1), length 8 (1): 18:5b:00:a5:36:8d

It is processed by dhcpcd :

Feb 18 18:14:13 [1565393]: eno1.832: Router Advertisement from fe80::ba0:bab
Feb 18 18:14:13 [1565393]: eno1.832: advertised MTU 1540 is greater than link MTU 1500
Feb 18 18:14:13 [1565393]: eno1.832: executing: /usr/local/libexec/dhcpcd-run-hooks ROUTERADVERT

But the default route's lifetime is not updated :

Tue 18 Feb 18:14:07 CET 2025
default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires 1481sec mtu 1500 pref medium
Tue 18 Feb 18:14:12 CET 2025
default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires 1476sec mtu 1500 pref medium
Tue 18 Feb 18:14:17 CET 2025
default via fe80::ba0:bab dev eno1.832 proto ra metric 1034 expires 1471sec mtu 1500 pref medium

@ColinMcInnes
Copy link
Contributor

I'm seeing neither the "change" route log message, so it looks like it's not doing any route update after the initial push out to the kernel, and then the kernel is dutifully deleting the route after the expiry time.

in 10.1.0 a lifetime is not set, so the kernel assumes "infinite"

@jlsnt can you add an exit hook for ROUTERADVERT that logs the environment? If a router advertisement comes in it should be getting processed.

I will try to replicate, but that info would help.

@jlsnt
Copy link
Author

jlsnt commented Feb 18, 2025

can you add an exit hook for ROUTERADVERT that logs the environment?

Sure, which data are you interested in ? "ip route" 's output is already available above.

@ColinMcInnes
Copy link
Contributor

@jlsnt ip route shows the aftermath. I'm curious what dhcpcd is seeing from the incoming RA.
watching the output of radvdump could also work.

I add a file in /usr/libexec/dhcpcd-hooks that does something like

set | logger -t $0 -p user.info

dhcpcd will push a lot of the info from the RA into the exit hook environment.

the log should then contain a bunch of entries from the RA.

  • Is it always sending the lifetime?

I wonder if the oversized MTU is causing it to think the route isn't the same?

@jlsnt
Copy link
Author

jlsnt commented Feb 18, 2025

Here it is. Captured at dhcpcd's (10.2.0) startup.

Tue Feb 18 22:15:17 CET 2025
IFS=' 	
'
OPTIND='1'
PATH='/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin'
PPID='1572576'
PS1='# '
PS2='> '
PS4='+ '
PWD='/'
_detected_init='false'
from='from'
hook='/usr/local/libexec/dhcpcd-hooks/00-ra_received'
if_configured='true'
if_down='false'
if_up='true'
ifcarrier='up'
ifflags='69699'
ifmetric='1039'
ifmtu='1500'
ifname='eno1.832.ra'
ifwireless='0'
interface='eno1.832'
interface_order='br0 eno1.832'
nd1_acquired='15485709'
nd1_flags=''
nd1_from='fe80::ba0:bab'
nd1_hoplimit='255'
nd1_lifetime='4500'
nd1_mtu='1540'
nd1_now='15485709'
nd1_source_address='185b00a5368d'
pid='1572576'
protocol='ra'
reason='ROUTERADVERT'
signature='# Generated by dhcpcd from eno1.832.ra'
signature_base='# Generated by dhcpcd'
signature_base_end='# End of dhcpcd'
signature_end='# End of dhcpcd from eno1.832.ra'
skip='timesyncd.conf'
skip_hooks='hostname resolv.conf timesyncd.conf'
state_dir='/var/run/dhcpcd/hook-state'
syslog_debug='true'

@ColinMcInnes
Copy link
Contributor

I notice even in 10.1.0 it's not actually setting the mtu of 1540

default via fe80::ba0:bab dev eno1.832 proto ra metric 1033 mtu 1500 pref medium

But at least that gives me some more info, we do see it sending a lifetime.

nd1_lifetime='4500'

I wonder if the MTU value is somehow short-circuiting the logic that tries to update the route.

@ColinMcInnes
Copy link
Contributor

MTU was a red herring, it was just warning us that it was ignoring the "1540" and setting it to 1500.

I'm still looking into why it might be skipping the route update.

@gdluca
Copy link

gdluca commented Feb 21, 2025

Sorry for the quick comment without detailed logs but I am having the same issue.

dhcpcd 10.2.0
Copyright (c) 2006-2024 Roy Marples
Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH PRIVSEP

This is the RA with 1800sec lifetime
default via fe80::e269:baff:fed8:5b4b dev enp10s0 proto ra metric 1003 expires 1106sec mtu 1500 pref medium

every 30 minutes, dhcpcd gives me the "pid 0 deleted default route via" message.

-- Boot cdab7395174b488582ff4bcdc096db61 --
Feb 21 01:40:11 viper systemd[1]: Starting DHCP/ IPv4LL/ IPv6RA/ DHCPv6 client on enp10s0...
Feb 21 01:40:11 viper dhcpcd[685]: dhcpcd-10.2.0 starting
Feb 21 01:40:11 viper dhcpcd[691]: DUID 00:01:00:01:2f:3c:03:e0:30:68:93:68:b5:18
Feb 21 01:40:12 viper systemd[1]: Started DHCP/ IPv4LL/ IPv6RA/ DHCPv6 client on enp10s0.
Feb 21 01:40:12 viper dhcpcd[691]: enp10s0: waiting for carrier
Feb 21 01:40:20 viper dhcpcd[691]: enp10s0: carrier acquired
Feb 21 01:40:20 viper dhcpcd[691]: enp10s0: IAID 93:68:b5:18
Feb 21 01:40:20 viper dhcpcd[691]: enp10s0: IA type 25 IAID 00:00:00:01
Feb 21 01:40:20 viper dhcpcd[691]: enp10s0: adding address fe80::163c:8427:5b92:5f6
Feb 21 01:40:22 viper dhcpcd[691]: enp10s0: rebinding prior DHCPv6 lease
Feb 21 01:40:22 viper dhcpcd[691]: br0: activating for delegation
Feb 21 01:40:22 viper dhcpcd[691]: br0: waiting for carrier
Feb 21 01:40:22 viper dhcpcd[691]: br0: carrier acquired
Feb 21 01:40:22 viper dhcpcd[691]: br0: IAID cb:78:e2:10
Feb 21 01:40:22 viper dhcpcd[691]: br0: adding address fe80::e2c:d34d:5f9f:c521
Feb 21 01:40:23 viper dhcpcd[691]: enp10s0: soliciting an IPv6 router
Feb 21 01:40:23 viper dhcpcd[691]: enp10s0: Router Advertisement from fe80::e269:baff:fed8:5b4b
Feb 21 01:40:23 viper dhcpcd[691]: enp10s0: no global addresses for default route
Feb 21 01:40:23 viper dhcpcd[691]: lo: adding reject route to 2409:xxxx:xxxx:xxxx::/56
Feb 21 01:40:23 viper dhcpcd[691]: enp10s0: REPLY6 received from fe80::e269:baff:fed8:5b4b
Feb 21 01:40:23 viper dhcpcd[691]: enp10s0: renew in 7200, rebind in 10800, expire in 14400 seconds
Feb 21 01:40:23 viper dhcpcd[691]: enp10s0: delegated prefix 2409:xxxx:xxxx:xxxx::/56
Feb 21 01:40:23 viper dhcpcd[691]: br0: adding address 2409:xxxx:xxxx:xxxx::xxxx/64
Feb 21 01:40:23 viper dhcpcd[691]: enp10s0: adding default route via fe80::e269:baff:fed8:5b4b
Feb 21 01:40:23 viper dhcpcd[691]: br0: adding route to 2409:xxxx:xxxx:xxxx::/64
Feb 21 02:10:38 viper dhcpcd[691]: enp10s0: pid 0 deleted default route via fe80::e269:baff:fed8:5b4b
Feb 21 02:11:03 viper dhcpcd[691]: enp10s0: adding default route via fe80::e269:baff:fed8:5b4b
Feb 21 02:41:22 viper dhcpcd[691]: enp10s0: pid 0 deleted default route via fe80::e269:baff:fed8:5b4b
Feb 21 02:42:38 viper dhcpcd[691]: enp10s0: adding default route via fe80::e269:baff:fed8:5b4b
Feb 21 03:13:07 viper dhcpcd[691]: enp10s0: pid 0 deleted default route via fe80::e269:baff:fed8:5b4b
Feb 21 03:14:57 viper dhcpcd[691]: enp10s0: adding default route via fe80::e269:baff:fed8:5b4b
Feb 21 03:40:24 viper dhcpcd[691]: enp10s0: changing default route via fe80::e269:baff:fed8:5b4b
Feb 21 03:41:20 viper dhcpcd[691]: enp10s0: changing default route via fe80::e269:baff:fed8:5b4b
Feb 21 04:11:21 viper dhcpcd[691]: enp10s0: pid 0 deleted default route via fe80::e269:baff:fed8:5b4b
Feb 21 04:13:50 viper dhcpcd[691]: enp10s0: adding default route via fe80::e269:baff:fed8:5b4b

dhcpcd.conf

interface enp10s0
	ipv6rs
	ia_pd 1 br0/0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants