rigacci.org

This page is read only. You can view the source, but not change it. Ask your administrator if you think this is wrong.
====== 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).

The **new method used** by Raspbian to configure the network interfaces involves **dhcpcd**, so the **/etc/network/interfaces** should be almost empty, with just the following:

<file>
source-directory /etc/network/interfaces.d
</file>

There are no **allow-hotplug** or **auto** sections anymore; everything should be managed by **dhcpcd**, even the start of **wpa_supplicant**. Which indeed was failing.

First of all I added some debug to **dhcpcd**: just adding the option **%%-d%%** to the **dhcpcd** //ExecStart// into **/etc/systemd/system/dhcpcd.service.d/wait.conf**. After executing **systemctl daemon-reload** and a reboot, this was the log:

<file>
daemon.debug dhcpcd[772]: dhcpcd-6.11.5 starting
daemon.debug dhcpcd[772]: udev: starting
daemon.info dhcpcd[772]: dev: loaded udev
daemon.debug dhcpcd[772]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks' PREINIT
daemon.debug dhcpcd[772]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks' NOCARRIER
daemon.info dhcpcd[772]: wlan0: waiting for carrier
daemon.err dhcpcd[772]: timed out
daemon.debug dhcpcd[772]: forking to background
</file>

So no **wpa_supplicant** was fired, the **wlan0** interface does not //sense the carrier// and **dhcpcd** refuses to configure it. It seems that dhcpcd does not aknowledge that it is a WiFi adapter, so we have to force it. Just add an interface section into **/etc/dhcpcd.conf**:

<file>
interface wlan0
env ifwireless=1
env wpa_supplicant_driver=nl80211,wext
</file>

the driver specification is required, **otherwise wpa_supplicant will die** with the error message

<code>
nl80211: Driver does not support authentication/association or connect commands
nl80211: deinit ifname=wlan0 disabled_11b_rates=0
wlan0: Failed to initialize driver interface
</code>

After a reboot everything worked as expected, which is confirmed by the **wpa_supplicant process running**:

<code>
wpa_supplicant -B -c/etc/wpa_supplicant/wpa_supplicant.conf -iwlan0 -Dnl80211,wext
</code>

Notice that the configuration file used is **/etc/wpa_supplicant/wpa_supplicant.conf**, but if one named **wpa_supplicant-wlan0.conf** exists, it will be preferred.

===== Alternative: wpa_supplicant started by systemd =====

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 //interface-specific// service against the name **wlan0**, so make the following:

<code>
mv /etc/wpa_supplicant/wpa_supplicant.conf /etc/wpa_supplicant/wpa_supplicant-wlan0.conf
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]]