"delaying IPv6 Router Solicitation for LL address" - despite LL address present on interface

[nicholasthorn]

Hello,

dhcpcd v10.1.0 running on debian 11, accept_ra = 0, ipv6ra_noautoconf set in dhcpcd.conf

We have an issue where we create a vlan and then attempt to run dhcpcd to obtain an ip address - occasionally we see dhcpcd getting stuck while waiting for LL address, but the LL address appears to exist on the interface?

Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output: eth3.411 Link encap:Ethernet HWaddr 94:6D:AE:B8:A0:39
Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output: inet6 addr: fe80::966d:aeff:feb8:a039/64 Scope:Link
Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output: UP BROADCAST RUNNING MULTICAST MTU:9000 Metric:1
Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output: RX packets:1 errors:0 dropped:0 overruns:0 frame:0
Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output: TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output: collisions:0 txqueuelen:1000
Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output: RX bytes:104 (104.0 B) TX bytes:0 (0.0 B)
Dec 5 13:05:35 cnivc0031g0214 user.notice ip-output:
Dec 5 13:05:35 cnivc0031g0214 daemon.info dhcpcd[77940]: dhcpcd-10.1.0 starting
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77940]: chrooting as dhcpcd to /root
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77942]: spawned manager process on PID 77942
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77943]: spawned privileged proxy on PID 77943
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77943]: spawned network proxy on PID 77944
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77943]: spawned controller proxy on PID 77945
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77943]: eth3.411: executing: /libexec/dhcpcd-run-hooks PREINIT
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77943]: eth3.411: executing: /libexec/dhcpcd-run-hooks CARRIER
Dec 5 13:05:35 cnivc0031g0214 daemon.info dhcpcd[77943]: DUID 00:01:00:01:2e:e4:61:9f:94:6d:ae:b8:a0:39
Dec 5 13:05:35 cnivc0031g0214 daemon.info dhcpcd[77943]: eth3.411: IAID ff:00:01:9b
Dec 5 13:05:35 cnivc0031g0214 daemon.debug dhcpcd[77943]: eth3.411: delaying IPv6 Router Solicitation for LL address
...
Dec 5 13:06:05 cnivc0031g0214 daemon.err dhcpcd[77943]: timed out
Dec 5 13:06:05 cnivc0031g0214 daemon.debug dhcpcd[77943]: eth3.411: executing: /libexec/dhcpcd-run-hooks STOPPED
Dec 5 13:06:05 cnivc0031g0214 daemon.debug dhcpcd[77943]: eth3.411: control proxy exited from PID 77945
Dec 5 13:06:05 cnivc0031g0214 daemon.debug dhcpcd[77943]: eth3.411: network proxy exited from PID 77944

Could this be a race between kernel & dhcpcd in assigning linklocal? In any case, dhcpcd never gets the callback. Do you have any suggestions?

Thanks in advance,

Nick

[nicholasthorn]

well, it's not an obvious race with the kernel; flushing ip address immediately before running results in dhcpcd attempting to add linklocal but still timing out unable to find it:

Dec 10 17:09:44 cnivc0031f0070 daemon.info dhcpcd[75479]: dhcpcd-10.1.0 starting
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75479]: chrooting as dhcpcd to /root
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75481]: spawned manager process on PID 75481
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: spawned privileged proxy on PID 75482
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: spawned network proxy on PID 75483
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: spawned controller proxy on PID 75484
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: eth3.411: executing: /libexec/dhcpcd-run-hooks PREINIT
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: eth3.411: executing: /libexec/dhcpcd-run-hooks CARRIER
Dec 10 17:09:44 cnivc0031f0070 daemon.info dhcpcd[75482]: DUID 00:01:00:01:2e:eb:32:58:e8:eb:d3:55:80:17
Dec 10 17:09:44 cnivc0031f0070 daemon.info dhcpcd[75482]: eth3.411: IAID ff:00:01:9b
Dec 10 17:09:44 cnivc0031f0070 daemon.info dhcpcd[75482]: eth3.411: IA type 3 IAID 00:00:00:01
Dec 10 17:09:44 cnivc0031f0070 daemon.info dhcpcd[75482]: eth3.411: adding address fe80::eaeb:d3ff:fe55:8017
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: eth3.411: pltime infinity, vltime infinity
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: eth3.411: delaying IPv6 Router Solicitation for LL address
Dec 10 17:09:44 cnivc0031f0070 daemon.debug dhcpcd[75482]: eth3.411: delaying DHCPv6 for LL address
...
Dec 10 17:10:14 cnivc0031f0070 daemon.err dhcpcd[75482]: timed out

[nicholasthorn]

eventually figured it out - in case this helps people in future:

Dec 16 14:34:03 cnivc0031f0070 user.notice dhcp-output: 56: eth3.411@eth3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 9000 qdisc noqueue qlen 1000
Dec 16 14:34:03 cnivc0031f0070 user.notice dhcp-output: link/ether e8:eb:d3:55:80:17 brd ff:ff:ff:ff:ff:ff
Dec 16 14:34:03 cnivc0031f0070 user.notice dhcp-output: inet6 fe80::eaeb:d3ff:fe55:8017/64 scope link tentative
Dec 16 14:34:03 cnivc0031f0070 user.notice dhcp-output: valid_lft forever preferred_lft forever

VLAN had only just been created, and linklocal address is marked as tentative so dhcpcd won't use it and will wait for call back which never comes.

[rsmarples]

dhcpcd should spot the address drop the tentative flag. Does the flag eventually drop and dhcpcd just doesn't see it?