FS#66191 - [dhcpcd 9.0] It takes 90 seconds for dhcpcd to start -> timeout.

Attached to Project: Arch Linux
Opened by Frederic Bezies (fredbezies) - Friday, 10 April 2020, 05:57 GMT
Last edited by Antonio Rojas (arojas) - Saturday, 11 April 2020, 22:13 GMT
Task Type Bug Report
Category Packages: Testing
Status Closed
Assigned To Antonio Rojas (arojas)
Architecture All
Severity Low
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 2
Private No

Details

Description: I noticed that dhdcpd 9.0 is taking up to 90 seconds to start.

Here is what I get in systemd-analyze blame log:

systemd-analyze blame
1min 30.180s dhcpcd.service

And an journalctl -xe | grep dhcpcd:

journalctl -xe | grep dhcpcd
avril 10 07:50:47 fredo-arch-mate systemd[1]: Starting dhcpcd on all interfaces...
-- Subject: L'unité (unit) dhcpcd.service a commencé à démarrer
-- L'unité (unit) dhcpcd.service a commencé à démarrer.
avril 10 07:50:47 fredo-arch-mate dhcpcd[529]: no such user _dhcpcd
avril 10 07:50:47 fredo-arch-mate dhcpcd[529]: no such user _dhcpcd
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: dev: loaded udev
avril 10 07:50:47 fredo-arch-mate systemd[1]: dhcpcd.service: Can't open PID file /run/dhcpcd.pid (yet?) after start: Operation not permitted
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: enp6s0: waiting for carrier
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: enp6s0: carrier acquired
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: DUID 00:01:00:01:22:28:5a:a3:e0:d5:5e:24:93:32
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: enp6s0: IAID 5e:24:93:32
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: enp6s0: adding address fe80::d79f:1a38:5635:f6fc
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: enp6s0: carrier lost
avril 10 07:50:47 fredo-arch-mate dhcpcd[538]: enp6s0: deleting address fe80::d79f:1a38:5635:f6fc
avril 10 07:50:50 fredo-arch-mate dhcpcd[538]: enp6s0: carrier acquired
avril 10 07:50:50 fredo-arch-mate dhcpcd[538]: enp6s0: IAID 5e:24:93:32
avril 10 07:50:50 fredo-arch-mate dhcpcd[538]: enp6s0: adding address fe80::d79f:1a38:5635:f6fc
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: soliciting a DHCP lease
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: offered 192.168.1.6 from 192.168.1.254
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: leased 192.168.1.6 for 43200 seconds
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: adding route to 192.168.1.0/24
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: adding default route via 192.168.1.254
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: soliciting an IPv6 router
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: Router Advertisement from fe80::160c:76ff:fe7a:5f23
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: adding address 2a01:e0a:535:e7b0:1cd:d459:ecb5:3f46/64
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: adding route to 2a01:e0a:535:e7b0::/64
avril 10 07:50:51 fredo-arch-mate dhcpcd[538]: enp6s0: adding default route via fe80::160c:76ff:fe7a:5f23
avril 10 07:50:56 fredo-arch-mate dhcpcd[538]: enp6s0: pid 546 deleted default route via fe80::160c:76ff:fe7a:5f23
avril 10 07:52:17 fredo-arch-mate systemd[1]: dhcpcd.service: start operation timed out. Terminating.
avril 10 07:52:17 fredo-arch-mate dhcpcd[538]: received SIGTERM, stopping
avril 10 07:52:17 fredo-arch-mate dhcpcd[538]: enp6s0: removing interface
avril 10 07:52:17 fredo-arch-mate dhcpcd[538]: dhcpcd exited
avril 10 07:52:17 fredo-arch-mate systemd[1]: dhcpcd.service: Failed with result 'timeout'.
-- The unit dhcpcd.service has entered the 'failed' state with result 'timeout'.
avril 10 07:52:17 fredo-arch-mate systemd[1]: Failed to start dhcpcd on all interfaces.
-- Subject: L'unité (unit) dhcpcd.service a échoué
-- L'unité (unit) dhcpcd.service a échoué, avec le résultat failed.

Additional info:


Steps to reproduce:

Just upgrade dhcpd and reboot.
This task depends upon

Closed by  Antonio Rojas (arojas)
Saturday, 11 April 2020, 22:13 GMT
Reason for closing:  Fixed
Additional comments about closing:  dhcpcd 9.0.0-2
Comment by Sebastiaan Lokhorst (lonaowna) - Friday, 10 April 2020, 10:05 GMT
Yes, same issue here. This results in no (IPv4) connectivity on my machine, so I think it's a pretty serious issue.
Comment by Sebastiaan Lokhorst (lonaowna) - Friday, 10 April 2020, 10:09 GMT
I guess this is related to the new "Privilege Separation" feature introduced in 9.0.0:
https://roy.marples.name/archives/dhcpcd-discuss/0002881.html
Comment by Antonio Rojas (arojas) - Friday, 10 April 2020, 12:56 GMT
Please test 9.0.0-2
Comment by Sebastiaan Lokhorst (lonaowna) - Friday, 10 April 2020, 13:16 GMT
9.0.0-2 is working great for me. Thanks arojas!
Comment by Darek (blablo) - Friday, 10 April 2020, 15:41 GMT
9.0.0-2 is working
Comment by Elvis Angelaccio (elvisangelaccio) - Saturday, 11 April 2020, 17:32 GMT
  • Field changed: Percent Complete (100% → 0%)
Still doesn't work for me with 9.0.0-2. I have enabled dhcpcd@wlp3s0.service and I use dhcpcd with NetworkManager.
Comment by Antonio Rojas (arojas) - Saturday, 11 April 2020, 17:33 GMT
Please post full logs
Comment by Elvis Angelaccio (elvisangelaccio) - Saturday, 11 April 2020, 17:44 GMT
journalctl -u dhcpcd@wlp3s0.service doesnt' say anything useful. What else should I check?
Comment by Antonio Rojas (arojas) - Saturday, 11 April 2020, 17:51 GMT
I don't think NM uses dhcpcd's systemd service. Anything in the NM logs?
Comment by Elvis Angelaccio (elvisangelaccio) - Saturday, 11 April 2020, 17:57 GMT
> I don't think NM uses dhcpcd's systemd service. Anything in the NM logs?

Ah, that would explain it, maybe. So NetworkManager should be fixed to support dhcpcd 9.0.0?

NetworkManager logs:

apr 11 19:29:16 arch-t450s NetworkManager[6737]: <info> [1586626156.9730] device (wlp3s0): Activation: starting connection 'UniFi Ang' (9a1544f2-2a00-4f08-89ac-29974e72cc42)
apr 11 19:29:16 arch-t450s NetworkManager[6737]: <info> [1586626156.9733] device (wlp3s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
apr 11 19:29:16 arch-t450s NetworkManager[6737]: <info> [1586626156.9736] manager: NetworkManager state is now CONNECTING
apr 11 19:29:16 arch-t450s NetworkManager[6737]: <info> [1586626156.9754] device (wlp3s0): set-hw-addr: reset MAC address to 34:02:86:ED:88:25 (preserve)
apr 11 19:29:16 arch-t450s NetworkManager[6737]: <info> [1586626156.9779] device (wlp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
apr 11 19:29:16 arch-t450s NetworkManager[6737]: <info> [1586626156.9783] device (wlp3s0): Activation: (wifi) access point 'UniFi Ang' has security, but secrets are required.
apr 11 19:29:16 arch-t450s NetworkManager[6737]: <info> [1586626156.9784] device (wlp3s0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0129] device (wlp3s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0134] device (wlp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0138] device (wlp3s0): Activation: (wifi) connection 'UniFi Ang' has security, and secrets exist. No new secrets needed.
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0138] Config: added 'ssid' value 'UniFi Ang'
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0138] Config: added 'scan_ssid' value '1'
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0138] Config: added 'bgscan' value 'simple:30:-70:86400'
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0139] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256 FT-PSK'
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0139] Config: added 'auth_alg' value 'OPEN'
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0139] Config: added 'psk' value '<hidden>'
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0307] device (wlp3s0): supplicant interface state: disconnected -> scanning
apr 11 19:29:17 arch-t450s NetworkManager[6737]: <info> [1586626157.0307] device (p2p-dev-wlp3s0): supplicant management interface state: disconnected -> scanning
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5182] device (wlp3s0): supplicant interface state: scanning -> authenticating
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5184] device (p2p-dev-wlp3s0): supplicant management interface state: scanning -> authenticating
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5232] device (wlp3s0): supplicant interface state: authenticating -> associating
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5232] device (p2p-dev-wlp3s0): supplicant management interface state: authenticating -> associating
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5432] device (wlp3s0): supplicant interface state: associating -> 4-way handshake
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5432] device (p2p-dev-wlp3s0): supplicant management interface state: associating -> 4-way handshake
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5501] device (wlp3s0): supplicant interface state: 4-way handshake -> completed
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5503] device (wlp3s0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "UniFi Ang"
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5503] device (p2p-dev-wlp3s0): supplicant management interface state: 4-way handshake -> completed
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5508] device (wlp3s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5534] dhcp4 (wlp3s0): activation: beginning transaction (timeout in 45 seconds)
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5560] dhcp4 (wlp3s0): dhcpcd started with pid 6863
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5582] dhcp4 (wlp3s0): client pid 6863 exited with status 0
apr 11 19:29:20 arch-t450s NetworkManager[6737]: <info> [1586626160.5582] dhcp4 (wlp3s0): state changed unknown -> terminated
apr 11 19:29:51 arch-t450s NetworkManager[6737]: <info> [1586626191.8016] device (wlp3s0): state change: ip-config -> failed (reason 'ip-config-unavailable', sys-iface-state: 'managed')
apr 11 19:29:51 arch-t450s NetworkManager[6737]: <info> [1586626191.8036] manager: NetworkManager state is now DISCONNECTED
apr 11 19:29:51 arch-t450s NetworkManager[6737]: <warn> [1586626191.8093] device (wlp3s0): Activation: failed for connection 'UniFi Ang'
Comment by nl6720 (nl6720) - Saturday, 11 April 2020, 18:03 GMT
Regardless of whether NetworkManager supports dhcpcd 9.0 or not, you cannot have both dhcpcd@wlp3s0.service enabled and NetworkManager managing connections for wlp3s0. Either disable dhcpcd@wlp3s0.service or add wlp3s0 to unmanaged-devices in NetworkManager's configuration ( https://wiki.archlinux.org/index.php/NetworkManager#Ignore_specific_devices ).
Comment by Elvis Angelaccio (elvisangelaccio) - Saturday, 11 April 2020, 18:23 GMT
I don't know, it's been working for months like that. Anyway, I was using dhcpcd just to set a custom DNS server, for now I will disable it and set the DNS server in NetworkManager itself.
Comment by Sebastiaan Lokhorst (lonaowna) - Saturday, 11 April 2020, 18:24 GMT
This is probably not related to the networkmanager issue, but I did notice that my logs (`journalctl -u dhcpcd@enp3s0.service`) are empty since 9.0.0-2 too, whereas they used to show some info before that (e.g. `enp3s0: leased 192.168.178.66 for 3600 seconds`). So that would make debugging more difficult.
Comment by Antonio Rojas (arojas) - Saturday, 11 April 2020, 18:40 GMT
From a quick look at the NM code this can never work:
https://github.com/NetworkManager/NetworkManager/blob/master/src/dhcp/nm-dhcp-dhcpcd.c#L89
The PID file is in a different place now. There are probably further issues.

Since this has nothing to do with the original issue in this ticket (dhcpcd itself works fine), I will reclose this and open a new ticket to track this

Loading...