Installer: wpa_supplicant fails to start

Hello,

Ricardo and sirgazil reported on IRC that the ‘wpa-supplicant’ would

(sometimes?) fail to start for the in the installation image on their

laptop.

As a result the ‘networking’ service (Connman) would not start either;

thus, the installer would report that it failed to establish Internet

access, and would just stop there.

Sirgazil posted /var/log/messages, which shows this:

Ludo’.

Ludovic Courtès <ludo@gnu.org> skribis:

My guess is that it goes like this:

1. shepherd starts ‘networking’, which triggers the start of

‘wpa-supplicant’ (PID 398), which immediately “fails”. Thus

‘networking’ is not started.

2. shepherd continues and starts ‘wpa-supplicant’ directly (PID 400).

This time it fails for good; after 5 seconds, since the PID file

didn’t show up, shepherd says again that it could not be started.

Indeed, by looking at shepherd.conf from:

guix gc -R $(guix system build gnu/system/install.scm) | grep shepherd.conf

one can see that ‘networking’ comes before ‘wpa-supplicant’ in the expression:

(for-each start '(… networking … wpa-supplicant …))

So why is ‘wpa-supplicant’ marked as failing to start on the first

attempt?

The only reason I can think of is if ‘read-pid-file’ from (shepherd

service) returns immediately and returns #f instead of a number. That

can actually happen if the PID file exists but is empty (or contains

garbage).

You would expect wpa_supplicant to create its PID file atomically: write

it under a different name, then rename(2)… but no:

So there is a possibility, albeit unlikely, for shepherd to see the PID

file after it’s been open but before it’s been written to. (This

problem is not limited to the installer.)

I’m not 100% convinced that this is what’s happening there but that’s

the only lead I have. I’m surprised we haven’t seen other reports

before.

Thoughts?

Ludo’.

Ludovic Courtès <ludo@gnu.org> writes:

What I observed was that the wpa-supplicant *service* would not start

and starting it manually would fail because a wpa_supplicant *process*

would already be running.

Upon killing the stray process the service could be started.

--

Ricardo

In my case, "wpa-supplicant" would *always* fail to start (I rebooted and tried the graphical installer around 4 times).

Killing "wpa-supplicant" and then running "herd start networking" made it possible for the graphical installer to display the steps where you select Wireless or Wired, and then continue normally.

severity 35550 important

Hi,

sirgazil@zoho.com skribis:

Could you check whether the sequence of events in /var/log/messages

always looks like the snippet I showed?

Could you also:

1. Let the installation image boot;

2. Confirm with ‘herd status wpa-supplicant’ that the ‘wpa-supplicant’

service is marked as stopped (failed to start);

3. Show the contents /var/run/wpa_supplicant.pid, and check whether

they correspond to the PID of a running ‘wpa_supplicant’ process.

?

Besides, do you have a Guix(SD) installation, recent or not, that uses

wpa_supplicant? If so, does it suffer from the same problem

(‘wpa-supplicant’ service fails to start)?

Thanks,

Ludo’.

On Sat, May 04, 2019 at 02:49:55PM +0200, Ludovic Courtès wrote:

So for me it sometimes fails on two different machines. Actually it

started failing four times in a row now that I test this.

When it fails, I also get

On Fri, May 03, 2019 at 09:31:40PM +0200, Ludovic Courtès wrote:

$ herd status wpa-supplicant

Status of wpa-supplicant:

It is stopped.

It is enabled.

Provides (wpa-supplicant).

Requires (user-processes dbus-system loopback syslogd).

Conflicts with ().

Will be respawned.

There is no such file.

Regards,

Florian

Ludovic Courtès <ludo@gnu.org> skribis:

Shepherd commit 72631752149d000c8c98ae0cc66e0b0c2eda94ef changes

‘read-pid-file’ to better deal with this.

Ludo’.

Hi Florian,

"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> skribis:

At this point, could you also check:

3b. The output of “pgrep -fa wpa_supplicant”.

The PID file was probably removed by the second attempt to start the

‘wpa-supplicant’ service.

Could you also try running (as root):

while herd restart wpa-supplicant; do : ; done

to see the frequency at which the service fails to start?

Thanks!

Ludo’.

On Sat, May 04, 2019 at 05:32:23PM +0200, Ludovic Courtès wrote:

root@gnu ~# pgrep -fa wpa_supplicant

481 /gnu/store/ifqy2dr2hbqplv14k50dzprw3k2bz9m9-wpa-supplicant-2.7/sbin/wpa_supplicant -P/var/run/wpa_supplicant.pid -B -s -u

It displays

Service wpa-supplicant is not running.

Service wpa-supplicant could not be started.

after and again and again every approximately 5 seconds.

Regards,

Florian

Hi,

"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> skribis:

[...]

Sorry, to be complete, I should have asked you to first kill the

“dangling” wpa_supplicant process:

pkill -f wpa_supplicant

pgrep -fa wpa_supplicant # make sure it’s really dead

while herd restart wpa-supplicant; do : ; done

Could you try this?

TIA,

Ludo’.

On Sat, May 04, 2019 at 11:14:29PM +0200, Ludovic Courtès wrote:

pgrep does not display anything.

Now it displays

Service wpa-supplicant has been stopped.

Service wpa-supplicant has been started.

again and again incessantly, one immediately after the other with no

time in between.

By the way, the network connection only failed sometimes when I tested

Guix 1.0.0, but since I started using a Guix disk image from a more

recent Guix, wpa-supplicant apparently always fails. Strange.

Regards,

Florian

Hello,

I’ve been able to test it on the bare metal as well and I confirm: I

booted the install image a few times and the ‘wpa-supplicant’ service

would be stopped every time, with a dangling ‘wpa_supplicant’ process

running. Given that this seems to be systematic, I’m not sure my PID

file atomicity hypothesis explains everything.

I’ve tried running:

pkill wpa_supplicant

while herd start wpa-supplicant ; do herd stop wpa-supplicant ; done

and that always works (i.e., no “failed to start ‘wpa-supplicant’”

error.)

If I run in parallel this:

while touch /var/run/wpa_supplicant.pid ; do : ; done

then it occasionally “fails to start”, but not very often.

To be continued…

Ludo’.

Ludovic Courtès <ludo@gnu.org> skribis:

Regarding this PID file atomicity issue, a few other data points: Tor,

syslogd (GNU Inetutils), sshd (OpenSSH), and dbus-daemon all do the

exact same non-atomic PID file creation as wpa_supplicant.

Libdaemon (used by Avahi) does something more fancy: it acquires an

exclusive write lock (fcntl with F_SETLKW) on the PID file right after

opening it, but since shepherd does not attempt to acquire locks on PID

file, it has no effect.

systemd and GNU Pies don’t take any precautions while reading PID

files. The assumption seems to be that if the file exists, then it must

contain a valid PID.

So perhaps the problem we see with ‘wpa_supplicant’ is elsewhere.

Ludo’.

Ludovic Courtès <ludo@gnu.org> skribis:

I’ve produced an ISO with the patch below and ran it on the bare metal

to get confirmation (too bad the bug doesn’t show in QEMU :-/). Indeed,

‘read-pid-file’ for /var/run/wpa_supplicant.pid systematically reads the

empty string the first time the ‘wpa-supplicant’ service is started.

(After that, if we kill the process and try to restart the service, the

problem doesn’t show up.)

With the second patch below, I confirm that the ‘wpa-supplicant’ starts

correctly. We can see in /var/log/messages that ‘read-pid-file’ first

reads the empty string from /var/run/wpa_supplicant.pid, then tries

again, and gets a valid PID on the second attempt.

It’s surprising that the timing is always like that, and only on the

bare metal, but that’s the way it is.

It’d be great if you could do some testing with the patch below. Then I

guess we’ll push a Shepherd release with this fix.

I wonder if this could also explain

https://issues.guix.info/issue/30993.

Thanks,

Ludo’.

On Mon, May 06, 2019 at 12:21:26AM +0200, Ludovic Courtès wrote:

The second patch (the one for Guix is the only one I have tested)

works fine on the system which always failed before since sometime

after 1.0.

One time wpa-supplicant worked fine but it had an error establishing

the internet connection, but I am quite certain it was an unrelated

hardware issue.

Regards,

Florian

Hi Ludo,

what happens when the loop reads the pid file when it contains just half of a

numeral? It won't detect it, right?

Hi Florian,

"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> skribis:

Awesome, thanks for testing.

Note that I made similar changes in shepherd, which I’ll probably

release as 0.6.1 so we can use it in Guix 1.0.1:

https://git.savannah.gnu.org/cgit/shepherd.git/log

Ludo’.

Hi Danny,

Danny Milosavljevic <dannym@scratchpost.org> skribis:

Correct.

I’m proposing the addition below to be on the verrrry safe side.

WDYT?

The weird thing, as I mentioned earlier, is that systemd and Pies do not

protect against truncated PID files, and I couldn’t find any

“documentation” of the problem on the intertubes. For systemd it’s

maybe less of a problem since services are started in a cgroup, I think.

Thanks,

Ludo’.

Hi Florian,

thank you for pointing me to the right bug report!

I checked the bug reports list via web [1] but did not link

wpa-supplicant to my issue since I did not realized that such an issue

also affects wired connections

"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> writes:

yes, this is definitely an instance of #35550

I confirm I see the very same wpa_supplicant log messages in

/var/log/messages as reported by Sirgazil and pelzflorian

the following suggested workaround (in a text console activated via

CTRL-ALT-F3) works for me:

after that I was able to restart the "Network interface" installer step

(by choosing "Exit" and selecting it again in the proposed dialog) and

was able to select the wired interface

Thanks! Gio'

[1] I'm going to subscribe bug-guix :-)

--

Giovanni Biscuolo

Xelera IT Infrastructures

Ludovic Courtès <ludo@gnu.org> skribis:

Pushed as Shepherd commit 1ebea0a6e4c6ff11212eda348072acf9c379e7b2.

Unless something goes wrong, I’ll make Shepherd commit

fbb9c3fac745552eaf0f354bd0134cca7027bf17 version 0.6.1 in the coming

days (well, with an updated NEWS file.)

Thanks,

Ludo’.

Ludovic Courtès <ludo@gnu.org> skribis:

If you want to re-test that wpa_supplicant does start correctly with the

latest Shepherd, you can do so by applying the patch below to Guix.

Ludo’.

On Thu, May 09, 2019 at 12:25:59AM +0200, Ludovic Court�s wrote:

Works fine too on Macbook and PC (using a non-ISO disk image).

Regards,

Florian

"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> skribis:

Great, thanks for testing!

Ludovic Courtès <ludo@gnu.org> skribis:

Commit 3b8699f9c2a9f88d44a5320398b4c968c432429d upgrades the Shepherd to

0.6.1, which fixes the PID file race condition we’ve been talking about.

Closing!

Ludo’.