User Tools

Site Tools


doc:appunti:hardware:raspberrypi_wpa_supplicant_problem

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:

source-directory /etc/network/interfaces.d

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:

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

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:

interface wlan0
env ifwireless=1
env wpa_supplicant_driver=nl80211,wext

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

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

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

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

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:

mv /etc/wpa_supplicant/wpa_supplicant.conf /etc/wpa_supplicant/wpa_supplicant-wlan0.conf
systemctl enable wpa_supplicant@wlan0.service

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:

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

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 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:

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

At reboot, dhcpcd will fail to start its own instance of wpa_supplicant on the same device, as seen in the following debug log:

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

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:

systemd-analyze plot > services-start-graph.svg

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:

systemctl edit dhcpcd.service

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:

[Unit]
After=wpa_supplicant@..service

The systemd daemon will be automatically reloaded, se we can reboot.

Web References

doc/appunti/hardware/raspberrypi_wpa_supplicant_problem.txt · Last modified: 2024/11/17 15:55 by niccolo