NetworkConfiguration
dhcpcd gets stuck after system reboot
I encountered an issue where dhcpcd after a system reboot gets stuck waiting for interfaces to become available. My guess is that it is some timing issue.
If dhcpcd starts without issues, then the syslog contains output like this:
2025-04-25T15:11:04.923985+02:00 server-timo systemd[1]: Starting dhcpcd.service - DHCP Client Daemon on all interfaces...
2025-04-25T15:11:04.976983+02:00 server-timo dhcpcd[36827]: dhcpcd-10.1.0 starting
2025-04-25T15:11:04.977753+02:00 server-timo dhcpcd[36831]: dev: loaded udev
2025-04-25T15:11:04.977787+02:00 server-timo dhcpcd[36831]: DUID 00:01:00:01:2f:94:cb:b5:88:c9:b3:b4:07:33
2025-04-25T15:11:04.979898+02:00 server-timo systemd[1]: Started dhcpcd.service - DHCP Client Daemon on all interfaces.
2025-04-25T15:11:04.984188+02:00 server-timo dhcpcd[36831]: lan1: IAID b3:b4:07:33
2025-04-25T15:11:04.984222+02:00 server-timo dhcpcd[36831]: lan1: adding address fe80::8ac9:b3ff:feb4:733
2025-04-25T15:11:04.984261+02:00 server-timo dhcpcd[36831]: lan0: IAID 59:b7:51:09
2025-04-25T15:11:04.984432+02:00 server-timo dhcpcd[36831]: wg0: IAID 77:67:30:00
2025-04-25T15:11:04.984446+02:00 server-timo dhcpcd[36831]: ppp0: IAID 70:70:70:30
2025-04-25T15:11:04.984458+02:00 server-timo dhcpcd[36831]: ppp0: IA type 25 IAID 00:00:00:00
2025-04-25T15:11:04.984520+02:00 server-timo dhcpcd[36831]: ppp0: rebinding prior DHCPv6 lease
2025-04-25T15:11:05.765564+02:00 server-timo dhcpcd[36831]: ppp0: soliciting an IPv6 router
2025-04-25T15:11:05.768417+02:00 server-timo dhcpcd[36831]: ppp0: Router Advertisement from fe80::1239:e9ff:feb1:f02a
2025-04-25T15:11:05.769364+02:00 server-timo dhcpcd[36831]: ppp0: adding address 2003:ff:27ff:26d:1c16:c5d1:1e23:b506/64
2025-04-25T15:11:05.769637+02:00 server-timo dhcpcd[36831]: lo: adding reject route to 2003:ff:2702:5600::/56
2025-04-25T15:11:05.769751+02:00 server-timo dhcpcd[36831]: ppp0: adding route to 2003:ff:27ff:26d::/64
2025-04-25T15:11:05.769815+02:00 server-timo dhcpcd[36831]: ppp0: adding default route via fe80::1239:e9ff:feb1:f02a
2025-04-25T15:11:14.986370+02:00 server-timo dhcpcd[36831]: ppp0: failed to rebind prior DHCPv6 delegation
2025-04-25T15:11:17.517985+02:00 server-timo dhcpcd[36831]: ppp0: REPLY6 received from fe80::1239:e9ff:feb1:f02a
2025-04-25T15:11:17.518362+02:00 server-timo dhcpcd[36831]: ppp0: deleting address 2003:ff:2702:5600::/56
2025-04-25T15:11:17.518439+02:00 server-timo dhcpcd[36831]: ppp0: renew in 43200, rebind in 69120, expire in 86400 seconds
2025-04-25T15:11:17.518502+02:00 server-timo dhcpcd[36831]: lo: adding reject route to 2003:ff:2702:5700::/56
2025-04-25T15:11:17.518605+02:00 server-timo dhcpcd[36831]: lo: deleting reject route to 2003:ff:2702:5600::/56
2025-04-25T15:11:17.518888+02:00 server-timo dhcpcd[36831]: ppp0: delegated prefix 2003:ff:2702:5700::/56
2025-04-25T15:11:17.519058+02:00 server-timo dhcpcd[36831]: lan1: adding address 2003:ff:2702:5711::1/64
2025-04-25T15:11:17.519170+02:00 server-timo dhcpcd[36831]: lan0: adding address 2003:ff:2702:5710::1/64
2025-04-25T15:11:17.520499+02:00 server-timo dhcpcd[36831]: lan1: adding route to 2003:ff:2702:5711::/64
2025-04-25T15:11:17.520846+02:00 server-timo dhcpcd[36831]: lan0: adding route to 2003:ff:2702:5710::/64
However, sometimes the output is like this:
2025-04-25T15:06:37.591896+02:00 server-timo systemd[1]: Starting dhcpcd.service - DHCP Client Daemon on all interfaces...
2025-04-25T15:06:37.592703+02:00 server-timo dhcpcd[893]: dhcpcd-10.1.0 starting
2025-04-25T15:06:37.592710+02:00 server-timo dhcpcd[969]: dev: loaded udev
2025-04-25T15:06:37.592717+02:00 server-timo dhcpcd[969]: DUID 00:01:00:01:2f:94:cb:b5:88:c9:b3:b4:07:33
2025-04-25T15:06:37.878332+02:00 server-timo dhcpcd[969]: no valid interfaces found
2025-04-25T15:06:37.880732+02:00 server-timo systemd[1]: Started dhcpcd.service - DHCP Client Daemon on all interfaces.
2025-04-25T15:06:37.880912+02:00 server-timo dhcpcd[969]: no valid interfaces found
2025-04-25T15:06:40.109810+02:00 server-timo dhcpcd[969]: lan0: waiting for carrier
2025-04-25T15:06:41.153821+02:00 server-timo dhcpcd[969]: lan1: waiting for carrier
2025-04-25T15:06:41.162723+02:00 server-timo dhcpcd[969]: lan0: waiting for carrier
2025-04-25T15:06:41.163300+02:00 server-timo dhcpcd[969]: lan1: waiting for carrier
2025-04-25T15:06:41.163340+02:00 server-timo dhcpcd[969]: lan0: removing interface
2025-04-25T15:06:41.165324+02:00 server-timo dhcpcd[969]: lan0: waiting for carrier
2025-04-25T15:06:41.166086+02:00 server-timo dhcpcd[969]: lan1: removing interface
2025-04-25T15:06:41.168099+02:00 server-timo dhcpcd[969]: lan1: waiting for carrier
2025-04-25T15:06:41.168134+02:00 server-timo dhcpcd[969]: lan1: removing interface
2025-04-25T15:06:41.170127+02:00 server-timo dhcpcd[969]: lan1: waiting for carrier
2025-04-25T15:06:41.170159+02:00 server-timo dhcpcd[969]: lan0: removing interface
2025-04-25T15:06:41.172077+02:00 server-timo dhcpcd[969]: lan0: waiting for carrier
2025-04-25T15:06:41.172109+02:00 server-timo dhcpcd[969]: lan1: removing interface
2025-04-25T15:06:41.174049+02:00 server-timo dhcpcd[969]: lan1: waiting for carrier
The pattern above (removing interface -- waiting for carrier) repeats for a while and then the following message occurs, indicating that ifupdown is (indeed) still bringing up the network:
2025-04-25T15:06:42.344673+02:00 server-timo dhcpcd[969]: lan1: waiting for carrier
2025-04-25T15:06:42.344699+02:00 server-timo dhcpcd[969]: lan1: removing interface
2025-04-25T15:06:42.345551+02:00 server-timo systemd[1]: Finished ifupdown-wait-online.service - Wait for network to be configured by ifupdown.
2025-04-25T15:06:42.346854+02:00 server-timo dhcpcd[969]: lan1: waiting for carrier
2025-04-25T15:06:42.346884+02:00 server-timo dhcpcd[969]: lan1: removing interface
The pattern then again repeats for a while, until it changes as follows:
2025-04-25T15:06:44.354078+02:00 server-timo dhcpcd[969]: lan1: IAID b3:b4:07:33
2025-04-25T15:06:44.354105+02:00 server-timo dhcpcd[969]: lan1: adding address fe80::8ac9:b3ff:feb4:733
2025-04-25T15:06:44.355206+02:00 server-timo dhcpcd[969]: lan0: removing interface
2025-04-25T15:06:44.355220+02:00 server-timo dhcpcd[969]: lan0: deleting address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.356280+02:00 server-timo dhcpcd[969]: lan0: IAID 59:b7:51:09
2025-04-25T15:06:44.356296+02:00 server-timo dhcpcd[969]: lan0: adding address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.356351+02:00 server-timo dhcpcd[969]: lan1: removing interface
2025-04-25T15:06:44.356403+02:00 server-timo dhcpcd[969]: lan1: deleting address fe80::8ac9:b3ff:feb4:733
2025-04-25T15:06:44.358584+02:00 server-timo dhcpcd[969]: lan1: IAID b3:b4:07:33
2025-04-25T15:06:44.358620+02:00 server-timo dhcpcd[969]: lan1: adding address fe80::8ac9:b3ff:feb4:733
2025-04-25T15:06:44.358653+02:00 server-timo dhcpcd[969]: lan0: removing interface
2025-04-25T15:06:44.358666+02:00 server-timo dhcpcd[969]: lan0: deleting address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.360848+02:00 server-timo dhcpcd[969]: lan0: IAID 59:b7:51:09
2025-04-25T15:06:44.360876+02:00 server-timo dhcpcd[969]: lan0: adding address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.360905+02:00 server-timo dhcpcd[969]: lan1: removing interface
2025-04-25T15:06:44.360922+02:00 server-timo dhcpcd[969]: lan1: deleting address fe80::8ac9:b3ff:feb4:733
2025-04-25T15:06:44.363073+02:00 server-timo dhcpcd[969]: lan1: IAID b3:b4:07:33
2025-04-25T15:06:44.363096+02:00 server-timo dhcpcd[969]: lan1: adding address fe80::8ac9:b3ff:feb4:733
2025-04-25T15:06:44.363133+02:00 server-timo dhcpcd[969]: lan0: removing interface
2025-04-25T15:06:44.363148+02:00 server-timo dhcpcd[969]: lan0: deleting address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.365306+02:00 server-timo dhcpcd[969]: lan0: IAID 59:b7:51:09
2025-04-25T15:06:44.365330+02:00 server-timo dhcpcd[969]: lan0: adding address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.365407+02:00 server-timo dhcpcd[969]: lan0: removing interface
2025-04-25T15:06:44.365451+02:00 server-timo dhcpcd[969]: lan0: deleting address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.367532+02:00 server-timo dhcpcd[969]: lan0: IAID 59:b7:51:09
2025-04-25T15:06:44.367553+02:00 server-timo dhcpcd[969]: lan0: adding address fe80::aaa1:59ff:feb7:5109
2025-04-25T15:06:44.367635+02:00 server-timo dhcpcd[969]: lan1: removing interface
2025-04-25T15:06:44.367646+02:00 server-timo dhcpcd[969]: lan1: deleting address fe80::8ac9:b3ff:feb4:733
And this keeps going on forever, flooding the syslog with similar lines.
It only stops when I restart the dhcpcd service.
Any idea what is going on here?
Cheers,
Timo
Possibly related issues: https://github.com/NetworkConfiguration/dhcpcd/issues/314, https://github.com/NetworkConfiguration/dhcpcd/issues/359, https://github.com/NetworkConfiguration/dhcpcd/issues/402
I noticed this comment which contains the suggestion to upgrade to dhcpcd-10.0.10, as it fixes a lot of PPP issues. However, I'm running version "1:10.1.0-9" from Debian. So that seems to be a newer version.
Another user indicated in this comment that he has a similar issue with version 10.1.0 from the Debian repository. And in this comment, he states that the issue doesn't exist in latest master branch.
Could it be that this issue was fixed in one of the newer releases, i.e. in version 10.2.x?
I've just installed version "1:10.2.2-5" from the Debian experimental release and rebooted the system a few times; and haven't seen the issue anymore. I'll keep monitoring if it reappears or not.
@rsmarples would you have any educated guess as to which commit restored operations with PPP? Since Debian is frozed in preparation for Trixie's release, the best I can do is cherry-pick specific commits and add them to the 10.1.0 that's shipping with Trixie.
@perkelix I'm not convinced it's any PPP issue, nor any I have seen before. From the logs all we can tell is that the lan0 and lan1 interfaces keep being added and removed. This tells me dhcpcd is doing the best it can.
@Stamgastje if you see this situation again, please run ip monitor and capture it's output.
If we see the same interfaces coming and going we know the root cause of the issue is outside dhcpcd.
Not relevant to a fix, but 6299f1f1cabecdee1f82e06fc6cce234f933eea9 is related just by the actions happening here.
udev is also in play here, so whilst ip monitor might not show anything, it could be a bug in udev announcements looping.
I have no idea how to work or debug that one though.
On Wed, Apr 30, 2025 at 04:45:40AM -0700, Roy Marples wrote:
udev is also in play here, so whilst
ip monitormight not show anything, it could be a bug in udev announcements looping.I have no idea how to work or debug that one though.
By interleaving all the things :-)
$ udevadm monitor& ip -t monitor -t& journalctl -u dhcpcd -f&
--Daniel
