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
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
|
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
Saturday, 11 April 2020, 22:13 GMT
Reason for closing: Fixed
Additional comments about closing: dhcpcd 9.0.0-2
https://roy.marples.name/archives/dhcpcd-discuss/0002881.html
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'
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