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.

Sign up for GitHub

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

Jump to bottom

requires 'dhcpcd -k' to aquire a good ipv4 lease #298

Closed
dkwo opened this issue Feb 23, 2024 · 12 comments
Closed

requires 'dhcpcd -k' to aquire a good ipv4 lease #298

dkwo opened this issue Feb 23, 2024 · 12 comments
Labels
bug

Comments

@dkwo
Copy link

dkwo commented Feb 23, 2024

After suspending, or upon reboot, dhcpcd seems stuck, either with no carrier or with the ipv4all ip address.
This is on Void Linux, which has dhcpcd-10.0.5 managed through a runit service:

$ cat /etc/sv/dhcpcd/run 
#!/bin/sh
exec 2>&1
[ -r conf ] && . ./conf
exec dhcpcd -B ${OPTS:=-M} 1>&2

It happens both on my home network (openwrt) as well as on enterprise network (eduroam at a university).
Issuing dhcpcd -k usually solves it, as seen in the log.

The config file is rather standard (if I add noipv4all, then it gets stuck at waiting for a carrier):

$ cat /etc/dhcpcd.conf 
controlgroup wheel
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

An excerpt from the log (I redacted a bunch of addresses, let me know if they're needed. Also, for some reason, the logs appear twice as info and as notice, which I removed by hand to avoid clutter. Not sure if it's a mistake in the runit service though.):

2024-02-23T16:00:47.74842 daemon.info: Feb 23 11:00:47 dhcpcd[1155]: wlp4s0: carrier acquired
2024-02-23T16:00:47.74845 daemon.notice: Feb 23 11:00:47 dhcpcd: wlp4s0: carrier acquired
dhcpcd[1155]: wlp4s0: connected to Access Point: eduroam
dhcpcd[1155]: wlp4s0: IAID [xxx]
dhcpcd[1155]: wlp4s0: adding address [xxx]
dhcpcd[1155]: wlp4s0: soliciting an IPv6 router
dhcpcd[1155]: wlp4s0: soliciting a DHCP lease
dhcpcd[1155]: wlp4s0: probing for an IPv4LL address
dhcpcd[1155]: wlp4s0: using IPv4LL address 169.254.69.177
dhcpcd[1155]: wlp4s0: adding route to 169.254.0.0/16
dhcpcd[1155]: wlp4s0: adding default route
dhcpcd[1155]: wlp4s0: no IPv6 Routers available
dhcpcd[1645]: sending signal ALRM to pid 1155
dhcpcd[1645]: waiting for pid 1155 to exit
dhcpcd[1155]: received SIGALRM, releasing
dhcpcd[1155]: eth0: removing interface
dhcpcd: received SIGALRM, releasing
dhcpcd: eth0: removing interface
dhcpcd[1155]: wlp4s0: removing interface
dhcpcd[1155]: wlp4s0: deleting address [xxx]
dhcpcd[1155]: wlp4s0: deleting route to 169.254.0.0/16
dhcpcd[1155]: wlp4s0: deleting default route
dhcpcd[1155]: enp0s31f6: removing interface
dhcpcd[1155]: dhcpcd exited
dhcpcd[1696]: dhcpcd-10.0.5 starting
dhcpcd[1696]: dev: loaded udev
dhcpcd[1696]: DUID [xxx]
dhcpcd[1696]: wlp4s0: connected to Access Point: eduroam
dhcpcd[1696]: enp0s31f6: waiting for carrier
dhcpcd[1696]: wlp4s0: IAID [xxx]
dhcpcd: enp0s31f6: waiting for carrier
dhcpcd: wlp4s0: IAID [xxx]
dhcpcd[1696]: wlp4s0: adding address [xxx]
dhcpcd[1696]: eth0: waiting for carrier
dhcpcd[1696]: wlp4s0: soliciting an IPv6 router
dhcpcd[1696]: wlp4s0: soliciting a DHCP lease
dhcpcd[1696]: wlp4s0: offered [good ip] from [xxx]
dhcpcd[1696]: wlp4s0: probing address [xxx]
dhcpcd[1696]: wlp4s0: leased [xxx] for 900 seconds
dhcpcd[1696]: wlp4s0: adding route to [xxx]
dhcpcd[1696]: wlp4s0: adding default route via [xxx]
dhcpcd[1645]: pid 1696 failed to exit
dhcpcd[1696]: wlp4s0: no IPv6 Routers available

Do you see anything out of place? Thanks.
@dkwo
Copy link
Author

dkwo commented Feb 23, 2024

Building from master branch _commit=727c78f503d456875e2a3cee7609288b537d9d25 does not change the result.
Also, removing 1>&2 from the service does not change the log output format.

@dkwo
Copy link
Author

dkwo commented Feb 26, 2024

let me add that building from master branch fixes the issue with openwrt router (but not with eduroam, see above).
the two config differ in wpa_supplcant point:

$ doas cat /etc/wpa_supplicant/wpa_supplicant-wlp4s0.conf
ctrl_interface=/run/wpa_supplicant
ctrl_interface_group=wheel
update_config=1
eapol_version=1
ap_scan=1
fast_reauth=1
mac_addr=1
preassoc_mac_addr=1
gas_rand_mac_addr=1
country=US
ext_password_backend=file:/etc/wpa_supplicant/wifi-passwords.conf

network={
	ssid="eduroam"
	scan_ssid=1
	key_mgmt=WPA-EAP
	eap=TTLS
	identity="xxx@yyy"
	anonymous_identity="anonymous@yyy"
	ca_cert2="/etc/wpa_supplicant/eduroam.cer"
	phase2="auth=PAP"
#	phase2="auth=MSCHAPV2"
	password=ext:pwd_eduroam
}

network={
	ssid="home-openwrt"
	key_mgmt=SAE
	ieee80211w=2
	psk=ext:pwd_cia
#	sae_password=
	mac_addr=0
}

@rsmarples
Copy link
Member

Sorry for the late reply, but I have been thinking this over.
About the double log, add -qq to the command line options in the runit service to solve that.

I'll need logging with debug enabled in dhcpcd.conf please.
Also do you know if privsep is enabled or not in your build? dhcpcd --version can tell you this.

@rsmarples rsmarples added the bug label Apr 2, 2024
@dkwo
Copy link
Author

dkwo commented Apr 3, 2024

Thanks for looking at this, and for maintaining dhcpcd.

$ dhcpcd --version 
dhcpcd 10.0.6
Copyright (c) 2006-2023 Roy Marples
Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH

The log with debug enabled:

daemon.notice: Apr  3 15:01:06 seatd: 00:00:00.000 [INFO] [seatd/seat.c:39] Created VT-bound seat seat0
daemon.notice: Apr  3 15:01:06 seatd: 00:00:00.000 [INFO] [seatd/seatd.c:194] seatd started
daemon.debug: Apr  3 15:01:06 dhcpcd[918]: udev: starting
daemon.info: Apr  3 15:01:06 dhcpcd[918]: dev: loaded udev
daemon.info: Apr  3 15:01:06 dhcpcd[918]: DUID [redacted]
daemon.debug: Apr  3 15:01:06 dhcpcd[918]: lo: ignoring due to interface type and no config
daemon.debug: Apr  3 15:01:06 dhcpcd[918]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.debug: Apr  3 15:01:06 dhcpcd[918]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks NOCARRIER
daemon.notice: Apr  3 15:01:06 wpa_supplicant[943]: Successfully initialized wpa_supplicant
daemon.info: Apr  3 15:01:06 chronyd[953]: chronyd version 4.5 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER -SIGND +ASYNCDNS +NTS +SECHASH +IPV6 -DEBUG)
daemon.info: Apr  3 15:01:06 chronyd[953]: Frequency 23.536 +/- 0.902 ppm read from /var/lib/chrony/drift
daemon.debug: Apr  3 15:01:06 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.debug: Apr  3 15:01:06 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks NOCARRIER
daemon.warn: Apr  3 15:01:06 dhcpcd[918]: no interfaces have a carrier
daemon.notice: Apr  3 15:01:06 acpid: starting up with netlink and the input layer
daemon.notice: Apr  3 15:01:06 acpid: 1 rule loaded
daemon.notice: Apr  3 15:01:06 acpid: waiting for events: event logging is on
daemon.notice: Apr  3 15:01:06 seatd: 00:00:00.131 [INFO] [seatd/server.c:145] New client connected (pid: 1014, uid: 1000, gid: 1000)2024-04-03T19:01:06.63087 daemon.notice: Apr  3 15:01:06 seatd: 00:00:00.131 [INFO] [seatd/seat.c:170] Added client 1 to seat0
daemon.notice: Apr  3 15:01:06 seatd: 00:00:00.131 [INFO] [seatd/seat.c:480] Opened client 1 on seat0
daemon.info: Apr  3 15:01:06 dhcpcd[918]: enp0s31f6: waiting for carrier
daemon.info: Apr  3 15:01:06 dhcpcd[918]: wlp4s0: waiting for carrier
daemon.notice: Apr  3 15:01:06 tlp: Applying power save settings...done.
daemon.notice: Apr  3 15:01:07 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=WORLD
daemon.notice: Apr  3 15:01:07 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=WORLD
daemon.notice: Apr  3 15:01:07 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
daemon.notice: Apr  3 15:01:07 tlp: Setting battery charge thresholds...done.
daemon.info: [    1.707045] udevd[89]: starting version 3.2.14
daemon.info: [    1.707566] udevd[90]: starting eudev-3.2.14
daemon.info: [   25.787633] udevd[629]: starting version 3.2.14
daemon.info: [   25.798955] udevd[630]: starting eudev-3.2.14
daemon.info: [   28.578319] udevd[923]: starting version 3.2.14
daemon.info: [   28.584694] udevd[923]: starting eudev-3.2.14
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=US
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=US
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: SME: Trying to authenticate with [redacted] (SSID='eduroam' freq=5260 MHz)
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: Trying to associate with [redacted] (SSID='eduroam' freq=5260 MHz)
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: Associated with [redacted]
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-STARTED EAP authentication started
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/ST=New Jersey/L=Jersey City/O=The USERTRUST Network/CN=USERTrust RSA Certification Authority' hash=[redacted]
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/ST=New Jersey/L=Jersey City/O=The USERTRUST Network/CN=USERTrust RSA Certification Authority' hash=[redacted]
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=US/O=Internet2/CN=InCommon RSA Server CA 2' hash=[redacted]
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=US/ST=New Jersey/O=Rutgers, The State University of New Jersey/CN=ise.ruw.rutgers.edu' hash=[redacted]
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:ise.ruw.rutgers.edu
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:ise-dev-asb.ei.rutgers.edu
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:ise-policy-srv-asb.ei.rutgers.edu
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:ise-policy-srv-kb.ei.rutgers.edu
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:ise-policy-srv-rbhs.ei.rutgers.edu
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
daemon.notice: Apr  3 15:01:09 wpa_supplicant[943]: wlp4s0: PMKSA-CACHE-ADDED [redacted] 0
daemon.notice: Apr  3 15:01:10 wpa_supplicant[943]: wlp4s0: WPA: Key negotiation completed with [redacted] [PTK=CCMP GTK=CCMP]
daemon.notice: Apr  3 15:01:10 wpa_supplicant[943]: wlp4s0: CTRL-EVENT-CONNECTED - Connection to [redacted] completed [id=0 id_str=]
daemon.info: Apr  3 15:01:10 dhcpcd[918]: wlp4s0: carrier acquired
daemon.info: Apr  3 15:01:10 dhcpcd[918]: wlp4s0: connected to Access Point: eduroam
daemon.debug: Apr  3 15:01:10 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks CARRIER
daemon.info: Apr  3 15:01:10 dhcpcd[918]: wlp4s0: IAID [redacted]
daemon.debug: Apr  3 15:01:10 dhcpcd[918]: wlp4s0: delaying IPv4 for 1.4 seconds
daemon.notice: Apr  3 15:01:10 seatd: 00:00:04.409 [INFO] [seatd/seat.c:418] No clients on seat0 to activate
daemon.notice: Apr  3 15:01:10 seatd: 00:00:04.466 [INFO] [seatd/seat.c:524] Closed client 1 on seat0
daemon.notice: Apr  3 15:01:10 seatd: 00:00:04.466 [INFO] [seatd/seat.c:192] Removed client 1 from seat0
daemon.notice: Apr  3 15:01:10 seatd: 00:00:04.466 [INFO] [seatd/client.c:471] Client disconnected
daemon.notice: Apr  3 15:01:11 seatd: 00:00:04.589 [INFO] [seatd/server.c:145] New client connected (pid: 1329, uid: 1000, gid: 1000)2024-04-03T19:01:11.08806 daemon.notice: Apr  3 15:01:11 seatd: 00:00:04.589 [INFO] [seatd/seat.c:170] Added client 1 to seat0
daemon.notice: Apr  3 15:01:11 seatd: 00:00:04.589 [INFO] [seatd/seat.c:480] Opened client 1 on seat0
daemon.debug: Apr  3 15:01:11 dhcpcd[918]: wlp4s0: reading lease: /var/db/dhcpcd/wlp4s0-eduroam.lease
daemon.info: Apr  3 15:01:11 dhcpcd[918]: wlp4s0: rebinding lease of [some good IP4]
daemon.debug: Apr  3 15:01:11 dhcpcd[918]: wlp4s0: sending REQUEST (xid 0x3b6d4932), next in 3.5 seconds
daemon.notice: Apr  3 15:01:14 seatd: 00:00:07.671 [INFO] [seatd/seat.c:418] No clients on seat0 to activate
daemon.notice: Apr  3 15:01:14 seatd: 00:00:07.723 [INFO] [seatd/seat.c:524] Closed client 1 on seat0
daemon.notice: Apr  3 15:01:14 seatd: 00:00:07.723 [INFO] [seatd/seat.c:192] Removed client 1 from seat0
daemon.notice: Apr  3 15:01:14 seatd: 00:00:07.723 [INFO] [seatd/client.c:471] Client disconnected
daemon.notice: Apr  3 15:01:14 seatd: 00:00:07.797 [INFO] [seatd/server.c:145] New client connected (pid: 1481, uid: 1000, gid: 1000)
daemon.notice: Apr  3 15:01:14 seatd: 00:00:07.797 [INFO] [seatd/seat.c:170] Added client 1 to seat0
daemon.notice: Apr  3 15:01:14 seatd: 00:00:07.797 [INFO] [seatd/seat.c:480] Opened client 1 on seat0
daemon.debug: Apr  3 15:01:14 dhcpcd[918]: wlp4s0: sending REQUEST (xid 0x3b6d4932), next in 7.2 seconds
daemon.info: Apr  3 15:01:16 dhcpcd[918]: wlp4s0: probing for an IPv4LL address
daemon.debug: Apr  3 15:01:16 dhcpcd[918]: wlp4s0: probing for 169.254.69.177
daemon.debug: Apr  3 15:01:16 dhcpcd[918]: wlp4s0: ARP probing 169.254.69.177 (1 of 3), next in 1.5 seconds
daemon.err: Apr  3 15:01:16 dhcpcd[918]: wlp4s0: DHCP lease expired
daemon.debug: Apr  3 15:01:16 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks EXPIRE
daemon.info: Apr  3 15:01:16 dhcpcd[918]: wlp4s0: soliciting a DHCP lease
daemon.debug: Apr  3 15:01:16 dhcpcd[918]: wlp4s0: sending DISCOVER (xid 0x46e9aada), next in 3.5 seconds
daemon.notice: Apr  3 15:01:16 seatd: 00:00:10.039 [INFO] [seatd/seat.c:418] No clients on seat0 to activate
daemon.notice: Apr  3 15:01:16 seatd: 00:00:10.093 [INFO] [seatd/seat.c:524] Closed client 1 on seat0
daemon.notice: Apr  3 15:01:16 seatd: 00:00:10.093 [INFO] [seatd/seat.c:192] Removed client 1 from seat0
daemon.notice: Apr  3 15:01:16 seatd: 00:00:10.093 [INFO] [seatd/client.c:471] Client disconnected
daemon.notice: Apr  3 15:01:16 seatd: 00:00:10.146 [INFO] [seatd/server.c:145] New client connected (pid: 1639, uid: 1000, gid: 1000)
daemon.notice: Apr  3 15:01:16 seatd: 00:00:10.146 [INFO] [seatd/seat.c:170] Added client 1 to seat0
daemon.notice: Apr  3 15:01:16 seatd: 00:00:10.146 [INFO] [seatd/seat.c:480] Opened client 1 on seat0
daemon.debug: Apr  3 15:01:17 dhcpcd[918]: wlp4s0: ARP probing 169.254.69.177 (2 of 3), next in 1.7 seconds
daemon.debug: Apr  3 15:01:19 dhcpcd[918]: wlp4s0: ARP probing 169.254.69.177 (3 of 3), next in 2.0 seconds
daemon.debug: Apr  3 15:01:20 dhcpcd[918]: wlp4s0: sending DISCOVER (xid 0x46e9aada), next in 8.8 seconds
daemon.info: Apr  3 15:01:21 dhcpcd[918]: wlp4s0: using IPv4LL address 169.254.69.177
daemon.debug: Apr  3 15:01:21 dhcpcd[918]: wlp4s0: adding IP address 169.254.69.177/16 broadcast 169.254.255.255
daemon.info: Apr  3 15:01:21 dhcpcd[918]: wlp4s0: adding route to 169.254.0.0/16
daemon.info: Apr  3 15:01:21 dhcpcd[918]: wlp4s0: adding default route
daemon.debug: Apr  3 15:01:21 dhcpcd[918]: wlp4s0: ARP announcing 169.254.69.177 (1 of 2), next in 2.0 seconds
daemon.debug: Apr  3 15:01:21 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks IPV4LL
daemon.debug: Apr  3 15:01:23 dhcpcd[918]: wlp4s0: ARP announcing 169.254.69.177 (2 of 2)
daemon.debug: Apr  3 15:01:28 dhcpcd[918]: wlp4s0: sending DISCOVER (xid 0x46e9aada), next in 16.9 seconds
daemon.debug: Apr  3 15:01:45 dhcpcd[918]: wlp4s0: sending DISCOVER (xid 0x46e9aada), next in 32.6 seconds
daemon.debug: Apr  3 15:02:18 dhcpcd[918]: wlp4s0: sending DISCOVER (xid 0x46e9aada), next in 64.6 seconds
daemon.info: Apr  3 15:02:40 dhcpcd[1866]: sending signal ALRM to pid 918
daemon.info: Apr  3 15:02:40 dhcpcd[1866]: waiting for pid 918 to exit
daemon.info: Apr  3 15:02:40 dhcpcd[918]: received SIGALRM, releasing
daemon.info: Apr  3 15:02:40 dhcpcd[918]: wlp4s0: removing interface
daemon.debug: Apr  3 15:02:40 dhcpcd[918]: wlp4s0: deleting IP address 169.254.69.177/16
daemon.info: Apr  3 15:02:40 dhcpcd[918]: wlp4s0: deleting route to 169.254.0.0/16
daemon.info: Apr  3 15:02:40 dhcpcd[918]: wlp4s0: deleting default route
daemon.debug: Apr  3 15:02:40 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks IPV4LL
daemon.debug: Apr  3 15:02:40 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks STOP
daemon.debug: Apr  3 15:02:40 dhcpcd[918]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks STOPPED
daemon.info: Apr  3 15:02:40 dhcpcd[918]: enp0s31f6: removing interface
daemon.debug: Apr  3 15:02:40 dhcpcd[918]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks STOPPED
daemon.debug: Apr  3 15:02:40 dhcpcd[918]: dev: unloaded udev
daemon.info: Apr  3 15:02:40 dhcpcd[918]: dhcpcd exited
daemon.info: Apr  3 15:02:40 dhcpcd[1907]: dhcpcd-10.0.6 starting
daemon.debug: Apr  3 15:02:40 dhcpcd[1907]: udev: starting
daemon.info: Apr  3 15:02:40 dhcpcd[1907]: dev: loaded udev
daemon.info: Apr  3 15:02:40 dhcpcd[1907]: DUID [redacted]
daemon.debug: Apr  3 15:02:40 dhcpcd[1907]: lo: ignoring due to interface type and no config
daemon.debug: Apr  3 15:02:40 dhcpcd[1907]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.debug: Apr  3 15:02:40 dhcpcd[1907]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks NOCARRIER
daemon.debug: Apr  3 15:02:40 dhcpcd[1907]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.info: Apr  3 15:02:40 dhcpcd[1907]: wlp4s0: connected to Access Point: eduroam
daemon.debug: Apr  3 15:02:40 dhcpcd[1907]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks CARRIER
daemon.info: Apr  3 15:02:40 dhcpcd[1907]: enp0s31f6: waiting for carrier
daemon.info: Apr  3 15:02:40 dhcpcd[1907]: wlp4s0: IAID [redacted]
daemon.debug: Apr  3 15:02:40 dhcpcd[1907]: wlp4s0: delaying IPv4 for 1.0 seconds
daemon.debug: Apr  3 15:02:41 dhcpcd[1907]: wlp4s0: reading lease: /var/db/dhcpcd/wlp4s0-eduroam.lease
daemon.info: Apr  3 15:02:41 dhcpcd[1907]: wlp4s0: soliciting a DHCP lease
daemon.debug: Apr  3 15:02:41 dhcpcd[1907]: wlp4s0: sending DISCOVER (xid 0x66d7e108), next in 4.8 seconds
daemon.info: Apr  3 15:02:42 dhcpcd[1907]: wlp4s0: offered [good ip4] from 192.0.2.2
daemon.debug: Apr  3 15:02:42 dhcpcd[1907]: wlp4s0: sending REQUEST (xid 0x66d7e108), next in 3.0 seconds
daemon.debug: Apr  3 15:02:42 dhcpcd[1907]: wlp4s0: acknowledged [good] from 192.0.2.2
daemon.info: Apr  3 15:02:42 dhcpcd[1907]: wlp4s0: probing address [good]/22
daemon.debug: Apr  3 15:02:42 dhcpcd[1907]: wlp4s0: probing for [good]
daemon.debug: Apr  3 15:02:42 dhcpcd[1907]: wlp4s0: ARP probing [good] (1 of 3), next in 1.9 seconds
daemon.debug: Apr  3 15:02:44 dhcpcd[1907]: wlp4s0: ARP probing [good] (2 of 3), next in 1.5 seconds
daemon.debug: Apr  3 15:02:45 dhcpcd[1907]: wlp4s0: ARP probing [good] (3 of 3), next in 2.0 seconds
daemon.debug: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: DAD completed for [good]
daemon.info: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: leased [good] for 900 seconds
daemon.debug: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: renew in 450 seconds, rebind in 787 seconds
daemon.debug: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: writing lease: /var/db/dhcpcd/wlp4s0-eduroam.lease
daemon.debug: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: adding IP address [good]/22 broadcast [good]
daemon.info: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: adding route to [good]
daemon.info: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: adding default route via [good]
daemon.debug: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: ARP announcing [good] (1 of 2), next in 2.0 seconds
daemon.debug: Apr  3 15:02:47 dhcpcd[1907]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks BOUND
daemon.debug: Apr  3 15:02:49 dhcpcd[1907]: wlp4s0: ARP announcing [good] (2 of 2)
daemon.err: Apr  3 15:02:50 dhcpcd[1866]: pid 1907 failed to exit

The etc/dhcpcd.conf file:

controlgroup wheel
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
noipv6rs
noipv6
debug

@rsmarples
Copy link
Member

Well, there's nothing that stands out as wrong in your logs.
Is it possible you could enable privsep support? Generally it's as simple as adding a dhcpcd system user with a home directory of /var/chroot/dhcpcd and ensure that directory exists.
I ask as I generally don't test non privsep builds too much.

@rsmarples
Copy link
Member

And thanks for the thanks :)

@dkwo
Copy link
Author

dkwo commented Apr 4, 2024

Sure. The Void Linux package already creates a system account _dhcpcd with homedir /var/db/dhcpcd.
Would rebuilding the package with privsep option enabled work, or does it need specifically homedir set to /var/chroot/dhcpcd?

@rsmarples
Copy link
Member

The directory itself doesn't matter as long as it exists.

@dkwo
Copy link
Author

dkwo commented Apr 5, 2024

Building with privsep

$ dhcpcd --version 
dhcpcd 10.0.6
Copyright (c) 2006-2023 Roy Marples
Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH PRIVSEP

produces the log

daemon.info: Apr  5 11:19:28 dhcpcd[924]: dhcpcd-10.0.6 starting
daemon.info: [    1.703200] udevd[91]: starting version 3.2.14
daemon.info: [    1.703748] udevd[92]: starting eudev-3.2.14
daemon.info: [   13.279336] udevd[628]: starting version 3.2.14
daemon.info: [   13.290977] udevd[629]: starting eudev-3.2.14
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: udev: starting
daemon.info: Apr  5 11:19:28 dhcpcd[958]: dev: loaded udev
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: spawned privileged proxy on PID 958
daemon.info: [   16.183403] udevd[922]: starting version 3.2.14
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: spawned network proxy on PID 960
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: spawned controller proxy on PID 961
daemon.info: Apr  5 11:19:28 dhcpcd[958]: DUID [redacted]
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: sandbox: seccomp
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: lo: ignoring due to interface type and no config
daemon.info: [   16.187823] udevd[922]: starting eudev-3.2.14
daemon.notice: Apr  5 11:19:28 wpa_supplicant[938]: Successfully initialized wpa_supplicant
daemon.notice: Apr  5 11:19:28 acpid: starting up with netlink and the input layer
daemon.notice: Apr  5 11:19:28 acpid: 1 rule loaded
daemon.notice: Apr  5 11:19:28 acpid: waiting for events: event logging is on
daemon.notice: Apr  5 11:19:28 seatd: 00:00:00.136 [INFO] [seatd/server.c:145] New client connected (pid: 997, uid: 1000, gid: 1000)
daemon.notice: Apr  5 11:19:28 seatd: 00:00:00.136 [INFO] [seatd/seat.c:170] Added client 1 to seat0
daemon.notice: Apr  5 11:19:28 seatd: 00:00:00.136 [INFO] [seatd/seat.c:480] Opened client 1 on seat0
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.notice: Apr  5 11:19:28 tlp: Applying power save settings...done.
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks NOCARRIER
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.debug: Apr  5 11:19:28 dhcpcd[958]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks NOCARRIER
daemon.warn: Apr  5 11:19:28 dhcpcd[958]: no interfaces have a carrier
daemon.notice: Apr  5 11:19:28 tlp: Setting battery charge thresholds...done.
daemon.info: Apr  5 11:19:28 dhcpcd[958]: enp0s31f6: waiting for carrier
daemon.info: Apr  5 11:19:28 dhcpcd[958]: wlp4s0: waiting for carrier
daemon.notice: Apr  5 11:19:28 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=WORLD
daemon.notice: Apr  5 11:19:28 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=WORLD
daemon.notice: Apr  5 11:19:28 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=US
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=US
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: SME: Trying to authenticate with [redacted] (SSID='eduroam' freq=5260 MHz)
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: Trying to associate with [redacted] (SSID='eduroam' freq=5260 MHz)
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: Associated with [redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-STARTED EAP authentication started
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=2 [redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=2 [redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=1 [redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-CERT depth=0 [redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:[redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:[redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:[redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:[redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:[redacted]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: PMKSA-CACHE-ADDED [redacted] 0
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: WPA: Key negotiation completed with [redacted] [PTK=CCMP GTK=CCMP]
daemon.notice: Apr  5 11:19:31 wpa_supplicant[938]: wlp4s0: CTRL-EVENT-CONNECTED - Connection to [redacted] completed [id=0 id_str=]
daemon.info: Apr  5 11:19:31 dhcpcd[958]: wlp4s0: carrier acquired
daemon.info: Apr  5 11:19:31 dhcpcd[958]: wlp4s0: connected to Access Point: eduroam
daemon.debug: Apr  5 11:19:31 dhcpcd[958]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks CARRIER
daemon.info: Apr  5 11:19:31 dhcpcd[958]: wlp4s0: IAID [redacted]
daemon.debug: Apr  5 11:19:31 dhcpcd[958]: wlp4s0: delaying IPv4 for 1.7 seconds
daemon.debug: Apr  5 11:19:33 dhcpcd[958]: wlp4s0: reading lease: /var/db/dhcpcd/wlp4s0-eduroam.lease
daemon.debug: Apr  5 11:19:33 dhcpcd[958]: wlp4s0: discarding expired lease
daemon.info: Apr  5 11:19:33 dhcpcd[958]: wlp4s0: soliciting a DHCP lease
daemon.debug: Apr  5 11:19:33 dhcpcd[958]: wlp4s0: sending DISCOVER (xid 0x97ecbb5e), next in 4.8 seconds
daemon.debug: Apr  5 11:19:33 dhcpcd[958]: wlp4s0: spawned BPF BOOTP on PID 1333
daemon.debug: Apr  5 11:19:38 dhcpcd[958]: wlp4s0: sending DISCOVER (xid 0x97ecbb5e), next in 7.5 seconds
daemon.debug: Apr  5 11:19:38 dhcpcd[958]: wlp4s0: process BPF BOOTP already started on pid 1333
daemon.info: Apr  5 11:19:38 dhcpcd[958]: wlp4s0: probing for an IPv4LL address
daemon.debug: Apr  5 11:19:38 dhcpcd[958]: wlp4s0: spawned BPF ARP 169.254.69.177 on PID 1355
daemon.debug: Apr  5 11:19:38 dhcpcd[958]: wlp4s0: probing for 169.254.69.177
daemon.debug: Apr  5 11:19:38 dhcpcd[958]: wlp4s0: ARP probing 169.254.69.177 (1 of 3), next in 1.5 seconds
daemon.debug: Apr  5 11:19:39 dhcpcd[958]: wlp4s0: ARP probing 169.254.69.177 (2 of 3), next in 1.2 seconds
daemon.debug: Apr  5 11:19:40 dhcpcd[958]: wlp4s0: ARP probing 169.254.69.177 (3 of 3), next in 2.0 seconds
daemon.info: Apr  5 11:19:42 dhcpcd[958]: wlp4s0: using IPv4LL address 169.254.69.177
daemon.debug: Apr  5 11:19:42 dhcpcd[958]: wlp4s0: adding IP address 169.254.69.177/16 broadcast 169.254.255.255
daemon.info: Apr  5 11:19:42 dhcpcd[958]: wlp4s0: adding route to 169.254.0.0/16
daemon.info: Apr  5 11:19:42 dhcpcd[958]: wlp4s0: adding default route
daemon.debug: Apr  5 11:19:42 dhcpcd[958]: wlp4s0: ARP announcing 169.254.69.177 (1 of 2), next in 2.0 seconds
daemon.debug: Apr  5 11:19:42 dhcpcd[958]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks IPV4LL
daemon.debug: Apr  5 11:19:44 dhcpcd[958]: wlp4s0: ARP announcing 169.254.69.177 (2 of 2)
daemon.debug: Apr  5 11:19:45 dhcpcd[958]: wlp4s0: sending DISCOVER (xid 0x97ecbb5e), next in 16.6 seconds
daemon.debug: Apr  5 11:19:45 dhcpcd[958]: wlp4s0: process BPF BOOTP already started on pid 1333
daemon.debug: Apr  5 11:20:02 dhcpcd[958]: wlp4s0: sending DISCOVER (xid 0x97ecbb5e), next in 32.2 seconds
daemon.debug: Apr  5 11:20:02 dhcpcd[958]: wlp4s0: process BPF BOOTP already started on pid 1333
daemon.info: Apr  5 11:20:19 dhcpcd[1393]: sending signal ALRM to pid 924
daemon.info: Apr  5 11:20:19 dhcpcd[1393]: waiting for pid 924 to exit
daemon.info: Apr  5 11:20:19 dhcpcd[958]: received SIGALRM, releasing
daemon.info: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: removing interface
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: deleting IP address 169.254.69.177/16
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: BPF ARP 169.254.69.177 exited from PID 1355
daemon.info: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: deleting route to 169.254.0.0/16
daemon.info: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: deleting default route
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks IPV4LL
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks STOP
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks STOPPED
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: wlp4s0: BPF BOOTP exited from PID 1333
daemon.info: Apr  5 11:20:19 dhcpcd[958]: enp0s31f6: removing interface
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks STOPPED
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: network proxy exited from PID 960
daemon.debug: Apr  5 11:20:19 dhcpcd[958]: control proxy exited from PID 961
daemon.info: Apr  5 11:20:19 dhcpcd[958]: dhcpcd exited
daemon.info: Apr  5 11:20:19 dhcpcd[1434]: dhcpcd-10.0.6 starting
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: udev: starting
daemon.info: Apr  5 11:20:19 dhcpcd[1435]: dev: loaded udev
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: spawned privileged proxy on PID 1435
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: spawned network proxy on PID 1436
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: spawned controller proxy on PID 1437
daemon.info: Apr  5 11:20:19 dhcpcd[1435]: DUID [redacted]
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: sandbox: seccomp
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: lo: ignoring due to interface type and no config
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: enp0s31f6: executing: /usr/libexec/dhcpcd-run-hooks NOCARRIER
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks PREINIT
daemon.info: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: connected to Access Point: eduroam
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks CARRIER
daemon.info: Apr  5 11:20:19 dhcpcd[1435]: enp0s31f6: waiting for carrier
daemon.info: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: IAID [redacted]
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: delaying IPv4 for 0.1 seconds
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: reading lease: /var/db/dhcpcd/wlp4s0-eduroam.lease
daemon.info: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: soliciting a DHCP lease
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: sending DISCOVER (xid 0x1948731a), next in 4.9 seconds
daemon.debug: Apr  5 11:20:19 dhcpcd[1435]: wlp4s0: spawned BPF BOOTP on PID 1451
daemon.info: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: offered [good] from 192.0.2.2
daemon.debug: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: sending REQUEST (xid 0x1948731a), next in 3.8 seconds
daemon.debug: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: process BPF BOOTP already started on pid 1451
daemon.debug: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: acknowledged [good] from 192.0.2.2
daemon.debug: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: spawned BPF ARP [good] on PID 1454
daemon.info: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: probing address [good]/22
daemon.debug: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: probing for [good]
daemon.debug: Apr  5 11:20:20 dhcpcd[1435]: wlp4s0: ARP probing [good] (1 of 3), next in 1.7 seconds
daemon.debug: Apr  5 11:20:22 dhcpcd[1435]: wlp4s0: ARP probing [good] (2 of 3), next in 1.3 seconds
daemon.debug: Apr  5 11:20:23 dhcpcd[1435]: wlp4s0: ARP probing [good] (3 of 3), next in 2.0 seconds
daemon.debug: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: DAD completed for [good]
daemon.info: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: leased [good] for 900 seconds
daemon.debug: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: renew in 450 seconds, rebind in 787 seconds
daemon.debug: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: writing lease: /var/db/dhcpcd/wlp4s0-eduroam.lease
daemon.debug: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: adding IP address [good]/22 broadcast [good]
daemon.info: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: adding route to [good]/22
daemon.info: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: adding default route via [good]
daemon.debug: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: ARP announcing [good] (1 of 2), next in 2.0 seconds
daemon.debug: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks BOUND
daemon.debug: Apr  5 11:20:25 dhcpcd[1435]: wlp4s0: BPF BOOTP exited from PID 1451
daemon.debug: Apr  5 11:20:27 dhcpcd[1435]: wlp4s0: ARP announcing [good] (2 of 2)
daemon.err: Apr  5 11:20:29 dhcpcd[1393]: pid 1434 failed to exit

The template that Void Linux uses to build dhcpcd is at https://github.com/void-linux/void-packages/tree/master/srcpkgs/dhcpcd
I edited it for the new version, and enabled the privsep build option.

BTW, you might be interested in upstreaming the privsep-ppc-build.patch in the patch folder.

@dkwo
Copy link
Author

dkwo commented Apr 5, 2024

I now suspect this may be related to runit: if I disable the service, and either re-enable it or start dhcpcd manually after logging in (i.e. presumably after every other service like udev, wpa_supplicant etc have settled), then the issue is not present.

@dkwo
Copy link
Author

dkwo commented Apr 5, 2024

However, after suspending for a few minutes, the same issue comes back:

daemon.info: Apr  5 15:14:17 dhcpcd[1339]: wlp4s0: carrier acquired
daemon.debug: Apr  5 15:14:17 dhcpcd[1339]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks CARRIER
daemon.info: Apr  5 15:14:17 dhcpcd[1339]: wlp4s0: IAID [redact]
daemon.debug: Apr  5 15:14:17 dhcpcd[1339]: wlp4s0: delaying IPv4 for 1.1 seconds
daemon.debug: Apr  5 15:14:18 dhcpcd[1339]: wlp4s0: reading lease: /var/db/dhcpcd/wlp4s0-eduroam.lease
daemon.info: Apr  5 15:14:18 dhcpcd[1339]: wlp4s0: rebinding lease of [good]
daemon.debug: Apr  5 15:14:18 dhcpcd[1339]: wlp4s0: spawned BPF ARP [good] on PID 9744
daemon.debug: Apr  5 15:14:18 dhcpcd[1339]: wlp4s0: sending REQUEST (xid 0xb8dd4106), next in 3.1 seconds
daemon.debug: Apr  5 15:14:18 dhcpcd[1339]: wlp4s0: spawned BPF BOOTP on PID 9745
daemon.debug: Apr  5 15:14:21 dhcpcd[1339]: wlp4s0: sending REQUEST (xid 0xb8dd4106), next in 7.2 seconds
daemon.debug: Apr  5 15:14:21 dhcpcd[1339]: wlp4s0: process BPF BOOTP already started on pid 9745
daemon.info: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: probing for an IPv4LL address
daemon.debug: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: probing for 169.254.53.216
daemon.debug: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: spawned BPF ARP 169.254.53.216 on PID 9748
daemon.debug: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: ARP probing 169.254.53.216 (1 of 3), next in 1.5 seconds
daemon.err: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: DHCP lease expired
daemon.debug: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks EXPIRE
daemon.debug: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: BPF BOOTP exited from PID 9745
daemon.info: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: soliciting a DHCP lease
daemon.debug: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: spawned BPF BOOTP on PID 9759
daemon.debug: Apr  5 15:14:23 dhcpcd[1339]: wlp4s0: sending DISCOVER (xid 0x8e4d3ede), next in 3.7 seconds
daemon.debug: Apr  5 15:14:25 dhcpcd[1339]: wlp4s0: ARP probing 169.254.53.216 (2 of 3), next in 1.1 seconds
daemon.debug: Apr  5 15:14:26 dhcpcd[1339]: wlp4s0: ARP probing 169.254.53.216 (3 of 3), next in 2.0 seconds
daemon.debug: Apr  5 15:14:27 dhcpcd[1339]: wlp4s0: sending DISCOVER (xid 0x8e4d3ede), next in 7.1 seconds
daemon.debug: Apr  5 15:14:27 dhcpcd[1339]: wlp4s0: process BPF BOOTP already started on pid 9759
daemon.info: Apr  5 15:14:28 dhcpcd[1339]: wlp4s0: using IPv4LL address 169.254.53.216
daemon.debug: Apr  5 15:14:28 dhcpcd[1339]: wlp4s0: adding IP address 169.254.53.216/16 broadcast 169.254.255.255
daemon.info: Apr  5 15:14:28 dhcpcd[1339]: wlp4s0: adding route to 169.254.0.0/16
daemon.info: Apr  5 15:14:28 dhcpcd[1339]: wlp4s0: adding default route
daemon.debug: Apr  5 15:14:28 dhcpcd[1339]: wlp4s0: ARP announcing 169.254.53.216 (1 of 2), next in 2.0 seconds
daemon.debug: Apr  5 15:14:28 dhcpcd[1339]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks IPV4LL
daemon.debug: Apr  5 15:14:30 dhcpcd[1339]: wlp4s0: ARP announcing 169.254.53.216 (2 of 2)
daemon.debug: Apr  5 15:14:34 dhcpcd[1339]: wlp4s0: sending DISCOVER (xid 0x8e4d3ede), next in 16.6 seconds
daemon.debug: Apr  5 15:14:34 dhcpcd[1339]: wlp4s0: process BPF BOOTP already started on pid 9759
daemon.debug: Apr  5 15:14:50 dhcpcd[1339]: wlp4s0: sending DISCOVER (xid 0x8e4d3ede), next in 31.5 seconds
daemon.debug: Apr  5 15:14:50 dhcpcd[1339]: wlp4s0: process BPF BOOTP already started on pid 9759
daemon.warn: Apr  5 15:15:01 chronyd[951]: Forward time jump detected!
daemon.info: Apr  5 15:15:01 chronyd[951]: Can't synchronise: no selectable sources
daemon.warn: Apr  5 15:15:01 dhcpcd[1339]: wlp4s0: [redact] claims 169.254.53.216
daemon.debug: Apr  5 15:15:01 dhcpcd[1339]: wlp4s0: defended address 169.254.53.216
daemon.warn: Apr  5 15:15:02 dhcpcd[1339]: wlp4s0: [redact] claims 169.254.53.216
daemon.warn: Apr  5 15:15:02 dhcpcd[1339]: wlp4s0: 10 second defence failed for 169.254.53.216
daemon.debug: Apr  5 15:15:02 dhcpcd[1339]: wlp4s0: deleting IP address 169.254.53.216/16
daemon.info: Apr  5 15:15:02 dhcpcd[1339]: wlp4s0: deleting route to 169.254.0.0/16
daemon.info: Apr  5 15:15:02 dhcpcd[1339]: wlp4s0: deleting default route
daemon.debug: Apr  5 15:15:02 dhcpcd[1339]: wlp4s0: BPF ARP 169.254.53.216 exited from PID 9748
daemon.debug: Apr  5 15:15:02 dhcpcd[1339]: wlp4s0: executing: /usr/libexec/dhcpcd-run-hooks IPV4LL
daemon.debug: Apr  5 15:15:22 dhcpcd[1339]: wlp4s0: sending DISCOVER (xid 0x8e4d3ede), next in 63.3 seconds
daemon.debug: Apr  5 15:15:22 dhcpcd[1339]: wlp4s0: process BPF BOOTP already started on pid 9759
daemon.debug: Apr  5 15:16:25 dhcpcd[1339]: wlp4s0: sending DISCOVER (xid 0x8e4d3ede), next in 63.2 seconds
daemon.debug: Apr  5 15:16:25 dhcpcd[1339]: wlp4s0: process BPF BOOTP already started on pid 9759

@dkwo
Copy link
Author

dkwo commented May 29, 2024

Since today, I'm unable to reproduce this.
Either something changed with the settings at my University, or updating the kernel to the 6.9 series and/or reverting to wpa_supplicant released (instead of master branch) fixed this. I'll reopen if I can reproduce it again.
Thanks.

@dkwo dkwo closed this as completed May 29, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rsmarples @dkwo