Differences

This shows you the differences between two versions of the page.

--- doc:appunti:hardware:raspberrypi_wpa_supplicant_problem [2018/02/17 10:17] – [Alternative: wpa_supplicant started by systemd] niccolo
+++ doc:appunti:hardware:raspberrypi_wpa_supplicant_problem [2024/11/17 16:55] (current) – [dhcpcd process dies without configuring wlan0] niccolo
@@ Line 1: / Line 1: @@
-====== Rapsberry Pi problem: dhcpcd not starting wpa_supplicant ======
+====== Raspberry Pi problem: dhcpcd not starting wpa_supplicant ======
 I got a problem with a **Realtek RTL8188EUS** UBS WiFi dongle, into a **Raspberry Pi Model A+**, running **Rasbpian 2017-11-29 Stretch Lite** (based on Debian 9.1).
@@ Line 52: / Line 52: @@
 The default is to start **wpa_supplicant** via **dhcpcd**, as seen above. But if you want, you can force **systemd** to start the service independently.
-You have to start the service against the specific interface name **wlan0**, so make the following:
+You have to start the //interface-specific// service against the name **wlan0**, so make the following:
 <code>
@@ Line 58: / Line 58: @@
 systemctl enable wpa_supplicant@wlan0.service
 </code>
+After a reboot you should see the wpa_supplicant process running, and dhcpcd will configure wlan0 happily.
+===== dhcpcd process dies without configuring wlan0 =====
+This is a similar problem encountered on a **Raspberry Pi Model B Rev 2** running Raspbian GNU/Linux 11 Bullseye. The **wlan0** interface is an USB dongle **Realtek RTL8188CUS**, the **eth0** interface is not used and **dhcpcd** is instructed to ignore it (via the ''denyinterfaces eth0'' option in **/etc/dhcpcd.conf**).
+At first I decided to **disable** the Systemd **wpa_supplicant.service** and let **dhcpcd** to manage the interface starting wpa_supplicant on its own, as seen above. Suddendly the system started to have random problems on bootstrap: sometimes the host resulted having the wpa_supplicant process running (lanched by dhcpcd), but **the dhcpcd process itself was die** and did not configured the IP address on the wlan0 interface.
+To trace the problem I had to enable the debugging option of dhcpcd, adding the **%%-d%%** parameter in **/etc/systemd/system/dhcpcd.service.d/wait.conf**; the log can be read with **journalctl -b -t dhcpcd**.
+A typical log when the problem arises is the following:
+<code>
+Nov 15 00:17:48 rpi dhcpcd[255]: dhcpcd-8.1.2 starting
+Nov 15 00:17:48 rpi dhcpcd[255]: udev: starting
+Nov 15 00:17:48 rpi dhcpcd[255]: dev: loaded udev
+Nov 15 00:17:53 rpi dhcpcd[255]: no valid interfaces found
+Nov 15 00:17:53 rpi dhcpcd[255]: lo: libudev: add
+Nov 15 00:18:00 rpi dhcpcd[255]: eth0: libudev: add
+Nov 15 00:18:13 rpi dhcpcd[255]: wlan0: libudev: add
+Nov 15 00:18:13 rpi dhcpcd[255]: wlan0: interface added
+Nov 15 00:18:13 rpi dhcpcd[255]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks' PREINIT
+Nov 15 00:18:13 rpi dhcpcd[443]: wlan0: starting wpa_supplicant
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: connected to Access Point `'
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks' NOCARRIER
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: waiting for carrier
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: carrier acquired
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks' CARRIER
+Nov 15 00:18:22 rpi dhcpcd[255]: DUID 00:01:00:01:29:0f:e9:4b:e8:4e:06:0e:08:90
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: IAID 02:f5:16:df
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: adding address fe80::ae69:a5aa:2c1d:2190
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: pltime infinity, vltime infinity
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: delaying IPv6 router solicitation for 0.5 seconds
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: delaying IPv4 for 0.5 seconds
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: carrier lost
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks' NOCARRIER
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: delaying IPv6 router solicitation for 0.5 seconds
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: delaying IPv4 for 0.5 seconds
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: carrier lost
+Nov 15 00:18:22 rpi dhcpcd[255]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks' NOCARRIER
+Nov 15 00:18:23 rpi dhcpcd[255]: wlan0: deleting address fe80::ae69:a5aa:2c1d:2190
+Nov 15 00:18:23 rpi dhcpcd[255]: timed out
+Nov 15 00:18:23 rpi dhcpcd[255]: forking to background
+Nov 15 00:18:23 rpi dhcpcd[478]: main: eloop_start: Invalid argument
+Nov 15 00:18:23 rpi dhcpcd[478]: dev: unloaded udev
+Nov 15 00:18:23 rpi dhcpcd[478]: dhcpcd exited
+Nov 15 00:18:23 rpi dhcpcd[255]: forked to background, child pid 478
+</code>
+The error that causes dhcpcd to die is **eloop_start: Invalid argument**; it happens after that dhcpcd has forked. The wlan0 interface instead is activated by dhcpcd launching an instance of wpa_suppplicant before forking. The forked process is probably working with an invalid interface descriptor (see this post [[https://bbs.archlinux.org/viewtopic.php?id=250516|dhcpcd Intermittently Fails]]).
+It results that wlan0 gets a sqeuence of ''wlan0: carrier acquired'' and ''wlan0: carrier lost'', after that the fatal error **main: eloop_start: Invalid argument** kills dhcpcd. Maybe this problem is triggered by the autoconfiguration of IPv6.
+I solved the problem by letting Systemd to start wpa_supplicant on the specific wlan0 interface. This is achieved renaming the wpa_supplicant.conf file and enabling only the interface-specific version service:
+<code>
+mv /etc/wpa_supplicant/wpa_supplicant.conf /etc/wpa_supplicant/wpa_supplicant-wlan0.conf
+systemctl enable wpa_supplicant@wlan0.service
+systemctl disable wpa_supplicant.service
+</code>
+At reboot, dhcpcd will fail to start its own instance of wpa_supplicant on the same device, as seen in the following debug log:
+<code>
+dhcpcd[415]: wlan0: Successfully initialized wpa_supplicant
+dhcpcd[415]: nl80211: kernel reports: Match already configured
+dhcpcd[415]: ctrl_iface exists and seems to be in use - cannot override it
+dhcpcd[415]: Delete '/var/run/wpa_supplicant/wlan0' manually if it is not used anymore
+dhcpcd[415]: Failed to initialize control interface 'DIR=/var/run/wpa_supplicant GROUP=netdev'.
+dhcpcd[415]: You may have another wpa_supplicant process already running or the file was
+dhcpcd[415]: left by an unclean termination of wpa_supplicant in which case you will need
+dhcpcd[415]: to manually remove this file before starting wpa_supplicant again.
+dhcpcd[415]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
+</code>
+Nevertehless dhcpcd is informed by udev when the wlan0 interface is activated and then it can configure it using DHCP.
+**NOTICE**: The default systemd configuration shipped with **Raspbian 11 Bullseye** does not ensure that the **wpa_supplicant@..service** is started before **dhcpcd.service**, thus ensuring that the above startup sequence is respected. You can generate the SVG graphic detailing which system services have been started at what time using the command:
+<code>
+systemd-analyze plot > services-start-graph.svg
+</code>
+Indeed you can see that **dhcpcd.service** becomes active after the **wpa_supplicant@wlan0.service**, but nothing is ensuring this behaviour. We should actually customize the dhcpcd.service unit adding an **After=wpa_supplicant@..service** option. For this purpose we use the command **systemctl edit**:
+<code>
+systemctl edit dhcpcd.service
+</code>
+this will launch an editor to create the file **/etc/systemd/system/dhcpcd.service.d/override.conf**; this is a drop-in snippet to extend or override the definition of the unit. Here we write:
+<file>
+[Unit]
+After=wpa_supplicant@..service
+</file>
+The systemd daemon will be automatically reloaded, se we can reboot.
 ===== Web References =====
   * [[https://www.raspberrypi.org/forums/viewtopic.php?t=191061|Raspbian Stretch: Wifi not starting on boot]]